【原创】大叔问题定位分享（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，作好日志监控及时发现问题；