[Bug]: LeaderElector:216 - Exception occurred while acquiring lock (the object has been modified)

[hunter86bg]

Bug Description

Kafka operator keeps spamming the logs with warnings about 'Exception occurred while acquiring lock' but the audit logs do not show any changes on the lease from other objects/users.

2024-11-22 11:34:20 DEBUG StandardHttpClient:185 - HTTP operation on url: https://IP:443/apis/coordination.k8s.io/v1/namespaces/NAMESPACE/leases/strimzi-cluster-operator should be retried after 100 millis because of IOException
java.io.IOException: /10.223.65.134:47762: GOAWAY received
        at jdk.internal.net.http.Http2Connection.handleGoAway(Http2Connection.java:1009) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection.handleConnectionFrame(Http2Connection.java:874) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection.processFrame(Http2Connection.java:749) ~[java.net.http:?]
        at jdk.internal.net.http.frame.FramesDecoder.decode(FramesDecoder.java:155) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection$FramesController.processReceivedData(Http2Connection.java:232) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection.asyncReceive(Http2Connection.java:675) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.processQueue(Http2Connection.java:1311) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.runOrSchedule(Http2Connection.java:1329) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.onNext(Http2Connection.java:1355) ~[java.net.http:?]
        at jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.onNext(Http2Connection.java:1289) ~[java.net.http:?]
        at jdk.internal.net.http.common.SSLTube$DelegateWrapper.onNext(SSLTube.java:210) ~[java.net.http:?]
        at jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onNext(SSLTube.java:492) ~[java.net.http:?]
        at jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onNext(SSLTube.java:295) ~[java.net.http:?]
        at jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:316) ~[java.net.http:?]
        at jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:259) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) ~[java.net.http:?]
        at jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:232) ~[java.net.http:?]
        at jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:198) ~[java.net.http:?]
        at jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:444) ~[java.net.http:?]
        at jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:268) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) ~[java.net.http:?]
        at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:840) ~[?:?]
2024-11-22 11:34:21 WARN  LeaderElector:216 - Exception occurred while acquiring lock 'LeaseLock: NAMESPACE - strimzi-cluster-operator (strimzi-cluster-operator-796767788c-7nhxp) retrying...'
io.fabric8.kubernetes.client.KubernetesClientException: Failure executing: PATCH at: https://IP:443/apis/coordination.k8s.io/v1/namespaces/NAMESPACE/leases/strimzi-cluster-operator. Message: Operation cannot be fulfilled on leases.coordination.k8s.io "strimzi-cluster-operator": the object has been modified; please apply your changes to the latest version and try again. Received status: Status(apiVersion=v1, code=409, details=StatusDetails(causes=[], group=coordination.k8s.io, kind=leases, name=strimzi-cluster-operator, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=Operation cannot be fulfilled on leases.coordination.k8s.io "strimzi-cluster-operator": the object has been modified; please apply your changes to the latest version and try again, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=Conflict, status=Failure, additionalProperties={}).
        at io.fabric8.kubernetes.client.KubernetesClientException.copyAsCause(KubernetesClientException.java:238) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.waitForResult(OperationSupport.java:507) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.handleResponse(OperationSupport.java:524) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.handlePatch(OperationSupport.java:419) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.handlePatch(OperationSupport.java:397) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.BaseOperation.handlePatch(BaseOperation.java:764) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.HasMetadataOperation.lambda$patch$2(HasMetadataOperation.java:231) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.HasMetadataOperation.patch(HasMetadataOperation.java:236) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.HasMetadataOperation.patch(HasMetadataOperation.java:251) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.HasMetadataOperation.patch(HasMetadataOperation.java:44) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.extension.ResourceAdapter.patch(ResourceAdapter.java:305) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.extended.leaderelection.resourcelock.ResourceLock.update(ResourceLock.java:64) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.extended.leaderelection.LeaderElector.tryAcquireOrRenew(LeaderElector.java:247) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.extended.leaderelection.LeaderElector.lambda$renewWithTimeout$6(LeaderElector.java:207) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.extended.leaderelection.LeaderElector.lambda$loop$8(LeaderElector.java:292) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:840) ~[?:?]
Caused by: io.fabric8.kubernetes.client.KubernetesClientException: Failure executing: PATCH at: https://IP:443/apis/coordination.k8s.io/v1/namespaces/NAMESPACE/leases/strimzi-cluster-operator. Message: Operation cannot be fulfilled on leases.coordination.k8s.io "strimzi-cluster-operator": the object has been modified; please apply your changes to the latest version and try again. Received status: Status(apiVersion=v1, code=409, details=StatusDetails(causes=[], group=coordination.k8s.io, kind=leases, name=strimzi-cluster-operator, retryAfterSeconds=null, uid=null, additionalProperties={}), kind=Status, message=Operation cannot be fulfilled on leases.coordination.k8s.io "strimzi-cluster-operator": the object has been modified; please apply your changes to the latest version and try again, metadata=ListMeta(_continue=null, remainingItemCount=null, resourceVersion=null, selfLink=null, additionalProperties={}), reason=Conflict, status=Failure, additionalProperties={}).
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.requestFailure(OperationSupport.java:660) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.requestFailure(OperationSupport.java:640) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.assertResponseCode(OperationSupport.java:589) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at io.fabric8.kubernetes.client.dsl.internal.OperationSupport.lambda$handleResponse$0(OperationSupport.java:549) ~[io.fabric8.kubernetes-client-6.13.0.jar:?]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646) ~[?:?]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
        at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147) ~[?:?]
        at io.fabric8.kubernetes.client.http.StandardHttpClient.lambda$completeOrCancel$10(StandardHttpClient.java:142) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
        at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147) ~[?:?]
        at io.fabric8.kubernetes.client.utils.AsyncUtils.lambda$retryWithExponentialBackoff$3(AsyncUtils.java:90) ~[io.fabric8.kubernetes-client-api-6.13.0.jar:?]
        at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510) ~[?:?]
        at java.util.concurrent.CompletableFuture.postFire(CompletableFuture.java:614) ~[?:?]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:844) ~[?:?]
        at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482) ~[?:?]
        ... 1 more

Steps to reproduce

1. Deploy the operator (Helmrelease, chart v 0.42.0) and values:

  values:
    affinity:
      nodeAffinity:
        requiredDuringSchedulingIgnoredDuringExecution:
          nodeSelectorTerms:
          - matchExpressions:
            - key: workload
              operator: In
              values:
              - namespace
    podLabels:
      label1: logging_kafka
      label2: somelabel
    podMonitor: {}
    statefulsetLabels:
      label1: logging_kafka
      label2: somelabel
    tolerations:
    - effect: NoSchedule
      key: workload
      operator: Equal
      value: namespace

2. Wait a few hours ~ 2h should be enough to show up

Expected behavior

No warnings should be logged if only the operator has patched the lease.

Strimzi version

0.42.0

Kubernetes version

v1.30.3-gke.1969002

Installation method

Helm Chart

Infrastructure

GKE

Configuration files and logs

strimzi_partial.log

Additional context

No response

[scholzj]

This is not generally reproducible.

The 409 errors might from time to time happen and are not something what can be prevented as they typically mean that multiple things are trying to modify the same resource - that cannot be avoided because there is no locking or transaction mechanism in Kubernetes. I never saw it for the Lease resource, but that does not mean it is impossible. It can indicate some misconfiguration on your side, but it can be also a completely innocent thing that randomly happens. Not sure if it is related to the GOAWAY exception from your super short log snippet or it is just a coincidence.

The GOAWAY is something sent by your Kubernetes API server and logged by the Kubernetes client that likely needs to reconnect. It seems to be logged on a DEBUG level, so if you want it, do not use DEBUG level logging. But even if it was on a warning level, it is a kind of disruption to the operator from which it should be able to recover.

[hunter86bg]

@scholzj , actually,It's visible on INFO logging level also. As it doesn't show up immediately, I assume the configuration is OK.

I tried deleting the lease and the problem is gone for a random period of time. I'm not sure if trace will show the actual patch or not in order to try and reproduce it.

P.S.: I've attached a debug log which provides more details.

[scholzj]

What you shared does not show it at INFO level. But as I said, even if it did, I do not think it would be unreasonable.

[scholzj]

actually,It's visible on INFO logging level also. As it doesn't show up immediately, I assume the configuration is OK.

The GOAWAY is sent by your API server. So that probably decides on when it is sent. Not sure why not seeing it immediately would have any specific meaning.

The 409 is essentially a race condition. So once again, it not showing immediately does not mean it is not misconfiguration. It could be for example two instances of the operator configured to use the same Lease resource but with different timeouts. But as I said, it could also be just a random thing that means nothing. But in any case, whether it happens right away or not means nothing in this case.