Home | About | Sematext search-lucene.com search-hadoop.com
 Search Hadoop and all its subprojects:

Switch to Plain View
Zookeeper, mail # user - Unhandled proposal scenario


+
Jared Cantwell 2013-01-06, 04:55
+
Flavio Junqueira 2013-01-06, 11:24
Copy link to this message
-
Re: Unhandled proposal scenario
Jared Cantwell 2013-01-06, 15:01
Thanks Flavio.  We haven't 100% figured out what was happening, but once we
do I'll update if your explanation doesn't match up.

~Jared
On Sun, Jan 6, 2013 at 4:24 AM, Flavio Junqueira <[EMAIL PROTECTED]>wrote:

> Hi Jared,
>
> The message is definitely not very informative, but the scenario I believe
> is harmless. The log entries that really matter are 1 and 3, not 2 and 3 as
> you pointed out originally:
>
> 1)  Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> :LearnerHandler@326] - Synchronizing with Follower sid: 2
> maxCommittedLog=0x900000004 minCommittedLog=0x900000001
> peerLastZxid=0x700000001
>
> 2) *Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.12:44880
> :LearnerHandler@326] - Synchronizing with Follower sid: 1
> maxCommittedLog=0x900000004 minCommittedLog=0x900000001
> peerLastZxid=0x900000004*
>
> 3) *Nov  5 12:46:34 zookeeper - WARN  [LearnerHandler-/10.10.5.13:51363
> :LearnerHandler@387] - Unhandled proposal scenario*
>
> The unhandled message is generate when we are trying to decide whether to
> send a diff or to truncate, so you've hit the case in which we do neither.
> However, by default, we send a snapshot, as your logs are showing we do:
>
> Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> :LearnerHandler@402] - Sending SNAP
>
> Please let me know if you disagree with this analysis. It might be worth
> having a trivial jura to change that log message.
>
> -Flavio
>
>
> On Jan 6, 2013, at 4:55 AM, Jared Cantwell <[EMAIL PROTECTED]>
> wrote:
>
> > Some code that we're testing was causing some servers to thrash, but once
> > things settled down leader election was getting "Unhandled proposal
> > scenario".  Anyone know what might cause a server to get into this
> > situation?
> >
> > Nov  5 12:46:33 zookeeper - INFO  [QuorumPeer[myid=5]/10.10.5.82:2181
> > :Leader@424] - LEADING - LEADER ELECTION TOOK - 12
> > Nov  5 12:46:33 zookeeper - INFO  [QuorumPeer[myid=5]/10.10.5.82:2181
> > :FileSnap@83] - Reading snapshot /sf/data/zookeeper/
> > 10.10.5.82/version-2/snapshot.800000017
> > Nov  5 12:46:33 zookeeper - INFO  [QuorumPeer[myid=5]/10.10.5.82:2181
> > :FileTxnSnapLog@270] - Snapshotting: 0x900000004 to /sf/data/zookeeper/
> > 10.10.5.82/version-2/snapshot.900000004
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> > :LearnerHandler@267] - Follower sid: 2 : info : 10.10.5.13:2182
> > :2183:participant;10.10.5.13:2181
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.12:44880
> > :LearnerHandler@267] - Follower sid: 1 : info : 10.10.5.12:2182
> > :2183:participant;10.10.5.12:2181
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> > :LearnerHandler@326] - Synchronizing with Follower sid: 2
> > maxCommittedLog=0x900000004 minCommittedLog=0x900000001
> > peerLastZxid=0x700000001
> > *Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.12:44880
> > :LearnerHandler@326] - Synchronizing with Follower sid: 1
> > maxCommittedLog=0x900000004 minCommittedLog=0x900000001
> > peerLastZxid=0x900000004*
> > *Nov  5 12:46:34 zookeeper - WARN  [LearnerHandler-/10.10.5.13:51363
> > :LearnerHandler@387] - Unhandled proposal scenario*
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> > :LearnerHandler@402] - Sending SNAP
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.12:44880
> > :LearnerHandler@402] - Sending DIFF
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> > :LearnerHandler@433] - Sending snapshot last zxid of peer is 0x700000001
> > zxid of leader is 0xa00000000sent zxid of db as 0x900000004
> > Nov  5 12:46:34 zookeeper - WARN  [LearnerHandler-/10.10.5.13:51363
> > :Leader@698] - Commiting zxid 0xa00000000 from /10.10.5.82:2182 not
> first!
> > Nov  5 12:46:34 zookeeper - WARN  [LearnerHandler-/10.10.5.13:51363
> > :Leader@700] - First is 0
> > Nov  5 12:46:34 zookeeper - INFO  [LearnerHandler-/10.10.5.13:51363
> > :Leader@753] - Have quorum of supporters; starting up and setting last