Home | About | Sematext search-lucene.com search-hadoop.com
NEW: Monitor These Apps!
elasticsearch, apache solr, apache hbase, hadoop, redis, casssandra, amazon cloudwatch, mysql, memcached, apache kafka, apache zookeeper, apache storm, ubuntu, centOS, red hat, debian, puppet labs, java, senseiDB
 Search Hadoop and all its subprojects:

Switch to Threaded View
Zookeeper >> mail # user >> Unhandled proposal scenario


Copy link to this message
-
Re: Unhandled proposal scenario
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
NEW: Monitor These Apps!
elasticsearch, apache solr, apache hbase, hadoop, redis, casssandra, amazon cloudwatch, mysql, memcached, apache kafka, apache zookeeper, apache storm, ubuntu, centOS, red hat, debian, puppet labs, java, senseiDB