You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@zookeeper.apache.org by "maoling (Jira)" <ji...@apache.org> on 2020/02/25 07:25:00 UTC
[jira] [Commented] (ZOOKEEPER-3526) When a zk Node just become the leader,synchronizing with Follower in the first time, the value of maxCommittedLog may be smaller than the value of minCommittedLog，is that a problem?
[ https://issues.apache.org/jira/browse/ZOOKEEPER-3526?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17044181#comment-17044181 ]
maoling commented on ZOOKEEPER-3526:
------------------------------------
**[~kiddou]
maxCommittedLog(0x3) has overflow? If not, why is is so smaller?
The leader judges follwer's *peerLastZxid* > maxCommittedLog, so Send it a TRUNC MSG
I still need some time to take a close at source code. I'm always here If you have provided more contexts
*{color:#ff0000}{color}*
> When a zk Node just become the leader,synchronizing with Follower in the first time, the value of maxCommittedLog may be smaller than the value of minCommittedLog，is that a problem?
> --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> 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
>
> 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)