You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@zookeeper.apache.org by "hong (Jira)" <ji...@apache.org> on 2021/08/26 09:35:00 UTC
[jira] [Updated] (ZOOKEEPER-4352) inconsistent data, when
minCommittedLog=0, only diff data is sent but not snapshots
[ https://issues.apache.org/jira/browse/ZOOKEEPER-4352?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
hong updated ZOOKEEPER-4352:
----------------------------
Summary: inconsistent data, when minCommittedLog=0, only diff data is sent but not snapshots (was: Resulting in inconsistent data, when minCommittedLog=0, only diff data is sent but not snapshots )
> inconsistent data, when minCommittedLog=0, only diff data is sent 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
> Attachments: zk-2.log, zk-3.log
>
>
> 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)