Re: [kubernetes/kubernetes] TestCascadingDeletion flaky [timed out waiting for the condition] (#56121)

[TigerXu]

I do not think the timeout reduce lead to more flaky. I have a thought, fake happens when Sync routine run after rc deleted and also Run routine misses the rc delete event. We can add explicit sleep after setup start two routines to see if flakes reduced.

—
You are receiving this because you are on a team that was mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

[Dan Mace]

I think @caesarxuchao has been chasing this one for a long time; I want to take a look with fresh eyes and see if I can find a root cause. I'll let @caesarxuchao decide which prior issue to re-open so we can cut down on duplicate issues.

[Dan Mace]

Good news is I was able to reproduce the issue with stress (took ~300 iterations to trigger).

[Chao Xu]

@ironcladlou Previously I found two root causes and fixed them, so I closed the previous issues. Not sure what's the cause of this recent flake.

[Dan Mace]

There’s a reflector backing the shared informer for replicationcontrollers, and sometimes (when this bug manifests), the reflector’s watch loop (ListWatch) is returning due to:

watch error: watch event(ok=%!s(bool=true), expectedType: *v1.ReplicationController): {ERROR &Status{ListMeta:ListMeta{SelfLink:,ResourceVersion:,Continue:,},Status:Failure,Message:too old resource version: 123872 (124014),Reason:Gone,Details:nil,Code:410,}}

and

k8s.io/kubernetes/vendor/k8s.io/client-go/informers/factory.go:86: watch of *v1.ReplicationController ended with: too old resource version: 129521 (129614)

When this happens, the reflector doesn’t restart ListWatch again until the full resync period hits. The net effect is the reflector isn't dispatching the rc events to the informer (and thus the GC), although given enough time (the resync period) I suspect things would self-repair.

This is perhaps somehow related to the watch cache. I first theorized that the replicationcontroller watch cache capacity was being reached sometimes, breaking the watch, but my latest debugging doesn't seem to prove it. The default capacity for replicationcontrollers in the test server setup is 100.

[Chao Xu]

When this happens, the reflector doesn’t restart ListWatch again until the full resync period hits.

It seems it restarts the ListWatch after r.period, which is always set to time.Second. (it's not the resync period).

[Dan Mace]

It seems it restarts the ListWatch after r.period, which is always set to time.Second. (it's not the resync period).

Good catch! That leads me down another path...

[Benjamin Elder]

This is the flakiest test in the repo:

• http://storage.googleapis.com/k8s-metrics/flakes-latest.json
• http://velodrome.k8s.io/dashboard/db/bigquery-metrics?orgId=1

[Jordan Liggitt]

this pattern seems common:

1. we get a watch failure on replication controllers, e.g. W1219 16:44:47.799199 23324 reflector.go:341] k8s.io/kubernetes/vendor/k8s.io/client-go/informers/factory.go:86: watch of *v1.ReplicationController ended with: too old resource version: 4291 (4860)
2. we are missing a graph_builder.go:588] GraphBuilder process object log message for the test.rc.1 replication controller

the only three events we have for test.rc.1:

• I1219 16:44:48.199297 23324 graph_builder.go:396] add virtual node.identity: [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.1, uid: ecaed94f-e4db-11e7-88ab-0242ac110002]
• I1219 16:44:48.199391 23324 garbagecollector.go:374] processing item [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.1, uid: ecaed94f-e4db-11e7-88ab-0242ac110002]
• I1219 16:44:48.209573 23324 garbagecollector.go:411] object [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.1, uid: ecaed94f-e4db-11e7-88ab-0242ac110002]'s doesn't have an owner, continue on next item

[Jordan Liggitt]

interestingly, the virtual node addition of test.rc.1 is usually within 1 second of the watch dropping, which would be within the window where the watch was down. opened #57419 with debugging logs

[Jordan Liggitt]

https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/57412/pull-kubernetes-unit/71699/artifacts/junit_e9d37341e9f7ab19ac436e5365ba6ae7c20eea71_20171219-164009.stdout

``` === RUN TestCascadingDeletion I1219 16:44:40.098299 23324 apiservice_controller.go:124] Shutting down APIServiceRegistrationController I1219 16:44:40.098360 23324 available_controller.go:274] Shutting down AvailableConditionController I1219 16:44:40.098402 23324 customresource_discovery_controller.go:163] Shutting down DiscoveryController I1219 16:44:40.098427 23324 naming_controller.go:285] Shutting down NamingConditionController I1219 16:44:40.098447 23324 crdregistration_controller.go:139] Shutting down crd-autoregister controller I1219 16:44:40.098427 23324 autoregister_controller.go:160] Shutting down autoregister controller I1219 16:44:40.098459 23324 crd_finalizer.go:254] Shutting down CRDFinalizer I1219 16:44:40.098542 23324 controller.go:90] Shutting down OpenAPI AggregationController I1219 16:44:40.098751 23324 serve.go:129] Stopped listening on [::]:34363 I1219 16:44:40.453915 23324 serving.go:295] Generated self-signed cert (/tmp/kubernetes-kube-apiserver709151440/apiserver.crt, /tmp/kubernetes-kube-apiserver709151440/apiserver.key) W1219 16:44:40.453952 23324 authentication.go:378] AnonymousAuth is not allowed with the AllowAll authorizer. Resetting AnonymousAuth to false. You should use a different authorizer I1219 16:44:40.605180 23324 master.go:225] Using reconciler: master-count [restful] 2017/12/19 16:44:40 log.go:33: [restful/swagger] listing is available at https://172.17.0.2:45589/swaggerapi [restful] 2017/12/19 16:44:40 log.go:33: [restful/swagger] https://172.17.0.2:45589/swaggerui/ is mapped to folder /swagger-ui/ [restful] 2017/12/19 16:44:42 log.go:33: [restful/swagger] listing is available at https://172.17.0.2:45589/swaggerapi [restful] 2017/12/19 16:44:42 log.go:33: [restful/swagger] https://172.17.0.2:45589/swaggerui/ is mapped to folder /swagger-ui/ I1219 16:44:47.340818 23324 serve.go:89] Serving securely on [::]:45589 I1219 16:44:47.340885 23324 apiservice_controller.go:112] Starting APIServiceRegistrationController I1219 16:44:47.340898 23324 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller I1219 16:44:47.341741 23324 crd_finalizer.go:242] Starting CRDFinalizer I1219 16:44:47.342442 23324 customresource_discovery_controller.go:152] Starting DiscoveryController I1219 16:44:47.342479 23324 naming_controller.go:274] Starting NamingConditionController I1219 16:44:47.342618 23324 controller.go:84] Starting OpenAPI AggregationController I1219 16:44:47.343019 23324 available_controller.go:262] Starting AvailableConditionController I1219 16:44:47.343044 23324 cache.go:32] Waiting for caches to sync for AvailableConditionController controller I1219 16:44:47.343495 23324 crdregistration_controller.go:110] Starting crd-autoregister controller I1219 16:44:47.343525 23324 controller_utils.go:1019] Waiting for caches to sync for crd-autoregister controller I1219 16:44:47.441127 23324 cache.go:39] Caches are synced for APIServiceRegistrationController controller I1219 16:44:47.443223 23324 cache.go:39] Caches are synced for AvailableConditionController controller I1219 16:44:47.443660 23324 controller_utils.go:1026] Caches are synced for crd-autoregister controller I1219 16:44:47.443769 23324 autoregister_controller.go:136] Starting autoregister controller I1219 16:44:47.443824 23324 cache.go:32] Waiting for caches to sync for autoregister controller I1219 16:44:47.544149 23324 cache.go:39] Caches are synced for autoregister controller I1219 16:44:47.738151 23324 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=daemonsets", kind "apps/v1, Kind=DaemonSet" I1219 16:44:47.738796 23324 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=rolebindings", kind "rbac.authorization.k8s.io/v1, Kind=RoleBinding" I1219 16:44:47.738929 23324 graph_builder.go:190] using a shared informer for resource "scheduling.k8s.io/v1alpha1, Resource=priorityclasses", kind "scheduling.k8s.io/v1alpha1, Kind=PriorityClass" I1219 16:44:47.739069 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=services", kind "/v1, Kind=Service" I1219 16:44:47.739155 23324 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=deployments", kind "apps/v1, Kind=Deployment" I1219 16:44:47.739294 23324 graph_builder.go:190] using a shared informer for resource "storage.k8s.io/v1, Resource=storageclasses", kind "storage.k8s.io/v1, Kind=StorageClass" I1219 16:44:47.739419 23324 graph_builder.go:190] using a shared informer for resource "admissionregistration.k8s.io/v1beta1, Resource=mutatingwebhookconfigurations", kind "admissionregistration.k8s.io/v1beta1, Kind=MutatingWebhookConfiguration" I1219 16:44:47.739616 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=replicationcontrollers", kind "/v1, Kind=ReplicationController" I1219 16:44:47.739731 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=endpoints", kind "/v1, Kind=Endpoints" I1219 16:44:47.739852 23324 graph_builder.go:190] using a shared informer for resource "batch/v1beta1, Resource=cronjobs", kind "batch/v1beta1, Kind=CronJob" I1219 16:44:47.739962 23324 graph_builder.go:190] using a shared informer for resource "policy/v1beta1, Resource=poddisruptionbudgets", kind "policy/v1beta1, Kind=PodDisruptionBudget" I1219 16:44:47.740078 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=pods", kind "/v1, Kind=Pod" I1219 16:44:47.740216 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=resourcequotas", kind "/v1, Kind=ResourceQuota" I1219 16:44:47.740405 23324 graph_builder.go:190] using a shared informer for resource "storage.k8s.io/v1alpha1, Resource=volumeattachments", kind "storage.k8s.io/v1alpha1, Kind=VolumeAttachment" I1219 16:44:47.740630 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=persistentvolumes", kind "/v1, Kind=PersistentVolume" I1219 16:44:47.740757 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=serviceaccounts", kind "/v1, Kind=ServiceAccount" I1219 16:44:47.740894 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=nodes", kind "/v1, Kind=Node" I1219 16:44:47.741109 23324 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=ingresses", kind "extensions/v1beta1, Kind=Ingress" I1219 16:44:47.741210 23324 graph_builder.go:190] using a shared informer for resource "autoscaling/v1, Resource=horizontalpodautoscalers", kind "autoscaling/v1, Kind=HorizontalPodAutoscaler" I1219 16:44:47.741338 23324 graph_builder.go:190] using a shared informer for resource "settings.k8s.io/v1alpha1, Resource=podpresets", kind "settings.k8s.io/v1alpha1, Kind=PodPreset" I1219 16:44:47.741439 23324 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=controllerrevisions", kind "apps/v1, Kind=ControllerRevision" I1219 16:44:47.741580 23324 graph_builder.go:190] using a shared informer for resource "events.k8s.io/v1beta1, Resource=events", kind "events.k8s.io/v1beta1, Kind=Event" I1219 16:44:47.741703 23324 graph_builder.go:190] using a shared informer for resource "admissionregistration.k8s.io/v1beta1, Resource=validatingwebhookconfigurations", kind "admissionregistration.k8s.io/v1beta1, Kind=ValidatingWebhookConfiguration" I1219 16:44:47.741960 23324 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=clusterrolebindings", kind "rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding" I1219 16:44:47.742128 23324 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=roles", kind "rbac.authorization.k8s.io/v1, Kind=Role" I1219 16:44:47.742245 23324 graph_builder.go:190] using a shared informer for resource "admissionregistration.k8s.io/v1alpha1, Resource=initializerconfigurations", kind "admissionregistration.k8s.io/v1alpha1, Kind=InitializerConfiguration" I1219 16:44:47.742462 23324 graph_builder.go:195] unable to use a shared informer for resource "extensions/v1beta1, Resource=networkpolicies", kind "extensions/v1beta1, Kind=NetworkPolicy": no informer found for {extensions v1beta1 networkpolicies} I1219 16:44:47.742507 23324 graph_builder.go:199] create storage for resource {extensions v1beta1 networkpolicies} I1219 16:44:47.742789 23324 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=deployments", kind "extensions/v1beta1, Kind=Deployment" I1219 16:44:47.742921 23324 graph_builder.go:190] using a shared informer for resource "batch/v1, Resource=jobs", kind "batch/v1, Kind=Job" I1219 16:44:47.743083 23324 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=clusterroles", kind "rbac.authorization.k8s.io/v1, Kind=ClusterRole" I1219 16:44:47.743353 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=configmaps", kind "/v1, Kind=ConfigMap" I1219 16:44:47.743575 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=namespaces", kind "/v1, Kind=Namespace" I1219 16:44:47.743804 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=podtemplates", kind "/v1, Kind=PodTemplate" I1219 16:44:47.743988 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=limitranges", kind "/v1, Kind=LimitRange" I1219 16:44:47.744220 23324 graph_builder.go:190] using a shared informer for resource "networking.k8s.io/v1, Resource=networkpolicies", kind "networking.k8s.io/v1, Kind=NetworkPolicy" I1219 16:44:47.744437 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=secrets", kind "/v1, Kind=Secret" I1219 16:44:47.744642 23324 graph_builder.go:190] using a shared informer for resource "/v1, Resource=persistentvolumeclaims", kind "/v1, Kind=PersistentVolumeClaim" I1219 16:44:47.744803 23324 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=replicasets", kind "extensions/v1beta1, Kind=ReplicaSet" I1219 16:44:47.744917 23324 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=podsecuritypolicies", kind "extensions/v1beta1, Kind=PodSecurityPolicy" I1219 16:44:47.745111 23324 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=daemonsets", kind "extensions/v1beta1, Kind=DaemonSet" I1219 16:44:47.745332 23324 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=replicasets", kind "apps/v1, Kind=ReplicaSet" I1219 16:44:47.745498 23324 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=statefulsets", kind "apps/v1, Kind=StatefulSet" I1219 16:44:47.745698 23324 graph_builder.go:190] using a shared informer for resource "certificates.k8s.io/v1beta1, Resource=certificatesigningrequests", kind "certificates.k8s.io/v1beta1, Kind=CertificateSigningRequest" I1219 16:44:47.745796 23324 graph_builder.go:263] synced monitors; added 43, kept 0, removed 0 I1219 16:44:47.745999 23324 garbagecollector.go:136] Starting garbage collector controller I1219 16:44:47.748325 23324 controller_utils.go:1019] Waiting for caches to sync for garbage collector controller I1219 16:44:47.748357 23324 graph_builder.go:321] GraphBuilder running I1219 16:44:47.748702 23324 graph_builder.go:295] started 43 new monitors, 43 currently running I1219 16:44:47.774874 23324 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name default, uid ec6dd62e-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:47.774992 23324 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name kube-system, uid ec70574d-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:47.775397 23324 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name kube-public, uid ec70e4ec-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:47.775494 23324 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name aval, uid ec99f4da-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:47.776594 23324 graph_builder.go:588] GraphBuilder process object: v1/Endpoints, namespace default, name kubernetes, uid ec6f50cf-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:47.786604 23324 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name gc-cascading-deletion, uid ecace303-e4db-11e7-88ab-0242ac110002, event type add W1219 16:44:47.799199 23324 reflector.go:341] k8s.io/kubernetes/vendor/k8s.io/client-go/informers/factory.go:86: watch of *v1.ReplicationController ended with: too old resource version: 4291 (4860) I1219 16:44:47.880786 23324 graph_builder.go:588] GraphBuilder process object: v1/Service, namespace default, name kubernetes, uid ec6ead45-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:48.017606 23324 graph_builder.go:588] GraphBuilder process object: v1/ServiceAccount, namespace aval, name default, uid ec9aa443-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:48.017668 23324 graph_builder.go:588] GraphBuilder process object: v1/ServiceAccount, namespace gc-cascading-deletion, name default, uid ecae361b-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:48.148587 23324 controller_utils.go:1026] Caches are synced for garbage collector controller I1219 16:44:48.148629 23324 garbagecollector.go:145] Garbage collector: all resource monitors have synced. Proceeding to collect garbage I1219 16:44:48.199224 23324 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.1, uid ecec42db-e4db-11e7-88ab-0242ac110002, event type add I1219 16:44:48.199297 23324 graph_builder.go:396] add virtual node.identity: [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.1, uid: ecaed94f-e4db-11e7-88ab-0242ac110002]

I1219 16:44:48.199391 23324 garbagecollector.go:374] processing item [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.1, uid: ecaed94f-e4db-11e7-88ab-0242ac110002]
I1219 16:44:48.209573 23324 garbagecollector.go:411] object [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.1, uid: ecaed94f-e4db-11e7-88ab-0242ac110002]'s doesn't have an owner, continue on next item

I1219 16:44:48.238847 23324 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.3, uid ecf26de2-e4db-11e7-88ab-0242ac110002, event type add
I1219 16:44:48.238913 23324 graph_builder.go:396] add virtual node.identity: [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.2, uid: ecaf8bc0-e4db-11e7-88ab-0242ac110002]

I1219 16:44:48.238970 23324 garbagecollector.go:374] processing item [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.2, uid: ecaf8bc0-e4db-11e7-88ab-0242ac110002]
I1219 16:44:48.241206 23324 garbagecollector.go:411] object [v1/ReplicationController, namespace: gc-cascading-deletion, name: test.rc.2, uid: ecaf8bc0-e4db-11e7-88ab-0242ac110002]'s doesn't have an owner, continue on next item
I1219 16:44:48.279013 23324 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.2, uid ecf876df-e4db-11e7-88ab-0242ac110002, event type add
I1219 16:44:48.657159 23324 garbagecollector.go:183] syncing garbage collector with updated resources from discovery: map[{ v1 events}:{} {rbac.authorization.k8s.io v1 roles}:{} {rbac.authorization.k8s.io v1 clusterrolebindings}:{} {storage.k8s.io v1alpha1 volumeattachments}:{} { v1 replicationcontrollers}:{} { v1 serviceaccounts}:{} { v1 limitranges}:{} {extensions v1beta1 ingresses}:{} {extensions v1beta1 daemonsets}:{} {apps v1 controllerrevisions}:{} {policy v1beta1 poddisruptionbudgets}:{} {settings.k8s.io v1alpha1 podpresets}:{} { v1 resourcequotas}:{} {apps v1 daemonsets}:{} {apps v1 replicasets}:{} {certificates.k8s.io v1beta1 certificatesigningrequests}:{} {admissionregistration.k8s.io v1beta1 validatingwebhookconfigurations}:{} { v1 configmaps}:{} {apps v1 statefulsets}:{} {admissionregistration.k8s.io v1beta1 mutatingwebhookconfigurations}:{} {scheduling.k8s.io v1alpha1 priorityclasses}:{} { v1 pods}:{} {extensions v1beta1 networkpolicies}:{} {batch v1beta1 cronjobs}:{} {networking.k8s.io v1 networkpolicies}:{} { v1 persistentvolumes}:{} { v1 secrets}:{} { v1 namespaces}:{} {extensions v1beta1 replicasets}:{} {events.k8s.io v1beta1 events}:{} {batch v1 jobs}:{} {rbac.authorization.k8s.io v1 rolebindings}:{} {admissionregistration.k8s.io v1alpha1 initializerconfigurations}:{} {extensions v1beta1 deployments}:{} {apps v1 deployments}:{} {storage.k8s.io v1 storageclasses}:{} { v1 podtemplates}:{} { v1 nodes}:{} { v1 persistentvolumeclaims}:{} { v1 services}:{} {apiregistration.k8s.io v1beta1 apiservices}:{} {extensions v1beta1 podsecuritypolicies}:{} {autoscaling v1 horizontalpodautoscalers}:{} {rbac.authorization.k8s.io v1 clusterroles}:{} {apiextensions.k8s.io v1beta1 customresourcedefinitions}:{} { v1 endpoints}:{}]
I1219 16:44:48.837813 23324 graph_builder.go:588] GraphBuilder process object: v1/ReplicationController, namespace gc-cascading-deletion, name test.rc.2, uid ecaf8bc0-e4db-11e7-88ab-0242ac110002, event type add
I1219 16:44:49.316790 23324 graph_builder.go:263] synced monitors; added 0, kept 43, removed 0
I1219 16:44:49.316840 23324 graph_builder.go:295] started 0 new monitors, 43 currently running
I1219 16:44:49.316860 23324 controller_utils.go:1019] Waiting for caches to sync for garbage collector controller
I1219 16:44:49.417177 23324 controller_utils.go:1026] Caches are synced for garbage collector controller
I1219 16:44:49.417222 23324 garbagecollector.go:220] synced garbage collector
I1219 16:44:54.447225 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:44:59.473854 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:04.500785 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:09.530108 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:14.562200 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:19.590412 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:24.611082 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:29.640088 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:34.663912 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:39.691322 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:44.717282 23324 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync
I1219 16:45:48.373161 23324 garbagecollector.go:154] Shutting down garbage collector controller
I1219 16:45:48.377971 23324 graph_builder.go:348] stopped 43 of 43 monitors
I1219 16:45:48.378008 23324 graph_builder.go:349] GraphBuilder stopping
--- FAIL: TestCascadingDeletion (68.31s)
testserver.go💯 Starting kube-apiserver on port 45589...
testserver.go:112: Waiting for /healthz to be ok...
garbage_collector_test.go:368: timed out waiting for the condition

</details>

[Jordan Liggitt]

successful test
https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/57322/pull-kubernetes-unit/71545/artifacts/junit_e9d37341e9f7ab19ac436e5365ba6ae7c20eea71_20171219-031024.stdout

``` === RUN TestCascadingDeletion I1219 03:15:04.123990 23030 naming_controller.go:285] Shutting down NamingConditionController I1219 03:15:04.124412 23030 crd_finalizer.go:254] Shutting down CRDFinalizer I1219 03:15:04.124508 23030 controller.go:90] Shutting down OpenAPI AggregationController I1219 03:15:04.124635 23030 apiservice_controller.go:124] Shutting down APIServiceRegistrationController I1219 03:15:04.124671 23030 autoregister_controller.go:160] Shutting down autoregister controller I1219 03:15:04.124690 23030 crdregistration_controller.go:139] Shutting down crd-autoregister controller I1219 03:15:04.124746 23030 customresource_discovery_controller.go:163] Shutting down DiscoveryController I1219 03:15:04.124770 23030 available_controller.go:274] Shutting down AvailableConditionController I1219 03:15:04.124973 23030 serve.go:129] Stopped listening on [::]:39145 I1219 03:15:04.295902 23030 serving.go:295] Generated self-signed cert (/tmp/kubernetes-kube-apiserver595085823/apiserver.crt, /tmp/kubernetes-kube-apiserver595085823/apiserver.key) I1219 03:15:04.295978 23030 server.go:644] external host was not specified, using 172.17.0.2 W1219 03:15:04.296017 23030 authentication.go:378] AnonymousAuth is not allowed with the AllowAll authorizer. Resetting AnonymousAuth to false. You should use a different authorizer I1219 03:15:04.484571 23030 master.go:225] Using reconciler: master-count [restful] 2017/12/19 03:15:04 log.go:33: [restful/swagger] listing is available at https://172.17.0.2:41105/swaggerapi [restful] 2017/12/19 03:15:04 log.go:33: [restful/swagger] https://172.17.0.2:41105/swaggerui/ is mapped to folder /swagger-ui/ [restful] 2017/12/19 03:15:05 log.go:33: [restful/swagger] listing is available at https://172.17.0.2:41105/swaggerapi [restful] 2017/12/19 03:15:05 log.go:33: [restful/swagger] https://172.17.0.2:41105/swaggerui/ is mapped to folder /swagger-ui/ I1219 03:15:11.263476 23030 serve.go:89] Serving securely on [::]:41105 I1219 03:15:11.269722 23030 available_controller.go:262] Starting AvailableConditionController I1219 03:15:11.269761 23030 cache.go:32] Waiting for caches to sync for AvailableConditionController controller I1219 03:15:11.269795 23030 crd_finalizer.go:242] Starting CRDFinalizer I1219 03:15:11.269813 23030 apiservice_controller.go:112] Starting APIServiceRegistrationController I1219 03:15:11.269837 23030 cache.go:32] Waiting for caches to sync for APIServiceRegistrationController controller I1219 03:15:11.269846 23030 controller.go:84] Starting OpenAPI AggregationController I1219 03:15:11.269900 23030 customresource_discovery_controller.go:152] Starting DiscoveryController I1219 03:15:11.269933 23030 naming_controller.go:274] Starting NamingConditionController I1219 03:15:11.270067 23030 crdregistration_controller.go:110] Starting crd-autoregister controller I1219 03:15:11.270097 23030 controller_utils.go:1019] Waiting for caches to sync for crd-autoregister controller I1219 03:15:11.369966 23030 cache.go:39] Caches are synced for AvailableConditionController controller I1219 03:15:11.370024 23030 cache.go:39] Caches are synced for APIServiceRegistrationController controller I1219 03:15:11.370302 23030 controller_utils.go:1026] Caches are synced for crd-autoregister controller I1219 03:15:11.370382 23030 autoregister_controller.go:136] Starting autoregister controller I1219 03:15:11.370407 23030 cache.go:32] Waiting for caches to sync for autoregister controller I1219 03:15:11.470614 23030 cache.go:39] Caches are synced for autoregister controller I1219 03:15:11.637995 23030 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=statefulsets", kind "apps/v1, Kind=StatefulSet" I1219 03:15:11.638152 23030 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=replicasets", kind "apps/v1, Kind=ReplicaSet" I1219 03:15:11.638254 23030 graph_builder.go:190] using a shared informer for resource "admissionregistration.k8s.io/v1alpha1, Resource=initializerconfigurations", kind "admissionregistration.k8s.io/v1alpha1, Kind=InitializerConfiguration" I1219 03:15:11.638378 23030 graph_builder.go:190] using a shared informer for resource "events.k8s.io/v1beta1, Resource=events", kind "events.k8s.io/v1beta1, Kind=Event" I1219 03:15:11.638475 23030 graph_builder.go:190] using a shared informer for resource "settings.k8s.io/v1alpha1, Resource=podpresets", kind "settings.k8s.io/v1alpha1, Kind=PodPreset" I1219 03:15:11.638566 23030 graph_builder.go:190] using a shared informer for resource "storage.k8s.io/v1alpha1, Resource=volumeattachments", kind "storage.k8s.io/v1alpha1, Kind=VolumeAttachment" I1219 03:15:11.638688 23030 graph_builder.go:190] using a shared informer for resource "admissionregistration.k8s.io/v1beta1, Resource=mutatingwebhookconfigurations", kind "admissionregistration.k8s.io/v1beta1, Kind=MutatingWebhookConfiguration" I1219 03:15:11.638804 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=configmaps", kind "/v1, Kind=ConfigMap" I1219 03:15:11.638924 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=services", kind "/v1, Kind=Service" I1219 03:15:11.639061 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=pods", kind "/v1, Kind=Pod" I1219 03:15:11.639155 23030 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=deployments", kind "extensions/v1beta1, Kind=Deployment" I1219 03:15:11.639258 23030 graph_builder.go:195] unable to use a shared informer for resource "extensions/v1beta1, Resource=networkpolicies", kind "extensions/v1beta1, Kind=NetworkPolicy": no informer found for {extensions v1beta1 networkpolicies} I1219 03:15:11.639295 23030 graph_builder.go:199] create storage for resource {extensions v1beta1 networkpolicies} I1219 03:15:11.639475 23030 graph_builder.go:190] using a shared informer for resource "batch/v1, Resource=jobs", kind "batch/v1, Kind=Job" I1219 03:15:11.639606 23030 graph_builder.go:190] using a shared informer for resource "batch/v1beta1, Resource=cronjobs", kind "batch/v1beta1, Kind=CronJob" I1219 03:15:11.639735 23030 graph_builder.go:190] using a shared informer for resource "certificates.k8s.io/v1beta1, Resource=certificatesigningrequests", kind "certificates.k8s.io/v1beta1, Kind=CertificateSigningRequest" I1219 03:15:11.639844 23030 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=clusterroles", kind "rbac.authorization.k8s.io/v1, Kind=ClusterRole" I1219 03:15:11.639930 23030 graph_builder.go:190] using a shared informer for resource "storage.k8s.io/v1, Resource=storageclasses", kind "storage.k8s.io/v1, Kind=StorageClass" I1219 03:15:11.640050 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=resourcequotas", kind "/v1, Kind=ResourceQuota" I1219 03:15:11.640150 23030 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=podsecuritypolicies", kind "extensions/v1beta1, Kind=PodSecurityPolicy" I1219 03:15:11.640245 23030 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=daemonsets", kind "extensions/v1beta1, Kind=DaemonSet" I1219 03:15:11.640342 23030 graph_builder.go:190] using a shared informer for resource "autoscaling/v1, Resource=horizontalpodautoscalers", kind "autoscaling/v1, Kind=HorizontalPodAutoscaler" I1219 03:15:11.640427 23030 graph_builder.go:190] using a shared informer for resource "admissionregistration.k8s.io/v1beta1, Resource=validatingwebhookconfigurations", kind "admissionregistration.k8s.io/v1beta1, Kind=ValidatingWebhookConfiguration" I1219 03:15:11.640543 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=persistentvolumes", kind "/v1, Kind=PersistentVolume" I1219 03:15:11.640697 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=limitranges", kind "/v1, Kind=LimitRange" I1219 03:15:11.640809 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=serviceaccounts", kind "/v1, Kind=ServiceAccount" I1219 03:15:11.640900 23030 graph_builder.go:190] using a shared informer for resource "networking.k8s.io/v1, Resource=networkpolicies", kind "networking.k8s.io/v1, Kind=NetworkPolicy" I1219 03:15:11.640982 23030 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=clusterrolebindings", kind "rbac.authorization.k8s.io/v1, Kind=ClusterRoleBinding" I1219 03:15:11.641090 23030 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=rolebindings", kind "rbac.authorization.k8s.io/v1, Kind=RoleBinding" I1219 03:15:11.641212 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=podtemplates", kind "/v1, Kind=PodTemplate" I1219 03:15:11.641334 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=persistentvolumeclaims", kind "/v1, Kind=PersistentVolumeClaim" I1219 03:15:11.641450 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=nodes", kind "/v1, Kind=Node" I1219 03:15:11.641561 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=replicationcontrollers", kind "/v1, Kind=ReplicationController" I1219 03:15:11.641671 23030 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=deployments", kind "apps/v1, Kind=Deployment" I1219 03:15:11.641760 23030 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=controllerrevisions", kind "apps/v1, Kind=ControllerRevision" I1219 03:15:11.641855 23030 graph_builder.go:190] using a shared informer for resource "policy/v1beta1, Resource=poddisruptionbudgets", kind "policy/v1beta1, Kind=PodDisruptionBudget" I1219 03:15:11.641936 23030 graph_builder.go:190] using a shared informer for resource "scheduling.k8s.io/v1alpha1, Resource=priorityclasses", kind "scheduling.k8s.io/v1alpha1, Kind=PriorityClass" I1219 03:15:11.642033 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=secrets", kind "/v1, Kind=Secret" I1219 03:15:11.642165 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=endpoints", kind "/v1, Kind=Endpoints" I1219 03:15:11.642261 23030 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=ingresses", kind "extensions/v1beta1, Kind=Ingress" I1219 03:15:11.642361 23030 graph_builder.go:190] using a shared informer for resource "extensions/v1beta1, Resource=replicasets", kind "extensions/v1beta1, Kind=ReplicaSet" I1219 03:15:11.642447 23030 graph_builder.go:190] using a shared informer for resource "apps/v1, Resource=daemonsets", kind "apps/v1, Kind=DaemonSet" I1219 03:15:11.642539 23030 graph_builder.go:190] using a shared informer for resource "rbac.authorization.k8s.io/v1, Resource=roles", kind "rbac.authorization.k8s.io/v1, Kind=Role" I1219 03:15:11.642680 23030 graph_builder.go:190] using a shared informer for resource "/v1, Resource=namespaces", kind "/v1, Kind=Namespace" I1219 03:15:11.642777 23030 graph_builder.go:263] synced monitors; added 43, kept 0, removed 0 I1219 03:15:11.642933 23030 garbagecollector.go:136] Starting garbage collector controller I1219 03:15:11.642959 23030 controller_utils.go:1019] Waiting for caches to sync for garbage collector controller I1219 03:15:11.642991 23030 graph_builder.go:321] GraphBuilder running I1219 03:15:11.643374 23030 graph_builder.go:295] started 43 new monitors, 43 currently running I1219 03:15:11.651175 23030 graph_builder.go:588] GraphBuilder process object: v1/Endpoints, namespace default, name kubernetes, uid d2d68602-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.665532 23030 graph_builder.go:588] GraphBuilder process object: v1/Service, namespace default, name kubernetes, uid d2d59ae8-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.665693 23030 graph_builder.go:588] GraphBuilder process object: v1/ServiceAccount, namespace aval, name default, uid d30000d7-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.820768 23030 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name default, uid d2d474d1-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.820835 23030 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name kube-system, uid d2d76ed6-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.820882 23030 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name kube-public, uid d2d82e23-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.820922 23030 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name aval, uid d2ff9e15-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.820965 23030 graph_builder.go:588] GraphBuilder process object: v1/Namespace, namespace , name gc-cascading-deletion, uid d30ce469-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.850952 23030 controller_utils.go:1026] Caches are synced for garbage collector controller I1219 03:15:11.850989 23030 garbagecollector.go:145] Garbage collector: all resource monitors have synced. Proceeding to collect garbage I1219 03:15:11.854102 23030 graph_builder.go:588] GraphBuilder process object: v1/ServiceAccount, namespace gc-cascading-deletion, name default, uid d32a4281-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.894776 23030 graph_builder.go:588] GraphBuilder process object: v1/ReplicationController, namespace gc-cascading-deletion, name test.rc.1, uid d33066fe-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:11.933628 23030 graph_builder.go:588] GraphBuilder process object: v1/ReplicationController, namespace gc-cascading-deletion, name test.rc.2, uid d336738c-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:12.014475 23030 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.1, uid d342ac05-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:12.053417 23030 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.3, uid d348c2ca-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:12.101088 23030 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.2, uid d34efbf1-e46a-11e7-aca8-0242ac110002, event type add I1219 03:15:12.174703 23030 graph_builder.go:588] GraphBuilder process object: v1/ReplicationController, namespace gc-cascading-deletion, name test.rc.1, uid d33066fe-e46a-11e7-aca8-0242ac110002, event type delete I1219 03:15:12.174798 23030 garbagecollector.go:374] processing item [v1/Pod, namespace: gc-cascading-deletion, name: test.pod.1, uid: d342ac05-e46a-11e7-aca8-0242ac110002] I1219 03:15:12.174826 23030 garbagecollector.go:374] processing item [v1/Pod, namespace: gc-cascading-deletion, name: test.pod.3, uid: d348c2ca-e46a-11e7-aca8-0242ac110002] I1219 03:15:12.181955 23030 garbagecollector.go:286] according to the absentOwnerCache, object d342ac05-e46a-11e7-aca8-0242ac110002's owner v1/ReplicationController, test.rc.1 does not exist I1219 03:15:12.182006 23030 garbagecollector.go:419] classify references of [v1/Pod, namespace: gc-cascading-deletion, name: test.pod.1, uid: d342ac05-e46a-11e7-aca8-0242ac110002]. solid: []v1.OwnerReference(nil) dangling: []v1.OwnerReference{v1.OwnerReference{APIVersion:"v1", Kind:"ReplicationController", Name:"test.rc.1", UID:"d33066fe-e46a-11e7-aca8-0242ac110002", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}} waitingForDependentsDeletion: []v1.OwnerReference(nil) I1219 03:15:12.182059 23030 garbagecollector.go:478] delete object [v1/Pod, namespace: gc-cascading-deletion, name: test.pod.1, uid: d342ac05-e46a-11e7-aca8-0242ac110002] with propagation policy Background I1219 03:15:12.182880 23030 garbagecollector.go:286] according to the absentOwnerCache, object d348c2ca-e46a-11e7-aca8-0242ac110002's owner v1/ReplicationController, test.rc.1 does not exist I1219 03:15:12.187914 23030 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.1, uid d342ac05-e46a-11e7-aca8-0242ac110002, event type update I1219 03:15:12.189368 23030 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.1, uid d342ac05-e46a-11e7-aca8-0242ac110002, event type delete I1219 03:15:12.189622 23030 garbagecollector.go:419] classify references of [v1/Pod, namespace: gc-cascading-deletion, name: test.pod.3, uid: d348c2ca-e46a-11e7-aca8-0242ac110002]. solid: []v1.OwnerReference{v1.OwnerReference{APIVersion:"v1", Kind:"ReplicationController", Name:"test.rc.2", UID:"d336738c-e46a-11e7-aca8-0242ac110002", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}} dangling: []v1.OwnerReference{v1.OwnerReference{APIVersion:"v1", Kind:"ReplicationController", Name:"test.rc.1", UID:"d33066fe-e46a-11e7-aca8-0242ac110002", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}} waitingForDependentsDeletion: []v1.OwnerReference(nil) I1219 03:15:12.189731 23030 garbagecollector.go:423] object [{v1 ReplicationController test.rc.2 d336738c-e46a-11e7-aca8-0242ac110002 %!s(*bool=) %!s(*bool=)}] has at least one existing owner: garbagecollector.objectReference{OwnerReference:v1.OwnerReference{APIVersion:"v1", Kind:"Pod", Name:"test.pod.3", UID:"d348c2ca-e46a-11e7-aca8-0242ac110002", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}, Namespace:"gc-cascading-deletion"}, will not garbage collect I1219 03:15:12.189831 23030 garbagecollector.go:427] remove dangling references []v1.OwnerReference{v1.OwnerReference{APIVersion:"v1", Kind:"ReplicationController", Name:"test.rc.1", UID:"d33066fe-e46a-11e7-aca8-0242ac110002", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}} and waiting references []v1.OwnerReference(nil) for object [v1/Pod, namespace: gc-cascading-deletion, name: test.pod.3, uid: d348c2ca-e46a-11e7-aca8-0242ac110002] I1219 03:15:12.195277 23030 graph_builder.go:588] GraphBuilder process object: v1/Pod, namespace gc-cascading-deletion, name test.pod.3, uid d348c2ca-e46a-11e7-aca8-0242ac110002, event type update I1219 03:15:12.572221 23030 garbagecollector.go:183] syncing garbage collector with updated resources from discovery: map[{networking.k8s.io v1 networkpolicies}:{} {policy v1beta1 poddisruptionbudgets}:{} {admissionregistration.k8s.io v1beta1 mutatingwebhookconfigurations}:{} { v1 podtemplates}:{} { v1 namespaces}:{} { v1 serviceaccounts}:{} { v1 replicationcontrollers}:{} {extensions v1beta1 networkpolicies}:{} {extensions v1beta1 ingresses}:{} {storage.k8s.io v1 storageclasses}:{} {admissionregistration.k8s.io v1alpha1 initializerconfigurations}:{} { v1 events}:{} {apiregistration.k8s.io v1beta1 apiservices}:{} {autoscaling v1 horizontalpodautoscalers}:{} {rbac.authorization.k8s.io v1 clusterrolebindings}:{} {scheduling.k8s.io v1alpha1 priorityclasses}:{} { v1 services}:{} {apps v1 replicasets}:{} {batch v1beta1 cronjobs}:{} {certificates.k8s.io v1beta1 certificatesigningrequests}:{} {apps v1 controllerrevisions}:{} {apps v1 deployments}:{} {rbac.authorization.k8s.io v1 roles}:{} { v1 secrets}:{} { v1 limitranges}:{} { v1 nodes}:{} { v1 pods}:{} { v1 configmaps}:{} {extensions v1beta1 deployments}:{} { v1 resourcequotas}:{} {batch v1 jobs}:{} {settings.k8s.io v1alpha1 podpresets}:{} {admissionregistration.k8s.io v1beta1 validatingwebhookconfigurations}:{} {apiextensions.k8s.io v1beta1 customresourcedefinitions}:{} { v1 persistentvolumeclaims}:{} {apps v1 statefulsets}:{} {events.k8s.io v1beta1 events}:{} {rbac.authorization.k8s.io v1 clusterroles}:{} {rbac.authorization.k8s.io v1 rolebindings}:{} { v1 persistentvolumes}:{} {apps v1 daemonsets}:{} {extensions v1beta1 podsecuritypolicies}:{} {extensions v1beta1 daemonsets}:{} {storage.k8s.io v1alpha1 volumeattachments}:{} { v1 endpoints}:{} {extensions v1beta1 replicasets}:{}] I1219 03:15:13.212116 23030 graph_builder.go:263] synced monitors; added 0, kept 43, removed 0 I1219 03:15:13.212168 23030 graph_builder.go:295] started 0 new monitors, 43 currently running I1219 03:15:13.212188 23030 controller_utils.go:1019] Waiting for caches to sync for garbage collector controller I1219 03:15:13.312507 23030 controller_utils.go:1026] Caches are synced for garbage collector controller I1219 03:15:13.312560 23030 garbagecollector.go:220] synced garbage collector I1219 03:15:18.345343 23030 garbagecollector.go:178] no resource updates from discovery, skipping garbage collector sync I1219 03:15:22.186043 23030 garbagecollector.go:154] Shutting down garbage collector controller I1219 03:15:22.192035 23030 graph_builder.go:348] stopped 43 of 43 monitors I1219 03:15:22.192067 23030 graph_builder.go:349] GraphBuilder stopping --- PASS: TestCascadingDeletion (18.09s) testserver.go💯 Starting kube-apiserver on port 41105... testserver.go:112: Waiting for /healthz to be ok... ```

[Jordan Liggitt]

Finally tracked it down. I can consistently recreate this by artificially triggering the "too old resource version" error on first replication controller watch establishment. That results in the following flow:

time	pod informer	rc informer	test driver	graph builder
0	list pods, get [] at rv=10	list rcs, get [] at rv=10
1	mark synced	mark synced
2			create rc.test.1 at rv=11
3			create pod.test at rv=12
4	watch at rv=10	watch at rv=10, get "too old" error
5	observe pod.test create at rv=12
6				process pod.test create at rv=12
7				add virtual node for rc.test.1
8				add node for pod.test
9				attemptToDelete for rc.test.1, lookup finds the object
10			delete rc at rv=13
11		after 1 second, list rcs, get [] at rv=13
12		watch at rv=13

That leaves us with a node in the GC graph for rc.test.1 that was confirmed by direct lookup in attemptToDelete, but never observed via informer events. Because rc.test.1 was created AND deleted during the one second watch outage, the informer will never deliver a deletion event for that object.

[TigerXu]

@liggitt If we explicitly sleep more than 1 second, this probablity can be reduced.

[Jordan Liggitt]

@liggitt If we explicitly sleep more than 1 second, this probablity can be reduced.

where are you thinking we would add the sleep? I am more interested in tracking the virtual nodes that have not been observed via informer more rigorously to avoid them getting orphaned in the graph, rather than trying to time our way out of this bug.

[Jordan Liggitt]

Opened #57503 with fix

[Kubernetes Submit Queue]

Closed #56121 via #57503.