修复 ZooKeeper 数据视图不一致

smartx

已认证帐号

ZooKeeper 简介

ZooKeeper 是一个开源的分布式系统协调中间件，可以基于它实现选主、pub/sub 模式、分布式锁等功能。ZooKeeper 实现的共识算法名叫 Zab：ZooKeeper Atomic broadcast，即 ZooKeeper 原子广播协议。

Zookeeper 使用 ZKDatabase 保存数据，ZKDatabase 使用的数据结构是 DataTree。DataTree 维护一个路径到 DataNode 的哈希表。ZooKeeper Snapshot 就是 DataTree 进行序列化后保存在磁盘中的一系列文件。与此对应地，Zookeeper 启动时会使用磁盘上的 Snapshot 在内存中重建 DataTree。

每当客户端连接到 ZooKeeper Server 进行读，Server 会返回其本地的数据副本（这点与 Raft 不同，Raft 中对 non-leader 节点的读取会被转发到 leader 节点进行处理）。在 ZooKeeper 中，每个事务都会被分配一个 zxid。zxid 是全局唯一的 64 位整数，由 32 位的 Epoch 和一个 32 位的自增 ID （Counter）组成。每次提交一个新的事务，Counter += 1。每次有新成员（QuorumPeer）当选 Leader，Epoch += 1。当 zxid 溢出时会触发选举，之后 zxid 会被重置为 0。

ZooKeeper 暴露一个类似于文件系统的 API，对 Znode 进行组织和操作。Znode 以树状组织，支持 create、delete、getData 和 setData 等操作。

根据官方文档，ZooKeeper 提供的一致性保证属于 ordered sequential consistency ，一致性保证介于顺序一致性（sequential consistency）和线性一致性（linearizability）之间。对于写操作，ZooKeeper 保证线性一致性；对于读操作，仅保证顺序一致性。这意味着，当 Client A 对 Znode Z 进行更新，Client B 对 Z 进行读取，此时并不能保证 Client B 能立刻读到最新的值。但一旦 Client B 读到最新值后，就不应该再读到任何过期的数据了。

致命的 ZOOKEEPER-3911

在我司内部的测试流程中，有时会发现一种奇怪的现象：服务已经在 ZooKeeper 节点 A 上通过 setData 更新了数据，一段时间后再读取，却读取到了过期的，setData 之前的数据，破坏了顺序一致性。由于我司使用的 ZooKeeper 版本较老（3.4.13），因此我们将目标聚焦在了一些在新版本 ZooKeeper 中已经修复的 issue。经过一段时间的摸排，我们找到了一个现象相似的 issue： ZOOKEEPER-3911 。在当时，这个 issue 已经被修复，并入了 ZooKeeper 3.6 及其以上版本。

要理解 ZOOKEEPER-3911，我们首先回顾一下 ZooKeeper 的工作过程（本文以 ZooKeeper 3.6.3 为例）。

Zab 协议包括三个阶段：选举（Election）、恢复（Recovery）和广播（Broadcast）。每个成员都会在这三个阶段中反复切换，并进行相应动作。早期 Zab 刚提出时，实际是四个阶段：Election、Discovery、Sync、Broadcast。后来简化为三个阶段，即 Election、Recovery、Broadcast，其中 Recovery=Discovery+Sync

每个成员启动时，都会进入 Election 状态进行选主。选主时实际运行的是 FLE（Fast Leader Election），是 FastPaxos 在 ZooKeeper 中的实现，会选出 lastZxid 最大的节点作为 Leader。

选出 Leader 后，进入到 Recovery 阶段。Recovery 阶段主要是由 Follower 进行操作。首先，Follower 需要通过之前选举时的选票获取到当前 Leader 是哪一个节点。通常这个发现 Leader 的过程也叫作 Discovery。

Follower 开始服务之前需要进行与 Leader 间的数据同步（Sync）。同步的目的是将已经提交的事务但未在 Follower 上提交的事务，同步到 Follower，使得 Follower 持有与 Leader 一致的数据副本。同步完成后，Follower 应当拥有最新版本的数据。Sync 过程开始时，Leader 发送 NEWLEADER 消息给其他实例，以获取其他节点的 lastZxid。Leader 根据 lastZxid 决定如何同步数据。

每个 ZooKeeper 的 ZKDatabase 中维护着一个 committedLog 队列。CommittedLog 是一个 Proposal 队列，存储着已经提交的 Proposal。其中，队列头部的 Proposal Zxid 即为 minCommittedLog，队尾的 Proposal Zxid 即为 maxCommittedLog。当 Request 经过 FinalRequestProcessor 并处理完成后，会进行 Proposal Commit，此时，minCommittedLog 和 maxCommittedLog 这两个字段会被更新。

Leader 会从 ZKDatabase 中读取上一次处理的 Zxid（lastProcessedZxid）、minCommittedLog 和 maxCommittedLog 三个值，随后与 Follower 提供的 peerLastZxid 进行比较，确定使用何种策略进行数据同步。PeerLastZxid 由 Follower 提供。当 Leader 发送 LEADERINFO 消息给 Follower 时，Follower 会从自己的 ZKDatabase 读取上一次处理的 Zxid（也就是 lastProcessedZxid）发给 Leader。

此时，Leader 已经获取到足够的信息（lastProcessedZxid、minCommittedLog 和 maxCommittedLog）。根据这些信息，会尝试使用不同的同步策略。通常，Follower 的已提交事务，会落后于 Leader，这时便会执行 DIFF Sync。如果 Follower 上存在 Zxid 比 Leader 大的事务，会进行 TRUNC Sync。

进行 DIFF Sync 时，Leader 会向 Follower 发送一连串的 PROPOSAL 和 COMMIT 消息。具体发送的 Proposal 根据 Follower 最后记录的 zxid 有关。通常，Leader 会发送 Follower 并未持有的 Proposal，并 Commit。

进行 TRUNC Sync 时，Leader 向 Follower 发送 TRUNC 消息，消息中包含 Leader 的 maxCommittedLog。Follower 收到 TRUNC 消息后，通过消息中的 zxid 对自己的 ZKDatabase 进行 trunc，删除比 zxid 更大的事务。Trunc 的实现是：先清理内存中的 DataTree 等状态，然后对存储在磁盘中的 DataTree 快照进行 truncate，即截断。之后进入正常的 DIFF Sync 流程。

如果 Follower 上的已提交事务已经落后 Leader 太多，则会触发 SNAP sync。此时 Leader 会将自己的 DataTree 构建出一个 snapshot，并发送给 Follower。Follower 收到快照，清空自己本地的 zkdb，然后使用收到的快照重新构建自己内存中的 zkdb。

Sync 结束后，Leader 会向 Follower 发送 NEWLEADER，等待多数 Follower ACK NEWLEADER 消息后，再发送 UPTODATE 消息，通知 Follower 已经同步完成。收到 UPTODATE 并 ACK 后，Follower 会开始对外提供服务。在 ZOOKEEPER-2678 前，Follower 会在收到 NEWLEADER 后，ACK NEWLEADER 之前，对自己的 DateTree 进行快照，即序列化 DataTree 并写入磁盘，然后再对 QuorumPacket 这个阶段中收到的 QuorumPacket 进行持久化。

在 ZOOKEEPER-2678 中，引入了一个优化。优化前 Leader 如果宕机，进行重新选举前，每个节点会进行 shutdown 操作，导致 ZKDatabase 的整体 Reload。如果 ZKDatabase 非常大，会导致从故障中恢复的时间非常长。优化后，在重新选举前不会 clear db，并且移除了 ACK NEWLEADER 之前的快照动作，到 UPTODATE 后才会持久化最近来自 Leader 的 Proposal（原流程）——换而言之，DIFF sync 时，不再需要收到在 NEWLEADER 消息时进行持久化快照操作。Leader 在得到来自多数 Follower 的 NEWLEADER ACK 后，为 Client 请求提供服务。Follower 会在收到 UPTODATE 前发送 NEWLEADER ACKs。因此，当 Leader 开始服务时，Follower 可能没有持久化所有来自 Leader 的 DIFF sync proposal。

如收到来自 Leader 的 UPTODATE 消息之后所有的 ZooKeeper 实例都崩溃了，并且旧 Leader 没有回来，其他 Follower 产生了一轮新 Quorum（选出了一个新的 Leader，开启新的 Epoch），此时这些在旧 Leader 认为已经正确提交的 Proposal 就会丢失，导致客户端得到的数据视图在新 Quorum 形成前后不一致。这就是 ZOOKEEPER-3911 提到的问题。

下面我们用一个例子来解释该 Bug 的过程。

假设我们有一个正常运行的 5 节点 ZooKeeper 集群。所有节点的状态都是一致的，所有的节点中最新的 zxid 都是 2。Node1 表示一个 myid=1 的 ZooKeeper QuorumPeer。

介质\最新 Zxid	Node1(Leader)	Node2	Node3	Node4	Node5
内存	2	2	2	2	2
磁盘	2	2	2	2	2

表 1：初始状态

此时，Node1 Leader 发起新的 Proposal {zxid=3}，并且发给其他 Follower。但是，由于一些网络上的问题，Follower 并没有收到 Proposal。

介质\最新 Zxid	Node1(Leader)	Node2	Node3	Node4	Node5
内存	2	2	2	2	2
磁盘	3	2	2	2	2

表 2：Node1 发起 Proposal 前

Node1 将 Proposal {zxid=3} 持久化，然后重启（或者被重启）。

介质\最新 Zxid	Node1(Leader)	Node2	Node3	Node4	Node5
内存	3	2	2	2	2
磁盘	3	2	2	2	2

表 3：Node1 重启

此时 Node1 会把 zxid=3 读入内存。由于 Node1 重启，Follower 节点与 Leader 断开连接，Follower 节点会切换到 LOOKING 状态，Leader 重新启动，初始状态也是 LOOKING。于是进行重新选举。由于 Node1 持有最大的 zxid=3，因此 Node1 会成为新的 Leader。Follower 需要与 Leader 进行同步。首先，Follower 发送 FOLLOWERINFO 信息给 Leader，Leader 发送 LEADERINFO 信息给 Follower。此时需要进行 DIFF Sync。

不妨假设，此时 Node2 和 Node3 已经 ACK Leader，而 Node4 和 Node5 并没有 ACK Leader，状态如下表。Leader 向 Node2 和 Node3 发送 UPTODATE 消息。在 ZooKeeper 3.4 中，Follower 收到 UPTODATE 不会将 Proposal 持久化。

介质\最新 Zxid	Node1(Leader)	Node2	Node3	Node4	Node5
内存	3	3	3	2	2
磁盘	3	2	2	2	2

表 4：提交 proposal {zxid=3}

此时，Leader 认为 Proposal {zxid=3} 形成了 Quorum。人为关闭 Node1 并重新启动 Node2 和 Node3。

介质\最新 Zxid	Node1(离线)	Node2	Node3	Node4	Node5
内存		2	2	2	2
磁盘	3	2	2	2	2

表 5：关闭 Node1，重启 Node2 和 Node3 后

此时会进行重新选举，不妨假设 Node2 成为 Leader。Node3、Node4 和 Node5 向 Node2 进行 Sync，得到最新的 zxid=2。

如此，Proposal {zxid=3} 就被丢弃了。

修复方式

如上所述，我们已经知道了 ZOOKEEPER-3911 的成因：Leader 在得到来自多数 Follower 的 NEWLEADER ACK 后会为 Client 请求提供服务，但 Leader 可能会永久下线，并最终导致 Client 认为自己已经提交的请求在 Sync 过程中被丢弃。

为了修复这个问题，当 Leader 收到来自大多数 Follower 的 NEWLEADER ACK 时，需要得到一个保证：所有的 DIFF Sync Proposal 都已经持久化，并且在 Recovery 之后，这些 Proposal 仍然存在（因为已经持久化）。于是修复方式也显然了：Follower 在 NEWLEADER ACK 之前，需要持久化所有的未提交的 DIFF Sync Proposal。

readPacket(qp); // 接收来自 Leader 的 QuorumPacket，下文简称 QP
switch (qp.getType()) {
// ...
case Leader.NEWLEADER: // 收到 NEWLEADER 消息
    // ...
    // writeToTxnLog 为 true 时，处理 QP 写入 transaction log，否则写入内存中的队列
    writeToTxnLog = true;
    isPreZAB1_0 = false;
    sock.setSoTimeout(self.tickTime * self.syncLimit);
    self.setSyncMode(QuorumPeer.SyncMode.NONE);
    zk.startupWithoutServing();
    if (zk instanceof FollowerZooKeeperServer) {
        FollowerZooKeeperServer fzk = (FollowerZooKeeperServer) zk;
        for (PacketInFlight p : packetsNotCommitted) { // 将未提交的 QP 写入 Log
            fzk.logRequest(p.hdr, p.rec, p.digest);
        packetsNotCommitted.clear();
    // 向 Leader 返回 NEWLEADER ACK
    writePacket(new QuorumPacket(Leader.ACK, newLeaderZxid, null, null), true);
    break;
// ...
}

完整代码参见： ZOOKEEPER-3911: Data inconsistency caused by DIFF sync uncommitted log by hanm

艰难的 Backport 经历

了解了这个 Bug 的成因，那么我们要着手修复了。目前我司使用的 ZooKeeper 版本是 3.4.13，最近的包含该修复的 ZooKeeper 版本是 3.6.2。而 ZooKeeper 本身并不保证跨版本升级的兼容性（3.4 → 3.6 跨过了一个 3.5 版本）。因此需要将这个关键的 Patch backport 到 v3.5.9，再从 3.4.13 升级到 3.5.9。

观察 git history 可以发现，在 3.6.2 以及更新的 ZooKeeper 版本中，已经并入了该 Patch。而 3.5 分支上，ZOOKEEPER-3911 被 Revert，也就是并没有并入 3.5 分支中。

Backport 非常简单，git cherry-pick 再修改少许即可。然而，运行该 Patch 附带的单元测试，却未能通过：

42696 [main] INFO org.apache.zookeeper.ZKTestCase  - FAILED testInconsistentDueToUncommittedLog
java.lang.AssertionError: server 2 should have /zk
  // ...
    at org.apache.zookeeper.server.quorum.DIFFSyncConsistencyTest.testInconsistentDueToUncommittedLog(DIFFSyncConsistencyTest.java:168)
  // ...

观察单测代码，此时预期要读到 /zk2（leader=2）这个 znode，但这个 znode 不存在。

int c = 0;
while (c < 100) {
    ++c;
    try {
        Stat stat = zk.exists("/zk" + leader, false);
        assertNotNull("server " + leader + " should have /zk", stat);
        break;
    } catch (KeeperException.ConnectionLossException e) {}
    Thread.sleep(100);
}

反复在 3.5.9 上运行多次该单测，均能复现同样的问题。这是怎么回事呢？

单测运行中，可以看到处于 CLOSE_WAIT 状态的 socket。

Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp6     191      0 127.0.0.1:56570         127.0.0.1:11229         CLOSE_WAIT  22059/java
[myid:1] - INFO  [LeaderConnector-/127.0.0.1:11229:Learner$LeaderConnector@370] - Successfully connected to leader, using address: /127.0.0.1:11229
[myid:0] - INFO  [LeaderConnector-/127.0.0.1:11229:Learner$LeaderConnector@370] - Successfully connected to leader, using address: /127.0.0.1:11229

看到日志可以确认，127.0.0.1:11229 是 Leader 监听的。因此，上面这个 Socket 是来自于 Follower。还可以看到 Recv-Q 特别高，说明 Follower 没有处理来自 Leader 的消息。经验丰富的读者大佬们，此时已经知道了问题的成因：Follower 没有关闭与 Leader 的 socket 连接。

但这还不够，对于单测的错误，还是要刨根问底。要知道真相，首先我们得了解这个单测的流程：

启动 myid={0, 1, 2} 的三个 MockTestQPMain
等待选主。由于三个 QuorumPeer 都是新节点，此时 Epoch 相等，Zxid 相等，选主必定选出最大的 myid=2。
关闭所有的 Follower，myid={0, 1}
客户端连接到集群，尝试创建 Znode /zk2 ，创建必定失败（因为无法形成 Quorum）
确认 Proposal 已经写入磁盘
启动所有的 Follower，并注入一个网络错误，使得 Follower 无法收到来自 Leader 发送的 UPTODATE 消息（但是 Follower 可以正常收 NEWLEADER 消息）
此时，Leader 应当能看到 /zk2 。如果能看到 /zk2 ，说明 Leader 已经收到足够多的 NEWLEADER ACK，已经开始正常服务，并且 DIFF Sync 已经完成。
关闭所有的服务器 myid={0, 1, 2}
重启 myid={0, 1} 的 QuorumPeer。此时不注入网络错误。
等待选主。此时 Leader 一定不是 myid=2 的 QuorumPeer
关闭此前创建的客户端，重新连接。此时应当能读取到之前创建的 /zk2

单测失败的位置，位于步骤 7：Leader 看不到 /zk2 。这说明可能有这些可能性：

Leader 并没有收到来自 Follower 的足够多的 NEWLEADER ACK。可能是：Follower 没有收到 NEWLEADER 消息，或是没有发送 NEWLEADER ACK
Leader 已经不是 QuorumPeer {myid=2}

我们挨个进行排查。首先排查 NEWLEADER ACK 是否已经发送。从日志可以看到，NEWLEADER ACK 可以正常收发，并且数量足够。

为了简化描述，笔者对 ZooKeeper 代码进行了一些次要的修改：调整了部分日志的级别，增加了 NEWLEADER-ACK 的来源 myid

# grep 'NEWLEADER' .\zookeeper.log
[myid:2] - INFO  [LearnerHandler-/127.0.0.1:57162:LearnerHandler@589] - Sending NEWLEADER message to 0
[myid:2] - INFO  [LearnerHandler-/127.0.0.1:57160:LearnerHandler@589] - Sending NEWLEADER message to 1
[myid:1] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11225)(secure=disabled):Learner@717] - Learner received NEWLEADER message
[myid:0] - INFO  [QuorumPeer[myid=0](plain=127.0.0.1:11222)(secure=disabled):Learner@717] - Learner received NEWLEADER message
[myid:2] - INFO  [LearnerHandler-/127.0.0.1:57162:LearnerHandler@619] - Received NEWLEADER-ACK message from 0
[myid:2] - INFO  [LearnerHandler-/127.0.0.1:57160:LearnerHandler@619] - Received NEWLEADER-ACK message from 1
[myid:1] - INFO  [LearnerHandler-/127.0.0.1:49676:LearnerHandler@589] - Sending NEWLEADER message to 0
[myid:0] - INFO  [QuorumPeer[myid=0](plain=127.0.0.1:11222)(secure=disabled):Learner@717] - Learner received NEWLEADER message
[myid:1] - INFO  [LearnerHandler-/127.0.0.1:49676:LearnerHandler@619] - Received NEWLEADER-ACK message from 0
[myid:1] - INFO  [LearnerHandler-/127.0.0.1:49680:LearnerHandler@589] - Sending NEWLEADER message to 0
[myid:0] - INFO  [QuorumPeer[myid=0](plain=127.0.0.1:11222)(secure=disabled):Learner@717] - Learner received NEWLEADER message
[myid:1] - INFO  [LearnerHandler-/127.0.0.1:49680:LearnerHandler@619] - Received NEWLEADER-ACK message from 0
[myid:1] - INFO  [LearnerHandler-/127.0.0.1:49684:LearnerHandler@589] - Sending NEWLEADER message to 2
[myid:2] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11228)(secure=disabled):Learner@717] - Learner received NEWLEADER message
[myid:1] - INFO  [LearnerHandler-/127.0.0.1:49684:LearnerHandler@619] - Received NEWLEADER-ACK message from 2

但奇怪的地方出现了，Leader 在步骤 7 之前，应当一直都是 QuorumPeer {myid=2}。但 NEWLEADER 消息居然是从 QuorumPeer {myid=1} 发出，并且 NEWLEADER ACK 由 QuorumPeer {myid=0, 2} 发出。也就是此时 Leader 居然变成了 QuorumPeer {myid=1}。

检查对应时间点的日志，可以看到：

2021-08-29 12:12:15,958 [myid:2] - ERROR [LearnerHandler-/127.0.0.1:57386:LearnerHandler@714] - Unexpected exception causing shutdown while sock still open
java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
    at java.io.DataInputStream.readInt(DataInputStream.java:387)
    at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:96)
    at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:86)
    at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:134)
    at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:650)

对应代码段：

try { // ... } // java.net.SocketTimeoutException 发生在此处
catch (IOException e) {
    if (sock != null && !sock.isClosed()) {
        LOG.error("Unexpected exception causing shutdown while sock still open", e);
        //close the socket to make sure the
        //other side can see it being close
        try {
            sock.close();
        } catch (IOException ie) {
            // do nothing
} catch (InterruptedException e) {
    LOG.error("Unexpected exception in LearnerHandler.", e);
} catch (SyncThrottleException e) {
    LOG.error("too many concurrent sync.", e);
    syncThrottler = null;
} catch (Exception e) {
    LOG.error("Unexpected exception in LearnerHandler.", e);
    throw e;
} finally {
    if (syncThrottler != null) {
        syncThrottler.endSync();
        syncThrottler = null;
    String remoteAddr = getRemoteAddress();
    LOG.warn("******* GOODBYE {} ********", remoteAddr);
    messageTracker.dumpToLog(remoteAddr);
    shutdown();
}

可以看到，java.net.SocketTimeoutException 导致了 sock.close() 的发生，并在最后进行了 LearnerHandler 的 shutdown，并最终导致了 QuorumPeer {myid=2} 的退出。

2021-08-29 12:12:15,958 [myid:2] - ERROR [LearnerHandler-/127.0.0.1:57386:LearnerHandler@714] - Unexpected exception causing shutdown while sock still open
java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
    at java.io.DataInputStream.readInt(DataInputStream.java:387)
    at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:96)
    at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:86)
    at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:134)
    at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:650)
2021-08-29 12:12:15,959 [myid:2] - WARN  [LearnerHandler-/127.0.0.1:57386:LearnerHandler@737] - ******* GOODBYE /127.0.0.1:57386 ********
// ...
2021-08-29 12:12:25,961 [myid:2] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11228)(secure=disabled):Leader@793] - Shutting down
2021-08-29 12:12:25,961 [myid:2] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11228)(secure=disabled):Leader@799] - Shutdown called. For the reason Not sufficient followers synced, only synced with sids: [ [2] ]
// ...
2021-08-29 12:12:28,010 [myid:2] - WARN  [NIOWorkerThread-12:NIOServerCnxn@373] - Close of session 0x0
java.io.IOException: ZooKeeperServer not running
    at org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCnxn.java:544)
    at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:332)
    at org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:522)
    at org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

之后，QuorumPeer {myid=2} 重新启动，与 QuorumPeer {myid=1} 进行 TRUNC Sync，把最近提交的创建 Znode /zk2 的 Proposal 删除。

2021-08-29 12:12:28,013 [myid:1] - INFO  [LearnerHandler-/127.0.0.1:49904:LearnerHandler@807] - Synchronizing with Learner sid: 2 maxCommittedLog=0x100000001 minCommittedLog=0x100000001 lastProcessedZxid=0x300000000 peerLastZxid=0x100000002
2021-08-29 12:12:28,014 [myid:1] - INFO  [LearnerHandler-/127.0.0.1:49904:LearnerHandler@589] - Sending NEWLEADER message to 2, from myid=1
2021-08-29 12:12:28,014 [myid:1] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11225)(secure=disabled):QuorumPeer@864] - Peer state changed: leading - synchronization
2021-08-29 12:12:28,016 [myid:2] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11228)(secure=disabled):QuorumPeer@869] - Peer state changed: following - synchronization - trunc

了解了前因后果，修复自然是手到擒来。核心的修复只需要一行：

// Learner.java
* Shutdown the Peer
public void shutdown() {
    self.setZooKeeperServer(null);
    self.closeAllConnections();
    self.adminServer.setZooKeeperServer(null);
    if (sender != null) {
        sender.shutdown();
    closeSocket(); //+ 关闭 Learner 与 Leader 之间的 socket
    // shutdown previous zookeeper