You are viewing a plain text version of this content. The canonical link for it is here.
Posted to jira@kafka.apache.org by "Ondrej Cervinka (Jira)" <ji...@apache.org> on 2023/05/24 17:09:00 UTC
[jira] [Commented] (KAFKA-13679) Superfluous node disconnected log messages
[ https://issues.apache.org/jira/browse/KAFKA-13679?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17725882#comment-17725882 ]
Ondrej Cervinka commented on KAFKA-13679:
-----------------------------------------
Just adding some observations as I am also having this issue after upgrade from Kafka from 2.8.1 to 3.4.0. I'm using Kafka Streams and Confluent Cloud. The messages from Admin Client do appear every 5 minutes, however I was also getting them from producer and restore consumer. Those are coming from different thread ({{{}StreamThread-X{}}}) than Admin Client and are more irregular.:
I was trying to increase {{request.timeout.ms}} from 30 s to 60 s and then 120 s but it didn't change anything. I ended up configuring {{WARN}} level for {{NetworkClient}} class as the messages were being logged too frequently.
Example filtered by {{NetworkClient:}}
{code:java}
2023-05-22T12:44:36.732Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-consumer, groupId=xxx] Disconnecting from node 2147483644 due to request timeout.
2023-05-22T12:44:36.734Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-consumer, groupId=xxx] Cancelled in-flight JOIN_GROUP request with correlation id 175 due to node 2147483644 being disconnected (elapsed time since creation: 39187ms, elapsed time since send: 39189ms, request timeout: 305000ms)
2023-05-22T12:44:36.735Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-consumer, groupId=xxx] Cancelled in-flight OFFSET_FETCH request with correlation id 176 due to node 2147483644 being disconnected (elapsed time since creation: 30020ms, elapsed time since send: 30020ms, request timeout: 30000ms)
2023-05-22T12:44:36.961Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Disconnecting from node 2 due to request timeout.
2023-05-22T12:44:36.961Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Cancelled in-flight FETCH request with correlation id 174 due to node 2 being disconnected (elapsed time since creation: 30418ms, elapsed time since send: 30418ms, request timeout: 30000ms)
2023-05-22T12:46:50.299Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node -1 disconnected.
2023-05-22T12:49:00.260Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 9 disconnected.
2023-05-22T12:50:50.162Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-producer-network-thread | 100.96.98.11:9000-StreamThread-2-producer] [Producer clientId=100.96.98.11:9000-StreamThread-2-producer, transactionalId=xxx-a3e62c78-423f-43f1-a4a4-877005881eac-2] Node -1 disconnected.
2023-05-22T12:50:50.338Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-producer-network-thread | 100.96.98.11:9000-StreamThread-1-producer] [Producer clientId=100.96.98.11:9000-StreamThread-1-producer, transactionalId=xxx-a3e62c78-423f-43f1-a4a4-877005881eac-1] Node -1 disconnected.
2023-05-22T12:50:50.622Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-GlobalStreamThread] [Consumer clientId=100.96.98.11:9000-global-consumer, groupId=null] Node -1 disconnected.
2023-05-22T12:50:51.580Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-consumer, groupId=xxx] Node -1 disconnected.
2023-05-22T12:50:51.643Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-consumer, groupId=xxx] Node -1 disconnected.
2023-05-22T12:50:55.032Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node -1 disconnected.
2023-05-22T12:50:55.069Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node -1 disconnected.
2023-05-22T12:50:55.165Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 1 disconnected.
2023-05-22T12:50:55.166Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Cancelled in-flight METADATA request with correlation id 1238 due to node 1 being disconnected (elapsed time since creation: 54ms, elapsed time since send: 54ms, request timeout: 30000ms)
2023-05-22T12:50:55.509Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 4 disconnected.
2023-05-22T12:50:55.509Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Cancelled in-flight METADATA request with correlation id 1239 due to node 4 being disconnected (elapsed time since creation: 160ms, elapsed time since send: 160ms, request timeout: 30000ms)
2023-05-22T12:50:55.712Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 13 disconnected.
2023-05-22T12:50:55.712Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Cancelled in-flight METADATA request with correlation id 1243 due to node 13 being disconnected (elapsed time since creation: 102ms, elapsed time since send: 102ms, request timeout: 30000ms)
2023-05-22T12:53:36.977Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 8 disconnected.
2023-05-22T12:53:41.775Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 5 disconnected.
2023-05-22T12:53:41.914Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 2 disconnected.
2023-05-22T12:53:43.389Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 20 disconnected.
2023-05-22T12:53:43.527Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 14 disconnected.
2023-05-22T12:53:43.527Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Cancelled in-flight METADATA request with correlation id 2338 due to node 14 being disconnected (elapsed time since creation: 105ms, elapsed time since send: 105ms, request timeout: 30000ms)
2023-05-22T12:53:45.993Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 3 disconnected.
2023-05-22T12:53:46.223Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 6 disconnected.
2023-05-22T12:54:00.443Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 15 disconnected.
2023-05-22T12:54:00.444Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 8 disconnected.
2023-05-22T12:54:00.445Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 1 disconnected.
2023-05-22T12:54:00.445Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Cancelled in-flight METADATA request with correlation id 48 due to node 1 being disconnected (elapsed time since creation: 2ms, elapsed time since send: 2ms, request timeout: 30000ms)
2023-05-22T12:54:00.445Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 3 disconnected.
2023-05-22T12:54:00.546Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 14 disconnected.
2023-05-22T12:54:00.548Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 12 disconnected.
2023-05-22T12:54:00.553Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 2 disconnected.
2023-05-22T12:54:14.855Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 3 disconnected.
2023-05-22T12:54:15.344Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-producer-network-thread | 100.96.98.11:9000-StreamThread-1-producer] [Producer clientId=100.96.98.11:9000-StreamThread-1-producer, transactionalId=xxx-a3e62c78-423f-43f1-a4a4-877005881eac-1] Node 18 disconnected.
2023-05-22T12:57:53.580Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-producer-network-thread | 100.96.98.11:9000-StreamThread-2-producer] [Producer clientId=100.96.98.11:9000-StreamThread-2-producer, transactionalId=xxx-a3e62c78-423f-43f1-a4a4-877005881eac-2] Node 15 disconnected.
2023-05-22T12:57:54.042Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 11 disconnected.
2023-05-22T12:57:57.855Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 7 disconnected.
2023-05-22T12:57:57.992Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Node 11 disconnected.
2023-05-22T12:57:57.993Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-2] [Consumer clientId=100.96.98.11:9000-StreamThread-2-restore-consumer, groupId=null] Cancelled in-flight METADATA request with correlation id 4410 due to node 11 being disconnected (elapsed time since creation: 136ms, elapsed time since send: 136ms, request timeout: 30000ms)
2023-05-22T12:59:00.634Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 17 disconnected.
2023-05-22T12:59:00.635Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 13 disconnected.
2023-05-22T12:59:00.636Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 11 disconnected.
2023-05-22T12:59:00.636Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 7 disconnected.
2023-05-22T12:59:00.636Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Cancelled in-flight METADATA request with correlation id 50 due to node 7 being disconnected (elapsed time since creation: 1ms, elapsed time since send: 1ms, request timeout: 30000ms)
2023-05-22T12:59:00.737Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 5 disconnected.
2023-05-22T12:59:00.738Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [kafka-admin-client-thread | 100.96.98.11:9000-admin] [AdminClient clientId=100.96.98.11:9000-admin] Node 4 disconnected.
2023-05-22T13:02:37.300Z INFO xxx-69f6c97dc9-jcxbd o.a.k.c.NetworkClient [100.96.98.11:9000-StreamThread-1] [Consumer clientId=100.96.98.11:9000-StreamThread-1-restore-consumer, groupId=null] Node 17 disconnected.{code}
> Superfluous node disconnected log messages
> ------------------------------------------
>
> Key: KAFKA-13679
> URL: https://issues.apache.org/jira/browse/KAFKA-13679
> Project: Kafka
> Issue Type: Bug
> Components: clients
> Affects Versions: 3.1.0
> Reporter: Philip Bourke
> Priority: Minor
>
> In Kafka 3.1 the "{_}Node x disconnected{_}" log message in the {{NetworkClient.java}} class was changed from DEBUG to INFO - [https://github.com/apache/kafka/commit/79d97bd29d059e8ba8ee7726b49d76e03e281059#diff-dcc1af531d191de8da1e23ad6d878a3efc463ba4670dbcf2896295a9dacd1c18R935]
> Now my application logs are full of node disconnected messages and it would indicate that there may be a connectivity problem. However I can see that the logs are getting written every 5 minutes exactly, and it's the AdminClient that is writing the logs.
> {code:bash}
> 2022-02-16 14:45:39,277 [d-60105f051cdb-admin] INFO o.apache.kafka.clients.NetworkClient - [AdminClient clientId=desktop-session-internal-user-streamer-v1-9888ff1d-446e-40cd-88dd-60105f051cdb-admin] Node 1 disconnected.
> {code}
> My guess is that it may be the [connections.max.idle.ms|https://kafka.apache.org/documentation/#adminclientconfigs_connections.max.idle.ms] config setting, and there is in fact no issue with connectivity to the brokers?
> I'm raising this ticket here because the logs are full of these repetitive messages indicating an issue and setting off alarm bells, and also because I did not get a response on the confluent forum or in any slack channels.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)