踩坑 ZooKeeper Issue 2325

Posted 2021-04-13 唯品会质量工程

节前，客户端在重连时发送的setWatches请求包太大，超过了 Server的 jute.maxbuffer（默认为1M），Server报错 Len error ，然后关闭链接；客户端继续重连，如此往复的问题。为此，调大了该参数，可在重启后悲催的一面出现了，ZK 集群节点数据为空，同一集群内数据不一致，导致业务域一定几率获取不到数据。

开发同学找了一圈，发现有个运维的 crontab 计划，每天删除30天前的数据。可 ZK 本身有 snapshot 再生成机制，理论上还会将内存里的 datatree 写到 snapshot 的。此外，集群中的机器重启后，应该同 leader 进行同步数据的，理论上也能将数据还原。隐藏问题背后的究竟是什么原因呢？

Note: 问题 ZK 版本为 3.4.6，当时的集群中有3个节点。

snapshot生成机制

首先看以下 ZK code

public class SyncRequestProcessor extends ZooKeeperCriticalThread implements
        RequestProcessor {
    ...
    private final Random r = new Random(System.nanoTime());
    /**     * The number of log entries to log before starting a snapshot     */
    private static int snapCount = ZooKeeperServer.getSnapCount(); // snapCount的值，默认100000
    ...
    @Override
    public void run() {
        try {
            int logCount = 0;
 
            // we do this in an attempt to ensure that not all of the servers
            // in the ensemble take a snapshot at the same time
            int randRoll = r.nextInt(snapCount/2);
            while (true) {
                Request si = null;
                if (toFlush.isEmpty()) {
                    si = queuedRequests.take();
                } else {
                    si = queuedRequests.poll();
                    if (si == null) {
                        flush(toFlush);
                        continue;
                    }
                }
                if (si == requestOfDeath) {
                    break;
                }
                if (si != null) {
                    // track the number of records written to the log
                    if (zks.getZKDatabase().append(si)) {
                        logCount++;
                        if (logCount > (snapCount / 2 + randRoll)) {//注意这边，事务日志在snapCount/2 至 snapCount之间就有几率触发snapshot生成
                            randRoll = r.nextInt(snapCount/2);
                            // roll the log
                            zks.getZKDatabase().rollLog();
                            // take a snapshot
                            if (snapInProcess != null && snapInProcess.isAlive()) {
                                LOG.warn("Too busy to snap, skipping");
                            } else {
                                snapInProcess = new ZooKeeperThread("Snapshot Thread") {
                                        public void run() {
                                            try {
                                                zks.takeSnapshot();//写snapshot
                                            } catch(Exception e) {
                                                LOG.warn("Unexpected exception", e);
                                            }
                                        }
                                    };
                                snapInProcess.start();
                            }
                            logCount = 0;
                        }
                    } else if (toFlush.isEmpty()) {
                        // optimization for read heavy workloads
                        // iff this is a read, and there are no pending
                        // flushes (writes), then just pass this to the next
                        // processor
                        if (nextProcessor != null) {
                            nextProcessor.processRequest(si);
                            if (nextProcessor instanceof Flushable) {
                                ((Flushable)nextProcessor).flush();
                            }
                        }
                        continue;
                    }
                    toFlush.add(si);
                    if (toFlush.size() > 1000) {
                        flush(toFlush);
                    }
                }
            }
        } catch (Throwable t) {
            handleException(this.getName(), t);
        } finally{
            running = false;
        }
        LOG.info("SyncRequestProcessor exited!");
    }
    ...}

从上面代码可以发现：

1. 每次zk收到client发来的事务类型的操作会记录到事务日志（这里的事务型操作包括：create、delete与update）

2. 当事务日志在 snapCount/2 至 snapCount 之间就有几率触发snapshot生成（ 这里的 snapCount默认为100000，所以在事务日志数在 5w-10w 之间才会触发写 snapshot 文件。

问题集群因使用域比较少，且配置改动不平凡导致30天内没有snapshot与事务文件生成。任务执行之后清理所有的snapshot和事务文件。所以集群在30天内变动没有达到阈值导致未生成 snapshot。

无法从leader同步数据的原因

在说明具体原因前，先介绍下 ZK 相关的基本知识。

• zxid：ZooKeeper状态的每一次改变, 都对应着一个递增的 Transaction id, 该id称为 zxid. 由于zxid 的递增性质, 如果zxid1小于zxid2, 那么 zxid1 肯定先于 zxid2 发生。创建、更新任意节点的数据, 或者删除任意节点, 都会导致Zookeeper状态发生改变, 从而导致zxid的值增加。

• peerLastZxid：最近的一个zxid

• ZK follower 与 leader 同步机制： 根据 peerLastZxid 来判断如何进行同步

1. 如果 peerLastZxid 大于 leader 的最新的 zxid，则给 follower 发送 trunc 包，让follower 删掉多出来的事务，一般来说这种情况比较少。

2. 如果 peerLastZxid 小于 leader 的最新的 zxid，则给 follower 发送 diff 包，让follower 补齐和 leader 之间的差距。

Note：

为了和 follower 做快速的同步，leader 会在内存中缓存一部分最近的事务，即 minCommittedLog 和 maxCommittedLog 之间的事务，如果 peerLastZxid < minCommittedLog ，leader就给follower发送一个snap包，把当前leader的镜像发给follower。

具体可参考 ZK 3.4.6 中方法 syncWithLeader(long newLeaderZxid)的源码。

以下是问题发生时，leader 和 follower 的日志。

leader的日志：

2017-09-28 18:03:21,432 [myid:2] - INFO [LearnerHandler-/xxx.xxx.xxx.xxx:16799:LearnerHandler@385] - Synchronizing with Follower sid: 1 maxCommittedLog=0x3000110ba minCommittedLog=0x300010ec6 peerLastZxid=0x3000110ba
2017-09-28 18:03:21,432 [myid:2] - INFO [LearnerHandler-/xxx.xxx.xxx.xxx:16799:LearnerHandler@462] - Sending DIFF

问题节点001的日志：

2017-09-28 18:03:21,399 [myid:1] - INFO  [QuorumPeer[myid=1]/0.0.0.0:2181:FastLeaderElection@815] - New election. My id = 1, proposed zxid=0x3000110ba

...

2017-09-28 18:03:21,424 [myid:1] - INFO  [QuorumPeer[myid=1]/0.0.0.0:2181:Learner@323] - Getting a diff from the leader 0x3000110ba

从leader日志信息中可以看到，leader 向 follower 发送 DIFF 请求：maxCommittedLog=0x3000110ba peerLastZxid=0x3000110ba，而 001 本地的 zxid=0x3000110ba 是相同的，就不进行同步了。

问题节点001的日志表明其接受到了leader发过来的DIFF请求，并且leader传递过来的 zxid=0x3000110ba，与本身的zxid进行比较，发现是一致的，不需要进行数据同步，而后续的更新也将会是增量更新。

至此可以得到问题节点在经执行定时清理后，删除了所有的 snapshot 与事务文件。在执行 cron job 后至修改参数重启前，问题节点又生成了较新的事务日志，但因没有数据变更，因而没有生成新的 snapshot。变更参数 jute.maxbuffer，需要重启该 ZK 节点。Zookeeper 启动时会获取节点本地的 snapshot 和 log日志加载数据到datatree中，并且记录当前最大的ZXID。之后问题节点与leader同步数据时因 ZXID 相差很小，所以是恢复相差的事务处理，从而导致没有恢复到所有配置数据。

该问题出现在 ZK 3.4.6 中，在 3.5.4 中修复。具体参考 ZK 官方问题记录 ZOOKEEPER-2325 Data inconsistency if all snapshots empty or missing（https://issues.apache.org/jira/browse/ZOOKEEPER-2325）