Broker down but pod status shows running.

[LinzeSu]

Hi,

I've been running a test cluster with 3 brokers and last weekend one of the broker fail due to OOM, but pod status shows it's running. So I'm wondering:

1. Why the pod status shows it's still running? Is it because a manual restart is intended for some purposes?
2. Is there some built in restart policies that can be defined? I didn't manage to find info about it.

Thanks!

[scholzj]

You probably need to explain more about what does it mean that it is still running and that it failed due to OOM. Without understanding what do you mean with it, it is not really clear. You should for example share logs etc.

[LinzeSu]

Hi scholzj,

Thanks for the very fast reply. By saying 'pod status shows it's still running' I mean using kubectl get pod command shows it's running with restart count 0. By saying 'it failed due to OOM' I mean using kubectl to check the log and I find the following logs:

java.lang.OutOfMemoryError: Java heap space
2023-03-11 20:58:55,700 ERROR Uncaught exception in scheduled task 'kafka-log-retention' (kafka.utils.KafkaScheduler) [kafka-scheduler-11]
java.lang.OutOfMemoryError: Java heap space
2023-03-11 20:58:55,701 ERROR Uncaught exception in thread 'data-plane-kafka-network-thread-0-ListenerName(EXTERNAL-9094)-PLAINTEXT-10': (org.apache.kafka.common.utils.KafkaThread) [data-plane-kafka-network-thread-0-ListenerName(EXTERNAL-9094)-PLAINTEXT-10]
java.lang.OutOfMemoryError: Java heap space
2023-03-11 20:59:42,768 INFO [LocalLog partition=input-topic-runbo-0, dir=/var/lib/kafka/data-0/kafka-log0] Deleting segment files LogSegment(baseOffset=1891503, size=668732918, lastModifiedTime=1678494934138, largestRecordTimestamp=Some(1678494900568)) (kafka.log.LocalLog$) [kafka-scheduler-6]
2023-03-11 20:59:42,777 INFO Deleted producer state snapshot /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-0/00000000000001891503.snapshot.deleted (kafka.log.SnapshotFile) [kafka-scheduler-5]
2023-03-11 20:59:42,782 INFO Deleted log /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-0/00000000000001891503.log.deleted. (kafka.log.LogSegment) [kafka-scheduler-6]
2023-03-11 20:59:42,787 INFO Deleted offset index /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-0/00000000000001891503.index.deleted. (kafka.log.LogSegment) [kafka-scheduler-6]
2023-03-11 20:59:42,793 INFO Deleted time index /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-0/00000000000001891503.timeindex.deleted. (kafka.log.LogSegment) [kafka-scheduler-6]
2023-03-11 21:03:26,070 INFO [UnifiedLog partition=input-topic-runbo-7, dir=/var/lib/kafka/data-0/kafka-log0] Deleting segment LogSegment(baseOffset=1890878, size=685043755, lastModifiedTime=1678494715965, largestRecordTimestamp=Some(1678494715952)) due to retention time 72000000ms breach based on the largest record timestamp in the segment (kafka.log.UnifiedLog) [kafka-scheduler-4]
2023-03-11 21:03:26,092 INFO [UnifiedLog partition=input-topic-runbo-7, dir=/var/lib/kafka/data-0/kafka-log0] Incremented log start offset to 2081289 due to segment deletion (kafka.log.UnifiedLog) [kafka-scheduler-4]
2023-03-11 21:04:26,088 INFO [LocalLog partition=input-topic-runbo-7, dir=/var/lib/kafka/data-0/kafka-log0] Deleting segment files LogSegment(baseOffset=1890878, size=685043755, lastModifiedTime=1678494715965, largestRecordTimestamp=Some(1678494715952)) (kafka.log.LocalLog$) [kafka-scheduler-6]
2023-03-11 21:04:26,096 INFO Deleted producer state snapshot /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-7/00000000000001890878.snapshot.deleted (kafka.log.SnapshotFile) [kafka-scheduler-12]
2023-03-11 21:04:26,103 INFO Deleted log /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-7/00000000000001890878.log.deleted. (kafka.log.LogSegment) [kafka-scheduler-6]
2023-03-11 21:04:26,110 INFO Deleted offset index /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-7/00000000000001890878.index.deleted. (kafka.log.LogSegment) [kafka-scheduler-6]
2023-03-11 21:04:26,116 INFO Deleted time index /var/lib/kafka/data-0/kafka-log0/input-topic-runbo-7/00000000000001890878.timeindex.deleted. (kafka.log.LogSegment) [kafka-scheduler-6]

These are the last few lines of the broker, which stops few days ago, while the other two broker is still logging.
If it helps, here are one of the repeating log segment of the operator:

2023-03-13 05:20:47 INFO  ClusterOperator:125 - Triggering periodic reconciliation for namespace boc
2023-03-13 05:20:47 INFO  AbstractOperator:237 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Kafka boc-kafka-cluster will be checked for creation or modification
2023-03-13 05:20:47 INFO  AbstractOperator:237 - Reconciliation #15983(timer) KafkaConnect(boc/sftp-source-connect): KafkaConnect sftp-source-connect will be checked for creation or modification
2023-03-13 05:20:48 INFO  AbstractConnectOperator:470 - Reconciliation #15983(timer) KafkaConnect(boc/sftp-source-connect): creating/updating connector: sftp-source-connector
2023-03-13 05:20:48 INFO  AbstractOperator:501 - Reconciliation #15983(timer) KafkaConnect(boc/sftp-source-connect): reconciled
2023-03-13 05:21:19 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 250ms
2023-03-13 05:21:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:21:49 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 500ms
2023-03-13 05:22:20 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 1000ms
2023-03-13 05:22:47 INFO  ClusterOperator:125 - Triggering periodic reconciliation for namespace boc
2023-03-13 05:22:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:22:47 INFO  AbstractOperator:237 - Reconciliation #15985(timer) KafkaConnect(boc/sftp-source-connect): KafkaConnect sftp-source-connect will be checked for creation or modification
2023-03-13 05:22:47 INFO  AbstractConnectOperator:470 - Reconciliation #15985(timer) KafkaConnect(boc/sftp-source-connect): creating/updating connector: sftp-source-connector
2023-03-13 05:22:47 INFO  AbstractOperator:501 - Reconciliation #15985(timer) KafkaConnect(boc/sftp-source-connect): reconciled
2023-03-13 05:22:51 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 2000ms
2023-03-13 05:23:23 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 4000ms
2023-03-13 05:23:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:23:57 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 8000ms
2023-03-13 05:24:35 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 16000ms
2023-03-13 05:24:47 INFO  ClusterOperator:125 - Triggering periodic reconciliation for namespace boc
2023-03-13 05:24:47 INFO  AbstractOperator:237 - Reconciliation #15987(timer) KafkaConnect(boc/sftp-source-connect): KafkaConnect sftp-source-connect will be checked for creation or modification
2023-03-13 05:24:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:24:47 INFO  AbstractConnectOperator:470 - Reconciliation #15987(timer) KafkaConnect(boc/sftp-source-connect): creating/updating connector: sftp-source-connector
2023-03-13 05:24:47 INFO  AbstractOperator:501 - Reconciliation #15987(timer) KafkaConnect(boc/sftp-source-connect): reconciled
2023-03-13 05:25:21 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 32000ms
2023-03-13 05:25:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:26:23 INFO  KafkaRoller:306 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0} due to io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error getting broker config, retrying after at least 64000ms
2023-03-13 05:26:47 INFO  ClusterOperator:125 - Triggering periodic reconciliation for namespace boc
2023-03-13 05:26:47 INFO  AbstractOperator:237 - Reconciliation #15989(timer) KafkaConnect(boc/sftp-source-connect): KafkaConnect sftp-source-connect will be checked for creation or modification
2023-03-13 05:26:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:26:48 INFO  AbstractConnectOperator:470 - Reconciliation #15989(timer) KafkaConnect(boc/sftp-source-connect): creating/updating connector: sftp-source-connector
2023-03-13 05:26:48 INFO  AbstractOperator:501 - Reconciliation #15989(timer) KafkaConnect(boc/sftp-source-connect): reconciled
2023-03-13 05:27:47 INFO  AbstractOperator:378 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Reconciliation is in progress
2023-03-13 05:27:57 INFO  KafkaRoller:510 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Pod {boc-kafka-cluster-kafka-0} needs to be restarted. Reason: []
2023-03-13 05:28:30 WARN  NetworkClient:768 - [AdminClient clientId=adminclient-16684] Connection to node -1 (boc-kafka-cluster-kafka-0.boc-kafka-cluster-kafka-brokers.boc.svc.cluster.local/10.40.0.2:9091) terminated during authentication. This may happen due to any of the following reasons: (1) Authentication failed due to invalid credentials with brokers older than 1.0.0, (2) Firewall blocking Kafka TLS traffic (eg it may only allow HTTPS traffic), (3) Transient network issue.
2023-03-13 05:28:37 INFO  KafkaAvailability:135 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): input-topic-runbo/1 will be under-replicated (ISR={0}, replicas=[0,2], min.insync.replicas=1) if broker 0 is restarted.
2023-03-13 05:28:37 WARN  KafkaRoller:373 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Pod {boc-kafka-cluster-kafka-0} can't be safely force-rolled; original error: 
2023-03-13 05:28:37 INFO  KafkaRoller:299 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Could not roll pod {boc-kafka-cluster-kafka-0}, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error while trying to determine the cluster controller from pod boc-kafka-cluster-kafka-0
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.maybeTcpProbe(KafkaRoller.java:785) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.controller(KafkaRoller.java:760) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.deferController(KafkaRoller.java:737) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:340) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        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) ~[?:?]
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: listNodes
2023-03-13 05:28:37 ERROR AbstractOperator:258 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): createOrUpdate failed
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error while trying to determine the cluster controller from pod boc-kafka-cluster-kafka-0
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.maybeTcpProbe(KafkaRoller.java:785) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.controller(KafkaRoller.java:760) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.deferController(KafkaRoller.java:737) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:340) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        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) ~[?:?]
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: listNodes
2023-03-13 05:28:37 WARN  AbstractOperator:516 - Reconciliation #15982(timer) Kafka(boc/boc-kafka-cluster): Failed to reconcile
io.strimzi.operator.cluster.operator.resource.KafkaRoller$ForceableProblem: Error while trying to determine the cluster controller from pod boc-kafka-cluster-kafka-0
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.maybeTcpProbe(KafkaRoller.java:785) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.controller(KafkaRoller.java:760) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.deferController(KafkaRoller.java:737) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:340) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$6(KafkaRoller.java:284) ~[io.strimzi.cluster-operator-0.32.0.jar:0.32.0]
        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) ~[?:?]
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: listNodes

[scholzj]

Well, the OutOfMemory error in the code depends really on where it happened and how. It might be something it can recover from, it might also not be able to do so. If you want, there is a JVM flag to trigger exit on OOM errors which you can configure through the Kafka CR.

The operator log suggests it does not really work after the OOM error, so you should probably restart it manually by deleting the pod. You should also look into how you configured the cluster to avoid the OOM. You might need to tune the resource requests or the JVM settings.

[LinzeSu]

Thanks for the suggestions.