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

标签： 基础技术 debug Zookeeper | 发表时间：2016-12-30 07:00 | 作者：liuchi1993
出处：http://www.importnew.com

问题现象

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

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

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

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

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

相关文章

相关 [zookeeper 原因] 推荐：

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

- - ImportNew
最后发现线上的zookeeper的日志zookeeper.out 文件居然有6G，后来设置下日志为滚动输出，参考：. 但是改了之后，发现一天的日志量就是100多M，滚动日志一天就被冲掉了，这个不科学. 再仔细查看下日志里的内容，发现有很多连接建立好，马上又断开：. 从日志输出的时间来看，秒连秒断，非常诡异.

zookeeper( 转)

- - 企业架构 - ITeye博客
转自：http://qindongliang.iteye.com/category/299318. 分布式助手Zookeeper（一）. Zookeeper最早是Hadoop的一个子项目，主要为Hadoop生态系统中一些列组件提供统一的分布式协作服务，在2010年10月升级成Apache Software .

ZooKeeper监控

- - 淘宝网通用产品团队博客
        在公司内部，有不少应用已经强依赖zookeeper，比如meta和精卫系统，zookeeper的工作状态直接影响它们的正常工作. 目前开源世界中暂没有一个比较成熟的zk-monitor,公司内部的各个zookeeper运行也都是无监控，无报表状态. 目前zookeeper-monitor能做哪些事情，讲到这个，首先来看看哪些因素对zookeeper正常工作比较大的影响：.

zookeeper原理

- - CSDN博客云计算推荐文章
1.为了解决分布式事务性一致的问题. 2.文件系统也是一个树形的文件系统，但比linux系统简单，不区分文件和文件夹，所有的文件统一称为znode. 3.znode的作用：存放数据，但上限是1M ;存放ACL(access control list)访问控制列表，每个znode被创建的时候，都会带有一个ACL，身份验证方式有三种：digest(用户名密码验证)，host(主机名验证)，ip(ip验证) ，ACL到底有哪些权限呢.

Zookeeper Client简介

- - zzm
直接使用zk的api实现业务功能比较繁琐. 因为要处理session loss，session expire等异常，在发生这些异常后进行重连. 又因为ZK的watcher是一次性的，如果要基于wather实现发布/订阅模式，还要自己包装一下，将一次性订阅包装成持久订阅. 另外如果要使用抽象级别更高的功能，比如分布式锁，leader选举等，还要自己额外做很多事情.

zookeeper 理论

- - zzm
引用官方的说法：“Zookeeper是一个高性能，分布式的，开源分布式应用协调服务. 它提供了简单原始的功能，分布式应用可以基于它实现更高级 的服务，比如同步，配置管理，集群管理，名空间. 它被设计为易于编程，使用文件系统目录树作为数据模型. 服务端跑在java上，提供java和C的客户端 API”.

ZooKeeper 入门

- - 企业架构 - ITeye博客
ZooKeeper是一个高可用的分布式数据管理与系统协调框架. 基于对Paxos算法的实现，使该框架保证了分布式环境中数据的强一致性，也正是基于这样的特性，使得ZooKeeper解决很多分布式问题. 网上对ZK的应用场景也有不少介绍，本文将结合作者身边的项目例子，系统地对ZK的应用场景进行一个分门归类的介绍.

zookeeper场景

- - 企业架构 - ITeye博客
发布与订阅模型，即所谓的配置中心，顾名思义就是发布者将数据发布到ZK节点上，供订阅者动态获取数据，实现配置信息的集中式管理和动态更新. 例如全局的配置信息，服务式服务框架的服务地址列表等就非常适合使用. 应用中用到的一些配置信息放到ZK上进行集中管理. 这类场景通常是这样：应用在启动的时候会主动来获取一次配置，同时，在节点上注册一个Watcher，这样一来，以后每次配置有更新的时候，都会实时通知到订阅的客户端，从来达到获取最新配置信息的目的.

Zookeeper的Session

- - 行业应用 - ITeye博客
介绍一下基于zookeeper的一些API的编程. 在此之前，我们先来熟悉一下相关知识：. Zookeeper的Session：. （1）客户端和server间采用长连接. （2）连接建立后，server产生session ID（64位）返还给客户端. （3）客户端定期发送ping包来检查和保持和server的连接.

Paxos与zookeeper

- - 互联网 - ITeye博客
1，什么是Paxos算法. Paxos算法是分布式计算领域中一个非常重要的算法，主要解决分布式系统如何就某个值（决议）达成一致的问题. 一个典型的场景是分布式数据库的一致问题：如果分布式数据库的各个节点初始状态一致，又能执行相同的操作序列，那么最后能达到一个一致的状态. 但是如何保证在每个节点上执行相同的命令序列呢.