[
https://issues.apache.org/jira/browse/ZOOKEEPER-3526?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
wanglei updated ZOOKEEPER-3526:
-------------------------------
Description:
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][] - LEADING - LEADER
ELECTION TOOK - 15297*
*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][] - Synchronizing with
Follower sid: 1566815238 maxCommittedLog=0x3 minCommittedLog=0x9000002d9
peerLastZxid=0x9000004ca*
*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*
maxCommittedLog=0x3 minCommittedLog=0x9000002d9 peerLastZxid=0x9000004ca
{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][] - FOLLOWING -
LEADER ELECTION TOOK - 36*
*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][] - Truncating log
to get in sync with the leader 0x3*
*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*
was:
1.Node1:1566815238 (myid)、Node2:1566815239 (myid)、Node3:1566815240 (myid)
2.After a election, Node3 become the new leader, begin to sync with followers
!image-2019-08-30-12-57-33-883.png!
maxCommittedLog=0x3 minCommittedLog=0x9000002d9 peerLastZxid=0x9000004ca
*why maxCommittedLog < minCommittedLog?*
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.
!image-2019-08-30-13-07-31-467.png!
> 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][] - LEADING -
> LEADER ELECTION TOOK - 15297*
> *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][] - Synchronizing with
> Follower sid: 1566815238 maxCommittedLog=0x3 minCommittedLog=0x9000002d9
> peerLastZxid=0x9000004ca*
> *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*
> maxCommittedLog=0x3 minCommittedLog=0x9000002d9 peerLastZxid=0x9000004ca
> {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][] - FOLLOWING -
> LEADER ELECTION TOOK - 36*
> *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][] - Truncating
> log to get in sync with the leader 0x3*
> *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.2#803003)
