zookeeper 大量链接断开重连缘由排查

转自：http://blog.csdn.net/hengyunabc/article/details/41450003?utm_source=tuicool&utm_medium=referral

 

问题现象

最后发现线上的zookeeper的日志zookeeper.out 文件竟然有6G，后来设置下日志为滚动输出，参考：

http://blog.csdn.net/hengyunabc/article/details/19006911

可是改了以后，发现一天的日志量就是100多M，滚动日志一天就被冲掉了，这个不科学。

再仔细查看下日志里的内容，发现有不少链接创建好，立刻又断开：

 

2014-11-24 15:38:33,348 [myid:3] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed socket connection for client /10.0.0.3:47772 (no session established for client)
2014-11-24 15:38:33,682 [myid:3] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection from /10.0.0.3:32119
2014-11-24 15:38:33,682 [myid:3] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@349] - caught end of stream exception
EndOfStreamException: Unable to read additional data from client sessionid 0x0, likely client has closed socket
        at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
        at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
        at java.lang.Thread.run(Thread.java:745)
2014-11-24 15:38:33,682 [myid:3] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed socket connection for client /10.0.0.0:32119 (no session established for client)

从日志输出的时间来看，秒连秒断，很是诡异。

 

排查问题

用netstat查看网络链接状态

到client的服务器上查看链接的状态：

 

netstat -antp | grep 2181

发现有不少TIME_WAIT状态的链接：

 

 

tcp        0      0 10.0.0.3:44269         10.0.1.77:2181         TIME_WAIT   -
tcp        0      0 10.0.0.3:43646         10.0.1.77:2181         TIME_WAIT   -
tcp        0      0 10.0.0.3:44184         10.0.1.77:2181         TIME_WAIT   -
tcp        0      0 10.0.0.3:44026         10.0.1.77:2181         TIME_WAIT   -
tcp        0      0 10.0.0.3:43766         10.0.1.77:2181         TIME_WAIT   -

可是TIME_WAIT状态的链接是看不到进程号的。搜索研究了下netstat的参数，发现没有办法输出TIME_WAIT状态的链接的pid，只好尝试其它的办法。

 

再用 jstack -l pid 来查看进程的线程栈，也没有发现什么异常的东东。查看到有几个zookeeper链接的线程，但也是正常状态。

再检查了机器的IO，CPU，内存，也没有异常的状况。

没找到什么有用的信息，只好再研究下netstat的参数：
发现用 netstat -ae 输出了一些信息：

tcp        0      0 10.0.0.3:41772     10.0.1.77:eforward     TIME_WAIT   root       0
tcp        0      0 10.0.0.3:41412     10.0.1.77:eforward     TIME_WAIT   root       0
tcp        0      0 10.0.0.3:24226     10.0.1.77:2181         TIME_WAIT   root       0
tcp        0      0 10.0.0.3:24623     10.0.1.77:2181         TIME_WAIT   root       0

发现user是root。因而觉得是非Java应用，在不断地链接zookeeper。因而中止java程序，发现没有TIME_WAIT链接了。
可是确认是Java应用的问题，因而再重启Java应用，但没有再发现TIME_WAIT状况。很诡异。

 

问题不能重现了，至关的蛋疼。突然想到线上的应用也许也有这个问题，因而到线下zookeeper服务器上查看了下，果真发现有一样的问题。

用tcpdump抓包和wireshark分析

先用tcpdump来查看下具体的网络链接，发现的确是链接连上再断开。因而先保存成cap文件，再用wireshark来分析：

 

tcpdump -vv host 192.168.66.27 and port 2181 -w 2181.cap

可是也没有发现什么有用信息，的确是TCP链接连上，再FIN，ACK链接断开。

 

查看应用日志，发现Tomcat webcontext没有正常启动

没办法了，有两种考虑，一个是用strace，二是用btrace。可是btrace很久没用过了，不太想再去看例子文档。

还好，去下btrace以后，先去看了下应用的日志，发现应用报了一些ClassLoader的错误：

 

Nov 24, 2014 7:32:43 PM org.apache.catalina.loader.WebappClassLoader loadClass
INFO: Illegal access: this web application instance has been stopped already.  Could not load org.apache.zookeeper.ClientCnxnSocketNIO.  The eventual following stack trace is caused by an err
or thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact.
java.lang.IllegalStateException
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1564)
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1523)
        at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:198)
        at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)
        at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:132)
        at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:107)
        at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:99)

由于有经验了，立刻知道这个Tomcat由于其它缘由webcontext实始化失败退出，而后后面的一些线程继续跑时，会抛出ClassLoader，或者Class not found的异常。

 

因而猜测到缘由了：

Tomcat webcontext初始化失败，zookeeper的重连线程自动不断重连。

可是为何重启Tomcat以后，没有重现TIME_WAIT的状况？

再折腾了下，发现只有当zookeeper重启后，应用才会出现大量的TIME_WAIT链接。报的是下面这个异常：

 

2014-11-24 19:42:44,399 [Thread-3-SendThread(192.168.90.147:4181)] WARN  org.apache.zookeeper.ClientCnxn - Session 0x149c21809731325 for server 192.168.90.147/192.168.90.147:4181, unexpected error, closing socket connection and attempting reconnect
java.lang.NoClassDefFoundError: org/apache/zookeeper/proto/SetWatches
        at org.apache.zookeeper.ClientCnxn$SendThread.primeConnection(ClientCnxn.java:867) ~[zookeeper-3.4.5.jar:3.4.5-1392090]
        at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:352) ~[zookeeper-3.4.5.jar:3.4.5-1392090]

这个异常的缘由，是某些zookeeper的类没有加载到。

 

最终缘由分析

梳理下整个流程：

 

1. Tomcat启动，初始化webcontext；
2. 初始化spring, spring初始某些些bean，这些bean包括了zookeeper的链接相关的bean；
3. 这时zkClient（独立线程）已经链接上服务器了，可是classloader没有加载到org/apache/zookeeper/proto/SetWatches类；
4. spring初始化失败，致使Tomcat webcontext初始化也失败，应用在挂起状态，但zkClient线程仍是正常的；
5. zookeeper服务器重启，zkClient开始重连，链接上zookeeper服务器；
6. zkClient触发watch的一些代码，ClassLoader尝试加载org/apache/zookeeper/proto/SetWatches类，可是发现找不到类，因而抛出异常；
7. zkClient捕获到异常，认为重连失败，close掉connection，休眠几秒以后，再次重连；

 

因而出现了zkClient反复重试链接zookeeper服务器，并且都是秒连秒断的状况。

 

总结：

此次排查花了很多时间，有个缘由是开始没有去查看应用的日志，觉得应用的是正常的，并且zookeeper.out的输出日志不少，也有一段时间了。

还有线上的应用比较坑爹，活动已通过期好久了，可是程序仍是线上跑，也没有人管是否出问题了。

因此，主要精力放在各类网络链接状态的获取上。对去查看应用日志比较排斥。

还有一个缘由是，问题比较诡异，有点难重现，当发现能够重现时，基本已经发现问题所在了。

排查问题仍是要耐心收集信息，再分析判断。