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的輸出日誌不少，也有一段時間了。

還有線上的應用比較坑爹，活動已通過期好久了，可是程序仍是線上跑，也沒有人管是否出問題了。

因此，主要精力放在各類網絡鏈接狀態的獲取上。對去查看應用日誌比較排斥。

還有一個緣由是，問題比較詭異，有點難重現，當發現能夠重現時，基本已經發現問題所在了。

排查問題仍是要耐心收集信息，再分析判斷。