Controller-runtime: Why resync default is so large - 10hours

[skonto]

Resync interval is 10hours and there is a recommendation not to change it.

// SyncPeriod determines the minimum frequency at which watched resources are
// reconciled. A lower period will correct entropy more quickly, but reduce
// responsiveness to change if there are many watched resources. Change this
// value only if you know what you are doing. Defaults to 10 hours if unset.

https://github.com/kubernetes-sigs/controller-runtime/blob/master/pkg/manager/manager.go#L103
Several operators like the lyft flink operator (controller runtime based) and the spark operator (sample controller based) set it to 30s. Why a so large default value? Is there a difference between this and the cache mechanism used by go-client that justifies this. @DirectXMan12 any ideas?

[DirectXMan12]

controller-runtime uses the underlying client-go caches, so the difference isn't there. The main difference is that we force people to actually write level-based controllers (see below).

The problem was that nobody actually understood what this knob did -- it doesn't relist from the API server (which is what most people thought it did). All it does is force a re-reconcile of everything in the cache. Generally, you probably don't want to do this -- it's often expensive, it'll mask subtle bugs, and it's usually not necessary. It's actually probably fine to set this to never, except it might save you in production if you've got bugs in your reconcile logic because you didn't write a level-based controller.

The only place, IMO, it's actually reasonable to use this knob, is if you're writing something that needs periodic reconcilation, like a horizontal pod autoscaler, but we'd recommend using RequeueAfter or a custom event source implementation to do this instead.

Does that mostly answer your question?

[DirectXMan12]

(as for why the flink operator sets it so low, I'm not sure, except that perhaps they mistakenly copied it from elsewhere. The spark operator probably just copied the sample-controller code, which copied something else, which copied something else, until nobody actually remembered what the option did in the first place)

[enisoc]

@DirectXMan12 wrote:

it doesn't relist from the API server

This setting seems to get passed down to sharedIndexInformer.defaultEventHandlerResyncPeriod, which I've previously used to set the relist period, and I recall that it seemed to work, based on seeing the watches being stopped and restarted in the logs. Has this changed?

[DirectXMan12]

defaultEventHandlerResyncPeriod is used in AddEventHandler to call AddEventHandlerWithResyncPeriod, which in turn sets s.resyncCheckPeriod, which in turn is passed to Config as FullResyncPeriod, which is in turn passed to NewReflector to be the reflector's resync period. That in turn gets used to set up a timer, which regularly calls store.Resync. Now, store.Resync has no godoc in the interface, but we can check the actual implementations to see what it does it reality. practically, for the cache implementation, it calls cacheStorage.Resync and says "touches all the items in the store force processing". Same with ExpirationCache. Of the store implementations, threadSafeMap does nothing, DeltaFifo lists from the cache, and FIFO does the same FIFO.

So, at the very least, we know it lists from the cache. If we go back up the stack to the reflector, we can see that the listwatcher is called in ListAndWatch. .List is only called once at the beginning of that function (modulo paging support).

If we then check ListAndWatch, it's called via a wait.Until, whose period is r.period. period is hard-coded to time.Second in NewNamedReflector, and not changed elsewhere.

The last place to check would be to see if the go-routine that runs the resync loop in reflector.go interacts with the outside world. The only output mechasim it has is an error channel though, which only fires if Resync returns a non-nil error, which, looking at deltafifo and fifo, seems to only happen in cases of actual errors, or never, respectively.

From a concrete perspective, if we try with a controller-runtime and set a SyncPeriod of 10*time.Second, register the klog flags and pump the verbosity up to 10, the only logs that we see are forcing resync. If we had network traffic, we'd see request and response logs (which we do just before the list-watch starts).

TL;DR: I think may have done that a long time ago, but it hasn't been that way for a while now.

[enisoc]

Hm that's unfortunate because I've observed the watch stalling on rare occasions, leaving the cache to become more and more out-of-date over time. The relist would have mitigated this automatically, but if there's no more relist, then it appears my only recourse is to reboot the process.

[DirectXMan12]

o_O the watch shouldn't stall out ever. I'm surprised we don't time out and then trigger the reconnect. That sounds like a bug.

[DirectXMan12]

If you have more data on that, I'd love to see it (and probably SIG API machinery, too, since it's prob a reflector bug)

[enisoc]

My logs didn't have anything useful to report. I only see logs from controller-runtime and my own code. Will I get lower-level logs if I increase the log level? Do you have a recommended level to catch potential problems at the informer/reflector level without being too noisy to leave on all the time?

[DirectXMan12]

You'll have to call klog.InitFlags ATM to get lower-level info. Eventually, we'll get structured client-go logs (working on it :-P), and soon-ish we'll get the ability to direct klog to write to whatever logr implementation you're using (the PR landed, but there's some issues around compatibility that we have to resolve).

[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

[enisoc]

Just to close the loop on my report of the watch stalling: I ended up turning on detailed logging, but also at the same time updating to k8s-1.13.x-based operator-sdk. I haven't seen any watches stall since then.

[DirectXMan12]

(closing as per above response)