[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?

[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

[lukebakken]

I'm going to pick this up again soon, as I've seen OOMs due to this logging behavior.

[michaelklishin]

So we can add a new logging setting, e.g.

log.process_state.depth = 30

and default to 20 or so. Then the key question becomes: can we reconfigure error_logging after it's already been started? If so, that sounds like an elegant, low risk solution to me.

[lukebakken]

cc @dumbbell

I spent quite a bit of time going through rabbit_prelaunch_logging and other modules, like supervisor2, to see if we can configure the depth value the "right way", i.e. as part of a formatter configuration value. Since supervisor2 uses pre-logger logging it wouldn't recognize those values, anyway. Here's how the current supervisor code logs crashes and other errors:

https://github.com/erlang/otp/blob/master/lib/stdlib/src/supervisor.erl#L326

https://github.com/erlang/otp/blob/master/lib/stdlib/src/supervisor.erl#L2288-L2436

Notice that it's using the report_cb callback to format the message, and the supervisor:format_log/1,2 functions honor depth and other configuration settings to limit output.

So, what does work to limit output, given the way logging currently works in RabbitMQ, is to use

{kernel, [
    {error_logger_format_depth, 10}
]}

I know the above works when set in advanced.config, and I'll take a second to see about setting it in rabbit_prelaunch_logging.

[lukebakken]

@dumbbell @michaelklishin PR for when you have time, thanks! #14523

[michaelklishin]

This is addressed (note: you have to opt-in with one or two lines in rabbitmq.conf) in #14523 and #14548, and will ship in 4.2.0..

Thanks, @lukebakken and everyone else involved.