kafka-broker几乎每周六下午都会触发controller change

偉 发表于: 2022-02-07   最后更新时间: 2022-02-07 16:59:17   964 游览

1、kafka是由5个节点组成的集群，版本为2.12，zk是3节点组成的集群，版本为3.4.16；
2、kafka集群每周六下午均会出现波动，导致部分topic无法正常使用；
3、kafka brokerid分别是1-5，出现问题的是4和5节点。

#controller日志
apple@appledeMacBook-Pro kafka-2 % grep 'Newly added brokers' controller.log* 
controller.log.2022-01-08-13:2022-01-08 13:41:08.228|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 5, bounced brokers: , all live brokers: 1,2,3,4|(kafka.controller.KafkaController)
controller.log.2022-01-08-13:2022-01-08 13:41:09.064|INFO|[Controller id=2] Newly added brokers: 5, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-15-13:2022-01-15 13:49:17.824|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 4, bounced brokers: , all live brokers: 1,2,3,5|(kafka.controller.KafkaController)
controller.log.2022-01-15-13:2022-01-15 13:49:25.255|INFO|[Controller id=2] Newly added brokers: 4, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-22-13:2022-01-22 13:42:11.390|INFO|[Controller id=2] Newly added brokers: 4, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-11:2022-01-29 11:45:23.744|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 5, bounced brokers: , all live brokers: 1,2,3,4|(kafka.controller.KafkaController)
controller.log.2022-01-29-11:2022-01-29 11:45:24.751|INFO|[Controller id=2] Newly added brokers: 5, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-12:2022-01-29 12:09:23.720|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 4, bounced brokers: , all live brokers: 1,2,3,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-12:2022-01-29 12:09:24.248|INFO|[Controller id=2] Newly added brokers: 4, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-12:2022-01-29 12:44:31.720|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 4, bounced brokers: , all live brokers: 1,2,3,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-12:2022-01-29 12:45:15.981|INFO|[Controller id=2] Newly added brokers: 4, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-13:2022-01-29 13:21:55.719|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 5, bounced brokers: , all live brokers: 1,2,3,4|(kafka.controller.KafkaController)
controller.log.2022-01-29-13:2022-01-29 13:21:57.086|INFO|[Controller id=2] Newly added brokers: 5, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-16:2022-01-29 16:07:51.720|INFO|[Controller id=2] Newly added brokers: , deleted brokers: 4, bounced brokers: , all live brokers: 1,2,3,5|(kafka.controller.KafkaController)
controller.log.2022-01-29-16:2022-01-29 16:07:53.227|INFO|[Controller id=2] Newly added brokers: 4, deleted brokers: , bounced brokers: , all live brokers: 1,2,3,4,5|(kafka.controller.KafkaController)
#controller.log中的日志
2022-01-29 12:09:24.175|DEBUG|[Controller id=4] Resigning|(kafka.controller.KafkaController)
2022-01-29 12:09:24.176|DEBUG|[Controller id=4] Unregister BrokerModifications handler for Set()|(kafka.controller.KafkaController)
2022-01-29 12:09:24.185|INFO|[PartitionStateMachine controllerId=4] Stopped partition state machine|(kafka.controller.PartitionStateMachine)
2022-01-29 12:09:24.185|INFO|[ReplicaStateMachine controllerId=4] Stopped replica state machine|(kafka.controller.ReplicaStateMachine)
2022-01-29 12:09:24.185|INFO|[Controller id=4] Resigned|(kafka.controller.KafkaController)
2022-01-29 12:09:24.262|DEBUG|[Controller id=4] Broker 2 has been elected as the controller, so stopping the election process.|(kafka.controller.KafkaController)
2022-01-29 12:45:15.953|DEBUG|[Controller id=4] Resigning|(kafka.controller.KafkaController)
2022-01-29 12:45:15.953|DEBUG|[Controller id=4] Unregister BrokerModifications handler for Set()|(kafka.controller.KafkaController)
2022-01-29 12:45:15.953|INFO|[PartitionStateMachine controllerId=4] Stopped partition state machine|(kafka.controller.PartitionStateMachine)
2022-01-29 12:45:15.953|INFO|[ReplicaStateMachine controllerId=4] Stopped replica state machine|(kafka.controller.ReplicaStateMachine)
2022-01-29 12:45:15.953|INFO|[Controller id=4] Resigned|(kafka.controller.KafkaController)
2022-01-29 12:45:15.980|DEBUG|[Controller id=4] Broker 2 has been elected as the controller, so stopping the election process.|(kafka.controller.KafkaController)
#kafkaServer.out提炼的日志
2022-01-15 13:50:22.871|WARN|[LeaderEpochCache PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7] New epoch entry EpochEntry(epoch=4, startOffset=0) caused truncation of conflicting entries ListBuffer(EpochEntry(epoch=2, startOffset=0)). Cache now contains 1 entries.|(kafka.server.epoch.LeaderEpochFileCache)
2022-01-22 13:42:12.795|WARN|[LeaderEpochCache PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7] New epoch entry EpochEntry(epoch=6, startOffset=0) caused truncation of conflicting entries ListBuffer(EpochEntry(epoch=4, startOffset=0)). Cache now contains 1 entries.|(kafka.server.epoch.LeaderEpochFileCache)
2022-01-29 12:12:26.212|WARN|[LeaderEpochCache PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7] New epoch entry EpochEntry(epoch=8, startOffset=0) caused truncation of conflicting entries ListBuffer(EpochEntry(epoch=6, startOffset=0)). Cache now contains 1 entries.|(kafka.server.epoch.LeaderEpochFileCache)
2022-01-29 12:47:26.335|WARN|[LeaderEpochCache PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7] New epoch entry EpochEntry(epoch=10, startOffset=0) caused truncation of conflicting entries ListBuffer(EpochEntry(epoch=8, startOffset=0)). Cache now contains 1 entries.|(kafka.server.epoch.LeaderEpochFileCache)
#state-change.log中提炼的日志
2022-01-29 12:09:24.524|TRACE|[Broker id=4] Cached leader info PartitionState(controllerEpoch=8, leader=1, leaderEpoch=7, isr=[2, 1], zkVersion=11, replicas=[4, 1, 2], offlineReplicas=[]) for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 in response to UpdateMetadata request sent by controller 2 epoch 8 with correlation id 0|(state.change.logger)
2022-01-29 12:09:24.563|TRACE|[Broker id=4] Received LeaderAndIsr request PartitionState(controllerEpoch=8, leader=1, leaderEpoch=7, isr=2,1, zkVersion=11, replicas=4,1,2, isNew=false) correlation id 1 from controller 2 epoch 8 for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7|(state.change.logger)
2022-01-29 12:09:24.569|TRACE|[Broker id=4] Handling LeaderAndIsr request correlationId 1 from controller 2 epoch 8 starting the become-follower transition for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 with leader 1|(state.change.logger)
2022-01-29 12:09:26.720|TRACE|[Broker id=4] Cached leader info PartitionState(controllerEpoch=8, leader=1, leaderEpoch=7, isr=[2, 1], zkVersion=11, replicas=[4, 1, 2], offlineReplicas=[]) for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 in response to UpdateMetadata request sent by controller 2 epoch 8 with correlation id 2|(state.change.logger)
2022-01-29 12:09:32.256|TRACE|[Broker id=4] Cached leader info PartitionState(controllerEpoch=8, leader=1, leaderEpoch=7, isr=[2, 1, 4], zkVersion=12, replicas=[4, 1, 2], offlineReplicas=[]) for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 in response to UpdateMetadata request sent by controller 2 epoch 8 with correlation id 9|(state.change.logger)
2022-01-29 12:12:26.247|TRACE|[Broker id=4] Cached leader info PartitionState(controllerEpoch=8, leader=4, leaderEpoch=8, isr=[2, 1, 4], zkVersion=13, replicas=[4, 1, 2], offlineReplicas=[]) for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 in response to UpdateMetadata request sent by controller 2 epoch 8 with correlation id 14|(state.change.logger)
2022-01-29 12:45:16.010|TRACE|[Broker id=4] Cached leader info PartitionState(controllerEpoch=8, leader=1, leaderEpoch=9, isr=[2, 1], zkVersion=14, replicas=[4, 1, 2], offlineReplicas=[]) for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 in response to UpdateMetadata request sent by controller 2 epoch 8 with correlation id 0|(state.change.logger)
2022-01-29 12:45:39.671|TRACE|[Broker id=4] Cached leader info PartitionState(controllerEpoch=8, leader=1, leaderEpoch=9, isr=[2, 1, 4], zkVersion=15, replicas=[4, 1, 2], offlineReplicas=[]) for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 in response to UpdateMetadata request sent by controller 2 epoch 8 with correlation id 8|(state.change.logger)
2022-01-29 12:47:26.246|TRACE|[Broker id=4] Received LeaderAndIsr request PartitionState(controllerEpoch=8, leader=4, leaderEpoch=10, isr=2,1,4, zkVersion=16, replicas=4,1,2, isNew=false) correlation id 9 from controller 2 epoch 8 for partition PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7|(state.change.logger)

判断：
1、可以看到，从kafkaServer.out中日志挑选的PAAS_DOEM_PROD_INCIDENTASSIGNBUCKET_P-7 topic，大概率在执行leader重选举后的元数据加载或者同步；
2、state-change中的这个topic，在对应时间点感觉是因为broker4的问题（故障或者超过replica.lag.time.max.ms）剔除了isr列表，导致对应的topic 进行了leader重选举；

疑问：
1、目前没有解决这个每周六触发报错的问题，怀疑是gc的问题导致，但是通过查看gc日志，没有发现一次Full GC和较长时间的MajorGC，对应时间点内的gc正常；
2、通过查看监控，发现对应时间点内的服务器运行正常，无业务压力激增的情况；
3、有没有什么思路排查对应上述报错？

  • 看你的日志，还有个空broker，deleted brokers: ，是不是之前的脏数据。另外，你编辑一下问题，补充一下kafka集群信息，使用describe命令。半兽人 2年前 回复
    @半兽人 kafka brokerid分别是1-5，出现问题的是4和5节点。当前无法连接内网获取更多信息，理论上是不存在脏数据的情况。偉 回复
    @偉 那等你能登录内网吧，describe集群情况更直观一点，日志info和warn，理论上是可以忽略的。半兽人 回复
添加评论
你的答案

查看kafka相关的其他问题或提一个您自己的问题。
提问

找不到想要的答案？提一个您自己的问题。