Reactor Kafka无显式错误时消费停滞问题排查求助

现象描述 #

• 间歇性出现部分应用节点停止消费Kafka消息，引发部分主题分区消费延迟，最终所有节点均停止消费，全部分区产生延迟
• Kafka broker验证显示消费者线程状态正常
• 重启任意节点后，其他停滞节点恢复消费，此时日志出现「Attempt to heartbeat failed since the group is rebalancing」，触发消费者组重平衡

推测方向 #

短暂网络异常导致消费者进入无限暂停消费但心跳正常的状态，本地无法复现该场景

关键日志信息 #

消费停滞前的异常日志 #

2022-09-23|05:41:55.414 DEBUG r.k.r.internals.ConsumerEventLoop - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= Resumed
2022-09-23|05:41:56.835 DEBUG r.k.r.internals.ConsumerEventLoop - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= Emitting 1 records, requested now 1
2022-09-23|05:41:56.835 DEBUG r.k.r.internals.ConsumerEventLoop - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= onRequest.toAdd 1, paused false
2022-09-23|05:41:56.835 DEBUG r.k.r.internals.ConsumerEventLoop - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= Paused - too many deferred commits
2022-09-23|05:41:56.835 DEBUG r.k.r.internals.ConsumerEventLoop - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= Consumer woken
2022-09-23|05:42:13.082 INFO o.a.k.clients.FetchSessionHandler - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= [Consumer clientId=consumer-runtime-processor-1, groupId=runtime-processor-prd] Error sending fetch request (sessionId=214139410, epoch=1) to node 208:
org.apache.kafka.common.errors.DisconnectException: null
2022-09-23|05:42:18.097 INFO o.a.k.clients.FetchSessionHandler - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= [Consumer clientId=consumer-runtime-processor-1, groupId=runtime-processor-prd] Error sending fetch request (sessionId=973107219, epoch=1) to node 308:
org.apache.kafka.common.errors.DisconnectException: null
2022-09-23|05:42:21.106 INFO o.a.k.clients.FetchSessionHandler - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= [Consumer clientId=consumer-runtime-processor-1, groupId=runtime-processor-prd] Error sending fetch request (sessionId=1457615640, epoch=INITIAL) to node 107:
org.apache.kafka.common.errors.DisconnectException: null

重启节点后恢复时的日志 #

2022-09-23|07:39:20.019 INFO o.a.k.c.c.i.AbstractCoordinator - thread=reactive-kafka-runtime-processor-1 correlation_id= tid= provider_id= entity_type= userid= realmid= [Consumer clientId=consumer-runtime-processor-1, groupId=runtime-processor-prd] Attempt to heartbeat failed since group is rebalancing

环境与配置信息 #

Reactor Kafka版本 #

1.3.11

消费者代码实现 #

public Flux<Message<String>> consumeRecords() {
    return reactiveKafkaConsumerTemplate
      .receiveAutoAck()
      .doOnNext(t -> log.info("On Next call from customer template"))
      .doOnComplete(() -> log.info("On Complete call from customer template"))
      .publishOn(Schedulers.boundedElastic())
      // rate limit flow to start processing n events every t time duration where:
      //   t - is given by kafkaConsumerRateLimitConfig.getDurationInMillis()
      //   n - is given by kafkaConsumerRateLimitConfig.getConcurrency()
      .flatMap(x -> Mono.just(x)
          .delayElement(Duration.ofMillis(1000)),
        1
      )
      .flatMap(consumerRecord ->
        Mono.just(consumerRecord)
          .map(kafkaRecordMapper::mapConsumerRecordToMessage)
          // handle error
          .doOnError(t -> {
            log.error("AutoAck Exception occurred when consuming kafka consumer record", t);
          })
      )
      .doOnError(throwable -> Mono.just(throwable)
        .doOnNext(t -> log.error("AutoAck Kafka consumer template failed -", t))
        .subscribe()
      )
      .retryWhen(Retry.indefinitely())
      .repeat();
  }

KafkaReceiver显式配置属性 #

auto.commit.interval.ms = 1000
auto.offset.reset = earliest
heartbeat.interval.ms = 1000
security.protocol = SSL

maxDeferredCommits = 200

KafkaReceiver默认属性（Splunk打印） #

allow.auto.create.topics = true
    auto.commit.interval.ms = 1000
    auto.offset.reset = earliest
    check.crcs = true
    client.dns.lookup = use_all_dns_ips
    client.id = consumer-consumer-kafkaretry-2
    client.rack = 
    connections.max.idle.ms = 540000
    default.api.timeout.ms = 60000
    enable.auto.commit = false
    exclude.internal.topics = true
    fetch.max.bytes = 52428800
    fetch.max.wait.ms = 500
    fetch.min.bytes = 1
    group.id = consumer-kafkaretry
    group.instance.id = null
    heartbeat.interval.ms = 1000
    interceptor.classes = []
    internal.leave.group.on.close = true
    internal.throw.on.fetch.stable.offset.unsupported = false
    isolation.level = read_uncommitted
    key.deserializer = class org.springframework.kafka.support.serializer.ErrorHandlingDeserializer
    max.partition.fetch.bytes = 1048576
    max.poll.interval.ms = 300000
    max.poll.records = 500
    metadata.max.age.ms = 300000
    metric.reporters = []
    metrics.num.samples = 2
    metrics.recording.level = INFO
    metrics.sample.window.ms = 30000
    partition.assignment.strategy = [class org.apache.kafka.clients.consumer.RangeAssignor]
    receive.buffer.bytes = 65536
    reconnect.backoff.max.ms = 1000
    reconnect.backoff.ms = 50
    request.timeout.ms = 30000
    retry.backoff.ms = 100
    sasl.client.callback.handler.class = null
    sasl.jaas.config = null
    sasl.kerberos.kinit.cmd = /usr/bin/kinit
    sasl.kerberos.min.time.before.relogin = 60000
    sasl.kerberos.service.name = null
    sasl.kerberos.ticket.renew.jitter = 0.05
    sasl.kerberos.ticket.renew.window.factor = 0.8
    sasl.login.callback.handler.class = null
    sasl.login.class = null
    sasl.login.refresh.buffer.seconds = 300
    sasl.login.refresh.min.period.seconds = 60
    sasl.login.refresh.window.factor = 0.8
    sasl.login.refresh.window.jitter = 0.05
    sasl.mechanism = GSSAPI
    security.protocol = SSL
    security.providers = null
    send.buffer.bytes = 131072
    session.timeout.ms = 10000
    ssl.cipher.suites = null
    ssl.enabled.protocols = [TLSv1.2, TLSv1.3]
    ssl.endpoint.identification.algorithm = https
    ssl.engine.factory.class = null
    ssl.key.password = null
    ssl.keymanager.algorithm = SunX509
    ssl.keystore.location = null
    ssl.keystore.password = null
    ssl.keystore.type = JKS
    ssl.protocol = TLSv1.3
    ssl.provider = null
    ssl.secure.random.implementation = null
    ssl.trustmanager.algorithm = PKIX
    ssl.truststore.location = /app/resources/kafkatruststore.jks
    ssl.truststore.password = [hidden]
    ssl.truststore.type = JKS
    value.deserializer = class org.springframework.kafka.support.serializer.ErrorHandlingDeserializer

内容的提问来源于stack exchange，提问作者arunkumar ratheendran