手动执行 Example 代码长时间未操作后再次调用服务出现 500 错误

[AhianZhang]

代码为 Example 中的代码，按照文档步骤操作后访问正常，
过了六小时未操作后再次调用接口服务器会报 500 异常，手动将 Broker、Respones、Request 重启后正常访问

2019-12-11 10:27:20.625  INFO 97481 --- [           main] o.s.b.web.embedded.netty.NettyWebServer  : Netty started on port(s): 8181
2019-12-11 10:27:20.628  INFO 97481 --- [           main] c.a.s.b.r.demo.RSocketRequesterApp       : Started RSocketRequesterApp in 1.702 seconds (JVM running for 2.302)
io.rsocket.exceptions.ConnectionErrorException: No keep-alive acks for 65000 ms
	at io.rsocket.RSocketRequester.terminate(RSocketRequester.java:115)
	at io.rsocket.keepalive.KeepAliveSupport.tryTimeout(KeepAliveSupport.java:110)
	at io.rsocket.keepalive.KeepAliveSupport$ClientKeepAliveSupport.onIntervalTick(KeepAliveSupport.java:146)
	at io.rsocket.keepalive.KeepAliveSupport.lambda$start$0(KeepAliveSupport.java:54)
	at reactor.core.publisher.LambdaSubscriber.onNext(LambdaSubscriber.java:160)
	at reactor.core.publisher.FluxInterval$IntervalRunnable.run(FluxInterval.java:123)
	at reactor.core.scheduler.PeriodicWorkerTask.call(PeriodicWorkerTask.java:59)
	at reactor.core.scheduler.PeriodicWorkerTask.run(PeriodicWorkerTask.java:73)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2019-12-11 16:14:48.833 ERROR 97481 --- [ctor-http-nio-4] a.w.r.e.AbstractErrorWebExceptionHandler : [fc5bd7d9]  500 Server Error for HTTP GET "/user/1"

io.rsocket.exceptions.ConnectionErrorException: No keep-alive acks for 65000 ms
	at io.rsocket.RSocketRequester.terminate(RSocketRequester.java:115) ~[rsocket-core-1.0.0-RC5.jar:na]
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint ⇢ Handler com.alibaba.spring.boot.rsocket.demo.PortalController#user(Integer) [DispatcherHandler]
	|_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ HTTP GET "/user/1" [ExceptionHandlingWebHandler]
Stack trace:
		at io.rsocket.RSocketRequester.terminate(RSocketRequester.java:115) ~[rsocket-core-1.0.0-RC5.jar:na]
		at io.rsocket.keepalive.KeepAliveSupport.tryTimeout(KeepAliveSupport.java:110) ~[rsocket-core-1.0.0-RC5.jar:na]
		at io.rsocket.keepalive.KeepAliveSupport$ClientKeepAliveSupport.onIntervalTick(KeepAliveSupport.java:146) ~[rsocket-core-1.0.0-RC5.jar:na]
		at io.rsocket.keepalive.KeepAliveSupport.lambda$start$0(KeepAliveSupport.java:54) ~[rsocket-core-1.0.0-RC5.jar:na]
		at reactor.core.publisher.LambdaSubscriber.onNext(LambdaSubscriber.java:160) ~[reactor-core-3.3.1.RELEASE.jar:3.3.1.RELEASE]
		at reactor.core.publisher.FluxInterval$IntervalRunnable.run(FluxInterval.java:123) ~[reactor-core-3.3.1.RELEASE.jar:3.3.1.RELEASE]
		at reactor.core.scheduler.PeriodicWorkerTask.call(PeriodicWorkerTask.java:59) ~[reactor-core-3.3.1.RELEASE.jar:3.3.1.RELEASE]
		at reactor.core.scheduler.PeriodicWorkerTask.run(PeriodicWorkerTask.java:73) ~[reactor-core-3.3.1.RELEASE.jar:3.3.1.RELEASE]
		at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_212]
		at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[na:1.8.0_212]
		at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_212]
		at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[na:1.8.0_212]
		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_212]
		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_212]
		at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_212]

[sofkyle]

你这是打了断点，然后访问超时

[AhianZhang]

你这是打了断点，然后访问超时

我是在 IDEA 中直接 Run 的，没打断点没 Debug

[sofkyle]

@AhianZhang 建议具体确认下发生了啥，因为超时时间是65s，跟6小时没关系

[linux-china]

这个错误是对的。 目前的配置是 13 x 5 也就是65秒。 @xiazuojie 会和我一起看一下，他之前解决过这个问题。

clientRSocketFactory
                    .keepAlive(Duration.ofSeconds(5), Duration.ofSeconds(5), 12)

[linux-china]

目前有两个小问题，一个是requester要感知服务端关闭啦， 如下：
rsocket/rsocket-java#603

另外一个是keep alive的问题：
rsocket/rsocket-java#712

[linux-china]

目前的解决方案是在LoadBalancedRSocket添加一个 startHealthCheckTimer() ，会进行每15秒钟的连接检查，如果连接不可用，会重新创建连接 c3e5ea4

[linux-china]

客户端在调用请求时，如果是ClosedChannelException，则进行两个操作： 将失败的连接删除并尝试重新连接，然后调用retry函数，拿到新的连接然后进操作。

[linux-china]

新的LoadBalancedRSocket已经添加了连接健康度检查，同时在调用的时候出现连接错误也会重试。 如果还出现这个错误，告知一下 :) https://github.com/alibaba/alibaba-rsocket-broker/blob/master/alibaba-rsocket-core/src/main/java/com/alibaba/rsocket/loadbalance/LoadBalancedRSocket.java