Node on CentOS 8 fails to start with an 'eacces' error while using PVC as volume

[satyaranjanp]

I am facing issues when trying to deploy a rabbitmq cluster (more than one node) on kubernetes cluster on centos 8 machines.
Here are the details of the cluster:
Kubernetes version: Tried with 1.13.10, 1.17.5, 1.20.0
OS version on which k8s is deployed: centos 8
Rabbitmq version: tried with 3.8.4, 3.8.12

Below is the log with the issue (I have omitted some logs in between)

Starting broker...2021-02-11 08:32:26.301 [info] <0.268.0>
node           : rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local
home dir       : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash    : P1jSccBnQ4dVHVP8i9KFXA==
log(s)         : <stdout>
database dir   : /var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local
..........................
2021-02-11 08:32:31.098 [info] <0.268.0> Feature flags:   [ ] virtual_host_metadata
2021-02-11 08:32:31.098 [info] <0.268.0> Feature flags: feature flag states written to disk: yes
2021-02-11 08:32:31.111 [info] <0.268.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-02-11 08:32:31.112 [info] <0.268.0> Successfully synced tables from a peer
2021-02-11 08:32:31.112 [info] <0.268.0> Feature flag `quorum_queue`:   migrating Mnesia table rabbit_queue...
2021-02-11 08:32:31.232 [info] <0.268.0> Feature flag `quorum_queue`:   migrating Mnesia table rabbit_durable_queue...
dets: file "/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT" not properly closed, repairing ...
2021-02-11 08:32:31.387 [info] <0.268.0> Feature flag `quorum_queue`:   Mnesia tables migration done
2021-02-11 08:32:31.387 [info] <0.268.0> Feature flag `quorum_queue`: mark as enabled=true
2021-02-11 08:32:31.401 [info] <0.268.0> Feature flags: list of feature flags found:
...........................
2021-02-11 08:32:31.987 [info] <0.268.0> Setting user tags for user 'web' to [administrator]
2021-02-11 08:32:31.995 [info] <0.268.0> Setting permissions for 'web' in '/' to '.*', '.*', '.*'
2021-02-11 08:32:32.003 [info] <0.268.0> Running boot step rabbit_looking_glass defined by app rabbit
2021-02-11 08:32:32.003 [info] <0.268.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2021-02-11 08:32:32.004 [info] <0.268.0> Running boot step background_gc defined by app rabbit
2021-02-11 08:32:32.004 [info] <0.268.0> Running boot step connection_tracking defined by app rabbit
2021-02-11 08:32:32.050 [info] <0.268.0> Setting up a table for connection tracking on this node: 'tracked_connection_on_node_rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local'
2021-02-11 08:32:32.119 [error] <0.389.0> Mnesia('rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local'): ** ERROR ** (could not write core file: eacces)
 ** FATAL ** {error,{"Cannot open dets table",schema,[{file,"/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT"},{keypos,2},{repair,true},{type,set}],{not_a_dets_file,"/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT"}}}
2021-02-11 08:32:42.119 [error] <0.389.0> Mnesia('rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local'): ** ERROR ** mnesia_event got unexpected event: {'EXIT',<0.393.0>,killed}
2021-02-11 08:32:42.121 [error] <0.389.0> CRASH REPORT Process mnesia_event with 0 neighbours exited with reason: killed in gen_event:terminate_server/4 line 397
2021-02-11 08:32:42.123 [error] <0.386.0> CRASH REPORT Process <0.386.0> with 0 neighbours exited with reason: killed in application_master:terminate/2 line 232
2021-02-11 08:32:42.123 [info] <0.44.0> Application mnesia exited with reason: killed
2021-02-11 08:32:59.463 [info] <0.596.0> node 'rabbit@rbt-35-1.rbt-35-discovery.rabbitmq.svc.cluster.local' up
2021-02-11 08:34:32.005 [error] <0.674.0> ** Generic server rabbit_core_metrics_gc terminating

How to reproduce:

1. Have a kubernetes cluster on centos 8 vm (centos 8 is important, as the issue appears in this specific version)
2. Deploy rabbitmq cluster (using operator or manually), with more that one node, on kubernetes cluster. Use PVC for volume mounts in the rabbitmq pods.
3. First node comes up fine, but when the second node comes up, it tries to form a cluster with first node and then we hit this issue
4. This issue arises only when using PVC used as volume.
5. I am not getting this issue while using hostpath as volume on centos 8. Also, not facing this issue on centos 7, even while using PVC.
6. To sum up, the issue occurs on kubernetes, deployed on cenos 8 vm and while using PVC as volume for the rabbitmq pods.

[michaelklishin]

I will convert this issue to a GitHub discussion. Currently GitHub will automatically close and lock the issue even though your question will be transferred and responded to elsewhere. This is to let you know that we do not intend to ignore this but this is how the current GitHub conversion mechanism makes it seem for the users :(

[michaelklishin]

2021-02-11 08:32:32.119 [error] <0.389.0> Mnesia('rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local'): ** ERROR ** (could not write core file: eacces)

is the line you are looking for. The node fails to open a file used by its schema database because the OS returned an error: eacces (UNIX speak for "insufficient permissions").

[michaelklishin]

Without any detailed deployment information, in particular around storage, we won't be able to suggest anything beyond that: we
do not guess in this community. One part is more or less obvious from the log snippet: It is file system operation permission issue of some kind.

Some Kubernetes distributions, e.g. OpenShift, require additional SELinux policy tweaking.

[satyaranjanp]

I am getting this log every time I deploy on k8s cluster (on centos 8) with PVC as volume:

dets: file "/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT" not properly closed, repairing ...

It seems like the schema.DAT file becomes inconsistent while starting up.
And when a second pod comes up, to form a cluster, mnesia tries to open this file in recovery mode and then fails.

** FATAL ** {error,{"Cannot open dets table",schema,[{file,"/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT"},{keypos,2},{repair,true},{type,set}],{not_a_dets_file,"/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT"}}}

My guess is when it fails to read this schema.DAT file, it crashes and then it tries to write the core file, and again that also fails due to permission issue, even when I run the pods with root privilege.

[michaelklishin]

In order to understand when a DETS file would be incorrectly closed, I did a bit of googling. This DETS guide states that

Dets tables are not properly closed if the Erlang runtime system is terminated abnormally.

So it can be that the node is killed at some point. This dets module test suite
simulates this by writing some data to the file without fsync(2) and closing it:

crash(File, Where) ->
    crash(File, Where, 10).

crash(File, Where, What) when is_integer(What) ->
    {ok, Fd} = file:open(File, [read,write]),
    file:position(Fd, Where),
    ok = file:write(Fd, [What]),
    ok = file:close(Fd).

We don't have any information about what happened to the node. Consider collecting and sharing releavant OS logs, complete RabbitMQ logs, and maybe some Kubernetes pod events.
It very well may be that both symptoms have the same root cause: insufficient permissions of some kind.
Again, we don't have much to work with here: no Kubernetes deployment details of any kind. We do not guess in this community.

We absolutely do not recommend running RabbitMQ nodes as root. There are no reasons to do that.

[michaelklishin]

PVC doc section on access modes suggests that a volume can be mounted to multiple pods. Such scenario would be catastrophic for RabbitMQ nodes if they end up sharing a node data directory: they will not coordinate in any way and will end up rewriting each other's data.

This is my best guess (we don't have any Kubernetes deployment details to confirm): this PVC uses an access mode that results in nodes sharing a data directory, which is AN ABSOLUTE NO-NO and is guaranteed to result in data corruption and really confusing errors.

[michaelklishin]

The pod management policy used is also important here. If it is Parallel with a randomized startup delay, the above concurrent data directory access can happen early on first node's boot. With Ordered the first node should start just fine (there are no competing writers) and then fail on the second node boot.

[satyaranjanp]

@michaelklishin Thank you for sharing all these information. I will get more rabbitmq logs, OS logs and k8s events related to this.

Just for clarification,

1. Rabbitmq pods are not sharing single PVC. They are having their dedicated PVC attached to them.
2. The pods are not coming up parallelly. They are getting created up one after another. After the first pod comes to running state, the next pod is being created.

And to add, even when I create a single node rabbitmq cluster, that time also I am getting this log during starting up of rabbitmq:

dets: file "/var/lib/rabbitmq/mnesia/rabbit@rbt-35-0.rbt-35-discovery.rabbitmq.svc.cluster.local/schema.DAT" not properly closed, repairing ...

[michaelklishin]

Run this node under strace and with debug logging on, it will tell you what exactly the node does to that file.

Instead of focussing on the "DETS file was not properly closed" I'd focus on the eacces one.

I also have asked for the Kubernetes deployment file. Consider sharing it.

[satyaranjanp]

Thanks for your suggestions, I will definitely try running strace.

I have attached the kubernetes deplyment file (rabbit-statefulset.yaml), logs from both the rabbitmq pods and kubernetes events in that namespace. I will try to get more info after running node under strace.

k8s_events.txt
rabbit-node-0-log.txt
rabbit-node-1-log.txt
rabbit-statefulset.yaml.txt