Client-go: Node watch returns events with nil objects

[arunmk]

I have a small code running on master to detect when a node enters / leaves the cluster. The overall code is as follows:

1. Initially get all nodes in cluster using: clientset.Core().Nodes().List(v1.ListOptions{})
2. Create a watcher using: watcher, err := clientset.Core().Nodes().Watch(v1.ListOptions{})
3. Wait on nodeListChangedEventChan := watcher.ResultChan()
4. Consume the event using nodeListChangedEvent := <-nodeListChangedEventChan
5. Determine the node of interest using nodeListChangedEvent.Object.(*v1.Node)
6. Determine the activity of the node using: nodeListChangedEvent.Type (watch.Added / watch.Deleted)

I see that the node addition / removal events are cleanly received. However, after about 30 minutes of waiting on the channel, I begin to get thousands of events with the Object (nodeListChangedEvent.Object) being 'nil'.

As a workaround, whenever the error is hit, I have started recreating the watcher and listening again (2,3). However, it again works well for about 30 minutes and the situation is hit. This happens forever with an interval of about 30 minutes between the creation of the watcher and the error state.

[jbw976]

We are seeing this as well while watching for ConfigMap changes in https://github.com/rook/rook/issues/1195#issuecomment-347711772, which causes the watcher to go into a tight loop consuming 100% CPU.

We are using revision 42a124578af9e61f5c6902fa7b6b2cb6538f17d2 for the client-go pkg: https://github.com/kubernetes/client-go/tree/42a124578af9e61f5c6902fa7b6b2cb6538f17d2

Some logging I added for debugging shows the events having empty Type and nil Object fields (you can also see how rapidly the events are coming over the channel):

2017-11-29 04:30:09.762477 I | api: WatchMonConfig event received: {Type: Object:<nil>}
2017-11-29 04:30:09.762479 I | api: WatchMonConfig event received: {Type: Object:<nil>}
2017-11-29 04:30:09.762481 I | api: WatchMonConfig event received: {Type: Object:<nil>}
2017-11-29 04:30:09.762483 I | api: WatchMonConfig event received: {Type: Object:<nil>}

[jbw976]

This closed issue could potentially be related: https://github.com/kubernetes/client-go/issues/12#issuecomment-253348471

[arunmk]

@jbw976 the issue you see is exactly the same as the issue that I am seeing. And yes, we do see >1 notification per _millisecond_ indicating that the watch has failed.

[arunmk]

@caesarxuchao I see the issue linked with your workaround. I had implemented the same as a workaround. Is there any rationale for timing out the watches? (If liveliness is an issue it could be solved by keepalive pings)

Also, could you mention if this behavior of the watch is documented somewhere?

[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-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[roycaihw]

I found a flag description in apiserver reference: --min-request-timeout int: An optional field indicating the minimum number of seconds a handler must keep a request open before timing it out. Currently only honored by the watch request handler, which picks a randomized value above this number as the connection timeout, to spread out load. (default 1800)

[lavalamp]

It sounds like the HTTP connection closed, and our watch code doesn't exit cleanly on EOF. (Or there's an error somewhere that isn't getting checked?)

As mentioned above, you can extend the timeout by passing a query parameter.

The automated way to handle this is to use the Reflector rather than directly calling Watch. There are multiple tricky cases and Reflector will handle them all for you.

[jbw976]

Interesting @lavalamp, do you have a link to examples using the Reflector that you mentioned?

The way that I ended up addressing this was to recreate the watcher, as seen in this function: https://github.com/rook/rook/blob/f06dd0009e4f04ea9484cf0ca99c091fac857faa/pkg/operator/cluster/ceph/osd/osd.go#L419

However, we got a report from a user this weekend that the newly recreated watcher object is returning nil on the result channel immediately, not after a long HTTP timeout: https://github.com/rook/rook/issues/1544

I wonder why the channel is closed immediately in that case?

EDIT: ah, i believe this error from the kube-apiserver log may shed light. The watcher is attempting to start watching from a resource version that has been compacted. That must be the reason for the immediately closed result channel in this specific case.

1 watcher.go:208] watch chan error: etcdserver: mvcc: required revision has been compacted

[caesarxuchao]

Reflector handles the watch timeout in this function: https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/client-go/tools/cache/reflector.go#L239

Most k8s controllers uses informers, which uses reflectors to sync with the apiserver. This doc and this example shows how to write a controller.

[fejta-bot]

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

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

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten
/remove-lifecycle stale

[fejta-bot]

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/close