[ZOOKEEPER-3526] data inconsistency due to mistaken TRUNC caused by maxCommittedLog is much less than minCommittedLog when in readonly mode - ASF JIRA

Details

Type: Bug
Status: Open
Priority: Major
Resolution: Unresolved
Affects Version/s: 3.4.14
Fix Version/s: None
Component/s: server
Labels:
- pull-request-available
Environment:

1.version:3.4.14

2.num of zk nodes: 3

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

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.

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