Kubernetes websocket watches silently dying #5189
Comments
Yes this should be addressed by that discussion / issue in 6.7.
I'm not aware of a great workaround. It may be worth trying a different fabric8 http client if possible - if this happens with jetty or vertx with 6.6.1, then it's likely that we're not seeing a close back from the remote side. OkHttp does kill the websocket after 1 minute and should guarantee that we'll see onClose called.
Yes the most likely problem is that we are never seeing the websocket as truly closed - we send a close, but onClose nor onError are never invoked. It is not clear what is exactly is the root cause. There is one possible bad path in the fabric8 client addressed by #5153 - if we don't see a close back from the remote side within a minute, we'll abort the websocket. However once aborted onError nor onClose will not be invoked. To guard against this more generally with #5153 the watch manager will forcibly start another watch if it doesn't see the previous one die as expected. |
|
@andreaTP @manusa to recap from our call today - the 6.5 and before behavior (before adding our client side and url based timeout) was that it was up to the server to terminate the watch, which typically should have been after 1-2 hours. Reports from strimzi confirm that those long running watches would at some point seem to stop receiving events, and we would not see a close nor an error event. To mitigate that we introduced timeouts to the watch - similar to what is in the go client, but ours will generally be triggered from the client side. The issues seen by strimzi are seeing are likely largely due to jdk httpclient. The closure handling for the okhttp client was already more tolerant without the #5153 such that the changes for the timeout handling should be fine. The changes in #5153 should make jetty and jdk httpclient also tolerant to problematic closure - however vertx does not support the notion of aborting / terminating the websocket, so it will just log if it can't complete a close as expected. #5153 will forcibly start a new watch should the last one not end appropriately. That will emit an error log:
|
|
@shawkins I've done some more testing to try to find out what actually could be the root-cause of this issue with the strimzi-operator, but currently I'm getting more and more puzzled actually and thought to just share what I could currently find out, in the hopes it helps you to tackle this issue. I created a little test application that, as the strimzi-user-operator does, has 2 Informers. I have been running this test application for a couple of days straight in 4 different configurations:
From this test application I have not seen 1 occurrence in which any of the informers would die. Everything kept on working as expected, properly refreshing the websockets every 5 to 10 minutes without missing any close-frame from the kube-API. Of course, they are different applications, but from a watcher/informer point of view they should behave similar. So next thing I'm going to try out is the multi-threaded approach ... |
Can you take a thread dump of the strimzi application to see if any of the jdk worker threads are deadlocked or otherwise not able to continue working? We have seen potential issues with the vertx client wrt to its worker threads, but have not seen the same behavior from jdk as the workers share a work queue. It would seem to take exhausting all of the workers - the pool size should be based upon the available cores. |
|
@duke-bartholomew @scholzj continuing from the previous comment - I don't see any usage of informOnCondition, waitOnCondition, or ExecListener outside of test code in the strimzi operator. Those are the places in fabric8 where user provided methods are called directly by the IO threads that could be easily identified as problematic. So it's best to get a thread dump for final confirmation if there is a thread utilization issue with the jdk client. My expectation is that all the jdk client worker threads would need to be tied up and thus all IO handling, not just close events, would be inhibited. |
|
I'm not aware of any use of informOnCondition, waitOnCondition, or ExecListener in the production code. We use just the indexer and event handler as far as I know. |
|
@shawkins Further testing and debugging made me conclude it's (probably) not a thread issue. I'm currently running 6.7.0 in test on the strimzi-operator to see how that behaves .... |
Were you able to get a thread dump to confirm?
And to clarify, these informers are simply waiting on a watch closure, but have not completed the stopped future and are reporting isRunning=true.
If a similar situation arises in 6.7, you may see However the jdk client should be able to force a resolution sooner via |
|
@shawkins I was not able to capture a thread dump on that container, but got to the conclusion it was not a threading issue by inspecting Running my latest test with the latest strimzi-operator (with the 6.7.0 kubernetes-client) on jdk-http shows indeed a major improvement if not a fix for the issue I had been experiencing with it (the dying informers). |
Yes each of those logs before would have resulted in websocket being effectively dead for the jdk client, but no notification downstream that there was an issue. It's still not clear just from this what the root cause is, I'll add another log that might help shed more light. I would expect to see the same type of behavior with the other clients - in particular jetty / vertx as there would be similar logs. If not, then ideally we can narrow down to some one off problem with the jdk client. If we do see the behavior with the other clients, then we'll need to determine if that points toward an api server issue (if it appears from our side that close has been sent, but we're not receiving a close back), or if this is due to the lack of robust closure handling that we're now trying to compensate for. To recap - in 6.6 and before a failed close attempt by the jdk client would result in a abort call 1 minute later if the remote side did not send a close or terminate the connection before then. Since the server side timeout is always 10 minutes and the client side timeout is between 5-10 minutes, that was quite possible. Since that jdk abort call did not cause a call to onClose or onError the websocket was effectively dead, but downstream this was not known so no new watch was started. For jetty, vertx, and okhttp the expectation would be that the server side timeout would ultimately cause us to be notified that the websocket was closed / terminated. For okhttp it also already has close handling that is robust enough that we'd get notification of onClose or onError within a minute of calling sendClose regardless of the outcome. To go further back prior to 6.6 there were no explicit informer watch timeouts (client side or in the url), but we'd still get reports of scenarios where watches would stop getting events - unfortunately there was never a reproducer nor sufficient logs to determine why. Without the timeouts the default server side timeout would apply (typically 1-2 hours) but that of course is too long should there be an issue with receiving events. It's possible there are still api server issues related to event delivery / timeouts as we saw previously the api server mishandled the timeout - kubernetes/kubernetes#102464 So one way to help mitigate the possibility that long running watches were becoming non-functional was to add similar timeouts as are done by the go client - however that means in 6.6 we're quite frequently relying on closure behavior that especially for the jdk client was not sufficient. Some other next steps:
|
Describe the bug
This might be related to #5152
I'm using Strimzi (v0.35.0) as kafka-operator which uses the kubernetes-client (httpclient-jdk:v6.6.1) under the hood to watch for k8s resources.
I'm noticing websocket connections getting stale / not being reconnected quite often.
With often I mean, in my case, approx. 30 minutes or so after the operator starts, the websockets die.
Only way to recover from that, and have the operator functioning properly again, is restarting the kafka-operator container.
Is there to work around this problem, or to find out what the root-cause is?
AKS might also be in failure by not responding on the close frame sent by the client, but how can I be 100% sure about this?
Fabric8 Kubernetes Client version
other (please specify in additional context)
Steps to reproduce
logs show ws connection close
Expected behavior
This is a very good question.
I would expect the watches/informers to keep working instead of silently dying.
On the other hand: why is there the need to close the websocket connections every 'n' minutes anyway?
websockets do have a keep-alive mechanism, so why is this not sufficient?
Runtime
other (please specify in additional context)
Kubernetes API Server version
other (please specify in additional context)
Environment
Azure
Fabric8 Kubernetes Client Logs
Additional context
kubernetes-client version: 6.6.1
Kubernetes API Server version: AKS v1.25.5
Java version inside Strimzi operator:
related discussion on Strimzi GitHub: strimzi/strimzi-kafka-operator#8586
The text was updated successfully, but these errors were encountered: