记⼀次dubbo服务丢失的问题排查
主要环境与⽤到的（关键）组件：
Springboot2.3.2
其中，dubbo-spring-boot-starter版本为2.7.8
zookeeper3.5.9
⾸先是服务报错：
No provider available from registry ... for ... on consumer ... use dubbo version 2.7.8, please check status of providers(disabled, not registered or in blacklist).
很多使⽤过dubbo的同学对这个报错信息应该都不陌⽣，⼀般情况下，如果没有配置好⽣产端、消费端或者注册中⼼，启动的时候就会报这个错。但这⾥的情况是，消费端和⽣
产端都已经正常运⾏了⼀段时间了，⼤概10天左右，突然报这个错。
这⾥借助⽹上总结的⼀张图，来梳理⼀下排查No Provider的情况：
⾸先就来看看zookeeper下，⽣产端的provider情况，到zookeeper的安in⽬录下：
sh zkCli.sh
ls /dubbo/xxx/provider
查看⽣产端的信息，结果发现[]，这时的⽣产端程序还是running状态（ps -ef进程存在），⼤概率就是这个⽣产端出了问题。由于⽇志有滚动删除，⽽且出问题的时间点也不确
定，所以这个问题感觉没办法在服务本⾝的⽇志中查看。于是想到查看zookeeper下的事务⽇志：
cd lib/
java -cp .:zookeeper-3.5.9.jar:slf4j-api-1.7.25.jar:zookeeper-jute-3.5.9.jar keeper.server.LogFormatter /tmp/zookeeper/version-2/log.7d1 > /tmp/zookeeper/version-2/log.log
但也看不出什么端倪。这⾥不太确定是服务本⾝的问题，还是服务于zookeeper之间链接的问题。
于是在消费服务中设置了⼀个定时任务，每秒钟去调⽤⽣产端的⼀个接⼝，并在⽣产和消费端都打印⽇志，同时加个监控，这样在除了问题之后，就能第⼀时间到具体的错误
信息。
重启服务8天后，重现了这个错误，这⼀次直接看到了错误⽇志。
⾸先，消费端爆出了
2022-02-1816:23:27.713  WARN 2386027 --- [scheduling-1] o.s.FailoverClusterInvoker      :  [D
UBBO] Although retry the method heart in the service com.jf.zk.proxy.facade.BindFacade was successful by the provider 192.168
org.apache.dubbo.rpc.RpcException: Invoke remote method timeout. method: heart, provider: dubbo://192.168.1.13:20010/com.jf.zk.proxy.facade.BindFacade?anyhost=true&application=proxy-web&check=false&deprecated=false&dubbo=2.0.2& ......
Caused by: urrent.ExecutionException: org.ing.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2022-02-1816:22:39.000, end time: 2022-02-1816:23:09.020, client elapsed: ......
2022-02-1816:23:28.009 ERROR 2386027 --- [scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task
org.apache.dubbo.rpc.RpcException: No provider available from registry ...
这⾥看到是⼀些请求超过了consumer端的timeout，后续就是No provider，猜想应该是⽣产端出现了什么问题，响应越来越慢，到后来服务长时间不可⽤，直⾄与其它服务断开
了链接。这⾥就要看看⽣产端到底发⽣了什么，关键⽇志如下：
2022-02-1816:23:47.942  INFO 2385338 --- [main-SendThread(192.168.1.13:2181)] keeper.ClientCnxn          : Unable to read additional data from server sessionid 0x100000040fc01ae, likely server has closed socket, closing sock 2022-02-1816:23:32.144  WARN 2385338 --- [NettyServerWorker-6-2] o.ansport.AbstractServer  :  [DUBBO] All clients has disconnected from /192.168.1.13:20010. You can graceful shutdown now., dubbo version: 2.7
2022-02-1816:27:15.830  WARN 2385338 --- [DubboClientHandler-192.168.1.13:20004-thread-2] o.hange.support.DefaultFuture  :  [DUBBO] The timeout response finally returned at 2022-02-1816:27:13.882, response status
2022-02-1816:27:38.590  WARN 2385338 --- [DubboClientHandler-192.168.1.13:20004-thread-3] o.hange.support.DefaultFuture  :  [DUBBO] The timeout response finally returned at 2022-02-1816:26:53.015, response status ......
java dubbo2022-02-1816:23:47.117  INFO 2385338 --- [main-SendThread(192.168.1.13:2181)] keeper.ClientCnxn          : Unable to read additional data from server sessionid 0x100000040fc01ad, likely server has closed socket, closing sock 2022-02-1816:35:32.357  INFO 2385338 --- [NettyClientWorker-1-2] o.4.NettyClientHandler      :  [DUBBO] The connection of /192.168.1.13:44900 -> /192.168.1.13:8003is disconnected., dubbo version: 2.7.8, current host:
2022-02-1816:36:13.950  WARN 2385338 --- [dubbo-client-idleCheck-thread-1] o.s.header.ReconnectTimerTask    :  [DUBBO] Reconnect to channel HeaderExchangeClient [channel=org.ansportty4.NettyClient ......
2022-02-1818:46:33.184  WARN 2385338 --- [nioEventLoopGroup-10-3] AbstractChannelHandlerContext      : An exception 'java.lang.OutOfMemoryError: Java heap space' [enable DEBUG level for full stacktrace] was thrown by a user hand java.lang.OutOfMemoryError: Java heap space
这个服务虽然出现了很多与另⼀个服务的链接问题，但后续出现了java.lang.OutOfMemoryError: Java heap space，⼤概率是由于这个内存问题导致的。
由于服务还是running（ps -ef进程存在），我们可以直接把它的内存dump出来。
jmap -dump:file=javaDump.hprof,format=b {该服务的pid}
⽽后使⽤(jdk⾃带⼯具，其实JDK⾃带了很多有⽤的⼯具，有必要了解⼀下)将这个hprof⽂件打开，可以查看很多信息：
查看到了⼀个我们代码⾥定义的SessionModel对象异常地多，最终发现是同事代码⾥每次新建⼀个业务会话时，都会⽣成⼀个SessionModel对象，将其放在
ConcurrentHashMap中，但没有clear或者remove的逻辑，导致相关的对象越来越多，最终导致OOM。
猜测这个服务在内存资源消耗到⼀定程度时，已经⽆法处理其他的请求，发出去的请求也⽆法应答，所以与之相关的rpc链接会被断开，最终这个服务从注册中⼼被清理。
这⾥还可以看看这个⽣产端的服务A调⽤其它服务B的⽇志：
......
2022-02-1816:32:07.642  INFO 348283 --- [NettyServerWorker-6-3] o.4.NettyServerHandler      :  [DUBBO] IdleStateEvent triggered, close channel NettyChannel [channel=[id: 0x0efa3ba8, L:/192.168.1.13:20004 - R:/192.168 2022-02-1816:32:07.642  INFO 348283 --- [NettyServerWorker-6-3] o.ansportty4.NettyChannel    :  [DUBBO] Close netty channel [id: 0x0efa3ba8, L:/192.168.1.13:20004 - R:/192.168.1.13:35954], dubbo version: 2.7.8, current host: 2022-02-1816:32:07.642  INFO 348283 --- [NettyServerWorker-6-3] o.4.NettyServerHandler      :  [DUBBO] The connection of /192.168.1.13:35954 -> /192.168.1.13:20004is disconnected., dubbo version: 2.7.8, current host:
这⾥到对应⽇志的代码：
猜测是服务B由于长时间没有接收到来⾃上⽂提到的服务A（此时应该是客户端的⾓⾊）的⼼跳，持续了timeout这么长时间，于是服务B就把链接关闭了，此时对于A来说，应该就是收不到B服务的响应，所以也会在⽇志前期报访问服务B的timeout。

版权声明：本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系QQ:729038198，我们将在24小时内删除。