Kafka broker fails with OutOfMemoryError but container keeps running

[jakub-klapka]

Describe the bug
Hello, one of our kafka broker fails on OOM (which could be due to insufficient memory of course), but the container did not fail. Actually, even though kafka was not working, it's process was still present and even liveness probe was still returning success. So at the end, k8s had no idea, that kafka was down and did not restarted the instance.

I recall, that k8s reported usage 80% of memory limit.

I have tail of broker log:

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(ISHINT-9092)-SASL_SSL-8"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "ExpirationReaper-0-ElectLeader"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-socket-acceptor-ListenerName(ISHEXTTLS-9094)-SSL-9094"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "zk-session-expiry-handler0-SendThread(ish-kafka-cluster-zookeeper-client:2181)"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HTTP-Dispatcher"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "group-metadata-manager-0"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "ExpirationReaper-0-Heartbeat"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "ExpirationReaper-0-topic"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(TESTTLS-9096)-SSL-16"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(CONTROLPLANE-9090)-SSL-1"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "metrics-meter-tick-thread-2"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(REPLICATION-9091)-SSL-4"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(CONTROLPLANE-9090)-SSL-0"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(ISHINT-9092)-SASL_SSL-6"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-network-thread-0-ListenerName(REPLICATION-9091)-SSL-5"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "ThrottledChannelReaper-Produce"
2022-03-27 22:50:37,477 ERROR Error while accepting connection (kafka.network.Acceptor) [data-plane-kafka-socket-acceptor-ListenerName(TESTPLAIN-9095)-SASL_PLAINTEXT-9095]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:37,478 WARN A task raised an exception. Task: io.netty.channel.AbstractChannel$AbstractUnsafe$1@628aaf49 (io.netty.util.concurrent.AbstractEventExecutor) [nioEventLoopGroup-34-1]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:37,478 INFO future isn't success, cause: (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-34-1]
java.nio.channels.ClosedChannelException
    at io.netty.channel.AbstractChannel$AbstractUnsafe.newClosedChannelException(AbstractChannel.java:957)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.ensureOpen(AbstractChannel.java:976)
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.connect(AbstractNioChannel.java:237)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.connect(DefaultChannelPipeline.java:1342)
    at io.netty.channel.AbstractChannelHandlerContext.invokeConnect(AbstractChannelHandlerContext.java:548)
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:533)
    at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:517)
    at io.netty.channel.DefaultChannelPipeline.connect(DefaultChannelPipeline.java:978)
    at io.netty.channel.AbstractChannel.connect(AbstractChannel.java:253)
    at io.netty.bootstrap.Bootstrap$3.run(Bootstrap.java:250)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:829)
2022-03-27 22:50:38,001 WARN An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception. (io.netty.channel.DefaultChannelPipeline) [nioEventLoopGroup-32-1]
io.netty.channel.ChannelPipelineException: org.apache.zookeeper.ClientCnxnSocketNetty$ZKClientPipelineFactory.handlerAdded() has thrown an exception; removed.
    at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:624)
    at io.netty.channel.DefaultChannelPipeline.access$100(DefaultChannelPipeline.java:46)
    at io.netty.channel.DefaultChannelPipeline$PendingHandlerAddedTask.execute(DefaultChannelPipeline.java:1463)
    at io.netty.channel.DefaultChannelPipeline.callHandlerAddedForAllHandlers(DefaultChannelPipeline.java:1115)
    at io.netty.channel.DefaultChannelPipeline.invokeHandlerAddedIfNeeded(DefaultChannelPipeline.java:650)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.register0(AbstractChannel.java:502)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.access$200(AbstractChannel.java:417)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$1.run(AbstractChannel.java:474)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:38,006 ERROR [ExpirationReaper-0-Fetch]: Error due to (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-0-Fetch]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:38,007 INFO [ExpirationReaper-0-Fetch]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-0-Fetch]
2022-03-27 22:50:38,005 ERROR [ReplicaFetcher replicaId=0, leaderId=1, fetcherId=0] Error due to (kafka.server.ReplicaFetcherThread) [ReplicaFetcherThread-0-1]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:38,005 ERROR Uncaught exception in thread 'data-plane-kafka-socket-acceptor-ListenerName(REPLICATION-9091)-SSL-9091': (org.apache.kafka.common.utils.KafkaThread) [data-plane-kafka-socket-acceptor-ListenerName(REPLICATION-9091)-SSL-9091]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:38,008 INFO [ReplicaFetcher replicaId=0, leaderId=1, fetcherId=0] Stopped (kafka.server.ReplicaFetcherThread) [ReplicaFetcherThread-0-1]
2022-03-27 22:50:39,443 INFO Socket connection established, initiating session, client: /10.97.16.13:48070, server: ish-kafka-cluster-zookeeper-client/10.97.20.77:2181 (org.apache.zookeeper.ClientCnxn) [nioEventLoopGroup-32-1]
2022-03-27 22:50:38,006 ERROR Uncaught exception in thread 'SensorExpiryThread': (org.apache.kafka.common.utils.KafkaThread) [SensorExpiryThread]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:38,005 ERROR Uncaught exception in thread 'data-plane-kafka-request-handler-3': (org.apache.kafka.common.utils.KafkaThread) [data-plane-kafka-request-handler-3]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:50:39,783 INFO channel is connected: [id: 0xbb94454a, L:/10.97.16.13:48070 - R:ish-kafka-cluster-zookeeper-client/10.97.20.77:2181] (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-32-1]
2022-03-27 22:50:39,784 ERROR Uncaught exception in scheduled task 'kafka-recovery-point-checkpoint' (kafka.utils.KafkaScheduler) [kafka-scheduler-5]
java.lang.OutOfMemoryError: Java heap space

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "kafka-scheduler-1"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "data-plane-kafka-request-handler-0"
2022-03-27 22:52:39,672 ERROR Uncaught exception in scheduled task 'kafka-log-retention' (kafka.utils.KafkaScheduler) [kafka-scheduler-4]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:52:40,367 ERROR Uncaught exception in scheduled task 'PeriodicProducerExpirationCheck' (kafka.utils.KafkaScheduler) [kafka-scheduler-3]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:52:40,370 ERROR Uncaught exception in scheduled task 'kafka-recovery-point-checkpoint' (kafka.utils.KafkaScheduler) [kafka-scheduler-5]
java.lang.OutOfMemoryError: Java heap space
2022-03-27 22:52:40,746 ERROR Uncaught exception in thread 'data-plane-kafka-network-thread-0-ListenerName(ISHEXTTLS-9094)-SSL-10': (org.apache.kafka.common.utils.KafkaThread) [data-plane-kafka-network-thread-0-ListenerName(ISHEXTTLS-9094)-SSL-10]
java.lang.OutOfMemoryError: Java heap space

Since container was still running, I was able to shell into it and try /opt/kafka/kafka_liveness.sh which did return 0.

Here is output of ps:

[kafka@ish-kafka-cluster-kafka-0 kafka]$ ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
kafka        1     0  0 Mar27 ?        00:00:01 /usr/bin/tini -w -e 143 -- /opt/kafka/bin/kafka-server-start.sh /tmp/strimzi.properties
kafka       69     1 17 Mar27 ?        04:33:53 /usr/lib/jvm/jre-11/bin/java -Xms128M -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35
kafka      956     0  0 09:11 pts/1    00:00:00 bash
kafka      972   956  0 09:11 pts/1    00:00:00 ps -ef
kafka    30197     0  0 08:35 pts/0    00:00:00 bash

And netstat:

[kafka@ish-kafka-cluster-kafka-0 kafka]$ netstat -lnt
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State
tcp6       0      0 :::9404                 :::*                    LISTEN
tcp6       0      0 :::45149                :::*                    LISTEN
tcp6       0      0 :::9090                 :::*                    LISTEN
tcp6      51      0 :::9091                 :::*                    LISTEN
tcp6      51      0 :::9092                 :::*                    LISTEN
tcp6      51      0 :::9094                 :::*                    LISTEN
tcp6      51      0 :::9095                 :::*                    LISTEN
tcp6      51      0 :::9096                 :::*                    LISTEN

To Reproduce
Unfortunately, I don't know yet, how to reproduce that in consistent manner. This happened once during our production use and after manual restart of that container, it didn't happen again.

My hopes are, that you can see some "operation path", how this can happen. I don't have much knowledge about java runtime and it's memory management practices.

Expected behavior
We probably can solve the OOM issue by increasing KAFKA_HEAP_OPTS: -Xms128M, but I think, that in the described case, container should somehow fail, either by quitting their processes or returning non-0 from liveness probe.

Environment (please complete the following information):

• Strimzi version: quay.io/strimzi/kafka:0.25.0-kafka-2.7.0
• Installation method: Helm chart
• Kubernetes cluster: Kubernetes v1.21.9
• Infrastructure: Azure Kubernetes Service

YAML files and logs

Yaml of broker STS, so you can see startup params and memory limits:

apiVersion: apps/v1
kind: StatefulSet
metadata:
  annotations:
    strimzi.io/kafka-version: 2.7.0
    strimzi.io/storage: '{"volumes":[{"type":"persistent-claim","size":"200Gi","id":0}],"type":"jbod"}'
  creationTimestamp: "2022-03-14T18:27:38Z"
  generation: 2
  labels:
    app.kubernetes.io/instance: ish-kafka-cluster
    app.kubernetes.io/managed-by: strimzi-cluster-operator
    app.kubernetes.io/name: kafka
    app.kubernetes.io/part-of: strimzi-ish-kafka-cluster
    strimzi.io/cluster: ish-kafka-cluster
    strimzi.io/kind: Kafka
    strimzi.io/name: ish-kafka-cluster-kafka
  name: ish-kafka-cluster-kafka
  namespace: kafka
  ownerReferences:
  - apiVersion: kafka.strimzi.io/v1beta2
    blockOwnerDeletion: false
    controller: false
    kind: Kafka
    name: ish-kafka-cluster
    uid: 1544d95f-7fc3-4d8e-aad0-49a5d90f7f72
  resourceVersion: "11007450"
  uid: 334147f4-6591-44f5-8068-3fed045242d5
spec:
  podManagementPolicy: Parallel
  replicas: 3
  revisionHistoryLimit: 10
  selector:
    matchLabels:
      strimzi.io/cluster: ish-kafka-cluster
      strimzi.io/kind: Kafka
      strimzi.io/name: ish-kafka-cluster-kafka
  serviceName: ish-kafka-cluster-kafka-brokers
  template:
    metadata:
      annotations:
        kubectl.kubernetes.io/restartedAt: "2022-03-27T09:21:58+02:00"
        strimzi.io/broker-configuration-hash: 55ff6c7cdc46de94fa75c2634140d75a30dd0889bd4f4f169f005a29cb7c29ea62fd4aaea8530efc
        strimzi.io/clients-ca-cert-generation: "0"
        strimzi.io/cluster-ca-cert-generation: "0"
        strimzi.io/custom-listener-cert-thumbprints: '{ishexttls=xxx}'
        strimzi.io/generation: "0"
        strimzi.io/inter-broker-protocol-version: "2.7"
        strimzi.io/kafka-version: 2.7.0
        strimzi.io/log-message-format-version: "2.7"
        strimzi.io/logging-appenders-hash: e893ac9f32f7958042d1c82477e3484b0f8ebad5
        strimzi.io/storage: '{"volumes":[{"type":"persistent-claim","size":"200Gi","id":0}],"type":"jbod"}'
      creationTimestamp: null
      labels:
        app.kubernetes.io/instance: ish-kafka-cluster
        app.kubernetes.io/managed-by: strimzi-cluster-operator
        app.kubernetes.io/name: kafka
        app.kubernetes.io/part-of: strimzi-ish-kafka-cluster
        strimzi.io/cluster: ish-kafka-cluster
        strimzi.io/kind: Kafka
        strimzi.io/name: ish-kafka-cluster-kafka
      name: ish-kafka-cluster-kafka
    spec:
      affinity:
        nodeAffinity:
          requiredDuringSchedulingIgnoredDuringExecution:
            nodeSelectorTerms:
            - matchExpressions:
              - key: purpose
                operator: In
                values:
                - dbNode
        podAntiAffinity:
          requiredDuringSchedulingIgnoredDuringExecution:
          - labelSelector:
              matchExpressions:
              - key: strimzi.io/name
                operator: In
                values:
                - ish-kafka-cluster-kafka
            topologyKey: kubernetes.io/hostname
      containers:
      - command:
        - /opt/kafka/kafka_run.sh
        env:
        - name: KAFKA_METRICS_ENABLED
          value: "true"
        - name: STRIMZI_KAFKA_GC_LOG_ENABLED
          value: "false"
        - name: KAFKA_HEAP_OPTS
          value: -Xms128M
        image: quay.io/strimzi/kafka:0.25.0-kafka-2.7.0
        imagePullPolicy: IfNotPresent
        livenessProbe:
          exec:
            command:
            - /opt/kafka/kafka_liveness.sh
          failureThreshold: 3
          initialDelaySeconds: 15
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 5
        name: kafka
        ports:
        - containerPort: 9090
          name: tcp-ctrlplane
          protocol: TCP
        - containerPort: 9091
          name: tcp-replication
          protocol: TCP
        - containerPort: 9092
          name: tcp-ishint
          protocol: TCP
        - containerPort: 9094
          name: tcp-ishexttls
          protocol: TCP
        - containerPort: 9095
          name: tcp-testplain
          protocol: TCP
        - containerPort: 9096
          name: tcp-testtls
          protocol: TCP
        - containerPort: 9404
          name: tcp-prometheus
          protocol: TCP
        readinessProbe:
          exec:
            command:
            - test
            - -f
            - /var/opt/kafka/kafka-ready
          failureThreshold: 3
          initialDelaySeconds: 15
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 5
        resources:
          limits:
            memory: 1G
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
        volumeMounts:
        - mountPath: /var/lib/kafka/data-0
          name: data-0
        - mountPath: /tmp
          name: strimzi-tmp
        - mountPath: /opt/kafka/cluster-ca-certs
          name: cluster-ca
        - mountPath: /opt/kafka/broker-certs
          name: broker-certs
        - mountPath: /opt/kafka/client-ca-certs
          name: client-ca-cert
        - mountPath: /opt/kafka/custom-config/
          name: kafka-metrics-and-logging
        - mountPath: /var/opt/kafka
          name: ready-files
        - mountPath: /opt/kafka/certificates/custom-ishexttls-9094-certs
          name: custom-ishexttls-9094-certs
      dnsPolicy: ClusterFirst
      restartPolicy: Always
      schedulerName: default-scheduler
      securityContext:
        fsGroup: 0
      serviceAccount: ish-kafka-cluster-kafka
      serviceAccountName: ish-kafka-cluster-kafka
      terminationGracePeriodSeconds: 30
      tolerations:
      - effect: NoSchedule
        key: purpose
        operator: Equal
        value: dbNode
      volumes:
      - emptyDir:
          medium: Memory
          sizeLimit: 1Mi
        name: strimzi-tmp
      - name: cluster-ca
        secret:
          defaultMode: 292
          secretName: ish-kafka-cluster-cluster-ca-cert
      - name: broker-certs
        secret:
          defaultMode: 292
          secretName: ish-kafka-cluster-kafka-brokers
      - name: client-ca-cert
        secret:
          defaultMode: 292
          secretName: ish-kafka-cluster-clients-ca-cert
      - configMap:
          defaultMode: 420
          name: ish-kafka-cluster-kafka-config
        name: kafka-metrics-and-logging
      - emptyDir:
          medium: Memory
          sizeLimit: 1Ki
        name: ready-files
      - name: custom-ishexttls-9094-certs
        secret:
          defaultMode: 292
          items:
          - key: tls.key
            path: tls.key
          - key: tls.crt
            path: tls.crt
          secretName: ish-kafka-cluster-listener-ishexttls
  updateStrategy:
    type: OnDelete
  volumeClaimTemplates:
  - apiVersion: v1
    kind: PersistentVolumeClaim
    metadata:
      creationTimestamp: null
      name: data-0
    spec:
      accessModes:
      - ReadWriteOnce
      resources:
        requests:
          storage: 200Gi
      volumeMode: Filesystem
    status:
      phase: Pending
status:
  collisionCount: 0
  currentRevision: ish-kafka-cluster-kafka-5d89f69dd9
  observedGeneration: 2
  readyReplicas: 3
  replicas: 3
  updateRevision: ish-kafka-cluster-kafka-658dbcb8f9
  updatedReplicas: 3

Thank you, Jakub

[scholzj]

I have never seen this kind of error. I'm not sure Strimzi can do much about how Kafka is handling OoM exceptions. That is on Kafka. One thing I noticed from your StatefulSet, you do not have any resources configured. I think it would make sense to configure that to make sure the pods have a set amount of available memory. Not sure how much helps with this issue, but it should make it at least more clear what is hapepning.

[jakub-klapka]

It feels like some edge case with memory heap (but i still don't know anything about Java...). Should we try to reproduce it consistently (no promises), so maybe we can improve the liveness probe? Or it's not really a thing, you want in the probe and we'll leave it on Kafka/Java teams to solve (or ignore)?

[scholzj]

As I said, I haven't seen this before. So not sure how often it might happen.

CC @tombentley any idea about this one?

[ross211]

I usually run JVMs with -XX:+ExitOnOutOfMemoryError including Kafka (not using Strimzi yet) to avoid JVMs being allowed to run in unpredictable states after an OOME.

Looking at /opt/kafka/kafka_liveness.sh all it does is check something is listening on port 9091, so not surprising that continued to succeed. I'm using kcat in the healthchecks of our current non-Strimzi Kafkas.

[scholzj]

-XX:+ExitOnOutOfMemoryError can be easily configured in the Kafka CR. kcat as liveness probe seems fairly heavy.

[ross211]

Agreed, I would have preferred something more lightweight than kcat. Also kcat might fail temporarily if there is cluster leadership/rebalancing going on so care would need to be taken if using it in a liveness check.