Broker keeps restarting on kubernetes while reloading producer snapshot

[ginwakeup]

Describe the bug
I have a 3 Broker setup. When one of them crashes, it fails to restart.

The situation it's a bit tricky as I can't seem to see any error, the broker pod on kubernetes simply restarts at some point while reloading the offsets/data on start...

I can see the broker pod readiness probe keeps failing, probably because the broker is taking forever to reload the segments:
(a piece of the log from the restarting broker)

2022-12-14 12:03:56,497 INFO [LogLoader partition=__consumer_offsets-41, dir=/var/lib/kafka/data-0/kafka-log1] Producer state recovery took 0ms for snapshot load and 1ms for segment recovery from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:03:56,499 INFO Completed load of Log(dir=/var/lib/kafka/data-0/kafka-log1/__consumer_offsets-41, topicId=WJP-YmuvQ7ieid7KZyv-lA, topic=__consumer_offsets, partition=41, highWatermark=0, lastStableOffset=0, logStartOffset=0, logEndOffset=0) with 1 segments in 20472ms (20/89 loaded in /var/lib/kafka/data-0/kafka-log1) (kafka.log.LogManager) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:03:56,507 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Recovering unflushed segment 0 (kafka.log.LogLoader) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:03:56,507 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:03:56,507 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Reloading from producer snapshot and rebuilding producer state from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:03:56,507 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Producer state recovery took 0ms for snapshot load and 0ms for segment recovery from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,980 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,980 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Reloading from producer snapshot and rebuilding producer state from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,981 INFO [LogLoader partition=__consumer_offsets-29, dir=/var/lib/kafka/data-0/kafka-log1] Producer state recovery took 1ms for snapshot load and 0ms for segment recovery from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,983 INFO Completed load of Log(dir=/var/lib/kafka/data-0/kafka-log1/__consumer_offsets-29, topicId=WJP-YmuvQ7ieid7KZyv-lA, topic=__consumer_offsets, partition=29, highWatermark=0, lastStableOffset=0, logStartOffset=0, logEndOffset=0) with 1 segments in 20483ms (21/89 loaded in /var/lib/kafka/data-0/kafka-log1) (kafka.log.LogManager) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,992 INFO [LogLoader partition=__consumer_offsets-44, dir=/var/lib/kafka/data-0/kafka-log1] Recovering unflushed segment 0 (kafka.log.LogLoader) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,992 INFO [LogLoader partition=__consumer_offsets-44, dir=/var/lib/kafka/data-0/kafka-log1] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,992 INFO [LogLoader partition=__consumer_offsets-44, dir=/var/lib/kafka/data-0/kafka-log1] Reloading from producer snapshot and rebuilding producer state from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,994 INFO Deleted producer state snapshot /var/lib/kafka/data-0/kafka-log1/__consumer_offsets-44/00000000000000000003.snapshot (kafka.log.SnapshotFile) [log-recovery-/var/lib/kafka/data-0/kafka-log1]
2022-12-14 12:04:16,994 INFO [LogLoader partition=__consumer_offsets-44, dir=/var/lib/kafka/data-0/kafka-log1] Producer state recovery took 1ms for snapshot load and 0ms for segment recovery from offset 0 (kafka.log.UnifiedLog$) [log-recovery-/var/lib/kafka/data-0/kafka-log1]

There's no error, the pod simply restarts so I think it could be readiness probe issue maybe?

To Reproduce
Steps to reproduce the behavior:

1. Create kafka cluster with 3 brokers, min insync replicas: 2, default replication: 3
2. Fill topics with some data, be sure consumer offsets topic is not empty
3. Make 1 broker crash
4. Observe the broker restarting and failing readiness probe on kubernetes, until it restarts the pod indefinitely.
5. The Kafka cluster never comes back again (this is also weird because I set min insync replicas to 2, and it shouldn't care about 1 broker going down)

Expected behavior
The broker should restart, reload the offsets and work fine after a crash.

Environment (please complete the following information):

• Strimzi version: 0.31.1
• Installation method: YAML
• Kubernetes cluster 1.22.1

YAML files and logs

KafkaCluster.yaml

apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
  name: messaging
spec:
  kafka:
    version: 3.2.3 #Apache Kafka version
    replicas: 3
    resources:
      requests:
        cpu: 1000m
        memory: 3Gi
      limits:
        cpu: 1000m
        memory: 4Gi
    listeners:
      - name: plain
        port: 9092
        type: internal
        tls: false
      - name: tls
        port: 9093
        type: internal
        tls: true
      - name: external
        port: 9094
        type: loadbalancer
        tls: false
        configuration:
          bootstrap:
            loadBalancerIP: ...
          brokers:
          - broker: 0
            loadBalancerIP: ...
          - broker: 1
            loadBalancerIP: ...
          - broker: 2
            loadBalancerIP: ...
    config:
      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 
      inter.broker.protocol.version: "3.2.3"
    readinessProbe:
      initialDelaySeconds: 30 # I tried to increase this with no success
      timeoutSeconds: 30
    storage:
      type: jbod
      volumes:
      - id: 0
        type: persistent-claim
        size: 100Gi
        deleteClaim: false
  zookeeper:
    replicas: 3
    storage:
      type: persistent-claim
      size: 100Gi
      deleteClaim: false
  entityOperator:
    topicOperator: {}
    userOperator: {}

[ginwakeup]

Not sure how, but I solved it by increasing the following values:

num.recovery.threads.per.data.dir: 4
num.network.threads: 3
num.io.threads: 8

[scholzj]

Yes, increasing the number of threads can speed up the startup. So I guess that is why it helped.