3.13: consumer fails to consume (delivery runs into an exception in rabbit_channel)

[m-arre]

Describe the bug

Hi! I'm encountering an issue with two quorum queues in RabbitMQ v3.13, as they're no longer able to be consumed. Whenever I try to retrieve data from them, the channel suddenly closes, accompanied by an AMQP 541 error.
Getting messages through the management console results in a 500 error. I've also attempted to transfer messages from these problematic queues to new ones using the shovel plugin, but it still fails with the same error.

Reproduction steps

I'm not able to reproduce it

Expected behavior

I expect to be able to consume their data as usual, without this error

Additional context

The cluster has 3 nodes and this is the error log of one of the nodes:

...
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     links: [<0.29163.0>]
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     dictionary: [{permission_cache,
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                       [{{resource,<<"iot">>,queue,<<"ingestion-k0">>},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                         #{},read}]},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                   {process_name,
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                       {rabbit_channel,
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                           {<<"10.0.1.188:36372 -> 10.0.1.144:5672">>,1}}},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                   {rand_seed,
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                       {#{max => 288230376151711743,type => exsplus,
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                          next => #Fun<rand.5.65977474>,
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                          jump => #Fun<rand.3.65977474>},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                        [13265567542040676|202834942511650406]}},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                   {{queue_stats,{resource,<<"iot">>,queue,<<"ingestion-k0">>}},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                    none},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                   {msg_size_for_gc,62482},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                   {permission_cache_can_expire,false},
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>                   {channel_operation_timeout,15000}]
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     trap_exit: true
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     status: running
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     heap_size: 3581853
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     stack_size: 28
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>     reductions: 6791458
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0>   neighbours:
2024-03-01 10:30:29.947933+00:00 [error] <0.29166.0> 
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>     supervisor: {<0.29163.0>,rabbit_channel_sup}
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>     errorContext: child_terminated
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>     reason: {{badmatch,[]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>              [{rabbit_channel,handle_deliver0,4,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                               [{file,"rabbit_channel.erl"},{line,2677}]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>               {lists,foldl_1,3,[{file,"lists.erl"},{line,1599}]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>               {lists,foldl,3,[{file,"lists.erl"},{line,1594}]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>               {rabbit_channel,handle_cast,2,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                               [{file,"rabbit_channel.erl"},{line,728}]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>               {gen_server2,handle_msg,2,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                            [{file,"gen_server2.erl"},{line,1056}]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>               {proc_lib,init_p_do_apply,3,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         [{file,"proc_lib.erl"},{line,241}]}]}
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>     offender: [{pid,<0.29166.0>},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                {id,channel},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                {mfargs,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                    {rabbit_channel,start_link,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                        [1,<0.29136.0>,<0.29164.0>,<0.29136.0>,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         <<"10.0.1.188:36372 -> 10.0.1.144:5672">>,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         rabbit_framing_amqp_0_9_1,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         {user,<<"admin">>,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                             [management,administrator],
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                             [{rabbit_auth_backend_cache,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                                  #Fun<rabbit_auth_backend_http.0.41272021>}]},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         <<"iot">>,
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         [{<<"connection.blocked">>,bool,true},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                          {<<"consumer_cancel_notify">>,bool,true}],
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                         <0.29137.0>,<0.29165.0>]}},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                {restart_type,transient},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                {significant,true},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                {shutdown,70000},
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0>                {child_type,worker}]
2024-03-01 10:30:29.949536+00:00 [error] <0.29163.0> 
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0> Error on AMQP connection <0.29136.0> (10.0.1.188:36372 -> 10.0.1.144:5672, vhost: 'iot', user: 'admin', state: running), channel 1:
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>  {{badmatch,[]},
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>  [{rabbit_channel,handle_deliver0,4,[{file,"rabbit_channel.erl"},{line,2677}]},
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>   {lists,foldl_1,3,[{file,"lists.erl"},{line,1599}]},
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>   {lists,foldl,3,[{file,"lists.erl"},{line,1594}]},
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>   {rabbit_channel,handle_cast,2,[{file,"rabbit_channel.erl"},{line,728}]},
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>   {gen_server2,handle_msg,2,[{file,"gen_server2.erl"},{line,1056}]},
2024-03-01 10:30:29.950073+00:00 [error] <0.29136.0>   {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]}
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0> Non-AMQP exit reason '{{badmatch,[]},
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                        [{rabbit_channel,handle_deliver0,4,
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                             [{file,"rabbit_channel.erl"},{line,2677}]},
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                         {lists,foldl_1,3,[{file,"lists.erl"},{line,1599}]},
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                         {lists,foldl,3,[{file,"lists.erl"},{line,1594}]},
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                         {rabbit_channel,handle_cast,2,
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                             [{file,"rabbit_channel.erl"},{line,728}]},
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                         {gen_server2,handle_msg,2,
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                             [{file,"gen_server2.erl"},{line,1056}]},
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                         {proc_lib,init_p_do_apply,3,
2024-03-01 10:30:29.950614+00:00 [warning] <0.29136.0>                             [{file,"proc_lib.erl"},{line,241}]}]}'
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>     supervisor: {<0.29163.0>,rabbit_channel_sup}
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>     errorContext: shutdown
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>     reason: reached_max_restart_intensity
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>     offender: [{pid,<0.29166.0>},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                {id,channel},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                {mfargs,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                    {rabbit_channel,start_link,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                        [1,<0.29136.0>,<0.29164.0>,<0.29136.0>,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                         <<"10.0.1.188:36372 -> 10.0.1.144:5672">>,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                         rabbit_framing_amqp_0_9_1,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                         {user,<<"admin">>,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                             [management,administrator],
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                             [{rabbit_auth_backend_cache,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                                  #Fun<rabbit_auth_backend_http.0.41272021>}]},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                         <<"iot">>,
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                         [{<<"connection.blocked">>,bool,true},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                          {<<"consumer_cancel_notify">>,bool,true}],
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                         <0.29137.0>,<0.29165.0>]}},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                {restart_type,transient},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                {significant,true},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                {shutdown,70000},
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0>                {child_type,worker}]
2024-03-01 10:30:29.950560+00:00 [error] <0.29163.0> 
2024-03-01 10:30:29.957372+00:00 [info] <0.29136.0> closing AMQP connection <0.29136.0> (10.0.1.188:36372 -> 10.0.1.144:5672, vhost: 'iot', user: 'admin')

[michaelklishin]

@m-arre it's difficult to suggest much having just a stacktrace. Does deleting and re-creating the queue make this condition go away? What about if your consumers reconnect?

From the stack trace it's not obvious if this something that has to do with the QQ state or the channel state.

[m-arre]

1. These messages come from the MQTT plugin
2. All feature flags are enabled
3. It's an upgrade from 3.12, then 3.13 rc4 (which worked well) and then 3.13 stable

[m-arre]

@michaelklishin this is the definition (I removed users and unuseful info)

{
  "rabbit_version": "3.13.0",
  "rabbitmq_version": "3.13.0",
  "product_name": "RabbitMQ",
  "product_version": "3.13.0",
  "vhosts": [
    {
      "name": "/"
    },
    {
      "name": "iot"
    }
  ],
  "permissions": [
    {
      "user": "XXXXX",
      "vhost": "/",
      "configure": ".*",
      "write": ".*",
      "read": ".*"
    },
    {
      "user": "XXXXX",
      "vhost": "iot",
      "configure": ".*",
      "write": ".*",
      "read": ".*"
    },
    {
      "user": "YYYYY",
      "vhost": "iot",
      "configure": ".*",
      "write": ".*",
      "read": ".*"
    }
  ],
  "topic_permissions": [],
  "global_parameters": [
    {
      "name": "cluster_name",
      "value": "XXXXXXXXXXXX"
    },
    {
      "name": "mqtt_port_to_vhost_mapping",
      "value": {
        "18883": "iot"
      }
    },
    {
      "name": "internal_cluster_id",
      "value": "rabbitmq-cluster-id-XXXXXXXXXXXXXXXX"
    }
  ],
  "policies": [
    {
      "vhost": "iot",
      "name": "mqtt-unroutable",
      "pattern": "amq.topic",
      "apply-to": "exchanges",
      "definition": {
        "alternate-exchange": "mqtt.unroutable"
      },
      "priority": 0
    }
  ],
  "queues": [
    {
      "name": "mqtt-subscription-XXXXXXXXX",
      "vhost": "iot",
      "durable": true,
      "auto_delete": false,
      "arguments": {
        "x-expires": 86400000
      }
    },
    {
      "name": "ingestion-k0",
      "vhost": "iot",
      "durable": true,
      "auto_delete": false,
      "arguments": {
        "x-queue-type": "quorum"
      }
    },
    {
      "name": "up-q0",
      "vhost": "iot",
      "durable": true,
      "auto_delete": false,
      "arguments": {
        "x-queue-type": "quorum"
      }
    }
  ],
  "exchanges": [
    {
      "name": "data",
      "vhost": "iot",
      "type": "x-consistent-hash",
      "durable": true,
      "auto_delete": false,
      "internal": false,
      "arguments": {}
    },
    {
      "name": "kdata",
      "vhost": "iot",
      "type": "x-consistent-hash",
      "durable": true,
      "auto_delete": false,
      "internal": false,
      "arguments": {}
    },
    {
      "name": "mqtt.unroutable",
      "vhost": "iot",
      "type": "topic",
      "durable": true,
      "auto_delete": false,
      "internal": true,
      "arguments": {}
    },
    {
      "name": "up",
      "vhost": "iot",
      "type": "x-consistent-hash",
      "durable": true,
      "auto_delete": false,
      "internal": false,
      "arguments": {}
    }
  ],
  "bindings": [
    {
      "source": "amq.topic",
      "vhost": "iot",
      "destination": "mqtt-subscription-dev-XXXXXXXX",
      "destination_type": "queue",
      "routing_key": "j.dn.dev-XXXXXXXX",
      "arguments": {}
    },
    {
      "source": "amq.topic",
      "vhost": "iot",
      "destination": "kdata",
      "destination_type": "exchange",
      "routing_key": "*.data.*.*.#",
      "arguments": {}
    },
    {
      "source": "mqtt.unroutable",
      "vhost": "iot",
      "destination": "mqtt-unroutable",
      "destination_type": "queue",
      "routing_key": "#",
      "arguments": {}
    },
    {
      "source": "amq.topic",
      "vhost": "iot",
      "destination": "data",
      "destination_type": "exchange",
      "routing_key": "*.data.*.*.#",
      "arguments": {}
    },
    {
      "source": "amq.topic",
      "vhost": "iot",
      "destination": "up",
      "destination_type": "exchange",
      "routing_key": "*.up.#",
      "arguments": {}
    }
  ]
}

[michaelklishin]

@m-arre I'm afraid we don't support upgrades from RCs because things can change significantly internally, and RCs are not GA releases we support (or test) upgrades from

[ansd]

Thanks for all the infos.
The error is caused because messages were published with a 3.13 RC and routing_keys were stored on disk.
The on disk format changed with #10339 after your RC and before 3.13.0: rk is now used instead of routing_keys.

[ansd]

So, the TLDR is we don't support upgrades from an RC.

[michaelklishin]

To summarize: the messages in question were stored by a preview version of 3.13.0 that 3.13.0 GA does not "interpret" the same way (some internally used keys were renamed in #10339).

There's nothing to change in 3.13.x GA and I'm afraid those messages must be purged.

[michaelklishin]

Alternatively to purging, going back to RC4, consuming all messages and then upgrading should help but I don't know if that's a realistic scenario.

If not, then a Blue-Green upgrade and/or moving messages with a Shovel may be an option.