[Questions] Classic queue pread eof crash on 4.1.1 (continuation of #12367 and #13758)

[gomoripeti]

Community Support Policy

• I have read RabbitMQ's Community Support Policy
• I run RabbitMQ 4.x, the only series currently covered by community support
• I promise to provide all relevant information (versions, logs from all nodes, rabbitmq-diagnostics output, detailed reproduction steps)

RabbitMQ version used

4.1.1

Erlang version used

27.3.x

Operating system (distribution) used

ubuntu

How is RabbitMQ deployed?

Debian package

rabbitmq-diagnostics status output

See https://www.rabbitmq.com/docs/cli to learn how to use rabbitmq-diagnostics

# PASTE OUTPUT HERE, BETWEEN BACKTICKS

Logs from node 1 (with sensitive values edited out)

See https://www.rabbitmq.com/docs/logging to learn how to collect logs

# PASTE LOG HERE, BETWEEN BACKTICKS

Logs from node 2 (if applicable, with sensitive values edited out)

See https://www.rabbitmq.com/docs/logging to learn how to collect logs

# PASTE LOG HERE, BETWEEN BACKTICKS

Logs from node 3 (if applicable, with sensitive values edited out)

See https://www.rabbitmq.com/docs/logging to learn how to collect logs

# PASTE LOG HERE, BETWEEN BACKTICKS

rabbitmq.conf

See https://www.rabbitmq.com/docs/configure#config-location to learn how to find rabbitmq.conf file location

# PASTE rabbitmq.conf HERE, BETWEEN BACKTICKS

Steps to deploy RabbitMQ cluster

Steps to reproduce the behavior in question

unknown

advanced.config

See https://www.rabbitmq.com/docs/configure#config-location to learn how to find advanced.config file location

# PASTE advanced.config HERE, BETWEEN BACKTICKS

Application code

# PASTE CODE HERE, BETWEEN BACKTICKS

Kubernetes deployment file

# Relevant parts of K8S deployment that demonstrate how RabbitMQ is deployed
# PASTE YAML HERE, BETWEEN BACKTICKS

What problem are you trying to solve?

A single node cluster was upgraded to RabbitMQ 4.1.1 about a week ago. Since then the below crash happened two times (on the same queue).

    supervisor: {<0.633.0>,rabbit_amqqueue_sup}
    errorContext: child_terminated
    reason: {function_clause,
                [{rabbit_msg_store,reader_pread_parse,
                     [[[[ eof ]]]],
                     [{file,"src/rabbit_msg_store.erl"},{line,686}]},
                 {rabbit_msg_store,reader_pread,2,
                     [{file,"src/rabbit_msg_store.erl"},{line,682}]},
                 {rabbit_msg_store,read_from_disk,2,
                     [{file,"src/rabbit_msg_store.erl"},{line,642}]},
                 {rabbit_msg_store,client_read3,2,
                     [{file,"src/rabbit_msg_store.erl"},{line,634}]},
                 {rabbit_variable_queue,with_msg_store_state,3,
                     [{file,"src/rabbit_variable_queue.erl"},{line,1057}]},
                 {rabbit_variable_queue,read_msg,5,
                     [{file,"src/rabbit_variable_queue.erl"},{line,1291}]},
                 {rabbit_variable_queue,fetch,2,
                     [{file,"src/rabbit_variable_queue.erl"},{line,573}]},
                 {rabbit_priority_queue,'-fetch/2-fun-0-',4,
                     [{file,"src/rabbit_priority_queue.erl"},{line,256}]}]}

This is not the same crash as reported in #13758 and addressed in #13771 (which happens when trying to read multiple messages from disk into memory via rabbit_msg_store:read_many_file2/4 triggered by rabbit_variable_queue:remove_by_predicate/2)
But more similar to one reported in #12367 (when a single message is fetched, I assume, to be sent to a consumer)

About the setup:
The affected queue has: max-priority 2, expires 2 days
bound to a topic exchange with <key1>.#
topic exchange has 1 more binding with <key1>.#.<key2>.#

This server also experienced the pread within read_many crash addressed by #13771 before upgrading to 4.1.1, so it seems to have a special traffic pattern that is prone to expose issues with the shared message store. I might be able to add some tracing to catch additional info to help get closer to the root cause. What kind of info would be useful?

[gomoripeti]

The same server crashed several times in the past month. Both single read and read_many type of crashes occred. We have backup of the mnesia dir and extra logging for some of the crashes.

The last crash that happened on 2025-08-26 06:26:35.755199+00:00 was particularly interresting.

Logging the file_summary record of an affected rdq file, valid size is ~6MB but file size is only ~4MB, (This is the first time I saw such inconsistent file_summary record)

[{file_summary,340809,6614143,undefined,undefined,4295991,false,undefined}]},

File size is correct, same as on disk

ls
-rw-r----- 1 rabbitmq rabbitmq 4295991 Aug 26 04:40:09 msg_stores/vhosts/86WAU76IUR0OIES3J9T8DFV6Y/msg_store_persistent/340809.rdq

There are zero-holes in the rdq file so the file must have been compacted and truncated (probably at 4:40:09).

These are the locations given to pread. The last 5 entries are beyond the file size (and even beyond valid_size)

[{130491,11870},
 {172663,12598},
 {203369,71595},
 {309250,12336},
 {336103,12601},
 {366857,67359},
 {1035857,10755},
 {1719886,9037},
...
 {3892806,9900},
 {3947218,30117},
 {3992133,29293},
 {4062239,49681},
 {4195506,21161},
 {9458386,23505},
 {9495881,24292},
 {9907941,9380},
 {9934406,81047},
 {12499180,12630}]},

Unfortunately (or fortunately for the user) there were config changes made so the crash will likely won't happen again for further debugging.

The inconsistnt file_summary record is the most disturbing for me.

[lukebakken]

For what it's worth I've confirmed that this bug existed as far back as 3.13.7.

[lhoguin]

This one specifically or eof crashes? We've fixed a couple cases leading to eof since.

[lhoguin]

@gomoripeti For the preads in this I assume the crash logs did not have client_read3? Since that one should only read one message.

[gomoripeti]

the server crashed multiple occasions. One day it crashed in client_read3 single read another day in read_many. That's why I think the bug is not related to the reading (or it might be related to read-locks during compaction but not the read that crashes), that is only a symptom. But the msg_store is corrupted already, probably during compactions. (Maybe it needs multiple compactions)

In #14181 (comment) occasion the crash happened 2 hours after the rdq file was last modified (06:26:35 vs 4:40)

[gomoripeti]

Also in #14181 (comment) occasion the msg_id that is not found is not present anywhere in the file. So it is not only that the reader uses an outdated location from the index, but the msg is lost from the rdq file.

[trvrnrth]

We are seeing the same issue reported here across a fleet of standalone rabbit 4.1.1 instances with multiple daily crashes across several different queues.

I cannot determine a pattern of behaviour leading to the crashes but perhaps some of the following information may be helpful:

• all impacted queues are durable classic queues (we do not run any quorum queues on these instances)
• self-recovery is not always successful, requiring a delete and re-create of the queue to restore normal operation
• we see crashes more often on a set of priority queues
• the worst affected queues have a pattern of relatively fast publishes followed by a period of slow consumption with some message processing taking upwards of 1 hour by design before ack
• there is no easily discernable correlation between the time of crash and any increased/decreased publish/consume activity

Unfortunately I cannot share full logs as they may contain sensitive data, but I am happy to provide any extra context that may be valuable to investigation of the issue.

[lukebakken]

@trvrnrth I've got some additional questions based on this comment of yours:

the worst affected queues have a pattern of relatively fast publishes followed by a period of slow consumption with some message processing taking upwards of 1 hour by design before ack

I think this statement is the key to reproducing this issue, and the more we can learn about the exact workload, the more likely it is to reproduce.

• When you say "relatively fast publishes" can you quantify this better, in terms of overall msgs/sec to RabbitMQ as well as per-queues msgs/sec for the queues experiencing the crash?
• When these publishes happen, are the consumers already connected and consuming, or is there an explicit "publish window" followed by consumer start during which there is no publishing?
• Can you quantify the rate of slow consumption?
• Can you give more detail about the amount of time acks take? As in, 5% of messages take an hour, 25% take X amount of time, etc. Even a rough guess would be useful.
• Do you have an idea of when the messages that take a long time to ack are consumed? Right after the publish, spread out, at the end, etc?
• Can you give us a better idea of the distribution of <4KiB vs >4KiB messages published to the queues that are prone to crashing?

[trvrnrth]

@lukebakken We're happy to screen-share some metrics and discuss the behaviour as that's probably going to be the easiest way to make sure we provide as much useful information as possible. We could do a call tomorrow or the day after perhaps. It looks like you are PDT and we are BST (GMT+1) so the best cross-over time would probably be 15:00 or 16:00 GMT if that works for you?

[lukebakken]

@trvrnrth - one more important question. You've mentioned setting x-consumer-timeout: 86400000 on the affected queues. Do you ever see a consumer timeout? I'm assuming no, but I'd like to confirm.

[lukebakken]

@trvrnrth - How about a meeting at 0900PST / 1600GMT tomorrow, Tuesday, September 16th? Please email me - my address is public on my GH profile.

[trvrnrth]

The longest consumes before ack should typically be a little over an hour. We have the timeout set much higher just for simplicity and I'm not aware of there being any timeouts. I've just sent a meeting invite for tomorrow.

[lukebakken]

In case anyone has suggestions for improvements, or behavior changes, here's what I'm currently trying to use to reproduce the issue:

https://github.com/lukebakken/rabbitmq-server-14181/blob/main/targeted_bug_reproduction.py

@trvrnrth - here's what the publish / ack rates look like when I run 8 instances of the above program in my env:

Queue overview:

I'm curious how close these numbers are to what you see in your env, if they're close at all.

I'm planning to leave the test running for several hours. I'm testing against main using make run-broker.

[lukebakken]

Sorry, it wasn't clear in my second sentence that I was describing the second run, when I started the test script and PerfTest. In that run, the eof error was not triggered.

[mkuratczyk]

I'm trying to use your method on my side. I've had a bunch of timeouts already but no function_clauses so far. I will report back as well

[lukebakken]

I still haven't had success when trying to "speed up" the process with shorter consumer timeouts. I'm back to using the default 30-minute consumer timeout, waiting for two full "cycles" of timeouts to happen (60+) minutes, and only then adding additional load to try and reproduce.

[mkuratczyk]

My machine is resistant to this bug. I had spent a few day trying to reproduce it before and today I had your script running for ~8 hours + perf-test (on and off, sometimes for a a few minutes, sometimes for a few hours) and nothing. Not a single crash. 🤷

[lukebakken]

Yep, I've only reproduced it the one time. The stars must have aligned.

[lukebakken]

@lhoguin I have a question about some code in rabbit_msg_store. In this code...

https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_msg_store.erl#L628-L655

...between the time that index_lookup/2 is called on line 633, and reader_pread/2 is called on line 643, is it possible for compaction to have modified the message store file such that the data read via the index on line 633 is no longer valid, and thus eof is returned for some or all file positions passed to file:pread/2?

The ETS table used for the index is shared with the GC process, so I'm wondering if there could be a race condition between updating that ETS table during GC, and how the ETS table is used in client_read3/2 and elsewhere.

[lhoguin]

#14550

I'll add: at scale the unlikely becomes certain. So hopefully this is what fixes this, and if not we probably need to seek other unlikely scenarios.

[lukebakken]

Thanks @lhoguin. As soon as that patch is ready, @trvrnrth is able to test it in their environment. I will do so as well - I think I hit the eof issue again last night but this issue kept the stack from being formatted correctly. I've since updated my env and restarted my reproduction script to try to trigger the issue again.

[mkuratczyk]

Do you have any info about hardware resources in the affected clusters by any chance? I wonder if it's perhaps more common on small instances (few schedulers) or large instances or perhaps there's no correlation.

[lukebakken]

In my case, I'm using a single m5.large. I forgot to ask @trvrnrth that question. I'll see if I can get more info about this.

[trvrnrth]

Our affected queues are currently on amd64 instances with 16 vCPUs and 64GB memory with local SSDs.

[lukebakken]

@lhoguin hopefully this is helpful information - this PR correlates to a non-trivial increase in eof crashes seen across environments. eof did occur prior to that PR, all the way back to 3.13.7, but after #13959 it is more frequent.

[lukebakken]

Alright, I hit the eof again 🥳

2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0> ** Reason for termination ==
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0> ** {function_clause,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>        [{rabbit_msg_store,reader_pread_parse,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [[eof,eof,eof,eof,eof,eof,eof]],
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_msg_store.erl"},{line,687}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_msg_store,reader_pread_parse,1,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_msg_store.erl"},{line,694}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_msg_store,reader_pread,2,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_msg_store.erl"},{line,683}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_msg_store,read_many_file2,4,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_msg_store.erl"},{line,539}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_variable_queue,maybe_deltas_to_betas,4,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_variable_queue.erl"},{line,2345}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_variable_queue,fetch_from_q3,1,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_variable_queue.erl"},{line,2247}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_variable_queue,queue_out,1,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_variable_queue.erl"},{line,1268}]},
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>         {rabbit_variable_queue,collect_by_predicate,3,
2025-09-16 19:13:01.494622+00:00 [error] <0.7489.0>             [{file,"src/rabbit_variable_queue.erl"},{line,1565}]}]}

@lhoguin here's an archive of the entire RabbitMQ data and log directories for debugging -

https://gist.github.com/lukebakken/02e7411030d77cb2af75e6714aaa14d4#file-rabbit-ip-172-31-30-163-tar-xz

[lukebakken]

But what does that info can hint at, that the eof crash does not happen with the debug printout

This does seem to be the case.

Anything else I can do?

[lhoguin]

I think the problem comes from this line: https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_msg_store.erl#L1602

It's possible for Size < FileSize - Offset to be true when we are in the last scan block, resulting in another scan(...) call, which results in eof with the current Acc being returned (https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_msg_store.erl#L1548-L1549), despite not having looked at the entirety of the data.

This is because the check should be Size + 8 (or + 9, I'm a bit too tired to figure out off by ones), because Size does not include the 8 bytes of the encoded size, nor does it include the 255 end marker.

If I'm correct this perfectly explains why all the missing messages are from the end of the file.

[lhoguin]

I have opened #14576 with the check fixed. I used + 9 (8 bytes size + 1 byte end marker) but I'll appreciate a double check on that.

[lukebakken]

I will start running that patch in my repro environment, without any of the debugging code. The past several times I would hit eof within 4 to 6 hours.

[lukebakken]

Almost 4 hours, no crashes. I'll let it run all weekend of course.

[lukebakken]

cc @trvrnrth - if you're able to build and deploy using #14576 that would be great, thanks.

[trvrnrth]

Yep, we've been following along here. I was hoping to be able to reproduce the issue first in a test environment with just our worst affected queues on to make things easier but I've so far been unable to do so even with your repro script running. However, we've been discussing alternative arrangements to be able to test it safely and think we have a plan. I'll report back next week.

[lukebakken]

Thank you so much for your assistance.