• Kafka 叢集部署環境
  1. kafka 叢集所用版本 0.9.0.1
  2. 叢集部署了實時監控: 通過實時寫入資料來監控叢集的可用性, 延遲等;

叢集故障發生

• 叢集的實時監控發出一條寫入資料失敗的報警, 然後馬上又收到了恢復的報警, 這個報警當時沒有重要,沒有去到對應的伺服器上去看下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裡面, 大家有興趣可以自行查閱
  1. 這個問題不僅可能導致客戶端的request丟失, broker和broker, broker和controller之間的通訊也受影響;
  2. 這也解釋了為什麼 實時監控 先報警 然後又馬上恢復了: 不和這樣不被支援的request同批次處理就不會出現問題;
• 解決過程:
  1. 我們之前已經修復過這個問題, 有準備好的相應的jar包;
  2. 運維小夥伴開始了愉快的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

1. 第一條日誌 說明consumer已經確認了當前的coordinator, 連線沒有問題;
2. 第二條日誌顯示沒有 Not coordinator, 對應broker端是說雖然coordinator確認了,但是沒有在這個 coodinator上找到這個group對應的metada資訊;
3. group的metada資訊在coordinator啟動或__consuser_offsets的partion切主時被載入到記憶體,這麼說來是相應的__consumer_offsets的partition沒有被載入;
4. 關於coordinator, __consumer_offsets, group metada的資訊可以參考 Kafka的訊息是如何被消費的?

• 檢視broker端日誌, 確認goroup metadata的相關問題

1. 查詢對應的__consumer_offsets的partition的載入情況, 發現對應的__consumer_offsets正在被Loading;

Loading offsets and group metadata from [__consumer_offsets,19] (kafka.coordinator.GroupMetadataManager)

1. 沒有找到下面類似的載入完成的日誌:

Finished loading offsets from [__consumer_offsets,27] in 1205 milliseconds. (kafka.coordinator.GroupMetadataManager)

也沒有發生任何的exception的日誌

1. **使用jstack來dump出當前的執行緒堆疊多次檢視, 證實一直是在載入資料,沒有卡死;

• 現在的問題基本上明確了, 有些__consumer_offsets載入完成了,可以消費, 些沒有完成則暫時無法消費, 如果死等loading完成, 叢集的消費可以正常, 但將花費很多時間;**

• 為何loading這些__consumer_offsets要花費如此長的時間?

  1. 去到__conuser_offsets partition相應的磁碟目錄檢視,發生有2000多個log檔案, 每個在100M左右;
  2. kaka 的log compac功能失效了, 這個問題在之前的文章裡有過介紹: Kafka運維填坑,

• 手動加速Loading:

  1. 即使log cleaner功能失敗, 為了加速loading, 我們手動刪除了大部分的log檔案; 這樣作有一定風險, 可能會導致某些group的group metadata和committed offset丟失, 從而觸發客戶端在消費時offset reset;

故障恢復

• 所有__consumer_offset都載入完後, 所有group均恢復了消費;

總結

• 對實時監控的報警一定要足夠重視;
• 更新完jar包, 重啟broker時, 三臺儲存__consumer_offsets partition合部同時重啟,均在Loading狀態, 這種作法不合適,最多同時重啟兩臺, 留一臺可以繼續提供coordinattor的功能;
• 加強對log compact失效的監控, 完美方案是找到失效的根本原因並修復;