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 > processed zxid: 42949672960 > Nov 5 12:46:34 zookeeper - INFO [SyncThread:5:FileTxnLog@199] - Creating > new log file: log.a00000001 > > ~Jared
