Strimzi operator failed to Reconcile

[Sakib37]

I have a kafka cluster running in GKE. I have 5 zookeeper and 3 kafka pod. So I was trying to linearly scale out kafka to 5 pod. After I increase one replica (kafka-3), Kakfa object detects the change

~ k get kafka        
NAME      DESIRED KAFKA REPLICAS   DESIRED ZK REPLICAS   READY   WARNINGS
live-eu   5                        5                             
                         

and a new kafka broker (kafka-3) is added to the cluster.

live-eu-kafka-0                             1/1     Running   0             23h
live-eu-kafka-1                             1/1     Running   0             23h
live-eu-kafka-2                             1/1     Running   0             23h
live-eu-kafka-3                             1/1     Running   0             106m

Now, I want to add another replica (kafka-4) to have 5 kafka pods. After changing the replica count for kafka, I see that the change is reflected correctly

~ k get kafka        
NAME      DESIRED KAFKA REPLICAS   DESIRED ZK REPLICAS   READY   WARNINGS
live-eu   5                        5                             

However, strimzipodset for Kafka seems like did not detect any change

~ k get strimzipodsets.core.strimzi.io
NAME                PODS   READY PODS   CURRENT PODS   AGE
live-eu-kafka       4      4            4              24h
live-eu-zookeeper   5      5            5              24h

I faced this type of unusual situation before as well regarding strimzipodsets. However, restarting the cluster operator magically fixed the issue on that time. But this time it seems like the reconciliation failed permanently and strimzipodset does not increase the pod count for kafka to 5.

According to the logs from operator:

2023-05-10 15:18:20 INFO  ClusterOperator:139 - Triggering periodic reconciliation for namespace kafka
2023-05-10 15:18:24 INFO  AbstractOperator:380 - Reconciliation #36(timer) Kafka(kafka/live-eu): Reconciliation is in progress
2023-05-10 15:18:32 INFO  KafkaAvailability:135 - Reconciliation #36(timer) Kafka(kafka/live-eu): __strimzi_store_topic/0 will be under-replicated (ISR={2,3}, replicas=[3,2,4], min.insync.replicas=2) if broker 3 is restarted.
2023-05-10 15:18:32 INFO  KafkaRoller:327 - Reconciliation #36(timer) Kafka(kafka/live-eu): Will temporarily skip verifying pod live-eu-kafka-3 is up-to-date due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod live-eu-kafka-3 cannot be updated right now., retrying after at least 64000ms
2023-05-10 15:19:19 INFO  ClusterOperator:139 - Triggering periodic reconciliation for namespace kafka-user
2023-05-10 15:19:20 INFO  ClusterOperator:139 - Triggering periodic reconciliation for namespace kafka-topic
2023-05-10 15:19:20 INFO  ClusterOperator:139 - Triggering periodic reconciliation for namespace kafka
2023-05-10 15:19:24 INFO  AbstractOperator:380 - Reconciliation #36(timer) Kafka(kafka/live-eu): Reconciliation is in progress
2023-05-10 15:19:37 INFO  KafkaAvailability:135 - Reconciliation #36(timer) Kafka(kafka/live-eu): __strimzi_store_topic/0 will be under-replicated (ISR={2,3}, replicas=[3,2,4], min.insync.replicas=2) if broker 3 is restarted.
2023-05-10 15:19:37 INFO  KafkaRoller:320 - Reconciliation #36(timer) Kafka(kafka/live-eu): Could not verify pod live-eu-kafka-3 is up-to-date, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod live-eu-kafka-3 cannot be updated right now.
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:379) ~[io.strimzi.cluster-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:305) ~[io.strimzi.cluster-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:833) ~[?:?]
2023-05-10 15:19:37 ERROR AbstractOperator:260 - Reconciliation #36(timer) Kafka(kafka/live-eu): createOrUpdate failed
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod live-eu-kafka-3 cannot be updated right now.
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:379) ~[io.strimzi.cluster-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:305) ~[io.strimzi.cluster-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:833) ~[?:?]
2023-05-10 15:19:37 WARN  AbstractOperator:525 - Reconciliation #36(timer) Kafka(kafka/live-eu): Failed to reconcile
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod live-eu-kafka-3 cannot be updated right now.
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:379) ~[io.strimzi.cluster-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:305) ~[io.strimzi.cluster-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:833) ~[?:?]

operator cannot verify that kafka-3 pod is up to date or not. So operator temporarily stopped reconciliation and there is no kafka-4 pod created. However, there is no error in the log of kafka-3 pod.

log from kafka-3 pod:

2023-05-10 14:47:51,585 INFO [Broker id=3] Handling StopReplica request correlationId 23 from controller 1 for 1 partitions (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,585 TRACE [Broker id=3] Received StopReplica request StopReplicaPartitionState(partitionIndex=0, leaderEpoch=-2, deletePartition=false) correlation id 23 from controller 1 epoch 2 for partition load-test-0 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,585 INFO [ReplicaFetcherManager on broker 3] Removed fetcher for partitions Set(load-test-0) (kafka.server.ReplicaFetcherManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,585 INFO [ReplicaAlterLogDirsManager on broker 3] Removed fetcher for partitions Set(load-test-0) (kafka.server.ReplicaAlterLogDirsManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,586 INFO [Broker id=3] Handling StopReplica request correlationId 24 from controller 1 for 1 partitions (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,586 TRACE [Broker id=3] Received StopReplica request StopReplicaPartitionState(partitionIndex=0, leaderEpoch=-2, deletePartition=true) correlation id 24 from controller 1 epoch 2 for partition load-test-0 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,586 INFO [ReplicaFetcherManager on broker 3] Removed fetcher for partitions Set(load-test-0) (kafka.server.ReplicaFetcherManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,586 INFO [ReplicaAlterLogDirsManager on broker 3] Removed fetcher for partitions Set(load-test-0) (kafka.server.ReplicaAlterLogDirsManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,589 INFO Log for partition load-test-0 is renamed to /var/lib/kafka/data-0/kafka-log3/load-test-0.f727f71d4d1e436598b12b8ce69573ef-delete and is scheduled for deletion (kafka.log.LogManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,729 INFO [Broker id=3] Handling LeaderAndIsr request correlationId 25 from controller 1 for 1 partitions (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,730 TRACE [Broker id=3] Received LeaderAndIsr request LeaderAndIsrPartitionState(topicName='load-test', partitionIndex=0, controllerEpoch=2, leader=3, leaderEpoch=0, isr=[3, 0, 1], partitionEpoch=0, replicas=[3, 0, 1], addingReplicas=[], removingReplicas=[], isNew=true, leaderRecoveryState=0) correlation id 25 from controller 1 epoch 2 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,730 TRACE [Broker id=3] Handling LeaderAndIsr request correlationId 25 from controller 1 epoch 2 starting the become-leader transition for partition load-test-0 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,730 INFO [ReplicaFetcherManager on broker 3] Removed fetcher for partitions Set(load-test-0) (kafka.server.ReplicaFetcherManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,730 INFO [Broker id=3] Stopped fetchers as part of LeaderAndIsr request correlationId 25 from controller 1 epoch 2 as part of the become-leader transition for 1 partitions (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,732 INFO [LogLoader partition=load-test-0, dir=/var/lib/kafka/data-0/kafka-log3] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,733 INFO Created log for partition load-test-0 in /var/lib/kafka/data-0/kafka-log3/load-test-0 with properties {} (kafka.log.LogManager) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,733 INFO [Partition load-test-0 broker=3] Log loaded for partition load-test-0 with initial high watermark 0 (kafka.cluster.Partition) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,734 INFO [Broker id=3] Leader load-test-0 with topic id Some(MkpyK4VsTd2Nyfgt9IE2bQ) starts at leader epoch 0 from offset 0 with partition epoch 0, high watermark 0, ISR [3,0,1], adding replicas [] and removing replicas []. Previous leader epoch was -1. (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,739 TRACE [Broker id=3] Completed LeaderAndIsr request correlationId 25 from controller 1 epoch 2 for the become-leader transition for partition load-test-0 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,739 INFO [Broker id=3] Finished LeaderAndIsr request in 10ms correlationId 25 from controller 1 for 1 partitions (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,740 TRACE [Broker id=3] Cached leader info UpdateMetadataPartitionState(topicName='load-test', partitionIndex=0, controllerEpoch=2, leader=3, leaderEpoch=0, isr=[3, 0, 1], zkVersion=0, replicas=[3, 0, 1], offlineReplicas=[]) for partition load-test-0 in response to UpdateMetadata request sent by controller 1 epoch 2 with correlation id 26 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:47:51,740 INFO [Broker id=3] Add 1 partitions and deleted 0 partitions from metadata cache in response to UpdateMetadata request sent by controller 1 epoch 2 with correlation id 26 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:48:06,826 TRACE [Broker id=3] Deleted partition load-test-0 from metadata cache in response to UpdateMetadata request sent by controller 1 epoch 2 with correlation id 27 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:48:06,827 INFO [Broker id=3] Add 0 partitions and deleted 1 partitions from metadata cache in response to UpdateMetadata request sent by controller 1 epoch 2 with correlation id 27 (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:48:06,827 INFO [GroupCoordinator 3]: Removed 0 offsets associated with deleted partitions: load-test-0. (kafka.coordinator.group.GroupCoordinator) [control-plane-kafka-request-handler-0]
2023-05-10 14:48:06,836 INFO [Broker id=3] Handling StopReplica request correlationId 28 from controller 1 for 1 partitions (state.change.logger) [control-plane-kafka-request-handler-0]
2023-05-10 14:48:06,836 TRACE [Broker id=3] Received StopReplica request StopReplicaPartitionState(partitionIndex=0, leaderEpoch=-2, deletePartition=false) correlation id 28 from controller 1 epoch 2 for partition load-test-0 (state.change.logger) [control-plane-kafka-request-handler-0]

The spec of kafka object after increasing replica count to 5.

kafka:
    config:
      auto.create.topics.enable: 'true'
      default.replication.factor: 3
      inter.broker.protocol.version: '3.4'
      min.insync.replicas: 2
      offsets.topic.replication.factor: 3
      transaction.state.log.min.isr: 2
      transaction.state.log.replication.factor: 3
    jvmOptions: {}
    listeners:
      - configuration:
          useServiceDnsDomain: true
        name: plain
        port: 9092
        tls: false
        type: internal
      - authentication:
          type: tls
        name: tls
        port: 9093
        tls: true
        type: internal
      - configuration:
          brokers:
            - advertisedHost: live-eu-kafka-0.net
              advertisedPort: 9094
              broker: 0
              loadBalancerIP: 10.156.0.142
            - advertisedHost: live-eu-kafka-1.net
              advertisedPort: 9094
              broker: 1
              loadBalancerIP: 10.156.0.143
            - advertisedHost: live-eu-kafka-2.net
              advertisedPort: 9094
              broker: 2
              loadBalancerIP: 10.156.0.128
            - advertisedHost: live-eu-kafka-3.net
              advertisedPort: 9094
              broker: 3
              loadBalancerIP: 10.156.0.184
            - advertisedHost: live-eu-kafka-4.net
              advertisedPort: 9094
              broker: 4
              loadBalancerIP: 10.156.0.82
          externalTrafficPolicy: Local
        name: external
        port: 9094
        tls: false
        type: loadbalancer
    logging:
      loggers:
        kafka.root.logger.level: INFO
      type: inline
    metricsConfig:
       ...
    rack:
      topologyKey: topology.kubernetes.io/zone
    readinessProbe:
      initialDelaySeconds: 15
      timeoutSeconds: 5
    replicas: 5
    storage:
      .....
    template:
      pod:
        affinity:
          nodeAffinity:
            requiredDuringSchedulingIgnoredDuringExecution:
              nodeSelectorTerms:
                - matchExpressions:
                    - key: purpose
                      operator: In
                      values:
                        - kafka
          podAntiAffinity:
            requiredDuringSchedulingIgnoredDuringExecution:
              - labelSelector:
                  matchExpressions:
                    - key: app.kubernetes.io/name
                      operator: In
                      values:
                        - kafka
                topologyKey: kubernetes.io/hostname
        tolerations:
          - effect: NoSchedule
            key: purpose
            operator: Equal
            value: kafka
        topologySpreadConstraints:
          - labelSelector:
              matchLabels:
                app.kubernetes.io/name: kafka
            maxSkew: 1
            topologyKey: topology.kubernetes.io/zone
            whenUnsatisfiable: DoNotSchedule
      podDisruptionBudget:
        maxUnavailable: 0
    version: 3.4.0

To clarify a bit more, kafka-3 and kafka-4 pods were previously deleted manually to check how reclaiming and existing PVC actually works for kafka pod. So kafka-3 successfully reclaimed the retained PVC and started without any issue.

It is unclear why operator is not able to verify if kafka-3 is up-to-date or not.

[scholzj]

There was some similar issue / discussion somewhere else. This might be that the Pod informer is somehow terminated. But to be honest I'm not sure I follow what exactly you did and what is happening in your cluster since the description seems to mix different things such as scaling, deleting pods manually etc. So it is not clear what is actually happening when and how.

[Sakib37]

Let me try to explain the sequence of events in a more clear way

• There was an existing cluster with 5 Kafka and 5 zookeepers with the configuration to retain volume
• Wanted to test if volume(PVC) retaining works fine for the Kafka brokers. So scale down the Kafka cluster to 3 brokers by updating the number of replicas in the Kafka specs.
• PVC for kafka-3 and kafka-4 persisted after scaling down the cluster to 3 brokers and kafka-3 and kafka-4 pods got deleted.
• Now scaled up Kafka to 4 brokers i.e. added Kafka-3 to the cluster and previously existing PVC for Kafka-3 got attached with the new Kafka-3 broker. Everything worked fine and there are no error logs on the Kafka-3 pod.
• Scaled up Kafka to 5 brokers, but this time there is no new pod(Kafka-4) created and the cluster operator gives the above logs that it cannot verify if the Kafka-3 pod is up-to-date or not. Strimzipodset is not showing that 5 Kafka broker is expected in the cluster though the Kafka object shows that DESIRED KAFKA REPLICAS is 5.

So I was wondering

• If the Kafka-3 pod is running without any error in the log then why Strimzi operator is not able to verify if Kafka-3 is up-to-date or not?
• What is the reason for not creating a new broker (Kafka-4) when the Kafka object shows that DESIRED KAFKA REPLICAS is 5?

[scholzj]

So, I think the problem you have is this:

(ISR={2,3}, replicas=[3,2,4], min.insync.replicas=2

You have a topic which is assigned to brokers 3, 2 and 4. But with broker 4 missing, the pods 2 or 3 cannot be safely rolled. This is probably because you did not scale-down the cluster properly. You told it to remove the brokers, but did not reassign the partitions first (this currently has to be done separately first). So I think that essentially broke your cluster and it does not get far enough to do the scale-up to 5 brokers (which would recreate the broker 4 again). The easiest way to recover is probably to do a non-cascading deletion of the Kafka StrimziPodSet. That would get it recreated including the 5th broker and should hopefully allow the broker to recover the topic with the data and get the cluster back to normal.

[Sakib37]

Thank you for the explanation. I had a wrong understanding that in a 5 broker cluster, we can always allow 2 broker to go down. However, seems like it is not always true. It depends on replication factor and min.insync.replicas value.