Deployments do not get updated to the new version during upgrade

[anirudhprasad-sap]

Hi Colleagues,

We noticed that in some cases, the cap-operator version doesn't get updated to the new version when we upgrade the cap-operator-manager. It seems to happen randomly and is not consistently reproducible.

Our test scenario -

1. We have the cap-operator-manager running on version 1.0.7 which will deploy the cap-operator version 1.0.7.
2. We created a CRO and it deployed the cap-operator with version 1.0.7 into the namespace as expected.
3. Now we triggered an update by deploying version 1.0.8 of cap-operator-manager which should ideally deploy cap-operator version 1.0.8. But the cap-operator didn't get updated. We tried waiting for some time but still, the version was not updated.
4. But on restarting the cap-operator-manager pod, the cap-operator gets updated to the new version 1.0.8.

We were able to capture this behavior in a recording - Link. Let me know if you have any issue accessing the recording.

Please find the logs below just after updating cap-operator-manager to version 1.0.8 -

{"level":"info","ts":"2023-08-01T12:07:39Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"} {"level":"info","ts":"2023-08-01T12:07:39Z","logger":"setup","msg":"starting manager"} {"level":"info","ts":"2023-08-01T12:07:39Z","msg":"Starting server","kind":"health probe","addr":":8081"} {"level":"info","ts":"2023-08-01T12:07:39Z","msg":"starting server","path":"/metrics","kind":"metrics","addr":":8080"} I0801 12:07:39.458809 1 leaderelection.go:245] attempting to acquire leader lease cap-operator-system/cap-operator.sme.sap.com... I0801 12:07:48.909261 1 leaderelection.go:255] successfully acquired lease cap-operator-system/cap-operator.sme.sap.com {"level":"info","ts":"2023-08-01T12:07:48Z","msg":"Starting EventSource","controller":"capoperator","controllerGroup":"operator.sme.sap.com","controllerKind":"CAPOperator","source":"kind source: *v1alpha1.CAPOperator"} {"level":"info","ts":"2023-08-01T12:07:48Z","msg":"Starting Controller","controller":"capoperator","controllerGroup":"operator.sme.sap.com","controllerKind":"CAPOperator"} {"level":"info","ts":"2023-08-01T12:07:49Z","msg":"Starting workers","controller":"capoperator","controllerGroup":"operator.sme.sap.com","controllerKind":"CAPOperator","worker count":3}

Logs after restarting the cap-operator-manager pods-

{"level":"info","ts":"2023-08-01T12:08:29Z","logger":"controller-runtime.metrics","msg":"Metrics server is starting to listen","addr":":8080"} {"level":"info","ts":"2023-08-01T12:08:29Z","logger":"setup","msg":"starting manager"} {"level":"info","ts":"2023-08-01T12:08:29Z","msg":"Starting server","kind":"health probe","addr":":8081"} {"level":"info","ts":"2023-08-01T12:08:29Z","msg":"starting server","path":"/metrics","kind":"metrics","addr":":8080"} I0801 12:08:29.774471 1 leaderelection.go:245] attempting to acquire leader lease cap-operator-system/cap-operator.sme.sap.com... I0801 12:08:29.797858 1 leaderelection.go:255] successfully acquired lease cap-operator-system/cap-operator.sme.sap.com {"level":"info","ts":"2023-08-01T12:08:29Z","msg":"Starting EventSource","controller":"capoperator","controllerGroup":"operator.sme.sap.com","controllerKind":"CAPOperator","source":"kind source: *v1alpha1.CAPOperator"} {"level":"info","ts":"2023-08-01T12:08:29Z","msg":"Starting Controller","controller":"capoperator","controllerGroup":"operator.sme.sap.com","controllerKind":"CAPOperator"} {"level":"info","ts":"2023-08-01T12:08:29Z","msg":"Starting workers","controller":"capoperator","controllerGroup":"operator.sme.sap.com","controllerKind":"CAPOperator","worker count":3} I0801 12:08:32.260244 1 request.go:696] Waited for 1.004779362s due to client-side throttling, not priority and fairness, request: GET:https://api.i325261-test.cs-trial.internal.canary.k8s.ondemand.com:443/apis/rbac.authorization.k8s.io/v1?timeout=32s

After the pod restart, we see an additional log - 12:08:32.260244 1 request.go:696] Waited for 1.004779362s due to client-side throttling, not priority and fairness, request: GET:https://api.i325261-test.cs-trial.internal.canary.k8s.ondemand.com:443/apis/rbac.authorization.k8s.io/v1?timeout=32s. But not sure if this is related to the issue.

Can you please help us with this? Also, let me know if you need the cap-operator-manager deployment files. I can share them via mail.

Thanks and regards,
Anirudh

[cbarbian-sap]

If the metadata.generation of the component CRO does not change (which is likely happening when upgrading the component operator), then a reconcile through the new component operator should happen immediately only if the last reconcile done by the previous controller happened more than 60s ago; otherwise it may take up to 10 (or 11) minutes until that happens.

Can you confirm that it did not even happen after that timeframe?

If you still think there is an issue, please attach the CRO descriptors (including status) before and after the manager upgrade.

[cbarbian-sap]

There is a bug, indeed. The problematic statement is

return ctrl.Result{}, nil

(https://github.com/SAP/component-operator-runtime/blob/main/pkg/component/reconcile.go#L266), not returning any RequeueAfter.

Meaning: whenever a reconcile is happening, and status.lastAppliedGeneration equals metadata.Generation and status.lastAppliedAt is less than 60s in the past, then no further periodic reconcile will happen at all (only, the next change of the CRO or future restarts of the controller will trigger one).

This is probably happening in your case when starting a new component operator version.