KafkaRoller exception

[eslam-gomaa]

Describe the bug

our Kafka cluster can't reconcile pods or increase the replicas

• We faced the problem after the pods crashed due to "storage shortage" and increased the cluster storage.
• 2 pods out of 3 were running, we deleted the third broker with its pvc, the new pvc was created but the pod didn't create.
• even if we increase the cluster replica count, it doesn't work.

The kafka-2 didn't come up

To Reproduce

Reason is unknown

Expected behavior

the operator adds new replicas normally

Environment (please complete the following information):

• Strimzi version: [e.g. main, 3.2.0
• Installation method: Helm chart
• Kubernetes cluster: Kubernetes 1.21
• Infrastructure: Amazon EKS

YAML files and logs

2023-02-08 19:54:56 INFO  AbstractOperator:378 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Reconciliation is in progress
2023-02-08 19:55:17 INFO  KafkaRoller:306 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Could not roll pod {strimzi-kafka-cluster-aws-prod-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod strimzi-kafka-cluster-aws-prod-kafka-0 is currently the controller and there are other pods still to roll, retrying after at least 64000ms
2023-02-08 19:55:18 INFO  KafkaAvailability:135 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): src-dtr-prod.prod.webhook.sms/0 will be under-replicated (ISR={0,1}, replicas=[2,0,1], min.insync.replicas=2) if broker 1 is restarted.
2023-02-08 19:55:18 INFO  KafkaRoller:306 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Could not roll pod {strimzi-kafka-cluster-aws-prod-kafka-1} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod strimzi-kafka-cluster-aws-prod-kafka-1 is currently not rollable, retrying after at least 64000ms
2023-02-08 19:55:25 INFO  OperatorWatcher:38 - Reconciliation #67(watch) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Kafka strimzi-kafka-cluster-aws-prod in namespace strimzi-kafka-prod was MODIFIED
2023-02-08 19:55:56 INFO  ClusterOperator:120 - Triggering periodic reconciliation for namespace *
2023-02-08 19:55:56 INFO  AbstractOperator:378 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Reconciliation is in progress
2023-02-08 19:55:56 INFO  AbstractOperator:237 - Reconciliation #69(timer) KafkaMirrorMaker2(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): KafkaMirrorMaker2 strimzi-kafka-cluster-aws-prod will be checked for creation or modification
2023-02-08 19:55:57 INFO  AbstractOperator:501 - Reconciliation #69(timer) KafkaMirrorMaker2(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): reconciled
2023-02-08 19:56:21 INFO  KafkaAvailability:135 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): src-dtr-prod.prod.webhook.sms/0 will be under-replicated (ISR={0,1}, replicas=[2,0,1], min.insync.replicas=2) if broker 0 is restarted.
2023-02-08 19:56:21 WARN  KafkaRoller:373 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Pod {strimzi-kafka-cluster-aws-prod-kafka-0} can't be safely force-rolled; original error: 
2023-02-08 19:56:21 INFO  KafkaRoller:299 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Could not roll pod {strimzi-kafka-cluster-aws-prod-kafka-0}, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod strimzi-kafka-cluster-aws-prod-kafka-0 is currently the controller and there are other pods still to roll
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:342) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        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:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:829) ~[?:?]

--
2023-02-08 19:56:23 INFO  KafkaRoller:299 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Could not roll pod {strimzi-kafka-cluster-aws-prod-kafka-1}, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod strimzi-kafka-cluster-aws-prod-kafka-1 is currently not rollable
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:354) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        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:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:829) ~[?:?]
2023-02-08 19:56:23 ERROR AbstractOperator:258 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): createOrUpdate failed
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod strimzi-kafka-cluster-aws-prod-kafka-0 is currently the controller and there are other pods still to roll
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:342) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        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:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:829) ~[?:?]
2023-02-08 19:56:23 INFO  OperatorWatcher:38 - Reconciliation #70(watch) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Kafka strimzi-kafka-cluster-aws-prod in namespace strimzi-kafka-prod was MODIFIED
2023-02-08 19:56:23 INFO  CrdOperator:111 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Status of Kafka strimzi-kafka-cluster-aws-prod in namespace strimzi-kafka-prod has been updated
2023-02-08 19:56:23 WARN  AbstractOperator:516 - Reconciliation #65(timer) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Failed to reconcile
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod strimzi-kafka-cluster-aws-prod-kafka-0 is currently the controller and there are other pods still to roll
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:342) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.31.1.jar:0.31.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        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:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:829) ~[?:?]
2023-02-08 19:56:23 INFO  AbstractOperator:237 - Reconciliation #70(watch) Kafka(strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod): Kafka strimzi-kafka-cluster-aws-prod will be checked for creation or modification

---

Cluster config

########################
#    Kafka cluster     #
########################
kafkaCluster:
  version: 3.2.0
  interBrokerProtocolVersion: "3.2"

  kafka:
    replicas: 3
    template:
      pod:
        metadata:
          annotations:
            prometheus.io/scrape: true
            prometheus.io/path: /metrics
            prometheus.io/port: "9404"
    listeners:
      - name: plain
        port: 9092
        type: internal
        tls: false
      - name: tls
        port: 9093
        type: internal
        tls: true
#...
#...
#...
    config:
      auto.create.topics.enable: false
      delete.topic.enable: true
      num.io.threads: 8
      num.recovery.threads.per.data.dir: 1
      unclean.leader.election.enable: false
      offsets.topic.replication.factor: 3
      transaction.state.log.replication.factor: 3
      transaction.state.log.min.isr: 2
      default.replication.factor: 3
      min.insync.replicas: 2
      # Retention period of 4 days
      log.retention.hours: 96
    storage:
      type: jbod
      volumes:
      - id: 0
        type: persistent-claim
        size: 900Gi
        class: gp2
        deleteClaim: false
    resources:
      requests:
        cpu: 1
        memory: 8Gi
      limits:
        cpu: 2
        memory: 20Gi
    jvmOptions:
      -Xms: 4G
      -Xmx: 4G

  zookeeper:
    replicas: 3
    template:
      # We need to add Prometheus annotations, so that we can auto discover the Pod metrics by Prometheus (if needed)
      pod:
        metadata:
          annotations:
            prometheus.io/scrape: true
            prometheus.io/path: /metrics
            prometheus.io/port: "9404"
    storage:
      type: persistent-claim
      size: 150Gi
      class: gp2
      deleteClaim: false
    resources:
      requests:
        cpu: 1
        memory: 1Gi
      limits:
        cpu: 2
        memory: 2Gi
    entityOperator:
      topicOperator:
        resources:
          requests:
            cpu: 200m
            memory: 256Mi
          limits:
            cpu: 1
            memory: 256Mi
      userOperator:
        resources:
          requests:
            cpu: 200m
            memory: 512Mi
          limits:
            cpu: 1
            memory: 512Mi

  kafkaExporter:
    template:
      # We need to add Prometheus annotations, so that we can auto discover the Pod metrics by Prometheus (if needed)
      pod:
        metadata:
          annotations:
            prometheus.io/scrape: true
            prometheus.io/path: /metrics
            prometheus.io/port: tcp-prometheus
    resources:
      requests:
        cpu: 200m
        memory: 256Mi
      limits:
        cpu: 500m
        memory: 512Mi

To easily collect all YAMLs and logs, you can use our report script which will automatically collect all files and prepare a ZIP archive which can be easily attached to this issue.
The usage of this script is:
./report.sh --namespace <string> --cluster <string> [--bridge <string>] [--connect <string>] [--mm2 <string>]

Additional context
Add any other context about the problem here.

[scholzj]

You should probably start by sharing the full operator log from the start, Kubernetes events, What Strimzi version are you using etc.

[eslam-gomaa]

Operator version: 0.31.1
Kafka version: 3.2.0

operator.log

kubectl -n ... get events --field-selector involvedObject.kind=Pod

LAST SEEN   TYPE      REASON      OBJECT                                                        MESSAGE
13m         Normal    Killing     pod/kafka-producer-test                                       Stopping container kafka-producer-test
13m         Normal    Killing     pod/pod-monitor-7fd79c58c9-b2hqp                              Stopping container pod-monitor
13m         Normal    Scheduled   pod/pod-monitor-7fd79c58c9-plkmz                              Successfully assigned strimzi-kafka-prod/pod-monitor-7fd79c58c9-plkmz to ip-192-168-98-171.me-south-1.compute.internal
13m         Normal    Pulling     pod/pod-monitor-7fd79c58c9-plkmz                              Pulling image "docker.io/praveensam/kubectl:latest"
12m         Normal    Pulled      pod/pod-monitor-7fd79c58c9-plkmz                              Successfully pulled image "docker.io/praveensam/kubectl:latest" in 25.714644936s
12m         Normal    Created     pod/pod-monitor-7fd79c58c9-plkmz                              Created container pod-monitor
12m         Normal    Started     pod/pod-monitor-7fd79c58c9-plkmz                              Started container pod-monitor
37m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Readiness probe failed: Get "http://192.168.107.205:9000/actuator/health": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
37m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Liveness probe failed: Get "http://192.168.107.205:9000/actuator/health": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
37m         Normal    Killing     pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Container kafdrop failed liveness probe, will be restarted
37m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Readiness probe failed: Get "http://192.168.107.205:9000/actuator/health": EOF
37m         Normal    Pulled      pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Container image "obsidiandynamics/kafdrop:3.29.0" already present on machine
37m         Normal    Created     pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Created container kafdrop
37m         Normal    Started     pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Started container kafdrop
37m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafdrop-7cbcb7b9cf-8bsjl   Readiness probe failed: Get "http://192.168.107.205:9000/actuator/health": dial tcp 192.168.107.205:9000: connect: connection refused
55m         Normal    Killing     pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Stopping container kafka
55m         Normal    Scheduled   pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Successfully assigned strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod-kafka-0 to ip-192-168-98-171.me-south-1.compute.internal
55m         Normal    Pulled      pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Container image "quay.io/strimzi/kafka:0.31.1-kafka-3.2.0" already present on machine
55m         Normal    Created     pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Created container kafka
55m         Normal    Started     pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Started container kafka
12m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Liveness probe failed:
12m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafka-0                    Readiness probe failed:
54m         Normal    Killing     pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Stopping container kafka
54m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Liveness probe failed: task d9e21b5b852c3e410fb50541919641997ab462b4b0221a3dd667ce000881ba1f not found: not found
54m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Readiness probe failed: OCI runtime exec failed: exec failed: unable to start container process: read init-p: connection reset by peer: unknown
54m         Normal    Scheduled   pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Successfully assigned strimzi-kafka-prod/strimzi-kafka-cluster-aws-prod-kafka-1 to ip-192-168-96-180.me-south-1.compute.internal
54m         Normal    Pulled      pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Container image "quay.io/strimzi/kafka:0.31.1-kafka-3.2.0" already present on machine
54m         Normal    Created     pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Created container kafka
54m         Normal    Started     pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Started container kafka
22m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Readiness probe failed:
22m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-kafka-1                    Liveness probe failed:
12m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-zookeeper-0                Readiness probe failed:
12m         Warning   Unhealthy   pod/strimzi-kafka-cluster-aws-prod-zookeeper-0                Liveness probe failed:

[scholzj]

So, what do you get when you do kubectl get strimzipodsets -o yaml and kubect get statefulsets -o yaml and kubectl get pod -o yaml?

[vjvel]

There is no sts resource, please find the strimzipodset and pods yaml for the broker.

[vjvel]

strimzipodset.txt
pods.txt

[scholzj]

Ok, the StrimziPodSet controller is correct. There should be only 2 pods. So I guess you should for a start explain what exactly you did. You say your cluster has 3 replicas, but it seems it has really only 2 Kafka replicas. I do not know how you got there, but you have only 2 replicas but topics with replication factor 3 and min.insync.replicas=2. You should probably change the topics to have a configuration that corresponds to your cluster. It is also not clear why is the cluster trying to roll the pods - you would probably need to use DEBUG log level for it. Maybe you can help it by deleting the pods using kubectl.

[vjvel]

We reduced from 3 broker to 2 broker in the kafka CRD and also changed the replication.factor and topic.replication to 2 then, we were increased to 3 replicas with changing the topic-replication and replicaton.factor = 3 as old value, its not creating the new pod.

We have tried to reduce the broker since one of the broker was not in ready state. readiness probe failed and its not accepting the traffic and don't find any error logs.

will enable the debug and share it.

[vjvel]

@scholzj can you please provide the reference to debug logging on this operator version 0.31.1 ?

[robobario]

You could set the STRIMZI_LOG_LEVEL env var for the cluster operator via extraEnvs in the helm chart like:

extraEnvs:
  - name: STRIMZI_LOG_LEVEL
    value: "DEBUG"

Or if you can edit the configmaps directly this blog works to change it without restarting the operator.

[scholzj]

Well, I'm not sure I follow ll the changes. But you scaled down the cluster but did not changed the topics configurations as the roller has topics with RF=3 and MinISR=2. So I think you have in general 2 options:

• As I said, you can try to roll the pods manually by deleting them with kubectl. That might get you beyond the update of the current broker to the next steps which include the scale-up back to 3 brokers.
• You have to edit the topics to change the RF and make the brokers rollable. That would allow the operator to proceed through the rolling update to the scale-up.

[eslam-gomaa]

Thank you @scholzj for your support, that was helpful, however deleting the pods didn't work. worked when I deleted the StrimziPodSet

[scholzj]

Yeah, that would have avoided the scale-up process as well. Yes. Not sure why deleting the other two pods didn't help. Anyway, if it works, it works.