check_if_node_is_quorum_critical incorrect status

[zaeemarshad]

Describe the bug

With a 3-member QQ, if one member is in a timeout state, rabbitmq-queues check_if_node_is_quorum_critical incorrectly reports that the queue will become unavailable.

# rabbitmq-queues quorum_status qq-test
Status of quorum queue qq-test on node rabbit@node-1 ...
┌────────────────────────────┬────────────┬───────────┬──────────────┬────────────────┬──────┬─────────────────┐
│ Node Name                  │ Raft State │ Log Index │ Commit Index │ Snapshot Index │ Term │ Machine Version │
├────────────────────────────┼────────────┼───────────┼──────────────┼────────────────┼──────┼─────────────────┤
│ rabbit@node-3 │ timeout    │           │              │                │      │                 │
├────────────────────────────┼────────────┼───────────┼──────────────┼────────────────┼──────┼─────────────────┤
│ rabbit@node-2 │ follower   │ 74184652  │ 74184652     │ 62000870       │ 22   │ 3               │
├────────────────────────────┼────────────┼───────────┼──────────────┼────────────────┼──────┼─────────────────┤
│ rabbit@node-1 │ leader     │ 74184652  │ 74184652     │ 62000870       │ 22   │ 3               │
└────────────────────────────┴────────────┴───────────┴──────────────┴────────────────┴──────┴─────────────────┘

# rabbitmq-queues check_if_node_is_quorum_critical
Checking if node rabbit@node-3 is critical for quorum of any queues/streams ...
queue 'qq-test' in vhost '/' will become unavailable if node rabbit@node-3 stops

Reproduction steps

1. Create a 2 member QQ with a backlog of 10M
2. Add a third member to the queue - replication will start
3. Add a consumer on the third member - this will cause local effects duplication and mess with the replication
4. The queue will likely end up in a resync-crash loop with a timeout status
5. Run rabbitmq-queues check_if_node_is_quorum_critical

Expected behavior

Expect the check to pass and not report any issues

Additional context

No response

[michaelklishin]

There is ongoing work in the Ra repository making sure that such new members that are behind are not counted as online replicas.

When it comes to timeouts, is your expectation that timeouts from such nodes should be ignored by the nodes that are caught up?

What node did you run the check agains?

[michaelklishin]

This is definitely one of the key ideas behind rabbitmq/ra#375 by @illotum and @kjnilsson: a non-caught up cluster member should not be considered a regular online replica, and currently in several key aspects they are.

[zaeemarshad]

Sorry, that's my bad. When running the command on node-1/node-2, the tooling correctly reports them as quorum critical. On node-3, which is timed-out, I do not expect this to be reported as quorum critical but it does.

[michaelklishin]

If what you are saying is that C should not be considered quorum-critical in the above scenario of A, B having full log and C catching up, then I'd agree, as long as C is aware of two other cluster members.

If it's not or cannot communicate with them because its link is saturated, it's a good question what should this check return at all. A node that's already in the minority — is it "quorum critical" or not for preserving a majority?

[michaelklishin]

OK, now I see. Thanks for clarifying.

[zaeemarshad]

If what you are saying is that C should not be considered quorum-critical in the above scenario of A, B having full log and C catching up, then I'd agree, as long as C is aware of two other cluster members.

This is exactly what I mean, thanks.

If it's not or cannot communicate with them because its link is saturated, it's a good question what should this check return at all. A node that's already in the minority — is it "quorum critical" or not for preserving a majority?

Our cluster partition handling strategy is set to pause_minority. There are other quorum queues that are on node-3 and I don't see any indication of timeout or other issues with them. I don't think there's a link saturation issue but I could be wrong.

[michaelklishin]

Can logs from all nodes be shared, please? That will likely shed some light on where these timeouts happen.

[zaeemarshad]

I was going to open up another bug report for the timeout issue. It is reproducible on the test cluster that I have. Should I do that?

[michaelklishin]

If you have it running then running collect-env on it would help a lot. That will collect a lot of information, so please make sure nothing in the tarball is sensitive.

A catching up node won't be operational until it catches up one way or another. The goal of rabbitmq/ra#375 is to mark it as such. I don't think "handling timeouts" separately would somehow be possible, so we don't need more issues.

[zaeemarshad]

The timeout issue in this particular case is not a catching up issue. The queue sync process crashes after about 80% of the way and then restarts. Here are some logs of what I am seeing.

2023-09-22 01:12:22.250550+00:00 [debug] <0.401.0> wal: opening new file 00000696.wal open mem tables: #Ref<0.4135819722.976093185.211723>
2023-09-22 01:12:27.185471+00:00 [debug] <0.391.0> segment_writer: deleting wal file: 00000695.wal
2023-09-22 01:12:27.308784+00:00 [debug] <0.334.0> ra_log_ets: ets:delete/1 took 123ms to delete #Ref<0.4135819722.979238915.39044>
2023-09-22 01:12:30.008213+00:00 [debug] <0.440.64> queue 'jimmy-qq-test-2' in vhost '/': terminating with function_clause in state follower
2023-09-22 01:12:30.008282+00:00 [debug] <0.440.64> queue 'jimmy-qq-test-2' in vhost '/': terminating with reason 'function_clause'
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64> ** State machine '%2F_jimmy-qq-test-2' terminating
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64> ** Last event = {cast,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                  {append_entries_rpc,22,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                   {'%2F_jimmy-qq-test-2','rabbit@rabbitmq-store-xbm8'},
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                   74184656,70786966,22,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                   [{70786967,22,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                     {'$usr',
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                      #{ts => 1695186686318},
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                      {enqueue,<26023.13365.12>,149140,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                       {basic_message,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                        {resource,<<"/">>,exchange,<<"direct">>},
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                        [<<"d816724d-d50d-4790-8bbd-2b29ac789a13">>],
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                        {content,60,none,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                         <<16,0,2>>,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                         rabbit_framing_amqp_0_9_1,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                         [<<0,2,70,147,0,4,246,78,237,149,5,167,0,0,0,0,0,0,0,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                            0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                            0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
2023-09-22 01:12:30.008383+00:00 [error] <0.440.64>                            0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
<snip>

This is followed by restarts of the process requesting missing segments.

2023-09-22 01:38:08.184806+00:00 [info] <0.31477.66> queue 'jimmy-qq-test-2' in vhost '/': follower did not have entry at 70792278 in 22. Requesting {'%2F_jimmy-qq-test-2','rabbit@rabbitmq-store-xbm8'} from 70788439
2023-09-22 01:40:14.136775+00:00 [info] <0.6098.67> queue 'jimmy-qq-test-2' in vhost '/': follower did not have entry at 70792694 in 22. Requesting {'%2F_jimmy-qq-test-2','rabbit@rabbitmq-store-xbm8'} from 70788919
2023-09-22 01:42:18.130461+00:00 [info] <0.12757.67> queue 'jimmy-qq-test-2' in vhost '/': follower did not have entry at 70793174 in 22. Requesting {'%2F_jimmy-qq-test-2','rabbit@rabbitmq-store-xbm8'} from 70789719
2023-09-22 01:44:21.710821+00:00 [info] <0.19547.67> queue 'jimmy-qq-test-2' in vhost '/': follower did not have entry at 70793974 in 22. Requesting {'%2F_jimmy-qq-test-2','rabbit@rabbitmq-store-xbm8'} from 70790471
2023-09-22 01:46:27.514730+00:00 [info] <0.26531.67> queue 'jimmy-qq-test-2' in vhost '/': follower did not have entry at 70794726 in 22. Requesting {'%2F_jimmy-qq-test-2','rabbit@rabbitmq-store-xbm8'} from 70790855

With the LogIndex at 74184658, this will take days to process. Deleting and re-adding the member does not address the issue. I will run collect-env and attach the tarball here.

[michaelklishin]

Filed #9519 with a clarified description.

[michaelklishin]

@zaeemarshad also, would you mind describing how you use this health check?

It was designed to be used before restarting a node during a rolling upgrade:

• Run the check
• If it returns false, proceed to restart the node
• Wait for it to come up
• Move on to the next node

When you add a node, you don't need to run this check against it. A newly joined member generally won't be quorum-critical for several reasons, one of which was brought up in this discussion.

So I am curious how did you end up with this check being run against node C in the scenario above?

[zaeemarshad]

We are not running this on new nodes. Let me add a bit more context on how we use this. We run rabbitmq servers on VMs. The VMs have to be restarted on a regular basis for security updates, patches, rabbitmq upgrades etc and get replaced once a year for OS upgrades. Our maintenance tool runs a pre-emptive check on the node before stopping rabbitmq. These checks are usually about capacity, synchronised CMQs etc. I recently added this check to ensure that the node is not stopped if it is quorum critical.

In this particular case where I am running into timeout issue with this queue, I was going to restart rabbitmq and ran our maintenance tool (force of habit). It spat the error about the node being quorum critical and the name of the queue which is having trouble synchronising. Hope this explains.

[michaelklishin]

It does clarify things for me, thank you.