Crash on RPC reply on 3.13.4 while it works on 3.12.14

[bollhals]

Describe the bug

For our single node rabbitmq, we use RPC to send commands. When we use the newest version (3.13.4) our tests start to fail with an RPC timeout, as the connection is getting closed by the server.

The logs looks like this:

2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0> ** Generic server <0.2901.0> terminating
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0> ** Last message in was {'$gen_cast',
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {method,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                {'basic.publish',0,<<>>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                    <<"amq.rabbitmq.reply-to.g1h2AA5yZXBseUAyNzc5NjQyMAAAC1oAAAAAZo4bIw==.+Uvn1EmAp0ZA+oQx2yoQFA==">>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                    false,false},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                {content,60,none,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                    <<REDACTED>>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                    rabbit_framing_amqp_0_9_1,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                    [<<"{\"Timestamp\":\"2024-07-10T05:25:26.8790473Z\"}">>]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                flow}}
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0> ** When Server state == {ch,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {conf,running,rabbit_framing_amqp_0_9_1,1,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           <0.2892.0>,<0.2899.0>,<0.2892.0>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           <<"127.0.0.1:48230 -> 127.0.0.1:5672">>,undefined,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           {user,<<"REDACTED">>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            [administrator],
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            [{rabbit_auth_backend_internal,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                              #Fun<rabbit_auth_backend_internal.3.26105038>}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           <<"/">>,<<>>,<0.2893.0>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           [{<<"publisher_confirms">>,bool,true},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {<<"exchange_exchange_bindings">>,bool,true},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {<<"basic.nack">>,bool,true},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {<<"consumer_cancel_notify">>,bool,true},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {<<"connection.blocked">>,bool,true},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {<<"authentication_failure_close">>,bool,true}],
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           {exchange,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {resource,<<"/">>,exchange,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                             <<"amq.rabbitmq.trace">>},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            topic,true,false,true,[],undefined,undefined,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            undefined,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            {[],[]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                            #{user => <<"rmq-internal">>}},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           0,134217728,1800000,#{},infinity,1000000000,false},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {lstate,<0.2900.0>,false},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          none,5,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {0,[],[]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {state,#{},erlang},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          #{<<"amq.ctag-1A0r8B1utxtUXzlXg4D8gA">> =>
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                             {{amqqueue,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                               {resource,<<"/">>,queue,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                <<"REDACTED.q">>},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                               false,false,none,[],<0.1240.0>,[],[],[],
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                               undefined,undefined,[],[],live,0,[],<<"/">>,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                               #{user => <<"rmq-internal">>},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                               rabbit_classic_queue,#{}},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                              {true,0,false,[]}}},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          #{{resource,<<"/">>,queue,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                             <<"REDACTED.q">>} =>
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                             {1,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                              {<<"amq.ctag-1A0r8B1utxtUXzlXg4D8gA">>,nil,nil}}},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {state,fine,5000,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           #Ref<0.2489594534.2211971076.159317>},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          false,1,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {rabbit_confirms,undefined,#{}},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          [],[],none,flow,[],
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          {rabbit_queue_type,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                           #{{resource,<<"/">>,queue,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                              <<"REDACTED.q">>} =>
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                              {ctx,rabbit_classic_queue,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                               {rabbit_classic_queue,<0.1240.0>,#{},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                                #{<0.1240.0> => ok}}}}},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                          #Ref<0.2489594534.2211971076.159313>,false}
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0> ** Reason for termination ==
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0> ** {function_clause,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>        [{rabbit_trace,'-tap_in/6-fun-0-',
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>             [{virtual_reply_queue,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>                  <<"amq.rabbitmq.reply-to.g1h2AA5yZXBseUAyNzc5NjQyMAAAC1oAAAAAZo4bIw==.+Uvn1EmAp0ZA+oQx2yoQFA==">>}],
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>             [{file,"rabbit_trace.erl"},{line,62}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>         {lists,map,2,[{file,"lists.erl"},{line,1559}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>         {rabbit_trace,tap_in,6,[{file,"rabbit_trace.erl"},{line,62}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>         {rabbit_channel,handle_method,3,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>             [{file,"rabbit_channel.erl"},{line,1284}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>         {rabbit_channel,handle_cast,2,
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>             [{file,"rabbit_channel.erl"},{line,659}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>         {gen_server2,handle_msg,2,[{file,"gen_server2.erl"},{line,1056}]},
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0>         {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]}
2024-07-10 05:25:26.883713+00:00 [error] <0.2901.0> 
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>   crasher:
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     initial call: rabbit_channel:init/1
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     pid: <0.2901.0>
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     registered_name: []
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     exception exit: {function_clause,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                         [{rabbit_trace,'-tap_in/6-fun-0-',
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{virtual_reply_queue,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                                   <<"amq.rabbitmq.reply-to.g1h2AA5yZXBseUAyNzc5NjQyMAAAC1oAAAAAZo4bIw==.+Uvn1EmAp0ZA+oQx2yoQFA==">>}],
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{file,"rabbit_trace.erl"},{line,62}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          {lists,map,2,[{file,"lists.erl"},{line,1559}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          {rabbit_trace,tap_in,6,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{file,"rabbit_trace.erl"},{line,62}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          {rabbit_channel,handle_method,3,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{file,"rabbit_channel.erl"},{line,1284}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          {rabbit_channel,handle_cast,2,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{file,"rabbit_channel.erl"},{line,659}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          {gen_server2,handle_msg,2,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{file,"gen_server2.erl"},{line,1056}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          {proc_lib,init_p_do_apply,3,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                              [{file,"proc_lib.erl"},{line,241}]}]}
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>       in function  gen_server2:terminate/3 (gen_server2.erl, line 1172)
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     ancestors: [<0.2898.0>,<0.2896.0>,<0.2891.0>,<0.2890.0>,<0.1761.0>,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   <0.1760.0>,<0.1759.0>,<0.1757.0>,<0.1756.0>,rabbit_sup,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   <0.254.0>]
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     message_queue_len: 0
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     messages: []
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     links: [<0.2898.0>]
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     dictionary: [{channel_operation_timeout,15000},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {process_name,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                       {rabbit_channel,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                           {<<"127.0.0.1:48230 -> 127.0.0.1:5672">>,1}}},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {rand_seed,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                       {#{max => 288230376151711743,type => exsplus,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          next => #Fun<rand.5.65977474>,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                          jump => #Fun<rand.3.65977474>},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                        [51119937867544353|237024794780865726]}},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {msg_size_for_gc,365},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {{queue_stats,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                        {resource,<<"/">>,queue,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                            <<"REDACTED.q">>}},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                    none},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {guid,{{884801551,3500111506,691586313,885863849},4}},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {credit_flow_default_credit,{400,200}},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {permission_cache,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                       [{{resource,<<"/">>,exchange,<<>>},#{},write},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                        {{resource,<<"/">>,queue,
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                             <<"REDACTED.q">>},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                         #{},read}]},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {permission_cache_can_expire,false},
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>                   {{credit_to,<0.2892.0>},199}]
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     trap_exit: true
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     status: running
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     heap_size: 28690
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     stack_size: 28
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>     reductions: 68735
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0>   neighbours:
2024-07-10 05:25:26.884760+00:00 [error] <0.2901.0> 

Reproduction steps

1. Start our testsuite with rabbitmq 3.13.4 instead of 3.12.14
2. wait for the first RPC
3. watch it timeout/die

Expected behavior

Even after replacing the Rabbitmq the RPC functionality still works

Additional context

As I see "trace" in the stack trace, we do have it enabled.

I've redacted the log to remove the contents / queue names, if they'd be relevant, let me know.

[bollhals]

Due to the stack trace, could it be somewhat related to this change? It at least was the last change in that area where it fails for us now.

[bollhals]

When we disable the tracing, it works, so it's related to this.

[michaelklishin]

I'm afraid we cannot answer this question without an executable way to reproduce.

I don't know what you mean by "RPC" and how MQTT can be related. Tracing is a rarely used feature that was never meant to be used in production continuously, so most changes are not tested in combination with tracing.

[bollhals]

It certainly is a rare case of having tracing enabled, this is most likely why noone noticed so far :)

[michaelklishin]

Besides MQTT, there were very substantial internal changes around how messages are represented. They could affect the tracing plugin but currently I have to guess as to how to reproduce.

According to the stack trace, Direct Reply-to is likely used and tracing is enabled for the virtual host. I would really like to have a way to reproduce, we do not guess in this community.

[lukebakken]

The anonymous function signature here does not take the virtual_reply_queue kind into account:

https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_trace.erl#L61-L65

[lukebakken]

This PR added virtual_reply_queue - #5077

The change may not have been tested with the tracing module (cc @kjnilsson @ansd)

[bollhals]

Whoops my bad.

Yes, by RPC I meant the Direct Reply-to Feature of RabbitMQ.
Yes, with Tracing enabled for the virtual host. (It works if we disable the tracing, which we are not yet ready to turn off)

The related change is the last change that modified the line that seems to cause the issue.

[michaelklishin]

Thanks. It should be something easy to fix now that we know the combination of factors involved.

[bollhals]

Let me know if I can help in anyway. (e.g. do a pretest if that helps)

[ansd]

Thank you for this bug report @bollhals.
This bug is fixed in #11665