'..error"="Operation cannot be fulfilled...object has been modified..' lines in the logs

[irbekrm]

E0208 11:09:19.068736       1 controller.go:159] cert-manager/controller/CertificateIssuing "msg"="re-queuing item due to error processing" "error"="Operation cannot be fulfilled on certificates.cert-manager.io \"self-signed\": the object has been modified; please apply your changes to the latest version and try again" "key"="default/self-signed" 
I0208 11:09:19.068763       1 controller.go:153] cert-manager/controller/CertificateIssuing "msg"="syncing item" "key"="default/self-signed" 
I0208 11:09:19.070713       1 readiness_controller.go:182] cert-manager/controller/CertificateReadiness "msg"="CertificateReadiness: failed updating certificate" "key"="default/self-signed" "Operation cannot be fulfilled on certificates.cert-manager.io \"self-signed\": the object has been modified; please apply your changes to the latest version and try again"=null
E0208 11:09:19.070738       1 controller.go:159] cert-manager/controller/CertificateReadiness "msg"="re-queuing item due to error processing" "error"="Operation cannot be fulfilled on certificates.cert-manager.io \"self-signed\": the object has been modified; please apply your changes to the latest version and try again" "key"="default/self-signed" 

These kind of log lines occur if a control loop picks up a resource, such as a Certficate, applies some changes and attempts to send the update request to k8s API server (i.e here), but meanwhile another control loop has already updated the same resource and its version has changed.
This is not an error as such as the control loop will simply re-queue and retry the update.

However, to a user who is looking at the logs, trying to debug an actual issue, these logs suggest an error, also because there is no obvious indication of the system having recovered.

See, for example, the conversations on Slack here and issues #3516, #3501, #3603 .

Perhaps we could catch these error messages and wrap them in a more explanatory error/message or log a different message.

/kind cleanup

[alex-guenther]

There is no need to catch and wrap this error messages. The message appeares because the cert-manager is doing something wrong. K8s is doing optimistic locking. So when you update an object and include the version of the last known state K8s will compare and complain if your last known state is not the current state. As far as I understand cert-manager acts like an K8s operator. This means that it runs the reconcile loop on each change it notices. Durring that loop it seems to update the Certificate object multiple times. But it doesn't care about what the API Server returns and cary on with the old object instead of replacing it and using the returned one for the rest of the loop. I also made the same mistake writing my first operator and storing the state multiple times. Effectively it still works but only because the reconcile loop is caled often enough to not write new state before the essential tasks get done.

Please don't trt to cover up bugs either do nothing until someone fixes them or fix them. I might find some time to look into it.

[irbekrm]

Hi @alex-guenther,

Thanks for the comment!

We run multiple reconcile loops (with a few of them watching the same resources), so this happens when two loops pick up an object, one of them updates the object, causing the version to change and then the other also attempts to apply an update, but at that point it has an out of date version of that object.

[irbekrm]

I am going to pin this issue as it seems like this is confusing for a large number of questions and we get a number of GitHub issues open where folks think that there is something wrong with their installation when they see these lines in the logs.

[maelvls]

Note that since cert-manager 1.4, we changed (#3794) the message. The message now suggests that this is expected behavior and that you should not worry about this message. Before/after:

-re-queuing item due to error processing
+re-queuing item due to optimistic locking on resource

The message is also shown at the info level (I prefix) instead of the error level (E prefix). The goal is to prevent users from thinking that the optimistic locking mechanism has to do with their issues, when in reality it mostly isn't and is the normal operation mode for Kubernetes controllers.