search

spring-projects / spring-kafka

Provides Familiar Spring Abstractions for Apache Kafka
https://projects.spring.io/spring-kafka
Apache License 2.0
2.19k stars 1.56k forks source link

Failed to start bean 'org.springframework.kafka.config.internalKafkaListenerEndpointRegistry'; nested exception is org.apache.kafka.common.errors.TimeoutException: Timeout expired while fetching topic metadata #876

Closed jinqinghua closed 5 years ago

jinqinghua commented 5 years ago

Bug report Spring boot 2.1.0.RELEASE(spring kafka 2.2.0), and a kafka cluster with 3 patitions use git checkout https://github.com/spring-projects/spring-kafka/tree/master/samples/sample-02 import to IDEA Copy MultiMethods.java to MultiMethods00.java, MultiMethods01.java.... MultiMethods11.java rename the filename to MultiMethodsXX.java rename @KafkaListener(id = "multiGroup" to @KafkaListener(id = "multiGroupXX" XX is from 00 to 11

@Component
@KafkaListener(id = "multiGroup00", topics = { "foos", "bars" })
public class MultiMethods00 {

    @KafkaHandler
    public void foo(Foo2 foo) {
        System.out.println("Received: " + foo);
    }

    @KafkaHandler
    public void bar(Bar2 bar) {
        System.out.println("Received: " + bar);
    }

    @KafkaHandler(isDefault = true)
    public void unknown(Object object) {
        System.out.println("Received unknown: " + object);
    }

Then start the application, following are error details:

2018-11-15 20:25:10.004 TRACE 3521 --- [           main] o.s.c.io.support.SpringFactoriesLoader   : Loaded [org.springframework.boot.diagnostics.FailureAnalysisReporter] names: [org.springframework.boot.diagnostics.LoggingFailureAnalysisReporter]
2018-11-15 20:25:10.005 ERROR 3521 --- [           main] o.s.boot.SpringApplication               : Application run failed

org.springframework.context.ApplicationContextException: Failed to start bean 'org.springframework.kafka.config.internalKafkaListenerEndpointRegistry'; nested exception is org.apache.kafka.common.errors.TimeoutException: Timeout expired while fetching topic metadata
    at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:185) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.context.support.DefaultLifecycleProcessor.access$200(DefaultLifecycleProcessor.java:53) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.start(DefaultLifecycleProcessor.java:360) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.context.support.DefaultLifecycleProcessor.startBeans(DefaultLifecycleProcessor.java:158) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.context.support.DefaultLifecycleProcessor.onRefresh(DefaultLifecycleProcessor.java:122) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:879) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.finishRefresh(ServletWebServerApplicationContext.java:161) ~[spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:549) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
    at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:140) ~[spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:775) [spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:397) [spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:316) [spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1260) [spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1248) [spring-boot-2.1.0.RELEASE.jar:2.1.0.RELEASE]
    at com.example.Application.main(Application.java:45) [classes/:na]
Caused by: org.apache.kafka.common.errors.TimeoutException: Timeout expired while fetching topic metadata

And we found there are at most 4 ListenerConsumers (if downgrade spring boot to 2.0.5, there is at most 9 ListenerConsumers, and groupId is random

2018-11-15 20:24:09.957  INFO 3521 --- [           main] o.a.kafka.common.utils.AppInfoParser     : Kafka version : 2.0.0
2018-11-15 20:24:09.957  INFO 3521 --- [           main] o.a.kafka.common.utils.AppInfoParser     : Kafka commitId : 3402a8361b734732
2018-11-15 20:24:10.294  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : [Consumer clientId=consumer-6, groupId=multiGroup04] Revoking previously assigned partitions []
2018-11-15 20:24:10.294  INFO 3521 --- [tiGroup04-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions revoked: []
2018-11-15 20:24:10.294  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : [Consumer clientId=consumer-6, groupId=multiGroup04] (Re-)joining group
2018-11-15 20:24:12.502 DEBUG 3521 --- [tiGroup02-0-C-1] essageListenerContainer$ListenerConsumer : Received: 0 records
2018-11-15 20:24:12.542 DEBUG 3521 --- [tiGroup03-0-C-1] essageListenerContainer$ListenerConsumer : Received: 0 records
2018-11-15 20:24:12.556  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : [Consumer clientId=consumer-2, groupId=multiGroup02] Successfully joined group with generation 1
2018-11-15 20:24:12.557  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : [Consumer clientId=consumer-2, groupId=multiGroup02] Setting newly assigned partitions [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:12.616  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-2, groupId=multiGroup02] Resetting offset for partition foos-2 to offset 1.
2018-11-15 20:24:12.616  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-2, groupId=multiGroup02] Resetting offset for partition bars-0 to offset 0.
2018-11-15 20:24:12.622  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-2, groupId=multiGroup02] Resetting offset for partition bars-2 to offset 0.
2018-11-15 20:24:12.622  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-2, groupId=multiGroup02] Resetting offset for partition foos-1 to offset 1.
2018-11-15 20:24:12.625  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-2, groupId=multiGroup02] Resetting offset for partition bars-1 to offset 0.
2018-11-15 20:24:12.625  INFO 3521 --- [tiGroup02-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-2, groupId=multiGroup02] Resetting offset for partition foos-0 to offset 4.
2018-11-15 20:24:12.625 DEBUG 3521 --- [tiGroup02-0-C-1] essageListenerContainer$ListenerConsumer : Committing on assignment: {bars-2=OffsetAndMetadata{offset=0, metadata=''}, foos-2=OffsetAndMetadata{offset=1, metadata=''}, foos-1=OffsetAndMetadata{offset=1, metadata=''}, bars-1=OffsetAndMetadata{offset=0, metadata=''}, foos-0=OffsetAndMetadata{offset=4, metadata=''}, bars-0=OffsetAndMetadata{offset=0, metadata=''}}
2018-11-15 20:24:12.653  INFO 3521 --- [tiGroup02-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions assigned: [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:12.852 DEBUG 3521 --- [tiGroup04-0-C-1] essageListenerContainer$ListenerConsumer : Received: 0 records
2018-11-15 20:24:12.914 DEBUG 3521 --- [tiGroup05-0-C-1] essageListenerContainer$ListenerConsumer : Received: 0 records
2018-11-15 20:24:12.961 DEBUG 3521 --- [tiGroup06-0-C-1] essageListenerContainer$ListenerConsumer : Received: 0 records
2018-11-15 20:24:12.978  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : [Consumer clientId=consumer-8, groupId=multiGroup05] Successfully joined group with generation 1
2018-11-15 20:24:12.978  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : [Consumer clientId=consumer-8, groupId=multiGroup05] Setting newly assigned partitions [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:12.979  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : [Consumer clientId=consumer-4, groupId=multiGroup03] Successfully joined group with generation 1
2018-11-15 20:24:12.981  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : [Consumer clientId=consumer-4, groupId=multiGroup03] Setting newly assigned partitions [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:13.006  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-4, groupId=multiGroup03] Resetting offset for partition foos-2 to offset 1.
2018-11-15 20:24:13.006  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-8, groupId=multiGroup05] Resetting offset for partition foos-2 to offset 1.
2018-11-15 20:24:13.006  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-4, groupId=multiGroup03] Resetting offset for partition bars-0 to offset 0.
2018-11-15 20:24:13.006  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-8, groupId=multiGroup05] Resetting offset for partition bars-0 to offset 0.
2018-11-15 20:24:13.006  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-4, groupId=multiGroup03] Resetting offset for partition bars-2 to offset 0.
2018-11-15 20:24:13.006  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-4, groupId=multiGroup03] Resetting offset for partition foos-1 to offset 1.
2018-11-15 20:24:13.008  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-8, groupId=multiGroup05] Resetting offset for partition bars-2 to offset 0.
2018-11-15 20:24:13.008  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-8, groupId=multiGroup05] Resetting offset for partition foos-1 to offset 1.
2018-11-15 20:24:13.009  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-4, groupId=multiGroup03] Resetting offset for partition bars-1 to offset 0.
2018-11-15 20:24:13.009  INFO 3521 --- [tiGroup03-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-4, groupId=multiGroup03] Resetting offset for partition foos-0 to offset 4.
2018-11-15 20:24:13.009 DEBUG 3521 --- [tiGroup03-0-C-1] essageListenerContainer$ListenerConsumer : Committing on assignment: {bars-2=OffsetAndMetadata{offset=0, metadata=''}, foos-2=OffsetAndMetadata{offset=1, metadata=''}, foos-1=OffsetAndMetadata{offset=1, metadata=''}, bars-1=OffsetAndMetadata{offset=0, metadata=''}, foos-0=OffsetAndMetadata{offset=4, metadata=''}, bars-0=OffsetAndMetadata{offset=0, metadata=''}}
2018-11-15 20:24:13.009  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-8, groupId=multiGroup05] Resetting offset for partition bars-1 to offset 0.
2018-11-15 20:24:13.009  INFO 3521 --- [tiGroup05-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-8, groupId=multiGroup05] Resetting offset for partition foos-0 to offset 4.
2018-11-15 20:24:13.009 DEBUG 3521 --- [tiGroup05-0-C-1] essageListenerContainer$ListenerConsumer : Committing on assignment: {bars-2=OffsetAndMetadata{offset=0, metadata=''}, foos-2=OffsetAndMetadata{offset=1, metadata=''}, foos-1=OffsetAndMetadata{offset=1, metadata=''}, bars-1=OffsetAndMetadata{offset=0, metadata=''}, foos-0=OffsetAndMetadata{offset=4, metadata=''}, bars-0=OffsetAndMetadata{offset=0, metadata=''}}
2018-11-15 20:24:13.025  INFO 3521 --- [tiGroup05-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions assigned: [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:13.026  INFO 3521 --- [tiGroup03-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions assigned: [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:13.556  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : [Consumer clientId=consumer-6, groupId=multiGroup04] Successfully joined group with generation 1
2018-11-15 20:24:13.557  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : [Consumer clientId=consumer-6, groupId=multiGroup04] Setting newly assigned partitions [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
2018-11-15 20:24:13.682  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-6, groupId=multiGroup04] Resetting offset for partition bars-2 to offset 0.
2018-11-15 20:24:13.682  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-6, groupId=multiGroup04] Resetting offset for partition foos-1 to offset 1.
2018-11-15 20:24:13.683  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-6, groupId=multiGroup04] Resetting offset for partition foos-2 to offset 1.
2018-11-15 20:24:13.683  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-6, groupId=multiGroup04] Resetting offset for partition bars-0 to offset 0.
2018-11-15 20:24:13.693  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-6, groupId=multiGroup04] Resetting offset for partition bars-1 to offset 0.
2018-11-15 20:24:13.693  INFO 3521 --- [tiGroup04-0-C-1] o.a.k.c.consumer.internals.Fetcher       : [Consumer clientId=consumer-6, groupId=multiGroup04] Resetting offset for partition foos-0 to offset 4.
2018-11-15 20:24:13.693 DEBUG 3521 --- [tiGroup04-0-C-1] essageListenerContainer$ListenerConsumer : Committing on assignment: {bars-2=OffsetAndMetadata{offset=0, metadata=''}, foos-2=OffsetAndMetadata{offset=1, metadata=''}, foos-1=OffsetAndMetadata{offset=1, metadata=''}, bars-1=OffsetAndMetadata{offset=0, metadata=''}, foos-0=OffsetAndMetadata{offset=4, metadata=''}, bars-0=OffsetAndMetadata{offset=0, metadata=''}}
2018-11-15 20:24:13.711  INFO 3521 --- [tiGroup04-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions assigned: [bars-2, foos-2, foos-1, bars-1, foos-0, bars-0]
garyrussell commented 5 years ago

Please push the modified project to github someplace so we can take a look.

jinqinghua commented 5 years ago

@garyrussell sorry, we use virtual ip in dev env. and there's some issue with it, check with IT, and use brokers list instead of vip address, it works. Could you please help to close this issue, thanks.

nimeshsoni091 commented 4 years ago

I got the same issue, Can you please suggest me what exactly you did?

sidarunoyo commented 1 year ago

Any solution for this yet??

abdoochabrik commented 1 year ago

guys try to hardcode consumerConfig, it works fine props.put(consumerconfig.bootstrap_servers_config, "localhost:9092");