Spring boot with GRPC server blocking GRPC client request

[ValeriyDolgov]

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

[ST-DDT]

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

[ValeriyDolgov]

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]

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]

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]

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]

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]

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.

[lmcdasi]

In my case if I turn down the grpc server app and I start the grpc client app, then as long as the grpc client request occurs before the ServletWebServerInitializedEvent (or any other spring boot event) then the client request will not hang and the deadline exceeded takes place.

One work around is to drop the deadline exceeded and use instead a ListenableFuture with the timeout moved to the future get method. `try { createSessionResponse = futureStub.createSession(createSessionRequest); final var createSessionResponseMessage = createSessionResponse.get(withDeadlineAfter, TimeUnit.MILLISECONDS);

        return createSessionResponseMessage;
    } catch (final CancellationException | ExecutionException | InterruptedException | TimeoutException  e) {
         // handle each error accordingly
     }

`

I have tried ApplicationStartedEvent, ContextRefreshedEvent - same. The grpc client hangs.

In ClientCalls.java from the grpc-java project, the thread that sends that request is never woke up .... More precisely in blockingUnaryCall method executor.waitAndDrain does not timeout on the LockSupport.park call. And that because the execute method is not called to perform the unlock at LockSupport.unpark ....

Some form of reference is lost somehow or something else gets corrupted for a reason.

Unfortunately I could not go further than that.