问题描述

最近项目中碰到一个Grpc调用的问题，久久没有解决。
场景是这样:
Java程序通过Grpc调用C++服务，Java内部多个模块之间也有接口通过Grpc进行通信。当C++的Grpc服务启动的情况下，Java可以通过Grpc正常调用，但当C++的Grpc服务未启动时，Java调用，就会报错（这是肯定的），待服务启动后，Java仍然调用失败，两次报的是同样的错误，报错的具体内容如下：

java.util.concurrent.ExecutionException: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 4.999895300s. [buffered_nanos=5014468700, waiting_for_connection]
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
	at com.lg.coding.controller.HiController.grpcTest(HiController.java:36)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1722)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Caused by: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: deadline exceeded after 4.999895300s. [buffered_nanos=5014468700, waiting_for_connection]
	at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:262)
	at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:243)
	at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:156)
	at com.example.grpc.api.TestServiceGrpc$TestServiceBlockingStub.heyBody(TestServiceGrpc.java:135)
	at com.lg.coding.controller.HiController.lambda$grpcTest$0(HiController.java:34)
	at java.util.concurrent.CompletableFuture$AsyncSupply.run$$$capture(CompletableFuture.java:1590)
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java)
	at java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1582)
	at java.util.concurrent.ForkJoinTask.doExec$$$capture(ForkJoinTask.java:289)
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java)
	at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

需要等一段时间之后才能调用成功，并且在服务未启动的情况下，Java调用的次数越多，服务启动后，等待Java调用服务成功的时间也越长。上网查资料，没有找到类似的问题，现在网上对Grpc的资料比较少，前后过了半个多月才解决。贴出来，以后自己再遇到类似问题的时候能快速找到解决办法，也希望能帮到遇到类似问题的人。
原来出问题时的代码实现，贴在下面：

pom文件中grpc相关依赖
<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>io.grpc</groupId>
            <artifactId>grpc-bom</artifactId>
            <version>1.34.1</version>
            <type>pom</type>
            <scope>import</scope>
        </dependency>
    </dependencies>
</dependencyManagement>
<dependencies>
    <dependency>
        <groupId>net.devh</groupId>
        <artifactId>grpc-server-spring-boot-starter</artifactId>
        <version>2.13.0</version>
    </dependency>
    <dependency>
        <groupId>net.devh</groupId>
        <artifactId>grpc-client-spring-boot-starter</artifactId>
        <version>2.13.0</version>
    </dependency>
    <dependency>
        <groupId>com.google.protobuf</groupId>
        <artifactId>protobuf-java-util</artifactId>
        <version>3.12.0</version>
    </dependency>
</dependencies>
<build>
    <extensions>
        <extension>
            <groupId>kr.motd.maven</groupId>
            <artifactId>os-maven-plugin</artifactId>
            <version>1.6.2</version>
        </extension>
    </extensions>   
    <plugins>
        <plugin>
            <groupId>org.xolstice.maven.plugins</groupId>
            <artifactId>prortobuf-maven-plugin</artifactId>
            <version>0.6.1</version>
            <configuration>
                <protocArtifact>
                    com.google.protobuf:protoc:3.12.0:exe:windows-x86_64
                </protocArtifact>
                <pluginId>grpc-java</pluginId>
                <pluginArtifact>
                    io.grpc:protoc-gen-grpc-java:1.34.1:exe:windows-x86_64
                </pluginArtifact>
                <protoSourceRoot>src/main/resources/proto</protoSourceRoot> 
            </configuration>
            <extensions>
                <extension>
                    <goals>
                        <goal>compile</goal>  
                        <goal>compile-custom</goal> 
                    </goals>
                </extension>  
            </extensions> 
        </plugin>
    </plugins> 
</build>
配置文件中Grpc相关配置
grpc:
  server:
    port: 19998
    maxConnectionIdle: 1
  client:
    cfw_server:
      address: 'static://192.1.130.103:50051'
      negotiationType: plaintext
调用C++服务的代码片段
public class GrpcClientComponent {
    @GrpcClient("cfw_server")
    private Service_GHGrpc.Service_GHBlockingStub ghBlockingStub;
    public void grpcRequestRefreshCache () {
        EmptyParam param = EmptyParam.newBuilder().build();
        ghBlockingStub.withWaitForReady().withDeadlineAfter(5, TimeUnit.SECONDS).refreshCache(param);
    }
}
Java内部定义的Grpc服务
@GrpcService
public class TableManageServer extends TableManageServiceGrpc.TableManageServiceImplBase {
    @Override
    public void updateStatus (GlobalState request, StreamObserver<reponseData> responseObserver) {
        CommonCollection.globalStateMap.put(request.getParamName(), request.getParamValue());
        ResponseData response = ResponseData.newBuilder().build();
        responseObserver.onNext(response);
        responseObserver.onCompleted();
    }
}

Java模块之间通过Grpc进行调用的方式与上面的调用方式相同，在此不做赘述。

问题分析

在上面的代码中，Java通过Grpc调用C++服务时设置的超时时间是5秒钟，也就是从Java发起调用开始计时，5秒钟之后若还未收到C++服务的回复，就会报deadline exceeded after 4.999895300s的错误。当C++服务启动后，Java再次调用，仍然报这个错误，并且在C++程序中发现，根本就没有收到外部Java的调用请求。
在Java调用C++服务之前查看Grpc客户端与服务端建立连接的通道（Channel）状态，正常情况下，可以正常调用的通道状态是READY状态，当C++的Grpc服务端关闭时，再进行调用，调用之后，再查看通道状态，此时是TRANSIENT_FAILURE状态，启动C++服务后，再进行调用，还是报错，是因为此时的通道状态仍然是TRANSIENT_FAILURE状态。
于是从网上查了一下Grpc客服端与服务端之间建立通道的5种状态:
CONNECTING:
Channel正在尝试建立连接并期望在以下步骤中取得进展name resolution，TCP connection establishment或TLS handshake。这可能被用作通道创建的初始化状态。
READY:
Channel已通过以下方法成功建立连接，TLS handshake(或其他等价方式)和协议层级(HTTP/2，etc)的握手，且随后所有的通讯尝试都已经成功（或在没有任何已经失败的情况下挂起）。
TRANSIENT_FAILURE:
已经有一些短暂的失败（如TCP三路握手超时或一个socket错误）。在这一状态的Channels将最终转换为CONNECTING状态并尝试再次建立连接。因为重试使用指数回退，连接失败的Channel开始时将花费很少的时间挂起，但随之不断重复尝试，时间会逐渐增加。对于很多non-fatal失败（e.g.，TCP连接尝试超时因为服务不可用），Channel可能会花费大量时间在这个状态上。
IDLE:
在这一状态，Channel甚至不会尝试创建连接，因为缺少新的或挂起的RPCs。新的RPCs可能在这一状态被创建。任何在本Channel上开始rpc的尝试都会使Channel离开本状态，进入CONNECTING状态。当在指定的IDLE_TIMEOUT内，Channel上没有RPC活动，i.e，在这期间没有新的或挂起的（激活的）RPCs，Channel将从READY或CONNECTING状态IDLE。另外，接收到GOAWAY的Channel且没有激活或挂起的RPCs，也应当转到IDLE来避免试图断开连接的服务器连接过载。
SHUTDOWN:
本Channel已经开始关闭了，任何新的RPCs将会立刻失败。挂起的RPCs可能会继续运行直到应用取消它们。Channel可能进入这个状态，因为应用显式的请求关闭，或在尝试连接通讯时一个不可修复的错误发生了。进入这种状态的Channel永远不会离开这种状态。

到这里不难理解，Grpc客户端与服务端双方建立的通道在READY状态下才能够正常进行通信，当通道状态处于TRANSIENT_FAILURE时，会继而进入CONNECTING状态尝试再次建立连接，但重新建立连接用的是指数回退，所以在TRANSIENT_FAILURE状态下客户端调用服务端的次数越多，重新建立连接所需要的时间就会越长（这也是为什么在C++服务关闭的情况下，Java调用次数越多，待C++启动后，Java调用服务成功的时间就会越长的原因）。
针对这一原因，判断如果通道状态处于TRANSIENT_FAILURE，则立即回退。
修改后的客户端调用代码如下:

public class GrpcClientComponent {
    @GrpcClient("cfw_server")    
    private Service_GHGrpc.Service_GHBlockingStub ghBlockingStub;    
    public void grpcRequestRefreshCache () {        
        EmptyParam param = EmptyParam.newBuilder().build();
        ManagedChannel channel = (ManagedChannel) ghBlockingStub.getChannel();
        ConnectivityState state = channel.getState(false);
        if (ConnectivityState.TRANSIENT_FAILURE == state)
            channel.resetConnectBackoff();
        ghBlockingStub .withWaitForReady().withDeadlineAfter(5, TimeUnit.SECONDS).refreshCache(param);
}}

再回头看Java内部对Grpc服务端的配置:

grpc:
  server:
    port: 19998
    maxConnectionIdle: 1

定义Grpc服务端端口为19998，下面来看一下maxConnectionIdle: 1的解释:
若一个client空闲超过1秒，发送一个GOAWAY，为了防止同一时间发送大量GOAWAY，会在1秒时间间隔上下浮动1*10%，即0.9-1.1秒。
当client在收到GOAWAY包之后会主动关闭连接，下次需要发送数据时，就会重新建立连接。GOAWAY是实现grpc.gracefulStop机制的重要保证。
从上面Channel在IDLE状态的解释来看，当在指定的IDLE_TIMEOUT内，客户端与服务端若没有进行通信或挂起，Channel将会从READY状态或CONNECTING状态转为IDLE状态。
设想一下，Java与C++通过Grpc建立连接之后，在某一时间段Java没有通过Grpc调用C++服务，则Channel进入IDLE状态，之后Grpc服务端会在1秒钟左右向客户端发送GOAWAY包，于是，服务端和客户端就会不断重新建立连接。
用命令行查看19998端口状态，看到如下结果:
LG
可以看到，Grpc客户端端口一直在变化，并且之前与服务端建立连接的端口，端口状态为TIME_WAIT，这样频繁的重新建立连接，必然会消耗大量系统资源。
针对这一问题，可以直接将Grpc服务端的maxConnectionIdle配置去掉，或者将其值设置的大一些。在这，我是直接将该配置去掉了。去掉之后再查看Grpc服务端端口状态，可以看到，建立连接之后，客户端端口一直没变:
LG
注：该问题在win10及以上的系统平台上没有复现，也就是即使配置了maxConnectionIdle: 1，Grpc客户端端口依旧未发生变化。暂不知其原因。
改掉这两处问题之后，再在C++服务关闭的状态下，重复调用，待服务启动后，Java立刻就能调用成功。至此，问题终于解决！

# java # rpc
Logo
开放原子开发者工作坊

开放原子开发者工作坊旨在鼓励更多人参与开源活动，与志同道合的开发者们相互交流开发经验、分享开发心得、获取前沿技术趋势。工作坊有多种形式的开发者活动，如meetup、训练营等，主打技术交流，干货满满，真诚地邀请各位开发者共同参与！

更多推荐

第二届开放原子大赛首批创新成果集结武汉，诚邀广大开发者共鉴开源技术盛宴

第二届开放原子大赛首批创新成果集结武汉，诚邀广大开发者共鉴开源技术盛宴

avatar 开放原子开发者工作坊

诚邀报名 | 开源基础设施能力建设分论坛：打造开源生态的“心脏”

诚邀报名 | 开源基础设施能力建设分论坛：打造开源生态的“心脏”

avatar 开放原子开发者工作坊

诚邀报名 | 编程语言分论坛：AI时代的技术革新与开源实践

诚邀报名 | 编程语言分论坛：AI时代的技术革新与开源实践

avatar 开放原子开发者工作坊