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

SharedIndexInformer EventHandler sees double updates at resync interval #2812

Closed
shawkins opened this issue Feb 15, 2021 · 6 comments · Fixed by #2964
Closed

SharedIndexInformer EventHandler sees double updates at resync interval #2812

shawkins opened this issue Feb 15, 2021 · 6 comments · Fixed by #2964
Assignees
Labels
Milestone

Comments

@shawkins
Copy link
Contributor

shawkins commented Feb 15, 2021

Creating an informer with an Eventhandler similar to this:

informerFactory = client.informers();
informer = informerFactory.sharedIndexInformerFor(MyCustomResource.class, MyCustomResourceList.class, 30000);
informer.addEventHandler(new ResourceEventHandler() {
   public void onUpdate(ManagedKafkaAgent oldObj, ManagedKafkaAgent newObj) {
     //some action             
   }
   ...
});
informerFactory.startAllRegisteredInformers();

Results in the onUpdate method being called twice for every resource on the resync interval. Is that expected?

@manusa
Copy link
Member

manusa commented Mar 24, 2021

We should compare what happens in the analogous operation for client-go.

@rohanKanojia rohanKanojia self-assigned this Mar 29, 2021
@rohanKanojia
Copy link
Member

I tried this on client-go and it doesn't look like they also get double updates. So a code like this:

func (c *PodLoggingController) podAdd(obj interface{}) {
        pod := obj.(*v1.Pod)
        klog.Infof("POD CREATED: %s/%s", pod.Namespace, pod.Name)
}

func (c *PodLoggingController) podUpdate(old, new interface{}) {
        oldPod := old.(*v1.Pod)
        newPod := new.(*v1.Pod)
        klog.Infof(
                "POD UPDATED. %s/%s %s",
                oldPod.Namespace, oldPod.Name, newPod.Status.Phase,
        )
}

func (c *PodLoggingController) podDelete(obj interface{}) {
        pod := obj.(*v1.Pod)
        klog.Infof("POD DELETED: %s/%s", pod.Namespace, pod.Name)
}

// NewPodLoggingController creates a PodLoggingController
func NewPodLoggingController(informerFactory informers.SharedInformerFactory) *PodLoggingController {
        podInformer := informerFactory.Core().V1().Pods()

        c := &PodLoggingController{
                informerFactory: informerFactory,
                podInformer:     podInformer,
        }
        podInformer.Informer().AddEventHandler(
                // Your custom resource event handlers.
                cache.ResourceEventHandlerFuncs{
                        // Called on creation
                        AddFunc: c.podAdd,
                        // Called on resource update and every resyncPeriod on existing resources.
                        UpdateFunc: c.podUpdate,
                        // Called on resource deletion.
                        DeleteFunc: c.podDelete,
                },
        )
        return c
}

This seems to produce the following output:

informer : $  KUBECONFIG=~/.kube/config go run informer.go
I0330 11:32:50.108272   12626 informer.go:42] POD CREATED: kube-system/kube-controller-manager-minikube
I0330 11:32:50.108343   12626 informer.go:42] POD CREATED: kube-system/kube-proxy-r8ptm
I0330 11:32:50.108351   12626 informer.go:42] POD CREATED: kube-system/kube-scheduler-minikube
I0330 11:32:50.108359   12626 informer.go:42] POD CREATED: kube-system/storage-provisioner
I0330 11:32:50.108382   12626 informer.go:42] POD CREATED: rokumar/ex964p9
I0330 11:32:50.108395   12626 informer.go:42] POD CREATED: kube-system/coredns-74ff55c5b-fs7xc
I0330 11:32:50.108408   12626 informer.go:42] POD CREATED: kube-system/etcd-minikube
I0330 11:32:50.108413   12626 informer.go:42] POD CREATED: kube-system/kube-apiserver-minikube


I0330 11:33:00.109416   12626 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0330 11:33:00.109671   12626 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0330 11:33:00.109779   12626 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0330 11:33:00.109829   12626 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0330 11:33:00.109845   12626 informer.go:48] POD UPDATED. rokumar/ex964p9 Running
I0330 11:33:00.109861   12626 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0330 11:33:00.109873   12626 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running
I0330 11:33:00.109895   12626 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running


I0330 11:33:10.109422   12626 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running
I0330 11:33:10.109515   12626 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0330 11:33:10.109590   12626 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0330 11:33:10.109630   12626 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0330 11:33:10.109742   12626 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0330 11:33:10.109814   12626 informer.go:48] POD UPDATED. rokumar/ex964p9 Running
I0330 11:33:10.109849   12626 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0330 11:33:10.109886   12626 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running


I0330 11:33:20.109847   12626 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0330 11:33:20.109919   12626 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running
I0330 11:33:20.109963   12626 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running
I0330 11:33:20.109990   12626 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0330 11:33:20.110066   12626 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0330 11:33:20.110101   12626 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0330 11:33:20.110169   12626 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0330 11:33:20.110231   12626 informer.go:48] POD UPDATED. rokumar/ex964p9 Running

But similar code on Fabric8 Kubernetes Client seem to be generating double updates on resync intervals:

INFO: Starting all registered informers
[informer-controller-Pod] INFO io.fabric8.kubernetes.client.informers.cache.Controller - informer#Controller: ready to run resync and reflector runnable
[informer-controller-Pod] INFO io.fabric8.kubernetes.client.informers.cache.Reflector - Started ReflectorRunnable watch for class io.fabric8.kubernetes.api.model.Pod
Pod kube-system/coredns-74ff55c5b-fs7xc got added
Pod kube-system/coredns-74ff55c5b-fs7xc got updated
Pod kube-system/etcd-minikube got added
Pod kube-system/etcd-minikube got updated
Pod kube-system/kube-apiserver-minikube got added
Pod kube-system/kube-apiserver-minikube got updated
Pod kube-system/kube-controller-manager-minikube got added
Pod kube-system/kube-controller-manager-minikube got updated
Pod kube-system/kube-proxy-r8ptm got added
Pod kube-system/kube-proxy-r8ptm got updated
Pod kube-system/kube-scheduler-minikube got added
Pod kube-system/kube-scheduler-minikube got updated
Pod kube-system/storage-provisioner got added
Pod kube-system/storage-provisioner got updated
Pod rokumar/ex964p9 got added
Pod rokumar/ex964p9 got updated


Pod kube-system/kube-apiserver-minikube got updated
Pod kube-system/kube-controller-manager-minikube got updated
Pod rokumar/ex964p9 got updated
Pod kube-system/kube-scheduler-minikube got updated
Pod kube-system/storage-provisioner got updated
Pod kube-system/etcd-minikube got updated
Pod kube-system/coredns-74ff55c5b-fs7xc got updated
Pod kube-system/kube-proxy-r8ptm got updated
Pod kube-system/coredns-74ff55c5b-fs7xc got updated
Pod kube-system/etcd-minikube got updated
Pod kube-system/kube-apiserver-minikube got updated
Pod kube-system/kube-controller-manager-minikube got updated
Pod kube-system/kube-proxy-r8ptm got updated
Pod kube-system/kube-scheduler-minikube got updated
Pod kube-system/storage-provisioner got updated
Pod rokumar/ex964p9 got updated

I think somehow we're updating the cache twice during resync intervals

@rohanKanojia
Copy link
Member

I think we're triggering cache update at these two places here:

In Controller, we are scheduling execution for ResyncRunnable which calls store.resync()

resyncFuture = resyncExecutor.scheduleAtFixedRate(resyncRunnable, fullResyncPeriod, fullResyncPeriod, TimeUnit.MILLISECONDS);

In Reflector.scheduleResyncExecution we're scheduling execution for Reflector.relistAndSync which calls store.replace with all items received in list call

resyncExecutor.scheduleWithFixedDelay(this::reListAndSync, 0L, resyncPeriodMillis, TimeUnit.MILLISECONDS);

I think if we remove one of them, we'll be able to see correct behavior.

@rohanKanojia
Copy link
Member

rohanKanojia commented Mar 31, 2021

Looks like client-go resync mechanism is purely in-memory and doesn't trigger a call to the server. Here are sample logs with verbose logs in which we can see calls to the API server are only done in the beginning

I0331 16:37:35.239762   41318 loader.go:375] Config loaded from file:  /home/rohaan/.kube/config
I0331 16:37:35.240417   41318 cert_rotation.go:137] Starting client certificate rotation controller
I0331 16:37:35.241361   41318 reflector.go:175] Starting reflector *v1.Pod (10s) from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:125
I0331 16:37:35.241373   41318 reflector.go:211] Listing and watching *v1.Pod from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:125
I0331 16:37:35.241468   41318 round_trippers.go:420] GET https://192.168.39.93:8443/api/v1/pods?limit=500&resourceVersion=0
I0331 16:37:35.241479   41318 round_trippers.go:427] Request Headers:
I0331 16:37:35.241492   41318 round_trippers.go:431]     Accept: application/json, */*
I0331 16:37:35.241498   41318 round_trippers.go:431]     User-Agent: informer/v0.0.0 (linux/amd64) kubernetes/$Format
I0331 16:37:35.248295   41318 round_trippers.go:446] Response Status: 200 OK in 6 milliseconds
I0331 16:37:35.254015   41318 round_trippers.go:420] GET https://192.168.39.93:8443/api/v1/pods?allowWatchBookmarks=true&resourceVersion=67629&timeout=8m1s&timeoutSeconds=481&watch=true
I0331 16:37:35.254028   41318 round_trippers.go:427] Request Headers:
I0331 16:37:35.254038   41318 round_trippers.go:431]     Accept: application/json, */*
I0331 16:37:35.254047   41318 round_trippers.go:431]     User-Agent: informer/v0.0.0 (linux/amd64) kubernetes/$Format
I0331 16:37:35.254082   41318 informer.go:42] POD CREATED: kube-system/kube-scheduler-minikube
I0331 16:37:35.254101   41318 informer.go:42] POD CREATED: rokumar/ex964p9
I0331 16:37:35.254108   41318 informer.go:42] POD CREATED: default/code-with-quarkus-dbb76b8c6-n6478
I0331 16:37:35.254117   41318 informer.go:42] POD CREATED: kube-system/etcd-minikube
I0331 16:37:35.254121   41318 informer.go:42] POD CREATED: kube-system/kube-controller-manager-minikube
I0331 16:37:35.254126   41318 informer.go:42] POD CREATED: kube-system/kube-proxy-r8ptm
I0331 16:37:35.254131   41318 informer.go:42] POD CREATED: kube-system/storage-provisioner
I0331 16:37:35.254134   41318 informer.go:42] POD CREATED: kube-system/coredns-74ff55c5b-fs7xc
I0331 16:37:35.254138   41318 informer.go:42] POD CREATED: kube-system/kube-apiserver-minikube
I0331 16:37:35.254845   41318 round_trippers.go:446] Response Status: 200 OK in 0 milliseconds
I0331 16:37:35.341523   41318 shared_informer.go:253] caches populated

I0331 16:37:45.254358   41318 reflector.go:336] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:125: forcing resync
I0331 16:37:45.254691   41318 informer.go:48] POD UPDATED. default/code-with-quarkus-dbb76b8c6-n6478 Running
I0331 16:37:45.254835   41318 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0331 16:37:45.254900   41318 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0331 16:37:45.254980   41318 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0331 16:37:45.255017   41318 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0331 16:37:45.255039   41318 informer.go:48] POD UPDATED. rokumar/ex964p9 Running
I0331 16:37:45.255068   41318 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running
I0331 16:37:45.255106   41318 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0331 16:37:45.255127   41318 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running

I0331 16:37:55.254704   41318 reflector.go:336] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:125: forcing resync
I0331 16:37:55.254922   41318 informer.go:48] POD UPDATED. default/code-with-quarkus-dbb76b8c6-n6478 Running
I0331 16:37:55.255079   41318 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0331 16:37:55.255141   41318 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0331 16:37:55.255169   41318 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0331 16:37:55.255247   41318 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0331 16:37:55.255329   41318 informer.go:48] POD UPDATED. rokumar/ex964p9 Running
I0331 16:37:55.255372   41318 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running
I0331 16:37:55.255435   41318 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0331 16:37:55.255480   41318 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running

I0331 16:38:05.255147   41318 reflector.go:336] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:125: forcing resync
I0331 16:38:05.255641   41318 informer.go:48] POD UPDATED. rokumar/ex964p9 Running
I0331 16:38:05.255802   41318 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running
I0331 16:38:05.255974   41318 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0331 16:38:05.256092   41318 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running
I0331 16:38:05.256208   41318 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0331 16:38:05.256341   41318 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0331 16:38:05.256417   41318 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0331 16:38:05.256461   41318 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0331 16:38:05.256543   41318 informer.go:48] POD UPDATED. default/code-with-quarkus-dbb76b8c6-n6478 Running

I0331 16:38:15.255693   41318 reflector.go:336] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:125: forcing resync
I0331 16:38:15.255945   41318 informer.go:48] POD UPDATED. default/code-with-quarkus-dbb76b8c6-n6478 Running
I0331 16:38:15.256005   41318 informer.go:48] POD UPDATED. kube-system/kube-controller-manager-minikube Running
I0331 16:38:15.256061   41318 informer.go:48] POD UPDATED. kube-system/kube-proxy-r8ptm Running
I0331 16:38:15.256129   41318 informer.go:48] POD UPDATED. kube-system/storage-provisioner Running
I0331 16:38:15.256215   41318 informer.go:48] POD UPDATED. kube-system/kube-scheduler-minikube Running
I0331 16:38:15.256367   41318 informer.go:48] POD UPDATED. rokumar/ex964p9 Running
I0331 16:38:15.256421   41318 informer.go:48] POD UPDATED. kube-system/etcd-minikube Running
I0331 16:38:15.256448   41318 informer.go:48] POD UPDATED. kube-system/coredns-74ff55c5b-fs7xc Running
I0331 16:38:15.256481   41318 informer.go:48] POD UPDATED. kube-system/kube-apiserver-minikube Running

Right now we're having that in memory resync too(which is ResyncRunnable). I think we are doing an extra periodic relistAndSync

@manusa
Copy link
Member

manusa commented Mar 31, 2021

Given that the SharedInformer is purely a client-go feature, our implementation should strictly align with what client-go does.

In understand that users using this feature assume that the behavior will be the same as if the same logic was implemented using go.

rohanKanojia added a commit to rohanKanojia/kubernetes-client that referenced this issue Mar 31, 2021
…tes at resync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
rohanKanojia added a commit to rohanKanojia/kubernetes-client that referenced this issue Apr 5, 2021
…tes at resync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
rohanKanojia added a commit to rohanKanojia/kubernetes-client that referenced this issue Apr 5, 2021
…tes at resync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
rohanKanojia added a commit to rohanKanojia/kubernetes-client that referenced this issue Apr 5, 2021
…tes at resync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
rohanKanojia added a commit to rohanKanojia/kubernetes-client that referenced this issue Apr 5, 2021
…tes at resync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
@rohanKanojia
Copy link
Member

rohanKanojia commented Apr 6, 2021

Here is a reference to Client Go's reflector.Run(): tools/cache/reflector.go#L218

This is where resync seems to be called: reflector.go#L382 which delegates to delta_fifo's Resync(): tools/cache/delta_fifo.go#L651

manusa pushed a commit to rohanKanojia/kubernetes-client that referenced this issue Apr 6, 2021
…tes at resync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
manusa pushed a commit that referenced this issue Apr 6, 2021
…sync interval

+ Remove scheduleAtFixedDelay execution of Reflector#resyncAndList(),
  resync should happen in memory without contacting the apiserver just
  like client go implementation
+ Added logic for watch.close() when Reflector#stop() is called
@manusa manusa added this to the 5.3.0 milestone Apr 8, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
3 participants