37 一次获取redis连接阻塞引起的 Thread pool is EXHAUSTED

前言

上周五的时候, 我们系统[非业务系统, 一个离线业务处理系统] 曾经出现过这样一个问题

我们 base 服务的线程池无故被耗尽, 然后所有的业务都拒绝处理了, 然后之后只好进行惯例的"重启", 还有不幸的事情就是业务系统那边的异步处理似乎是存在些问题, 然后影响到了业务系统

然后这个问题, 从日志层面上来看, 似乎是看不出太大的端倪, 又是周五了, 还是先下班吧, 空闲的时候再来看看

然后上周周末的时候, 抽时间看了一下这个问题, 并做了一些排查, 但是当时还是没有发现问题之所在 ??

然后本周周三的时候, 尼玛本问题又出现了, 不过好在此次业务系统那边异步处理做了一些调整, 因此没有影响到业务系统

呵呵好在有了两次的信息, 以及日志等等, 可以做出一些初步的判断了, 不过似乎也是有一些运气的成分, 居然想通了整个事情的"流程"

日志信息

## 处理线程池耗尽之后的相关业务处理 异常日志
Nov 23 17:00:43 $dubboHost $module-base 2018-11-23 17:00:41,624 [New I/O worker #3] WARN  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:54) -  [DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-$dubboHost:$portProvider, Pool Size: 100 (active: 100, core: 100, max: 100, largest: 100), Task: 182459 (completed: 182359), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://$ipProvider:$portProvider!, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:00:43 $dubboHost $module-base 2018-11-23 17:00:41,624 [New I/O worker #3] WARN  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:62) -  [DUBBO] An exception was thrown by a user handler while handling an exception event ([id: 0xfa544b32, /$ipCustomer:$portCustomer => /$ipProvider:$portProvider] EXCEPTION: com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process received event .), dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:00:43 $dubboHost $module-base com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process caught event .
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:67)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractPeer.caught(AbstractPeer.java:127)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.netty.NettyHandler.exceptionCaught(NettyHandler.java:112)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.exceptionCaught(NettyCodecAdapter.java:165)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:525)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:48)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.messageReceived(NettyCodecAdapter.java:148)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90)
Nov 23 17:00:43 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)
Nov 23 17:00:43 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
Nov 23 17:00:43 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Nov 23 17:00:43 $dubboHost $module-base     at java.lang.Thread.run(Thread.java:745)
Nov 23 17:00:43 $dubboHost $module-base Caused by: java.util.concurrent.RejectedExecutionException: Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-$dubboHost:$portProvider, Pool Size: 100 (active: 100, core: 100, max: 100, largest: 100), Task: 182459 (completed: 182359), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://$ipProvider:$portProvider!
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.common.threadpool.support.AbortPolicyWithReport.rejectedExecution(AbortPolicyWithReport.java:53)
Nov 23 17:00:43 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
Nov 23 17:00:43 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
Nov 23 17:00:43 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:65)
Nov 23 17:00:43 $dubboHost $module-base     ... 19 more
## 连续的 "Thread pool is EXHAUSTED" 异常日志信息
## 重启 dubbo 服务 - 关闭服务
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,065 [DubboShutdownHook-NettyClient] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Run shutdown hook of netty client now., dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,065 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Run shutdown hook now., dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,066 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Close all registries [zookeeper://$zk01:$zk01Port/com.alibaba.dubbo.registry.RegistryService?application=$module-base&backup=$zk02:$zk02Port, $zk03:$zk03Port&check=false&dubbo=2.8.4&file=/home/dubbo/.dubbo/$module-base.cache/dubbo-$module-base.cache&interface=com.alibaba.dubbo.registry.RegistryService&logger=slf4j&pid=30608&timestamp=1542942111709], dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,067 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Destroy registry:zookeeper://$zk01:$zk01Port/com.alibaba.dubbo.registry.RegistryService?application=$module-base&backup=$zk02:$zk02Port, $zk03:$zk03Port&check=false&dubbo=2.8.4&file=/home/dubbo/.dubbo/$module-base.cache/dubbo-$module-base.cache&interface=com.alibaba.dubbo.registry.RegistryService&logger=slf4j&pid=30608&timestamp=1542942111709, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,067 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Unregister: dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.settlement.train.IXXBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942113849, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,069 [DubboClientHandler-$localIp:$localPort-thread-369] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] disconected from /$localIp:$localPort,url:dubbo://$localIp:$localPort/com.alibaba.dubbo.monitor.MonitorService?anyhost=true&application=$company-monitor&check=false&codec=dubbo&delay=-1&dubbo=2.8.4&generic=false&heartbeat=60000&interface=com.alibaba.dubbo.monitor.MonitorService&methods=$methodList&pid=30608&revision=2.8.4&side=provider&timestamp=1542942112230, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,073 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Destroy unregister url dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.settlement.train.IXXBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942113849, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:39 $dubboHost $module-base 2018-11-23 17:10:39,074 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Unregister: dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.order.ITrainExtraInfoBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942112544, dubbo version: 2.8.4, current host: $ipProvider
## 连续的 "Destroy unregister url" 日志信息
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:39,250 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Unsubscribe: provider://$dubboHost:$portProvider/com.$company.$module.base.api.settlement.sell_channel.IXXBaseService?application=$module-base&category=configurators&check=false&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942113800, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:39,250 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Destroy unsubscribe url provider://$dubboHost:$portProvider/com.$company.$module.base.api.settlement.sell_channel.IXXBaseService?application=$module-base&category=configurators&check=false&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942113800, dubbo version: 2.8.4, current host: $ipProvider
## 连续的 "Destroy unsubscribe url" 日志信息
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:39,272 [ZkClient-EventThread-62-$zk01:$zk01Port,$zk02:$zk02Port, $zk03:$zk03Port] INFO  org.I0Itec.zkclient.ZkEventThread (ZkEventThread.java:82) - Terminate ZkClient event thread.
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:39,283 [DubboShutdownHook] INFO  org.apache.zookeeper.ZooKeeper (ZooKeeper.java:684) - Session: 0x2008eab6e4c000d closed
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:39,284 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Close dubbo server: $dubboHost/$ipProvider:$portProvider, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:39,286 [main-EventThread] INFO  org.apache.zookeeper.ClientCnxn$EventThread (ClientCnxn.java:519) - EventThread shut down for session: 0x2008eab6e4c000d
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:40,552 [DubboClientReconnectTimer-thread-1] WARN  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:62) -  [DUBBO] An exception was thrown by an exception handler., dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:42 $dubboHost $module-base java.util.concurrent.RejectedExecutionException: Worker has already been shutdown
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioSelector.registerTask(AbstractNioSelector.java:115)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(AbstractNioWorker.java:73)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.java:36)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(AbstractNioWorker.java:57)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.java:36)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioChannelSink.execute(AbstractNioChannelSink.java:34)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.Channels.fireExceptionCaughtLater(Channels.java:496)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:46)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.Channels.close(Channels.java:812)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:197)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.ChannelFutureListener$2.operationComplete(ChannelFutureListener.java:52)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:427)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.DefaultChannelFuture.notifyListeners(DefaultChannelFuture.java:413)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.DefaultChannelFuture.setFailure(DefaultChannelFuture.java:380)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:130)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:70)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.Channels.connect(Channels.java:634)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.AbstractChannel.connect(AbstractChannel.java:207)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:229)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:182)
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.netty.NettyClient.doConnect(NettyClient.java:105)
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractClient.connect(AbstractClient.java:280)
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractClient$1.run(AbstractClient.java:145)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Nov 23 17:10:42 $dubboHost $module-base     at java.lang.Thread.run(Thread.java:745)
Nov 23 17:10:42 $dubboHost $module-base 2018-11-23 17:10:40,553 [DubboClientReconnectTimer-thread-1] WARN  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:62) -  [DUBBO] client reconnect to $localIp:$localPort find error . url: dubbo://$localIp:$localPort/com.alibaba.dubbo.monitor.MonitorService?anyhost=true&application=$company-monitor&check=false&codec=dubbo&delay=-1&dubbo=2.8.4&generic=false&heartbeat=60000&interface=com.alibaba.dubbo.monitor.MonitorService&methods=$methodList&pid=30608&revision=2.8.4&side=provider&timestamp=1542942112230, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:42 $dubboHost $module-base com.alibaba.dubbo.remoting.RemotingException: client(url: dubbo://$localIp:$localPort/com.alibaba.dubbo.monitor.MonitorService?anyhost=true&application=$company-monitor&check=false&codec=dubbo&delay=-1&dubbo=2.8.4&generic=false&heartbeat=60000&interface=com.alibaba.dubbo.monitor.MonitorService&methods=$methodList&pid=30608&revision=2.8.4&side=provider&timestamp=1542942112230) failed to connect to server /$localIp:$localPort, error message is:Worker has already been shutdown
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.netty.NettyClient.doConnect(NettyClient.java:141)
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractClient.connect(AbstractClient.java:280)
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.AbstractClient$1.run(AbstractClient.java:145)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
Nov 23 17:10:42 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Nov 23 17:10:42 $dubboHost $module-base     at java.lang.Thread.run(Thread.java:745)
Nov 23 17:10:42 $dubboHost $module-base Caused by: java.util.concurrent.RejectedExecutionException: Worker has already been shutdown
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioSelector.registerTask(AbstractNioSelector.java:115)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.AbstractNioSelector.register(AbstractNioSelector.java:100)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioClientBoss.register(NioClientBoss.java:42)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:121)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:70)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.Channels.connect(Channels.java:634)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.channel.AbstractChannel.connect(AbstractChannel.java:207)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:229)
Nov 23 17:10:42 $dubboHost $module-base     at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:182)
Nov 23 17:10:42 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.netty.NettyClient.doConnect(NettyClient.java:105)
Nov 23 17:10:42 $dubboHost $module-base     ... 9 more
## 连续的 "Worker has already been shutdown" 日志信息
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:49,285 [DubboServerHandler-$dubboHost:$portProvider-thread-37] ERROR $company.$module.common.redis.impl.RedisClientTemplate (RedisClientTemplate.java:206) - Could not get a resource from the pool
Nov 23 17:10:51 $dubboHost $module-base redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
Nov 23 17:10:51 $dubboHost $module-base     at redis.clients.util.Pool.getResource(Pool.java:53)
Nov 23 17:10:51 $dubboHost $module-base     at redis.clients.jedis.ShardedJedisPool.getResource(ShardedJedisPool.java:36)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.redis.impl.RedisClientTemplate.getResource(RedisClientTemplate.java:181)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.redis.impl.RedisClientTemplate.doWithCallback(RedisClientTemplate.java:201)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.redis.impl.RedisClientTemplate.get(RedisClientTemplate.java:40)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.RedisBasedCacheService.get0(RedisBasedCacheService.java:92)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.get(BaseCacheService.java:415)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.getOrNull0(BaseCacheService.java:111)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.getOrNull(BaseCacheService.java:489)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.getOrNull(BaseCacheService.java:592)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.aop.CacheHandlerAop.getResult(CacheHandlerAop.java:177)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.aop.CacheHandlerAop.doProcess(CacheHandlerAop.java:100)
Nov 23 17:10:51 $dubboHost $module-base     at sun.reflect.GeneratedMethodAccessor181.invoke(Unknown Source)
Nov 23 17:10:51 $dubboHost $module-base     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Nov 23 17:10:51 $dubboHost $module-base     at java.lang.reflect.Method.invoke(Method.java:606)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:62)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.base.apiImpl.common.XXBaseService$$EnhancerBySpringCGLIB$$8065d831.getByAdapterAndOldStationNo(<generated>)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.common.bytecode.Wrapper4.invokeMethod(Wrapper4.java)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:65)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:70)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:132)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:113)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Nov 23 17:10:51 $dubboHost $module-base     at java.lang.Thread.run(Thread.java:745)
Nov 23 17:10:51 $dubboHost $module-base Caused by: java.lang.InterruptedException
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2052)
Nov 23 17:10:51 $dubboHost $module-base     at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:524)
Nov 23 17:10:51 $dubboHost $module-base     at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:433)
Nov 23 17:10:51 $dubboHost $module-base     at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:360)
Nov 23 17:10:51 $dubboHost $module-base     at redis.clients.util.Pool.getResource(Pool.java:49)
Nov 23 17:10:51 $dubboHost $module-base     ... 52 more
## 连续的 "Could not get a resource from the pool" 日志信息
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:49,286 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Close NettyServer bind $dubboHost/$ipProvider:$portProvider, export $dubboHost/$ipProvider:$portProvider, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:49,299 [DubboServerHandler-$dubboHost:$portProvider-thread-52] ERROR alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:74) -  [DUBBO] Got unchecked and undeclared exception which called by $ipProvider. service: com.$company.$module.base.api.IXXBaseService, method: add, exception: redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:49,381 [DubboShutdownHook] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Unexport service: dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&monitor=dubbo%3A%2F%2Fzk1.tz.com%3A2181%2Fcom.alibaba.dubbo.registry.RegistryService%3Fapplication%3D$module-base%26backup%3Dzk2.tz.com%3A2181%2Czk3.tz.com%3A2181%26check%3Dfalse%26dubbo%3D2.8.4%26file%3D%2Fhome%2Fdubbo%2F.dubbo%2F$module-base.cache%2Fdubbo-$module-base.cache%26logger%3Dslf4j%26pid%3D30608%26protocol%3Dregistry%26refer%3Ddubbo%253D2.8.4%2526interface%253Dcom.alibaba.dubbo.monitor.MonitorService%2526pid%253D30608%2526timestamp%253D1542942113785%26registry%3Dzookeeper%26timestamp%3D1542942113778&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942113778, dubbo version: 2.8.4, current host: $ipProvider
## 连续多个 "Unexport service" 信息 ## 重启 dubbo 服务 - 启动服务
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:50,794 [INFO ] [dubbo.common.logger.LoggerFactory] using logger: com.alibaba.dubbo.common.logger.log4j.Log4jLoggerAdapter
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:50,851 [INFO ] [alibaba.dubbo.container.Main]  [DUBBO] Use container type([log4j, spring]) to run dubbo serivce., dubbo version: 2.8.4, current host: 127.0.0.1
Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:50,853 [main] INFO  com.alibaba.dubbo.container.Main (Main.java:81) -  [DUBBO] Dubbo Log4jContainer started!, dubbo version: 2.8.4, current host: 127.0.0.1
Nov 23 17:11:09 $dubboHost $module-base 2018-11-23 17:11:06,873 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) - using logger: com.alibaba.dubbo.common.logger.slf4j.Slf4jLoggerAdapter
Nov 23 17:11:15 $dubboHost $module-base 2018-11-23 17:11:12,838 [main] INFO  org.hibernate.validator.internal.util.Version (Version.java:27) - HV000001: Hibernate Validator 4.3.1.Final
Nov 23 17:11:17 dubbo04 $module-base 2018-11-23 17:11:14,862 [DubboMonitorSendTimer-thread-2] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Send statistics to monitor zookeeper://$zk01:$zk01Port/com.alibaba.dubbo.monitor.MonitorService?anyhost=true&application=$company-monitor&check=false&delay=-1&dubbo=2.8.4&generic=false&interface=com.alibaba.dubbo.monitor.MonitorService&methods=$methodList&pid=3799&revision=2.8.4&side=provider&timestamp=1542942111092, dubbo version: 2.8.4, current host: $ipCustomer
Nov 23 17:11:18 $dubboHost $module-base 2018-11-23 17:11:16,014 [main] INFO  web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter (RequestMappingHandlerAdapter.java:534) - Looking for @ControllerAdvice: org.springframework.context.support.ClassPathXmlApplicationContext@28db4ccf: startup date [Fri Nov 23 17:10:50 CST 2018]; root of context hierarchy
Nov 23 17:11:18 $dubboHost $module-base 2018-11-23 17:11:16,436 [main] INFO  web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter (RequestMappingHandlerAdapter.java:534) - Looking for @ControllerAdvice: org.springframework.context.support.ClassPathXmlApplicationContext@28db4ccf: startup date [Fri Nov 23 17:10:50 CST 2018]; root of context hierarchy
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:18,736 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Start NettyServer bind $dubboHost/$ipProvider:$portProvider, export $dubboHost/$ipProvider:$portProvider, dubbo version: 2.8.4, current host: 127.0.0.1
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:18,778 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Load registry store file /home/dubbo/.dubbo/$module-base.cache/dubbo-$module-base.cache, data: {com.$company.$module.base.api.report.car.IXXBaseService=empty://$dubboHost:$portProvider/com.$company.$module.base.api.report.car.IXXBaseService?application=$module-base&category=configurators&check=false&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=30608&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542942114084
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:18,790 [ZkClient-EventThread-62-$zk01:$zk01Port,$zk02:$zk02Port, $zk03:$zk03Port] INFO  org.I0Itec.zkclient.ZkEventThread (ZkEventThread.java:64) - Starting ZkClient event thread.
## 省略 zk 环境信息
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:18,798 [main] INFO  org.apache.zookeeper.ZooKeeper (ZooKeeper.java:438) - Initiating client connection, connectString=$zk01:$zk01Port,$zk02:$zk02Port, $zk03:$zk03Port sessionTimeout=60000 watcher=org.I0Itec.zkclient.ZkClient@6386386d
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:18,828 [main-EventThread] INFO  org.I0Itec.zkclient.ZkClient (ZkClient.java:449) - zookeeper state changed (SyncConnected)
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,126 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] The service ready on spring started. service: com.$company.$module.base.api.IXXBaseService, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,136 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Export dubbo service com.$company.$module.base.api.IXXBaseService to local registry, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,136 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Export dubbo service com.$company.$module.base.api.IXXBaseService to url dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=20519&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542964281127, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,136 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Register dubbo service com.$company.$module.base.api.IXXBaseService url dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&monitor=dubbo%3A%2F%2Fzk1.tz.com%3A2181%2Fcom.alibaba.dubbo.registry.RegistryService%3Fapplication%3D$module-base%26backup%3Dzk2.tz.com%3A2181%2Czk3.tz.com%3A2181%26check%3Dfalse%26dubbo%3D2.8.4%26file%3D%2Fhome%2Fdubbo%2F.dubbo%2F$module-base.cache%2Fdubbo-$module-base.cache%26logger%3Dslf4j%26pid%3D20519%26protocol%3Dregistry%26refer%3Ddubbo%253D2.8.4%2526interface%253Dcom.alibaba.dubbo.monitor.MonitorService%2526pid%253D20519%2526timestamp%253D1542964281136%26registry%3Dzookeeper%26timestamp%3D1542964281127&pid=20519&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542964281127 to registry registry://$zk01:$zk01Port/com.alibaba.dubbo.registry.RegistryService?application=$module-base&backup=$zk02:$zk02Port, $zk03:$zk03Port&check=false&dubbo=2.8.4&file=/home/dubbo/.dubbo/$module-base.cache/dubbo-$module-base.cache&logger=slf4j&pid=20519&registry=zookeeper&timestamp=1542964281127, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,137 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Register: dubbo://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=20519&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542964281127, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,143 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Subscribe: provider://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&category=configurators&check=false&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=20519&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542964281127, dubbo version: 2.8.4, current host: $ipProvider
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,148 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Notify urls for subscribe url provider://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&category=configurators&check=false&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=20519&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542964281127, urls: [empty://$dubboHost:$portProvider/com.$company.$module.base.api.IXXBaseService?application=$module-base&category=configurators&check=false&default.retries=0&default.timeout=60000&dubbo=2.8.4&generic=false&interface=com.$company.$module.base.api.IXXBaseService&logger=slf4j&methods=$methodList&pid=20519&revision=0.2-SNAPSHOT&side=provider&threads=100&timestamp=1542964281127], dubbo version: 2.8.4, current host: $ipProvider
## 连续多个 "Register / Subscribe" 信息
Nov 23 17:11:21 $dubboHost $module-base 2018-11-23 17:11:21,166 [main] INFO  alibaba.dubbo.common.logger.slf4j.Slf4jLogger (Slf4jLogger.java:42) -  [DUBBO] Dubbo SpringContainer started!, dubbo version: 2.8.4, current host: $ipProvider

问题的分析

上面的日志是上周五出现的问题的相关的日志, 删除了相关的不太影响本文的其他日志, 以及相关信息做了一些 mask

首先是思路 : step1 -> step2 -> step3

step 1. 因为当时生产上正在分销商切换相关的服务, 我首先怀疑的是是不是这个时间段的业务处理的数量有一个突增, 然后导致我们系统这边撑不住了 ??

然后经过后面的日志分析, 发现这段时间的请求其实和平常是差不多的, 然后前后十分钟的处理的请求的数量也是比较均衡的

下面是两个模块依赖于 base 模块的日志统计, 着重需要观察 dep-01 模块, 因为这部分是和业务系统这边对接的, 请求的数量远远大于 dep-02

module-dep-01.log

2018-11-23-16.log调用次数 methodInvocationByTimeCnt 如下
Nov 23 16:50 : 225
Nov 23 16:51 : 235
Nov 23 16:52 : 264
Nov 23 16:53 : 241
Nov 23 16:54 : 220
Nov 23 16:55 : 266
Nov 23 16:56 : 204
Nov 23 16:57 : 216
Nov 23 16:58 : 245
Nov 23 16:59 : 184
2018-11-23-17.log调用次数 methodInvocationByTimeCnt 如下
Nov 23 17:00 : 155
Nov 23 17:01 : 143
Nov 23 17:02 : 143
Nov 23 17:03 : 138
Nov 23 17:04 : 169
Nov 23 17:05 : 158
Nov 23 17:06 : 153
Nov 23 17:07 : 159
Nov 23 17:08 : 188
Nov 23 17:09 : 174
Nov 23 17:10 : 1081
---------------------
2018-11-22-16.log调用次数 methodInvocationByTimeCnt 如下
Nov 22 16:50 : 124
Nov 22 16:51 : 117
Nov 22 16:52 : 132
Nov 22 16:53 : 108
Nov 22 16:54 : 105
Nov 22 16:55 : 103
Nov 22 16:56 : 78
Nov 22 16:57 : 137
Nov 22 16:58 : 109
Nov 22 16:59 : 108
2018-11-22-17.log调用次数 methodInvocationByTimeCnt 如下
Nov 22 17:00 : 109
Nov 22 17:01 : 101
Nov 22 17:02 : 134
Nov 22 17:03 : 113
Nov 22 17:04 : 101
Nov 22 17:05 : 91
Nov 22 17:06 : 121
Nov 22 17:07 : 112
Nov 22 17:08 : 102
Nov 22 17:09 : 109
Nov 22 17:10 : 122

module-dep-02.log

2018-11-23-16.log调用次数 methodInvocationByTimeCnt 如下
Nov 23 16:50 : 23
Nov 23 16:51 : 6
Nov 23 16:52 : 14
Nov 23 16:53 : 35
Nov 23 16:54 : 7
Nov 23 16:55 : 3
Nov 23 16:56 : 30
Nov 23 16:57 : 10
Nov 23 16:58 : 26
Nov 23 16:59 : 20
2018-11-23-17.log调用次数 methodInvocationByTimeCnt 如下
Nov 23 17:00 : 10
Nov 23 17:01 : 12
Nov 23 17:02 : 8
Nov 23 17:03 : 8
Nov 23 17:04 : 19
Nov 23 17:05 : 27
Nov 23 17:06 : 22
Nov 23 17:07 : 22
Nov 23 17:08 : 14
Nov 23 17:09 : 36
Nov 23 17:10 : 16

step 2 : 相关资源被占用了??

从上面的日志可以看出, 确实是如上面总结的 "发现这段时间的请求其实和平常是差不多的, 然后前后十分钟的处理的请求的数量也是比较均衡的"

然后我就怀疑, 是不是 mongo, mysql 的相关的连接这段期间存在问题??, 导致获取连接存在耗时的情况??

因为缺少一些查看 mongo, mysql 连接的方式, 因此上周周末就到此为止了 , 但是看了一下获取 mongo, mysql 的一些默认的超时配置

获取 mongo 连接

获取 mongo 连接的代码如上图, 默认是 2分钟[ConnectionPoolSettings$Builder], 我们系统配置的是 5 秒钟, 如果阻塞也是可能引起线程池耗尽的

获取 mysql 连接

获取 mysql 连接的代码如上图, 不超时[DruidAbstractDataSource.DEFAULT_MAX_WAIT], 我们系统配置的是 1 分钟

.. 这个配置看起来有些怪

然后本周一, 找运维同事要了一下 mongo, mysql 的日志, 以及连接的情况

mongo 这边是正常的, 前后十分钟的链接都很稳定

mysql 这边连接情况 "Aborted Clients" 这个指标偏高, 上周五一成左右, 本周三两成

但是对于这个指标, 我也不是太了解, 而且另外一点就是, 也未必能拿到 "Aborted Clients" 相关的日志

因此本周一的排查, 也差不多是到这里了

这是上周周末排查问题记录的一些日志, 也暂时放在这里

然后 你妹, 看了一下, 然后 看了一下请求的 相关的数量什么的, 没有什么太 特别的地方, 一分钟 也差不多是一百多个, 17点10分的时候 爆炸性的增加了一些, 可能是超时的一部分的订单
因此 我怀疑是 mongo 连接的问题, 可能是 获取 mongo 的链接 开销太大了, 然后 导致大量请求 积压在 $base, 然后 接收请求的 线程池 满了之后, 开始拒绝请求,
然后 差不多是 16:59:06 - 16:59:36 这段时间, $module-dep01, 里面 IXXService 的访问 是第一个 出现异常的,
然后 16:59:06 - 17:00:06 这段期间, 依然 有一部分缓慢处理的, 的部分的 订单处理
这个 下周一 去了 再去确认一下， 看下 上周五的这段时间的 mongo, mysql 的连接的状态呢???,

step 3 : redis 连接没有问题吗 ??

这里有一个点就是, 我没有怀疑另外的一个资源, redis, 因为从上面的日志来看, 实际上是 10 分左右的时候, "redis 相关的异常", 才出来, 然而这个是致命的

本周三再一次出现了这个问题, 然后我们领导看了一下这部分模块的日志, 很快的就定位到了 redis 的这个异常, 然后就跑过来指导了一下我

然后我因为有一些底了, 我觉得可能是 mysql 的连接的问题瑟?, 然后找运维同事看了一下事发五分钟的监控, 发现 "Aborted Clients" 飙到了两成 !!

但是最后问题, 好像是和这个没有什么关系[不过这部分应该是存在一些其他问题], 嘿嘿, 不过附加记录一下

然后之后灵机一动, 我统计了一下 17 点这个时间段的所有的 "Could not get a resource from the pool" 的数量

差不多是 202 个, 然后有两个是 "RemotingException" 记录的, 和其他业务线程记录的有些不同, 因此各个业务线程记录的差不多是 200 个, 然后一个线程打印了两次, 因此和线程数量 100 个是匹配的上的

然后我又统计了一下本周三的日志, "Could not get a resource from the pool" 的数量, 也是 200 次, 然后问题的点好像是在获取 redis 连接这里啊

问题的真正原因是 : 获取 redis 连接是没有超时配置的, 然后 100 个 dubbo请求线程阻塞在了获取 redis 连接的地方, 然后导致抛出了 "Thread pool is EXHAUSTED" 异常

然后问题就来了?, 为什么上周五发生这个情况的时候, 获取 redis 连接的异常是在 17:10 才抛出来呢 ?

脑袋转了一下, "java.lang.InterruptedException", 这是一个关键的点, 这个异常是其他线程中断了 100 个 dubbo请求线程, 然后才抛出来的

因此现在的点, 就是看 谁来中断的了?

case 1. 自然是 dubbo shutdown 的时候通过线程池中断的各个线程??

最开始, 我也这么想, 然后跟踪了一下代码

AbstractServer.close

我觉得可能在 shutdownNow 这里 [我这里的模拟代码和实际情况下的有些差异, 所以我没有判断这个 executor]

然后之后构造了一个 customer 来消费服务, 看看这个线程池这个到底是不是处理业务的线程池, 结果不是这个

这里的几个线程池各有不同, 有各自处理的业务

然后跟踪的 shutdown 相关的钩子函数处理的业务这段差不多对于这里来说就没有太大的意义了

然后 看了一下创建 AllChannelHandler 的线程池, 默认创建的是守护线程

因此, 如果没有手动中断这些线程, 非 daemon 线程都 gg 了, 是不会管这些线程的

然后我又在 Thread. interrupt 打断点 [手动中断的线程]

发现过来的只有这几个线程(池) : zkEventThread, remoteServerHeartBeatExecutors, bossExecutors, workerExecutors

DubboServerHandler 相关的线程不是被其他线程中断的

这里附上一个所有的请求线程都阻塞的一个监控图, +_+

以次例, 我测试了一下 "DubboServerHandler 相关的线程不是被其他线程中断的 " 这个结论, 发现并没有走 catch (InterruptedException ) 处理的相关代码, 没有别的线程中断请求处理线程

case 2. 还有一点日志可以分析

Nov 23 17:10:51 $dubboHost $module-base 2018-11-23 17:10:49,285 [DubboServerHandler-$dubboHost:$portProvider-thread-37] ERROR $company.$module.common.redis.impl.RedisClientTemplate (RedisClientTemplate.java:206) - Could not get a resource from the pool
Nov 23 17:10:51 $dubboHost $module-base redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
Nov 23 17:10:51 $dubboHost $module-base     at redis.clients.util.Pool.getResource(Pool.java:53)
Nov 23 17:10:51 $dubboHost $module-base     at redis.clients.jedis.ShardedJedisPool.getResource(ShardedJedisPool.java:36)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.redis.impl.RedisClientTemplate.getResource(RedisClientTemplate.java:181)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.redis.impl.RedisClientTemplate.doWithCallback(RedisClientTemplate.java:201)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.redis.impl.RedisClientTemplate.get(RedisClientTemplate.java:40)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.RedisBasedCacheService.get0(RedisBasedCacheService.java:92)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.get(BaseCacheService.java:415)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.getOrNull0(BaseCacheService.java:111)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.getOrNull(BaseCacheService.java:489)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.local.service.cache.BaseCacheService.getOrNull(BaseCacheService.java:592)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.aop.CacheHandlerAop.getResult(CacheHandlerAop.java:177)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.common.aop.CacheHandlerAop.doProcess(CacheHandlerAop.java:100)
Nov 23 17:10:51 $dubboHost $module-base     at sun.reflect.GeneratedMethodAccessor181.invoke(Unknown Source)
Nov 23 17:10:51 $dubboHost $module-base     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Nov 23 17:10:51 $dubboHost $module-base     at java.lang.reflect.Method.invoke(Method.java:606)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:62)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
Nov 23 17:10:51 $dubboHost $module-base     at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:655)
Nov 23 17:10:51 $dubboHost $module-base     at com.$company.$module.base.apiImpl.common.StationMapInfoBaseService$$EnhancerBySpringCGLIB$$8065d831.getByAdapterAndOldStationNo(<generated>)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.common.bytecode.Wrapper4.invokeMethod(Wrapper4.java)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:65)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:70)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:132)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:113)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
Nov 23 17:10:51 $dubboHost $module-base     at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
Nov 23 17:10:51 $dubboHost $module-base     at java.lang.Thread.run(Thread.java:745)
Nov 23 17:10:51 $dubboHost $module-base Caused by: java.lang.InterruptedException
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
Nov 23 17:10:51 $dubboHost $module-base     at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2052)
Nov 23 17:10:51 $dubboHost $module-base     at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:524)
Nov 23 17:10:51 $dubboHost $module-base     at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:433)
Nov 23 17:10:51 $dubboHost $module-base     at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:360)
Nov 23 17:10:51 $dubboHost $module-base     at redis.clients.util.Pool.getResource(Pool.java:49)
Nov 23 17:10:51 $dubboHost $module-base     ... 52 more
## 连续的 "Could not get a resource from the pool" 日志信息

通过日志 , 可以发现中断是来自于这里的 takeFirst

GenericObjectPool. brrowObject

LinkedBlockingDeque. takeFirst

## 感觉一下这段话不对, 更新于 2018.12.03 21, 再想想吧

那就说明打印日志的时候, redis 连接池里面的空闲连接被释放出来了, 然后这阻塞的 100 个线程才产生了中断, 然后在外面的 "Pool.getResource" 拦截下来, 打印日志

这里留下了一个疑问 : 那么 redis 连接池中的空闲链接为什么会被占用满了呢?, 然后为什么关闭服务的时候这些占用的连接被释放了呢 ? [不释放这些连接的话, 我们是看不到这些日志的, 这100个请求线程是 daemon 线程]

反正翻了一下代码, 都没有看到可能存在连接泄露的地方

那么之前这么长的时间, 为什么项目没有出现过这个问题呢 ? 这个和 redis 服务器有关系么 ?

100 个请求线程请求资源的时候出现了死锁 ?

啊这个问题, 可能就需要后面在观察下了, 也许需要剖析一下 ShardedJedisPool 的相关代码吧

还是留下了一个问题, 后面再看看吧

后记

这部分记录, 是关于日志部分的, 根据日志追踪的代码关闭的相关钩子函数处理的业务

1. "Run shutdown hook of netty client now" 之后做的事情
NettyClient. addShutdownHook, DubboShutdownHook-NettyClient
这一点在 2.8.4 里面才有, ali 的dubbo 版本里面没有

关闭 NettyClient 引用的相关资源

2. "Run shutdown hook now" 之后做的事情

上面的关闭 zkEventThread, remoteServerHeartBeatExecutors, bossExecutors, workerExecutors 都是在这里处理的

3. "java.util.concurrent.RejectedExecutionException: Worker has already been shutdown" 的上下文以及原因
   bootstrap.releaseExternalResources
   NioServerSocketChannelFactory. releaseExternalResources
   shutdown, 关闭了 AbstractNioSelector. selector
after that -->
   Channels.fireExceptionCaughtLater 去注册处理异常的任务, selector 为 null