Kafka and Zookeeper pods reports reason for termination as Completed even after some failure

[d-saikiran]

If there is any issue in Kafka and is restarted with below kafka log:
Terminating process due to signal SIGTERM
We see restart reason as completed instead of error.

This issue is reproducible easily, if we kill java process with SIGTERM.

[root@master-node ~]# k exec -it my-cluster-kafka-0 bash
[kafka@my-cluster-kafka-0 kafka]$ ls -l /proc/*/exe
lrwxrwxrwx 1 kafka root 0 Apr 18 11:51 /proc/1/exe -> /usr/bin/tini
lrwxrwxrwx 1 kafka root 0 Apr 18 11:51 /proc/810/exe -> /usr/bin/bash
lrwxrwxrwx 1 kafka root 0 Apr 18 11:51 /proc/94/exe -> /usr/lib/jvm/java-17-openjdk-17.0.10.0.7-2.el8.x86_64/bin/java
lrwxrwxrwx 1 kafka root 0 Apr 18 11:51 /proc/self/exe -> /usr/bin/coreutils
lrwxrwxrwx 1 kafka root 0 Apr 18 11:51 /proc/thread-self/exe -> /usr/bin/coreutils
[kafka@my-cluster-kafka-0 kafka]$ kill 94
[kafka@my-cluster-kafka-0 kafka]$ command terminated with exit code 137

Describe pod output:

Containers:
  kafka:
    Container ID:  containerd://1bd2cd2a14498cbc759780497b294ea6dc6385d43fe1c50c5d5e327d516d498f
    Image:         quay.io/strimzi/kafka:0.40.0-kafka-3.7.0
    Image ID:      quay.io/strimzi/kafka@sha256:c491a95f9b9b58f406461faf222ef612ad8d2f4d7b53f7f3645b20c99d7d1583
    Ports:         9090/TCP, 9091/TCP, 9092/TCP, 9093/TCP
    Host Ports:    0/TCP, 0/TCP, 0/TCP, 0/TCP
    Args:
      /opt/kafka/kafka_run.sh
    State:          Terminated
      Reason:       Completed
      Exit Code:    0
      Started:      Thu, 18 Apr 2024 13:51:11 +0200
      Finished:     Thu, 18 Apr 2024 13:51:47 +0200

Used following chart for operator deployment: https://github.com/strimzi/strimzi-kafka-operator/tree/main/helm-charts/helm3/strimzi-kafka-operator
kakfka CR used: https://github.com/strimzi/strimzi-kafka-operator/blob/main/examples/kafka/kafka-ephemeral-single.yaml

In above output, we can see exit code is 0 and reason is terminated insted of exit code 143. This can hide issues, when container stop is not intentional. Can you please look at issue and let me know if this is a bug?

Thanks & regards,
Saikiran

[scholzj]

I'm not sure what is it you expect. If you terminate the broker it will be indeed terminated. There is no bug in that.

[d-saikiran]

Hi @scholzj ,

Pod restart is expected and there is no issue with that. But when we see reason in describe pod output, it is Completed with exit code 0 instead of exit code 143.

If container stop is not intentional, then reason in describe pod output should not be Completed and that will hide issues. But in Strimzi code exit code 143 is remapped to 0 in this script: https://github.com/strimzi/strimzi-kafka-operator/blob/main/docker-images/kafka-based/kafka/scripts/kafka_run.sh#L122

[scholzj]

You have sent termination signal to the Kafka broker and it shutdown as you requested. So what else is that than a completed process?

[d-saikiran]

Hi @scholzj ,

Thank you for response. I see this issue even without sending termination signal to Kafka broker. This time with user-operator container after health checks were failed, we see Reason Completed with exit code 0.

  user-operator:
    Container ID:  containerd://349d12afc40d52dda62f08aa3c336790844134671d3d37385cc96ea3fbb73da7
    Image:         quay.io/strimzi/operator:0.40.0
    Image ID:      quay.io/strimzi/operator@sha256:2228d89b53e3524e69d1bcf5c2cd373884ce696d9005389a6c78dad23310e837
    Port:          8081/TCP
    Host Port:     0/TCP
    Args:
      /opt/strimzi/bin/user_operator_run.sh
    State:          Running
      Started:      Thu, 25 Apr 2024 14:53:44 +0200
    Last State:     Terminated
      Reason:       Completed
      Exit Code:    0
      Started:      Thu, 25 Apr 2024 14:53:04 +0200
      Finished:     Thu, 25 Apr 2024 14:53:44 +0200

Please find describe pod output and user-operator pod logs here:
entity_pod_describe.txt
user_operator_logs.txt

Events:

  Type     Reason     Age                From               Message
  ----     ------     ----               ----               -------
  Normal   Scheduled  58s                default-scheduler  Successfully assigned zahisad/my-cluster-entity-operator-5b78bc6bd-f6czm to node-10-117-149-18
  Normal   Pulled     58s                kubelet            Container image "quay.io/strimzi/operator:0.40.0" already present on machine
  Normal   Created    58s                kubelet            Created container topic-operator
  Normal   Started    58s                kubelet            Started container topic-operator
  Normal   Killing    19s                kubelet            Container user-operator failed liveness probe, will be restarted
  Warning  Unhealthy  19s (x5 over 48s)  kubelet            Readiness probe failed: HTTP probe failed with statuscode: 500
  Warning  Unhealthy  19s (x3 over 39s)  kubelet            Liveness probe failed: HTTP probe failed with statuscode: 500
  Normal   Created    18s (x2 over 58s)  kubelet            Created container user-operator
  Normal   Started    18s (x2 over 58s)  kubelet            Started container user-operator
  Normal   Pulled     18s (x2 over 58s)  kubelet            Container image "quay.io/strimzi/operator:0.40.0" already present on machine
  Warning  Unhealthy  9s (x4 over 39s)   kubelet            Startup probe failed: Get "http://192.168.93.78:8080/healthy": dial tcp 192.168.93.78:8080: connect: connection refused

Restart is due to timeout as per below log:

2024-04-25 12:15:06 INFO  AdminMetadataManager:267 - [AdminClient clientId=adminclient-1] Metadata update failed
org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: fetchMetadata

But when we see describe pod output, Reason is Completed due to exit code 0.

This I believe is due to remapping of exit code 143 to 0 in Strimzi code in below files.

[root@master-node strimzi]# grep -r "/usr/bin/tini -w -e 143" strimzi-kafka-operator-main
strimzi-kafka-operator-main/docker-images/kafka-based/kafka/cruise-control-scripts/cruise_control_run.sh:exec /usr/bin/tini -w -e 143 -- java ${KAFKA_HEAP_OPTS} ${KAFKA_JVM_PERFORMANCE_OPTS} ${KAFKA_GC_LOG_OPTS} ${KAFKA_JMX_OPTS} ${KAFKA_LOG4J_OPTS} ${KAFKA_OPTS} -classpath "${CLASSPATH}" com.linkedin.kafka.cruisecontrol.KafkaCruiseControlMain /tmp/cruisecontrol.properties
strimzi-kafka-operator-main/docker-images/kafka-based/kafka/exporter-scripts/kafka_exporter_run.sh:exec /usr/bin/tini -w -e 143 -- /tmp/run.sh
strimzi-kafka-operator-main/docker-images/kafka-based/kafka/scripts/kafka_connect_run.sh:exec /usr/bin/tini -w -e 143 -- "${KAFKA_HOME}/bin/connect-distributed.sh" /tmp/strimzi-connect.properties
strimzi-kafka-operator-main/docker-images/kafka-based/kafka/scripts/kafka_mirror_maker_run.sh:exec /usr/bin/tini -w -e 143 -- "$KAFKA_HOME"/bin/kafka-mirror-maker.sh \
strimzi-kafka-operator-main/docker-images/kafka-based/kafka/scripts/kafka_run.sh:exec /usr/bin/tini -w -e 143 -- "${KAFKA_HOME}/bin/kafka-server-start.sh" /tmp/strimzi.properties
strimzi-kafka-operator-main/docker-images/kafka-based/kafka/scripts/zookeeper_run.sh:exec /usr/bin/tini -w -e 143 -- "${KAFKA_HOME}/bin/zookeeper-server-start.sh" /tmp/zookeeper.properties
strimzi-kafka-operator-main/docker-images/operator/scripts/launch_java.sh:exec /usr/bin/tini -w -e 143 -- java $JAVA_OPTS -classpath "$JAVA_CLASSPATH" "$JAVA_MAIN" "$@"

This remapping of exit code to 0 will hide issues if container stop is not intentional as in current case.

Can this remapping of 143 exit code to 0 be removed from Strimzi? If not, can we know why this is added?

Thanks & regards,
Saikiran

[scholzj]

It clearly does not hide any issues if you still know who terminated it and how / why. SIGTERM is a normal way how to terminate the container and if the container terminates correctly, there is no reason to handle it as some special event with regards to shutdown. Special event is when the container is terminated by some probe failures. But the container does not know about that, it was just told to terminate so it terminated. Why was it terminated is in the events for example. This is different from for example being killed because of being out of memory etc., where you get different codes.