问题描述
最近项目中碰到一个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端口状态，看到如下结果:
可以看到，Grpc客户端端口一直在变化，并且之前与服务端建立连接的端口，端口状态为TIME_WAIT，这样频繁的重新建立连接，必然会消耗大量系统资源。
针对这一问题，可以直接将Grpc服务端的maxConnectionIdle配置去掉，或者将其值设置的大一些。在这，我是直接将该配置去掉了。去掉之后再查看Grpc服务端端口状态，可以看到，建立连接之后，客户端端口一直没变:
注：该问题在win10及以上的系统平台上没有复现，也就是即使配置了
maxConnectionIdle: 1
，Grpc客户端端口依旧未发生变化。暂不知其原因。
改掉这两处问题之后，再在C++服务关闭的状态下，重复调用，待服务启动后，Java立刻就能调用成功。至此，问题终于解决！