[Bug]: Strimzi Operator Delays in creating Kafka Cluster K8S Resources (5+ Minutes)

[alita1991]

Bug Description

After deleting and reapplying the Kafka Custom Resources (CRs) for a Kafka cluster configured with KRaft, the Strimzi operator takes approximately 5 minutes to recreate the required Kubernetes resources. This delay significantly exceeds the expected initialization time, which should typically occur within seconds.

Steps to reproduce

1. Create a KafkaNodePool + Kafka Cluster
2. Wait to reconcile
3. Delete the CRs and wait for pods to be deleted
4. Re-create the KafkaNodePool + Kafka Cluster (5+ minutes)

Expected behavior

Strimiz operator should create the K8S resources in seconds

Strimzi version

0.43.0

Kubernetes version

v1.26.12+k3s1

Installation method

Helm Chart

Infrastructure

K3S

Configuration files and logs

2024-10-30 17:08:29 INFO  AbstractOperator:510 - Reconciliation #294(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Kafka kafka-cluster in namespace alita-kafka-nfrs was ADDED
2024-10-30 17:08:29 INFO  KafkaAssemblyOperator:920 - Reconciliation #295(watch) Kafka(alita-kafka-nfrs/kafka-cluster): KafkaNodePool kafka-cluster in namespace alita-kafka-nfrs was ADDED
2024-10-30 17:08:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:09:20 INFO  AbstractOperator:399 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:10:20 INFO  AbstractOperator:399 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:10:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:11:20 INFO  AbstractOperator:399 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:12:20 INFO  AbstractOperator:399 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:12:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:13:20 INFO  AbstractOperator:399 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:13:22 ERROR VertxUtil:132 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Exceeded timeout of 300000ms while waiting for Deployment resource kafka-cluster-entity-operator in namespace alita-kafka-nfrs to be observed
2024-10-30 17:13:22 ERROR AbstractOperator:283 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): createOrUpdate failed
io.strimzi.operator.common.TimeoutException: Exceeded timeout of 300000ms while waiting for Deployment resource kafka-cluster-entity-operator in namespace alita-kafka-nfrs to be observed
        at io.strimzi.operator.cluster.operator.VertxUtil$1.lambda$handle$1(VertxUtil.java:133) ~[io.strimzi.cluster-operator-0.43.0.jar:0.43.0]
        at io.vertx.core.impl.future.FutureImpl$4.onFailure(FutureImpl.java:188) ~[io.vertx.vertx-core-4.5.9.jar:4.5.9]
        at io.vertx.core.impl.future.FutureBase.lambda$emitFailure$1(FutureBase.java:75) ~[io.vertx.vertx-core-4.5.9.jar:4.5.9]
        at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) ~[io.netty.netty-transport-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at java.lang.Thread.run(Thread.java:840) ~[?:?]
2024-10-30 17:13:22 INFO  CrdOperator:123 - Reconciliation #290(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Status of Kafka kafka-cluster in namespace alita-kafka-nfrs has been updated

Additional context

If I wait a few minutes and then recreate the Kafka cluster along with the KafkaNodePool, the resources are created within seconds.

[scholzj]

It is not really clear what the order of things is and their timing. You talk about deleting the cluster, but that is not part of the log that is not complete. So it is not obvious. This could be related to #4856. But it is hard to say for sure because there is not enough information.

[alita1991]

I deleted Kafka+KafkaNodePool resources via kubectl at the same time. Before I trigger a new cluster creation, I only wait for the pods from the old cluster to be deleted. Interestingly, there is no issue if I wait a couple of minutes before I trigger the creation of a new cluster.

I updated the logs with extra information, like the "DELETE" message.

024-10-30 16:59:11 INFO  AbstractOperator:510 - Reconciliation #222(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Kafka kafka-cluster in namespace alita-kafka-nfrs was DELETED
2024-10-30 16:59:11 WARN  KafkaAssemblyOperator:926 - KafkaNodePool kafka-cluster in namespace alita-kafka-nfrs was DELETED, but the Kafka cluster kafka-cluster to which it belong
s does not exist
2024-10-30 17:00:10 INFO  AbstractOperator:399 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:00:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:01:10 INFO  AbstractOperator:399 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:02:10 INFO  AbstractOperator:399 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:02:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:03:10 INFO  AbstractOperator:399 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:04:10 INFO  AbstractOperator:399 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Reconciliation is in progress
2024-10-30 17:04:11 ERROR VertxUtil:132 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Exceeded timeout of 300000ms while waiting for Deployment resource kafk
a-cluster-entity-operator in namespace alita-kafka-nfrs to be observed
2024-10-30 17:04:11 ERROR AbstractOperator:283 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): createOrUpdate failed
io.strimzi.operator.common.TimeoutException: Exceeded timeout of 300000ms while waiting for Deployment resource kafka-cluster-entity-operator in namespace alita-kafka-nfrs to be o
bserved
        at io.strimzi.operator.cluster.operator.VertxUtil$1.lambda$handle$1(VertxUtil.java:133) ~[io.strimzi.cluster-operator-0.43.0.jar:0.43.0]
        at io.vertx.core.impl.future.FutureImpl$4.onFailure(FutureImpl.java:188) ~[io.vertx.vertx-core-4.5.9.jar:4.5.9]
        at io.vertx.core.impl.future.FutureBase.lambda$emitFailure$1(FutureBase.java:75) ~[io.vertx.vertx-core-4.5.9.jar:4.5.9]
        at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) ~[io.netty.netty-transport-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at java.lang.Thread.run(Thread.java:840) ~[?:?]
2024-10-30 17:04:11 ERROR AbstractOperator:358 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Current Kafka resource not found
2024-10-30 17:04:11 WARN  AbstractOperator:556 - Reconciliation #219(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Failed to reconcile
io.strimzi.operator.common.TimeoutException: Exceeded timeout of 300000ms while waiting for Deployment resource kafka-cluster-entity-operator in namespace alita-kafka-nfrs to be o
bserved
        at io.strimzi.operator.cluster.operator.VertxUtil$1.lambda$handle$1(VertxUtil.java:133) ~[io.strimzi.cluster-operator-0.43.0.jar:0.43.0]
        at io.vertx.core.impl.future.FutureImpl$4.onFailure(FutureImpl.java:188) ~[io.vertx.vertx-core-4.5.9.jar:4.5.9]
        at io.vertx.core.impl.future.FutureBase.lambda$emitFailure$1(FutureBase.java:75) ~[io.vertx.vertx-core-4.5.9.jar:4.5.9]
        at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) ~[io.netty.netty-transport-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.111.Final.jar:4.1.111.Final]
        at java.lang.Thread.run(Thread.java:840) ~[?:?]
2024-10-30 17:04:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:04:51 INFO  ClusterOperator:140 - Triggering periodic reconciliation for namespace alita-kafka-nfrs
2024-10-30 17:05:26 INFO  AbstractOperator:510 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Kafka kafka-cluster in namespace alita-kafka-nfrs was ADDED
2024-10-30 17:05:26 INFO  AbstractOperator:264 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Kafka kafka-cluster will be checked for creation or modification
2024-10-30 17:05:26 INFO  KafkaAssemblyOperator:920 - Reconciliation #224(watch) Kafka(alita-kafka-nfrs/kafka-cluster): KafkaNodePool kafka-cluster in namespace alita-kafka-nfrs w
as ADDED
2024-10-30 17:05:26 INFO  AbstractOperator:510 - Reconciliation #225(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Kafka kafka-cluster in namespace alita-kafka-nfrs was MODIFIED
2024-10-30 17:05:26 INFO  CrdOperator:123 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Status of Kafka kafka-cluster in namespace alita-kafka-nfrs has been 
updated
2024-10-30 17:05:26 INFO  Ca:1026 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Generating CA with subject=Subject(organizationName='io.strimzi', commonName=
'cluster-ca v0', dnsNames=[], ipAddresses=[])
2024-10-30 17:05:28 INFO  Ca:1026 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Generating CA with subject=Subject(organizationName='io.strimzi', commonName=
'clients-ca v0', dnsNames=[], ipAddresses=[])
2024-10-30 17:05:34 INFO  Ca:412 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Generating certificate Subject(organizationName='io.strimzi', commonName='clus
ter-operator', dnsNames=[], ipAddresses=[]), signed by CA cluster-ca
2024-10-30 17:05:34 INFO  CrdOperator:123 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Status of KafkaNodePool kafka-cluster in namespace alita-kafka-nfrs h
as been updated
2024-10-30 17:05:34 INFO  KafkaAssemblyOperator:920 - Reconciliation #226(watch) Kafka(alita-kafka-nfrs/kafka-cluster): KafkaNodePool kafka-cluster in namespace alita-kafka-nfrs w
as MODIFIED
2024-10-30 17:05:34 INFO  Ca:412 - Reconciliation #223(watch) Kafka(alita-kafka-nfrs/kafka-cluster): Generating certificate Subject(organizationName='io.strimzi', commonName='kafk
a-cluster-kafka', dnsNames=[kafka-cluster-kafka-brokers, kafka-cluster-kafka-bootstrap.alita-kafka-nfrs.svc, kafka-cluster-kafka-cluster-0.kafka-cluster-kafka-brokers.alita-kafka-
nfrs.svc, kafka-cluster-kafka-bootstrap.alita-kafka-nfrs.svc.cluster.local, kafka-cluster-kafka-brokers.alita-kafka-nfrs.svc.cluster.local, kafka-cluster-kafka-bootstrap, kafka-cl
uster-kafka-bootstrap.alita-kafka-nfrs, kafka-cluster-kafka-cluster-0.kafka-cluster-kafka-brokers.alita-kafka-nfrs.svc.cluster.local, kafka-cluster-kafka-brokers.alita-kafka-nfrs,
 kafka-cluster-kafka-brokers.alita-kafka-nfrs.svc], ipAddresses=[]), signed by CA cluster-ca
2024-10-30 17:05:35 INFO  StrimziPodSetController:378 - Reconciliation #227(watch) StrimziPodSet(alita-kafka-nfrs/kafka-cluster-kafka-cluster): StrimziPodSet will be reconciled
2024-10-30 17:05:35 INFO  StrimziPodSetController:414 - Reconciliation #227(watch) StrimziPodSet(alita-kafka-nfrs/kafka-cluster-kafka-cluster): reconciled

[scholzj]

Right, so this suggests this is cased by #4856. If you need to often create and delete clusters, we recommend to use different names. Waiting few minutes or restarting the operator might be other options.