[
https://issues.apache.org/jira/browse/ZOOKEEPER-4352?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17408642#comment-17408642
]
hong commented on ZOOKEEPER-4352:
---------------------------------
if minCommittedLog > 0 and minCommittedLog == peerLastZxid, leader send
commitLog in memery is no problem. But when minCommittedLog ==0, it mean that
the peer have not any proposals. So this need send snapshots and txlog.
I have fixed it in my pull request.
it alse confuse me with that Why proposals have the zxid is 0? when recevie
proposal that zxid is 0, Could follower give up it?
I think that an follower syncing with leader means epcho > 0, so zxid alse
greater than 0.
> inconsistent data, when minCommittedLog=0, only diff data send but not
> snapshots
> ----------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-4352
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-4352
> Project: ZooKeeper
> Issue Type: Bug
> Components: quorum
> Affects Versions: 3.6.3, 3.7.0
> Reporter: hong
> Priority: Critical
> Labels: pull-request-available
> Fix For: 3.6.3
>
> Attachments: zk-2.log, zk-3.log
>
> Time Spent: 20m
> Remaining Estimate: 0h
>
> leader is zookeeper-0, it add zk-1and zk-2. when adding zk-3, zk-2 become
> leader, but it minCommittedLog=0. After adding zk-3, zk-3 just receive the
> DIFF message from zk-2, so resulting in inconsistent data.
> Is there any error?
> {code:java}
> else if ((maxCommittedLog >= peerLastZxid) && (minCommittedLog <=
> peerLastZxid)) {
> // Follower is within commitLog range
> LOG.info("Using committedLog for peer sid: {}", getSid());
> Iterator<Proposal> itr = db.getCommittedLog().iterator();
> currentZxid = queueCommittedProposals(itr, peerLastZxid, null,
> maxCommittedLog);
> needSnap = false;
> }
> {code}
> there are logs:
> ###ZK-2
> 021-08-26 02:02:07,698 [myid:3] - INFO [NIOWorkerThread-1:NIOServerCnxn@507]
> - Processing ruok command from /127.0.0.1:56458
> 2021-08-26 02:02:08,046 [myid:3] - INFO
> [ListenerHandler-zookeeper-2.zookeeper-headless.default.svc.cluster.local/10.233.64.34:3888:QuorumCnxManager$Listener$ListenerHandler@1070]
> - Received connection request from /10.233.64.36:50788
> 2021-08-26 02:02:08,072 [myid:3] - INFO
> [LearnerHandler-/10.233.64.36:60310:LearnerHandler@504] - Follower sid: 4 :
> info :
> zookeeper-3.zookeeper-headless.default.svc.cluster.local:2888:3888:observer;0.0.0.0:2181
> 2021-08-26 02:02:08,073 [myid:3] - INFO
> [LearnerHandler-/10.233.64.36:60310:ZKDatabase@345] - On disk txn sync
> enabled with snapshotSizeFactor 0.33
> 2021-08-26 02:02:08,074 [myid:3] - INFO
> [LearnerHandler-/10.233.64.36:60310:LearnerHandler@807] -
> *{color:#ff0000}Synchronizing with Learner sid: 4 maxCommittedLog=0x200000003
> minCommittedLog=0x0 lastProcessedZxid=0x200000003 peerLastZxid=0x0{color}*
> *{color:#ff0000}2021-08-26 02:02:08,074 [myid:3] - INFO
> [LearnerHandler-/10.233.64.36:60310:LearnerHandler@871] - Using committedLog
> for peer sid: 4{color}*
> *{color:#ff0000}2021-08-26 02:02:08,074 [myid:3] - INFO
> [LearnerHandler-/10.233.64.36:60310:LearnerHandler@979] - Sending DIFF
> zxid=0x200000003 for peer sid: 4{color}*
> 2021-08-26 02:02:09,250 [myid:3] - INFO
> [WorkerReceiver[myid=3]:FastLeaderElection$Messenger$WorkerReceiver@471] -
> WorkerReceiver is down
> 2021-08-26 02:02:09,250 [myid:3] - INFO
> [WorkerSender[myid=3]:FastLeaderElection$Messenger$WorkerSender@505] -
> WorkerSender is down
> 2021-08-26 02:02:12,898 [myid:3] - INFO
> [NIOWorkerThread-2:NIOServerCnxn@507] - Processing ruok command from
> /127.0.0.1:56516
>
> ###ZK-3
> 2021-08-26 02:02:08,064 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):ZooKeeperServer@1512]
> - The large request threshold is set to -1
> 2021-08-26 02:02:08,064 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):ZooKeeperServer@339]
> - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout
> 40000 clientPortListenBacklog -1 datadir /data/version-2 snapdir
> /data/version-2
> 2021-08-26 02:02:08,064 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):ObserverZooKeeperServer@55]
> - syncEnabled =true
> 2021-08-26 02:02:08,066 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):QuorumPeer@864] -
> Peer state changed: observing - discovery
> 2021-08-26 02:02:08,067 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):Observer@163] -
> Observing new leader sid=3
> addr=zookeeper-2.zookeeper-headless.default.svc.cluster.local/10.233.64.34:2888
> 2021-08-26 02:02:08,068 [myid:4] - INFO
> [LeaderConnector-zookeeper-2.zookeeper-headless.default.svc.cluster.local/10.233.64.34:2888:Learner$LeaderConnector@370]
> - Successfully connected to leader, using address:
> zookeeper-2.zookeeper-headless.default.svc.cluster.local/10.233.64.34:2888
> 2021-08-26 02:02:08,072 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):QuorumPeer@864] -
> Peer state changed: observing - synchronization
> 2021-08-26 02:02:08,073 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):Learner@551] -
> *{color:#ff0000}Getting a diff from the leader 0x200000003{color}*
> 2021-08-26 02:02:08,073 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):QuorumPeer@869] -
> Peer state changed: observing - synchronization - diff
> 2021-08-26 02:02:08,077 [myid:4] - *{color:#ff0000}WARN
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):Learner@617] - Got
> zxid 0x100000023 expected 0x1{color}*
> *{color:#ff0000}2021-08-26 02:02:08,078 [myid:4] - ERROR
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):QuorumPeer@1836] -
> setLastSeenQuorumVerifier called with stale config 4294967332. Current
> version: 8589934595{color}*
> *{color:#ff0000}2021-08-26 02:02:08,080 [myid:4] - WARN
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):Learner@617] - Got
> zxid 0x200000001 expected 0x10000002e{color}*
> 2021-08-26 02:02:08,082 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):Learner@717] -
> Learner received NEWLEADER message
> 2021-08-26 02:02:08,083 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):QuorumPeer@869] -
> Peer state changed: observing - synchronization
> 2021-08-26 02:02:08,086 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):CommitProcessor@476]
> - Configuring CommitProcessor with readBatchSize -1 commitBatchSize 1
> 2021-08-26 02:02:08,086 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):CommitProcessor@438]
> - Configuring CommitProcessor with 1 worker threads.
> 2021-08-26 02:02:08,088 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):RequestThrottler@74]
> - zookeeper.request_throttler.shutdownTimeout = 10000
> 2021-08-26 02:02:08,098 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):Learner@701] -
> Learner received UPTODATE message
> 2021-08-26 02:02:08,099 [myid:4] - INFO [SyncThread:4:FileTxnLog@284] -
> Creating new log file: log.100000023
> 2021-08-26 02:02:08,099 [myid:4] - INFO
> [CommitProcessor:4:LearnerSessionTracker@116] - Committing global session
> 0x100001170e3000d
> 2021-08-26 02:02:08,099 [myid:4] - INFO
> [QuorumPeer[myid=4](plain=0.0.0.0:2181)(secure=disabled):QuorumPeer@864] -
> Peer state changed: observing - broadcast
> 2021-08-26 02:02:08,100 [myid:4] - WARN [CommitProcessor:4:RateLogger@86] -
> Message:Digests are not matching. Value is Zxid. Value:4294967331
> 2021-08-26 02:02:08,101 [myid:4] - {color:#ff0000}ERROR
> [CommitProcessor:4:DataTree@1832] - First digest mismatch on txn:
> 72057668946296845,0,4294967331,1629943304746,-10{color}
> {color:#ff0000} , 4000{color}
> {color:#ff0000} , expected digest is 2,10124071835{color}
> {color:#ff0000} , actual digest is 1371985504,{color}
> 2021-08-26 02:02:08,102 [myid:4] - INFO
> [CommitProcessor:4:LearnerSessionTracker@116] - Committing global session
> 0x200000b302e0000
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
