You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Jared Cantwell <ja...@gmail.com> on 2013/01/06 05:55:34 UTC
Unhandled proposal scenario
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
processed zxid: 42949672960
Nov 5 12:46:34 zookeeper - INFO [SyncThread:5:FileTxnLog@199] - Creating
new log file: log.a00000001
~Jared
Re: Unhandled proposal scenario
Posted by Jared Cantwell <ja...@gmail.com>.
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 <fp...@yahoo.com>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 <ja...@gmail.com>
> 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
> > processed zxid: 42949672960
> > Nov 5 12:46:34 zookeeper - INFO [SyncThread:5:FileTxnLog@199] -
> Creating
> > new log file: log.a00000001
> >
> > ~Jared
>
>
Re: Unhandled proposal scenario
Posted by Flavio Junqueira <fp...@yahoo.com>.
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 <ja...@gmail.com> 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
> processed zxid: 42949672960
> Nov 5 12:46:34 zookeeper - INFO [SyncThread:5:FileTxnLog@199] - Creating
> new log file: log.a00000001
>
> ~Jared