Controller stops reconciling, needs restart

[stefanprodan]

Reported here: fluxcd/flux2#2219

Having an automation that should reconcile every 7 minutes:

apiVersion: image.toolkit.fluxcd.io/v1beta1
kind: ImageUpdateAutomation
metadata:
  name: flux-system
  namespace: flux-system
spec:
  git:
    checkout:
      ref:
        branch: master
    commit:
      author:
        email: me@example.com
        name: me
      messageTemplate: '{{range .Updated.Images}}{{println .}}{{end}}'
    push:
      branch: master
  interval: 7m0s
  sourceRef:
    kind: GitRepository
    name: flux-system
  update:
    path: ./staging
    strategy: Setters

The reconciliation stoped two days ago for unknown reasons:

$ date
Fri Dec 17 16:25:48 EET 2021

$ flux get image update

NAME       	READY	MESSAGE                                                     	LAST RUN                 	SUSPENDED
flux-system	True 	no updates made; last commit 8574614 at 2021-12-14T22:47:08Z	2021-12-15T08:15:01-07:00	False

[jwerre]

This coincided with outages at AWS in us-west-2 where I'm running Kubernetes on EKS. My entire cluster went down on that day for about 10 minutes and when it came back up I ran into this issue.

[bondido]

Hi,
While waiting for permanent fix, are there any advice how to detect "stucked" image-automation-controller case?
Are there any metrics or logs we should monitor?
We have been suffering the issue (~couple of times per week) for some time and the only alert is from users who pushed their images to container registry and didn't notice cluster deployment for quite some time.

Another observation is that in most cases restarting image-automation-controller is sufficient, but there where two times when we needed to also restart source-controller.

[jwerre]

@bondido how about something like this:

kubectl get pod -n flux-system

NAME                                          READY   STATUS    RESTARTS   AGE
helm-controller-96dc99bfd-p9g4q               1/1     Running   0          9d
image-automation-controller-64c955c59-ckbft   1/1     Running   0          9d  <<< ------
image-reflector-controller-55fb7f765d-cr8zn   1/1     Running   0          9d
kustomize-controller-7bc878f768-xf2xb         1/1     Running   0          9d
notification-controller-945795558-q8nht       1/1     Running   0          9d
source-controller-65665fd68f-n7qqz            1/1     Running   0          9d

[bondido]

@jwerre
I'm afraid it won't help, as long running controller is no problem.
The problem is that it's running but not doing it's job and not reflecting it in any log or metric (I still hope I missed something here :-) )

[jwerre]

Ah yes.. I had the same problem you need to restart the pod e.g.:

kubectl delete pods image-automation-controller-64c955c59-ckbft -n flux-system

[bondido]

Sure @jwerre , I know. Thanks :-)
As I mentioned earlier, sometime restarting image-automation-controller is not enough and we need to restart source-controller pod as well.

As temporary kind of "automatic mitigation" we introduced a scheduled external script checking .status.lastAutomationRunTime of imageupdateautomation resource (

image-automation-controller/config/crd/bases/image.toolkit.fluxcd.io_imageupdateautomations.yaml

Line 170 in 041018f

lastAutomationRunTime:

) and invoking 'kubectl pod delete' commands if it seems to stuck for too long.

We'd love to see this bug fixed soon, anyway :-)

[jwerre]

@bondido, I misunderstood your question. Sorry for the confusion.

[squaremo]

sometime restarting image-automation-controller is not enough and we need to restart source-controller pod as well.

@bondido Do you mean that source-controller has the same problem; or, that to get image-automation-controller to start working again, you needed to restart source-controller?

[bondido]

@bondido Do you mean that source-controller has the same problem; or, that to get image-automation-controller to start working again, you needed to restart source-controller?

We have to restart source-controller for image-automation-controller to start working. In fact we restart both - first image-automation-controller, and if we don't see any improvement in a couple of minutes time - source-controller.

So far, we haven't try to restart just source-controller.

[squaremo]

@bondido Thanks for elaborating! On the face of it, I wouldn't expect restarting source-controller to have any effect on image-automation-controller, because it works independently: it only coincidentally refers to the same GitRepository objects, and doesn't alter anything at the upstream git repository (that might "unlock" image-automation-controller). Do you have good evidence that restarting source-controller is exactly what unblocks image-automation-controller; or could it be a sort of "reliable coincidence"?

[stefanprodan]

@bondido @jwerre can you please exec into the controller pod and see if there is anything left in tmp by running ls -lah /tmp and du -sh /tmp/*. Thanks!

[bondido]

Do you have good evidence that restarting source-controller is exactly what unblocks image-automation-controller; or could it be a sort of "reliable coincidence"?

I can't be 100% sure as I couldn't get to any logs or metric confirming what was actually happening.

At first two cases restarting image-automation-controller was enough and new images were applied to cluster just seconds after the restart.
But then - on the third occurence - we restarted image-automation-controller and nothing happened for over 10 minutes. So it was just blind shot by my colleague to restart source-controller, after which everything started working.

The situation repeated exactly like the above for one more time.

[bondido]

@bondido @jwerre can you please exec into the controller pod and see if there is anything left in tmp by running ls -lah /tmp and du -sh /tmp/*. Thanks!

You mean checking the directory contents inside "stucked" controller pod, don't you?
(in "working OK" pod I've checked it and it's empty).