from:http://blog.csdn.net/zheng0518/article/details/44943357

問題現象

最后發現線上的zookeeper的日志zookeeper.out 文件居然有6G，后來設置下日志為滾動輸出，參考：

http://blog.csdn.net/hengyunabc/article/details/19006911

但是改了之后，發現一天的日志量就是100多M，滾動日志一天就被沖掉了，這個不科學。

再仔細查看下日志里的內容，發現有很多連接建立好，馬上又斷開：

  1. 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)  
  2. 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  
  3. 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  
  4. EndOfStreamException: Unable to read additional data from client sessionid 0x0, likely client has closed socket  
  5.         at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)  
  6.         at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)  
  7.         at java.lang.Thread.run(Thread.java:745)  
  8. 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的服務器上查看連接的狀態：

  1. netstat -antp | grep 2181  

發現有很多TIME_WAIT狀態的連接：

  1. tcp        0      0 10.0.0.3:44269         10.0.1.77:2181         TIME_WAIT   -                     
  2. tcp        0      0 10.0.0.3:43646         10.0.1.77:2181         TIME_WAIT   -                     
  3. tcp        0      0 10.0.0.3:44184         10.0.1.77:2181         TIME_WAIT   -                     
  4. tcp        0      0 10.0.0.3:44026         10.0.1.77:2181         TIME_WAIT   -                     
  5. 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 輸出了一些信息：

  1. tcp        0      0 10.0.0.3:41772     10.0.1.77:eforward     TIME_WAIT   root       0            
  2. tcp        0      0 10.0.0.3:41412     10.0.1.77:eforward     TIME_WAIT   root       0            
  3. tcp        0      0 10.0.0.3:24226     10.0.1.77:2181         TIME_WAIT   root       0            
  4. 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來分析：

  1. tcpdump -vv host 192.168.66.27 and port 2181 -w 2181.cap  
但是也沒有發現什么有用信息，的確是TCP連接連上，再FIN，ACK連接斷開。

查看應用日志，發現Tomcat webcontext沒有正常啟動

沒辦法了，有兩種考慮，一個是用strace，二是用btrace。但是btrace好久沒用過了，不太想再去看例子文檔。

還好，去下btrace之后，先去看了下應用的日志，發現應用報了一些ClassLoader的錯誤：

  1. Nov 24, 2014 7:32:43 PM org.apache.catalina.loader.WebappClassLoader loadClass  
  2. 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  
  3. or thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access, and has no functional impact.  
  4. java.lang.IllegalStateException  
  5.         at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1564)  
  6.         at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1523)  
  7.         at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:198)  
  8.         at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:226)  
  9.         at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:132)  
  10.         at ch.qos.logback.classic.spi.PackagingDataCalculator.populateUncommonFrames(PackagingDataCalculator.java:107)  
  11.         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連接。報的是下面這個異常：

  1. 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  
  2. java.lang.NoClassDefFoundError: org/apache/zookeeper/proto/SetWatches  
  3.         at org.apache.zookeeper.ClientCnxn$SendThread.primeConnection(ClientCnxn.java:867) ~[zookeeper-3.4.5.jar:3.4.5-1392090]  
  4.         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的輸出日志很多，也有一段時間了。

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

所以，主要精力放在各種網絡連接狀態的獲取上。對去查看應用日志比較排斥。

還有一個原因是，問題比較詭異，有點難重現，當發現可以重現時，基本已經發現問題所在了。

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