Disruption test caused error: /opt/kafka/kafka_run.sh: line 32: /tmp/password.file: Permission denied

[fsouza-bux]

Hi guys,

In doing a small disruption test with our strimzi kafka cluster, and now we are getting an error related to permissions.
We have deleted one kafka broker pod, to check if it would recover, and it's not restarting anymore with the following error, related to permissions when starting the Pod, error is from the kafka-init initContainer:

+ JMX_ACCESS_FILE=/tmp/access.file
+ JMX_PASSWORD_FILE=/tmp/password.file
+ cat
+ cat
/opt/kafka/kafka_run.sh: line 32: /tmp/password.file: Permission denied

Looking at the other brokers the user running it is the user kafka, but with group root:

[kafka@kafka-kafka-1 kafka]$ id
uid=1001(kafka) gid=0(root) groups=0(root)
[kafka@kafka-kafka-1 kafka]$ ls -ltr /tmp/password.file
-r-------- 1 kafka root 34 Feb 17 21:09 /tmp/password.file

We are not using any custom images, and for storage we are creating the PVCs ahead of time, and we didn't include anything in the template related to the securityContext.
One additional info, the strimzi operator seems to not be pushing any updates we are doing to the cluster now, and it's throwing the following error message:

2021-02-23 12:26:00 WARN  AbstractOperator:379 - Reconciliation #80(timer) Kafka(kafka/kafka): Failed to acquire lock lock::kafka::Kafka::kafka within 10000ms.

Any ideas on how to get out of this deadlock situation? it seems that even when pushing new changes to the cluster it won't work as this reconcile is not being able to restart the pod.

Cheers,

Fernando

[fsouza-bux]

One additional update, i restarted the strimzi-operator, and it has passed through the first issue mentioned, but anyway it's erroring again, but now on a different point:

+ exec /usr/bin/tini -w -e 143 -- /opt/kafka/bin/kafka-server-start.sh /tmp/strimzi.properties
log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: /opt/kafka/kafka-request.log (Permission denied)

• Would that be related to the pre-created PVs / PVCs?
• is it mandatory to always push the security context to execute as root in certain cases?

I didn't change yet the securityContext but I'll be testing to see if the cluster recovers now and it's able to bring up the broker again.

Just to mention all version we are using now for these tests:
strimzi-kafka-operator: 0.21.1
k8s version (GKE): 1.18.12-gke.1206

[scholzj]

Well, the broker certainly cannot write to /opt/kafka/kafka-request.log. It should send all logs to standard output. So maybe that is related to something you have in the external Log4j configuration?

    logging:
      name: kafka-broker-log4j-config
      type: external

[fsouza-bux]

It might be let me check again that specific configuration session, but anyway I got to fix all the permission issues after including the securityContext to run as root.

[fsouza-bux]

Hi Jakub, in checking our log4j config, it is included there to write to this kafka-request.log file, but using the following:

log4j.appender.requestAppender.File=${kafka.logs.dir}/kafka-request.log

The weird part is that this was working just before the exception with the JMX password with the user kafka, but it might be the case that we could be getting some error's or warning's?
I'll remove those particular logs being pushed to files, if everything needs to be pushed to std out.

[scholzj]

TBH I do not think this ever worked. But in the past I did not saw this crash the pod. It IMHO just prints the error and continues happily (I guess Log4j had no way to shutdown the broker gracefully so it is either this System.exit() which would be evil as well). But I have no idea how would this related to the JMX stuff.

[fsouza-bux]

Ok, no worries, i think we can move everything to be pushing the logs to only stdout.
These are the other entries we have in log4j:

log4j.appender.kafkaAppender.File=${kafka.logs.dir}/server.log
log4j.appender.stateChangeAppender.File=${kafka.logs.dir}/state-change.log
log4j.appender.requestAppender.File=${kafka.logs.dir}/kafka-request.log
log4j.appender.cleanerAppender.File=${kafka.logs.dir}/log-cleaner.log
log4j.appender.controllerAppender.File=${kafka.logs.dir}/controller.log
log4j.appender.authorizerAppender.File=${kafka.logs.dir}/kafka-authorizer.log

We inherited this log4j conf from the current deployment, and i didn't observe before those log redirects to file.
As everything is not running as root, i think it was able to write the files:

[root@kafka-kafka-0 kafka]# cat /opt/kafka/log-cleaner.log
[2021-03-01 09:45:17,803] INFO Starting the log cleaner (kafka.log.LogCleaner)
[2021-03-01 09:45:18,178] INFO [kafka-log-cleaner-thread-0]: Starting (kafka.log.LogCleaner)
[root@kafka-kafka-0 kafka]#
[root@kafka-kafka-0 kafka]# cat /opt/kafka/controller.log
[2021-03-01 09:45:20,685] INFO [ControllerEventThread controllerId=0] Starting (kafka.controller.ControllerEventManager$ControllerEventThread)
[root@kafka-kafka-0 kafka]#