No promotion of mirrored queue home to synced mirror nodes upon home node termination

[Brandon Borden]

Hi All!

I have a 3-node clustered RabbitMQ broker in a classic mirrored-queue configuration. I attempted a rolling instance replacement for each of the nodes. During this, I expected Rabbit to promote one of the new nodes as the home for each of the existing queues. However, this didn't happen for some of the queues.

At a high-level, the sequence I carried out:

1. Shutdown and replace node-1 with node-4
2. Shutdown and replace node-2 with node-5
3. Shutdown and replace node-3 with node-6

Notes for the broker's HA settings, log observations and snippets are attached below. I'll see if I can attach more complete logs tomorrow.

I appreciate any insights on what could've gone wrong and how I can prevent this in future. 

Thanks,
Brandon

--------------------------------------------------------------------------

HA policy for all queues:

• ha-mode: all
• ha-sync-mode: automatic

Default mirror promotion (on failure, on shutdown) settings are in use.

There are a few Mnesia errors during the event (below). Not sure if they are related to the promotion issue yet.

Additionally, there are some nodedown messages (below) for one of the new nodes as it crashed a few times.

Lastly, there are numerous errors of type supervisor/emulator that may be related. I'll work on attaching a more complete set of logs soon that will include these.

RabbitMQ version: 3.8.6
Erlang version: 23.0.3

Logs for one queue:

```
--- end of previous rolling replacement ---
2021-02-21 01:23:31.785,node-1, [info] <0.17824.1326> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
2021-02-21 01:24:00.085,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-3.1613870554.3332.0> saw deaths of mirrors <rab...@ip-1.1613265846.3301.0>
2021-02-21 01:24:00.085,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Promoting mirror <rab...@ip-3.1613870554.3332.0> to master
2021-02-21 01:24:00.085,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: 0 messages to synchronise
2021-02-21 01:24:00.085,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: batch size: 4096
2021-02-21 01:24:00.085,node-3, [info] <0.23768.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
--- latest rolling replacement ----
2021-02-28 01:24:48.320,node-4, [info] <0.1189.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-4': <0.3465.0>
2021-02-28 01:24:52.340,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: 0 messages to synchronise
2021-02-28 01:24:52.340,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: batch size: 4096
2021-02-28 01:24:52.341,node-3, [info] <0.23727.1018> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
2021-02-28 01:25:08.349,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: 0 messages to synchronise
2021-02-28 01:25:08.349,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: batch size: 4096
2021-02-28 01:25:08.349,node-3, [info] <0.26700.1018> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
2021-02-28 01:25:08.831,node-4, [info] <0.3465.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-4.1614475447.3465.0> saw deaths of mirrors <rab...@ip-1.1613870647.3297.0>
2021-02-28 01:28:51.629,node-5, [info] <0.1144.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-5': <0.3433.0>
2021-02-28 01:28:55.958,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: 0 messages to synchronise
2021-02-28 01:28:55.958,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: batch size: 4096
2021-02-28 01:28:55.958,node-3, [info] <0.12676.1019> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
2021-02-28 01:29:26.421,node-4, [info] <0.3465.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-4.1614475447.3465.0> saw deaths of mirrors <rab...@ip-2.1613870603.3312.0>
2021-02-28 01:29:27.469,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: 0 messages to synchronise
2021-02-28 01:29:27.469,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: batch size: 4096
2021-02-28 01:29:27.469,node-3, [info] <0.19352.1019> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
2021-02-28 01:33:34.785,node-6, [info] <0.1206.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-6': <0.3413.0>
2021-02-28 01:33:39.068,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: 0 messages to synchronise
2021-02-28 01:33:39.068,node-3, [info] <0.3332.0> Mirrored queue 'queue_name' in vhost '/': Synchronising: batch size: 4096
2021-02-28 01:33:39.069,node-3, [info] <0.1909.1020> Mirrored queue 'queue_name' in vhost '/': Synchronising: all mirrors already synced
2021-02-28 01:34:32.819,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:34.069,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:37.823,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:39.073,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:42.825,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:44.076,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:47.827,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:34:49.578,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:18.353,node-4, [info] <0.1189.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-4': <0.3465.0>
2021-02-28 01:37:18.356,node-4, [info] <0.3465.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-4.1614475447.3465.0> saw deaths of mirrors <rab...@ip-1.1613870647.3297.0>
2021-02-28 01:37:18.365,node-4, [info] <0.3465.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-4.1614475447.3465.0> saw deaths of mirrors <rab...@ip-2.1613870603.3312.0>
2021-02-28 01:37:18.365,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:18.372,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:18.378,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:18.383,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:18.387,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:18.418,node-5, [info] <0.1144.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-5': <0.3433.0>
2021-02-28 01:37:22.088,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:22.091,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:22.095,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:37:24.848,node-6, [info] <0.1206.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-6': <0.3413.0>
2021-02-28 01:42:30.191,node-4, [info] <0.1189.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-4': <0.3465.0>
2021-02-28 01:42:30.192,node-4, [info] <0.3465.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-4.1614475447.3465.0> saw deaths of mirrors <rab...@ip-1.1613870647.3297.0>
2021-02-28 01:42:30.199,node-4, [info] <0.3465.0> Mirrored queue 'queue_name' in vhost '/': Slave <rab...@ip-4.1614475447.3465.0> saw deaths of mirrors <rab...@ip-2.1613870603.3312.0>
2021-02-28 01:42:30.199,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:30.205,node-6, [info] <0.1206.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-6': <0.3413.0>
2021-02-28 01:42:30.211,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:30.217,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:30.224,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:30.228,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:30.250,node-5, [info] <0.1144.0> Mirrored queue 'queue_name' in vhost '/': Adding mirror on node 'rabbit@ip-5': <0.3433.0>
2021-02-28 01:42:33.889,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:33.892,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'
2021-02-28 01:42:33.896,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name' in vhost '/'

```

Mnesia errors:

```
2021-02-28 01:33:57.338,node-3," [error] <0.374.0> Mnesia('rabbit@ip-3'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:33:57.385,node-3,"Mnesia('rabbit@ip-3'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:33:58.297,node-4," [error] <0.338.0> Mnesia('rabbit@ip-4'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:34:01.761,node-6," [error] <0.337.0> Mnesia('rabbit@ip-6'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:34:01.761,node-6,"Mnesia('rabbit@ip-6'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:34:02.048,node-4,"Mnesia('rabbit@ip-4'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:34:02.225,node-5," [error] <0.336.0> Mnesia('rabbit@ip-5'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:34:02.225,node-5,"Mnesia('rabbit@ip-5'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:37:18.347,node-4," [error] <0.338.0> Mnesia('rabbit@ip-4'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:37:18.406,node-5," [error] <0.336.0> Mnesia('rabbit@ip-5'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:37:24.799,node-6," [error] <0.337.0> Mnesia('rabbit@ip-6'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:37:26.662,node-4,"Mnesia('rabbit@ip-4'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:37:26.936,node-5,"Mnesia('rabbit@ip-5'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:37:33.314,node-6,"Mnesia('rabbit@ip-6'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:39:22.399,node-5,{badarg,[{mnesia_tm,commit_participant,7,[{file,"mnesia_tm.erl"},{line,1760}]}]}
2021-02-28 01:39:22.399,node-5,{badarg,[{mnesia_tm,commit_participant,7,[{file,"mnesia_tm.erl"},{line,1760}]}]}
2021-02-28 01:42:30.171,node-4,"Mnesia('rabbit@ip-4'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:42:30.178,node-4," [error] <0.338.0> Mnesia('rabbit@ip-4'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:42:30.209,node-6," [error] <0.337.0> Mnesia('rabbit@ip-6'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:42:30.226,node-5,"Mnesia('rabbit@ip-5'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:42:30.234,node-5," [error] <0.336.0> Mnesia('rabbit@ip-5'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"
2021-02-28 01:42:38.677,node-6,"Mnesia('rabbit@ip-6'): ** ERROR ** mnesia_event got {inconsistent_database, bad_decision, 'rabbit@ip-3'}"

```

Nodedown errors:

```
2021-02-28 01:42:30.178,node-4,"[{<46828.3820.0>,{exit,{nodedown,'rabbit@ip-6'},[]}}]"
2021-02-28 01:42:30.178,node-4,"[{<46828.3820.0>,{exit,{nodedown,'rabbit@ip-6'},[]}}]"
2021-02-28 01:37:18.346,node-4,"[{<46828.3820.0>,{exit,{nodedown,'rabbit@ip-6'},[]}}]"
2021-02-28 01:37:18.346,node-4,"[{<46828.3820.0>,{exit,{nodedown,'rabbit@ip-6'},[]}}]"
2021-02-28 01:33:44.048,node-4,"[{<46828.3820.0>,{exit,{nodedown,'rabbit@ip-6'},[]}}]"
2021-02-28 01:33:40.038,node-4,"[{<46828.3820.0>,{exit,{nodedown,'rabbit@ip-6'},[]}}]"

```

[Brandon Borden]

I should have attached logs for a second queue as well. Almost half the impacted queues also have a message about home node being down:

````

time,istanceId,withoutTimeMessage

2021-02-28 01:24:48.319,node-4, [info] <0.1189.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-4': <0.3007.0>

2021-02-28 01:24:51.341,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: 0 messages to synchronise

2021-02-28 01:24:51.341,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: batch size: 4096

2021-02-28 01:24:51.341,node-3, [info] <0.23595.1018> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: all mirrors already synced

2021-02-28 01:25:08.681,node-2, [info] <0.2858.0> Mirrored queue 'queue_name_2' in vhost '/': Slave <rab...@ip-2.1613870603.2858.0> saw deaths of mirrors <rab...@ip-1.1613870647.2850.0>

2021-02-28 01:25:09.100,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: 0 messages to synchronise

2021-02-28 01:25:09.100,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: batch size: 4096

2021-02-28 01:25:09.100,node-3, [info] <0.28796.1018> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: all mirrors already synced

2021-02-28 01:28:51.628,node-5, [info] <0.1144.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-5': <0.2954.0>

2021-02-28 01:28:54.945,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: 0 messages to synchronise

2021-02-28 01:28:54.945,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: batch size: 4096

2021-02-28 01:28:54.945,node-3, [info] <0.12732.1019> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: all mirrors already synced

2021-02-28 01:29:25.969,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: 0 messages to synchronise

2021-02-28 01:29:25.969,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: batch size: 4096

2021-02-28 01:29:25.969,node-3, [info] <0.23431.0> Mirrored queue 'queue_name_2' in vhost '/': Master <rab...@ip-3.1613870554.2889.0> saw deaths of mirrors <rab...@ip-2.1613870603.2858.0>

2021-02-28 01:29:26.469,node-3, [info] <0.16926.1019> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: all mirrors already synced

2021-02-28 01:33:34.784,node-6, [info] <0.1206.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-6': <0.2967.0>

2021-02-28 01:33:38.069,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: 0 messages to synchronise

2021-02-28 01:33:38.069,node-3, [info] <0.2889.0> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: batch size: 4096

2021-02-28 01:33:38.069,node-3, [info] <0.1899.1020> Mirrored queue 'queue_name_2' in vhost '/': Synchronising: all mirrors already synced

2021-02-28 01:33:56.586,node-5, [info] <0.2954.0> Mirrored queue 'queue_name_2' in vhost '/': Slave <rab...@ip-5.1614475716.2954.0> saw deaths of mirrors <rab...@ip-3.1613870554.2889.0>

2021-02-28 01:34:31.568,node-4,operation queue.declare caused a channel exception not_found: home node 'rabbit@ip-3' of durable queue 'queue_name_2' in vhost '/' is down or inaccessible

2021-02-28 01:34:32.103,node-5,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:34:34.069,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:34:36.572,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:18.345,node-4,operation queue.declare caused a channel exception not_found: home node 'rabbit@ip-3' of durable queue 'queue_name_2' in vhost '/' is down or inaccessible

2021-02-28 01:37:18.352,node-4, [info] <0.1189.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-4': <0.3007.0>

2021-02-28 01:37:18.372,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:18.374,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:18.379,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:18.416,node-5, [info] <0.1144.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-5': <0.2954.0>

2021-02-28 01:37:18.422,node-5, [info] <0.2954.0> Mirrored queue 'queue_name_2' in vhost '/': Slave <rab...@ip-5.1614475716.2954.0> saw deaths of mirrors <rab...@ip-3.1613870554.2889.0>

2021-02-28 01:37:18.432,node-5,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:18.435,node-5,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:18.438,node-5,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:22.089,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:37:24.848,node-6, [info] <0.1206.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-6': <0.2967.0>

2021-02-28 01:42:30.182,node-4,operation queue.declare caused a channel exception not_found: home node 'rabbit@ip-3' of durable queue 'queue_name_2' in vhost '/' is down or inaccessible

2021-02-28 01:42:30.190,node-4, [info] <0.1189.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-4': <0.3007.0>

2021-02-28 01:42:30.204,node-6, [info] <0.1206.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-6': <0.2967.0>

2021-02-28 01:42:30.211,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:42:30.213,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:42:30.218,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:42:30.248,node-5, [info] <0.1144.0> Mirrored queue 'queue_name_2' in vhost '/': Adding mirror on node 'rabbit@ip-5': <0.2954.0>

2021-02-28 01:42:30.252,node-5, [info] <0.2954.0> Mirrored queue 'queue_name_2' in vhost '/': Slave <rab...@ip-5.1614475716.2954.0> saw deaths of mirrors <rab...@ip-3.1613870554.2889.0>

2021-02-28 01:42:33.890,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:42:33.892,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

2021-02-28 01:42:33.897,node-4,operation queue.declare caused a channel exception not_found: no queue 'queue_name_2' in vhost '/'

```

[M K]

This could be [1]. IIRC we had similar log messages when it was first investigated.

3.8.9 is about six months old.

Since classic mirrored queues eagerly sync contents, a mass upgrade

can trigger an overload of the distribution buffer, which can lead to these Mnesia messages in the log.

1. rabbitmq/rabbitmq-server#2449

[Brandon Borden]

Hi Michael - thanks for the response. 

I'm taking a closer look at the linked PR to see if I can correlate the two.

Just to clarify, for "upgrade" - are you referring to a RabbitMQ version upgrade? If so, there was no version upgrade in this case, so it could be something else.

Thanks,

Brandon

[Brandon Borden]

Can you provide some info on how/when this assertion could fail? I don't see any particular message about this assertion/line of code in the RabbitMQ logs.

It seems like this assertion will only fail when get_pid for these two lines return different pids:
- https://github.com/rabbitmq/rabbitmq-server/blob/v3.8.6/src/rabbit_mirror_queue_slave.erl#L116

- https://github.com/rabbitmq/rabbitmq-server/blob/46bf724f1443e62f57a921dd70f602092bd3397b/src/rabbit_mirror_queue_slave.erl#L161

I'm not sure the context of when this would happen/what other conditions would need to be true for this to occur

Thanks again

[Brandon Borden]

Just an update on this - still seeing the issue on RabbitMQ version 3.8.11