Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Why resync default is so large - 10hours #521

Closed
skonto opened this issue Jul 17, 2019 · 17 comments
Closed

Why resync default is so large - 10hours #521

skonto opened this issue Jul 17, 2019 · 17 comments
Labels
lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale.

Comments

@skonto
Copy link

skonto commented Jul 17, 2019

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
Copy link
Contributor

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
Copy link
Contributor

(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
Copy link

enisoc commented Aug 22, 2019

@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
Copy link
Contributor

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
Copy link

enisoc commented Aug 22, 2019

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link

enisoc commented Aug 22, 2019

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
Copy link
Contributor

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
Copy link

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

@k8s-ci-robot k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Dec 2, 2019
@enisoc
Copy link

enisoc commented Dec 2, 2019

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
Copy link
Contributor

(closing as per above response)

ffilippopoulos added a commit to utilitywarehouse/semaphore-wireguard that referenced this issue Apr 27, 2021
Using the default 0 duration period should instruct the watchers to avoid
re-listing from cache and getting onUpdate calls.
We should not need this, since our reconcile logic is retrying if an event fails
to update wg peers and never lets go.
kubernetes-sigs/controller-runtime#521 (comment)
If a watcher fails to connect to apiservers for a while it should be able to
sync when is back online and create sufficient events to sync our peers again:
https://kubernetes.io/docs/reference/using-api/api-concepts/#efficient-detection-of-changes
shaneutt added a commit to Kong/kubernetes-ingress-controller that referenced this issue Jul 8, 2021
This patch adds the --sync-period flag back and delivers
the provided time duration to controller runtime, which
now in v2 handles the relevant client-go configuration on
our behalf (whereas in v1 we used it directly).

We now use the default value of 48 hours instead of the
value we previously used in v1 of 10 minutes, as per the
improvements and context relevant to the setting which make
relying on it no longer necessary.

See also: kubernetes-sigs/controller-runtime#521
shaneutt added a commit to Kong/kubernetes-ingress-controller that referenced this issue Jul 8, 2021
This patch adds the --sync-period flag back and delivers
the provided time duration to controller runtime, which
now in v2 handles the relevant client-go configuration on
our behalf (whereas in v1 we used it directly).

We now use the default value of 48 hours instead of the
value we previously used in v1 of 10 minutes, as per the
improvements and context relevant to the setting which make
relying on it no longer necessary.

See also: kubernetes-sigs/controller-runtime#521
@akashjain971
Copy link

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 can you please tell me how to set SyncPeriod as never? I don't see a way to set time.Duration as never in Golang.

tiraboschi added a commit to tiraboschi/hyperconverged-cluster-operator that referenced this issue Oct 26, 2022
If not explicitly set on its CR,
HCO webhook is consuming TLS configuration
from Openshift cluster-wide APIServer CR.
For performance reason it's not reading it on each request
to the HCO CR but it's consuming a cached representation.
The cache was only refreshed by a controller
based on an informer.
We got reports that due to the nature
of changes in the APIServer CR, the connection
to the APIserver itself could become stuck:
```
W1025 13:50:16.898592       1 reflector.go:424] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
E1025 13:50:16.898683       1 reflector.go:140] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: Failed to watch *v1.APIServer: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
I1025 13:50:43.182360       1 trace.go:205] Trace[621733159]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:19.338) (total time: 23843ms):
Trace[621733159]: ---"Objects listed" error:<nil> 23843ms (13:50:43.182)
Trace[621733159]: [23.843677488s] [23.843677488s] END
I1025 13:50:43.716723       1 trace.go:205] Trace[255710357]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:12.260) (total time: 31456ms):
Trace[255710357]: ---"Objects listed" error:<nil> 31456ms (13:50:43.716)
Trace[255710357]: [31.45666834s] [31.45666834s] END
I1025 13:50:43.968506       1 trace.go:205] Trace[2001360213]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:11.520) (total time: 32447ms):
Trace[2001360213]: ---"Objects listed" error:<nil> 32447ms (13:50:43.968)
Trace[2001360213]: [32.44785055s] [32.44785055s] END
```

On controller runtime the default SyncPeriod when all the
watched resources are refreshed is 10 hourse (
see kubernetes-sigs/controller-runtime#521
for its reasons) but it appears
too long for this specific use case.

Let's ensure we read the APIServer CR at least once every minute.

Make the logs less verbose.

Fixes: https://bugzilla.redhat.com/show_bug.cgi?id=2137896

Remove this once kubernetes-sigs/controller-runtime#2032
is properly addressed

Signed-off-by: Simone Tiraboschi <stirabos@redhat.com>
kubevirt-bot pushed a commit to kubevirt/hyperconverged-cluster-operator that referenced this issue Nov 2, 2022
If not explicitly set on its CR,
HCO webhook is consuming TLS configuration
from Openshift cluster-wide APIServer CR.
For performance reason it's not reading it on each request
to the HCO CR but it's consuming a cached representation.
The cache was only refreshed by a controller
based on an informer.
We got reports that due to the nature
of changes in the APIServer CR, the connection
to the APIserver itself could become stuck:
```
W1025 13:50:16.898592       1 reflector.go:424] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
E1025 13:50:16.898683       1 reflector.go:140] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: Failed to watch *v1.APIServer: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
I1025 13:50:43.182360       1 trace.go:205] Trace[621733159]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:19.338) (total time: 23843ms):
Trace[621733159]: ---"Objects listed" error:<nil> 23843ms (13:50:43.182)
Trace[621733159]: [23.843677488s] [23.843677488s] END
I1025 13:50:43.716723       1 trace.go:205] Trace[255710357]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:12.260) (total time: 31456ms):
Trace[255710357]: ---"Objects listed" error:<nil> 31456ms (13:50:43.716)
Trace[255710357]: [31.45666834s] [31.45666834s] END
I1025 13:50:43.968506       1 trace.go:205] Trace[2001360213]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:11.520) (total time: 32447ms):
Trace[2001360213]: ---"Objects listed" error:<nil> 32447ms (13:50:43.968)
Trace[2001360213]: [32.44785055s] [32.44785055s] END
```

On controller runtime the default SyncPeriod when all the
watched resources are refreshed is 10 hourse (
see kubernetes-sigs/controller-runtime#521
for its reasons) but it appears
too long for this specific use case.

Let's ensure we read the APIServer CR at least once every minute.

Make the logs less verbose.

Fixes: https://bugzilla.redhat.com/show_bug.cgi?id=2137896

Remove this once kubernetes-sigs/controller-runtime#2032
is properly addressed

Signed-off-by: Simone Tiraboschi <stirabos@redhat.com>

Signed-off-by: Simone Tiraboschi <stirabos@redhat.com>
kubevirt-bot pushed a commit to kubevirt-bot/hyperconverged-cluster-operator that referenced this issue Nov 2, 2022
If not explicitly set on its CR,
HCO webhook is consuming TLS configuration
from Openshift cluster-wide APIServer CR.
For performance reason it's not reading it on each request
to the HCO CR but it's consuming a cached representation.
The cache was only refreshed by a controller
based on an informer.
We got reports that due to the nature
of changes in the APIServer CR, the connection
to the APIserver itself could become stuck:
```
W1025 13:50:16.898592       1 reflector.go:424] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
E1025 13:50:16.898683       1 reflector.go:140] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: Failed to watch *v1.APIServer: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
I1025 13:50:43.182360       1 trace.go:205] Trace[621733159]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:19.338) (total time: 23843ms):
Trace[621733159]: ---"Objects listed" error:<nil> 23843ms (13:50:43.182)
Trace[621733159]: [23.843677488s] [23.843677488s] END
I1025 13:50:43.716723       1 trace.go:205] Trace[255710357]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:12.260) (total time: 31456ms):
Trace[255710357]: ---"Objects listed" error:<nil> 31456ms (13:50:43.716)
Trace[255710357]: [31.45666834s] [31.45666834s] END
I1025 13:50:43.968506       1 trace.go:205] Trace[2001360213]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:11.520) (total time: 32447ms):
Trace[2001360213]: ---"Objects listed" error:<nil> 32447ms (13:50:43.968)
Trace[2001360213]: [32.44785055s] [32.44785055s] END
```

On controller runtime the default SyncPeriod when all the
watched resources are refreshed is 10 hourse (
see kubernetes-sigs/controller-runtime#521
for its reasons) but it appears
too long for this specific use case.

Let's ensure we read the APIServer CR at least once every minute.

Make the logs less verbose.

Fixes: https://bugzilla.redhat.com/show_bug.cgi?id=2137896

Remove this once kubernetes-sigs/controller-runtime#2032
is properly addressed

Signed-off-by: Simone Tiraboschi <stirabos@redhat.com>
kubevirt-bot added a commit to kubevirt/hyperconverged-cluster-operator that referenced this issue Nov 7, 2022
If not explicitly set on its CR,
HCO webhook is consuming TLS configuration
from Openshift cluster-wide APIServer CR.
For performance reason it's not reading it on each request
to the HCO CR but it's consuming a cached representation.
The cache was only refreshed by a controller
based on an informer.
We got reports that due to the nature
of changes in the APIServer CR, the connection
to the APIserver itself could become stuck:
```
W1025 13:50:16.898592       1 reflector.go:424] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
E1025 13:50:16.898683       1 reflector.go:140] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262: Failed to watch *v1.APIServer: failed to list *v1.APIServer: Get "https://172.30.0.1:443/apis/config.openshift.io/v1/apiservers?resourceVersion=1572273": dial tcp 172.30.0.1:443: connect: connection refused
I1025 13:50:43.182360       1 trace.go:205] Trace[621733159]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:19.338) (total time: 23843ms):
Trace[621733159]: ---"Objects listed" error:<nil> 23843ms (13:50:43.182)
Trace[621733159]: [23.843677488s] [23.843677488s] END
I1025 13:50:43.716723       1 trace.go:205] Trace[255710357]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:12.260) (total time: 31456ms):
Trace[255710357]: ---"Objects listed" error:<nil> 31456ms (13:50:43.716)
Trace[255710357]: [31.45666834s] [31.45666834s] END
I1025 13:50:43.968506       1 trace.go:205] Trace[2001360213]: "Reflector ListAndWatch" name:sigs.k8s.io/controller-runtime/pkg/cache/internal/informers_map.go:262 (25-Oct-2022 13:50:11.520) (total time: 32447ms):
Trace[2001360213]: ---"Objects listed" error:<nil> 32447ms (13:50:43.968)
Trace[2001360213]: [32.44785055s] [32.44785055s] END
```

On controller runtime the default SyncPeriod when all the
watched resources are refreshed is 10 hourse (
see kubernetes-sigs/controller-runtime#521
for its reasons) but it appears
too long for this specific use case.

Let's ensure we read the APIServer CR at least once every minute.

Make the logs less verbose.

Fixes: https://bugzilla.redhat.com/show_bug.cgi?id=2137896

Remove this once kubernetes-sigs/controller-runtime#2032
is properly addressed

Signed-off-by: Simone Tiraboschi <stirabos@redhat.com>

Signed-off-by: Simone Tiraboschi <stirabos@redhat.com>
Co-authored-by: Simone Tiraboschi <stirabos@redhat.com>
@baldorch
Copy link

baldorch commented Feb 8, 2023

@akashjain971 Although you most probably found an answer to your question or have solved your problem in another way, I want to include the answer for everyone else who wonders:

time.Duration is an int64 and the Documentation for NewSharedIndexInformer states:

The created informer will not do resyncs if the given defaultEventHandlerResyncPeriod is zero.

Therefore I guess passing 0 will turn the resync off.

@DirectXMan12 Thank you very much for your elaborate answers in this issue. Very much appreciated!

@alexellis
Copy link

This is an old issue, but @stefanprodan sent me here and it was really helpful.

Sample controller should really be updated to use a similar time like the 10 hours we see in controller-runtime:

https://github.com/kubernetes/sample-controller/blob/61b24c8606ee48b75a878caf3827311d4483b1f9/main.go#L66

cc @dims

@dims
Copy link
Member

dims commented Oct 18, 2023

@alexellis could i persuade you to cut a PR for sample-controller? pretty please!

@stefanprodan
Copy link

stefanprodan commented Oct 18, 2023

Maybe the sample-controller should be archived and its readme could point to kubebuilder and controller-runtime. To avoid people start their controller journey with sample-controller, it served us well when we got started with controllers many years ago, but controller-runtime is by far so much better now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale.
Projects
None yet
Development

No branches or pull requests

10 participants