Nodes that form a new cluster may not cluster correctly

[gerhard]

Describe the bug

Since #621 was introduced, nodes that form a new cluster may not cluster correctly.

In our (+@ansd) case, pod quick-rabbit-server-0 formed its own cluster, while quick-rabbit-server-1 & quick-rabbit-server-2 formed a second cluster with the same name as the first cluster. Everything looks healthy from K8S (3 ready pods) & Erlang perspective (6 healthy distribution links), but we have 2 RabbitMQ clusters, one with 1 node & one with 2 nodes, and this is clearly wrong.

To Reproduce

This is a difficult one to reproduce as it's timing-specific. We are including all the logs and this can be reproduced with https://github.com/rabbitmq/observability-2021/tree/bf77efebc6760e16d8176bc0c7b750204d8b2a7e/talks/emea-tech-talk (private repo available to all maintainers of this repo) using the following steps:

make 1.k8s 2.k8s-rabbitmq 4.resolve-first-problem 5.second-problem

While 5.second-problem is not technically needed, it makes it very obvious as to what the problem is:

Version and environment information

• RabbitMQ: 3.8.14
• RabbitMQ Cluster Operator: 1.6.0
• Kubernetes: 1.19.9
• Cloud provider or hardware configuration: k3s (see https://github.com/rabbitmq/observability-2021/blob/bf77efebc6760e16d8176bc0c7b750204d8b2a7e/talks/emea-tech-talk/Makefile#L35)

Quick fix

Our quick fix was to reset quick-rabbit-server-0:

rabbitmqctl stop_app
rabbitmqctl reset
rabbitmqctl start_app

Additional context

kubectl logs --selector app.kubernetes.io/name=quick-rabbit --prefix=true --tail=-1

...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:40.634 [info] <0.273.0> Node database directory at /var/lib/rabbitmq/mnesia/rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default is empty. Assuming we need to join an existing cluster or initialise from scratch...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:40.634 [info] <0.273.0> Configured peer discovery backend: rabbit_peer_discovery_k8s
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:40.634 [info] <0.273.0> Will try to lock with peer discovery backend rabbit_peer_discovery_k8s
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:40.634 [info] <0.273.0> Peer discovery backend does not support locking, falling back to randomized delay
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:40.634 [info] <0.273.0> Peer discovery backend rabbit_peer_discovery_k8s supports registration.
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:40.634 [info] <0.273.0> Will wait for 17965 milliseconds before proceeding with registration...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:58.615 [info] <0.273.0> All discovered existing cluster peers: rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:58.615 [info] <0.273.0> Peer nodes we can cluster with: rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:58.616 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:58.616 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:58.616 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 9 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:59.117 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:59.118 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:59.118 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 8 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:59.619 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:59.620 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:38:59.620 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 7 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:00.122 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:00.123 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:00.123 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 6 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:00.624 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:00.625 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:00.625 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 5 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:01.126 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:01.127 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:01.127 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 4 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:01.628 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:01.629 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:01.629 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 3 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:02.130 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:02.131 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:02.131 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 2 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:02.632 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:02.633 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:02.633 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 1 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:03.134 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:03.135 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:03.135 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 0 retries left...
[pod/quick-rabbit-server-0/rabbitmq] 2021-04-14 14:39:03.637 [warning] <0.273.0> Could not successfully contact any node of: rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default,rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default (as in Erlang distribution). Starting as a blank standalone node...
...
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Node database directory at /var/lib/rabbitmq/mnesia/rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default is empty. Assuming we need to join an existing cluster or initialise from scratch...
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Configured peer discovery backend: rabbit_peer_discovery_k8s
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Will try to lock with peer discovery backend rabbit_peer_discovery_k8s
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Peer discovery backend does not support locking, falling back to randomized delay
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Peer discovery backend rabbit_peer_discovery_k8s supports registration.
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Will wait for 21437 milliseconds before proceeding with registration...
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.211 [info] <0.273.0> All discovered existing cluster peers: rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.211 [info] <0.273.0> Peer nodes we can cluster with: rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.212 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.212 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.212 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 9 retries left...
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.714 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.715 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:02.715 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 8 retries left...
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:03.216 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:03.217 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:03.217 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 7 retries left...
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:03.717 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-2/rabbitmq] 2021-04-14 14:39:03.733 [info] <0.273.0> Node 'rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default' selected for auto-clustering
...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:40.763 [info] <0.273.0> Node database directory at /var/lib/rabbitmq/mnesia/rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default is empty. Assuming we need to join an existing cluster or initialise from scratch...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:40.763 [info] <0.273.0> Configured peer discovery backend: rabbit_peer_discovery_k8s
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:40.763 [info] <0.273.0> Will try to lock with peer discovery backend rabbit_peer_discovery_k8s
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:40.763 [info] <0.273.0> Peer discovery backend does not support locking, falling back to randomized delay
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:40.763 [info] <0.273.0> Peer discovery backend rabbit_peer_discovery_k8s supports registration.
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:40.764 [info] <0.273.0> Will wait for 17512 milliseconds before proceeding with registration...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.292 [info] <0.273.0> All discovered existing cluster peers: rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.292 [info] <0.273.0> Peer nodes we can cluster with: rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default, rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.297 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.302 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.302 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 9 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.803 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.804 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:58.804 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 8 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:59.305 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:59.306 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:59.306 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 7 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:59.807 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:59.808 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:38:59.808 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 6 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:00.309 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:00.310 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:00.310 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 5 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:00.811 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:00.812 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:00.812 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 4 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:01.313 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:01.314 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:01.314 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 3 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:01.815 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:01.816 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:01.816 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 2 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:02.317 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:02.318 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:02.318 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 1 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:02.819 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:02.820 [warning] <0.273.0> Could not auto-cluster with node rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default: {error,tables_not_present}
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:02.820 [error] <0.273.0> Trying to join discovered peers failed. Will retry after a delay of 500 ms, 0 retries left...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.320 [warning] <0.273.0> Could not successfully contact any node of: rabbit@quick-rabbit-server-0.quick-rabbit-nodes.default,rabbit@quick-rabbit-server-2.quick-rabbit-nodes.default (as in Erlang distribution). Starting as a blank standalone node...
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.324 [info] <0.44.0> Application mnesia exited with reason: stopped
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.324 [info] <0.44.0> Application mnesia exited with reason: stopped
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.351 [info] <0.44.0> Application mnesia started on node 'rabbit@quick-rabbit-server-1.quick-rabbit-nodes.default'
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.461 [info] <0.273.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.461 [info] <0.273.0> Successfully synced tables from a peer
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.494 [info] <0.273.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
[pod/quick-rabbit-server-1/rabbitmq] 2021-04-14 14:39:03.494 [info] <0.273.0> Successfully synced tables from a peer
...

Attaching all logs as a file (1000+ lines): parallel-startup-problem.txt

Related improvement

In the context of alerts, we are missing metrics that would enable us to alert when the expected number of RabbitMQ nodes are not present in the cluster. In this case, we were expecting RabbitMQ to form a 3-node cluster. If that doesn't happen, we should have an alert that would catch it. Something for myself & @ansd to follow-up on. I'm adding it here so that we have it all in a single place.

[ansd]

This happens sporadically on kind v0.10.0 go1.15.7 darwin/amd64 as well.

Steps to reproduce:

kind delete cluster; kind create cluster; kubectl apply -f https://github.com/rabbitmq/cluster-operator/releases/download/v1.6.0/cluster-operator.yml ; kubectl rabbitmq create myrabbit --replicas 3

Once all pods are ready:

> kubectl exec myrabbit-server-0 -- rabbitmqctl cluster_status | grep -A 5 "Running Nodes"
Defaulted container "rabbitmq" out of: rabbitmq, setup-container (init)
Running Nodes

rabbit@myrabbit-server-0.myrabbit-nodes.default
rabbit@myrabbit-server-1.myrabbit-nodes.default

Versions
> kubectl exec myrabbit-server-2 -- rabbitmqctl cluster_status | grep -A 5 "Running Nodes"
Defaulted container "rabbitmq" out of: rabbitmq, setup-container (init)
Running Nodes

rabbit@myrabbit-server-2.myrabbit-nodes.default

Versions

[slacksach]

Observed this behaviour yesterday. We were performing an upgrade from 0.48.0 to 1.6.0, the -0 node started then -1 and -2 started and formed their own cluster.

[toredash]

Confirm, same behaviour here. I find it strange that PR got included as the documentation cleary says OrderedReady should be used:
https://www.rabbitmq.com/cluster-formation.html

Use OrderedReady Pod Management Policy
Peer discovery mechanism will filter out nodes whose pods are not yet ready (initialised) according to their readiness probe as reported by the Kubernetes API. For example, if pod management policy of a stateful set is set to Parallel, some nodes may be discovered but will not be joined. To work around this, the Kubernetes peer discovery plugin uses randomized startup delays.

Deployments that use the OrderedReady pod management policy start pods one by one and therefore all discovered nodes will be ready to join. This policy is used by default by Kubernetes.

[ansd]

@toredash what K8s cluster (IaaS) do you use?

We observe this bug only sporadically when creating a new RabbitMQ cluster. Rolling updates are not affected because Parallel Pod Management doesn't apply to updates.

[toredash]

@toredash what K8s cluster (IaaS) do you use?

GKE

It's easy to fix as you can set this value manually here: https://github.com/rabbitmq/cluster-operator/blob/main/docs/api/rabbitmq.com.ref.asciidoc#k8s-api-github-com-rabbitmq-cluster-operator-api-v1beta1-statefulsetspec

It's not allowed to modify this value, so the statefulset must be destroyed afterwards if the value changes.

We observe this bug only sporadically when creating a new RabbitMQ cluster. Rolling updates are not affected because Parallel Pod Management doesn't apply to updates.

What updates are you referring to ? Rolling updates are only applicable containers, labels, resource request/limits, and annotations for the Pods in a StatefulSet.: https://kubernetes.io/docs/concepts/workloads/controllers/statefulset/#update-strategies

If you want to see how badly this can break, do a kubectl --namespace rabbitmq-system rollout restart statefulset rabbitmq-operator-server, I'm pretty sure the cluster will break as the cluster is not shutdown cleanly.

[ansd]

@toredash I'm not sure what issue you observe, but I'm sure that the issue you observe is completely different from this GitHub issue.

This GitHub issue is about nodes failing to cluster for newly created RabbitMQ Clusters. So far we observe this sporadically only on kind and on k3s.

What updates are you referring to ?

I'm referring to the rolling update of the Pods in the StatefulSet.
Rolling updates work perfectly from what we can tell. We didn't observe any issues. If you do observe an issue with rolling updates, please open a separate GitHub issue with exact steps to reproduce.

[toredash]

@toredash I'm not sure what issue you observe, but I'm sure that the issue you observe is completely different from this GitHub issue.

This GitHub issue is about nodes failing to cluster for newly created RabbitMQ Clusters. So far we observe this sporadically only on kind and on k3s.

This is what we are seing. If we create a cluster without podManagementPolicy:OrderedReady, sometimes it will fail. I think it is a timing issue, as if node-0 and node-1 believes they are first to start the cluster, they will form their independent cluster.

With podManagementPolicy:OrderedReady set, we are not able to reproduce this.

[michaelklishin]

@toredash the approach and thinking of what's recommended has evolved over the 3-4 years since K8S peer discovery was introduced, in large part because of all the work that's gone into this Operator.

That section of the docs was not updated after our team has decided that this Operator can, in fact, quite safely use parallel pod startup. The only tricky part is that the randomized startup delay for K8S uses a very narrow default of [0, 2] seconds compared to [5, 30] or something like that in other places. It was used to avoid delaying deployments
where pods are started one by one. In the brave new world of parallel deployment, those settings are
counterproductive.

The default is hardcoded and can be easily changed. Tomorrow we should have an image you can try that will use whatever values you provide

[michaelklishin]

RabbitMQ nodes will log the effective randomized startup delay value and the range it was randomly picked from:

Randomized startup delay: configured range is from … to … milliseconds, PRNG pick: …

That is logged at debug level. So if you have a way to reproduce, please set log level to debug and look for that message on all nodes (each node uses its own delay: that's the point)

[mkuratczyk]

The Operator already stets the following range in the configuration:

    cluster_formation.randomized_startup_delay_range.min = 5
    cluster_formation.randomized_startup_delay_range.max = 30

It seems like this range is too narrow to prevent the race condition during cluster formation. We've discussed that and decided that:

1. as a short term solution, we'll look into making this default range wider. However, you can do that right now through additionalConfig. A range like 5-300 would almost certainly make this problem disappear.
2. This will take longer but we'll look into changing k8s peer discovery plugin to use locking instead of random delay. This should ultimately solve the issue

It's worth remembering that we introduced a parallel policy for a reason - it was to solve a problem where a cluster wouldn't start at all if multiple pods were deleted (if all of them were deleted due to an outage, it was almost guaranteed it wouldn't start). Therefore, going back to OrderedReady is not a solution - it's just choosing one problem over another. We decided that an issue with a newly deployed cluster is less of a problem than a cluster that won't start after an outage, because new clusters by definitions don't have any data nor clients yet.

[michaelklishin]

5-300 sounds pretty broad but OK. Note that the peer discovery plugin will filter out pods that are not considered ready. This significantly increases the likelihood of a node discovering no peers.

Locking is an option as some other peer discovery plugins use it (etcd, Consul). We just need to decide on what would be
an optimal locking mechanism in the Kubernetes API. Locking is a non-trivial problem in practice, so it can take a while.

[mkuratczyk]

I've run some tests to see how often the issue occurs. With default Operator settings - min=5, max=30, the issue occurred in 7% of cases (I created 100 3-node clusters for this test). The main reason is that the startup delay is not uniformly distributed between min and max - the delay value is generated between 0 and max and only then corrected - if it happens to be below min, it is set to min: https://github.com/rabbitmq/rabbitmq-server/blob/master/deps/rabbit/src/rabbit_peer_discovery.erl#L191-L194. This leads to a relatively large number of nodes waiting exactly the minimum required amount of time. For example, here are some of my results (first column is the number of nodes in the cluster as reported by each node so 212 means nodes 0 and 2 were clustered but node 1 was solo; the next 3 columns are the delays reported by each node):

122 5000 6761 9769
212 5000 7239 5000
221 12020 5000 5000
221 25781 5000 5000
221 7832 11910 8080

There are a few observations:

• in almost all failed cases at least one node, often two, waited exactly 5000ms
• sometimes the issue occurs for other reasons (eg. in the first case nodes started ~2s apart and yet didn't form a cluster correctly)
• it's not clear why sometimes the node with the shortest delay (again, first case for example) is the one that remains solo - this was probably caused by some unrelated pod startup delay)

I then deployed 100 clusters with min=0 and max=60 and the issue did not occur even once.

Conclusions:

• lock-based implementation remains the best solution
• while it's obvious that a wider range leads to a lower failure rate, it turns out that the minimum value is also very important. I don't see any reason to set it above 0.
• a range o 0-60 seems to be a reasonable choice as the failure rate is below 1% in my test.