現象
凌晨,當運維剛躺下,就被業務研發的電話叫醒,"哥們!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