运维兄弟！Kafka怎么又”超时”了？

现象

凌晨，当运维刚躺下，就被业务研发的电话叫醒，”哥们！kafka服务又异常了？影响到业务了，快看看”，业务研发给出的异常日志如下：

基本分析

• 集群检查：立即确认kafka集群以及涉及到topic健康状态。集群状态正常，收发消息正常，压力负载正常；topic读写正常。
• 变更操作：近期未做关于kafka的任何变更操作，排查变更影响。
• 确定影响范围：个例问题。问题规模限定在当前业务主机。

抓包分析

基本确定异常和集群无关后，接下来就是要排查网络相关的问题，网络和系统（内核参数设定）是息息相关的，网络问题是复杂而神秘的，后期会根据场景给大家分享，今天，我们主要分析网络链路问题

• 使用tcpdump抓包（客户端抓包）。

# 抓所有和kafka节点通信的网络数据包（因为数据量很大，在异常时抓取了几分钟的包）
nohup tcpdump  port 9092 -w kafka.pcap &

• 报文分析。
• 错误日志。

2022-09-30 00:08:53.470 kafka/consumer.go:128 kafka_util,error,consume,group:cop.inke_owt.inno_pdl.user_pushmsg.server,from:user.msg.push.consume,topic:inno_phxyuyin_user_pushmsg_push_msg,err:kafka: error while consuming inno_phxyuyin_user_pushmsg_push_msg/1: write tcp 10.226.11.15:38742->10.226.5.4:9092: write: broken pipe

• 过滤报文（10.226.11.15:38742->10.226.5.4:9092）。

• 报文分析。
• 第477个报文，也就是从2022-09-30 00:07:06.387480时开始，没有数据传输了，客户端每5秒发一个心跳包（TCP Keep-Alive），从交互报文可以看出很规律（每5秒一个心跳包和一个响应包）。
• 第899个报文，也就是2022-09-30 00:07:56.467480时服务端响应后，在下一个心跳包之前，也就是00:08:01 的时候，并未向服务端发送心跳。
• 第940个报文，也就是2022-09-30 00:08:01.376174，这时服务端给客户端发送了FIN包（请求断开连接），而且客户端也回复了ACK包，确认断开连接了。
• 连接已经被断开后，客户端再次在这个连接上发送心跳包，收到了服务端回复的rst包，程序报错（write: broken pipe）–管道关闭了，写失败。

分析结果

• 业务主机网络存在不稳定性，TCP心跳包丢了，导致服务端没收到，在00:08:06在次发送的时候，连接已经断了（最终问题反馈到厂商，厂商技术同学反馈宿主机在故障期间有异常，主机做过热迁移。）
• 5s内服务端收不到客户端的心跳包，就会主动发起断开连接（FIN），断开链接后，客户端在发送写请求，肯定会报broken pipe，异常会被抛出到程序侧。

知识扩展

1、TCP KeepAlive机制是什么？

在TCP长连接下，客户端和服务器若长时间无数据交互情况下，若一方出现异常情况关闭连接，另一方无法感知到，引入KeepAlive，当长连接无数据交互一定时间间隔时，连接的一方会向对方发送保活探测包，如连接仍正常，对方将对此确认回应。

2、Linux系统下KeepAlive内核参数配置

# 允许的持续空闲时长，或者说每次正常发送心跳的周期
net.ipv4.tcp_keepalive_time 

# 在tcp_keepalive_time之后，最大允许发送保活探测包的次数，到达此次数后直接放弃尝试，并关闭连接
net.ipv4.tcp_keepalive_probes

# 在tcp_keepalive_time之后，没有接收到对方确认，继续发送保活探测包的发送频率
net.ipv4.tcp_keepalive_intvl