【原創】大叔問題定位分享（3）Kafka集羣broker進程逐個報錯退出

 kafka0.8.1

一 問題現象

生產環境kafka服務器13四、13五、136分別在10月11號、10月13號掛掉：

134日誌

[2014-10-13 16:45:41,902] FATAL [KafkaApi-134] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis)

135日誌

[2014-10-11 11:02:35,754] FATAL [KafkaApi-135] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis)

136日誌

[2014-10-13 19:10:35,106] FATAL [KafkaApi-136] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis)

報java.io.FileNotFoundException（No such file or directory），具體錯誤日誌以下：

 

其中cacheClear-onlineConfirm-1是在線確認環境使用的一個分區；

二 問題分析

Kafka broker在做爲leader收到message以後會調用kafka.log.Log.append將message加到本地log

 

其中會先調用maybeRoll來檢查是否須要作roll，

 

roll中會新建一個segment，同時將老的segment的index文件作一下trim，

trimToValidSize中會調用resize，resize中會使用RandomAccessFile來打開index文件，報錯的就是這一行：

 

1.1 爲何須要對index作trim

index文件初始化過程爲：

 

LogSegment構造函數：

OffsetIndex構造函數：

 

可見index文件初始化時文件大小是固定的，按照配置中的maxIndexSize來定義，因此最後一個segment的index文件大小是同樣的，而且初始時比log文件要大不少，以下圖紅框所示：

 

可是這樣的index文件會有不少浪費，因此在roll時會根據index文件中的實際的entry數量作一下對文件大小作trim，這樣只須要必要的文件大小來存儲信息，如上圖藍框所示；

 

1.2 何時RandomAccessFile會報java.io.FileNotFoundException

目錄/home/test存在，可是/home/test/1.txt不存在，/home/test/1/1.txt也不存在，使用RandomAccessFile來分別讀取/home/test/1.txt和/home/test/1/1.txt，發現讀取/home/test/1.txt時程序不會報錯，可是讀取/home/test/1/1.txt時程序報錯：

1）  讀取/home/test/1.txt

 

2）  讀取/home/test/1/1.txt

 

因此報錯

是由於cacheClear-onlineConfirm-1目錄不存在，而不是由於00000000000002001137.index索引文件不存在；

 

1.3 目錄什麼時間被刪除

在kafka服務器進程退出以前，日誌中有不少error：

 

Kafka服務器有一個後臺線程會作retention檢查，檢查間隔默認是5分鐘

 

在134-136上分別檢查error發現：

 

可見134從10:49:48開始報error，135從11:00:38開始報error，136從11:00:03開始報error，而且他們的檢查間隔不一樣，134是5分鐘，135和136都是1分鐘，可見134上的分區目錄是在10:49:48以前被刪除，135是在11:00:38以前被刪除，136是在11:00:03以前被刪除；

 

1.4 爲何kafka進程退出時間不一樣

Kafka每一個partition都有一個leader，只有leader會對message作append，因此只有leader纔有可能執行上邊的代碼並退出進程，

 

Leader在接受message時會判斷是否須要roll，當segment大小超出限制或者segment存在時間超出限制時會作roll，當leader執行roll時會報錯退出；

 

因此剛開始是135做爲leader，而後在11號11:02:35時執行roll而後退出：

[2014-10-11 11:02:35,754] FATAL [KafkaApi-135] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis) 

而後134接任leader，而後在13號16:45:41執行roll報錯退出：

[2014-10-13 16:45:41,902] FATAL [KafkaApi-134] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis)

最後只剩下136接任leader，而後在13號19:10:35執行roll報錯退出：

[2014-10-13 16:45:41,902] FATAL [KafkaApi-134] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis)

 

Ps：

從135上的server.log能夠看到8月20號時135做爲leader對ISR進行操做：

 

從134的controller.log中能夠看出，當135掛了以後，134做爲controller接管本來135做爲leader的partition：

 

而134掛了以後，136做爲controller接管本來134做爲leader的partition：

 

三 問題定位

Partition目錄被刪除有幾種可能，一種是操做系統刪除，一種是人爲刪除，一種是kafka本身刪除；

1 操做系統刪除

/tmp 目錄是臨時目錄，操做系統會負責刪除過時文件

 

 

檢查cron日誌發現當天134-136執行tmpwatch的時間是在凌晨3點多，而且只執行了一次，

Oct 11 03:28:02 hz1-13-134 run-parts(/etc/cron.daily)[24593]: starting tmpwatch

Oct 11 03:28:02 hz1-13-134 run-parts(/etc/cron.daily)[24829]: finished tmpwatch

 

Ps：

tmpwatch recursively removes files which haven't been accessed for a given time. Normally, it's used to clean up directories which are used for temporary holding space such as /tmp.

It does not follow symbolic links in the directories it's cleaning (even if a symbolic link is given as its argument), will not switch filesystems, skipslost+found directories owned by the root user, and only removes empty directories, regular files, and symbolic links.

By default, tmpwatch dates files by their atime (access time), not their mtime (modification time). 

 

 

2 人爲刪除

 

Kafka日誌目錄屬於root，而且只有root纔有write權限，因此若是是人爲刪除，只能是root本身刪除，這點不太可能；

 

Ps：人爲刪除partition目錄能夠很容易重現服務器的錯誤；

 

3 kafka本身刪除

查看kafka代碼發現確實有刪除分區方法，位於kafka.cluster.Partition中:

 

LogManager的deleteLog方法以下：

 

Log的delete方法以下：

 

方法中會迭代刪除全部segment，而後清空segments變量，最後刪除分區目錄；

 

這裏有兩點須要考慮：

1. 發生問題是由於kafka認爲partition存在但其實partition已經因爲某種緣由被刪除了，因此纔會報錯，若是是調用以上deleteLog方法刪除partition，說明kafka確定知道分區被刪除（segments變量被清空，roll的時候取segments.lastEntry()確定取不到），這樣不會出問題；
2. 要執行roll，須要當前broker做爲partition的leader，可是以上deleteLog方法是被ReplicaManager.stopReplica調用，若是stopReplica被調用，說明當前broker已經再也不做爲partition的replica，更不可能做爲leader；

以上兩點能夠反證出不是kafka本身刪除partition目錄；

 

四 問題緣由

1 背景

1.1 Kafka的retention檢查會調用kafka.log.Log.deleteOldSegment方法：

 

能夠發現：若是沒有新的message，最後一個segment會一直爲空，這時這個segment不會被刪除，也不會被roll，這個segment會一直原封不動的保留下去；

1）  retention檢查時若是segment爲空，不會執行roll，這時即便partition目錄爲空，也不會報錯，因此不能直接根據報錯的時間推斷出目錄被刪除的時間；

2）  segment長時間爲空有可能會知足tmpwatch的刪除條件，即超過10天沒有訪問，若是segment文件被刪除以後，分區目錄會變成一個空目錄，也會被刪除；

 

1.2 kafka在接受消息時會調用kafka.log.Log.append方法，append方法會調用maybeRoll方法：

 

能夠發現：當segment爲空時，即segment.size=0，即便segment建立時間超過限制，在接收第一條消息的時候也不會進行roll，可是接受完第一條消息以後，segment.size>0，這時若是接收第二條消息就會進行roll；

 

2 模擬重現問題發生過程

1）  kafka服務器配置retention檢查間隔爲1分鐘，啓動kafka服務器；

log.retention.check.interval.ms=60000

2）  10:00:00，建立測試topic：

kafka-topics.sh --zookeeper $zk_server:2187 --create --topic test --partitions 1 --config retention.ms=300000 --config segment.ms=600000

3）  立刻手工將分區目錄test-0刪除；

4）  10:05:00以前至少進行4次retention檢查，因爲內存中的segment變量的最後修改時間尚未超過retention.ms（如下截圖紅框處），因此不會執行roll，不會報錯；

 

5）  10:05:00以後，在進行retention檢查時，segment最後修改時間超過retention.ms，可是因爲segment爲空（如下截圖紅框處），因此不會執行roll，不會報錯；

 

6）  10:10:00以後，segment的建立時間超過segment.ms（如下截圖紅框處）；

 

7）  在10:10:01，發送第一條消息到kafka

kafka-console-producer.sh --broker-list $kafka_server:9081 –topic test

8）  kafka服務器中，因爲此時segment.size=0，因此maybeRoll中下圖紅框中條件不知足，

 

因此不會進行roll，不會報錯；

9）  10:10:01開始，kafka服務器每次retention檢查時，下圖紅框兩個條件都爲true，

知足roll條件，進行roll，而後報錯：

ERROR Uncaught exception in scheduled task 'kafka-log-retention' (kafka.utils.KafkaScheduler)

java.io.FileNotFoundException: /home/wuweiwei/kafkalogs/1/test-0/00000000000000000000.index (No such file or directory)

10）              在發送第二條消息到kafka以前，服務器每隔1分鐘進行一次檢查都會報以上錯誤，因爲進行檢查的是後臺線程，因此kafka進程不會退出；

11）              10:20:00，發送第二條消息到kafka

kafka-console-producer.sh --broker-list $kafka_server:9081 –topic test

12）              kafka服務器中，因爲以前已經收到第一條消息，此時segment.size>0，因此maybeRoll中下圖紅框兩個條件都爲true，

 

知足roll條件，進行roll，而後報錯：

FATAL [KafkaApi-101] Halting due to unrecoverable I/O error while handling produce request:  (kafka.server.KafkaApis)

kafka.common.KafkaStorageException: I/O exception in append to log 'test1-0'

Caused by: java.io.FileNotFoundException: /home/test/kafkalogs/1/test-0/00000000000000000000.index (No such file or directory)

因爲這個報錯是在kafka進程中，因此kafka進程退出；

 

3 實際問題發生過程

3.1 135服務器

1）2014-10-01 03:44以前，kafka對分區cacheClear-onlineConfirm-1執行retention檢查，刪除了舊的segment而且新建了一個空的segment；

2）2014-10-01 03:44到2014-10-11 03:44沒有新的message到達分區cacheClear-onlineConfirm-1，因此這個分區一直只有一個空的segment；

3）2014-10-11 03:44 anacron執行，調用tmpwatch來清理/tmp目錄，分區cacheClear-onlineConfirm-1完整路徑是/tmp/kafka-logs/ cacheClear-onlineConfirm-1，tmpwatch發現分區目錄最後訪問時間是10天前，進行刪除；

4）2014-10-11 03:44到11:00:03之間kafka一直在進行retention檢查，可是因爲內存中的segment變量是空segment，因此沒有執行roll，不會報錯；

5）2014-10-11 10:59:38到11:00:38之間，第一條message到達分區cacheClear-onlineConfirm-1；

6）2014-10-11 11:00:38，kafka作retention檢查，此時segment不爲空，進入roll，而後開始報錯（ERROR）；

7）2014-10-11 11:02:35，第二條message到達分區cacheClear-onlineConfirm-1，這時kafka在append前進行roll，報錯（FATAL），kafka進程退出；

3.2 134服務器

1）135服務器掛了以後，134服務器做爲leader接管分區cacheClear-onlineConfirm-1；

2）2014-10-13 16:45:41，134服務器接收到第一條message，執行roll，報錯（FATAL），進程退出；

3.3 136服務器

1）134服務器掛了以後，136服務器做爲leader接管分區cacheClear-onlineConfirm-1；

2）2014-10-13 19:10:35，136服務器接收到第一條message，執行roll，報錯（FATAL），進程退出；

 

五 問題總結

1）使用默認的kafka日誌目錄/tmp/kafka-logs是一個隱患，能夠先將/tmp/kafka-logs加到/etc/cron.daily/tmpwatch的目錄排除列表裏；

2）另外能夠梳理一下kafka的日誌，尤爲是ERROR和FATAL，作好日誌監控及時發現問題；