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进程即可。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,590评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 86,808评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,151评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,779评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,773评论 5 367
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,656评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,022评论 3 398
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,678评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 41,038评论 1 299
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,659评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,756评论 1 330
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,411评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,005评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,973评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,053评论 2 350
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,495评论 2 343

推荐阅读更多精彩内容

  • 姓名:周小蓬 16019110037 转载自:http://blog.csdn.net/YChenFeng/art...
    aeytifiw阅读 34,701评论 13 425
  • Kafka入门经典教程-Kafka-about云开发 http://www.aboutyun.com/threa...
    葡萄喃喃呓语阅读 10,804评论 4 54
  • 可怕的写作瓶颈期来了! 记得刚开始决定踏足写作(写诗填词)行列时,每天文思如泉涌,好像如果不把它写出来,脑子就会被...
    烟火里的诗和远方阅读 464评论 2 2
  • 艾艾贴为什么这么火?揭秘红遍朋友圈的艾艾贴 2017-11-04 阿商 爱贴艾艾贴 翻开朋友圈,总有一个甚至十几...
    啊商阅读 327评论 0 1
  • 呃。。今天呢。算了吧,毕竟是安全回来了,虽然这一路走的是真累,真曲折,但是也真难忘了。 一早跟司机联系,被告知说车...
    绪红阅读 174评论 0 0