zookeeper 大量连接断开重连原因排查

问题现象

最后发现线上的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的输出日志很多，也有一段时间了。

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

所以，主要精力放在各种网络连接状态的获取上。对去查看应用日志比较排斥。

还有一个原因是，问题比较诡异，有点难重现，当发现可以重现时，基本已经发现问题所在了。

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