kafka0.8.1
一 問題現象
生產環境kafka服務器134、135、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變量，最后刪除分區目錄；
這里有兩點需要考慮：
- 發生問題是因為kafka認為partition存在但其實partition已經由於某種原因被刪除了，所以才會報錯，如果是調用以上deleteLog方法刪除partition，說明kafka肯定知道分區被刪除（segments變量被清空，roll的時候取segments.lastEntry()肯定取不到），這樣不會出問題；
- 要執行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，做好日志監控及時發現問題；