Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Spring boot with GRPC server blocking GRPC client request #1057

Open
ValeriyDolgov opened this issue Feb 21, 2024 · 7 comments
Open

Spring boot with GRPC server blocking GRPC client request #1057

ValeriyDolgov opened this issue Feb 21, 2024 · 7 comments
Labels
question A question about this library or its usage

Comments

@ValeriyDolgov
Copy link

I have Spring boot app v.3.2.1 and GRPC server and client in one app.
Initially, when I wrote the service, I only had a GRPC client. Everything worked well until the moment when I added a GRPC server to the same service. After adding it, requests to the GRPC server are successful, but when trying to make a request through the GRPC client, the request simply freezes.

Dependencies i have in pom.xml

<dependencies>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-data-jpa</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
		</dependency>

		<dependency>
			<groupId>org.projectlombok</groupId>
			<artifactId>lombok</artifactId>
			<optional>true</optional>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-test</artifactId>
			<scope>test</scope>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-validation</artifactId>
		</dependency>
		<dependency>
			<groupId>org.flywaydb</groupId>
			<artifactId>flyway-core</artifactId>
			<version>9.22.0</version>
		</dependency>
		<dependency>
			<groupId>org.postgresql</groupId>
			<artifactId>postgresql</artifactId>
			<version>42.7.1</version>
		</dependency>
		<dependency>
			<groupId>org.springdoc</groupId>
			<artifactId>springdoc-openapi-starter-webmvc-ui</artifactId>
			<version>2.2.0</version>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-security</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.security</groupId>
			<artifactId>spring-security-test</artifactId>
			<scope>test</scope>
		</dependency>
		<dependency>
			<groupId>net.devh</groupId>
			<artifactId>grpc-client-spring-boot-starter</artifactId>
			<version>2.15.0.RELEASE</version>
		</dependency>
		<dependency>
			<groupId>net.devh</groupId>
			<artifactId>grpc-server-spring-boot-starter</artifactId>
			<version>2.15.0.RELEASE</version>
		</dependency>
		<dependency>
			<groupId>io.grpc</groupId>
			<artifactId>grpc-stub</artifactId>
			<version>${grpc.version}</version>
		</dependency>
		<dependency>
			<groupId>io.grpc</groupId>
			<artifactId>grpc-protobuf</artifactId>
			<version>${grpc.version}</version>
		</dependency>
		<dependency>
			<groupId>io.grpc</groupId>
			<artifactId>grpc-netty</artifactId>
			<version>${grpc.version}</version>
		</dependency>
		<dependency>
			<groupId>javax.annotation</groupId>
			<artifactId>javax.annotation-api</artifactId>
			<version>1.3.1</version>
		</dependency>
		<dependency>
			<groupId>org.mapstruct</groupId>
			<artifactId>mapstruct</artifactId>
			<version>${mapstruct.version}</version>
		</dependency>
		<dependency>
			<groupId>org.testcontainers</groupId>
			<artifactId>postgresql</artifactId>
			<version>${testcontainers.version}</version>
			<scope>test</scope>
		</dependency>
		<dependency>
			<groupId>org.testcontainers</groupId>
			<artifactId>junit-jupiter</artifactId>
			<version>${testcontainers.version}</version>
			<scope>test</scope>
		</dependency>
		<dependency>
			<groupId>io.grpc</groupId>
			<artifactId>grpc-testing</artifactId>
			<version>1.61.0</version>
			<scope>test</scope>
		</dependency>
		<dependency>
			<groupId>org.hibernate.orm</groupId>
			<artifactId>hibernate-jpamodelgen</artifactId>
			<version>${jpamodelgen.version}</version>
			<scope>provided</scope>
		</dependency>
	</dependencies>

	<build>
		<extensions>
			<extension>
				<groupId>kr.motd.maven</groupId>
				<artifactId>os-maven-plugin</artifactId>
				<version>1.7.0</version>
			</extension>
		</extensions>
		<plugins>
			<plugin>
				<groupId>org.springframework.boot</groupId>
				<artifactId>spring-boot-maven-plugin</artifactId>
				<configuration>
					<excludes>
						<exclude>
							<groupId>org.projectlombok</groupId>
							<artifactId>lombok</artifactId>
						</exclude>
					</excludes>
				</configuration>
			</plugin>
			<plugin>
				<groupId>org.apache.maven.plugins</groupId>
				<artifactId>maven-compiler-plugin</artifactId>
				<configuration>
					<annotationProcessorPaths>
						<path>
							<groupId>org.projectlombok</groupId>
							<artifactId>lombok</artifactId>
							<version>${lombok.version}</version>
						</path>
						<path>
							<groupId>org.mapstruct</groupId>
							<artifactId>mapstruct-processor</artifactId>
							<version>${mapstruct.version}</version>
						</path>
						<path>
							<groupId>org.hibernate</groupId>
							<artifactId>hibernate-jpamodelgen</artifactId>
							<version>${jpamodelgen.version}</version>
						</path>
					</annotationProcessorPaths>
				</configuration>
			</plugin>
			<plugin>
				<groupId>org.xolstice.maven.plugins</groupId>
				<artifactId>protobuf-maven-plugin</artifactId>
				<version>0.6.1</version>
				<configuration>
					<protocArtifact>com.google.protobuf:protoc:${protobuf.version}:exe:${os.detected.classifier}</protocArtifact>
					<pluginId>grpc-java</pluginId>
					<pluginArtifact>io.grpc:protoc-gen-grpc-java:${grpc.version}:exe:${os.detected.classifier}</pluginArtifact>
				</configuration>
				<executions>
					<execution>
						<goals>
							<goal>compile</goal>
							<goal>compile-custom</goal>
						</goals>
					</execution>
				</executions>
			</plugin>
		</plugins>
	</build>

Applcation.yaml

spring:
  main:
    banner-mode: off
  datasource:
    driverClassName: org.postgresql.Driver
    url: jdbc:postgresql://localhost:5432/postgres?prepareThreshold=0
    username: user
    password: postgres
  jpa:
    generate-ddl: false
    hibernate:
      ddl-auto: none
  flyway:
    enabled: true

server:
  port: 8081

grpc:
  client:
    account-grpc-server:
      address: static://localhost:8080
      enableKeepAlive: true
      keepAliveWithoutCalls: true
      negotiationType: plaintext
  server:
    port: 8082

logging:
  level:
    root: trace
    grpc: trace

In logs due request i have

2024-02-20T21:39:08.645+06:00 DEBUG 22556 --- [nio-8081-exec-1] io.grpc.ChannelLogger                    : [Channel<1>: (static://localhost:8080)] Exiting idle mode
2024-02-20T21:39:08.651+06:00 DEBUG 22556 --- [nio-8081-exec-1] io.grpc.util.MultiChildLoadBalancer      : Created
2024-02-20T21:39:08.652+06:00 TRACE 22556 --- [nio-8081-exec-1] io.grpc.ChannelLogger                    : [Channel<1>: (static://localhost:8080)] Resolved address: [[[localhost/127.0.0.1:8080]/{}]], config={io.grpc.internal.RetryingNameResolver.RESOLUTION_RESULT_LISTENER_KEY=io.grpc.internal.RetryingNameResolver$ResolutionResultListener@4dd6799c}
2024-02-20T21:39:08.652+06:00 DEBUG 22556 --- [nio-8081-exec-1] io.grpc.ChannelLogger                    : [Channel<1>: (static://localhost:8080)] Address resolved: [[[localhost/127.0.0.1:8080]/{}]]
2024-02-20T21:39:08.658+06:00 DEBUG 22556 --- [nio-8081-exec-1] io.grpc.Context                          : Storage override doesn't exist. Using default

java.lang.ClassNotFoundException: io.grpc.override.ContextStorageOverride
	at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641) ~[na:na]
	at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188) ~[na:na]
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:525) ~[na:na]
	at java.base/java.lang.Class.forName0(Native Method) ~[na:na]
	at java.base/java.lang.Class.forName(Class.java:375) ~[na:na]
	at io.grpc.Context$LazyStorage.createStorage(Context.java:129) ~[grpc-api-1.59.0.jar:1.59.0]
	at io.grpc.Context$LazyStorage.<clinit>(Context.java:118) ~[grpc-api-1.59.0.jar:1.59.0]
	at io.grpc.Context.storage(Context.java:106) ~[grpc-api-1.59.0.jar:1.59.0]
	at io.grpc.Context.current(Context.java:172) ~[grpc-api-1.59.0.jar:1.59.0]
	at io.grpc.internal.ClientCallImpl.<init>(ClientCallImpl.java:122) ~[grpc-core-1.59.0.jar:1.59.0]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
	at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]

2024-02-20T21:39:09.280+06:00 DEBUG 22556 --- [nio-8081-Poller] org.apache.tomcat.util.net.NioEndpoint   : timeout completed: keys processed=1; now=1708443549280; nextExpiration=1708443548904; keyCount=0; hasEvents=false; eval=false
2024-02-20T21:39:09.911+06:00 DEBUG 22556 --- [5)-172.20.10.14] sun.rmi.transport.tcp                    : RMI TCP Connection(5)-172.20.10.14: accepted socket from [172.20.10.14:62195]

I try to make requests locally, but i didn't help.

Update:
I add deadline for this request:

try {
            return accountServiceBlockingStub.withDeadlineAfter(5, TimeUnit.SECONDS)
                                             .setAccountsForMerchant(getAccountBasicRequest(requestId, merchantId, contractFee));
        } catch (Exception e) {
            var message = String.format("Error when getting response from account-service: %s", e.getMessage());
            log.error(message, e);

            throw new AccountServiceResponseException(messageService.getMessage(ACCOUNT_SERVICE_NOT_AVAILABLE), 400);
        }

After passing 5 seconds I received the following logs after the ones I sent earlier.

2024-02-21T09:04:51.670+06:00 DEBUG 1976 --- [nio-8099-Poller] org.apache.tomcat.util.net.NioEndpoint   : timeout completed: keys processed=1; now=1708484691669; nextExpiration=1708484691664; keyCount=0; hasEvents=false; eval=false
2024-02-21T09:04:52.684+06:00 DEBUG 1976 --- [nio-8099-Poller] org.apache.tomcat.util.net.NioEndpoint   : timeout completed: keys processed=1; now=1708484692684; nextExpiration=1708484692669; keyCount=0; hasEvents=false; eval=false
2024-02-21T09:04:53.699+06:00 DEBUG 1976 --- [nio-8099-Poller] org.apache.tomcat.util.net.NioEndpoint   : timeout completed: keys processed=1; now=1708484693699; nextExpiration=1708484693684; keyCount=0; hasEvents=false; eval=false
2024-02-21T09:04:54.709+06:00 DEBUG 1976 --- [nio-8099-Poller] org.apache.tomcat.util.net.NioEndpoint   : timeout completed: keys processed=1; now=1708484694709; nextExpiration=1708484694699; keyCount=0; hasEvents=false; eval=false
2024-02-21T09:04:55.721+06:00 DEBUG 1976 --- [nio-8099-Poller] org.apache.tomcat.util.net.NioEndpoint   : timeout completed: keys processed=1; now=1708484695721; nextExpiration=1708484695709; keyCount=0; hasEvents=false; eval=false
2024-02-21T09:04:55.872+06:00 ERROR 1976 --- [nio-8099-exec-8] k.p.m.service.grpc.AccountService        : Error when getting response from account-service: DEADLINE_EXCEEDED: deadline exceeded after 4.794824000s. Name resolution delay 0.000000000 seconds. [closed=[], open=[[buffered_nanos=4802324400, waiting_for_connection]]]

io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 4.794824000s. Name resolution delay 0.000000000 seconds. [closed=[], open=[[buffered_nanos=4802324400, waiting_for_connection]]]
	at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:268) ~[grpc-stub-1.59.0.jar:1.59.0]
	at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:249) ~[grpc-stub-1.59.0.jar:1.59.0]
	at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:167) ~[grpc-stub-1.59.0.jar:1.59.0]
	at kz.paspay.paspayledgerservice.grpc.AccountServiceGrpc$AccountServiceBlockingStub.setAccountsForMerchant(AccountServiceGrpc.java:358) ~[classes/:na]
	at kz.paspay.merchantserviceinner.service.grpc.AccountService.setAccountsForMerchant(AccountService.java:30) ~[classes/:na]
	at kz.paspay.merchantserviceinner.service.MerchantService.createAccounts(MerchantService.java:185) ~[classes/:na]
	at kz.paspay.merchantserviceinner.service.MerchantService.createMerchant(MerchantService.java:69) ~[classes/:na]
	...

2024-02-21T09:04:55.886+06:00 TRACE 1976 --- [nio-8099-exec-8] o.s.t.i.TransactionInterceptor           : Completing transaction for [kz.paspay.merchantserviceinner.service.MerchantService.createMerchant] after exception: AccountServiceResponseException(code=400)
2024-02-21T09:04:55.886+06:00 DEBUG 1976 --- [nio-8099-exec-8] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction rollback
@ValeriyDolgov ValeriyDolgov added the question A question about this library or its usage label Feb 21, 2024
@ST-DDT
Copy link
Collaborator

ST-DDT commented Feb 21, 2024

How does your grpc service look like?
Did you call onComplete?

@ValeriyDolgov
Copy link
Author

Yes, I do.
Text below is my GRPC server code of this func on the other service.

    @Override
    public void setAccountsForMerchant(AccountProto.CreateAccountsRequest request,
                                       StreamObserver<AccountProto.AccountResponse> responseObserver) {
        log.info("Received create accounts for merchant request rqID={}, clientId={}",
                 request.getRequestId(),
                 request.getClientId());

        responseObserver.onNext(executeAndGetResponse(() -> {
            accountService.createAccountsForMerchant(request.getClientId(), request.getContractFee());
            var response = prepareResponse(0L, "", getJsonSuccess(true));
            log.info(SET_ACCOUNTS_RESPONSE_LOG, SUCCESS_KEY, request.getRequestId(), request.getClientId());
            return response;
        }, request.getRequestId(), request.getClientId(), SET_ACCOUNTS_RESPONSE_LOG));

        responseObserver.onCompleted();
    }

@ST-DDT
Copy link
Collaborator

ST-DDT commented Feb 21, 2024 •
edited

a) Is the setAccountsForMerchant function on the server called? Or does the call just hang elsewhere?
b) Is the responseObserver.onCompleted() method on the server actually called? Maybe your executeAndGetResponse blocks the code for longer than expected or throws an error.

@ValeriyDolgov
Copy link
Author

No, the code that I provided above is from the service that I want to reach from the service that I described in the question above. When it comes to executing the .setAccountsForMerchant method

        try {
            return accountServiceBlockingStub .setAccountsForMerchant(getAccountBasicRequest(requestId, merchantId, contractFee));
        } catch (Exception e) {
            var message = String.format("Error when getting response from account-service: %s", e.getMessage());
            log.error(message, e);

            throw new AccountServiceResponseException(messageService.getMessage(ACCOUNT_SERVICE_NOT_AVAILABLE), 400);
        }

my request just hangs.
But as soon as I remove the GRPC server functionality from this service, everything goes well

@ST-DDT
Copy link
Collaborator

ST-DDT commented Feb 22, 2024 •
edited

Unless that is some weird issue regarding server address resolution, I don't have any idea what might cause this.
You could probably check the state of the client channel to verify that is actually connected and not in some kind of transient failure. Do you use a scheme in the client address e.g. dns:///foo.bar.test? If not, you should.

[closed=[], open=[[buffered_nanos=4802324400, waiting_for_connection]]]

@ValeriyDolgov
Copy link
Author

Set in application.yml

grpc:
  client:
    account-grpc-server:
      address: dns:///ipaddress:port
      enableKeepAlive: true
      keepAliveWithoutCalls: true
      negotiationType: plaintext
  server:
    port: 8081

Also didn't help

@olvlvl
Copy link

olvlvl commented Feb 28, 2024

Hi everyone, we have had a similar experience since updating to v3.0.0. It's working on production, but locally, the client hangs forever when calling a gRPC server. After adding .withDeadlineAfter(5, TimeUnit.SECONDS) I get the following messages:

2024-02-28T16:24:34.984+01:00 ERROR 54410 --- [***] [nio-8080-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 4.978149667s. Name resolution delay 0.000143042 seconds. [closed=[], open=[[buffered_nanos=4978884666, waiting_for_connection]]]] with root cause

io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 4.978149667s. Name resolution delay 0.000143042 seconds. [closed=[], open=[[buffered_nanos=4978884666, waiting_for_connection]]]
	at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:268)
	at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:249)
	at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:167)

The host is configured as localhost:4312.

We reverted to v2.15.0 for now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question A question about this library or its usage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@olvlvl @ST-DDT @ValeriyDolgov