前言
ZooKeeper 作为 dubbo 的注册中心，可谓是重中之重，线上 ZK 的任何风吹草动都会牵动心弦。最近笔者就碰到线上 ZK Leader 宕机后，选主无法成功导致 ZK 集群拒绝服务的现象，于是把这个 case 写出来分享给大家(基于 ZooKeeper 3.4.5)。
Bug 现场
一天早上，突然接到电话，说是 ZooKeeper 物理机宕机了，而剩余几台机器状态都是
sh zkServer.sh statusit is probably not running
复制代码
笔者看了下监控，物理机宕机的正好是 ZK 的 leader。3 节点的 ZK，leader 宕了后，其余两台一直未能成为 leader，把宕机的那台紧急拉起来之后，依旧无法选主，导致 ZK 集群整体拒绝服务！
业务影响
Dubbo 如果连接不上 ZK，其调用元信息会一直缓存着，所以并不会对请求调用造成实际影响。麻烦的是，如果在 ZK 拒绝服务期间，应用无法重启或者发布，一旦遇到紧急事件而重启(发布)不能，就会造成比较重大的影响。好在我们为了高可用，做了对等机房建设，所以非常淡定的将流量切到 B 机房，
双机房建设就是好啊,一键切换！切换过后就可以有充裕的时间来恢复 A 机房的集群了。在紧张恢复的同时，笔者也开始了分析工作。
日志表现
首先，查看日志，期间有大量的 client 连接报错，自然是直接过滤掉，以免干扰。
cat zookeeper.out | grep -v 'client xxx' | > /tmp/1.txt
复制代码
首先看到的是下面这样的日志:
ZK-A 机器日志
Zk-A机器:2021-06-16 03:32:35 ... New election. My id=32021-06-16 03:32:46 ... QuoeumPeer] LEADING // 注意，这里选主成功2021-06-16 03:32:46 ... QuoeumPeer] LEADING - LEADER ELECTION TOOK - 7878'2021-06-16 03:32:48 ... QuoeumPeer] Reading snapshot /xxx/snapshot.xxx2021-06-16 03:32:54 ... QuoeumPeer] Snahotting xxx to /xxx/snapshot.xxx2021-06-16 03:33:08 ... Follower sid ZK-B.IP2021-06-16 03:33:08 ... Unexpected exception causing shutdown while sock still openjava.io.EOFException at java.io.DataInputStream.readInt ...... at quorum.LearnerHandler.run2021-06-16 03:33:08 ******* GOODBYE ZK-B.IP *******2021-06-16 03:33:27 Shutting down
复制代码
这段日志看上去像选主成功了，但是和其它机器的通信出问题了，导致 Shutdown 然后重新选举。
ZK-B 机器日志
2021-06-16 03:32:48 New election. My id=22021-06-16 03:32:48 QuoeumPeer] FOLLOWING2021-06-16 03:32:48 QuoeumPeer] FOLLOWING - LEADER ELECTION TOOK - 2222021-06-16 03:33:08.833 QuoeumPeer] Exception when following the leaderjava.net.SocketTimeoutException: Read time out at java.net.SocketInputStream.socketRead0 ...... at org.apache.zookeeper.server.quorum.Follower.followLeader2021-06-16 03:33:08.380 Shutting down
复制代码
这段日志也表明选主成功了，而且自己是 Following 状态，只不过 Leader 迟迟不返回，导致超时进而 Shutdown
时序图
笔者将上面的日志画成时序图，以便分析:
从 ZK-B 的日志可以看出，其在成为 follower 之后，一直等待 leader，直到 Read time out。从 ZK-A 的日志可以看出,其在成为 LEADING 后，在 33:08,803 才收到 Follower 也就是 ZK-B 发出的包。而这时，ZK-B 已经在 33:08,301 的时候 Read timed out 了。
首先分析 follower(ZK-B)的情况
我们知道其在 03:32:48 成为 follower,然后在 03:33:08 出错 Read time out，其间正好是 20s。于是笔者先从 Zookeeper 源码中找下其设置 Read time out 是多长时间。
Learnerprotected void connectToLeader(InetSocketAddress addr) { ...... sock = new Socket() // self.tockTime 2000 self.initLimit 10 sock.setSoTimeout(self.tickTime * self.initLimit); ......}
复制代码
其 Read time out 是按照 zoo.cfg 中的配置项而设置:
tickTime=2000 self.tickTimeinitLimit=10 self.initLimitsyncLimit=5
复制代码
很明显的，ZK-B 在成为 follower 后，由于某种原因 leader 在 20s 后才响应。那么接下来对 leader 进行分析。
对 leader(ZK-A)进行分析
首先我们先看下 Leader 的初始化逻辑:
quorumPeer |->打印 LEADING |->makeLeader |-> new ServerSocket listen and bind |->leader.lead() |->打印 LEADER ELECTION TOOK |->loadData |->loadDataBase |->resore 打印Reading snapshot |->takeSnapshot |->save 打印Snapshotting |->cnxAcceptor 处理请求Accept
复制代码
可以看到，在我们的 ZK 启动监听端口到正式处理请求之间，还有 Reading Snapshot 和 Snapshotting(写)动作。从日志可以看出一个花了 6s 多,一个花了 14s 多。然后就有 20s 的处理空档期。如下图所示:
由于在 socket listen 20s 之后才开始处理数据，所以 ZK-B 建立成功的连接实际还放在 tcp 的内核全连接队列(backlog)里面，由于在内核看来三次握手是成功的，所以能够正常接收 ZK-B 发送的 follower ZK-B 数据。在 20s，ZK-A 真正处理后，从 buffer 里面拿出来 20s 前 ZK-B 发送的数据，处理完回包的时候，发现 ZK-B 连接已经断开。同样的，另一台 follower(这时候我们已经把宕机的拉起来了，所以是 3 台)也是由于此原因 gg,而 leader 迟迟收不到其它机器的响应，认为自己的 leader 没有达到 1/2 的票数，而 Shutdown 重新选举。
Snapshot 耗时
那么是什么导致 Snapshotting 读写这么耗时呢？笔者查看了下 Snapshot 文件大小,有将近一个 G 左右。
调大 initLimit
针对这种情况，其实我们只要调大 initLimit，应该就可以越过这道坎。
zoo.cfgtickTime=2000 // 这个不要动，因为和ZK心跳机制有关initLimit=100 // 直接调成100,200s!
复制代码
这么巧就 20s 么？
难道就这么巧，每次选举流程都刚好卡在 20s 不过？反复选举了好多次，应该有一次要<20s 成功把，不然运气也太差了。如果是每次需要处理 Snapshot 30s 也就算了，但这个 20s 太接近极限值了，是否还有其它因素导致选主不成功？
第二种情况
于是笔者翻了下日志，还真有！这次 leader 这边处理 Snapshot 快了，但是 follower 又拉跨了!日志如下:
leader(ZK-A)第二种情况
2021-06-16 03:38:03 New election. My id= 32021-06-16 03:38:22 QuorumPeer] LEADING2021-06-16 03:38:22 QuorumPeer] LEADING - LEADER ELECTION TOOK 257032021-06-16 03:38:22 QuorumPeer] Reading snapshot2021-06-16 03:38:29 QuorumPeer] Snapshotting2021-06-16 03:38:42 LearnerHandler] Follower sid 12021-06-16 03:38:42 LearnerHandler] Follower sid 32021-06-16 03:38:42 LearnerHandler] Sending DIFF2021-06-16 03:38:42 LearnerHandler] Sending DIFF2021-06-16 03:38:54 LearnerHandler] Have quorum of supporters2021-06-16 03:38:55 client attempting to establsh new session 到这开始接收client请求了......2021-06-16 03:38:58 Shutdown callsedjava.lang.Exception: shutdown Leader! reason: Only 1 followers,need 1 at org.apache.zookeeper.server.quorum.Leader.shutdown
复制代码
从日志中我们可以看到选举是成功了的，毕竟处理 Snapshot 只处理了 13s(可能是 pagecache 的原因处理变快)。其它两个 follower 顺利连接，同时给他们发送 DIFF 包，但是情况没好多久，又爆了一个 follower 不够的报错，这里的报错信息比较迷惑。我们看下代码:
Leader.leadvoid lead() { while(true){ Thread.sleep(self.tickTime/2); ...... syncedSet.add(self.getId()) for(LearnerHandler f:getLearners()){ if(f.synced() && f.getLearnerType()==LearnerType.PARTICIPANT){ syncedSet.add(f.getSid()); } f.ping(); } // syncedSet只有1个也就是自身，不符合>1/2的条件，报错并跳出 if (!tickSkip && !self.getQuorumVerifier().containsQuorum(syncedSet)) { shutdown("Only" + syncedSet.size() + " followers, need" + (self.getVotingView().size()/2)); return; } }}
复制代码
报错的实质就是和 leader 同步的 syncedSet 小于固定的 1/2 集群，所以 shutdown 了。同时在代码里面我们又可以看到 syncedSet 的判定是通过 learnerHander.synced()来决定。我们继续看下代码:
LearnerHandler public boolean synced(){ // 这边isAlive是线程的isAlive return isAlive() && tickOfLastAck >= leader.self.tick - leader.self.syncLimit; }
复制代码
很明显的，follower 和 leader 的同步时间超过了 leader.self.syncLimit 也就是 5 * 2 = 10s
zoo.cfgtickTime = 2000syncLimit = 5
复制代码
那么我们的 tick 是怎么更新的呢,答案是在 follower 响应 UPTODATE 包,也就是已经和 leader 同步后，follower 每个包过来就更新一次，在此之前并不更新。
进一步推理，也就是我们的 follower 处理 leader 的包超过了 10s，导致 tick 未及时更新，进而 syncedSet 小于数量，导致 leader shutdown。
follower(ZK-B)第二种情况
带着这个结论，笔者去翻了 follower(ZK-B)的日志(注:ZK-C 也是如此)
2021-06-16 03:38:24 New election. My id = 32021-06-16 03:38:24 FOLLOWING2021-06-16 03:38:24 FOLLOWING - LEADER ELECTION TOOK - 80042021-06-16 03:38:42 Getting a diff from the leader2021-06-16 03:38:42 Snapshotting2021-06-16 03:38:57 Snapshotting2021-06-16 03:39:12 Got zxid xxx2021-06-16 03:39:12 Exception when following the leaderjava.net.SocketException: Broken pipe
复制代码
又是 Snapshot,这次我们可以看到每次 Snapshot 会花 15s 左右，远超了 syncLimit。从源码中我们可以得知，每次 Snapshot 之后都会立马 writePacket(即响应)，但是第一次回包有由于不是处理的 UPTODATE 包,所以并不会更新 Leader 端对应的 tick:
learner:proteced void syncWithLeader(...){outerloop: while(self.isRunning()){ readPacket(qp); switch(qp.getType()){ case Leader.UPTODATE if(!snapshotTaken){ zk.takeSnapshot(); ...... } break outerloop; } case Leader.NEWLEADER: zk.takeSnapshot(); ...... writePacket(......) // leader收到后会更新tick break; } ...... writePacket(ack,True); // leader收到后会更新tick}
复制代码
注意，ZK-B 的日志里面表明会两次 Snapshotting。至于为什么两次，应该是一个微妙的 Bug,(在 3.4.5 的官方注释里面做了 fix,但看日志依旧打了两次)，笔者并没有深究。好了，整个时序图就如下所示:
好了，第二种情况也 gg 了。这一次时间就不是刚刚好出在边缘了，得将近 30s 才能 Okay, 而 synedSet 只有 10s(2*5)。ZK 集群就在这两种情况中反复选举，直到人工介入。
调大 syncLimit
针对这种情况，其实我们只要调大 syncLimit，应该就可以越过这道坎。
zoo.cfgtickTime=2000 // 这个不要动，因为和ZK心跳机制有关syncLimit=50 // 直接调成50,100s!
复制代码
线下复现
当然了，有了分析还是不够的。我们还需要通过测试去复现并验证我们的结论。我们在线下构造了一个 1024G Snapshot 的 ZookKeeper 进行测试，在 initLimit=10 以及 syncLimit=5 的情况下确实和线上出现一模一样的那两种现象。在笔者将参数调整后:
zoo.cfgtickTime=2000initLimit=100 // 200ssyncLimit=50 // 100s
复制代码
Zookeeper 集群终于正常了。
线下用新版本 3.4.13 尝试复现
我们在线下还用比较新的版本 3.4.13 尝试复现，发现 Zookeeper 在不调整参数的情况下，很快的就选主成功并正常提供服务了。笔者翻了翻源码，发现其直接在 Leader.lead()阶段和 SyncWithLeader 阶段(如果是用 Diff 的话)将 takeSnapshot 去掉了。这也就避免了处理 snapshot 时间过长导致无法提供服务的现象。
Zookeeper 3.4.13
ZookeeperServer.javapublic void loadData(){ ... // takeSnapshot() 删掉了最后一行的takeSnapshot}
learner.javaprotected void syncWithLeader(...){ boolean snapshotNeeded=true if(qp.getType() == Leader.DIFF){ ...... snapshotNeeded = false } ...... if(snapshotNeeded){ zk.takeSnapshot(); } ......}
复制代码
还是升级到高版本靠谱呀，这个版本的代码顺带把那个迷惑性的日志也改了！
为何 Dubbo-ZK 有那么多的数据
最后的问题就是一个 dubbo 相关的 ZK 为什么有那么多数据了!笔者利用 ZK 使用的
org.apache.zookeeper.server.SnapshotFormatter
复制代码
工具 dump 出来并用 shell(awk|unique)聚合了一把，发现 dubbo 的数据只占了其中的 1/4。有 1/2 是 Solar 的 Zookeeper(已经迁移掉，遗留在上面的)。还有 1/4 是由于某个系统的分布式锁 Bug 不停的写入进去并且不删除的(已让他们修改)。所以将 dubbo-zk 和其它 ZK 数据分离是多么的重要！随便滥用就有可能导致重大事件！
总结
Zookeeper 作为重要的元数据管理系统，其无法提供服务有可能会带来不可估量的影响。感谢双机房建设让我们有充足的时间和轻松的心态处理此问题。另外，虽然 ZK 选举虽然复杂，但是只要沉下心来慢慢分析，总归能够发现蛛丝马迹，进而找到突破口!
评论