[
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)
