kafka问题的一次不负责任排查

2022的第一篇文章，分享总结下一个kafka问题的排查过程。

【问题现象】

---

元旦前，某测试环境因为网络不稳定，出现了kafka与zookeeper连接断开后，没有重连。

【问题定位】

---

初步查看了下日志，发现kafka与zookeeper之间出现了会话超时，第一次超时有正确进行重连，之后再次出现会话超时，在这之后就没有进行重连了。

而实际查看zookeeper本身没有任何异常，无解，还是得结合源码来分析。

首先，kafka内部与zookeeper的交互是通过创建一个Zookeeper类的实例对象来进行通信的，同时通过传递一个watch对象（ZookeeperClientWatch），作为事件的回调处理。

@volatile private var zooKeeper = new ZooKeeper(connectString, sessionTimeoutMs, ZooKeeperClientWatcher)

Expire事件(会话超时会产生该事件)发生时，回调该对象的process方法进行处理

在该方法中，由单独的线程负责进行重连。

具体的重连逻辑为，判断zookeeper客户端中的状态，然后关闭客户端，并重建对象以进行重连。

注意，处理超时事件时（scheduleSessionExpiryHandler方法中）有会话超时的日志打印；同时重连时会有一个初始化新会话的日志打印。

分析到这里，一开始会认为是zookeeper客户端中的状态不对，导致没有进入if分支，继而没有进行重连。朝着这个方向，又仔细分析了zookeeper客户端中的代码，发现并不会出现该问题，因为在出现会话超时的时候，首先就将状态进行了变更，然后才回调。

到这里，感觉有点无头绪了，回想当时排查问题时，将kafka内部的线程堆栈信息都打印出来了，索性拿出来看看，结果发现，有这么一个堆栈信息：

从堆栈来看，第二次会话超时确实进入了reinitialize方法，但一直卡在foreach循环中，也就是该方法的第一行调用中。

那么在这里又是为什么会卡住呢，继续分析代码

在callBeforeInitializingSession中，调用handler的beforeInitializingSession

该handler是KafkaController通过调用registerStateChangeHandler注册进来的

也就是说，在重连之前最终会调用kafkaController中的beforeInitializingSession方法，在这个方法中，会new一个Expire事件，然后将该事件放到事件队列中，由事件线程驱动回调处理，而自身则阻塞直到事件处理完成。

结合代码，再对照上面的堆栈信息，可以看到确实是这么个流程。

那问题又来了，为什么该事件会一直没有被处理呢？事件只要处理就会回调process方法，在该方法中通过将计数器减1，阻塞的线程感知计数器变0，也就不会再阻塞，可以继续往下运行了。

再来看事件处理线程的堆栈：

什么？事件处理线程同样也是在卡主死等？

那么就只有一种可能来解释：事件处理线程在处理其他某个事件一直没有返回，因此重新初始化的时候expire事件丢到队列中，一直没有被事件处理线程拿出来处理。从而引起会话过期处理线程也卡住导致没有重连zookeeper！

顺着堆栈信息，跟踪相关代码调用链，发现kafka在连接zookeeper之后，会进行一系列的交互处理（注意之前reinitialize方法中的最后一行代码），包括向zookeeper发送请求，并同步等待直到拿到响应才继续后续的逻辑处理。

handleRequests方法中的那段代码，个人理解为：涉及两个线程的交互：

线程1调用send方法，将数据打包，最终调用zookeeper客户端进行处理（实际上是放到zookeeper客户端内部的一个outgoing队列中，再由zookeeper客户端内部的sendThread进行发送），然后同步等待（这个线程就是事件处理线程）。

线程2通过send方法中的processResult回调将响应放到responseQueue中，然后将计数器减1，当所有请求都回调完成时，计数器归0，上面的线程阻塞解除继续后续逻辑处理。

如果在回调过程中出现异常，是不是就无法调用

countDownLatch.countDown()

从而导致出现事件线程卡主，连锁引起会话超时处理线程卡主，不再重连zookeeper。

而实际日志中，也确实发现有这么一个异常，也恰好是在processResult的处理过程中。

// 第一次超时
[2021-12-27 21:22:48.416][INFO][zk-session-expiry-handler0][Logging.scala:info:66] , [ZooKeeperClient] Session expired.
// 准备重连
[