From issues-return-835-archive-asf-public=cust-asf.ponee.io@zookeeper.apache.org Fri Aug 30 07:10:02 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 176DF18065E for ; Fri, 30 Aug 2019 09:10:02 +0200 (CEST) Received: (qmail 88921 invoked by uid 500); 30 Aug 2019 07:10:01 -0000 Mailing-List: contact issues-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 issues@zookeeper.apache.org Received: (qmail 88912 invoked by uid 99); 30 Aug 2019 07:10:01 -0000 Received: from mailrelay1-us-west.apache.org (HELO mailrelay1-us-west.apache.org) (209.188.14.139) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 30 Aug 2019 07:10:01 +0000 Received: from jira-he-de.apache.org (static.172.67.40.188.clients.your-server.de [188.40.67.172]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 9DF4BE00A9 for ; Fri, 30 Aug 2019 07:10:00 +0000 (UTC) Received: from jira-he-de.apache.org (localhost.localdomain [127.0.0.1]) by jira-he-de.apache.org (ASF Mail Server at jira-he-de.apache.org) with ESMTP id 06319780259 for ; Fri, 30 Aug 2019 07:10:00 +0000 (UTC) Date: Fri, 30 Aug 2019 07:10:00 +0000 (UTC) From: "wanglei (Jira)" To: issues@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: =?utf-8?Q?[jira]_[Updated]_(ZOOKEEPER-3526)_When_a_zk_Node_just_?= =?utf-8?Q?become_the_leader,synchronizing_with_Follower_in_the_f?= =?utf-8?Q?irst_time,_the_value_of_maxCommittedLog_may_be_smaller?= =?utf-8?Q?_than_the_value_of__minComm?= =?utf-8?Q?ittedLog=EF=BC=8Cis_that_a_problem=3F?= MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/ZOOKEEPER-3526?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:all-tabpanel ] wanglei updated ZOOKEEPER-3526: ------------------------------- Description:=20 1.Node1:1566815238 (myid)=E3=80=81Node2:1566815239 (myid)=E3=80=81Node3:156= 6815240 (myid) 2.After a election, Node3 become the new leader, begin to sync with followe= rs =C2=A0 *2019-08-27 04:26:09,521 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:ZooKeeperServer@910][] - Refusing session request for not-r= ead-only client /172.28.0.3:38994* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:ZooKeeperServer@502][] - shutting down* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:SessionTrackerImpl@226][] - Shutting down* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:PrepRequestProcessor@769][] - Shutting down* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [ReadOnlyRequestProcesso= r:1566815240:ReadOnlyRequestProcessor@111][] - ReadOnlyRequestProcessor exi= ted loop!* *2019-08-27 04:26:09,610 [myid:1566815240] - INFO [ProcessThread(sid:15668= 15240 cport:-1)::PrepRequestProcessor@144][] - PrepRequestProcessor exited = loop!* *2019-08-27 04:26:09,610 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:FinalRequestProcessor@430][] - shutdown of request= processor complete* *2019-08-27 04:26:09,613 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:QuorumPeer@992][] - LEADING* *2019-08-27 04:26:09,615 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:Leader@64][] - TCP NoDelay set to: true* *2019-08-27 04:26:09,616 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:ZooKeeperServer@174][] - Created server with tickT= ime 2000 minSessionTimeout 4000 maxSessionTimeout 300000 datadir /opt/fusio= nplatform/data/zookeeper/data/version-2 snapdir /opt/fusionplatform/data/zo= okeeper/data/version-2* *2019-08-27 04:26:09,616 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:Leader@380][] - {color:#FF0000}LEADING - LEADER EL= ECTION TOOK - 15297{color}* *2019-08-27 04:26:09,956 [myid:1566815240] - INFO [NIOServerCxn.Factory:/1= 72.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection f= rom /172.28.0.3:39012* *2019-08-27 04:26:09,956 [myid:1566815240] - WARN [NIOServerCxn.Factory:/1= 72.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:/1= 72.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection f= rom /172.28.0.2:50732* *2019-08-27 04:26:09,974 [myid:1566815240] - WARN [NIOServerCxn.Factory:/1= 72.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:/1= 72.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection f= rom /172.28.0.5:60010* *2019-08-27 04:26:10,514 [myid:1566815240] - WARN [NIOServerCxn.Factory:/1= 72.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:/1= 72.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection f= rom /172.28.0.5:60020* *2019-08-27 04:26:10,517 [myid:1566815240] - WARN [NIOServerCxn.Factory:/1= 72.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:/1= 72.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection f= rom /172.28.0.5:60024* *2019-08-27 04:26:10,531 [myid:1566815240] - WARN [NIOServerCxn.Factory:/1= 72.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.apa= che.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 Followe= r sid: 1566815238 maxCommittedLog=3D0x3 minCommittedLog=3D0x9000002d9 peerL= astZxid=3D0x9000004ca{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=3D0= x9000004ca* *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:SessionT= rackerImpl@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 15668= 15238* *2019-08-27 04:26:10,833 [myid:1566815240] - INFO [QuorumPeer[myid=3D15668= 15240]/172.28.8.123:9880:Leader@964][] - Have quorum of supporters, sids: [= 1566815238,1566815240 ]; starting up and setting last processed zxid: 0xa0= 0000000* *2019-08-27 04:26:11,160 [myid:1566815240] - INFO [SyncThread:1566815240:F= ileTxnLog@216][] - Creating new log file: log.a00000001* {color:#FF0000}maxCommittedLog=3D0x3 minCommittedLog=3D0x9000002d9 peerLast= Zxid=3D0x9000004ca{color} {color:#ff0000}*why=C2=A0maxCommittedLog <=C2=A0minCommittedLog?*{color} 2.Node 2(follower) get a Trunc message form leader.The leader zxid of the T= runc message is 0x3. So Node3 truncat the=C2=A0 transaction log(the zxid wh= ich is bigger than 0x3 will be deleted). At last, the data in Node2 is inco= nsistent. =C2=A0 *2019-08-27 04:26:14,225 [myid:1566815239] - INFO [WorkerReceiver[myid=3D15= 66815239]:FastLeaderElection@595][] - Notification: 1 (message format versi= on), 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=3D1= 566815239]:FastLeaderElection@595][] - Notification: 1 (message format vers= ion), 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=3D15668= 15239]/172.28.8.122:9880:QuorumPeer@980][] - FOLLOWING* *2019-08-27 04:26:14,226 [myid:1566815239] - INFO [Thread-1:QuorumPeer$1@9= 36][] - Interrupted while attempting to start ReadOnlyZooKeeperServer, not = started* *2019-08-27 04:26:14,229 [myid:1566815239] - INFO [QuorumPeer[myid=3D15668= 15239]/172.28.8.122:9880:Learner@86][] - TCP NoDelay set to: true* *2019-08-27 04:26:14,229 [myid:1566815239] - INFO [QuorumPeer[myid=3D15668= 15239]/172.28.8.122:9880:ZooKeeperServer@174][] - Created server with tickT= ime 2000 minSessionTimeout 4000 maxSessionTimeout 300000 datadir /opt/fusio= nplatform/data/zookeeper/data/version-2 snapdir /opt/fusionplatform/data/zo= okeeper/data/version-2* *2019-08-27 04:26:14,230 [myid:1566815239] - INFO [QuorumPeer[myid=3D15668= 15239]/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=3D15668= 15239]/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=3D15668= 15239]/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=3D15668= 15239]/172.28.8.122:9880:DataTree@715][] - type: create, sessionid:0x100000= 80a040001 cxid:0x4 zxid:0x3 reqpath:/cps* *2019-08-27 04:26:14,374 [myid:1566815239] - WARN [QuorumPeer[myid=3D15668= 15239]/172.28.8.122:9880:Learner@387][] - Got zxid 0xa00000001 expected 0x1= * =C2=A0 was: 1.Node1:1566815238 (myid)=E3=80=81Node2:1566815239 (myid)=E3=80=81Node3:156= 6815240 (myid) 2.After a election, Node3 become the new leader, begin to sync with followe= rs =C2=A0 *2019-08-27 04:26:09,521 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:ZooKeeperServer@910][] - Refusing session request for not-r= ead-only client /172.28.0.3:38994* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:ZooKeeperServer@502][] - shutting down* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:SessionTrackerImpl@226][] - Shutting down* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:PrepRequestProcessor@769][] - Shutting down* *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [ReadOnlyRequestProcessor= :1566815240:ReadOnlyRequestProcessor@111][] - ReadOnlyRequestProcessor exit= ed loop!* *2019-08-27 04:26:09,610 [myid:1566815240] - INFO [ProcessThread(sid:156681= 5240 cport:-1)::PrepRequestProcessor@144][] - PrepRequestProcessor exited l= oop!* *2019-08-27 04:26:09,610 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:FinalRequestProcessor@430][] - shutdown of request = processor complete* *2019-08-27 04:26:09,613 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:QuorumPeer@992][] - LEADING* *2019-08-27 04:26:09,615 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:Leader@64][] - TCP NoDelay set to: true* *2019-08-27 04:26:09,616 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:ZooKeeperServer@174][] - Created server with tickTi= me 2000 minSessionTimeout 4000 maxSessionTimeout 300000 datadir /opt/fusion= platform/data/zookeeper/data/version-2 snapdir /opt/fusionplatform/data/zoo= keeper/data/version-2* *2019-08-27 04:26:09,616 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:Leader@380][] - LEADING - LEADER ELECTION TOOK - 15= 297* *2019-08-27 04:26:09,956 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection fr= om /172.28.0.3:39012* *2019-08-27 04:26:09,956 [myid:1566815240] - WARN [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxn@383][] - Exception causing close of session 0= x0: ZooKeeperServer not running* *2019-08-27 04:26:09,974 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection fr= om /172.28.0.2:50732* *2019-08-27 04:26:09,974 [myid:1566815240] - WARN [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxn@383][] - Exception causing close of session 0= x0: ZooKeeperServer not running* *2019-08-27 04:26:10,513 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection fr= om /172.28.0.5:60010* *2019-08-27 04:26:10,514 [myid:1566815240] - WARN [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxn@383][] - Exception causing close of session 0= x0: ZooKeeperServer not running* *2019-08-27 04:26:10,516 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection fr= om /172.28.0.5:60020* *2019-08-27 04:26:10,517 [myid:1566815240] - WARN [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxn@383][] - Exception causing close of session 0= x0: ZooKeeperServer not running* *2019-08-27 04:26:10,530 [myid:1566815240] - INFO [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxnFactory@222][] - Accepted socket connection fr= om /172.28.0.5:60024* *2019-08-27 04:26:10,531 [myid:1566815240] - WARN [NIOServerCxn.Factory:/17= 2.28.8.123:9880:NIOServerCnxn@383][] - Exception causing close of session 0= x0: 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.apac= he.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: 156681523= 8 maxCommittedLog=3D0x3 minCommittedLog=3D0x9000002d9 peerLastZxid=3D0x9000= 004ca* *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=3D0x= 9000004ca* *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:SessionTr= ackerImpl@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 156681= 5238* *2019-08-27 04:26:10,833 [myid:1566815240] - INFO [QuorumPeer[myid=3D156681= 5240]/172.28.8.123:9880:Leader@964][] - Have quorum of supporters, sids: [ = 1566815238,1566815240 ]; starting up and setting last processed zxid: 0xa00= 000000* *2019-08-27 04:26:11,160 [myid:1566815240] - INFO [SyncThread:1566815240:Fi= leTxnLog@216][] - Creating new log file: log.a00000001* maxCommittedLog=3D0x3 minCommittedLog=3D0x9000002d9 peerLastZxid=3D0x900000= 4ca {color:#FF0000}*why=C2=A0maxCommittedLog <=C2=A0minCommittedLog?*{color} 2.Node 2(follower) get a Trunc message form leader.The leader zxid of the T= runc message is 0x3. So Node3 truncat the=C2=A0 transaction log(the zxid wh= ich is bigger than 0x3 will be deleted). At last, the data in Node2 is inco= nsistent. =C2=A0 *2019-08-27 04:26:14,225 [myid:1566815239] - INFO [WorkerReceiver[myid=3D15= 66815239]:FastLeaderElection@595][] - Notification: 1 (message format versi= on), 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=3D15= 66815239]:FastLeaderElection@595][] - Notification: 1 (message format versi= on), 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=3D156681= 5239]/172.28.8.122:9880:QuorumPeer@980][] - FOLLOWING* *2019-08-27 04:26:14,226 [myid:1566815239] - INFO [Thread-1:QuorumPeer$1@93= 6][] - Interrupted while attempting to start ReadOnlyZooKeeperServer, not s= tarted* *2019-08-27 04:26:14,229 [myid:1566815239] - INFO [QuorumPeer[myid=3D156681= 5239]/172.28.8.122:9880:Learner@86][] - TCP NoDelay set to: true* *2019-08-27 04:26:14,229 [myid:1566815239] - INFO [QuorumPeer[myid=3D156681= 5239]/172.28.8.122:9880:ZooKeeperServer@174][] - Created server with tickTi= me 2000 minSessionTimeout 4000 maxSessionTimeout 300000 datadir /opt/fusion= platform/data/zookeeper/data/version-2 snapdir /opt/fusionplatform/data/zoo= keeper/data/version-2* *2019-08-27 04:26:14,230 [myid:1566815239] - INFO [QuorumPeer[myid=3D156681= 5239]/172.28.8.122:9880:Follower@65][] - FOLLOWING - LEADER ELECTION TOOK -= 36* *2019-08-27 04:26:14,232 [myid:1566815239] - INFO [QuorumPeer[myid=3D156681= 5239]/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=3D156681= 5239]/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=3D156681= 5239]/172.28.8.122:9880:DataTree@715][] - type: create, sessionid:0x1000008= 0a040001 cxid:0x4 zxid:0x3 reqpath:/cps* *2019-08-27 04:26:14,374 [myid:1566815239] - WARN [QuorumPeer[myid=3D156681= 5239]/172.28.8.122:9880:Learner@387][] - Got zxid 0xa00000001 expected 0x1* =C2=A0 > 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=EF=BC=8Cis 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)=E3=80=81Node2:1566815239 (myid)=E3=80=81Node3:1= 566815240 (myid) > 2.After a election, Node3 become the new leader, begin to sync with follo= wers > =C2=A0 > *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=3D156= 6815240]/172.28.8.123:9880:ZooKeeperServer@502][] - shutting down* > *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:SessionTrackerImpl@226][] - Shutting down* > *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:PrepRequestProcessor@769][] - Shutting down* > *2019-08-27 04:26:09,609 [myid:1566815240] - INFO [ReadOnlyRequestProces= sor:1566815240:ReadOnlyRequestProcessor@111][] - ReadOnlyRequestProcessor e= xited loop!* > *2019-08-27 04:26:09,610 [myid:1566815240] - INFO [ProcessThread(sid:156= 6815240 cport:-1)::PrepRequestProcessor@144][] - PrepRequestProcessor exite= d loop!* > *2019-08-27 04:26:09,610 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:FinalRequestProcessor@430][] - shutdown of reque= st processor complete* > *2019-08-27 04:26:09,613 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:QuorumPeer@992][] - LEADING* > *2019-08-27 04:26:09,615 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:Leader@64][] - TCP NoDelay set to: true* > *2019-08-27 04:26:09,616 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:ZooKeeperServer@174][] - Created server with tic= kTime 2000 minSessionTimeout 4000 maxSessionTimeout 300000 datadir /opt/fus= ionplatform/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=3D156= 6815240]/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 sessio= n 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 sessio= n 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 sessio= n 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 sessio= n 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 sessio= n 0x0: ZooKeeperServer not running* > *2019-08-27 04:26:10,619 [myid:1566815240] - INFO [LearnerHandler-/172.2= 8.0.2:59666:LearnerHandler@346][] - Follower sid: 1566815238 : info : org.a= pache.zookeeper.server.quorum.QuorumPeer$QuorumServer@6f38a687* > *2019-08-27 04:26:10,747 [myid:1566815240] - INFO [LearnerHandler-/172.2= 8.0.2:59666:LearnerHandler@401][] -{color:#FF0000} Synchronizing with Follo= wer sid: 1566815238 maxCommittedLog=3D0x3 minCommittedLog=3D0x9000002d9 pee= rLastZxid=3D0x9000004ca{color}* > *2019-08-27 04:26:10,747 [myid:1566815240] - INFO [LearnerHandler-/172.2= 8.0.2:59666:LearnerHandler@410][] - leader and follower are in sync, zxid= =3D0x9000004ca* > *2019-08-27 04:26:10,748 [myid:1566815240] - INFO [LearnerHandler-/172.2= 8.0.2:59666:LearnerHandler@475][] - Sending DIFF* > *2019-08-27 04:26:10,811 [myid:1566815240] - INFO [SessionTracker:Sessio= nTrackerImpl@163][] - SessionTrackerImpl exited loop!* > *2019-08-27 04:26:10,833 [myid:1566815240] - INFO [LearnerHandler-/172.2= 8.0.2:59666:LearnerHandler@535][] - Received NEWLEADER-ACK message from 156= 6815238* > *2019-08-27 04:26:10,833 [myid:1566815240] - INFO [QuorumPeer[myid=3D156= 6815240]/172.28.8.123:9880:Leader@964][] - Have quorum of supporters, sids:= [ 1566815238,1566815240 ]; starting up and setting last processed zxid: 0x= a00000000* > *2019-08-27 04:26:11,160 [myid:1566815240] - INFO [SyncThread:1566815240= :FileTxnLog@216][] - Creating new log file: log.a00000001* > {color:#FF0000}maxCommittedLog=3D0x3 minCommittedLog=3D0x9000002d9 peerLa= stZxid=3D0x9000004ca{color} > {color:#ff0000}*why=C2=A0maxCommittedLog <=C2=A0minCommittedLog?*{color} > 2.Node 2(follower) get a Trunc message form leader.The leader zxid of the= Trunc message is 0x3. So Node3 truncat the=C2=A0 transaction log(the zxid = which is bigger than 0x3 will be deleted). At last, the data in Node2 is in= consistent. > =C2=A0 > *2019-08-27 04:26:14,225 [myid:1566815239] - INFO [WorkerReceiver[myid=3D= 1566815239]:FastLeaderElection@595][] - Notification: 1 (message format ver= sion), 1566815240 (n.leader), 0x9000004ca (n.zxid), 0x1 (n.round), FOLLOWIN= G (n.state), 1566815238 (n.sid), 0xa (n.peerEpoch) LOOKING (my state)* > *2019-08-27 04:26:14,226 [myid:1566815239] - INFO [WorkerReceiver[myid= =3D1566815239]:FastLeaderElection@595][] - Notification: 1 (message format = version), 1566815240 (n.leader), 0x9000004ca (n.zxid), 0x1 (n.round), FOLLO= WING (n.state), 1566815238 (n.sid), 0xa (n.peerEpoch) FOLLOWING (my state)* > *2019-08-27 04:26:14,226 [myid:1566815239] - INFO [QuorumPeer[myid=3D156= 6815239]/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, no= t started* > *2019-08-27 04:26:14,229 [myid:1566815239] - INFO [QuorumPeer[myid=3D156= 6815239]/172.28.8.122:9880:Learner@86][] - TCP NoDelay set to: true* > *2019-08-27 04:26:14,229 [myid:1566815239] - INFO [QuorumPeer[myid=3D156= 6815239]/172.28.8.122:9880:ZooKeeperServer@174][] - Created server with tic= kTime 2000 minSessionTimeout 4000 maxSessionTimeout 300000 datadir /opt/fus= ionplatform/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=3D156= 6815239]/172.28.8.122:9880:Follower@65][] - {color:#FF0000}FOLLOWING - LEAD= ER ELECTION TOOK - 36{color}* > *2019-08-27 04:26:14,232 [myid:1566815239] - INFO [QuorumPeer[myid=3D156= 6815239]/172.28.8.122:9880:QuorumPeer$QuorumServer@185][] - Resolved hostna= me: 172.28.8.123 to address: /172.28.8.123* > *2019-08-27 04:26:14,346 [myid:1566815239] - WARN [QuorumPeer[myid=3D156= 6815239]/172.28.8.122:9880:Learner@349][] - {color:#FF0000}Truncating log t= o get in sync with the leader 0x3{color}* > *2019-08-27 04:26:14,371 [myid:1566815239] - INFO [QuorumPeer[myid=3D156= 6815239]/172.28.8.122:9880:DataTree@715][] - type: create, sessionid:0x1000= 0080a040001 cxid:0x4 zxid:0x3 reqpath:/cps* > *2019-08-27 04:26:14,374 [myid:1566815239] - WARN [QuorumPeer[myid=3D156= 6815239]/172.28.8.122:9880:Learner@387][] - Got zxid 0xa00000001 expected 0= x1* > =C2=A0 -- This message was sent by Atlassian Jira (v8.3.2#803003)