[
https://issues.apache.org/jira/browse/ZOOKEEPER-3591?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17001154#comment-17001154
]
Fangmin Lv commented on ZOOKEEPER-3591:
---------------------------------------
[~mirg] it doesn't seem to be related to reconfig, is this the same issue as
ZOOKEEPER-3642?
> Inconsistent resync with dynamic reconfig
> -----------------------------------------
>
> Key: ZOOKEEPER-3591
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-3591
> Project: ZooKeeper
> Issue Type: Bug
> Components: server
> Affects Versions: 3.5.5
> Reporter: Alex Mirgorodskiy
> Priority: Major
> Attachments: instance1.log.gz, instance6.log.gz
>
>
> We've run into a problem where one of the zookeeper instances lost most of
> its data after its zk process has been restarted. We suspect an interaction
> between dynamic reconfiguration and snapshot-based resync of that instance.
> Details and some amateurish analysis are below. We can also upload
> transaction logs, if need be.
> We have a 6-instance ensemble running version 3.5.5 with 3 quorum members and
> 3 observers. One of the observers (Instance 6) saw its db shrink from 3162
> znodes down to 10 after that instance restarted:
> > 2019-10-13T16:44:19.060+0000 [.zk-monitor-0] Monitor command mntr:
> > zk_version 3.5.5-afd10a8846b22a34c5a818034bb22e99dd44587b, built on
> > 09/16/2019 18:31 GMT
> > zk_znode_count 3162
> > --
> > 2019-10-13T16:48:32.713+0000 [.zk-monitor-0] Monitor command mntr:
> > zk_version 3.5.5-afd10a8846b22a34c5a818034bb22e99dd44587b, built on
> > 09/16/2019 18:31 GMT
> > zk_znode_count 10
> Contrast it with Instance 1 that was the leader at the time, and whose
> znode_count remained stable around 3000:
> > 2019-10-13T16:44:48.625+0000 [.zk-monitor-0] Monitor command mntr:
> > zk_version 3.5.5-afd10a8846b22a34c5a818034bb22e99dd44587b, built on
> > 09/16/2019 18:31 GMT
> > zk_znode_count 3178
> > --
> > ...
> > --
> > 2019-10-13T16:48:48.731+0000 [.zk-monitor-0] Monitor command mntr:
> > zk_version 3.5.5-afd10a8846b22a34c5a818034bb22e99dd44587b, built on
> > 09/16/2019 18:31 GMT
> > zk_znode_count 3223
> It appears that the problem had happened 30 minutes earlier, when Instance 6
> got resynced from the leader via the Snap method, yet skipped creating an
> on-disk snapshot. The end result was that the in-memory state was fine, but
> there was only the primordial snapshot.0 on disk, and transaction logs only
> started after the missing snapshot:
> $ ls -l version-2
> > total 1766
> > -rw-r--r-- 1 daautomation daautomation 1 Oct 13 09:14 acceptedEpoch
> > -rw-r--r-- 1 daautomation daautomation 1 Oct 13 10:12 currentEpoch
> > -rw-r--r-- 1 daautomation daautomation 2097168 Oct 13 09:44 log.6000002e0
> > -rw-r--r-- 1 daautomation daautomation 1048592 Oct 13 10:09 log.600001f1b
> > -rw-r--r-- 1 daautomation daautomation 4194320 Oct 13 12:16 log.600003310
> > -rw-r--r-- 1 daautomation daautomation 770 Oct 13 09:14 snapshot.0
> So the zk reboot wiped out most of the state.
> Dynamic reconfig might be relevant here. Instance 6 started as an observer,
> got removed, and immediately re-added as a participant. Instance 2 went the
> other way, from participant to observer:
> > 2019-10-13T16:14:19.323+0000 ZK reconfig: removing node 6
> > 2019-10-13T16:14:19.359+0000 ZK reconfig: adding
> > server.6=10.80.209.138:2888:3888:participant;0.0.0.0:2181
> > 2019-10-13T16:14:19.399+0000 ZK reconfig: adding
> > server.2=10.80.209.131:2888:3888:observer;0.0.0.0:2181
> Looking at the logs, Instance 6 started and received a resync snapshot from
> the leader right before the dynamic reconfig:
> > 2019-10-13T16:14:19.284+0000
> > [.QuorumPeer[myid=6](plain=/0.0.0.0:2181)(secure=disabled)] Getting a
> > snapshot from leader 0x6000002dd
> > ...
> > 2019-10-13T16:14:19.401+0000
> > [.QuorumPeer[myid=6](plain=/0.0.0.0:2181)(secure=disabled)] Got zxid
> > 0x6000002de expected 0x1
> Had it processed the NEWLEADER packet afterwards, it would've persisted the
> snapshot locally. But there's no NEWLEADER message in the Instance 6 log.
> Instead, there's a "changes proposed in reconfig" exception, likely a result
> of the instance getting dynamically removed and re-added as a participant:
> > 2019-10-13T16:14:19.467+0000
> > [.QuorumPeer[myid=6](plain=/0.0.0.0:2181)(secure=disabled)] Becoming a
> > non-voting participant
> > 2019-10-13T16:14:19.467+0000
> > [.QuorumPeer[myid=6](plain=/0.0.0.0:2181)(secure=disabled)] Exception when
> > observing the leaderjava.lang.Exception: changes proposed in reconfig\n\tat
> > org.apache.zookeeper.server.quorum.Learner.syncWithLeader(Learner.java:506)\n\tat
> >
> > org.apache.zookeeper.server.quorum.Observer.observeLeader(Observer.java:74)\n\tat
> > org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1258)
> Perhaps the NEWLEADER packet was still in the socket, but sitting behing
> INFORMANDACTIVATE, whose exception prevented us from processing NEWLEADER?
> Also, it may or may not be related, but this area got changed recently as
> part of https://issues.apache.org/jira/browse/ZOOKEEPER-3104.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
