fluentd -> kafka timeouts "Connection has been unused for too long"

[kingnarmer]

I am getting random timeouts from fluentd pods to kafka provisioned by strimzi operator 0.31. Nothing changed before timeouts surfaced.

The pattern is the same timeout followed by successful connection. most of failed SRC IPs are on same subnet as kafka .

Appreciate help figuring out source of the issue and if any kafka confi could be tuned to alleviate the issue on source.

This is what I see on fluentd clients.

2022-12-09 17:07:03 +0000 [info]: #0 Sending 4 messages to 10.200.170.24:9094 (node_id=1)
2022-12-09 17:08:09 +0000 [info]: #0 Sending 3 messages to 10.200.170.26:9094 (node_id=3)
2022-12-09 17:08:09 +0000 [warn]: #0 Connection has been unused for too long, re-connecting...
2022-12-09 17:08:09 +0000 [info]: #0 Sending 6 messages to 10.200.170.24:9094 (node_id=1)
2022-12-09 17:08:09 +0000 [warn]: #0 Connection has been unused for too long, re-connecting...
2022-12-09 17:08:09 +0000 [info]: #0 Sending 2 messages to 10.200.170.24:9094 (node_id=1)
2022-12-09 17:08:09 +0000 [warn]: #0 Connection has been unused for too long, re-connecting...
2022-12-09 17:08:09 +0000 [info]: #0 Sending 6 messages to 10.200.170.25:9094 (node_id=4)
2022-12-09 17:08:09 +0000 [warn]: #0 Connection has been unused for too long, re-connecting...
2022-12-09 17:08:09 +0000 [info]: #0 Sending 6 messages to 10.200.170.26:9094 (node_id=3)
2022-12-09 17:08:09 +0000 [warn]: #0 Connection has been unused for too long, re-connecting...
2022-12-09 17:08:10 +0000 [info]: #0 stats - namespace_cache_size: 3, pod_cache_size: 3, namespace_cache_api_updates: 56, pod_cache_api_updates: 56, id_cache_miss                                                                     : 56
2022-12-09 17:08:58 +0000 [info]: #0 Sending 1 messages to 10.200.170.26:9094 (node_id=3)
2022-12-09 17:08:58 +0000 [warn]: #0 Connection has been unused for too long, re-connecting...
2022-12-09 17:08:59 +0000 [info]: #0 stats - namespace_cache_size: 3, pod_cache_size: 3, namespace_cache_api_updates: 56, pod_cache_api_updates: 56, id_cache_miss                                                                     : 56
2022-12-09 17:09:14 +0000 [info]: #0 Sending 5 messages to 10.200.170.26:9094 (node_id=3)
2022-12-09 17:09:14 +0000 [info]: #0 Sending 3 messages to 10.200.170.25:9094 (node_id=4)```

[robobario]

Some questions:

1. Is that the log from a single pod?
2. What fluentd kafka plugin/version are you using?
3. Are you able to share any of your fluentd config?
4. Is my understanding right, you've been using this fluentd and strimzi 0.31 setup for some time and these log messages have started happening?

Any chance you could turn up the fluentd log level? I can see there's plenty of debug logs in ruby-kafka (assuming that's what you're running).

[SampsonCrowley]

just an FYI, if the plugin uses the ruby-kafka gem (which has this exact phrase), the warnings aren't anything to worry about on their own, as it's just a warning log that a new connection is needed. the idle settings are hard-coded to be 30 seconds. so anytime a connection has gone unused for 30s the message will appear the next time it is used.

it doesn't necessarily mean anything changed on the code; maybe your average usage changed. your message does start with a 60 second gap in usage.

also the gem didn't always used to log that it was reconnecting; it used to just do it silently until v0.5.1. so if the fluentd plugin updated the ruby version (which was way out of date if that is the case) then that could also be what happened

https://github.com/zendesk/ruby-kafka/blob/62a0cf9c44b0c05a4f98c4ec073ae5f04f4194e0/lib/kafka/broker.rb#L202