Zookeeper用戶端錯誤：Packet len* is out of range!

這是一個生産環境使用zookeeper異常的情況，錯誤是java.io.IOException: Packet len8854970 is out of range!。然後就換了一個namespace，就沒有在出錯，以為是偶然發生，是以沒有重視。但是年後居然又出現問題，才意識到嚴重性。分析之後發現，每隔一段時間，某一個znode節點下超過用戶端所設定的大小，用戶端連接配接會失敗，zkCli.sh操作該節點也會失敗。如果對于簡單依賴zookeeper的系統，這種錯誤可以容忍（但是必須解決）；如果是強依賴zookeeper的系統，這種錯誤可以說是災難。

1 發現問題

問題的發現比較曲折，首先是發現伺服器磁盤寫滿了（吐槽下運維居然沒有對磁盤添加監控），緻使項目中的報警功能失效。然後就把無用日志删除，習（tou）慣（lan）的把異常的應用重新開機了下。幸好有個比較好的習慣就是，項目啟動成功後，都會打看日志跟蹤下，确定無誤才會關掉終端。結果就被錯誤日志刷屏了：

ERROR 2017-02-20 10:45:44,729 [Curator-Framework-0] o.a.c.f.i.CuratorFrameworkImpl.logError() (CuratorFrameworkImpl.java:557) - Background retry gave up
org.apache.curator.CuratorConnectionLossException: KeeperErrorCode = ConnectionLoss
        at org.apache.curator.framework.imps.CuratorFrameworkImpl.performBackgroundOperation(CuratorFrameworkImpl.java:838) [curator-framework-2.10.0.jar:na]
        at org.apache.curator.framework.imps.CuratorFrameworkImpl.backgroundOperationsLoop(CuratorFrameworkImpl.java:809) [curator-framework-2.10.0.jar:na]
        at org.apache.curator.framework.imps.CuratorFrameworkImpl.access$300(CuratorFrameworkImpl.java:64) [curator-framework-2.10.0.jar:na]
        at org.apache.curator.framework.imps.CuratorFrameworkImpl$4.call(CuratorFrameworkImpl.java:267) [curator-framework-2.10.0.jar:na]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_111]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_111]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_111]
      

因為zookeeper的用戶端使用的是Apache Curator，與zookeeper的連接配接斷開會重新建立連接配接，是以會出現大量的連接配接失敗異常。

2 分析問題

在這個項目中，對于zookeepr的使用有下面幾種場景：

服務狀态資料：将服務狀态寫入znode節點

服務注冊：将服務位址寫入znode節點

服務發現：擷取znode節點中的可用服務位址

監聽節點：監聽某個znode節點或該節點的位元組點狀态

這幾種情況都需要與zookeeper的znode節點建立連接配接，然後執行操作。根據錯誤提示，java.io.IOException: Packet len8854970 is out of range!，out of range就是超過了某個限制，隻能檢視代碼了。

protected final ByteBuffer lenBuffer = ByteBuffer.allocateDirect(4);
protected ByteBuffer incomingBuffer = lenBuffer;

protected void readLength() throws IOException {
    int len = incomingBuffer.getInt();
    if (len < 0 || len >= ClientCnxn.packetLen) {
        throw new IOException("Packet len" + len + " is out of range!");
    }
    incomingBuffer = ByteBuffer.allocate(len);
}

public static final int packetLen = Integer.getInteger("jute.maxbuffer", 4096 * 1024);
      

從代碼就能夠很容易的看出，這個錯誤是因為len小于0或大于packetLen，根據代碼邏輯，len不小于0，那就是大于packetLen。而packetLen的值是jute.maxbuffer系統變量定義或預設的4096 * 1024（4M）。

繼續深扒代碼，因為代碼比較長，這裡就不寫了。大體邏輯就是，建立與zookeeper連接配接之後，要對某個節點進行讀寫操作，為了提高吞吐量，先判斷下該節點資料量大小是否超過設定的jute.maxbuffer，如果是，就抛出異常。在zookeeper用戶端中，這一部分異常的處理比較粗糙，因為注釋上也寫着“this is ugly, you have a better way speak up”。

3 解決問題

根據上面的糾錯，答案就很明顯了。隻有兩種方案：

把待操作節點的大小減下來，小于預設的4M

把預設的jute.maxbuffer大小提高

對于第一種方式，需要根據自身具體情況具體操作。這裡沒有什麼有效建議。

對于第二種方式，就比較簡單了。隻要在建立Zookeeper對象之前，設定System.setProperty("jute.maxbuffer", 4096 * 1024 * 10 + "");，這裡的大小根據自己的系統設定，我這裡隻是一個測試值（如果設定太大，這個節點真的比較大的話，會影響吞吐）。

因為我這裡使用的是Apache Curator，不需要自己建立Zookeeper對象，是以需要在建立CuratorFramework對象之前添加這個變量。

解決問題要徹底，不能留下禍患。（此處應該伴随陰笑和冷風。。。）

java用戶端的問題解決了，但是通過zkCli.sh連接配接時，還是會出現這個問題。報錯如下：

2017-02-20 12:08:03,999 [myid:] - WARN  [main-SendThread(localhost:2181):ClientCnxn$SendThread@1102] - Session 0x1591b713cefd2b3 for server localhost/127.0.0.1:2181, unexpected error, closing socket connection and attempting reconnect
java.io.IOException: Packet len8854970 is out of range!
    at org.apache.zookeeper.ClientCnxnSocket.readLength(ClientCnxnSocket.java:112)
    at org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:79)
    at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:366)
    at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1081)

WATCHER::

WatchedEvent state:Disconnected type:None path:null
Exception in thread "main" org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /it-monitor/com/wfj/monitor/sales-overview-info
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:99)
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
    at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1472)
    at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1500)
    at org.apache.zookeeper.ZKUtil.listSubTreeBFS(ZKUtil.java:114)
    at org.apache.zookeeper.ZKUtil.deleteRecursive(ZKUtil.java:49)
    at org.apache.zookeeper.ZooKeeperMain.processZKCmd(ZooKeeperMain.java:703)
    at org.apache.zookeeper.ZooKeeperMain.processCmd(ZooKeeperMain.java:588)
    at org.apache.zookeeper.ZooKeeperMain.executeLine(ZooKeeperMain.java:360)
    at org.apache.zookeeper.ZooKeeperMain.run(ZooKeeperMain.java:323)
    at org.apache.zookeeper.ZooKeeperMain.main(ZooKeeperMain.java:282)
      

找到zkCli.sh，最下面的java指令中添加對jute.maxbuffer的定義（使用D參數）：

"$JAVA" "-Dzookeeper.log.dir=${ZOO_LOG_DIR}" "-Dzookeeper.root.logger=${ZOO_LOG4J_PROP}" \
     "-Djute.maxbuffer=41943040" \
     -cp "$CLASSPATH" $CLIENT_JVMFLAGS $JVMFLAGS \
     org.apache.zookeeper.ZooKeeperMain "$@"
      

當然，為了運維友善，可以把jute.maxbuffer的值設定成變量，通過修改配置來設定值。避免因為修改sh腳本出現其他問題。