Mailing-List: contact user-help@zookeeper.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@zookeeper.apache.org
From: Ryan Zhang <yangzhangrice@hotmail.com>
To: "user@zookeeper.apache.org" <user@zookeeper.apache.org>
CC: "anpartha@avinetworks.com" <anpartha@avinetworks.com>
Subject: Re: Zookeeper leader election takes a long time.
Thread-Topic: Zookeeper leader election takes a long time.
Thread-Index: AQHSIQDyWc+cz21JGUya1ZsS1WJ/DaCepfyAgAAkcACACDlJgA==
Date: Thu, 13 Oct 2016 22:41:01 +0000
Message-ID: <BLUPR15MB0033E9515121B029E542C8F9B9DC0@BLUPR15MB0033.namprd15.prod.outlook.com>
References: <CAM+wfv4Lbaouv=c4BXW41A7Rc71nvgw+DcE+mOQXtC3Y7bEn3A@mail.gmail.com>
 <1A9BB7DA-9D76-40CF-92C8-743A3B418743@apache.org>
 <CAM+wfv7h5MFeqsWpFevomi4ccjdwtQpQRfTfa8zcZye7L299UA@mail.gmail.com>
In-Reply-To: <CAM+wfv7h5MFeqsWpFevomi4ccjdwtQpQRfTfa8zcZye7L299UA@mail.gmail.com>
Accept-Language: en-US
Content-Language: en-US
x-ms-exchange-messagesentrepresentingtype: 1
x-incomingheadercount: 37
x-eopattributedmessage: 0
x-microsoft-exchange-diagnostics: 
	1;BY2NAM03HT147;6:M+O2TPVLLD0ATahblfOyY0kbjzTAoEwXWEK8iQ1eFrwM1xfieR67V8h6tJEMOxUTnTZ9gnjJ2Q/KxrPoQiMtvouCbuegq2cAY75OsQToV4g6pUo7RLmfzs4Zxu1cALymaZllEvGQVJnGa0AJXsvIV8GZEnsTBNATA5nqqtYwJqN9vlFS7JSpyxwd3Kl0GDcGx/D/iUoBvuIFggy8gA0DcLIHrCVluF1l6Yvvg9BVxFC6qGNiZRLUyaOvZviMwt+Lo7MTDpdKTpqeru8wRZKSZsSiBQE8qhKeEVb8b+lSA2N7sDD90CnLbmXAnBAbiIZf;5:cSK5yBS9oK6V31/sj/VxpznsM0WR/pSzAADM4UtQ1z1EPpxqxK+SOZRgDjMSlzGIXMWdFCB5F/HCOtnkibHfV9/o4yxt5vgOJ7A/HxrfBDzaZPbwSK8Ns9Ds5D/4sf4S0Nf4IDqzbSclM2OVmroBTAMEUmJJ6ziKGdlnU0E6bU8=;24:f6OdGCNTbdSTYh40QMg0wHuxWpC2YqsZ92iqoUuTOX2RQ+5rz95H9HUs9QyC52JjfhK96SWcmeGK4GhtHOBOpf2FcgO+B5DTENTpVMtRqCo=;7:2I7K0PejqmwaE2/XNdcu75pXMZ1Egu6nDRZ0/DxQDtQI/Yg5ZJu+tUDJOvRIk/zs6LN3zF6sROQCbT6ppgQXqxTyrsHsHMYZdNCn1UJZv38KnVNL+g9Ipx9wNPa2xkOq3haONW9ot1udokSeY2EB7qx0YWrwBAqzOw48x3IuDxjq7Hbi7dhY24xNG7JZl7vx9AxamT2Cr1pt8yJObNxJmoMGrCsJtJdUteQkzMIBrKd6Khv1KvNRoam3InyfuolUDfoeyvrRmCPyZAfoq3y1WQjB7WmPudu3XQvsJFJfg0ZWUYHhdbvvAQZVDXlJl9ANpiqwPw2Pu3MO7WQ8wOgSTzwbsMZE34YNtTgoOB/jufY=
x-forefront-antispam-report: EFV:NLI;SFV:NSPM;SFS:(10019020)(98900003);DIR:OUT;SFP:1102;SCL:1;SRVR:BY2NAM03HT147;H:BLUPR15MB0033.namprd15.prod.outlook.com;FPR:;SPF:None;LANG:en;
x-ms-office365-filtering-correlation-id: f0f9c6d0-8765-4ba1-252d-08d3f3ba0150
x-microsoft-antispam: UriScan:;BCL:0;PCL:0;RULEID:(1601124038)(1603103081)(1601125047);SRVR:BY2NAM03HT147;
x-exchange-antispam-report-cfa-test: BCL:0;PCL:0;RULEID:(432015012)(82015046);SRVR:BY2NAM03HT147;BCL:0;PCL:0;RULEID:;SRVR:BY2NAM03HT147;
x-forefront-prvs: 0094E3478A
spamdiagnosticoutput: 1:99
spamdiagnosticmetadata: NSPM
Content-Type: multipart/alternative;
	boundary="_000_BLUPR15MB0033E9515121B029E542C8F9B9DC0BLUPR15MB0033namp_"
MIME-Version: 1.0
X-OriginatorOrg: hotmail.com
X-MS-Exchange-CrossTenant-originalarrivaltime: 13 Oct 2016 22:41:01.6370
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Internet
X-MS-Exchange-CrossTenant-id: 84df9e7f-e9f6-40af-b435-aaaaaaaaaaaa
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BY2NAM03HT147
X-OriginalArrivalTime: 13 Oct 2016 22:41:03.0577 (UTC) FILETIME=[E0EDB490:01D225A2]
archived-at: Thu, 13 Oct 2016 22:41:39 -0000

--_000_BLUPR15MB0033E9515121B029E542C8F9B9DC0BLUPR15MB0033namp_
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable

Hi, Anand, I took a look and I wonder how do you explain the following

The N1.log starts at around
2016-10-03 12:37:38,073 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:QuorumPeer@714] - LOOKING

and it failed to talk to Node 2 (id: 2)
2016-10-03 12:37:38,136 [myid:1] - WARN  [WorkerSender[myid=3D1]:QuorumCnxM=
anager@382] - Cannot open channel to 2 at election address node2.controller=
.local/127.0.0.8:5004
java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketIm=
pl.java:339)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainS=
ocketImpl.java:200)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl=
.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:579)

However, after failed to get any election messages from Node 3, it started =
a new round but then I seem to see the election messages from Node 2 again.=
 Any idea why?

2016-10-03 12:38:32,815 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:QuorumPeer@714] - LOOKING
2016-10-03 12:38:32,816 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:FileSnap@83] - Reading snapshot /var/lib/zookeeper/version-2/snapshot.20=
002aa0b
2016-10-03 12:38:32,875 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:FastLeaderElection@815] - New election. My id =3D  1, proposed zxid=3D0x=
20002bfb5
2016-10-03 12:38:32,876 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 1 (n.leader), 0=
x20002bfb5 (n.zxid), 0x6 (n.round), LOOKING (n.state), 1 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:32,878 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 2 (n.leader), 0=
x20002bfb5 (n.zxid), 0x6 (n.round), LOOKING (n.state), 2 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:32,878 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 2 (n.leader), 0=
x20002bfb5 (n.zxid), 0x6 (n.round), LOOKING (n.state), 1 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:32,917 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 3 (n.leader), 0=
x20002bfb5 (n.zxid), 0x4 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:33,117 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:FastLeaderElection@849] - Notification time out: 400
2016-10-03 12:38:33,118 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 2 (n.leader), 0=
x20002bfb5 (n.zxid), 0x6 (n.round), LOOKING (n.state), 1 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:33,159 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 3 (n.leader), 0=
x20002bfb5 (n.zxid), 0x4 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:33,559 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:FastLeaderElection@849] - Notification time out: 800
2016-10-03 12:38:33,560 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 2 (n.leader), 0=
x20002bfb5 (n.zxid), 0x6 (n.round), LOOKING (n.state), 1 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:33,561 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 2 (n.leader), 0=
x20002bfb5 (n.zxid), 0x6 (n.round), LEADING (n.state), 2 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:33,601 [myid:1] - INFO  [WorkerReceiver[myid=3D1]:FastLead=
erElection@597] - Notification: 1 (message format version), 3 (n.leader), 0=
x20002bfb5 (n.zxid), 0x4 (n.round), LEADING (n.state), 3 (n.sid), 0x2 (n.pe=
erEpoch) LOOKING (my state)
2016-10-03 12:38:34,402 [myid:1] - INFO  [QuorumPeer[myid=3D1]/127.0.0.1:50=
02:FastLeaderElection@849] - Notification time out: 1600


On Oct 8, 2016, at 10:05 AM, Anand Parthasarathy <anpartha@avinetworks.com<=
mailto:anpartha@avinetworks.com>> wrote:

Hi Flavio,

I have attached the logs from node 1 and node 3. Node 2 was powered off aro=
und 10-03 12:36. Leader election kept going until 10-03 15:57:16 when it fi=
nally converged.

Thanks,
Anand.

On Sat, Oct 8, 2016 at 7:55 AM, Flavio Junqueira <fpj@apache.org<mailto:fpj=
@apache.org>> wrote:
Hi Anand,

I don't understand whether 1 and 3 were able or even trying to connect to e=
ach other. They should be able to elect a leader between them and make prog=
ress. You might want to upload logs and let us know.

-Flavio

> On 08 Oct 2016, at 02:11, Anand Parthasarathy <anpartha@avinetworks.com<m=
ailto:anpartha@avinetworks.com>> wrote:
>
> Hi,
>
> We are currently using zookeeper 3.4.6 version and use a 3 node solution =
in
> our system. We see that occasionally, when a node is powered off (in this
> instance, it was actually a leader node), the remaining two nodes do not
> form a quorum for a really long time. Looking at the logs, it appears the
> sequence is as follows:
> - Node 2 is the zookeeper leader
> - Node 2 is powered off
> - Node 1 and Node 3 recognize and start the election
> - Node 3 times out after initLimit * tickTime with "Timeout while waiting
> for quorum" for Round N
> - Node 1 times out after initLimit * tickTime with "Exception while tryin=
g
> to follow leader" for Round N+1 at the same time.
> - And the process continues where N is sequentially incrementing.
> - This happens for a long time.
> - In one instance, we used tickTime=3D5000 and initLimit=3D20 and it took
> around 3.5 hours to converge.
> - In a given round, Node 1 will try connecting to Node 2, gets connection
> refused waits for notification timeout which increases by 2 every iterati=
on
> until it hits the initLimit. Connection Refused is because the node 2 com=
es
> up after reboot, but zookeeper process is not started (due to a different
> failure).
>
> It looks similar to ZOOKEEPER-2164 but there it is a connection timeout
> where Node 2 is not reachable.
>
> Could you pls. share if you have seen this issue and if so, what is the
> workaround that can be employed in 3.4.6.
>
> Thanks,
> Anand.


<log.tgz>


--_000_BLUPR15MB0033E9515121B029E542C8F9B9DC0BLUPR15MB0033namp_--