[Suggestion] Fix potential dump of huge queue process state to log

[lukebakken]

RabbitMQ series

4.1.x

Operating system (distribution) used

Ubuntu 24

How is RabbitMQ deployed?

Community Docker image

What would you like to suggest for a future version of RabbitMQ?

Currently, if a crash happens in the rabbit_amqqueue_process, there can be huge amounts of data that is formatted and logged. If enough message data is in-memory, this can OOM-kill the server / container on which RabbitMQ is running.

See the following diff for an idea how to address this issue:

main...lukebakken:rmq-rabbitmq-server:lukebakken/fix-format-status

Note that rabbit_amqqueue_process already exports the format_status function, as defined by the gen_server2 behavior. Since RabbitMQ changed its logging to use the latest OTP logging library, and OTP interacts with gen_server differently, this function is not called when the process crashes.

Arguably, the correct fix is to update gen_server2 to the current gen_server code, or find a way to remove gen_server2 entirely. For the time being, I think this change to rabbit_amqqueue_process and the backing queue modules is the least intrusive fix.

In addition to these changes, setting the following kernel parameter in advanced.config also drastically reduces the amount of logging for crashes with large mailboxes (like queue processes):

[
    {kernel, [
        {error_logger_format_depth, 10}
    ]}
].

That configuration setting is deprecated, and I'm looking into how rabbit_prelaunch_logging can be modified to do the same thing as that setting.

To see the amount of data logged without format_state, modify my patch so that gen_server2:terminate does not call maybe_format_state. Start up RabbitMQ, and use PerfTest to publish some messages:

lrbakken@SEA-3LG5HVJUWJK ~/development/rabbitmq/rabbitmq-perf-test (main %=)
$ make ARGS='--pmessages 2000 --producers 1 --consumers 1 --confirm 10' run

After the 1000th message, the rabbit_amqqueue_process process will crash due to badmatch. If you catch the backing queue state with a lot of messages in RAM pending ack, the vqstate will look like this:

rabbit-no-truncated-state.log

2025-08-08 11:43:46.249610-07:00 [error] <0.601.0> ** When Server state == {q,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                          {amqqueue,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           {resource,<<"/">>,queue,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            <<"amq.gen-drydy1NEogXM_TivWviMUg">>},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           false,true,none,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           [{<<"x-queue-type">>,longstr,<<"classic">>}],
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           <0.601.0>,[],[],[],undefined,undefined,[],[],live,0,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           [],<<"/">>,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           #{user => <<"guest">>},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           rabbit_classic_queue,#{}},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                          none,true,rabbit_priority_queue,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                          {passthrough,rabbit_variable_queue,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                           {vqstate,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            {0,[],[]},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            {0,[],[]},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            {delta,undefined,0,0,undefined},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            {0,[],[]},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            {0,[],[]},
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            11,11,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                            #{0 =>
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                               {msg_status,0,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                                <<199,1,202,40,85,80,216,34,114,46,222,151,51,
2025-08-08 11:43:46.249610-07:00 [error] <0.601.0>                                  57,195,35>>,

Everything after 11,11, are messages stored in RAM. With large enough messages, and enough of them, this can OOM a RabbitMQ instance.

With my proposed code, the message data is modified by rabbit_variable_queue:format_state to be the atom ram_pending_ack_truncated.

Thoughts?

[the-mikedavis]

The format depth part would also be good to investigate for use in other (non-gen_server2) parts of the broker. I have seen a very large error log from ra_log_wal in a crash which would benefit from limiting the part where OTP prints the mailbox. In particular for any gen_batch_server a big mailbox is normal during high throughput, so a failed assertion could generate a massive log containing message bodies. And the mailbox itself is not very interesting for debugging.

Crash details...

I saw this running a horrible perf-test workload against main and I haven't looked into it at all yet, but I'd like to. Putting some details here for future reference...

2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>   crasher:
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>     initial call: ra_log_wal:init/1
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>     pid: <0.523.0>
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>     registered_name: ra_log_wal
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>     exception exit: {{cannot_extend,750,{861,1196}},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                      [{ra_range,extend,2,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/ra_range.erl"},{line,96}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {ra_log_wal,incr_batch,8,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/ra_log_wal.erl"},{line,541}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {ra_log_wal,write_data,8,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/ra_log_wal.erl"},{line,479}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {ra_log_wal,handle_op,2,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/ra_log_wal.erl"},{line,349}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {ra_log_wal,'-handle_batch/2-lists^foldr/2-0-',3,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/ra_log_wal.erl"},{line,318}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {ra_log_wal,handle_batch,2,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/ra_log_wal.erl"},{line,318}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {gen_batch_server,complete_batch,1,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/gen_batch_server.erl"},{line,367}]},
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                       {gen_batch_server,loop_batched,2,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                           [{file,"src/gen_batch_server.erl"},{line,317}]}]}
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>       in function  gen_batch_server:complete_batch/1 (src/gen_batch_server.erl:397)
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>       in call from gen_batch_server:loop_batched/2 (src/gen_batch_server.erl:317)
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>     ancestors: [<0.522.0>,ra_log_sup,<0.512.0>,ra_systems_sup,ra_sup,
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>                   <0.183.0>]
2025-08-06 19:32:13.888931-04:00 [error] <0.523.0>     message_queue_len: 32
... then we see "messages: [" 😱 ...

This was from publishing with perf-test with a workload that sends a crazy ~3.7 GB/sec of message bodies (my beefy computer was unsurprisingly unhappy!). ra_log_wal got quite a large backlog (~9000 messages) in its mailbox and when that finally got down to 32 I saw this crash.

perf-test --queue-pattern queue.%d --queue-pattern-from 0 --queue-pattern-to 59 --producers 60 --consumers 60 --confirm 512 --size 1048576 --rate 60 --predeclared --flag persistent --auto-delete false --confirm-timeout 180 --quorum-queue

[michaelklishin]

kernel.error_logger_format_depth is supposedly capped at 10, according to the docs.

This change can make investigating certain issues harder but I see the benefits, of course.

@lukebakken instead of using just atoms, e.g. ram_pending_ack_truncated, can we use something like
<<"ram_pending_ack (1234 elements) (truncated)">>, that is, reflect the size of the collection and return a binary which would be more descriptive than an atom?

[michaelklishin]

and I guess the same should be applied to backing_queue_state. Losing the BQ state from the output will be particularly painful in terms of debugging but also the most beneficial in terms of not running the node OOM.

[lukebakken]

I was thinking that printing the first few messages might be helpful. Thanks for the suggestions.

[lukebakken]

Looks like error_logger_format_depth is unlimited by default, and can't be set to less than 10:

https://github.com/erlang/otp/blob/master/lib/kernel/src/error_logger.erl#L970-L992