• Kafka 集群部署環(huán)境
  1. kafka 集群所用版本 0.9.0.1
  2. 集群部署了實時監(jiān)控: 通過實時寫入數(shù)據來監(jiān)控集群的可用性, 延遲等;

集群故障發(fā)生

• 集群的實時監(jiān)控發(fā)出一條寫入數(shù)據失敗的報警, 然后馬上又收到了恢復的報警, 這個報警當時沒有重要,沒有去到對應的服務器上去看下log, 惡夢的開始啊~~~
• 很快多個業(yè)務反饋Topic無法寫入, 運維人員介入

故障解決

• 運維人員首先查看kafka broker日志, 發(fā)現(xiàn)大量如下的日志:

[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, 發(fā)送了舊版 kafka broker 不支持的request, 這會導致exception發(fā)生, 然后同批次select出來的所有客戶端對應的request都將被拋棄不能處理,代碼在 SocketServer.scala里面, 大家有興趣可以自行查閱
  1. 這個問題不僅可能導致客戶端的request丟失, broker和broker, broker和controller之間的通訊也受影響;
  2. 這也解釋了為什么 實時監(jiān)控 先報警 然后又馬上恢復了: 不和這樣不被支持的request同批次處理就不會出現(xiàn)問題;
• 解決過程:
  1. 我們之前已經修復過這個問題, 有準備好的相應的jar包;
  2. 運維小伙伴開始了愉快的jar包替換和啟動broker的工作~~~~~~

集群恢復

• kafka broker的優(yōu)雅shutdown的時間極不受控, 如果強行kill -9 在start后要作長時間的recovery, 數(shù)據多的情況下能讓你等到崩潰;
• 集群重啟完, 通過log觀察, ArrayIndexOutOfBoundsException異常已經被正確處理, 也找到了相應的業(yè)務來源;
• 業(yè)務反饋Topic可以重新寫入;

然而, 事件并沒有結束, 而是另一個惡夢的開始

集群故障再次發(fā)生

• 很多業(yè)務反饋使用原有的group無法消費Topic數(shù)據;
• 用自己的consumer測試, 發(fā)現(xiàn)確實有些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的加載情況, 發(fā)現(xiàn)對應的__consumer_offsets正在被Loading;

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

2. 沒有找到下面類似的加載完成的日志:

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

也沒有發(fā)生任何的exception的日志

3. **使用jstack來dump出當前的線程堆棧多次查看, 證實一直是在加載數(shù)據,沒有卡死;

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

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

  1. 去到__conuser_offsets partition相應的磁盤目錄查看,發(fā)生有2000多個log文件, 每個在100M左右;
  2. kaka 的log compac功能失效了, 這個問題在之前的文章里有過介紹: Kafka運維填坑,
  3. log compact相關介紹可以參考 Kafka的日志清理-LogCleaner

• 手動加速Loading:

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

故障恢復

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

總結

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

Kafka源碼分析-匯總