AbstractWatchManager:442 - Watch connection error recieved xxx times without progress, will reconnect if possible

[RobertoTroianiSistematica]

Hi all,
after strimzi upgrade from v 0.29 to v 0.41, all seem to work fine unless one error in strimzi-cluster-operator log:

2024-06-25 15:21:15 INFO ClusterOperator:140 - Triggering periodic reconciliation for namespace default
2024-06-25 15:21:29 INFO AbstractWatchManager:442 - Watch connection error recieved 15 times without progress, will reconnect if possible
java.net.SocketException: Connection reset
at sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394) ~[?:?]
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426) ~[?:?]
at jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170) ~[java.net.http:?]
at jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833) ~[java.net.http:?]
at jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181) ~[java.net.http:?]
at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) ~[java.net.http:?]
at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) ~[java.net.http:?]
at jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774) ~[java.net.http:?]
at jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957) ~[java.net.http:?]
at jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253) ~[java.net.http:?]
at jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979) ~[java.net.http:?]
at jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934) ~[java.net.http:?]
at java.util.ArrayList.forEach(ArrayList.java:1511) ~[?:?]
at jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934) ~[java.net.http:?]
2024-06-25 15:21:37 INFO ClusterOperator:140 - Triggering periodic reconciliation for namespace kafka-cluster
2024-06-25 15:21:37 INFO AbstractOperator:264 - Reconciliation #134 Kafka(kafka-cluster/myname): Kafka myname will be checked for creation or modification
2024-06-25 15:21:41 INFO AbstractOperator:536 - Reconciliation #134 Kafka(kafka-cluster/myname): reconciled

The error start about after 40/45 minutes pod start.

Thanks for the support.

[scholzj]

Sounds like some issues in the communication with your API server. But for issues like this it is hard to find the actual cause if it can be anything from lack of resources, networking issues, networking instability, APi server issues etc.

[ppatierno]

Not sure it's related to the Strimzi operator itself, it seems an issue on the connection between the operator and the Kubernetes API server.

[alert101]

We are seeing the same error with both 0.41 and 0.42. Currently it's a pain to try and find the root cause.

Could the error be handled properly so that the error message would contain the FQDN/IP that the operator is trying to connect to?

[scholzj]

I read the only log snippet actually shared here as that the exception is part of the log message. So how is it not handled? How do you not know what logged it?

[alert101]

Sorry, you are correct. The exception is actually part of the log message. Problem is that this is the only information in addition to the not very helpful stacktrace:

2024-06-25 15:21:29 INFO AbstractWatchManager:442 - Watch connection error recieved 15 times without progress, will reconnect if possible

Something somewhere in the strimzi operator logs this. I've cloned the strimzi-cluster-operator repo and so far I've failed to find any mention of AbstractWatchManager or WatchManager. Now, I haven't programmed software in almost ten years so maybe I'm a little bit rusty when it comes to code. I do however remember that logs should tell the user what is going wrong and not print obscure stack traces. Now the software basically tells you "I tried to connect somewhere but I won't tell you where. The connection failed, have a nice day trying to figure out what went wrong."

Even better, for some reason the error doesn't show up today, apparently the cause, whatever it may be, has magically fixed itself over night. Next time I will increase logging to try and figure out where the operator is trying to connect and what might be the root cause.

A very productive day at work yet again...

/end of rant

[scholzj]

I already told you in the beginning that this is coming from the Fabric8 Kubernetes Client. That makes it also quite obvious where it is connecting. I also told you what the error indicates. If the connection to something (Kube API server in this case) is terminated or interrupted, the application typically does not know why that happened. It cannot really provide more details - it can share only what it has. But feel free to open PRs to improve things if you think it can be done as easily as you suggest.

Ranting is fine, but it will hardly get you any sympathy if you are here only to rant and not read what people give you as advice.

[alert101]

As a new user of strimzi-kafka-operator I do not understand the ins and outs of it yet. How is it obvious? There's no indication in the error message or stack trace. Neither does Fabric8 Kubernetes Client tell me anything, I hadn't heard of that until today. That is something you brought up, not the error message. If this is indeed a failed connection to the kubernetes api server, well, we are using Azure Kubernetes Service. Currently outbound connections from the cluster are not restricted, neither do we have a whitelist for the API servers so there should be a clear path for any such connection. And as stated, the issue fixed itself. How, I do not know. Checking the logs this issue appeared on Monday. That's when our Kubernetes node images were updated. Seems to me that something went wonky with the strimzi-operator or one of its components during that. Reason still unknown.

I never said it was easy to fix. I was merely suggesting that the error message could be improved. And as I also said I've cloned the operator repo and couldn't find any reference to the log message. If the actual error message is referring to some third-party gimmick that is not in any way clear from the log entry.

[scholzj]

So once again. the error is not coming from Strimzi. It is coming from Java. But Connection reset is a pretty standard error that is as far as I know used also in other programming languages or even things like browsers. So to understand what it means, you do not need any Strimzi experience or expertise. And - once again, as I already said before - it quite often means various networking issues or instabilities. So it is not surprising that you sometimes see it and sometimes don't. It could be related to the load of your cluster, some glitches in the different components, noisy neighbors, etc.

I'm not sure why would a log message from a dependency be a third-party gimmick. I also think the message is fairly clear:

• It is on INFO level to indicate how important it is (it is info level because the library handles it and tries to reconnect)
• It clearly says that it will try to reconnect
• It says that the message is coming from the class AbstractWatchManager. It is indeed not completely obvious which dependency/project this class is coming from. I think it is quite easy to find out where does it come from when you open Strimzi sources from an IDE. But if you want that, you can configure your logging output to list the full package - but it is disabled by default as it can get very long.

Given the nature of the log message, I think it is not surfaced to the Strimzi level at all. So as I said before, there is not much Strimzi code can do about this.