zookeeper-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "wanglei (Jira)" <j...@apache.org>
Subject [jira] [Updated] (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?
Date Fri, 30 Aug 2019 07:10:00 GMT

     [ 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][]
- {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*

 

  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

 

*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*

 


> 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.2#803003)

Mime
View raw message