記一次Kafka集群的故障恢復
- Kafka 集群部署環境
- kafka 集群所用版本 0.9.0.1
- 集群部署了實時監控: 通過實時寫入數據來監控集群的可用性, 延遲等;
集群故障發生
- 集群的實時監控發出一條寫入數據失敗的報警, 然後馬上又收到了恢復的報警, 這個報警當時沒有重要,沒有去到對應的伺服器上去看下log, 惡夢的開始啊~~~
- 很快多個業務反饋Topic無法寫入, 運維人員介入
故障解決
- 運維人員首先查看kafka broker日誌, 發現大量如下的日誌:
[2017-10-12 16:52:38,141] ERROR Processor got uncaught exception. (kafka.network.Processor)
java.lang.ArrayIndexOutOfBoundsException: 18
at org.apache.kafka.common.protocol.ApiKeys.forId(ApiKeys.java:68)
at org.apache.kafka.common.requests.AbstractRequest.getRequest(AbstractRequest.java:39)
at kafka.network.RequestChannel$Request.<init>(RequestChannel.scala:79)
at kafka.network.Processor$$anonfun$run$11.apply(SocketServer.scala:426)
at kafka.network.Processor$$anonfun$run$11.apply(SocketServer.scala:421)
at scala.collection.Iterator$class.foreach(Iterator.scala:742)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
at scala.collection.IterableLike$class.foreach(IterableLike.scala:72)
at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
- 這個問題就很明了了, 在之前的文章里有過介紹: Kafka運維填坑, 上面也給出了簡單修復, 主要原因是 新版kafka 客戶端 sdk訪問較舊版的kafka, 發送了舊版 kafka broker 不支持的request, 這會導致exception發生, 然後同批次select出來的所有客戶端對應的request都將被拋棄不能處理,代碼在
SocketServer.scala裡面, 大家有興趣可以自行查閱 - 這個問題不僅可能導致客戶端的request丟失, broker和broker, broker和controller之間的通訊也受影響;
- 這也解釋了為什麼 實時監控 先報警 然後又馬上恢復了: 不和這樣不被支持的request同批次處理就不會出現問題;
- 解決過程:
- 我們之前已經修復過這個問題, 有準備好的相應的jar包;
- 運維小夥伴開始了愉快的jar包替換和啟動broker的工作~~~~~~
集群恢復
- kafka broker的優雅shutdown的時間極不受控, 如果強行kill -9 在start後要作長時間的recovery, 數據多的情況下能讓你等到崩潰;
- 集群重啟完, 通過log觀察,
ArrayIndexOutOfBoundsException異常已經被正確處理, 也找到了相應的業務來源; - 業務反饋Topic可以重新寫入;
然而, 事件並沒有結束, 而是另一個惡夢的開始
集群故障再次發生
- 很多業務反饋使用原有的group無法消費Topic數據;
- 用自己的consumer測試, 發現確實有些group可以, 有些group不能消費;
- 一波不平一波又起, 註定是個不平凡的夜晚啊, 居然還有點小興奮~~~
故障解決
- 查看consumer測試程序不能消費時的日誌,一直在重複如下log:
Group "xxx" coordinator is xxx.xxx.xxx.xxx:9092 id 3
Broker: Not coordinator for group
- 第一條日誌 說明consumer已經確認了當前的coordinator, 連接沒有問題;
- 第二條日誌顯示沒有
Not coordinator, 對應broker端是說雖然coordinator確認了,但是沒有在這個 coodinator上找到這個group對應的metada信息; - group的metada信息在coordinator啟動或consuser_offsets的partion切主時被載入到內存,這麼說來是相應的consumer_offsets的partition沒有被載入;
- 關於coordinator, __consumer_offsets, group metada的信息可以參考 Kafka的消息是如何被消費的?
- 查看broker端日誌, 確認goroup metadata的相關問題
- 查找對應的consumer_offsets的partition的載入情況, 發現對應的consumer_offsets正在被
Loading;
Loading offsets and group metadata from [__consumer_offsets,19] (kafka.coordinator.GroupMetadataManager)
- 沒有找到下面類似的載入完成的日誌:
Finished loading offsets from [__consumer_offsets,27] in 1205 milliseconds. (kafka.coordinator.GroupMetadataManager)
也沒有發生任何的exception的日誌 3. 使用jstack來dump出當前的線程堆棧多次查看, 證實一直是在載入數據,沒有卡死; * 現在的問題基本上明確了, 有些__consumer_offsets載入完成了,可以消費, 些沒有完成則暫時無法消費, 如果死等loading完成, 集群的消費可以正常, 但將花費很多時間;
- 為何loading這些__consumer_offsets要花費如此長的時間?
- 去到__conuser_offsets partition相應的磁碟目錄查看,發生有2000多個log文件, 每個在100M左右;
- kaka 的log compac功能失效了, 這個問題在之前的文章里有過介紹: Kafka運維填坑,
- log compact相關介紹可以參考 Kafka的日誌清理-LogCleaner
- 手動加速Loading:
- 即使log cleaner功能失敗, 為了加速loading, 我們手動刪除了大部分的log文件; 這樣作有一定風險, 可能會導致某些group的group metadata和committed offset丟失, 從而觸發客戶端在消費時offset reset; ## 故障恢復
- 所有__consumer_offset都載入完後, 所有group均恢復了消費;
總結
- 對實時監控的報警一定要足夠重視;
- 更新完jar包, 重啟broker時, 三台存儲__consumer_offsets partition合部同時重啟,均在Loading狀態, 這種作法不合適,最多同時重啟兩台, 留一台可以繼續提供coordinattor的功能;
- 加強對log compact失效的監控, 完美方案是找到失效的根本原因並修復;
Kafka源碼分析-匯總
推薦閱讀：
