You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by "Round, Mark" <Ma...@sky.uk> on 2015/06/25 16:28:43 UTC
Tracking down possible network partition
I have a 5-node Zookeeper 3.4.6 cluster across 3 data centres (2 zookeepers in each “main” DC, and a 5th in a 3rd DC for quorum). I see that the two nodes in one DC have regular “issues” where they get kicked out of the cluster and the ZooKeeperServer process stops for a few minutes until the node rejoins. I’d like to know a couple of things, if someone could please point me in the direction of the relevant docs I’d greatly appreciate it.
1.) Is it expected behaviour that when a node is kicked from the cluster, it will not be allowed to re-join for a period ? From the logs below I can see that re-establishing a valid cluster took around 15 minutes.
2.) It appears that the leader closes connections to the affected followers after a “transaction timeout” occurs. Where would I find out what this timeout is ? Is this the same thing as a session timout (e.g. The default of 20 * tickTime) ?
3.) Where can I find the definition of the different fields in the election log messages (I.e. What are “n.round”, “n.zxid”, “n.state” and so on) ? I can make an educated guess, which seems to point towards a possible network partition event (see below). This should help me start to narrow down the issue. For reference, below are some extracts from the relevant logs:
On the leader, I see a message similar to the following :
2015-06-24 04:18:40,152 [myid:5] - WARN [QuorumPeer[myid=5]/0:0:0:0:0:0:0:0:2181:LearnerHandler@687] - Closing connection to peer due to transaction timeout.
2015-06-24 04:18:40,152 [myid:5] - WARN [LearnerHandler-/10.93.167.74:36874:LearnerHandler@646] - ******* GOODBYE /10.93.167.74:36874 ********
2015-06-24 04:18:40,153 [myid:5] - WARN [LearnerHandler-/10.93.167.74:36874:LearnerHandler@658] - Ignoring unexpected exception
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1219)
at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:340)
at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:338)
at org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:656)
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:649)
And on the affected follower :
2015-06-24 04:18:40,160 [myid:3] - WARN [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Follower@89] - Exception when following the leader
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83)
at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:103)
at org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:153)
at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:85)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786)
2015-06-24 04:18:40,160 [myid:3] - INFO [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Follower@166] - shutdown called
java.lang.Exception: shutdown Follower
at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:790)
Following this, the follower has a lot of the following :
2015-06-24 04:26:24,615 [myid:3] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] - Accepted socket connection from /0:0:0:0:0:0:0:1:42079
2015-06-24 04:26:24,616 [myid:3] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@362] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running
And a few election messages. These are interesting as (from a guess of what the fields are in these messages), I see what looks like a network partition issue :
2015-06-24 04:26:27,689 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 3 (n.leader), 0x10009b227 (n.zxid), 0x2 (n.round), LOOKING (n.state), 3 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:26:27,691 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 4 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
Assuming that “n.leader” means what this zookeeper thinks the leader is, it looks like there are two leaders – 3 (the affected follower) and 5 (the actual leader that the rest of the cluster recognises) . And a little while later on the follower, I see a successful election. It looks like there’s also some shaking out of quorum here – almost as if it’s trying to recover from a near split-brain scenario (of course, it’s possible my interpretation of these logs is way off…):
2015-06-24 04:34:27,707 [myid:3] - INFO [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:FastLeaderElection@849] - Notification time out: 60000
2015-06-24 04:34:27,712 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 3 (n.leader), 0x10009b227 (n.zxid), 0x2 (n.round), LOOKING (n.state), 3 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,714 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 4 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,719 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,719 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,721 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 2 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,722 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), FOLLOWING (n.state), 2 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,728 [myid:3] - INFO [WorkerSender[myid=3]:QuorumCnxManager@193] - Have smaller server identifier, so dropping the connection: (5, 3)
2015-06-24 04:34:27,762 [myid:3] - INFO [nftserentzk01.slu.skycdc.com/10.93.167.74:3888:QuorumCnxManager$Listener@511] - Received connection request /10.105.6.117:38358
2015-06-24 04:34:27,764 [myid:3] - INFO [WorkerReceiver[myid=3]:FastLeaderElection@597] - Notification: 1 (message format version), 5 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LEADING (n.state), 5 (n.sid), 0x1 (n.peerEpoch) LOOKING (my state)
2015-06-24 04:34:27,765 [myid:3] - INFO [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:QuorumPeer@784] - FOLLOWING
2015-06-24 04:34:27,765 [myid:3] - INFO [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@162] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /zkdata/version-2 snapdir /zkdata/version-2
2015-06-24 04:34:27,765 [myid:3] - INFO [QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Follower@63] - FOLLOWING - LEADER ELECTION TOOK - 943889
Are my assumptions correct here, or am I barking up the wrong tree ?
Many thanks in advance,
Mark Dastmalchi-Round
DevOps Engineer, Sky Search
BSkyB | Great West House | GW1 - 4th floor
Information in this email including any attachments may be privileged, confidential and is intended exclusively for the addressee. The views expressed may not be official policy, but the personal views of the originator. If you have received it in error, please notify the sender by return e-mail and delete it from your system. You should not reproduce, distribute, store, retransmit, use or disclose its contents to anyone. Please note we reserve the right to monitor all e-mail communication through our internal and external networks. SKY and the SKY marks are trademarks of Sky plc and Sky International AG and are used under licence. Sky UK Limited (Registration No. 2906991), Sky-In-Home Service Limited (Registration No. 2067075) and Sky Subscribers Services Limited (Registration No. 2340150) are direct or indirect subsidiaries of Sky plc (Registration No. 2247735). All of the companies mentioned in this paragraph are incorporated in England and Wales and share the same registered office at Grant Way, Isleworth, Middlesex TW7 5QD.
RE: Tracking down possible network partition
Posted by "snair123 ." <na...@outlook.com>.
2.) It appears that the leader closes connections to the affected followers
after a “transaction timeout” occurs. Where would I find out what this
timeout is ? Is this the same thing as a session timout (e.g. The default
of 20 * tickTime) ?
https://github.com/apache/zookeeper/blob/trunk/src/java/main/org/apache/zookeeper/server/quorum/LearnerHandler.java#L496
a. So the Leader closes connections to Followers and Observers after syncLimit*ticktime milliseconds ?
b. So what purpose does the SyncLimit serve in followers and in observers ?
c. If i needed the Observer to stay connected to ZKEnsemble for a longer time - in case of network partitiions - do i increase the syncLimit at the leader or at the Observer ?
> Date: Fri, 26 Jun 2015 18:10:45 -0700
> Subject: Re: Tracking down possible network partition
> From: rgs@itevenworks.net
> To: user@zookeeper.apache.org
>
> On 25 June 2015 at 07:28, Round, Mark <Ma...@sky.uk> wrote:
>
> > I have a 5-node Zookeeper 3.4.6 cluster across 3 data centres (2
> > zookeepers in each “main” DC, and a 5th in a 3rd DC for quorum). I see that
> > the two nodes in one DC have regular “issues” where they get kicked out of
> > the cluster and the ZooKeeperServer process stops for a few minutes until
> > the node rejoins. I’d like to know a couple of things, if someone could
> > please point me in the direction of the relevant docs I’d greatly
> > appreciate it.
> >
> > 1.) Is it expected behaviour that when a node is kicked from the cluster,
> > it will not be allowed to re-join for a period ? From the logs below I can
> > see that re-establishing a valid cluster took around 15 minutes.
> >
>
> I don't think so.
>
> 2.) It appears that the leader closes connections to the affected followers
> > after a “transaction timeout” occurs. Where would I find out what this
> > timeout is ? Is this the same thing as a session timout (e.g. The default
> > of 20 * tickTime) ?
> >
>
> https://github.com/apache/zookeeper/blob/trunk/src/java/main/org/apache/zookeeper/server/quorum/LearnerHandler.java#L496
>
>
> > 3.) Where can I find the definition of the different fields in the
> > election log messages (I.e. What are “n.round”, “n.zxid”, “n.state” and so
> > on) ?
>
>
> Not sure if there's a better source than the source:
> https://github.com/apache/zookeeper/blob/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java#L687
>
>
>
> -rgs
Re: ZOOKEEPER-1998
Posted by Steven Schlansker <ss...@opentable.com>.
On Oct 2, 2015, at 11:25 AM, Pramod Srinivasan <pr...@juniper.net> wrote:
>
> Are there any plans to fix this bug?
>
> https://issues.apache.org/jira/browse/ZOOKEEPER-1998
>
> We are hitting a unusual problem with applications getting stuck in the linux kernel when they call getaddrinfo
>
> This is due to a bug in linux kernel:
>
> http://www.spinics.net/lists/netdev/msg328772.html
>
> We hit this problem frequently as we have a number of our applications using the zookeeper client library and due to ZOOKEEPER-1998, our likelihood of hitting this problem increases. We have had mixed luck with getting a fix for the linux kernel bug, it would be good to reduce the probability at least.
The linked improvement would certainly be welcome.
We ran into the same problem in a different context, and found
that upgrading from kernel 4.0.4 to 4.0.9 dramatically
improved our situation.
Maybe a similar upgrade helps you out too.
RE: ZOOKEEPER-1998
Posted by Pramod Srinivasan <pr...@juniper.net>.
gentle nudge!
________________________________________
From: Pramod Srinivasan [pramod@juniper.net]
Sent: Thursday, September 24, 2015 6:56 PM
To: user@zookeeper.apache.org
Subject: ZOOKEEPER-1998
Hello Folks
Are there any plans to fix this bug?
https://issues.apache.org/jira/browse/ZOOKEEPER-1998
We are hitting a unusual problem with applications getting stuck in the linux kernel when they call getaddrinfo
This is due to a bug in linux kernel:
http://www.spinics.net/lists/netdev/msg328772.html
We hit this problem frequently as we have a number of our applications using the zookeeper client library and due to ZOOKEEPER-1998, our likelihood of hitting this problem increases. We have had mixed luck with getting a fix for the linux kernel bug, it would be good to reduce the probability at least.
Thanks,
Pramod
ZOOKEEPER-1998
Posted by Pramod Srinivasan <pr...@juniper.net>.
Hello Folks
Are there any plans to fix this bug?
https://issues.apache.org/jira/browse/ZOOKEEPER-1998
We are hitting a unusual problem with applications getting stuck in the linux kernel when they call getaddrinfo
This is due to a bug in linux kernel:
http://www.spinics.net/lists/netdev/msg328772.html
We hit this problem frequently as we have a number of our applications using the zookeeper client library and due to ZOOKEEPER-1998, our likelihood of hitting this problem increases. We have had mixed luck with getting a fix for the linux kernel bug, it would be good to reduce the probability at least.
Thanks,
Pramod
RE: Tracking down possible network partition
Posted by Akihiro Suda <su...@lab.ntt.co.jp>.
Hi,
this JIRA ticket seems related:
https://issues.apache.org/jira/browse/ZOOKEEPER-2246
The patch suggested in the ticket might be helpful for you.
Regards,
Akihiro Suda
-----Original Message-----
From: Bob Sheehan [mailto:bsheehan@vmware.com]
Sent: Friday, September 25, 2015 4:32 AM
To: user@zookeeper.apache.org
Subject: Tracking down possible network partition
We have similar issue:
3 node ZK cluster in DC1 (e.g. Las Vegas) .. quorum of 2. Each node on
Vmware ESXI host in same rack.
2 observer ZK nodes in DC2 (e.g Germany).Each node on Vmware ESXI host in
same rack.
Centos 6
ZK version Cloudera cdh 3.4.5.
* Looks like leader election in DC1 is taking a while ~15 minutes. At
some point TCP connection to one of three nodes is lost. Eventualy repairs.
* Apparently during leader election connection lost to observers for ~15
minutes... then connection repaired. But we have 15 minute window where both
observers (DC2) cannot communicate with ZK cluster (DC1). Our DC2 clients
are comuunicating to observers using apache curator library. This causes our
API to fail as it needs ZK data.
We used netstat on TCP ports and are seeing non 0 SENDQ size.
Is there any know fix/patch for this ? Suggestions welcome.
Thanks,
Bob
Re: Tracking down possible network partition
Posted by Raúl Gutiérrez Segalés <rg...@itevenworks.net>.
On 25 June 2015 at 07:28, Round, Mark <Ma...@sky.uk> wrote:
> I have a 5-node Zookeeper 3.4.6 cluster across 3 data centres (2
> zookeepers in each “main” DC, and a 5th in a 3rd DC for quorum). I see that
> the two nodes in one DC have regular “issues” where they get kicked out of
> the cluster and the ZooKeeperServer process stops for a few minutes until
> the node rejoins. I’d like to know a couple of things, if someone could
> please point me in the direction of the relevant docs I’d greatly
> appreciate it.
>
> 1.) Is it expected behaviour that when a node is kicked from the cluster,
> it will not be allowed to re-join for a period ? From the logs below I can
> see that re-establishing a valid cluster took around 15 minutes.
>
I don't think so.
2.) It appears that the leader closes connections to the affected followers
> after a “transaction timeout” occurs. Where would I find out what this
> timeout is ? Is this the same thing as a session timout (e.g. The default
> of 20 * tickTime) ?
>
https://github.com/apache/zookeeper/blob/trunk/src/java/main/org/apache/zookeeper/server/quorum/LearnerHandler.java#L496
> 3.) Where can I find the definition of the different fields in the
> election log messages (I.e. What are “n.round”, “n.zxid”, “n.state” and so
> on) ?
Not sure if there's a better source than the source:
https://github.com/apache/zookeeper/blob/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java#L687
-rgs