Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 41EC5200C40 for ; Thu, 9 Mar 2017 06:27:18 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 40912160B86; Thu, 9 Mar 2017 05:27:18 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 62CBB160B83 for ; Thu, 9 Mar 2017 06:27:17 +0100 (CET) Received: (qmail 47826 invoked by uid 500); 9 Mar 2017 05:27:16 -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 47815 invoked by uid 99); 9 Mar 2017 05:27:16 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 09 Mar 2017 05:27:16 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 849A0186280 for ; Thu, 9 Mar 2017 05:27:15 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -2.302 X-Spam-Level: X-Spam-Status: No, score=-2.302 tagged_above=-999 required=6.31 tests=[RCVD_IN_DNSWL_MED=-2.3, RCVD_IN_MSPIKE_H2=-0.001, RP_MATCHES_RCVD=-0.001, SPF_PASS=-0.001, URIBL_BLOCKED=0.001] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id HDHnwPNEX7R1 for ; Thu, 9 Mar 2017 05:27:14 +0000 (UTC) Received: from aserp1040.oracle.com (aserp1040.oracle.com [141.146.126.69]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id B53D160E24 for ; Thu, 9 Mar 2017 05:27:13 +0000 (UTC) Received: from userv0022.oracle.com (userv0022.oracle.com [156.151.31.74]) by aserp1040.oracle.com (Sentrion-MTA-4.3.2/Sentrion-MTA-4.3.2) with ESMTP id v295R6N9002394 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=OK) for ; Thu, 9 Mar 2017 05:27:06 GMT Received: from aserv0121.oracle.com (aserv0121.oracle.com [141.146.126.235]) by userv0022.oracle.com (8.14.4/8.14.4) with ESMTP id v295R4np017466 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Thu, 9 Mar 2017 05:27:06 GMT Received: from abhmp0009.oracle.com (abhmp0009.oracle.com [141.146.116.15]) by aserv0121.oracle.com (8.13.8/8.13.8) with ESMTP id v295R2ws007442 for ; Thu, 9 Mar 2017 05:27:03 GMT MIME-Version: 1.0 Message-ID: <3cd12056-d058-43df-a43a-810e2504b6b4@default> Date: Wed, 8 Mar 2017 21:27:01 -0800 (PST) From: Daniel Chan Sender: Daniel Chan To: user@zookeeper.apache.org Subject: RE: Zookeeper statup issue References: <6a090c32-bf63-4a7f-97e4-bc974b63bfb7@default> In-Reply-To: X-Priority: 3 X-Mailer: Oracle Beehive Extensions for Outlook 2.0.1.9.1 (1003210) [OL 12.0.6753.5000 (x86)] Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Source-IP: userv0022.oracle.com [156.151.31.74] archived-at: Thu, 09 Mar 2017 05:27:18 -0000 It stays there forever. The ZK version is 3.4.6.=20 We just use the bin/zkServer.sh script to start up ZK.=20 It seems not reproducible again. Also logged a bug https://issues.apache.org/jira/browse/ZOOKEEPER-2714 for = the issue. -----Original Message----- From: Michael Han [mailto:hanm@cloudera.com]=20 Sent: Wednesday, March 8, 2017 7:23 PM To: UserZooKeeper Subject: Re: Zookeeper statup issue Did your ZK server stay in this "not running" state forever - or eventually= it's up and serving requests? If it's the later, then this is not a bug, b= ecause during start up ZK server has to initialize various sub systems afte= r the server instance is initialized; so if there are client requests comin= g in after the server instance initialized but before all subsystems are in= itialized, you will see this what's logged here which is expected. If it's = the former, please state the ZK version you use and if possible, detailed s= teps on how to reproduce. On Wed, Mar 8, 2017 at 1:40 PM, Daniel Chan wrote: > We've a standalone ZK setup. Upon restart, it failed to serve requests. > > Here are the logs: > ------------------ > 2017-03-05 17:33:58,888 [myid:] - INFO [main:QuorumPeerConfig@103] -=20 > Reading configuration from: /zookeeper/zookeeper-3.4.6/conf/zoo.1.cfg > 2017-03-05 17:33:58,898 [myid:] - WARN [main:QuorumPeerConfig@293] -=20 > No server failure will be tolerated. You need at least 3 servers. > 2017-03-05 17:33:58,898 [myid:] - INFO [main:QuorumPeerConfig@340] -=20 > Defaulting to majority quorums > 2017-03-05 17:33:58,909 [myid:1] - INFO =20 > [main:DatadirCleanupManager@78] > - autopurge.snapRetainCount set to 10 > 2017-03-05 17:33:58,910 [myid:1] - INFO =20 > [main:DatadirCleanupManager@79] > - autopurge.purgeInterval set to 5 > 2017-03-05 17:33:58,911 [myid:1] - INFO =20 > [PurgeTask:DatadirCleanupManager$ PurgeTask@138] - Purge task started. > 2017-03-05 17:33:58,946 [myid:1] - INFO [main:QuorumPeerMain@127] -=20 > Starting quorum peer > 2017-03-05 17:33:58,966 [myid:1] - INFO =20 > [PurgeTask:DatadirCleanupManager$ PurgeTask@144] - Purge task completed. > 2017-03-05 17:33:58,991 [myid:1] - INFO =20 > [main:NIOServerCnxnFactory@94] - binding to port 0.0.0.0/0.0.0.0:2181 > 2017-03-05 17:33:59,016 [myid:1] - INFO [main:QuorumPeer@959] -=20 > tickTime set to 2000 > 2017-03-05 17:33:59,016 [myid:1] - INFO [main:QuorumPeer@979] -=20 > minSessionTimeout set to -1 > 2017-03-05 17:33:59,016 [myid:1] - INFO [main:QuorumPeer@990] -=20 > maxSessionTimeout set to -1 > 2017-03-05 17:33:59,016 [myid:1] - INFO [main:QuorumPeer@1005] -=20 > initLimit set to 20 > 2017-03-05 17:34:01,328 [myid:1] - INFO [main:QuorumPeer@473] -=20 > currentEpoch not found! Creating with a reasonable default of 0. This=20 > should only happen when you are upgrading your installation > 2017-03-05 17:34:01,332 [myid:1] - INFO [main:QuorumPeer@488] -=20 > acceptedEpoch not found! Creating with a reasonable default of 0. This=20 > should only happen when you are upgrading your installation > 2017-03-05 17:34:01,335 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxnFactory@197]=20 > - Accepted socket connection from / > 10.245.66.147:48198 > 2017-03-05 17:34:01,339 [myid:1] - INFO [Thread-4:QuorumCnxManager$=20 > Listener@504] - My election bind port: server001-internal/10.245.66. > 137:3888 > 2017-03-05 17:34:01,346 [myid:1] - WARN =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@362] -=20 > Exception causing close of session 0x0 due to java.io.IOException:=20 > ZooKeeperServer not running > 2017-03-05 17:34:01,346 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@1007] -=20 > Closed socket connection for client / > 10.245.66.147:48198 (no session established for client) > 2017-03-05 17:34:01,346 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxnFactory@197]=20 > - Accepted socket connection from / > 10.245.66.147:48199 > 2017-03-05 17:34:01,347 [myid:1] - WARN =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@362] -=20 > Exception causing close of session 0x0 due to java.io.IOException:=20 > ZooKeeperServer not running > 2017-03-05 17:34:01,347 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@1007] -=20 > Closed socket connection for client / > 10.245.66.147:48199 (no session established for client) > 2017-03-05 17:34:01,347 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxnFactory@197]=20 > - Accepted socket connection from / > 10.245.66.147:48200 > 2017-03-05 17:34:01,347 [myid:1] - WARN =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@362] -=20 > Exception causing close of session 0x0 due to java.io.IOException:=20 > ZooKeeperServer not running > 2017-03-05 17:34:01,348 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@1007] -=20 > Closed socket connection for client / > 10.245.66.147:48200 (no session established for client) > 2017-03-05 17:34:01,348 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxnFactory@197]=20 > - Accepted socket connection from / > 10.245.66.147:48201 > 2017-03-05 17:34:01,348 [myid:1] - INFO =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxnFactory@197]=20 > - Accepted socket connection from / > 10.245.66.137:46628 > 2017-03-05 17:34:01,348 [myid:1] - WARN =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@362] -=20 > Exception causing close of session 0x0 due to java.io.IOException:=20 > ZooKeeperServer not running > ------------------ > > Is it a race issue during startup? > 2017-03-05 17:34:01,346 [myid:1] - WARN =20 > [NIOServerCxn.Factory:0.0.0.0/ 0.0.0.0:2181:NIOServerCnxn@362] -=20 > Exception causing close of session 0x0 due to java.io.IOException:=20 > ZooKeeperServer not running > > Thanks, > Daniel > -- Cheers Michael.