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

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

【问题现象】


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

【问题定位】


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

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

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

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

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

1e203706400a58dfdb3847ce3d94dd37.png

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

8111512d592c086169a76115f4d61aa5.png

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

98e1a1ca9e2152e2d25abdcf272e9bce.png

注意,处理超时事件时(scheduleSessionExpiryHandler方法中)有会话超时的日志打印;同时重连时会有一个初始化新会话的日志打印。

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

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

f35f4ef510b1b6a188ab8f38665728da.png

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

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

在callBeforeInitializingSession中,调用handler的beforeInitializingSession

d02c780316f72f9d3cddcb4932616bbb.png

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

25367a3e779306cafc2653ac9a0e010f.png

b841f332d3ab37c727460c2c3ce06071.png

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

e8d4bc5a3a2810f6fcc0d7091f830bfa.png

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

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

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

f2098e398ccaa29ac78b12dbc5d3073b.png

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

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

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

b53601e1822438d1db5fdb7374316577.png

fe8c008ff106f2bafec5d209aa716e5f.png

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.
// 准备重连
[
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值