[
https://issues.apache.org/jira/browse/ZOOKEEPER-3526?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17134018#comment-17134018
]
Martin Güthle commented on ZOOKEEPER-3526:
------------------------------------------
Due to this bug, this occures, as the zxid is modified and taken as
maxCommittedLog. The leader itself has further data, as the epoche > 0.
Related to the your other question, I hope i can try to provide a patch within
the next days
> data inconsistency due to mistaken TRUNC caused by maxCommittedLog is much
> less than minCommittedLog when in readonly mode
> --------------------------------------------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-3526
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-3526
> Project: ZooKeeper
> Issue Type: Bug
> Components: server
> Affects Versions: 3.4.14
> Environment: 1.version:3.4.14
> 2.num of zk nodes: 3
> Reporter: wanglei
> Priority: Major
> Attachments: zookeeper-1.txt, zookeeper-2.txt, zookeeper-3.txt
>
>
> 1.Node1:1566815238 (myid)、Node2:1566815239 (myid)、Node3:1566815240 (myid)
> 2.After a election, Node3 become the new leader, begin to sync with followers
>
> *2019-08-27 04:26:09,521 [myid:1566815240] - INFO
> [NIOServerCxn.Factory:/172.28.8.123:9880:ZooKeeperServer@910][] - Refusing
> session request for not-read-only client /172.28.0.3:38994*
> *2019-08-27 04:26:09,609 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:ZooKeeperServer@502][] -
> shutting down*
> *2019-08-27 04:26:09,609 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:SessionTrackerImpl@226][] -
> Shutting down*
> *2019-08-27 04:26:09,609 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:PrepRequestProcessor@769][] -
> Shutting down*
> *2019-08-27 04:26:09,609 [myid:1566815240] - INFO
> [ReadOnlyRequestProcessor:1566815240:ReadOnlyRequestProcessor@111][] -
> ReadOnlyRequestProcessor exited loop!*
> *2019-08-27 04:26:09,610 [myid:1566815240] - INFO
> [ProcessThread(sid:1566815240 cport:-1)::PrepRequestProcessor@144][] -
> PrepRequestProcessor exited loop!*
> *2019-08-27 04:26:09,610 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:FinalRequestProcessor@430][] -
> shutdown of request processor complete*
> *2019-08-27 04:26:09,613 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:QuorumPeer@992][] - LEADING*
> *2019-08-27 04:26:09,615 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:Leader@64][] - TCP NoDelay set
> to: true*
> *2019-08-27 04:26:09,616 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:ZooKeeperServer@174][] -
> Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout
> 300000 datadir /opt/fusionplatform/data/zookeeper/data/version-2 snapdir
> /opt/fusionplatform/data/zookeeper/data/version-2*
> *2019-08-27 04:26:09,616 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:Leader@380][] -
> {color:#FF0000}LEADING - LEADER ELECTION TOOK - 15297{color}*
> *2019-08-27 04:26:09,956 [myid:1566815240] - INFO
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxnFactory@222][] -
> Accepted socket connection from /172.28.0.3:39012*
> *2019-08-27 04:26:09,956 [myid:1566815240] - WARN
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxn@383][] - Exception
> causing close of session 0x0: ZooKeeperServer not running*
> *2019-08-27 04:26:09,974 [myid:1566815240] - INFO
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxnFactory@222][] -
> Accepted socket connection from /172.28.0.2:50732*
> *2019-08-27 04:26:09,974 [myid:1566815240] - WARN
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxn@383][] - Exception
> causing close of session 0x0: ZooKeeperServer not running*
> *2019-08-27 04:26:10,513 [myid:1566815240] - INFO
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxnFactory@222][] -
> Accepted socket connection from /172.28.0.5:60010*
> *2019-08-27 04:26:10,514 [myid:1566815240] - WARN
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxn@383][] - Exception
> causing close of session 0x0: ZooKeeperServer not running*
> *2019-08-27 04:26:10,516 [myid:1566815240] - INFO
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxnFactory@222][] -
> Accepted socket connection from /172.28.0.5:60020*
> *2019-08-27 04:26:10,517 [myid:1566815240] - WARN
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxn@383][] - Exception
> causing close of session 0x0: ZooKeeperServer not running*
> *2019-08-27 04:26:10,530 [myid:1566815240] - INFO
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxnFactory@222][] -
> Accepted socket connection from /172.28.0.5:60024*
> *2019-08-27 04:26:10,531 [myid:1566815240] - WARN
> [NIOServerCxn.Factory:/172.28.8.123:9880:NIOServerCnxn@383][] - Exception
> causing close of session 0x0: ZooKeeperServer not running*
> *2019-08-27 04:26:10,619 [myid:1566815240] - INFO
> [LearnerHandler-/172.28.0.2:59666:LearnerHandler@346][] - Follower sid:
> 1566815238 : info :
> org.apache.zookeeper.server.quorum.QuorumPeer$QuorumServer@6f38a687*
> *2019-08-27 04:26:10,747 [myid:1566815240] - INFO
> [LearnerHandler-/172.28.0.2:59666:LearnerHandler@401][] -{color:#FF0000}
> Synchronizing with Follower sid: 1566815238 maxCommittedLog=0x3
> minCommittedLog=0x9000002d9 peerLastZxid=0x9000004ca{color}*
> *2019-08-27 04:26:10,747 [myid:1566815240] - INFO
> [LearnerHandler-/172.28.0.2:59666:LearnerHandler@410][] - leader and follower
> are in sync, zxid=0x9000004ca*
> *2019-08-27 04:26:10,748 [myid:1566815240] - INFO
> [LearnerHandler-/172.28.0.2:59666:LearnerHandler@475][] - Sending DIFF*
> *2019-08-27 04:26:10,811 [myid:1566815240] - INFO
> [SessionTracker:SessionTrackerImpl@163][] - SessionTrackerImpl exited loop!*
> *2019-08-27 04:26:10,833 [myid:1566815240] - INFO
> [LearnerHandler-/172.28.0.2:59666:LearnerHandler@535][] - Received
> NEWLEADER-ACK message from 1566815238*
> *2019-08-27 04:26:10,833 [myid:1566815240] - INFO
> [QuorumPeer[myid=1566815240]/172.28.8.123:9880:Leader@964][] - Have quorum of
> supporters, sids: [ 1566815238,1566815240 ]; starting up and setting last
> processed zxid: 0xa00000000*
> *2019-08-27 04:26:11,160 [myid:1566815240] - INFO
> [SyncThread:1566815240:FileTxnLog@216][] - Creating new log file:
> log.a00000001*
> {color:#FF0000}maxCommittedLog=0x3 minCommittedLog=0x9000002d9
> peerLastZxid=0x9000004ca{color}
> {color:#ff0000}*why maxCommittedLog < minCommittedLog?*{color}
> 2.Node 2(follower) get a Trunc message form leader.The leader zxid of the
> Trunc message is 0x3. So Node3 truncat the transaction log(the zxid which is
> bigger than 0x3 will be deleted). At last, the data in Node2 is inconsistent.
>
> *2019-08-27 04:26:14,225 [myid:1566815239] - INFO
> [WorkerReceiver[myid=1566815239]:FastLeaderElection@595][] - Notification: 1
> (message format version), 1566815240 (n.leader), 0x9000004ca (n.zxid), 0x1
> (n.round), FOLLOWING (n.state), 1566815238 (n.sid), 0xa (n.peerEpoch) LOOKING
> (my state)*
> *2019-08-27 04:26:14,226 [myid:1566815239] - INFO
> [WorkerReceiver[myid=1566815239]:FastLeaderElection@595][] - Notification: 1
> (message format version), 1566815240 (n.leader), 0x9000004ca (n.zxid), 0x1
> (n.round), FOLLOWING (n.state), 1566815238 (n.sid), 0xa (n.peerEpoch)
> FOLLOWING (my state)*
> *2019-08-27 04:26:14,226 [myid:1566815239] - INFO
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:QuorumPeer@980][] - FOLLOWING*
> *2019-08-27 04:26:14,226 [myid:1566815239] - INFO
> [Thread-1:QuorumPeer$1@936][] - Interrupted while attempting to start
> ReadOnlyZooKeeperServer, not started*
> *2019-08-27 04:26:14,229 [myid:1566815239] - INFO
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:Learner@86][] - TCP NoDelay
> set to: true*
> *2019-08-27 04:26:14,229 [myid:1566815239] - INFO
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:ZooKeeperServer@174][] -
> Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout
> 300000 datadir /opt/fusionplatform/data/zookeeper/data/version-2 snapdir
> /opt/fusionplatform/data/zookeeper/data/version-2*
> *2019-08-27 04:26:14,230 [myid:1566815239] - INFO
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:Follower@65][] -
> {color:#FF0000}FOLLOWING - LEADER ELECTION TOOK - 36{color}*
> *2019-08-27 04:26:14,232 [myid:1566815239] - INFO
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:QuorumPeer$QuorumServer@185][]
> - Resolved hostname: 172.28.8.123 to address: /172.28.8.123*
> *2019-08-27 04:26:14,346 [myid:1566815239] - WARN
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:Learner@349][] -
> {color:#FF0000}Truncating log to get in sync with the leader 0x3{color}*
> *2019-08-27 04:26:14,371 [myid:1566815239] - INFO
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:DataTree@715][] - type:
> create, sessionid:0x10000080a040001 cxid:0x4 zxid:0x3 reqpath:/cps*
> *2019-08-27 04:26:14,374 [myid:1566815239] - WARN
> [QuorumPeer[myid=1566815239]/172.28.8.122:9880:Learner@387][] - Got zxid
> 0xa00000001 expected 0x1*
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
