ReflectorRunnable.watchHandler seems to be stuck after about 5min of inactivity

[karunasagark]

I'm working on custom controller where I noticed this issue. After about 5min of inactivity i.e. no updates in the api server, the controller stops receiving watch events from the api server. So any add/delete on the custom resource after the 5min of inactivity on api server, is not reconciled by the controller .

On further debugging, what I've seen is that ReflectorRunnable.watchHandler which should be constantly reading from the response stream seems to be stuck. The Receiving resourceVersion log from ReflectorRunnable doesn't show up. Also, kubectl get <customresource> -w sees the updates as expected.

The minimal repo is here kubetest.zip and I'm able to reproduce this consistently. I tried running this using both java 8 and java 11, with the same result as above. I got a jstack dump when the issue occurred, but couldn't notice any issue, the reflector thread was in runnable state.

"controller-reflector-com.XXXXX-0" #23 prio=5 os_prio=0 cpu=39.77ms elapsed=986.61s allocated=1080K defined_classes=39 tid=0x00007f19b856c800 nid=0x1bbe9 runnable  [0x00007f19b5ff2000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(java.base@11.0.10/Native Method)
        at java.net.SocketInputStream.socketRead(java.base@11.0.10/SocketInputStream.java:115)
        at java.net.SocketInputStream.read(java.base@11.0.10/SocketInputStream.java:168)
        at java.net.SocketInputStream.read(java.base@11.0.10/SocketInputStream.java:140)
        at sun.security.ssl.SSLSocketInputRecord.read(java.base@11.0.10/SSLSocketInputRecord.java:478)
        at sun.security.ssl.SSLSocketInputRecord.readHeader(java.base@11.0.10/SSLSocketInputRecord.java:472)
        at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(java.base@11.0.10/SSLSocketInputRecord.java:70)
        at sun.security.ssl.SSLSocketImpl.readApplicationRecord(java.base@11.0.10/SSLSocketImpl.java:1354)
        at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base@11.0.10/SSLSocketImpl.java:963)
        at okio.Okio$2.read(Okio.java:140)
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
        at okio.RealBufferedSource.request(RealBufferedSource.java:72)
        at okio.RealBufferedSource.require(RealBufferedSource.java:65)
        at okio.RealBufferedSource.readHexadecimalUnsignedLong(RealBufferedSource.java:307)
        at okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.readChunkSize(Http1ExchangeCodec.java:492)
        at okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.read(Http1ExchangeCodec.java:471)
        at okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.java:286)
        at okio.RealBufferedSource.exhausted(RealBufferedSource.java:61)
        at io.kubernetes.client.util.Watch.hasNext(Watch.java:179)
        at io.kubernetes.client.informer.cache.ReflectorRunnable.watchHandler(ReflectorRunnable.java:160)
        at io.kubernetes.client.informer.cache.ReflectorRunnable.run(ReflectorRunnable.java:108)
        at io.kubernetes.client.informer.cache.Controller$$Lambda$126/0x000000080069a440.run(Unknown Source)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.10/Executors.java:515)
        at java.util.concurrent.FutureTask.runAndReset(java.base@11.0.10/FutureTask.java:305)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.10/ScheduledThreadPoolExecutor.java:305)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.10/ThreadPoolExecutor.java:1128)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.10/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11.0.10/Thread.java:834)

   Locked ownable synchronizers:
        - <0x00000007655823d8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        - <0x00000007656801a0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

[brendandburns]

What version of the client are you using?

Have a look at the discussion starting here:

#1370 (comment)

You should try setting the read timeout to < 5 minutes and things should work.

Basically, something in the network somewhere is disconnected, but it takes a long time for the socket to timeout.

[karunasagark]

Thanks for the information. Looks like similar issue has been faced by others and by other clients (js, c#, go); I should search under closed issues too.

I'm using 10.0.0 java client. And from the discussion in #1370, it seems the fix was made in #1498. However, don't see this fix #1498 in the latest release 11.0.1.

It seems releases are cherry picks from master branch. Is there a way to list this fix and maybe others for the next release? Should I open an issue to track this?

Also, should fix the ControllerExample. Will send out a PR for this.

java/examples/examples-release-10/src/main/java/io/kubernetes/client/examples/ControllerExample.java

Line 49 in 8e89844

apiClient.getHttpClient().newBuilder().readTimeout(0, TimeUnit.SECONDS).build();

Meanwhile, while we figure out the release, I see couple of options to workaround below. Any preference which is better option?

1. as suggested in earlier comment, set read timeout to < 5 minutes. This should timeout the watch connection and the ReflectorRunnable should setup a new watch connection -

   java/util/src/main/java/io/kubernetes/client/informer/cache/ReflectorRunnable.java

   Line 144 in 8e89844

   if ((t instanceof RuntimeException)

2. by modifying the http client as shown here - kubernetes watch API is behaving oddly #1370 (comment). This uses infinite read timeout, but uses keepalive to keep TCP connection active.

[brendandburns]

We can see about cherry-picking that in. Rather than opening an issue, if you wanted to send a PR with the cherry-pick that's the fastest way to get it done.

Personally, I would set a short timeout, because I don't trust the network, but either one should work.

[karunasagark]

Setting the read timeout to < 5 minutes but > 0 i.e. solution 1, didn't help. I thought this will lead to a io timed out exception but it didn't. I'll investigate this.

Solution 2 does work.

[karunasagark]

Oh I see this commit overwrites the read timeout I set.

Once I hacked in to remove the overwrite of read timeout to zero, it does work fine. So next, trying to figure out why the above commit was made.

[brendandburns]

Yeah, I don't think we should be overriding the read timeout. I think there was a belief that it was better to try to keep the connection open for forever, even when there is no data, but I think that having the option to timeout is better for user control...

@yue9944882 wdyt?

[codeyq]

Another data point. I also saw the exact same issue happening on GKE 1.18. It was fixed by option 2. Thanks @karunasagark Would it be possible to fix the read timeout overwrite in the next release or be back ported to the existing ones?

[karunasagark]

@yue9944882 can take a look at Brendan's comment and provide your suggestion? I can make the changes accordingly.

[karunasagark]

Also, #1588 seems to be making things more complex. The SharedInformerFactory.java overrides the read timeout to 0 (infinite) and depending on the sharedIndexInformerFor overload used, the watch call either uses 0 read timeout or what is specified from the reflectorRunnable.

Overload that would use the read timeout specified by reflectorRunnable:

java/util/src/main/java/io/kubernetes/client/informer/SharedInformerFactory.java

Line 211 in c580990

public Watch<ApiType> watch(CallGeneratorParams params) throws ApiException {

Overload that would NOT use the read timeout specified by reflectorRunnable:

java/util/src/main/java/io/kubernetes/client/informer/SharedInformerFactory.java

Line 259 in c580990

public Watchable<ApiType> watch(CallGeneratorParams params) throws ApiException {

Further it gets harder to reason about what is the value of read timeout without looking through the code path carefully.

I would propose to remove the read timeout override originally introduced in this commit. However, this would probably expose out the memory leak as discussed in #1259 which needs to be addressed differently (possibly by de-deuping). I'm guessing the memory leak would also be exposed by #1588, since the timeout is 5min and reflectorRunnable would re-list and re-watch. Probably will need to spend more time to understand the root cause of the memory leak.

@yue9944882 and @brendanburns what do you guys think? should we spend more time addressing the memory leak in a different way OR patch all watch code paths further will 5min timeout?

[karunasagark]

IIUC, the de-duping approach would also solve #1634 as mentioned by @brendanburns in this comment.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-contributor-experience at kubernetes/community.
/lifecycle stale

[k8s-triage-robot]

The Kubernetes project currently lacks enough active contributors to adequately respond to all issues and PRs.

This bot triages issues and PRs according to the following rules:

• After 90d of inactivity, lifecycle/stale is applied
• After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
• After 30d of inactivity since lifecycle/rotten was applied, the issue is closed

You can:

• Mark this issue or PR as fresh with /remove-lifecycle rotten
• Close this issue or PR with /close
• Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle rotten