[Questions] Dead lettered message crashes QQ when upgrading from 3.13.7 to 4.0.4.

[LoisSotoLopez]

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.0.4

Erlang version used

26.2.x

Operating system (distribution) used

Linux

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

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?

We have seen several crashes related to the annotation of death lettered messages in one of our RMQ nodes, right after upgrading it from 3.13.7 to 4.0.4. We ran such upgrade at 2024-12-10 07:14:46 +0000.

Worth to mention that despite the running version being 4.0.4, one should not go to the
v4.0.4 tag in GitHub but to this commit to look at the code associated to this discussion:

rabbitmq-server/deps/rabbit/src/mc.erl

Line 410 in 8e9c2a7

Anns0#{<<"x-last-death-reason">> := ReasonBin,

Reson for this mismatch between the reported 4.0.4 version and the actual commit to look at described in the Discord server: https://discordapp.com/channels/1092487794984755311/1316380484812541973/1316909611370151936

The dead lettering configuration is as follows:

• There's a Q1 QQ with no special configuration regarding dead lettering, i.e.: no deal letter routing key nor TTL configured.
• There are a number of RETRY_Q1_<n> queues, each of them configuring Q1 as their dead letter routing key.

Errors below happen right after the upgrade.

2024-12-10 07:16:07.314032+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': follower did not have entry at 27 in 2. Requesting {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-02'} from 26
2024-12-10 07:16:07.314211+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': detected a new leader {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-02'} in term 2
2024-12-10 07:16:07.314507+00:00 [warning] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': await_condition - Leader node 'rabbit@my-rmq-host-02' might be down. Re-entering follower state.
...
2024-12-10 07:16:31.789453+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': granting vote for {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-03'} with last indexterm {28,2} for term 3 previous term was 2
...
2024-12-10 07:16:31.803784+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': detected a new leader {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-03'} in term 3
...
2024-12-10 07:17:48.804392+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': granting vote for {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-02'} with last indexterm {29,3} for term 4 previous term was 4
...
2024-12-10 07:17:48.820592+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': detected a new leader {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-02'} in term 4
...
2024-12-10 08:16:47.420431+00:00 [info] <0.1409.0> queue 'RETRY_Q1_1' in vhost 'vhost': detected a new leader {'vhost_RETRY_Q1_1','rabbit@my-rmq-host-03'} in term 5
...
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** State machine 'vhost_RETRY_Q1_1' terminating
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** Last event = {cast,
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                     {{'vhost_RETRY_Q1_1',
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                          'rabbit@my-rmq-host-03'},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                      {append_entries_reply,6,true,37,36,6}}}
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** When server state  = [{id,
... <more of the state machine termination>
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** Reason for termination = error:{badkey,<<"x-last-death-exchange">>}
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** Callback modules = [ra_server_proc]
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** Callback mode = [state_functions,state_enter]
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** Stacktrace =
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> **  [{mc,record_death,4,[{file,"mc.erl"},{line,410}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {rabbit_dead_letter,publish,5,
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                          [{file,"rabbit_dead_letter.erl"},{line,38}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {lists,foreach_1,2,[{file,"lists.erl"},{line,1686}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {rabbit_quorum_queue,dead_letter_publish,5,
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                           [{file,"rabbit_quorum_queue.erl"},{line,1611}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {ra_server_proc,handle_effect,5,
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                      [{file,"src/ra_server_proc.erl"},{line,1549}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {lists,foldl,3,[{file,"lists.erl"},{line,1594}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {ra_server_proc,handle_effects,5,
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>                      [{file,"src/ra_server_proc.erl"},{line,1301}]},
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0>      {lists,foldl_1,3,[{file,"lists.erl"},{line,1599}]}]
2024-12-10 08:16:47.520636+00:00 [error] <0.1409.0> ** Time-outs: {1,[{{timeout,tick},tick_timeout}]}

By looking at the segment file we find a message with deaths but no x-last-death-exchange key.

{'$usr',#{ts => 1733794307348},
        {enqueue,<12346.4010241.0>,1,
                 {mc,mc_amqpl,
                     {content,60,none,
                              <<48,0,0,0,3,218,18,120,45,100,97,116,97,100,111,...>>,
                              rabbit_framing_amqp_0_9_1,
                              [<<"{\"documentId\":\"redacted\"}">>]},
                     #{x => <<>>,
                       rk => [<<"RETRY_Q1_1">>],
                       deaths =>
                           [{{<<"RETRY_Q1_2">>,expired},
                             {death,<<>>,
                                    [<<"RETRY_Q1_2">>],
                                    1,
                                    #{first_time => 1733794297000,last_time => 1733794297000}}},
                            {{<<"RETRY_Q1_3">>,expired},
                             {death,<<>>,
                                    [<<"RETRY_Q1_3">>],
                                    1,
                                    #{first_time => 1733786186000,last_time => 1733786186000}}},
                            {{<<"RETRY_Q1_4">>,expired},
                             {death,<<>>,
                                    [<<"RETRY_Q1_4">>],
                                    1,
                                    #{first_time => 1733783476000,last_time => 1733783476000}}},
                            {{<<"RETRY_Q1_5">>,expired},
                             {death,<<>>,
                                    [<<"RETRY_Q1_5">>],
                                    1,
                                    #{first_time => 1733782566000,last_time => 1733782566000}}}],
                       rts => 1733794307346}}},
        {notify,0,<12346.4010241.0>}}

I haven't been able to reproduce this issue, i.e.: causing some message with deaths annotation but no x-last-death-reason to reach the mc:record_death/4 function, but I feel it's worth mentioning it here in case anyone can figure out the reason.

[ansd]

Thank you @LoisSotoLopez for starting a discussion and the detailed report including the contents of the segment file.

This issue occurs also with classic queues, not only with quorum queues.
This issue can happen when the deaths annotation is recovered from a message sent to RabbitMQ 3.13.7 via AMQP 0.9.1. In

rabbitmq-server/deps/rabbit/src/mc_amqpl.erl

Line 704 in 52b3843

deaths, Deaths,

the deaths annotation is set, but not the x-last-death-* annotations.

Repro steps:

1. In v3.13.7, dead letter a message from Q1 to Q2 (both can be classic queues).
2. Re-publish the message including its x-death header from Q2 back to Q1. (RabbitMQ 3.13.7 will interpret this x-death header and set the deaths annotation as linked in the line above.)
3. Upgrade to v4.0.4
4. Dead letter the message from Q1 to Q2 will cause this crash.

[ansd]

I created an issue #12933. We can therefore mark this discussion as answered.

[ansd]

#12935 provides the fix.

[michaelklishin]

And is currently scheduled ship in 4.0.5 next week.