zookeeper连接，报caught end of stream exception EndOfStreamException: Unable to read additional data from client

问题现象

最近发现线上的zookeeper的日志zookeeper.out 文件居然有6G，后来设置下日志为滚动输出，但是改了之后，发现一天的日志量就是100多M，滚动日志一天就被冲掉了，这个不科学。

再仔细查看下日志里的内容，发现有很多连接建立好，马上又断开：

2016-09-19 22:48:54,347 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /10.0.20.101:54584 (no session established for client)
2016-09-19 22:48:54,351 [myid:] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection from /10.0.20.141:37713
2016-09-19 22:48:54,351 [myid:] - WARN  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@357] - 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:228)
    at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
    at java.lang.Thread.run(Thread.java:662)

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

排查问题

用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的类没有加载到。