Our controller log is full of "broker is not rollable" errors

[itaydj]

Hi,
We are using Strimzi in our on prem k8s environment.
we have multiple Strimzi Kafka clusters but a specific cluster started throwing erros in the controller logs:

2023-06-27 07:26:24 INFO  ClusterOperator:121 - Triggering periodic reconciliation for namespace *
2023-06-27 07:26:24 INFO  AbstractOperator:226 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Kafka vertica-data-digestion will be checked for creation or modification
2023-06-27 07:26:26 INFO  KafkaAvailability:135 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/0 will be under-replicated (ISR={0}, replicas=[0,2,1], min.insync.replicas=1) if broker 0 is restarted.
2023-06-27 07:26:26 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 0 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-0 is currently not rollable, retrying after at least 250ms
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 1 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod vertica-data-digestion-kafka-1 is currently the controller and there are other pods still to roll, retrying after at least 250ms
2023-06-27 07:26:27 INFO  KafkaAvailability:135 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/1 will be under-replicated (ISR={2}, replicas=[2,1,0], min.insync.replicas=1) if broker 2 is restarted.
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 2 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-2 is currently not rollable, retrying after at least 250ms
2023-06-27 07:26:27 INFO  KafkaAvailability:135 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/0 will be under-replicated (ISR={0}, replicas=[0,2,1], min.insync.replicas=1) if broker 0 is restarted.
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 0 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-0 is currently not rollable, retrying after at least 500ms
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 1 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod vertica-data-digestion-kafka-1 is currently the controller and there are other pods still to roll, retrying after at least 500ms
2023-06-27 07:26:27 INFO  KafkaAvailability:135 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/1 will be under-replicated (ISR={2}, replicas=[2,1,0], min.insync.replicas=1) if broker 2 is restarted.
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 2 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-2 is currently not rollable, retrying after at least 500ms
2023-06-27 07:26:27 INFO  KafkaAvailability:135 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/0 will be under-replicated (ISR={0}, replicas=[0,2,1], min.insync.replicas=1) if broker 0 is restarted.
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 0 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-0 is currently not rollable, retrying after at least 1000ms
2023-06-27 07:26:27 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 1 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod vertica-data-digestion-kafka-1 is currently the controller and there are other pods still to roll, retrying after at least 1000ms
2023-06-27 07:26:28 INFO  KafkaAvailability:135 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/1 will be under-replicated (ISR={2}, replicas=[2,1,0], min.insync.replicas=1) if broker 2 is restarted.
2023-06-27 07:26:28 INFO  KafkaRoller:299 - Reconciliation #14(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 2 due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-2 is currently not rollable, retrying after at least 1000ms

I am trying to understand whats wrong but the logs wont provide much info

I am also getting these errors periodically:

2023-06-27 07:24:37 INFO  KafkaRoller:292 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 0, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-0 is currently not rollable
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:370) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.1]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:277) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.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-06-27 07:24:37 INFO  KafkaAvailability:135 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/2 will be under-replicated (ISR={1}, replicas=[1,0,2], min.insync.replicas=1) if broker 1 is restarted.
2023-06-27 07:24:37 WARN  KafkaRoller:388 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): Pod vertica-data-digestion-kafka-1 can't be safely force-rolled; original error:
2023-06-27 07:24:37 INFO  KafkaRoller:292 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 1, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Pod vertica-data-digestion-kafka-1 is currently the controller and there are other pods still to roll
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:358) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.1]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:277) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.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-06-27 07:24:38 INFO  KafkaAvailability:135 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): my-cluster.vertica.public.telems.general-telemetries-json-prod.replica/1 will be under-replicated (ISR={2}, replicas=[2,1,0], min.insync.replicas=1) if broker 2 is restarted.
2023-06-27 07:24:38 INFO  KafkaRoller:292 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): Could not roll pod 2, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-2 is currently not rollable
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:370) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.1]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:277) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.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-06-27 07:24:38 ERROR AbstractOperator:247 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): createOrUpdate failed
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-0 is currently not rollable
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:370) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.1]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:277) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.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-06-27 07:24:38 WARN  AbstractOperator:532 - Reconciliation #12(timer) Kafka(my-cluster/vertica-data-digestion): Failed to reconcile
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod vertica-data-digestion-kafka-0 is currently not rollable
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:370) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.1]
	at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:277) ~[io.strimzi.cluster-operator-0.27.1.jar:0.27.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) [?:?]

Kafka version is: 2.8
operator version is: 0.27.1

we are planning to upgrade soon..

Thanks in advance

[scholzj]

You might need to try to use DEBUG logging to get the exact issue. Or maybe it is in the full log even on INFO level, but you did not shared it.

[itaydj]

it wont let me upload the entire log so if you can point me to a specific keyword I can paste it here

[scholzj]

I do not have any specific keyword, sorry. But you have one example reason why the broker cannot be rolled in the log above -> with topic which has only one in-sync-replica.

[itaydj]

yes, saw that and trying to figure out what can cause that.
I guess my poor Kafka knowledge is not helping here.
Thanks for the pointer

[scholzj]

It is really hard to judge what the issue might be without understanding more about your environment. In general, you should check the topic configurations and the producer configurations and double-check they are well configured (e.g. with acks=all in producers or possibly using in.insync.replicas=2 for topics with 3 replicas etc.).

[itaydj]

thanks again for the pointers and I will come back to update once we find the issue.