All three quorum queue replicas run into an identical EOF exception on Kubernetes

[sbocahu]

Describe the bug

3 nodes cluster with quorum queues. One queue got in a bad state: consumers get Connection closed: 541 and rabbitmq server logs show crashes with exception ra_log_segment_unexpected_eof.

This exception get a single result on google: 9733 / but segment_max_entries = 4096 so it seems unrelated.

Rabbitmq management UI showed '???' in metrics for the queue (ready/acked messages...)

rabbitmq-queues quorum_status queue shows one node is pre-vote state and two in timeout.

First try to delete the queue from the UI: error with timeout.

Tried from the cli to delete_member each node:

{:no_more_servers_to_try, [timeout: {:"%2F_queue", :"[email protected]"}, timeout: {:"%2F_queue", :"[email protected]"}, timeout: {:"%2F_queue", :"[email protected]"}]}

tried again from the ui and it worked...

I experienced similar issue one another cluster few days ago. rabbitmq-management ui was showing numbers in metrics, queue was empty with 2 unacked messages but rabbitmq-server was crashing with the same ra_log_segment_unexpected_eof exception.

Reproduction steps

1. setup a rabbitmq cluster, version 3.13.0
2. use quorum queues
3. wait ?
   ...

Expected behavior

i expect rabbitmq server not to crash

Additional context

No response

[kjnilsson]

How are you running RabbitMQ, in which type of environment and what type of disks / filesystem do you use?

Can you share full logs from all nodes or ideally the data directory with us?

Have you made any recent changes to your infrastructure?

[sbocahu]

We are using RabbitMQ Operator for kubernetes managed 3 nodes cluster using local storage on LVM/ext4 on SSD disks.

I may not be able to share the data director as it may contain sensitive information. I'll see what I can do.
But is it still valid after the deletion of the impacted queue ?

We have been running such clusters for months without any issue. Upgraded fro mtime to time. Latest upgrade; from 5.12.12 from 5.13.0; took place on march 2. The disk space allocated to rabbitmq has been raised from 20GB to 25GB 4 days ago.

I extracted the logs from grafana, 12 to 4 days ago (too many lines to get the full logs efficiently, it loops on the same errors)

server-0.txt
server-1.txt
server-2.txt

thanks !

[sbocahu]

In the initial description I reported a first issue on another cluster, but I was wrong. It was on the same cluster and happened on march 9. So growing disk seem to be unrelated.

[michaelklishin]

Since Kubernetes adds a ton of complexity and additional layers to debug, we need a way to reproduce this behavior outside of Kubernetes. "Install Kubernetes" is not a reproduction step because is a good dozen of flavors available, many fragmented in subtle ways.

[michaelklishin]

All nodes log exactly the same exception that looks like this:

2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0> ** Reason for termination = exit:{ra_log_segment_unexpected_eof,30756,
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>                                      "/var/lib/rabbitmq/mnesia/[email protected]./quorum/[email protected]./2F_PUS3R21LYLA3VJZ/00000009.segment"}
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0> ** Callback modules = [ra_server_proc]
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0> ** Callback mode = [state_functions,state_enter]
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0> ** Stacktrace =
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0> **  [{ra_log_segment,fold0,8,[{file,"src/ra_log_segment.erl"},{line,366}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_log_reader,'-segment_fold/5-fun-1-',4,
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>                     [{file,"src/ra_log_reader.erl"},{line,378}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_log_reader,'-segment_fold/5-lists^foldl/2-1-',3,
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>                     [{file,"src/ra_log_reader.erl"},{line,375}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_log_reader,segment_fold,5,
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>                     [{file,"src/ra_log_reader.erl"},{line,375}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_log_reader,'-fold/5-lists^foldl/2-1-',3,
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>                     [{file,"src/ra_log_reader.erl"},{line,173}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_log,fold,5,[{file,"src/ra_log.erl"},{line,314}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_server,apply_to,5,[{file,"src/ra_server.erl"},{line,2306}]},
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0>      {ra_server,recover,1,[{file,"src/ra_server.erl"},{line,374}]}]
2024-03-16 17:45:47.082	2024-03-16 16:45:47.071348+00:00 [error] <0.19631090.0> 
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>   crasher:
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>     initial call: ra_server_proc:init/1
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>     pid: <0.19631090.0>
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>     registered_name: '%2F_push_playbook'
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>     exception exit: {ra_log_segment_unexpected_eof,30756,
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>                         "/var/lib/rabbitmq/mnesia/[email protected]./quorum/[email protected]./2F_PUS3R21LYLA3VJZ/00000009.segment"}
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in function  ra_log_segment:fold0/8 (src/ra_log_segment.erl, line 366)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_log_reader:'-segment_fold/5-fun-1-'/4 (src/ra_log_reader.erl, line 378)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_log_reader:'-segment_fold/5-lists^foldl/2-1-'/3 (src/ra_log_reader.erl, line 375)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_log_reader:segment_fold/5 (src/ra_log_reader.erl, line 375)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_log_reader:'-fold/5-lists^foldl/2-1-'/3 (src/ra_log_reader.erl, line 173)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_log:fold/5 (src/ra_log.erl, line 314)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_server:apply_to/5 (src/ra_server.erl, line 2306)
2024-03-16 17:45:47.082	2024-03-16 16:45:47.079733+00:00 [error] <0.19631090.0>       in call from ra_server:recover/1 (src/ra_server.erl, line 374)

(the segment file names are different, of course).

It looks quite likely that something in this cluster is off on all nodes, could be disk volume availability or something like that.

It is very unusual to see the same local operation exception on all nodes, repeatedly, otherwise.

[michaelklishin]

@sbocahu our working hypothesis is that a brief episode of running out of disk space resulted in an incomplete Raft segment file write. In fact, @kjnilsson can reproduce this exception with a deliberately trimmed segment file.

But I guess we cannot be fully sure without at least the segment file in question, or ideally a bunch of them :(

[michaelklishin]

Also, if that is the case, our Raft library could lean up such segment files or fail. I guess which option is better is a philosophical question that will vary from one tech operations team to the other.

I guess it could be an option with the current default (fail) unless @kjnilsson objects.

[kjnilsson]

@sbocahu on second inspection this issue isn't actually a data corruption per-se, at least not in the way I thought it might be. If these is any way you could share some segment data with me I may be able to work out what went on. E.g. /var/lib/rabbitmq/mnesia/[email protected]./quorum/[email protected]./2F_PUS9UDF41G78XUP/00000009.segment

[kjnilsson]

@sbocahu did you at any point find an error in the logs something like "segment_writer: N failures encountered during segment flush..." segment_writer_segment_write_failure?

[sbocahu]

@kjnilsson yes:

To your previous question: the 2F_PUS9UDF41G78XUP folder does not exist anymore