Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 3D748200D44 for ; Mon, 20 Nov 2017 09:32:10 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id 3BC96160BF9; Mon, 20 Nov 2017 08:32:10 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id D7EA7160BEC for ; Mon, 20 Nov 2017 09:32:08 +0100 (CET) Received: (qmail 13463 invoked by uid 500); 20 Nov 2017 08:32:07 -0000 Mailing-List: contact dev-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list dev@zookeeper.apache.org Received: (qmail 13452 invoked by uid 99); 20 Nov 2017 08:32:07 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 20 Nov 2017 08:32:07 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id 201F31A20E4 for ; Mon, 20 Nov 2017 08:32:07 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -99.202 X-Spam-Level: X-Spam-Status: No, score=-99.202 tagged_above=-999 required=6.31 tests=[KAM_ASCII_DIVIDERS=0.8, RP_MATCHES_RCVD=-0.001, SPF_PASS=-0.001, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id uvlbph5CclPy for ; Mon, 20 Nov 2017 08:32:01 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 007BE5FD14 for ; Mon, 20 Nov 2017 08:32:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 7324AE095A for ; Mon, 20 Nov 2017 08:32:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 2369D240D6 for ; Mon, 20 Nov 2017 08:32:00 +0000 (UTC) Date: Mon, 20 Nov 2017 08:32:00 +0000 (UTC) From: "Beom Heyn Kim (JIRA)" To: dev@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (ZOOKEEPER-2945) Synchronization code on the follower does not truncate uncommitted write when it receives SNAP from the leader MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Mon, 20 Nov 2017 08:32:10 -0000 [ https://issues.apache.org/jira/browse/ZOOKEEPER-2945?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:all-tabpanel ] Beom Heyn Kim updated ZOOKEEPER-2945: ------------------------------------- Description:=20 Synchronization code in the syncWithLeader function of Learner.java seems n= ot properly truncating the uncommitted write when the follower receives SNA= P msg from the leader. So, inconsistency can occur in the in-memory data tr= ee across nodes. Here is one procedure to reproduce the inconsistency. (Act= ually, this seems similar to my previous report on ZOOKEEPER-2832, but it w= as for 3.4.10 and this one is for 3.4.11 and later) Initially: # Start the ensemble with three nodes: node 0, 1 and 2 (the node 2 is the l= eader) # Create 5 znodes with initial values as follow (key =3D value) {noformat} /testDivergenceResync0 =3D 0 /testDivergenceResync1 =3D 1 /testDivergenceResync2 =3D 2 /testDivergenceResync3 =3D 3 /testDivergenceResync4 =3D 4 {noformat} To Reproduce: # Diverge the node 2 a. Shutdown the node 0 and 1 b. Async setData to the node 2 writing 1000 to the key =E2=80=98/testDiverg= enceResync0=E2=80=99 c. Shutdown the node 2 # Restart the node 0 and 1 (let them finish with resync) # Diverge the node 1 a. Shutdown the node 0 b. Async setData to the node 1 writing 1001 to the key =E2=80=98/testDiverg= enceResync1=E2=80=99 c. Shutdown the node 1 # Restart the node 0 and 1 (let them finish with resync) # Diverge the node 1 a. Shutdown the node 0 b. Async setData to the node 1 writing 1002 to the key =E2=80=98/testDiverg= enceResync2=E2=80=99 c. Shutdown the node 1 # Restart the node 0 and 2 (let them finish with resync) # Diverge the node 0 a. Shutdown the node 2 b. Async setData to the node 0 writing 1003 to the key =E2=80=98/testDiverg= enceResync3=E2=80=99 c. Shutdown the node 0 # Restart the node 1 and 2 (let them finish with resync) # Diverge the node 2 a. Shutdown the node 1 b. Async setData to the node 2 writing 1004 to the key =E2=80=98/testDiverg= enceResync4=E2=80=99 c. Shutdown the node 2 # Restart the node 1 and 2 (let them finish with resync) # Restart the node 0 (let it finish with resync) Reading each key from each node directly will give us the output: {noformat} /testDivergenceResync0 on the node 0 =3D 0 /testDivergenceResync0 on the node 1 =3D 0 /testDivergenceResync0 on the node 2 =3D 0 /testDivergenceResync1 on the node 0 =3D 1001 /testDivergenceResync1 on the node 1 =3D 1001 /testDivergenceResync1 on the node 2 =3D 1001 /testDivergenceResync2 on the node 0 =3D 2 /testDivergenceResync2 on the node 1 =3D 1002 /testDivergenceResync2 on the node 2 =3D 2 /testDivergenceResync3 on the node 0 =3D 3 /testDivergenceResync3 on the node 1 =3D 3 /testDivergenceResync3 on the node 2 =3D 3 /testDivergenceResync4 on the node 0 =3D 1004 /testDivergenceResync4 on the node 1 =3D 1004 /testDivergenceResync4 on the node 2 =3D 1004 {noformat} Thus, the value of key /testDivergenceResync2 is inconsistent across nodes. What seems to happen: At the step 5, setData (at zxid 0x300000001) writing the value 1002 is comm= itted on the node 1. Log from the node 1:=20 2017-11-16 03:02:19,964 [myid:1] - DEBUG [ProcessThread(sid:1 cport:-1)::Co= mmitProcessor@174] - Processing request:: sessionid:0x100011108080000 type:= setData cxid:0x4 zxid:0x300000001 txntype:5 reqpath:n/a 2017-11-16 03:02:19,964 [myid:1] - DEBUG [ProcessThread(sid:1 cport:-1)::Le= ader@787] - Proposing:: sessionid:0x100011108080000 type:setData cxid:0x4 z= xid:0x300000001 txntype:5 reqpath:n/a 2017-11-16 03:02:19,965 [myid:1] - INFO [SyncThread:1:FileTxnLog@209] - Cr= eating new log file: log.300000001 2017-11-16 03:02:20,016 [myid:1] - DEBUG [SyncThread:1:Leader@600] - Count = for zxid: 0x300000001 is 1 2017-11-16 03:02:21,173 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Leader@512] - Shutting down 2017-11-16 03:02:21,173 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Leader@518] - Shutdown called java.lang.Exception: shutdown Leader! reason: Not sufficient followers sync= ed, only synced with sids: [ 1 ] ... At the step 8, the node 1 is restarted and supposed to be properly resync= =E2=80=99ed with the node 2 which is the leader.=20 Log from the node 2: ... 2017-11-16 03:02:37,470 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@372] - LEADING - LEADER ELECTION TOOK - 232 2017-11-16 03:02:37,479 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@346] - Follower sid: 1 : info : org.apache.zookeeper.server.q= uorum.QuorumPeer$QuorumServer@46cc2846 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@401] - Synchronizing with Follower sid: 1 maxCommittedLog=3D0= x0 minCommittedLog=3D0x0 peerLastZxid=3D0x300000001 2017-11-16 03:02:37,626 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@472] - proposals is empty 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@475] - Sending SNAP 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@499] - Sending snapshot last zxid of peer is 0x300000001 zxi= d of leader is 0x500000000sent zxid of db as 0x200000001 2017-11-16 03:02:37,701 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@535] - Received NEWLEADER-ACK message from 1 2017-11-16 03:02:37,702 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@962] - Have quorum of supporters, sids: [ 1,2 ]; starting = up and setting last processed zxid: 0x500000000 ... Log from the node 1: ... 2017-11-16 03:02:37,473 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 218 2017-11-16 03:02:37,475 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:QuorumPeer$QuorumServer@184] - Resolved hostname:=20 127.0.0.1 to address: /127.0.0.1 2017-11-16 03:02:37,593 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxnFactory@215] - Accepted socket connection from /127.= 0.0.1:57338 2017-11-16 03:02:37,626 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Learner@336] - Getting a snapshot from leader 0x200000001 2017-11-16 03:02:37,627 [myid:1] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxn@383] - Exception causing close of=20 session 0x0: ZooKeeperServer not running 2017-11-16 03:02:37,627 [myid:1] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxn@386] - IOException stack trace java.io.IOException: ZooKeeperServer not running at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCn= xn.java:977) at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.jav= a:257) at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCn= xnFactory.java:226) at java.lang.Thread.run(Thread.java:745) 2017-11-16 03:02:37,627 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxn@1040] - Closed socket connection f or client /127.0.0.1:57338 (no session established for client) 2017-11-16 03:02:37,629 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:FileTxnSnapLog@248] - Snapshotting: 0x200000001 to /home/ben/proj= ect/strata/test-5-3-ZooKeeper-3.4.11-strata-0.1/data/1/version-2/snapshot.2= 00000001 ... Comment: The node 2 sends SNAP msg so that the node 1 can restore its in-memory data= tree from the snapshot of the in-memory data tree on the node 2.=20 On the other hand, the node 1 will clear its in-memory data tree and restor= e it with the snapshot from the node 2. Then, it takes its own snapshot at = zxid 0x200000001.=20 However, this does not remove the setData at zxid 0x300000001 from the tran= saction log on the node 1. At the step 10, the node 1 is restarted again and supposed to be properly r= esync=E2=80=99ed with the node 2 which is the leader again. Log from the node 2: =E2=80=A6 2017-11-16 03:03:21,033 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@372] - LEADING - LEADER ELECTION TOOK - 217 2017-11-16 03:03:21,038 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@346] - Follower sid: 1 : info : org.apache.zookeeper.server.q= uorum.QuorumPeer$QuorumServer@1e1cf18c 2017-11-16 03:03:21,103 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@401] - Synchronizing with Follower sid: 1 maxCommittedLog=3D0= x500000004 minCommittedLog=3D0x500000001 peerLastZxid=3D0x500000003 2017-11-16 03:03:21,103 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@415] - proposal size is 4 2017-11-16 03:03:21,103 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@418] - Sending proposals to follower 2017-11-16 03:03:21,103 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@475] - Sending DIFF 2017-11-16 03:03:21,156 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxnFactory@215] - Accepted socket connection from /127.= 0.0.1:49611 2017-11-16 03:03:21,178 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@535] - Received NEWLEADER-ACK message from 1 2017-11-16 03:03:21,178 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@962] - Have quorum of supporters, sids: [ 1,2 ]; starting = up and setting last processed zxid: 0x600000000 2017-11-16 03:03:21,196 [myid:2] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxn@383] - Exception causing close of session 0x0: ZooK= eeperServer not running 2017-11-16 03:03:21,196 [myid:2] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxn@386] - IOException stack trace java.io.IOException: ZooKeeperServer not running at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCn= xn.java:977) at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.jav= a:257) at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCn= xnFactory.java:226) at java.lang.Thread.run(Thread.java:745) 2017-11-16 03:03:21,196 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxn@1040] - Closed socket connection for client /127.0.= 0.1:49611 (no session established for client) 2017-11-16 03:03:21,237 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967:L= eader@579] - outstanding is 0 ... Log from the node 1: =E2=80=A6 2017-11-16 03:03:21,034 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 222 2017-11-16 03:03:21,035 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:QuorumPeer$QuorumServer@184] - Resolved hostname: 127.0.0.1 to ad= dress: /127.0.0.1 2017-11-16 03:03:21,104 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Learner@332] - Getting a diff from the leader 0x500000004 2017-11-16 03:03:21,105 [myid:1] - WARN [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Learner@387] - Got zxid 0x500000004 expected 0x1 2017-11-16 03:03:21,189 [myid:1] - INFO [SyncThread:1:FileTxnLog@209] - Cr= eating new log file: log.500000004 2017-11-16 03:03:21,189 [myid:1] - DEBUG [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:CommitProcessor@164] - Committing request:: sessionid:0x200011108= 2b0000 type:setData cxid:0x4 zxid:0x500000004 txntype:5 reqpath:n/a 2017-11-16 03:03:21,189 [myid:1] - DEBUG [CommitProcessor:1:FinalRequestPro= cessor@89] - Processing request:: sessionid:0x2000111082b0000 type:setData = cxid:0x4 zxid:0x500000004 txntype:5 reqpath:n/a ... Comment: When the node 1 is restarted, it restores its in-memory data tree from the = snapshot at zxid 0x200000001 and replay setData at zxid 0x300000001 (which = actually needed to be truncated) However, the node 2 just sends DIFF containing setData written at 9th path,= and no truncation will be occurred. As a result, the node 1 still has the value 1002 while other nodes will hav= e the value 2 for the same key was: Synchronization code in the syncWithLeader function of Learner.java seems n= ot properly truncating the uncommitted write when the follower receives SNA= P msg from the leader. So, inconsistency can occur in the in-memory data tr= ee across nodes. Here is one procedure to reproduce the inconsistency. (Act= ually, this seems similar to my previous report on ZOOKEEPER-2832, but it w= as for 3.4.10 and this one is for 3.4.11 and later) Initially: # Start the ensemble with three nodes: node 0, 1 and 2 (the node 2 is the l= eader) # Create 5 znodes with initial values as follow (key =3D value) {noformat} /testDivergenceResync0 =3D 0 /testDivergenceResync1 =3D 1 /testDivergenceResync2 =3D 2 /testDivergenceResync3 =3D 3 /testDivergenceResync4 =3D 4 {noformat} To Reproduce: # Diverge the node 2 a. Shutdown the node 0 and 1 b. Async setData to the node 2 writing 1000 to the key =E2=80=98/testDiverg= enceResync0=E2=80=99 c. Shutdown the node 2 # Restart the node 0 and 1 (let them finish with resync) # Diverge the node 1 ## Shutdown the node 0 ## Async setData to the node 1 writing 1001 to the key =E2=80=98/testDiverg= enceResync1=E2=80=99 ## Shutdown the node 1 # Restart the node 0 and 1 (let them finish with resync) # Diverge the node 1 ## Shutdown the node 0 ## Async setData to the node 1 writing 1002 to the key =E2=80=98/testDiverg= enceResync2=E2=80=99 ## Shutdown the node 1 # Restart the node 0 and 2 (let them finish with resync) # Diverge the node 0 ## Shutdown the node 2 ## Async setData to the node 0 writing 1003 to the key =E2=80=98/testDiverg= enceResync3=E2=80=99 ## Shutdown the node 0 # Restart the node 1 and 2 (let them finish with resync) # Diverge the node 2 ## Shutdown the node 1 ## Async setData to the node 2 writing 1004 to the key =E2=80=98/testDiverg= enceResync4=E2=80=99 ## Shutdown the node 2 # Restart the node 1 and 2 (let them finish with resync) # Restart the node 0 (let it finish with resync) Reading each key from each node directly will give us the output: {noformat} /testDivergenceResync0 on the node 0 =3D 0 /testDivergenceResync0 on the node 1 =3D 0 /testDivergenceResync0 on the node 2 =3D 0 /testDivergenceResync1 on the node 0 =3D 1001 /testDivergenceResync1 on the node 1 =3D 1001 /testDivergenceResync1 on the node 2 =3D 1001 /testDivergenceResync2 on the node 0 =3D 2 /testDivergenceResync2 on the node 1 =3D 1002 /testDivergenceResync2 on the node 2 =3D 2 /testDivergenceResync3 on the node 0 =3D 3 /testDivergenceResync3 on the node 1 =3D 3 /testDivergenceResync3 on the node 2 =3D 3 /testDivergenceResync4 on the node 0 =3D 1004 /testDivergenceResync4 on the node 1 =3D 1004 /testDivergenceResync4 on the node 2 =3D 1004 {noformat} Thus, the value of key /testDivergenceResync2 is inconsistent across nodes. What seems to happen: At the step 5, setData (at zxid 0x300000001) writing the value 1002 is comm= itted on the node 1. Log from the node 1:=20 2017-11-16 03:02:19,964 [myid:1] - DEBUG [ProcessThread(sid:1 cport:-1)::Co= mmitProcessor@174] - Processing request:: sessionid:0x100011108080000 type:= setData cxid:0x4 zxid:0x300000001 txntype:5 reqpath:n/a 2017-11-16 03:02:19,964 [myid:1] - DEBUG [ProcessThread(sid:1 cport:-1)::Le= ader@787] - Proposing:: sessionid:0x100011108080000 type:setData cxid:0x4 z= xid:0x300000001 txntype:5 reqpath:n/a 2017-11-16 03:02:19,965 [myid:1] - INFO [SyncThread:1:FileTxnLog@209] - Cr= eating new log file: log.300000001 2017-11-16 03:02:20,016 [myid:1] - DEBUG [SyncThread:1:Leader@600] - Count = for zxid: 0x300000001 is 1 2017-11-16 03:02:21,173 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Leader@512] - Shutting down 2017-11-16 03:02:21,173 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Leader@518] - Shutdown called java.lang.Exception: shutdown Leader! reason: Not sufficient followers sync= ed, only synced with sids: [ 1 ] ... At the step 8, the node 1 is restarted and supposed to be properly resync= =E2=80=99ed with the node 2 which is the leader.=20 Log from the node 2: ... 2017-11-16 03:02:37,470 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@372] - LEADING - LEADER ELECTION TOOK - 232 2017-11-16 03:02:37,479 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@346] - Follower sid: 1 : info : org.apache.zookeeper.server.q= uorum.QuorumPeer$QuorumServer@46cc2846 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@401] - Synchronizing with Follower sid: 1 maxCommittedLog=3D0= x0 minCommittedLog=3D0x0 peerLastZxid=3D0x300000001 2017-11-16 03:02:37,626 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@472] - proposals is empty 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@475] - Sending SNAP 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@499] - Sending snapshot last zxid of peer is 0x300000001 zxi= d of leader is 0x500000000sent zxid of db as 0x200000001 2017-11-16 03:02:37,701 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899:L= earnerHandler@535] - Received NEWLEADER-ACK message from 1 2017-11-16 03:02:37,702 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@962] - Have quorum of supporters, sids: [ 1,2 ]; starting = up and setting last processed zxid: 0x500000000 ... Log from the node 1: ... 2017-11-16 03:02:37,473 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 218 2017-11-16 03:02:37,475 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:QuorumPeer$QuorumServer@184] - Resolved hostname:=20 127.0.0.1 to address: /127.0.0.1 2017-11-16 03:02:37,593 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxnFactory@215] - Accepted socket connection from /127.= 0.0.1:57338 2017-11-16 03:02:37,626 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Learner@336] - Getting a snapshot from leader 0x200000001 2017-11-16 03:02:37,627 [myid:1] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxn@383] - Exception causing close of=20 session 0x0: ZooKeeperServer not running 2017-11-16 03:02:37,627 [myid:1] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxn@386] - IOException stack trace java.io.IOException: ZooKeeperServer not running at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCn= xn.java:977) at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.jav= a:257) at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCn= xnFactory.java:226) at java.lang.Thread.run(Thread.java:745) 2017-11-16 03:02:37,627 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11224:NIOServerCnxn@1040] - Closed socket connection f or client /127.0.0.1:57338 (no session established for client) 2017-11-16 03:02:37,629 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:FileTxnSnapLog@248] - Snapshotting: 0x200000001 to /home/ben/proj= ect/strata/test-5-3-ZooKeeper-3.4.11-strata-0.1/data/1/version-2/snapshot.2= 00000001 ... Comment: The node 2 sends SNAP msg so that the node 1 can restore its in-memory data= tree from the snapshot of the in-memory data tree on the node 2.=20 On the other hand, the node 1 will clear its in-memory data tree and restor= e it with the snapshot from the node 2. Then, it takes its own snapshot at = zxid 0x200000001.=20 However, this does not remove the setData at zxid 0x300000001 from the tran= saction log on the node 1. At the step 10, the node 1 is restarted again and supposed to be properly r= esync=E2=80=99ed with the node 2 which is the leader again. Log from the node 2: =E2=80=A6 2017-11-16 03:03:21,033 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@372] - LEADING - LEADER ELECTION TOOK - 217 2017-11-16 03:03:21,038 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@346] - Follower sid: 1 : info : org.apache.zookeeper.server.q= uorum.QuorumPeer$QuorumServer@1e1cf18c 2017-11-16 03:03:21,103 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@401] - Synchronizing with Follower sid: 1 maxCommittedLog=3D0= x500000004 minCommittedLog=3D0x500000001 peerLastZxid=3D0x500000003 2017-11-16 03:03:21,103 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@415] - proposal size is 4 2017-11-16 03:03:21,103 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@418] - Sending proposals to follower 2017-11-16 03:03:21,103 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@475] - Sending DIFF 2017-11-16 03:03:21,156 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxnFactory@215] - Accepted socket connection from /127.= 0.0.1:49611 2017-11-16 03:03:21,178 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967:L= earnerHandler@535] - Received NEWLEADER-ACK message from 1 2017-11-16 03:03:21,178 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:0:= 0:0:11227:Leader@962] - Have quorum of supporters, sids: [ 1,2 ]; starting = up and setting last processed zxid: 0x600000000 2017-11-16 03:03:21,196 [myid:2] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxn@383] - Exception causing close of session 0x0: ZooK= eeperServer not running 2017-11-16 03:03:21,196 [myid:2] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxn@386] - IOException stack trace java.io.IOException: ZooKeeperServer not running at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCn= xn.java:977) at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.jav= a:257) at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCn= xnFactory.java:226) at java.lang.Thread.run(Thread.java:745) 2017-11-16 03:03:21,196 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.= 0.0:11227:NIOServerCnxn@1040] - Closed socket connection for client /127.0.= 0.1:49611 (no session established for client) 2017-11-16 03:03:21,237 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967:L= eader@579] - outstanding is 0 ... Log from the node 1: =E2=80=A6 2017-11-16 03:03:21,034 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 222 2017-11-16 03:03:21,035 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:QuorumPeer$QuorumServer@184] - Resolved hostname: 127.0.0.1 to ad= dress: /127.0.0.1 2017-11-16 03:03:21,104 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Learner@332] - Getting a diff from the leader 0x500000004 2017-11-16 03:03:21,105 [myid:1] - WARN [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:Learner@387] - Got zxid 0x500000004 expected 0x1 2017-11-16 03:03:21,189 [myid:1] - INFO [SyncThread:1:FileTxnLog@209] - Cr= eating new log file: log.500000004 2017-11-16 03:03:21,189 [myid:1] - DEBUG [QuorumPeer[myid=3D1]/0:0:0:0:0:0:= 0:0:11224:CommitProcessor@164] - Committing request:: sessionid:0x200011108= 2b0000 type:setData cxid:0x4 zxid:0x500000004 txntype:5 reqpath:n/a 2017-11-16 03:03:21,189 [myid:1] - DEBUG [CommitProcessor:1:FinalRequestPro= cessor@89] - Processing request:: sessionid:0x2000111082b0000 type:setData = cxid:0x4 zxid:0x500000004 txntype:5 reqpath:n/a ... Comment: When the node 1 is restarted, it restores its in-memory data tree from the = snapshot at zxid 0x200000001 and replay setData at zxid 0x300000001 (which = actually needed to be truncated) However, the node 2 just sends DIFF containing setData written at 9th path,= and no truncation will be occurred. As a result, the node 1 still has the value 1002 while other nodes will hav= e the value 2 for the same key > Synchronization code on the follower does not truncate uncommitted write = when it receives SNAP from the leader > -------------------------------------------------------------------------= ------------------------------------- > > Key: ZOOKEEPER-2945 > URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2945 > Project: ZooKeeper > Issue Type: Bug > Affects Versions: 3.4.11, 3.4.12 > Reporter: Beom Heyn Kim > > Synchronization code in the syncWithLeader function of Learner.java seems= not properly truncating the uncommitted write when the follower receives S= NAP msg from the leader. So, inconsistency can occur in the in-memory data = tree across nodes. Here is one procedure to reproduce the inconsistency. (A= ctually, this seems similar to my previous report on ZOOKEEPER-2832, but it= was for 3.4.10 and this one is for 3.4.11 and later) > Initially: > # Start the ensemble with three nodes: node 0, 1 and 2 (the node 2 is the= leader) > # Create 5 znodes with initial values as follow (key =3D value) > {noformat} > /testDivergenceResync0 =3D 0 > /testDivergenceResync1 =3D 1 > /testDivergenceResync2 =3D 2 > /testDivergenceResync3 =3D 3 > /testDivergenceResync4 =3D 4 > {noformat} > To Reproduce: > # Diverge the node 2 > a. Shutdown the node 0 and 1 > b. Async setData to the node 2 writing 1000 to the key =E2=80=98/testDive= rgenceResync0=E2=80=99 > c. Shutdown the node 2 > # Restart the node 0 and 1 (let them finish with resync) > # Diverge the node 1 > a. Shutdown the node 0 > b. Async setData to the node 1 writing 1001 to the key =E2=80=98/testDive= rgenceResync1=E2=80=99 > c. Shutdown the node 1 > # Restart the node 0 and 1 (let them finish with resync) > # Diverge the node 1 > a. Shutdown the node 0 > b. Async setData to the node 1 writing 1002 to the key =E2=80=98/testDive= rgenceResync2=E2=80=99 > c. Shutdown the node 1 > # Restart the node 0 and 2 (let them finish with resync) > # Diverge the node 0 > a. Shutdown the node 2 > b. Async setData to the node 0 writing 1003 to the key =E2=80=98/testDive= rgenceResync3=E2=80=99 > c. Shutdown the node 0 > # Restart the node 1 and 2 (let them finish with resync) > # Diverge the node 2 > a. Shutdown the node 1 > b. Async setData to the node 2 writing 1004 to the key =E2=80=98/testDive= rgenceResync4=E2=80=99 > c. Shutdown the node 2 > # Restart the node 1 and 2 (let them finish with resync) > # Restart the node 0 (let it finish with resync) > Reading each key from each node directly will give us the output: > {noformat} > /testDivergenceResync0 on the node 0 =3D 0 > /testDivergenceResync0 on the node 1 =3D 0 > /testDivergenceResync0 on the node 2 =3D 0 > /testDivergenceResync1 on the node 0 =3D 1001 > /testDivergenceResync1 on the node 1 =3D 1001 > /testDivergenceResync1 on the node 2 =3D 1001 > /testDivergenceResync2 on the node 0 =3D 2 > /testDivergenceResync2 on the node 1 =3D 1002 > /testDivergenceResync2 on the node 2 =3D 2 > /testDivergenceResync3 on the node 0 =3D 3 > /testDivergenceResync3 on the node 1 =3D 3 > /testDivergenceResync3 on the node 2 =3D 3 > /testDivergenceResync4 on the node 0 =3D 1004 > /testDivergenceResync4 on the node 1 =3D 1004 > /testDivergenceResync4 on the node 2 =3D 1004 > {noformat} > Thus, the value of key /testDivergenceResync2 is inconsistent across node= s. > What seems to happen: > At the step 5, setData (at zxid 0x300000001) writing the value 1002 is co= mmitted on the node 1. > Log from the node 1:=20 > 2017-11-16 03:02:19,964 [myid:1] - DEBUG [ProcessThread(sid:1 cport:-1)::= CommitProcessor@174] - Processing request:: sessionid:0x100011108080000 typ= e:setData cxid:0x4 zxid:0x300000001 txntype:5 reqpath:n/a > 2017-11-16 03:02:19,964 [myid:1] - DEBUG [ProcessThread(sid:1 cport:-1)::= Leader@787] - Proposing:: sessionid:0x100011108080000 type:setData cxid:0x4= zxid:0x300000001 txntype:5 reqpath:n/a > 2017-11-16 03:02:19,965 [myid:1] - INFO [SyncThread:1:FileTxnLog@209] - = Creating new log file: log.300000001 > 2017-11-16 03:02:20,016 [myid:1] - DEBUG [SyncThread:1:Leader@600] - Coun= t for zxid: 0x300000001 is 1 > 2017-11-16 03:02:21,173 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Leader@512] - Shutting down > 2017-11-16 03:02:21,173 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Leader@518] - Shutdown called > java.lang.Exception: shutdown Leader! reason: Not sufficient followers sy= nced, only synced with sids: [ 1 ] > ... > At the step 8, the node 1 is restarted and supposed to be properly resync= =E2=80=99ed with the node 2 which is the leader.=20 > Log from the node 2: > ... > 2017-11-16 03:02:37,470 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:= 0:0:0:11227:Leader@372] - LEADING - LEADER ELECTION TOOK - 232 > 2017-11-16 03:02:37,479 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899= :LearnerHandler@346] - Follower sid: 1 : info : org.apache.zookeeper.server= .quorum.QuorumPeer$QuorumServer@46cc2846 > 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899= :LearnerHandler@401] - Synchronizing with Follower sid: 1 maxCommittedLog= =3D0x0 minCommittedLog=3D0x0 peerLastZxid=3D0x300000001 > 2017-11-16 03:02:37,626 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46899= :LearnerHandler@472] - proposals is empty > 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899= :LearnerHandler@475] - Sending SNAP > 2017-11-16 03:02:37,626 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899= :LearnerHandler@499] - Sending snapshot last zxid of peer is 0x300000001 z= xid of leader is 0x500000000sent zxid of db as 0x200000001 > 2017-11-16 03:02:37,701 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46899= :LearnerHandler@535] - Received NEWLEADER-ACK message from 1 > 2017-11-16 03:02:37,702 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:= 0:0:0:11227:Leader@962] - Have quorum of supporters, sids: [ 1,2 ]; startin= g up and setting last processed zxid: 0x500000000 > ... > Log from the node 1: > ... > 2017-11-16 03:02:37,473 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 218 > 2017-11-16 03:02:37,475 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:QuorumPeer$QuorumServer@184] - Resolved hostname:=20 > 127.0.0.1 to address: /127.0.0.1 > 2017-11-16 03:02:37,593 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11224:NIOServerCnxnFactory@215] - Accepted socket connection from /12= 7.0.0.1:57338 > 2017-11-16 03:02:37,626 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Learner@336] - Getting a snapshot from leader 0x200000001 > 2017-11-16 03:02:37,627 [myid:1] - WARN [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11224:NIOServerCnxn@383] - Exception causing close of=20 > session 0x0: ZooKeeperServer not running > 2017-11-16 03:02:37,627 [myid:1] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11224:NIOServerCnxn@386] - IOException stack trace > java.io.IOException: ZooKeeperServer not running > at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServer= Cnxn.java:977) > at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.j= ava:257) > at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServer= CnxnFactory.java:226) > at java.lang.Thread.run(Thread.java:745) > 2017-11-16 03:02:37,627 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11224:NIOServerCnxn@1040] - Closed socket connection f > or client /127.0.0.1:57338 (no session established for client) > 2017-11-16 03:02:37,629 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:FileTxnSnapLog@248] - Snapshotting: 0x200000001 to /home/ben/pr= oject/strata/test-5-3-ZooKeeper-3.4.11-strata-0.1/data/1/version-2/snapshot= .200000001 > ... > Comment: > The node 2 sends SNAP msg so that the node 1 can restore its in-memory da= ta tree from the snapshot of the in-memory data tree on the node 2.=20 > On the other hand, the node 1 will clear its in-memory data tree and rest= ore it with the snapshot from the node 2. Then, it takes its own snapshot a= t zxid 0x200000001.=20 > However, this does not remove the setData at zxid 0x300000001 from the tr= ansaction log on the node 1. > At the step 10, the node 1 is restarted again and supposed to be properly= resync=E2=80=99ed with the node 2 which is the leader again. > Log from the node 2: > =E2=80=A6 > 2017-11-16 03:03:21,033 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:= 0:0:0:11227:Leader@372] - LEADING - LEADER ELECTION TOOK - 217 > 2017-11-16 03:03:21,038 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967= :LearnerHandler@346] - Follower sid: 1 : info : org.apache.zookeeper.server= .quorum.QuorumPeer$QuorumServer@1e1cf18c > 2017-11-16 03:03:21,103 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967= :LearnerHandler@401] - Synchronizing with Follower sid: 1 maxCommittedLog= =3D0x500000004 minCommittedLog=3D0x500000001 peerLastZxid=3D0x500000003 > 2017-11-16 03:03:21,103 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967= :LearnerHandler@415] - proposal size is 4 > 2017-11-16 03:03:21,103 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967= :LearnerHandler@418] - Sending proposals to follower > 2017-11-16 03:03:21,103 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967= :LearnerHandler@475] - Sending DIFF > 2017-11-16 03:03:21,156 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11227:NIOServerCnxnFactory@215] - Accepted socket connection from /12= 7.0.0.1:49611 > 2017-11-16 03:03:21,178 [myid:2] - INFO [LearnerHandler-/127.0.0.1:46967= :LearnerHandler@535] - Received NEWLEADER-ACK message from 1 > 2017-11-16 03:03:21,178 [myid:2] - INFO [QuorumPeer[myid=3D2]/0:0:0:0:0:= 0:0:0:11227:Leader@962] - Have quorum of supporters, sids: [ 1,2 ]; startin= g up and setting last processed zxid: 0x600000000 > 2017-11-16 03:03:21,196 [myid:2] - WARN [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11227:NIOServerCnxn@383] - Exception causing close of session 0x0: Zo= oKeeperServer not running > 2017-11-16 03:03:21,196 [myid:2] - DEBUG [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11227:NIOServerCnxn@386] - IOException stack trace > java.io.IOException: ZooKeeperServer not running > at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServer= Cnxn.java:977) > at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.j= ava:257) > at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServer= CnxnFactory.java:226) > at java.lang.Thread.run(Thread.java:745) > 2017-11-16 03:03:21,196 [myid:2] - INFO [NIOServerCxn.Factory:0.0.0.0/0.= 0.0.0:11227:NIOServerCnxn@1040] - Closed socket connection for client /127.= 0.0.1:49611 (no session established for client) > 2017-11-16 03:03:21,237 [myid:2] - DEBUG [LearnerHandler-/127.0.0.1:46967= :Leader@579] - outstanding is 0 > ... > Log from the node 1: > =E2=80=A6 > 2017-11-16 03:03:21,034 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Follower@65] - FOLLOWING - LEADER ELECTION TOOK - 222 > 2017-11-16 03:03:21,035 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:QuorumPeer$QuorumServer@184] - Resolved hostname: 127.0.0.1 to = address: /127.0.0.1 > 2017-11-16 03:03:21,104 [myid:1] - INFO [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Learner@332] - Getting a diff from the leader 0x500000004 > 2017-11-16 03:03:21,105 [myid:1] - WARN [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:Learner@387] - Got zxid 0x500000004 expected 0x1 > 2017-11-16 03:03:21,189 [myid:1] - INFO [SyncThread:1:FileTxnLog@209] - = Creating new log file: log.500000004 > 2017-11-16 03:03:21,189 [myid:1] - DEBUG [QuorumPeer[myid=3D1]/0:0:0:0:0:= 0:0:0:11224:CommitProcessor@164] - Committing request:: sessionid:0x2000111= 082b0000 type:setData cxid:0x4 zxid:0x500000004 txntype:5 reqpath:n/a > 2017-11-16 03:03:21,189 [myid:1] - DEBUG [CommitProcessor:1:FinalRequestP= rocessor@89] - Processing request:: sessionid:0x2000111082b0000 type:setDat= a cxid:0x4 zxid:0x500000004 txntype:5 reqpath:n/a > ... > Comment: > When the node 1 is restarted, it restores its in-memory data tree from th= e snapshot at zxid 0x200000001 and replay setData at zxid 0x300000001 (whic= h actually needed to be truncated) > However, the node 2 just sends DIFF containing setData written at 9th pat= h, and no truncation will be occurred. > As a result, the node 1 still has the value 1002 while other nodes will h= ave the value 2 for the same key -- This message was sent by Atlassian JIRA (v6.4.14#64029)