Return-Path: X-Original-To: apmail-zookeeper-user-archive@www.apache.org Delivered-To: apmail-zookeeper-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 8EC6311329 for ; Wed, 17 Sep 2014 06:48:09 +0000 (UTC) Received: (qmail 70527 invoked by uid 500); 17 Sep 2014 06:48:08 -0000 Delivered-To: apmail-zookeeper-user-archive@zookeeper.apache.org Received: (qmail 70475 invoked by uid 500); 17 Sep 2014 06:48:08 -0000 Mailing-List: contact user-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@zookeeper.apache.org Delivered-To: mailing list user@zookeeper.apache.org Received: (qmail 70459 invoked by uid 99); 17 Sep 2014 06:48:08 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 17 Sep 2014 06:48:08 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS,WEIRD_PORT X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of tobeg3oogle@gmail.com designates 209.85.217.182 as permitted sender) Received: from [209.85.217.182] (HELO mail-lb0-f182.google.com) (209.85.217.182) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 17 Sep 2014 06:48:03 +0000 Received: by mail-lb0-f182.google.com with SMTP id u10so1225377lbd.13 for ; Tue, 16 Sep 2014 23:47:41 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; bh=Gea5jLhVdnoUbzhBrHdgyy8HzzWtLEiTlK/5FqNONQw=; b=usH5VE0Bj/qawjUairF5YxYMZ5VDbv/YcSjz+T+FVuSyvff4OdlSo2+IOeWYdtbqlk oz3MbFa5GT/XAyztcRskP8rOKKlHddYvnR57bOOjk8Yf9URqWkVde8R4C+ACRXYODK93 tDfecz2LLe1npZqan/J2weTmix+Q1K1CmMPH5vQaikwTkaDrk8EdcVdwyi+Ml0UIJVdd h4aOxb7Vj/GYT7lOI55ryJRTF0NL68Xn8f9XjvCtI/7NNyeEpL6TaJobaC5HdR/uHbzR QzIQkaoUltpzGwRq/MifjNyCtiKTCoU5gGJHoHVvp7+fzcD11mWoeQo6gS8FdKkRTAHt GO8Q== MIME-Version: 1.0 X-Received: by 10.153.11.132 with SMTP id ei4mr42022491lad.24.1410936461363; Tue, 16 Sep 2014 23:47:41 -0700 (PDT) Received: by 10.25.25.149 with HTTP; Tue, 16 Sep 2014 23:47:41 -0700 (PDT) In-Reply-To: References: Date: Wed, 17 Sep 2014 14:47:41 +0800 Message-ID: Subject: Re: Too many "Broken pipe" in ZooKeeper log From: tobe To: "user@zookeeper.apache.org" Content-Type: multipart/alternative; boundary=001a1134787a948e0b05033d3ece X-Virus-Checked: Checked by ClamAV on apache.org --001a1134787a948e0b05033d3ece Content-Type: text/plain; charset=UTF-8 @patrick The ports of these commands are sequential. Here're 48668, 48669, 48670. So is it the periodically check of ZooKeeper? We mainly use ZooKeeper for HDFS and HBase. Other processes in this server will not sent 4lw to ZooKeeper. On Wed, Sep 17, 2014 at 2:19 PM, tobe wrote: > > I have found that the command is called from the same host and run `stat`, > `wchs`, `wchc` and `cons` as well. Here'is log from another ZooKeeper > cluster. It works well because it doesn't have a lot of znodes. But I > wonder why it call the commands frequently? We're using ZooKeeper-3.4.4 and > any patch about this? > > Log from 10.0.4.161 ZooKeeper: > 2014-09-17,08:26:38,336 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Processing stat command from /10.0.4.161:48668 > 2014-09-17,08:26:38,336 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Stat command output > 2014-09-17,08:26:38,337 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Closed socket connection for client /10.0.4.161:48668 (no > session established for client) > 2014-09-17,08:26:38,398 INFO > org.apache.zookeeper.server.NIOServerCnxnFactory: [myid:0] Accepted socket > connection from /10.0.4.172:62393 > 2014-09-17,08:26:38,398 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] Client attempting to establish new session at /10.0.4.172:62393 > 2014-09-17,08:26:38,399 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] Established session 0x4833538b30989d with negotiated timeout 30000 > for client /10.0.4.172:62393 > 2014-09-17,08:26:38,400 INFO > org.apache.zookeeper.server.auth.SaslServerCallbackHandler: [myid:0] > Successfully authenticated client: > authenticationID=hbase_srv/hadoop@XIAOMI.HADOOP; > authorizationID=hbase_srv/hadoop@XIAOMI.HADOOP. > 2014-09-17,08:26:38,400 INFO > org.apache.zookeeper.server.auth.SaslServerCallbackHandler: [myid:0] > Setting authorizedID: hbase_srv > 2014-09-17,08:26:38,400 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] adding SASL authorization for authorizationID: hbase_srv > 2014-09-17,08:26:38,403 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Closed socket connection for client /10.0.4.172:62393 which had > sessionid 0x4833538b30989d > 2014-09-17,08:26:38,526 INFO > org.apache.zookeeper.server.NIOServerCnxnFactory: [myid:0] Accepted socket > connection from /10.0.4.161:48669 > 2014-09-17,08:26:38,526 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Processing wchs command from /10.0.4.161:48669 > 2014-09-17,08:26:38,527 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Closed socket connection for client /10.0.4.161:48669 (no > session established for client) > 2014-09-17,08:26:38,587 INFO > org.apache.zookeeper.server.NIOServerCnxnFactory: [myid:0] Accepted socket > connection from /10.0.4.171:50026 > 2014-09-17,08:26:38,588 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] Client attempting to establish new session at /10.0.4.171:50026 > 2014-09-17,08:26:38,588 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] Established session 0x4833538b30989e with negotiated timeout 30000 > for client /10.0.4.171:50026 > 2014-09-17,08:26:38,589 INFO > org.apache.zookeeper.server.auth.SaslServerCallbackHandler: [myid:0] > Successfully authenticated client: > authenticationID=hbase_srv/hadoop@XIAOMI.HADOOP; > authorizationID=hbase_srv/hadoop@XIAOMI.HADOOP. > 2014-09-17,08:26:38,589 INFO > org.apache.zookeeper.server.auth.SaslServerCallbackHandler: [myid:0] > Setting authorizedID: hbase_srv > 2014-09-17,08:26:38,589 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] adding SASL authorization for authorizationID: hbase_srv > 2014-09-17,08:26:38,592 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Closed socket connection for client /10.0.4.171:50026 which had > sessionid 0x4833538b30989e > 2014-09-17,08:26:38,613 INFO > org.apache.zookeeper.server.NIOServerCnxnFactory: [myid:0] Accepted socket > connection from /10.0.4.172:62397 > 2014-09-17,08:26:38,614 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] Client attempting to establish new session at /10.0.4.172:62397 > 2014-09-17,08:26:38,614 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] Established session 0x4833538b30989f with negotiated timeout 30000 > for client /10.0.4.172:62397 > 2014-09-17,08:26:38,615 INFO > org.apache.zookeeper.server.auth.SaslServerCallbackHandler: [myid:0] > Successfully authenticated client: > authenticationID=hbase_srv/hadoop@XIAOMI.HADOOP; > authorizationID=hbase_srv/hadoop@XIAOMI.HADOOP. > 2014-09-17,08:26:38,615 INFO > org.apache.zookeeper.server.auth.SaslServerCallbackHandler: [myid:0] > Setting authorizedID: hbase_srv > 2014-09-17,08:26:38,615 INFO org.apache.zookeeper.server.ZooKeeperServer: > [myid:0] adding SASL authorization for authorizationID: hbase_srv > 2014-09-17,08:26:38,618 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Closed socket connection for client /10.0.4.172:62397 which had > sessionid 0x4833538b30989f > 2014-09-17,08:26:38,707 INFO > org.apache.zookeeper.server.NIOServerCnxnFactory: [myid:0] Accepted socket > connection from /10.0.4.161:48670 > 2014-09-17,08:26:38,708 INFO org.apache.zookeeper.server.NIOServerCnxn: > [myid:0] Processing wchc command from /10.0.4.161:48670 > > > On Wed, Sep 17, 2014 at 1:00 PM, Patrick Hunt wrote: > >> Looks like a client is calling the "dump" 4lw and not waiting for the >> results before closing the socket. Try tracking down where that >> command is called from. The logs should have something like this in >> it: >> >> 2014-09-16 21:59:11,407 [myid:1] - INFO >> [NIOWorkerThread-2:NIOServerCnxn@835] - Processing dump command from >> /127.0.0.1:51740 >> >> (note the ip address) >> >> Patrick >> >> On Tue, Sep 16, 2014 at 7:57 PM, tobe wrote: >> > Can any one help to explain why I get so many "Broken pipe IOE" in >> > ZooKeeper log? >> > >> > ZooKeeper throws this exception almost every minute. I don't think we >> use >> > the four letter command to dumpWatches so frequently. So what does this >> > mean? >> > >> > 2014-09-17,10:52:09,179 ERROR org.apache.zookeeper.server.NIOServerCnxn: >> > [myid:0] Error sending data synchronously >> > java.io.IOException: Broken pipe >> > at sun.nio.ch.FileDispatcher.write0(Native Method) >> > at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29) >> > at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:69) >> > at sun.nio.ch.IOUtil.write(IOUtil.java:40) >> > at >> sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:336) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn.sendBufferSync(NIOServerCnxn.java:138) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$SendBufferWriter.checkFlush(NIOServerCnxn.java:453) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$SendBufferWriter.write(NIOServerCnxn.java:474) >> > at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111) >> > at java.io.BufferedWriter.write(BufferedWriter.java:212) >> > at java.io.PrintWriter.write(PrintWriter.java:412) >> > at java.io.PrintWriter.write(PrintWriter.java:429) >> > at java.io.PrintWriter.print(PrintWriter.java:559) >> > at java.io.PrintWriter.println(PrintWriter.java:695) >> > at >> > >> org.apache.zookeeper.server.WatchManager.dumpWatches(WatchManager.java:166) >> > at >> > org.apache.zookeeper.server.DataTree.dumpWatches(DataTree.java:1240) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$WatchCommand.commandRun(NIOServerCnxn.java:722) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$CommandThread.run(NIOServerCnxn.java:496) >> > 2014-09-17,10:52:09,179 INFO org.apache.zookeeper.server.NIOServerCnxn: >> > [myid:0] Closed socket connection for client /10.20.201.234:53756 >> which had >> > sessionid 0x34840357f664081 >> > 2014-09-17,10:52:09,179 ERROR org.apache.zookeeper.server.NIOServerCnxn: >> > [myid:0] Error sending data synchronously >> > java.io.IOException: Broken pipe >> > at sun.nio.ch.FileDispatcher.write0(Native Method) >> > at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29) >> > at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:69) >> > at sun.nio.ch.IOUtil.write(IOUtil.java:40) >> > at >> sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:336) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn.sendBufferSync(NIOServerCnxn.java:138) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$SendBufferWriter.checkFlush(NIOServerCnxn.java:453) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$SendBufferWriter.write(NIOServerCnxn.java:474) >> > at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111) >> > at java.io.BufferedWriter.flush(BufferedWriter.java:235) >> > at java.io.PrintWriter.flush(PrintWriter.java:276) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn.cleanupWriterSocket(NIOServerCnxn.java:424) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn.access$000(NIOServerCnxn.java:60) >> > at >> > >> org.apache.zookeeper.server.NIOServerCnxn$CommandThread.run(NIOServerCnxn.java:500) >> > > --001a1134787a948e0b05033d3ece--