watcher connection stops receiving events after some time

[jkryl]

It is a known issue that some people have worked around by using rather pull than push method for receiving updates about changes. Another workaround is to restart the watcher every n minutes. As @brendandburns pointed out in my earlier PR576, csharp k8s client suffers from the same problem: kubernetes-client/csharp#533 .

My experience shows that it happens when the connection is idle for a long time. The connection is dropped without closing it so the client keeps waiting for events, not receiving any. I have seen it in Azure and Google cloud with managed k8s service.

The c# issue suggests that it happens because keepalives are not enabled on underlaying connection. And indeed, I found that it is the case for JS k8s client too. That can be fixed by adding keep-alive option to "request" options if there wasn't a bug in the request library. I have created a new ticket for it: request/request#3367 . The request library has been deprecated and cannot be fixed. I was able to work around the bug in watcher's code. So with my fix, the connections are kept alive. My experience shows that every three minutes TCP ACK is exchanged between client and server. I would like the keep-alive to happen more often to detect dead watcher connections in more timely fashion however it does not seem to be possible to tweak keep-alive interval for the connection in nodejs: nodejs/node-v0.x-archive#4109 .

The fix I have does not seem to fix the problem in all cases. That might be because the keep-alive of 3 minutes may not be sufficient in all cases. I will test the fix more thoroughly and update the ticket with the results of testing.

[jkryl]

let me correct myself. The keep-alives shown by tcpdump were not keep-alives sent by the watcher but they are sent by the api server every 3 minutes:

...
11:32:59.239617 IP 227.114.246.35.bc.googleusercontent.com.https > gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832: Flags [.], ack 1, win 501, options [nop,nop,TS val 2612916151 ecr 3766451319], length 0
11:32:59.239753 IP gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832 > 227.114.246.35.bc.googleusercontent.com.https: Flags [.], ack 19557, win 331, options [nop,nop,TS val 3766631543 ecr 2611652359], length 0
11:35:59.463662 IP 227.114.246.35.bc.googleusercontent.com.https > gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832: Flags [.], ack 1, win 501, options [nop,nop,TS val 2613096375 ecr 3766631543], length 0
11:35:59.463762 IP gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832 > 227.114.246.35.bc.googleusercontent.com.https: Flags [.], ack 19557, win 331, options [nop,nop,TS val 3766811767 ecr 2611652359], length 0

Now comes the breakpoint roughly after half an hour since the connection has been established. The watcher receives a couple of bytes from the server and immediately starts to send keep-alives every second. That's when the connection becomes dead and does not receive any new events.

11:38:09.258810 IP 227.114.246.35.bc.googleusercontent.com.https > gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832: Flags [P.], seq 19557:19584, ack 1, win 501, options [nop,nop,TS val 2613226170 ecr 3766811767], length 27
11:38:09.258890 IP gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832 > 227.114.246.35.bc.googleusercontent.com.https: Flags [.], ack 19584, win 331, options [nop,nop,TS val 3766941562 ecr 2613226170], length 0
11:38:10.273184 IP gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832 > 227.114.246.35.bc.googleusercontent.com.https: Flags [.], ack 19584, win 331, options [nop,nop,TS val 3766942576 ecr 2613226170], length 0
11:38:10.273612 IP 227.114.246.35.bc.googleusercontent.com.https > gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832: Flags [.], ack 1, win 501, options [nop,nop,TS val 2613227185 ecr 3766941562], length 0
11:38:11.297176 IP gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832 > 227.114.246.35.bc.googleusercontent.com.https: Flags [.], ack 19584, win 331, options [nop,nop,TS val 3766943600 ecr 2613227185], length 0
11:38:11.297533 IP 227.114.246.35.bc.googleusercontent.com.https > gke-jan-test2-default-pool-664e7812-gs7g.c.mayastor.internal.55832: Flags [.], ack 1, win 501, options [nop,nop,TS val 2613228209 ecr 3766941562], length 0
...

My keep-alive patch does not seem to change this behaviour. Either it's not the way to go or it is not complete and still missing something. For the reference this is the commit I have been testing: https://github.com/jkryl/javascript/commit/0fef4de1e7c1dacfa7da04f1e4f6e2047525c9f3#diff-8af1000c89b03ced37f439c61c5696c45e1e83a70cc07182feef6595123f0bad

[brendandburns]

In general, I think relying on watches to stick around for greater than N minutes (where N is fairly small) is probably not the best bet. I think adding a timeout if an event hasn't been received in N minutes (you can tune N depending on your workload) is probably the right approach.

The network is just too weird a place to expect that HTTP/TCP connections will stay alive for a long time.

[jkryl]

yes, I tend to agree. It would be interesting to know what golang watcher does - given that it's kinda referential implementation for k8s watchers. I decided to work around the problem by doing exactly what you have suggested 🤞

[DocX]

Can you point out to how to set the timeout? Would that be on the list function, e.g.

listNamespacedPod(
  namespace, 
  undefined, // pretty?: string, 
  undefined, // allowWatchBookmarks?: boolean, 
  undefined, // _continue?: string, 
  undefined, // fieldSelector?: string,
  undefined, // labelSelector?: string, 
  undefined, // limit?: number, 
  undefined, // resourceVersion?: string, 
  undefined, // resourceVersionMatch?: string,
  300, // timeoutSeconds?: number, 
  true, // watch?: boolean
)

[brendandburns]

@DocX I would place a timer in your own code, e.g. something like:

function maybeRestartInformer() {
    if (noUpdates) {
        restartInformer();
   }
   setTimeout(maybeRestartInformer, <timeout>);
}

setTimeout(maybeRestartInformer, <timeout>);

or something like that.

[brendandburns]

@jkryl the relevant code starts here:

https://github.com/kubernetes/client-go/blob/master/rest/request.go#L674

There's also a big discussion here:

kubernetes/client-go#374

and here

kubernetes/kubernetes#65012 (comment)

The consensus seems to be switching to HTTP/2 and sending Pings from the client.

[jmickey]

@brendandburns This might be slightly off the topic of this issue, but can you give any advice on how to properly restart an informer? Informers don't seem to have a stop() function, and I'm worried that just re-calling start() is going to cause some problems.

[jkryl]

@DocX : As @brendanburns suggests I have a special code in my watcher wrapper that restarts the watcher after being idle for too long. Snippet from my current code:

 _setIdleTimeout() {
    if (this.idleTimeout > 0) {
      this._clearTimer();
      this.timer = setTimeout(() => {
        this.stop();
        this.start();
      }, this.idleTimeout);
    }
  }
  
   _onEvent(event: string, cr: CustomResource) {
     ...
     this._setIdleTimeout();
     ...
   }

Full implementation specific for my use case is here: https://github.com/openebs/Mayastor/blob/develop/csi/moac/watcher.ts#L225

[dominykas]

Informers don't seem to have a stop() function, and I'm worried that just re-calling start() is going to cause some problems.

makeInformer returns a ListWatch which does have a stop() method, which just works in JS world?

Quite possibly the interface Informer<T> should be updated to expose that in TS world.

It seems that stop() just makes the request abort, which in turn just restarts it.

Yes, there is a need for a proper stop method 👍

[brendandburns]

@dominykas that's a fair request. I filed #604 to track.

A PR would be welcome, or I will get to it eventually.

[dominykas]

Thanks 🙇

I'll see if I can catch a break to PR this soon enough. Guidelines on how you'd approach it most welcome - I have my ideas, but not sure about alternatives.

[brendandburns]

I would add some sort of intercept/break in the timeout handler code path.

e.g.

if (aborted) { return; }

Or somesuch.

[DocX]

Not sure if that is relevant, but just FYI, specifying the timeout seconds on the list function as shared above, seems to have get rid of the problem for us.

[dkontorovskyy]

@brendanburns We've seen a similar issue with Informer API in AKS. After a short period of time, depending on how big was the cluster, Informer stops receiving events and goes into ECONNRESET loop, and then eventually becomes unresponsive.

I've raised a ticket with Azure support. They raised some findings back, might be helpful

• From the traces interestingly we saw lot of RST from the API Server directly without even having any handshake
• It seems there is no keepalive ? i.e. the client TCP socket will send a keepalive packet from time to time to make sure this is an active TCP stream . Servers usually discard inactive TCP streams with RST.

Indeed, there is no keepalive in Informer requests.

Hope this helps :)