Remember Kafka troubleshooting once

Time:2021-8-15

environmental information

CentOS 7.3
Kafka uses the default configuration, starts zookeeper separately, and does not use its own ZK,
Kafka and zookeeper are on the same host, both of which are single nodes

Problem phenomenon

Using Kafka to test that the queue is normal, java code cannot receive queue messages normally

Related code

 pom.xml

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>1.5.6.RELEASE</version>
    <relativePath/> <!-- lookup parent from repository -->
</parent>
    
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
</dependency>
<dependency>
    <groupId>org.apache.kafka</groupId>
    <artifactId>kafka-clients</artifactId>
    <version>0.11.0.0</version>
</dependency>
<dependency>
    <groupId>org.springframework.kafka</groupId>
    <artifactId>spring-kafka</artifactId>
    <version>1.2.2.RELEASE</version>
</dependency>

application.properties

spring.kafka.consumer.group-id=junbaor-test-group
spring.kafka.bootstrap-servers=10.4.82.141:9092

App.java

package com.example.demo;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.kafka.annotation.KafkaListener;

@SpringBootApplication
public class App {

    public static void main(String[] args) {
        SpringApplication.run(App.class, args);
    }

    @KafkaListener(topics = "junbaor-test")
    public void test(String s) {
        System.out.println(s);
    }

}

journal

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.5.6.RELEASE)

2017-09-05 14:56:50.971  INFO 52968 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication on Junbaor-PC with PID 52968 (D:\Project\github\demo\target\classes started by junbaor in D:\Project\github\demo)
2017-09-05 14:56:50.973  INFO 52968 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2017-09-05 14:56:51.023  INFO 52968 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.spring[email protected]6bd61f98: startup date [Tue Sep 05 14:56:51 CST 2017]; root of context hierarchy
2017-09-05 14:56:51.463  INFO 52968 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.kafka.annotation.KafkaBootstrapConfiguration' of type [org.springframework.kafka.annotation.KafkaBootstrapConfiguration$$EnhancerBySpringCGLIB$$a05e7a75] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2017-09-05 14:56:51.714  INFO 52968 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2017-09-05 14:56:51.746  INFO 52968 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 0
2017-09-05 14:56:51.763  INFO 52968 --- [           main] o.a.k.clients.consumer.ConsumerConfig    : ConsumerConfig values: 
    auto.commit.interval.ms = 5000
    auto.offset.reset = latest
    bootstrap.servers = [10.4.82.141:9092]
    check.crcs = true
    client.id = 
    connections.max.idle.ms = 540000
    enable.auto.commit = true
    exclude.internal.topics = true
    fetch.max.bytes = 52428800
    fetch.max.wait.ms = 500
    fetch.min.bytes = 1
    group.id = junbaor-test-group
    heartbeat.interval.ms = 3000
    interceptor.classes = null
    internal.leave.group.on.close = true
    isolation.level = read_uncommitted
    key.deserializer = class org.apache.kafka.common.serialization.StringDeserializer
    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 = 305000
    retry.backoff.ms = 100
    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.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 = null
    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.StringDeserializer

2017-09-05 14:56:51.822  INFO 52968 --- [           main] o.a.kafka.common.utils.AppInfoParser     : Kafka version : 0.11.0.0
2017-09-05 14:56:51.822  INFO 52968 --- [           main] o.a.kafka.common.utils.AppInfoParser     : Kafka commitId : cb8625948210849f
2017-09-05 14:56:59.155  INFO 52968 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 8.466 seconds (JVM running for 10.586)
2017-09-05 14:56:59.259  INFO 52968 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : Discovered coordinator wkfg-1:9092 (id: 2147483647 rack: null) for group junbaor-test-group.
2017-09-05 14:57:06.036  INFO 52968 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : Marking the coordinator wkfg-1:9092 (id: 2147483647 rack: null) dead for group junbaor-test-group

Last line

Marking the coordinator wkfg-1:9092 (id: 2147483647 rack: null) dead for group junbaor-test-group

Marked as dead, the reason why the message cannot be received may be caused by the death of the consumer

Analysis process

This sentence can be analyzed from the logAbstractCoordinatorClass, we find the code to print this line of information

Remember Kafka troubleshooting once

as a result ofthis.coordinator != null, hit the breakpoint to see what the coordinator is

Remember Kafka troubleshooting once

wkfg-1Is the host name of the server where the Kafka instance is located,
9092It’s Kafka’s port. It seems to be Kafka’s connection address
At first glance, I think there is no problem (in fact, that’s the problem)


thatthis.coordinatorWhen was the assignment made? Trace up to find the last called method
Click to call the previous method in the stack

Remember Kafka troubleshooting once

Jumped here

Remember Kafka troubleshooting once

sincecoordinatorIf it is not empty, the code block must be entered becauseclient.connectionFailed(coordinator)
Semantic analysis is because of client connectioncoordinatorfail
Whatever the cause, click in first

Remember Kafka troubleshooting once

See that the formal parameter name is node, and this object should be Kafka’s node information,
Click open to view the specific properties of the object

Remember Kafka troubleshooting once

Problem location

Look at the picture abovehostProperties,hostIt usually means host
In the LAN, it is inaccessible through the host name.
Generally, the host name and IP are mapped through IP, domain name, or modifying the hosts file
After positioning, we try to solve the problem in the simplest way

Try to solve

The simplest way to implement the above schemes is to modify the local hosts file

The windows system hosts file is located inC:\Windows\System32\drivers\etc\hosts
Open with administrator privileges and append the corresponding relationship between IP and host name

10.4.82.141       wkfg-1

Start the project again, and the log is as follows

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.5.6.RELEASE)

2017-09-05 16:06:45.862  INFO 53000 --- [           main] com.example.demo.App                     : Starting App on Junbaor-PC with PID 53000 (D:\Project\github\demo\target\classes started by junbaor in D:\Project\github\demo)
2017-09-05 16:06:45.867  INFO 53000 --- [           main] com.example.demo.App                     : No active profile set, falling back to default profiles: default
2017-09-05 16:06:45.963  INFO 53000 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.spring[email protected]52b1beb6: startup date [Tue Sep 05 16:06:45 CST 2017]; root of context hierarchy
2017-09-05 16:06:46.838  INFO 53000 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.kafka.annotation.KafkaBootstrapConfiguration' of type [org.springframework.kafka.annotation.KafkaBootstrapConfiguration$$EnhancerBySpringCGLIB$$2436eacd] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2017-09-05 16:06:47.184  INFO 53000 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2017-09-05 16:06:47.248  INFO 53000 --- [           main] o.s.c.support.DefaultLifecycleProcessor  : Starting beans in phase 0
2017-09-05 16:06:47.308  INFO 53000 --- [           main] o.a.k.clients.consumer.ConsumerConfig    : ConsumerConfig values: 
    auto.commit.interval.ms = 5000
    auto.offset.reset = latest
    bootstrap.servers = [10.4.82.141:9092]
    check.crcs = true
    client.id = 
    connections.max.idle.ms = 540000
    enable.auto.commit = true
    exclude.internal.topics = true
    fetch.max.bytes = 52428800
    fetch.max.wait.ms = 500
    fetch.min.bytes = 1
    group.id = junbaor-test-group
    heartbeat.interval.ms = 3000
    interceptor.classes = null
    internal.leave.group.on.close = true
    isolation.level = read_uncommitted
    key.deserializer = class org.apache.kafka.common.serialization.StringDeserializer
    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 = 305000
    retry.backoff.ms = 100
    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.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 = null
    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.StringDeserializer

2017-09-05 16:06:47.412  INFO 53000 --- [           main] o.a.kafka.common.utils.AppInfoParser     : Kafka version : 0.11.0.0
2017-09-05 16:06:47.413  INFO 53000 --- [           main] o.a.kafka.common.utils.AppInfoParser     : Kafka commitId : cb8625948210849f
2017-09-05 16:06:47.432  INFO 53000 --- [           main] com.example.demo.App                     : Started App in 1.927 seconds (JVM running for 2.774)
2017-09-05 16:06:47.519  INFO 53000 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : Discovered coordinator wkfg-1:9092 (id: 2147483647 rack: null) for group junbaor-test-group.
2017-09-05 16:06:47.525  INFO 53000 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : Revoking previously assigned partitions [] for group junbaor-test-group
2017-09-05 16:06:47.525  INFO 53000 --- [ntainer#0-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions revoked:[]
2017-09-05 16:06:47.526  INFO 53000 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : (Re-)joining group junbaor-test-group
2017-09-05 16:06:47.765  INFO 53000 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.AbstractCoordinator  : Successfully joined group junbaor-test-group with generation 1
2017-09-05 16:06:47.766  INFO 53000 --- [ntainer#0-0-C-1] o.a.k.c.c.internals.ConsumerCoordinator  : Setting newly assigned partitions [junbaor-test-0, junbaor-test-1, junbaor-test-2] for group junbaor-test-group
2017-09-05 16:06:47.767  INFO 53000 --- [ntainer#0-0-C-1] o.s.k.l.KafkaMessageListenerContainer    : partitions assigned:[junbaor-test-0, junbaor-test-1, junbaor-test-2]

Log shows that the group has been joined and the partition has been allocated

Use Kafka’s own command to send a message to topic and try to receive it

[[email protected] bin]$ ./kafka-console-producer.sh --topic junbaor-test --broker-list 127.0.0.1:9092
>test
>

Remember Kafka troubleshooting once

So far, the problem has been solved

Scheme summary

The default listening host name may be caused by not setting the listening address for Kafka

Remember Kafka troubleshooting once

A similar option was found in the configuration. According to the annotation, it means the address will be broadcast to consumers and producers
We changed it toadvertised.listeners=PLAINTEXT://10.4.82.141:9092
Restoring the native hosts file has also solved the problem after testing

Knowledge points

We areapplication.propertiesAlready specified inspring.kafka.bootstrap-serversFor IP, why use the hostname link?

It is speculated that the client will get the configuration from ZK after connecting to the Kafka instance
Then, after the client watch ZK node obtains the configured address, it starts listening to the queue.

Remember Kafka troubleshooting once