"zombie" mqtt_subscription queues after node kill+restart

[gomoripeti]

Given a 3 node cluster of v3.9.23 with 10K MQTT QoS1 connections to only node1. After restarting/killing node1 there are a lot of mqtt_subscription<clientid>qos1 queues left with entries only in the rabbit_durable_queue table, but not in rabbit_queue table (and no associated process). These queues appear as down on the mgmt UI.

When an MQTT client with a <clientid> tries to connect again it fails with

operation queue.declare caused a channel exception not_found: home node 'rabbit@...' of durable queue 'mqtt-subscription-<clientid>qos1' in vhost '...' is down or inaccessible

I believe the root cause is exactly the same as very nicely investigated in #6272, just a different aspect (in this case these are durable, auto-delete, not-replicated queues). I think the node needs to be killed, as a clean shutdown would clean up auto-delete queues when the connections are closed.

Some additional logs
node02 timeline

2022-10-26 19:43:12.050862+00:00 [info] <0.2130.0> Node [email protected] is down, deleting its listeners
...
# lots of the below
2022-10-26 19:43:12.066050+00:00 [warning] <0.28015.6> Queue mqtt-subscription-....qos1 in vhost ... has its master node is down and no mirrors available or eligible for promotion. Forcing queue deletion.
...
# first occurance of mqtt connection failure
2022-10-26 19:43:37.610330+00:00 [error] <0.3312.16> Channel error on connection <0.3264.16> (... -> ...:1883, vhost: '...', user: '...'), channel 1:
2022-10-26 19:43:37.610330+00:00 [error] <0.3312.16> operation queue.declare caused a channel exception not_found: home node '[email protected]' of durable queue 'mqtt-subscription-...qos1' in vhost '...' is down or inaccessible
...
# took more than 2 minutes
2022-10-26 19:45:37.810260+00:00 [info] <0.2130.0> 10566 transient queues from an old incarnation of node '[email protected]' deleted in 145.759174

node01 timeline

2022-10-26 19:44:50.398007+00:00 [info] <0.24255.1> Starting message stores for vhost '...'
...
# why just 212 queues
2022-10-26 19:44:50.825165+00:00 [info] <0.24255.1> Recovering 212 queues of type rabbit_classic_queue took 435ms
...
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1> ** Generic server <0.25119.1> terminating
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1> ** Last message in was {init,{<0.24255.1>,[non_clean_shutdown]}}
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1> ** When Server state == {q,{amqqueue,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {resource,<<"...">>,queue,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                    <<"mqtt-subscription-...qos1">>},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                true,true,none,[],<0.25119.1>,[],[],[],
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                undefined,undefined,[],undefined,live,0,[],
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                <<"...">>,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                #{user => <<"...">>},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                rabbit_classic_queue,#{}},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            none,false,undefined,undefined,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            {state,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {queue,[],[],0},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {active,-576460654852017,1.0}},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            undefined,undefined,undefined,undefined,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            {state,fine,5000,undefined},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            #{},undefined,undefined,undefined,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            {state,#{},delegate},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            undefined,undefined,undefined,undefined,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                            'drop-head',0,0,running,false}
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1> ** Reason for termination ==
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1> ** {{badmatch,{error,not_found}},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>     [{rabbit_amqqueue_process,i,2,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                               [{file,"rabbit_amqqueue_process.erl"},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {line,1149}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {rabbit_amqqueue_process,'-infos/2-fun-0-',4,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                               [{file,"rabbit_amqqueue_process.erl"},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {line,1066}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {lists,foldr_1,3,[{file,"lists.erl"},{line,1372}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {rabbit_amqqueue_process,emit_stats,2,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                               [{file,"rabbit_amqqueue_process.erl"},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {line,1175}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {rabbit_event,if_enabled,3,[{file,"rabbit_event.erl"},{line,135}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {rabbit_amqqueue_process,init_it2,3,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                               [{file,"rabbit_amqqueue_process.erl"},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {line,218}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {rabbit_amqqueue_process,handle_call,3,
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                               [{file,"rabbit_amqqueue_process.erl"},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>                                {line,1262}]},
2022-10-26 19:44:53.443896+00:00 [error] <0.25119.1>      {gen_server2,handle_msg,2,[{file,"gen_server2.erl"},{line,1046}]}]}
...
2022-10-26 19:44:53.453111+00:00 [error] <0.25118.1>     supervisor: {<0.25118.1>,rabbit_amqqueue_sup}
2022-10-26 19:44:53.453111+00:00 [error] <0.25118.1>     errorContext: shutdown
2022-10-26 19:44:53.453111+00:00 [error] <0.25118.1>     reason: reached_max_restart_intensity
2022-10-26 19:44:53.453111+00:00 [error] <0.25118.1>     offender: [{pid,{restarting,<0.25119.1>}},

I'm including this last error, because I think that is not triggered by a new MQTT connection, but maybe part of the recovery process on the restarted node. It tries to start a defined queue, but meanwhile node2 deletes the entry from the rabbit_queue table.

I'm opening this new issue and added the error logs to show that maybe it's not just fast reconnecting clients that can interfere with the cleanup, and it's not enough to exclude queues that already have a replica on other nodes, because the cleanup (if takes too long) can interfere with the recovery on the same node that went down.

[ansd]

For MQTT clean_session=true connections that subscribe with QoS 1, the rabbitmq_mqtt plugin creates following queues:

• up to 3.11: durable=true auto-delete=true exclusive=false
• from 3.12 (Native MQTT): durable=true auto-delete=false exclusive=true See

  rabbitmq-server/deps/rabbitmq_mqtt/src/rabbit_mqtt_processor.erl

  Lines 960 to 961 in f47c7cb

  	%% Exclusive queues are auto-deleted after node restart while auto-delete queues are not.
  	%% Therefore make durable queue exclusive.

@gomoripeti can you please do the same test against current main branch? Does this issue still exist? If not, I think we can close this issue?

[gomoripeti]

thank you, I will test it next week
is this the right place to fetch nightly builds? https://github.com/rabbitmq/rabbitmq-server-binaries-dev/releases

[ansd]

Thanks. I'm not sure. I never use that repo tbh.
I'd recommend to use docker image pivotalrabbitmq/rabbitmq:main-otp-max-bazel. It always points to the latest main branch.

If you don't use containers, I think you could also just follow https://github.com/rabbitmq/contribute/wiki/Bazel-and-BuildBuddy#run-a-cluster-from-source

To produce a binary package: https://github.com/rabbitmq/contribute/wiki/Bazel-and-BuildBuddy#produce-a-generic-binary-package-generic-unix-package

[gomoripeti]

very helpful links, thank you

[gomoripeti]

On a second thought (although our issue happened with MQTT connections, and they are most probably fixed by using different queue arguments)
isn't it still possible to replicate the same behaviour via AMQP connections by declaring a lot of durable, auto-delete, not-replicated queues and killing the node?

[michaelklishin]

How much sense does a durable but non-replicated, auto-delete queue make?

[gomoripeti]

you are right, I did not think of it if this combo makes sense at all :) respect to those who can think carefully even late at night

[ansd]

I'm going to close this discussion as it is fixed in 3.12.