kubernetes-reflector: Reflection is to slow. Pod goes into ImagePullBackOff

I am using Gitops and on pull requests of my app I create a new environment to test the PR. I will create a namespace and the required pods. But until the kubernetes-reflector replicated the imagepullsecret, the pods already went into ImagePullBackOff state.

kubernetes-reflector logs show:

2022-05-04 12:38:13.495 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Session closed. Duration: 00:35:19.1644564. Faulted: False.
2022-05-04 12:38:13.504 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-04 12:38:13.768 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected my-ns/my-secret where permitted. Created 0 - Updated 0 - Deleted 0 - Validated 9.
2022-05-04 13:12:02.234 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Session closed. Duration: 00:57:19.8038623. Faulted: False.
2022-05-04 13:12:02.235 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources
2022-05-04 13:15:50.371 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Session closed. Duration: 00:38:42.5296269. Faulted: False.
2022-05-04 13:15:50.372 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources
2022-05-04 13:37:29.214 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Session closed. Duration: 00:59:15.7097240. Faulted: False.
2022-05-04 13:37:29.214 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-04 13:37:29.554 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected my-ns/my-secret where permitted. Created 0 - Updated 0 - Deleted 0 - Validated 9.
2022-05-04 13:44:03.810 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Session closed. Duration: 00:32:01.5747240. Faulted: False.
2022-05-04 13:44:03.810 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources
2022-05-04 14:03:22.530 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Session closed. Duration: 00:47:31.9659988. Faulted: False.
2022-05-04 14:03:22.530 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources
2022-05-04 14:14:12.683 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Session closed. Duration: 00:30:08.6807986. Faulted: False.
2022-05-04 14:14:12.683 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources
2022-05-04 14:30:02.454 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Session closed. Duration: 00:52:33.0470167. Faulted: False.
2022-05-04 14:30:02.454 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-04 14:30:02.562 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected my-ns/my-secret where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 9.
2022-05-04 14:30:02.600 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created my-new-ns/my-secret as a reflection of my-ns/my-secret
2022-05-04 14:39:40.142 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Session closed. Duration: 00:36:17.6118289. Faulted: False.
2022-05-04 14:39:40.142 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources

As I see it, the reflector tried to reflect secrets at 12:38, 13:37 and 14:30. So in the worst case, I’d have to wait for almost an hour until the secret get reflected.

Is this how the reflector works, or have I done something wrong? Can the reflector maybe get notified when a new namespace has been created and then “instantly” reflect secrets? Or alternatively can it check for new namespaces every 30 seconds or so?

About this issue

Original URL
State: closed
Created 2 years ago
Reactions: 3
Comments: 22 (3 by maintainers)

Commits related to this issue

Upgrade to .NET 7 and multiple stability fixes Fixes: #331, #316, #313, #295. #292, #283, #282 — committed to emberstack/kubernetes-reflector by winromulus a year ago
Upgrade to .NET 7 and multiple stability fixes Fixes: #331, #316, #313, #295. #292, #283, #282 — committed to emberstack/kubernetes-reflector by winromulus a year ago
Upgrade to .NET 7 and multiple stability fixes Fixes: #331, #316, #313, #295. #292, #283, #282 — committed to emberstack/kubernetes-reflector by winromulus a year ago
Upgrade to .NET 7 and multiple stability fixes (#332) Fixes: #331, #316, #313, #295. #292, #283, #282 — committed to emberstack/kubernetes-reflector by winromulus a year ago

Most upvoted comments

The new version (work in progress) should fix this issue.

winromulus on Nov 16, 2022

I can observe the same behavior in an AWS EKS cluster with k8s 1.21 and Argo CD. But I have no idea how to debug it.

ManuelMueller1st on May 10, 2022

Sorry for spamming, but I have some logs now.

The namespace was created by Helm at 8:58 UTC:

apiVersion: v1
kind: Namespace
metadata:
  creationTimestamp: "2022-05-30T08:58:01Z"
  labels:
    kubernetes.io/metadata.name: store-demo-review-infra-secrets
    name: store-demo-review-infra-secrets
  name: store-demo-review-infra-secrets
  resourceVersion: "2922145"
  uid: a1d88c0a-8bfb-4c2e-9860-ee1442531847
spec:
  finalizers:
  - kubernetes
status:
  phase: Active

The last few logs from the reflector, you can see that it didn’t notice the namespace being created, it just sits there (no logs after 8:51, but checked after the namespace was created)

2022-05-30 08:46:27.714 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Session closed. Duration: 00:38:27.3678417. Faulted: False.
2022-05-30 08:46:27.714 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources
2022-05-30 08:51:32.022 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Session closed. Duration: 00:57:18.4978533. Faulted: False.
2022-05-30 08:51:32.022 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources

Now delete the pod, it immediately creates the secrets on startup:

$ kubectl -n emberstack-reflector delete pod reflector-5fc85c9964-mxgwd
$ kubectl -n emberstack-reflector logs reflector-5fc85c9964-gmjkt 
2022-05-30 09:01:00.148 +00:00 [INF] () Starting host
2022-05-30 09:01:00.610 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources
2022-05-30 09:01:00.645 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-30 09:01:00.659 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources
2022-05-30 09:01:01.028 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/app-secrets where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 1.
2022-05-30 09:01:01.136 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-infra-secrets/app-secrets as a reflection of store-demo-templates/app-secrets
2022-05-30 09:01:01.184 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/registry-pull-secret where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 1.
2022-05-30 09:01:01.192 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-infra-secrets/registry-pull-secret as a reflection of store-demo-templates/registry-pull-secret

meaning the secrets are correctly configured for auto-reflection into this namespace.

Judging from the way you describe the tool architecture, this means the namespace creation event is not correctly received after a while. Could it be that, after the session is first closed by Kubernetes, the tool doesn’t correctly switch monitoring to the new subscription? That would explain why it works at first, but stops “after a while”. 🤔

I’ve created a namespace before the session reset to test the theory, the secrets got auto-reflected. I’ll create another one after I see the session got reset in the reflector logs, if it doesn’t work then, I think we have a culprit. Will update here in an hour or so.

Update

OK, it seems we’re on to something, but it’s not as clear cut as I imagined, here’s the logs

2022-05-30 09:26:03.388 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test-before-session-reset/registry-pull-secret as a reflection of store-demo-templates/registry-pull-secret
2022-05-30 09:26:03.398 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test-before-session-reset/app-secrets as a reflection of store-demo-templates/app-secrets
2022-05-30 09:43:32.639 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Session closed. Duration: 00:42:32.0333010. Faulted: False.
2022-05-30 09:43:32.641 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources
2022-05-30 09:44:25.294 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Session closed. Duration: 00:43:24.6352104. Faulted: False.
2022-05-30 09:44:25.295 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources

# here created store-demo-review-test-after-session-reset @09:45, reflection delayed for 2mins, until the restart (?)

2022-05-30 09:47:13.586 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Session closed. Duration: 00:46:12.9410373. Faulted: False.
2022-05-30 09:47:13.587 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-30 09:47:13.619 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/app-secrets where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 2.
2022-05-30 09:47:13.633 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test-after-session-reset/app-secrets as a reflection of store-demo-templates/app-secrets
2022-05-30 09:47:13.673 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/registry-pull-secret where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 2.
2022-05-30 09:47:13.681 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test-after-session-reset/registry-pull-secret as a reflection of store-demo-templates/registry-pull-secret

# here created store-demo-review-test2-after-session-reset @09:52, reflection immediate

2022-05-30 09:52:15.502 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test2-after-session-reset/registry-pull-secret as a reflection of store-demo-templates/registry-pull-secret
2022-05-30 09:52:15.512 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test2-after-session-reset/app-secrets as a reflection of store-demo-templates/app-secrets

# here created store-demo-review-test3-after-session-reset @10:08, reflection immediate

2022-05-30 10:08:21.141 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test3-after-session-reset/registry-pull-secret as a reflection of store-demo-templates/registry-pull-secret
2022-05-30 10:08:21.149 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test3-after-session-reset/app-secrets as a reflection of store-demo-templates/app-secrets
2022-05-30 10:14:49.370 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Session closed. Duration: 00:30:24.0749936. Faulted: False.
2022-05-30 10:14:49.370 +00:00 [INF] (ES.Kubernetes.Reflector.Core.ConfigMapWatcher) Requesting V1ConfigMap resources
2022-05-30 10:27:20.794 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Session closed. Duration: 00:40:07.2076328. Faulted: False.
2022-05-30 10:27:20.794 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-30 10:27:20.838 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/registry-pull-secret where permitted. Created 0 - Updated 0 - Deleted 0 - Validated 5.
2022-05-30 10:27:20.878 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/app-secrets where permitted. Created 0 - Updated 0 - Deleted 0 - Validated 5.
2022-05-30 10:41:35.917 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Session closed. Duration: 00:58:03.2754536. Faulted: False.
2022-05-30 10:41:35.917 +00:00 [INF] (ES.Kubernetes.Reflector.Core.NamespaceWatcher) Requesting V1Namespace resources

# here created store-demo-review-test3-after-session-reset @11:05, reflection delayed 6 mins

2022-05-30 11:14:22.213 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Session closed. Duration: 00:47:01.4186849. Faulted: False.
2022-05-30 11:14:22.213 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretWatcher) Requesting V1Secret resources
2022-05-30 11:14:22.245 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/registry-pull-secret where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 5.
2022-05-30 11:14:22.254 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test4-after-session-reset/registry-pull-secret as a reflection of store-demo-templates/registry-pull-secret
2022-05-30 11:14:22.281 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Auto-reflected store-demo-templates/app-secrets where permitted. Created 1 - Updated 0 - Deleted 0 - Validated 5.
2022-05-30 11:14:22.287 +00:00 [INF] (ES.Kubernetes.Reflector.Core.SecretMirror) Created store-demo-review-test4-after-session-reset/app-secrets as a reflection of store-demo-templates/app-secrets

I guess all secrets are reflected during the session restart, but something prevents the real-time aspect from working.

dkarlovi on May 30, 2022