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

問題現(xiàn)象

最后發(fā)現(xiàn)線上的zookeeper的日志zookeeper.out 文件居然有6G,后來設(shè)置下日志為滾動輸出,參考:

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

但是改了之后,發(fā)現(xiàn)一天的日志量就是100多M,滾動日志一天就被沖掉了,這個不科學(xué)。

再仔細(xì)查看下日志里的內(nèi)容,發(fā)現(xiàn)有很多連接建立好,馬上又?jǐn)嚅_:

  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查看網(wǎng)絡(luò)連接狀態(tài)

到client的服務(wù)器上查看連接的狀態(tài):

  1. netstat -antp | grep 2181  

發(fā)現(xiàn)有很多TIME_WAIT狀態(tài)的連接:

  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狀態(tài)的連接是看不到進(jìn)程號的。搜索研究了下netstat的參數(shù),發(fā)現(xiàn)沒有辦法輸出TIME_WAIT狀態(tài)的連接的pid,只好嘗試其它的辦法。

再用 jstack -l pid 來查看進(jìn)程的線程棧,也沒有發(fā)現(xiàn)什么異常的東東。查看到有幾個zookeeper連接的線程,但也是正常狀態(tài)。

再檢查了機器的IO,CPU,內(nèi)存,也沒有異常的情況。

沒找到什么有用的信息,只好再研究下netstat的參數(shù):
發(fā)現(xiàn)用 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  

發(fā)現(xiàn)user是root。于是以為是非Java應(yīng)用,在不斷地連接zookeeper。于是停止java程序,發(fā)現(xiàn)沒有TIME_WAIT連接了。
但是確認(rèn)是Java應(yīng)用的問題,于是再重啟Java應(yīng)用,但沒有再發(fā)現(xiàn)TIME_WAIT情況。很詭異。

問題不能重現(xiàn)了,相當(dāng)?shù)牡疤?。忽然想到線上的應(yīng)用也許也有這個問題,于是到線下zookeeper服務(wù)器上查看了下,果然發(fā)現(xiàn)有同樣的問題。

用tcpdump抓包和wireshark分析

先用tcpdump來查看下具體的網(wǎng)絡(luò)連接,發(fā)現(xiàn)的確是連接連上再斷開。于是先保存成cap文件,再用wireshark來分析:

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

查看應(yīng)用日志,發(fā)現(xiàn)Tomcat webcontext沒有正常啟動

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

還好,去下btrace之后,先去看了下應(yīng)用的日志,發(fā)現(xiàn)應(yīng)用報了一些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)  

因為有經(jīng)驗了,馬上知道這個Tomcat因為其它原因webcontext實始化失敗退出,然后后面的一些線程繼續(xù)跑時,會拋出ClassLoader,或者Class not found的異常。

于是猜想到原因了:

Tomcat webcontext初始化失敗,zookeeper的重連線程自動不斷重連。

但是為什么重啟Tomcat之后,沒有重現(xiàn)TIME_WAIT的情況?

再折騰了下,發(fā)現(xiàn)只有當(dāng)zookeeper重啟后,應(yīng)用才會出現(xiàn)大量的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的連接相關(guān)的bean;
  3. 這時zkClient(獨立線程)已經(jīng)連接上服務(wù)器了,但是classloader沒有加載到org/apache/zookeeper/proto/SetWatches類;
  4. spring初始化失敗,導(dǎo)致Tomcat webcontext初始化也失敗,應(yīng)用在掛起狀態(tài),但zkClient線程還是正常的;
  5. zookeeper服務(wù)器重啟,zkClient開始重連,連接上zookeeper服務(wù)器;
  6. zkClient觸發(fā)watch的一些代碼,ClassLoader嘗試加載org/apache/zookeeper/proto/SetWatches類,但是發(fā)現(xiàn)找不到類,于是拋出異常;
  7. zkClient捕獲到異常,認(rèn)為重連失敗,close掉connection,休眠幾秒之后,再次重連;

于是出現(xiàn)了zkClient反復(fù)重試連接zookeeper服務(wù)器,而且都是秒連秒斷的情況。


總結(jié):

這次排查花了不少時間,有個原因是開始沒有去查看應(yīng)用的日志,以為應(yīng)用的是正常的,而且zookeeper.out的輸出日志很多,也有一段時間了。

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

所以,主要精力放在各種網(wǎng)絡(luò)連接狀態(tài)的獲取上。對去查看應(yīng)用日志比較排斥。

還有一個原因是,問題比較詭異,有點難重現(xiàn),當(dāng)發(fā)現(xiàn)可以重現(xiàn)時,基本已經(jīng)發(fā)現(xiàn)問題所在了。

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