Spring kafka NonResponsiveConsumerEvent even trigger time when broker is down

Viewed 1695

I have consumer running in my machine. When I stop Kafka broker I am getting warning in my application as

"org.apache.kafka.clients.NetworkClient: [Consumer clientId=Data-client-0, groupId=Consumer_group] Connection to node 0 could not be established. Broker may not be available."

But the NonResponsiveConsumerEvent is getting triggered after 2-4 mins range. As per this documentation https://github.com/spring-projects/spring-kafka/blob/master/src/reference/asciidoc/kafka.adoc#idle-containers Its says " the container publishes a NonResponsiveConsumerEvent if a poll does not return within 3x the pollInterval property." My poll interval is 5 mins and I have set noPollThreshold to 1L. It should trigger this event after 5 mins but I am getting this event in 2-4 mins.

I tried by change my max.poll.interval.ms to 30secs - for this I got event triggerred sometimes when application starts then the next event triggers after 2-4 mins.

My consumerconfig

2019-10-15 13:12:54,403 INFO  [main]  org.apache.kafka.common.config.AbstractConfig: ConsumerConfig values: 
    auto.commit.interval.ms = 5000
    auto.offset.reset = latest
    bootstrap.servers = [localhost:9092]
    check.crcs = true
    client.id = Data-client-0
    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_group
    heartbeat.interval.ms = 3000
    interceptor.classes = []
    internal.leave.group.on.close = true
    isolation.level = read_uncommitted
    key.deserializer = class org.apache.kafka.common.serialization.ByteArrayDeserializer
    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 = PLAINTEXT
    send.buffer.bytes = 131072
    session.timeout.ms = 10000
    ssl.cipher.suites = null
    ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
    ssl.endpoint.identification.algorithm = https
    ssl.key.password = null
    ssl.keymanager.algorithm = SunX509
    ssl.keystore.location = null
    ssl.keystore.password = null
    ssl.keystore.type = JKS
    ssl.protocol = TLS
    ssl.provider = null
    ssl.secure.random.implementation = null
    ssl.trustmanager.algorithm = PKIX
    ssl.truststore.location = null
    ssl.truststore.password = null
    ssl.truststore.type = JKS
    value.deserializer = class org.apache.kafka.common.serialization.ByteArrayDeserializer

2019-10-15 13:12:54,461 INFO  [main]  org.apache.kafka.common.utils.AppInfoParser$AppInfo: Kafka version : 2.0.1
2019-10-15 13:12:54,462 INFO  [main]  org.apache.kafka.common.utils.AppInfoParser$AppInfo: Kafka commitId : fa14705e51bd2ce5
2019-10-15 13:12:54,466 INFO  [main]  org.springframework.scheduling.concurrent.ExecutorConfigurationSupport: Initializing ExecutorService
2019-10-15 13:12:54,469 INFO  [main]  org.springframework.core.log.LogAccessor: KafkaMessageListenerContainer.ListenerConsumer [containerProperties=ContainerProperties [topics=[row], pollTimeout=5000, groupId=Consumer_group, consumerRebalanceListener=org.springframework.kafka.listener.AbstractMessageListenerContainer$1@41962299, syncCommits=true, ackMode=MANUAL_IMMEDIATE, ackCount=0, ackTime=0, messageListener=org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter@3f910f36, consumerTaskExecutor=org.springframework.core.task.SimpleAsyncTaskExecutor@6421bc7e, shutdownTimeout=10000, ackOnError=false, idleEventInterval=not enabled, monitorInterval=1, noPollThreshold=1.0], listenerType=ACKNOWLEDGING_CONSUMER_AWARE, isConsumerAwareListener=true, isBatchListener=false, autoCommit=false, consumerGroupId=Consumer_group, clientIdSuffix=-0]

My container props

factory.getContainerProperties().setAckMode(AckMode.MANUAL_IMMEDIATE);
        factory.getContainerProperties().setNoPollThreshold(1L);
        factory.getContainerProperties().setMonitorInterval(1);
        factory.getContainerProperties().setLogContainerConfig(true);

I am using spring-kafka 2.3.0.RELEASE spring-boot-starter-parent 2.1.9.RELEASE spring-core 5.2.0.RELEASE

My eventlistener

@EventListener
    public void eventHandler(NonResponsiveConsumerEvent event) {
System.out.println("NonResponsiveConsumerEvent event triggered"+ event.getListenerId());
}
1 Answers

I am surprised you get that event at all because modern clients no longer hang in the poll when the broker is dead; the poll times out, returning no records, so lastPoll is updated before each poll.

There is a typo in the documentation. It should say

"the container publishes a NonResponsiveConsumerEvent if a poll does not return within 3x the pollTimeout property. Note pollTimeout not pollInterval.

With a threshold of 1, it appears you have a pollTimeout set to 2 minutes, which might cause these events to be published. Due to a race condition. The threshold should be > 1 to avoid that race condition.

Actually the setting of the pollTimeout is probably unimportant, just that the threshold being 1 means there is a race on every poll.

Related