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

最近发现线上的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的类没有加载到。

最终原因分析
梳理下整个流程：

Tomcat启动，初始化webcontext；
初始化spring, spring初始某些些bean，这些bean包括了zookeeper的连接相关的bean；
这时zkClient（独立线程）已经连接上服务器了，但是classloader没有加载到org/apache/zookeeper/proto/SetWatches类；
spring初始化失败，导致Tomcat webcontext初始化也失败，应用在挂起状态，但zkClient线程还是正常的；
zookeeper服务器重启，zkClient开始重连，连接上zookeeper服务器；
zkClient触发watch的一些代码，ClassLoader尝试加载org/apache/zookeeper/proto/SetWatches类，但是发现找不到类，于是抛出异常；
zkClient捕获到异常，认为重连失败，close掉connection，休眠几秒之后，再次重连；
于是出现了zkClient反复重试连接zookeeper服务器，而且都是秒连秒断的情况。

总结：
这次排查花了不少时间，有个原因是开始没有去查看应用的日志，以为应用的是正常的，而且zookeeper.out的输出日志很多，也有一段时间了。
还有线上的应用比较坑爹，活动已经过期很久了，但是程序还是线上跑，也没有人管是否出问题了。
所以，主要精力放在各种网络连接状态的获取上。对去查看应用日志比较排斥。
还有一个原因是，问题比较诡异，有点难重现，当发现可以重现时，基本已经发现问题所在了。
排查问题还是要耐心收集信息，再分析判断。

zookeeper连接，报caught end of stream exception EndOfStreamException: Unable to read additional data fro相关推荐

ZooKeeper只完美解决Unable to read additional data from server sessionid 0x0报错问题,并带你深度理解ZooKeeper内部机制之选举机制
ZooKeeper只完美解决Unable to read additional data from server sessionid 0x0报错问题,并带你深度理解ZooKeeper内部机制之选举机制 ...
Zookeeper报错：Unable to read additional data from server sessionid 0x
报错信息 INFO [main-SendThread(localhost:12181):ClientCnxn$SendThread@959] - Socket connection establish ...
Zookeeper客户端错误 Unable to read additional data from server
发现问题: 线上环境收到错误告警邮件,错误信息 keeperErrorCode = ConnectionLoss 解决问题: 1.分析错误信息得出,zk连接出了问题,先重启项目(项目重启后就恢复了正常 ...
zookeeper Unable to read additional data from server sessionid 0x0
问题描述项目是springboot 项目,通过dubbo 对各个模块进行调用,在项目启动的时候,zookeeper 客户端报如下错误. Unable to read additional data ...
注册不上zookeeper无报错_Zookeeper 跨区高可用方案
最近由于业务需求,测试各种组件的高可用性.由于我们的环境在AWS 北京部署.只有两个Aviable Zone(可用区). 注释:有两个数据中心,相互需要做容灾的需求,和本文测试的情况是相同的. 而Zo ...
hbase 查询设置超时_hbase master挂掉-zookeeper连接超时原因
并行运行hbase删表,建表操作,多个表多个region,导致hbase挂掉.查看日志: 从日志中可以看出GC时间过长导致zookeeper连接超时,master退出.(是master退出而不是reg ...
[解决] HiveServer2中使用jdbc访问hbase时导致ZooKeeper连接持续增加的解决
最近在监控中发现HiveServer2连接到zookeeper里的连接持续上涨,很奇怪,虽然知道HiveServer2支持并发连接,使用ZooKeeper来管理Hive表的读写锁,但我们的环境并不需要 ...
JUnit报错：Java.lang.Exception: No runnable methods解决方案
JUnit报错:Java.lang.Exception: No runnable methods解决方案参考文章: (1)JUnit报错:Java.lang.Exception: No runnab ...
Windos环境下kafka配置启动Zookeeper时,报错：Invalid config, exiting abnormally.
Windos环境下kafka配置启动ZooKeeper时,报错:Invalid config, exiting abnormally. 执行命令: D:\kafkaOnWindows\kafka_2. ...

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

zookeeper连接，报caught end of stream exception EndOfStreamException: Unable to read additional data fro相关推荐

最新文章

热门文章