java kafka无法消费,Kafka异常重启后无法消费

事故起因

2018.10.13日Kafka出现了无法启动问题，安稳了一天，结果第二天晚上又出现了新的问题，发现有些程序无法正常消费Kafka了。

这个问题在网上找了一下，发现有类似的经历，都是Kafka进程异常挂掉之后，起来无法消费的问题，但是试了一下，发现每次事故还是都有它的独特之处，所以这里专门记录一下。

调查过程

基本环境信息：

软件版本：使用的Kakfa的版本是1.1.0版本，之前因为从0.8.2升级过一次，所以消息格式仍然是沿用支持0.8.2的消息格式。

集群：6个节点，broker id分别是：0，1，2，3，4，5

节点配置：内存：64G 硬盘：4T * 12

网卡：万兆

其中0，1两个节点的Kafka出现过异常挂掉。

出现问题的时候，也不是所有的程序都无法消费，而是部分节点无法消费了，查了一下机器的负载情况，0号节点负载非常高，达到11了，磁盘利用率非常高，而其他的几个节点的负载都非常低。

这里我们简单重温一下消费的原理：

同一个组的消费者会加入到一起，向Coordinator请求加入消费组，Coordinator会向每个消费者分配消费的分区。

那么Coordinator是怎么确定的呢？一般一个消费者启动后，会随机想一个节点请求去获取它的Coordinator所在节点。

获取Coordinator所在的节点的原理与我们的消费组的消费偏移量信息是存储__consumer_offsets对应的分区上。

所以最终定位到Kafka是如何选择__consumer_offsets这个topic的分区来存储对应的偏移量。

以消费组名为ttt为例来说明：

int hashCode = Math.abs("ttt".hashCode());

int partition = hashCode % 50;

先计算group的hashCode，再除以分区数(50),可以得到partition的值为：44。

再通过kafka-topic.sh命令查看该partition的leader在哪个节点，那么就可以确定tttt这个消费组的Coordinator落在哪个节点了。

在消费过程中，消费不了的原因是说对应的Coordinator无效，日志如下：

[2018-10-14 21:20:28,860] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Discovered group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

[2018-10-14 21:20:28,860] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) is unavailable or invalid, will attempt rediscovery (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

[2018-10-14 21:20:28,962] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Discovered group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

[2018-10-14 21:20:28,962] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] (Re-)joining group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

[2018-10-14 21:20:28,964] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) is unavailable or invalid, will attempt rediscovery (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

[2018-10-14 21:20:29,065] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Discovered group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

[2018-10-14 21:20:29,066] INFO [Consumer clientId=consumer-1, groupId=console-consumer-28334] Group coordinator wxoddc2nn1:9092 (id: 2147483647 rack: null) is unavailable or invalid, will attempt rediscovery (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)

日志中的wx0ddc2nn1主机就是我们的0号节点，客户端无法消费的原因是发现Coordinator在0号节点，但是0号节点认为该Coordinator无效，刚开始怀疑是负载较大，我们查询了一下__consumer_offsets这个topic的leader居然全部是0号节点，而且只有两个副本，另外一个副本在1号节点上。

第一次尝试

把一些分区的leader调整到1号节点，发现也无法正常消费。

基本说明了一个问题，消费问题与负载不相关，但是可能与这两个节点异常启动过有关。

解决问题的过程

对__consumer_offsets进行整体的分区调整，调整为3个分区，并且把leader和副本分区均匀分配在6个节点上，发出了调整指令后，半个小时左右，有部分节点的leader调整到其他节点了。

我们按照前面的消费组所处__consumer_offsets的分区的计算算法，找到合适的group名，譬如：tttt，它的partition为44，发现44这个分区的leader落在了2号节点，然后，我们启动命令行消费者：

hadoop@wxoddc2dn4:~/kafka_2.11-1.1.0$ bin/kafka-console-consumer.sh --zookeeper zk01 --topic test --max-messages 2 --group tttt

{"app":{"businessid":"4","source":"java_sdk_1.3.3","ports":";18901;","ips":";127.0.0.1;","clientname":"guess.mobile_guess","srvid":"86787","time":1539593926175},"@timestamp":"2018-10-15T08:58:46.175Z","docid":"Akh+2+aRqtHXO7e+WQytelELbGNkZuxGVeBXQTxYNi8=WZ28vYfDhbvty","btKey":"Akh+2+aRqtHXO7e+WQytelELbGNkZuxGVeBXQTxYNi8=","model":{"ctx":{"activeThreads":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"queueId":2,"activeTimeWaiting":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeRunnable":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"minThreads":500,"activeBlocked":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeWaiting":{"avg":500.0,"count":1,"max":500,"min":500,"sum":500},"queueMaxSize":100000,"maxThreads":500,"queueCurSize":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"currentThreads":{"avg":500.0,"count":1,"max":500,"min":500,"sum":500},"maxUsedThreads":500},"id":"mainPool","type":1},"businessType":"queueState","batchid":"Dhbvty"}

{"app":{"businessid":"4","source":"java_sdk_1.3.3","ports":";18901;","ips":";127.0.0.1;","clientname":"guess.mobile_guess","srvid":"86787","time":1539593926175},"@timestamp":"2018-10-15T08:58:46.175Z","docid":"/kD1spNQhiu4VwtsuOVyX12y+kG/70S0/AH7ITcRwoQ=WZ28vYfDhbvty","btKey":"/kD1spNQhiu4VwtsuOVyX12y+kG/70S0/AH7ITcRwoQ=","model":{"ctx":{"activeThreads":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"queueId":1,"activeTimeWaiting":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeRunnable":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"minThreads":4,"activeBlocked":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"activeWaiting":{"avg":4.0,"count":1,"max":4,"min":4,"sum":4},"queueMaxSize":1000000,"maxThreads":4,"queueCurSize":{"avg":0.0,"count":1,"max":0,"min":0,"sum":0},"currentThreads":{"avg":4.0,"count":1,"max":4,"min":4,"sum":4},"maxUsedThreads":4},"id":"processor-threadpool","type":1},"businessType":"queueState","batchid":"Dhbvty"}

发现就能够正常消费了，所以怀疑是0，1两个节点的问题，因为这两个节点异常启动过。

等待__consumer_offsets重新调整的过程很长，有一些超级大的分区，我们把一些超过3天以上的数据删除了，加快了一点速度，但是调整完毕后，仍然有一部分分区的leader是在0，1上，使用落在这些分区的消费组消费，仍然不行。

第二轮调整

再次把__consumer_offsets进行了分区调整，把所有的分区都迁移到其他2，3，4，5节点上。

在这次调整后，使用所有的消费组名，都能够消费了。

总结

整个故障的解决时间比较长，而且中间做了各种尝试，所以对部分业务也造成了影响，好在我们kafka集群和数据都是双机房备份的，核心的业务做了切换。

现在Kafka的复杂性越来越高，不在代码层面去研究，碰到问题都很难解决，像这次的问题，我们虽然没有在去基于代码层面进行研究，但是最终结果只是暂时让我们的集群恢复正常了。而0，1号节点无法消费的原因，我们还没有找到。

后续会继续对这个问题进行更进一步的调研，如果有更进一步的结论，会继续完善该文档。

后记

经过了上次的调整以后，0和1这两个节点已经不再存储任何__consumer_offsets这个topic的分区了，我尝试把一个分区重新放回0和1，并且让它们做leader，结果发现也能消费了。

从这个现象看起来，初步怀疑是节点的异常重启造成了__consumer_offsets的部分分区数据异常，但是经过数据的迁移之后，由于0和1已经没有相关的数据，再次迁移回来，数据是全新的，所以不再有异常了，总得来说，还是该版本的kafka有隐藏的bug。

【20181022】

最近分析发现，Kafka进程启动后一直在加载对应的__consumer_offsets分区的数据，由于对应的logclean逻辑因为某个原因出问题了，造成对应的__consumer_offsets的清理一直没有进行，积累了大量的历史数据，最多的分区达到了2T，系统一直加载__consumer_offsets，所以对应的__consumer_offsets无法正常工作，从而提示Coordinator invalid。

解决方案很简单，删除__consumer_offsets的历史文件，再启动Kafka进程即可。