3.11.17: rabbitmq-upgrade drain fails with an exception

[mnasiadka]

Describe the bug

We use Ansible code to drain the node before restarting services on it, after upgrade to 3.11.17 it fails with an error:

RUNNING HANDLER [rabbitmq : Put RabbitMQ node into maintenance mode] ***********
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:9
Using module file /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/library/kolla_toolbox.py
Pipelining is enabled.
<104.130.172.7> ESTABLISH SSH CONNECTION FOR USER: None
<104.130.172.7> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/home/zuul/.ansible/cp/e89f229448"' 104.130.172.7 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-jcuubrawilqcyrnlzrtdkosapihhhfpa ; /usr/bin/python3'"'"'"'"'"'"'"'"' && sleep 0'"'"''
Escalation succeeded
<104.130.172.7> (0, b'\n{"action": "community.rabbitmq.rabbitmq_upgrade", "changed": false, "cmd": "/usr/sbin/rabbitmq-upgrade drain -n rabbit", "failed": true, "invocation": {"module_args": {"action": "drain", "node": "rabbit"}}, "msg": "\n09:53:57.406 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :\"-local_listener_fold_fun/1-fun-0-\", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}", "rc": 69, "stderr": "\n09:53:57.406 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :\"-local_listener_fold_fun/1-fun-0-\", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}\n", "stderr_lines": ["", "09:53:57.406 [warning] This node is being put into maintenance (drain) mode", "Error:", "{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :\"-local_listener_fold_fun/1-fun-0-\", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}"], "stdout": "Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!\n", "stdout_lines": ["Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!"]}\n', b'')
fatal: [primary]: FAILED! => {
"action": "community.rabbitmq.rabbitmq_upgrade",
"changed": false,
"cmd": "/usr/sbin/rabbitmq-upgrade drain -n rabbit",
"invocation": {
"module_args": {
"action": "drain",
"node": "rabbit"
}
},
"msg": "\n09:53:57.406 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :"-local_listener_fold_fun/1-fun-0-", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}",
"rc": 69,
"stderr": "\n09:53:57.406 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :"-local_listener_fold_fun/1-fun-0-", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}\n",
"stderr_lines": [
"",
"09:53:57.406 [warning] This node is being put into maintenance (drain) mode",
"Error:",
"{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :"-local_listener_fold_fun/1-fun-0-", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}"
],
"stdout": "Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!\n",
"stdout_lines": [
"Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!"
]
}

Reproduction steps

1. Use OpenStack Kolla-Ansible master branch
2. Deploy OpenStack and then run reconfigure - which restarts the rabbitmq nodes
3. Observe the failure
   ...

Expected behavior

Success (as in pre 3.11.17)

Additional context

No response

[michaelklishin]

"Deploy OpenStack" is not a reproduction step. There is a billion settings you can configure differently.

I cannot reproduce:

 ./sbin/rabbitmq-upgrade drain
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:24:55.249 [warning] This node is being put into maintenance (drain) mode

21:24:55.250 [warning] Suspended all listeners and will no longer accept client connections

21:24:55.250 [warning] Closed 0 local client connections

21:24:55.250 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!

./sbin/rabbitmq-diagnostics status | grep "under maintenance"
Is under maintenance?: true

[michaelklishin]

My best guess is that the node was not fully booted before it was put into maintenance, so it does not have any Ranch ETS tables, and rabbit_maintenance:suspend_all_client_listeners/0 fails.

In 3.11.17, there were no

• Changes to the ranch version used
• Changes to the drain command (last change: Jan 2, 2023)
• Changes to the rabbit_maintenance module (last change: Jan 24, 2023)

[mnasiadka]

I'll have a go at reproducing it on a VM (the error was from OpenStack CI) and come back with better diagnostics.
For now we're pinning to 3.11.16 and it seems to be working - so that was the first hunch that something changed.

[mnasiadka]

Is there a precheck that we could implement to check if Ranch ETS tables are there?

[michaelklishin]

rabbitmqctl await_startup awaits a complete boot.

[michaelklishin]

I'm all for making rabbit_maintenance:suspend_all_client_listeners/0 more defensive but the badarg about a missing map key comes from Ranch itself.

[michaelklishin]

There's also rabbitmqctl await_online_nodes.

[michaelklishin]

A CI system should arguably use both ctl await_startup (for the local node) and ctl await_online_nodes (a cluster-wide event) before attempting to restart nodes and such.

Our client libraries usually use the former when setting up a node, although with GitHub Actions this has changed slightly and sometimes may be easier to just sleep 15 or something like that.

[michaelklishin]

When I try to run the drain command in a loop and start a node in parallel, I observe that the command indeed fails the first few runs (for a different reason here, a schema DB table does not exist early on node boot because it is not loaded) but then it starts succeeding every single run:

for i in {1..1000}; do ./sbin/rabbitmq-upgrade drain; done

DIAGNOSTICS
===========

attempted to contact: [rabbit@sunnyside]

rabbit@sunnyside:
  * connected to epmd (port 4369) on sunnyside
  * epmd reports: node 'rabbit' not running at all
                  no other nodes on sunnyside
  * suggestion: start the node

Current node details:
 * node name: 'rabbitmqcli-986-rabbit@sunnyside'
 * effective user's home directory: [redacted]
 * Erlang cookie hash:[redacted]

Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:40.939 [warning] This node is being put into maintenance (drain) mode

21:41:41.536 [warning] Suspended all listeners and will no longer accept client connections

21:41:41.536 [warning] Closed 0 local client connections

21:41:41.545 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Error:
{:aborted, {:no_exists, [:rabbit_queue, {:amqqueue, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_}]}}
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:41.917 [warning] This node is being put into maintenance (drain) mode

21:41:41.917 [warning] Suspended all listeners and will no longer accept client connections

21:41:41.917 [warning] Closed 0 local client connections

21:41:41.917 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Error:
{:aborted, {:no_exists, [:rabbit_queue, {:amqqueue, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_}]}}
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:42.297 [warning] This node is being put into maintenance (drain) mode

21:41:42.297 [warning] Suspended all listeners and will no longer accept client connections

21:41:42.297 [warning] Closed 0 local client connections

21:41:42.299 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Error:
{:aborted, {:no_exists, [:rabbit_queue, {:amqqueue, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_, :_}]}}
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:43.397 [warning] This node is being put into maintenance (drain) mode

21:41:43.398 [warning] Suspended all listeners and will no longer accept client connections

21:41:43.398 [warning] Closed 0 local client connections

21:41:43.398 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:43.731 [warning] This node is being put into maintenance (drain) mode

21:41:43.731 [warning] Suspended all listeners and will no longer accept client connections

21:41:43.731 [warning] Closed 0 local client connections
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:44.066 [warning] This node is being put into maintenance (drain) mode
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:44.400 [warning] This node is being put into maintenance (drain) mode
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:44.734 [warning] This node is being put into maintenance (drain) mode

21:41:44.734 [warning] Suspended all listeners and will no longer accept client connections

21:41:44.734 [warning] Closed 0 local client connections

21:41:44.734 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:45.068 [warning] This node is being put into maintenance (drain) mode

21:41:45.068 [warning] Suspended all listeners and will no longer accept client connections

21:41:45.068 [warning] Closed 0 local client connections

21:41:45.068 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:45.401 [warning] This node is being put into maintenance (drain) mode

21:41:45.401 [warning] Suspended all listeners and will no longer accept client connections

21:41:45.401 [warning] Closed 0 local client connections

21:41:45.401 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:46.069 [warning] This node is being put into maintenance (drain) mode

21:41:46.069 [warning] Suspended all listeners and will no longer accept client connections

21:41:46.069 [warning] Closed 0 local client connections

21:41:46.069 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:46.406 [warning] This node is being put into maintenance (drain) mode
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:46.761 [warning] This node is being put into maintenance (drain) mode
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:47.431 [warning] This node is being put into maintenance (drain) mode
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:47.767 [warning] This node is being put into maintenance (drain) mode

21:41:47.767 [warning] Suspended all listeners and will no longer accept client connections

21:41:47.767 [warning] Closed 0 local client connections

21:41:47.767 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:48.107 [warning] This node is being put into maintenance (drain) mode

21:41:48.107 [warning] Suspended all listeners and will no longer accept client connections

21:41:48.107 [warning] Closed 0 local client connections

21:41:48.107 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:48.776 [warning] This node is being put into maintenance (drain) mode
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:49.445 [warning] This node is being put into maintenance (drain) mode

21:41:49.445 [warning] Suspended all listeners and will no longer accept client connections

21:41:49.445 [warning] Closed 0 local client connections

21:41:49.445 [warning] Skipping leadership transfer of quorum queues: no candidate (online, not under maintenance) nodes to transfer to!
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

21:41:49.779 [warning] This node is being put into maintenance (drain) mode

21:41:49.779 [warning] Suspended all listeners and will no longer accept client connections
Will put node rabbit@sunnyside into maintenance mode. The node will no longer serve any client traffic!

[mnasiadka]

So, I did add those two commands - and we're still failing in CI:

`RUNNING HANDLER [rabbitmq : Make sure RabbitMQ node is fully booted] ***********
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:9
Using module file /home/zuul/kolla-ansible-venv/lib64/python3.9/site-packages/ansible/modules/command.py
Pipelining is enabled.
<104.239.175.253> ESTABLISH SSH CONNECTION FOR USER: None
<104.239.175.253> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/home/zuul/.ansible/cp/e5079ac827"' 104.239.175.253 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-erirutcwajrwjdzpmisprrhwpykdulat ; /usr/bin/python3'"'"'"'"'"'"'"'"' && sleep 0'"'"''
Escalation succeeded
<104.239.175.253> (0, b'\n{"changed": true, "stdout": "", "stderr": "", "rc": 0, "cmd": ["docker", "exec", "rabbitmq", "rabbitmqctl", "await_startup"], "start": "2023-05-31 08:38:52.830012", "end": "2023-05-31 08:38:53.840920", "delta": "0:00:01.010908", "msg": "", "invocation": {"module_args": {"_raw_params": "docker exec rabbitmq rabbitmqctl await_startup", "_uses_shell": false, "warn": false, "stdin_add_newline": true, "strip_empty_ends": true, "argv": null, "chdir": null, "executable": null, "creates": null, "removes": null, "stdin": null}}}\n', b'')
changed: [primary] => {
"changed": true,
"cmd": [
"docker",
"exec",
"rabbitmq",
"rabbitmqctl",
"await_startup"
],
"delta": "0:00:01.010908",
"end": "2023-05-31 08:38:53.840920",
"invocation": {
"module_args": {
"_raw_params": "docker exec rabbitmq rabbitmqctl await_startup",
"_uses_shell": false,
"argv": null,
"chdir": null,
"creates": null,
"executable": null,
"removes": null,
"stdin": null,
"stdin_add_newline": true,
"strip_empty_ends": true,
"warn": false
}
},
"msg": "",
"rc": 0,
"start": "2023-05-31 08:38:52.830012",
"stderr": "",
"stderr_lines": [],
"stdout": "",
"stdout_lines": []
}

RUNNING HANDLER [rabbitmq : Make sure RabbitMQ cluster is in good shape] *******
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:17
Using module file /home/zuul/kolla-ansible-venv/lib64/python3.9/site-packages/ansible/modules/command.py
Pipelining is enabled.
<104.239.175.253> ESTABLISH SSH CONNECTION FOR USER: None
<104.239.175.253> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/home/zuul/.ansible/cp/e5079ac827"' 104.239.175.253 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-nvkdxqbpxbjgeduvbozkradgvbpdfaiv ; /usr/bin/python3'"'"'"'"'"'"'"'"' && sleep 0'"'"''
Escalation succeeded
<104.239.175.253> (0, b'\n{"changed": true, "stdout": "Will wait for at least 1 nodes to join the cluster of rabbit@primary. Timeout: 300 seconds.", "stderr": "", "rc": 0, "cmd": ["docker", "exec", "rabbitmq", "rabbitmqctl", "await_online_nodes", "1"], "start": "2023-05-31 08:38:54.334764", "end": "2023-05-31 08:38:55.361555", "delta": "0:00:01.026791", "msg": "", "invocation": {"module_args": {"_raw_params": "docker exec rabbitmq rabbitmqctl await_online_nodes 1", "_uses_shell": false, "warn": false, "stdin_add_newline": true, "strip_empty_ends": true, "argv": null, "chdir": null, "executable": null, "creates": null, "removes": null, "stdin": null}}}\n', b'')
changed: [primary] => {
"changed": true,
"cmd": [
"docker",
"exec",
"rabbitmq",
"rabbitmqctl",
"await_online_nodes",
"1"
],
"delta": "0:00:01.026791",
"end": "2023-05-31 08:38:55.361555",
"invocation": {
"module_args": {
"_raw_params": "docker exec rabbitmq rabbitmqctl await_online_nodes 1",
"_uses_shell": false,
"argv": null,
"chdir": null,
"creates": null,
"executable": null,
"removes": null,
"stdin": null,
"stdin_add_newline": true,
"strip_empty_ends": true,
"warn": false
}
},
"msg": "",
"rc": 0,
"start": "2023-05-31 08:38:54.334764",
"stderr": "",
"stderr_lines": [],
"stdout": "Will wait for at least 1 nodes to join the cluster of rabbit@primary. Timeout: 300 seconds.",
"stdout_lines": [
"Will wait for at least 1 nodes to join the cluster of rabbit@primary. Timeout: 300 seconds."
]
}

RUNNING HANDLER [rabbitmq : Put RabbitMQ node into maintenance mode] ***********
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:25
Using module file /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/library/kolla_toolbox.py
Pipelining is enabled.
<104.239.175.253> ESTABLISH SSH CONNECTION FOR USER: None
<104.239.175.253> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/home/zuul/.ansible/cp/e5079ac827"' 104.239.175.253 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-btpulgoxfxiotaxtuqolvyjgfrtkoswp ; /usr/bin/python3'"'"'"'"'"'"'"'"' && sleep 0'"'"''
Escalation succeeded
<104.239.175.253> (0, b'\n{"action": "community.rabbitmq.rabbitmq_upgrade", "changed": false, "cmd": "/usr/sbin/rabbitmq-upgrade drain -n rabbit", "failed": true, "invocation": {"module_args": {"action": "drain", "node": "rabbit"}}, "msg": "\n08:39:00.940 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :\"-local_listener_fold_fun/1-fun-0-\", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}", "rc": 69, "stderr": "\n08:39:00.940 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :\"-local_listener_fold_fun/1-fun-0-\", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}\n", "stderr_lines": ["", "08:39:00.940 [warning] This node is being put into maintenance (drain) mode", "Error:", "{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :\"-local_listener_fold_fun/1-fun-0-\", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}"], "stdout": "Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!\n", "stdout_lines": ["Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!"]}\n', b'')
fatal: [primary]: FAILED! => {
"action": "community.rabbitmq.rabbitmq_upgrade",
"changed": false,
"cmd": "/usr/sbin/rabbitmq-upgrade drain -n rabbit",
"invocation": {
"module_args": {
"action": "drain",
"node": "rabbit"
}
},
"msg": "\n08:39:00.940 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :"-local_listener_fold_fun/1-fun-0-", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}",
"rc": 69,
"stderr": "\n08:39:00.940 [warning] This node is being put into maintenance (drain) mode\nError:\n{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :"-local_listener_fold_fun/1-fun-0-", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}\n",
"stderr_lines": [
"",
"08:39:00.940 [warning] This node is being put into maintenance (drain) mode",
"Error:",
"{:badarg, [{:ets, :lookup_element, [:ranch_server, {:listener_sup, {:acceptor, {192, 0, 2, 1}, 15672}}, 2], [error_info: %{cause: :badkey, module: :erl_stdlib_errors}]}, {:ranch_server, :get_listener_sup, 1, [file: 'src/ranch_server.erl', line: 122]}, {:ranch, :get_status, 1, [file: 'src/ranch.erl', line: 353]}, {:ranch, :suspend_listener, 1, [file: 'src/ranch.erl', line: 209]}, {:rabbit_maintenance, :"-local_listener_fold_fun/1-fun-0-", 3, [file: 'rabbit_maintenance.erl', line: 370]}, {:lists, :foldl, 3, [file: 'lists.erl', line: 1350]}, {:rabbit_maintenance, :suspend_all_client_listeners, 0, [file: 'rabbit_maintenance.erl', line: 212]}, {:rabbit_maintenance, :drain, 0, [file: 'rabbit_maintenance.erl', line: 95]}]}"
],
"stdout": "Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!\n",
"stdout_lines": [
"Will put node rabbit@primary into maintenance mode. The node will no longer serve any client traffic!"
]
}

RUNNING HANDLER [rabbitmq : Restart rabbitmq container] ************************
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:35

RUNNING HANDLER [rabbitmq : Waiting for rabbitmq to start] *********************
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:50

RUNNING HANDLER [rabbitmq : Restart remaining rabbitmq containers] *************
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/handlers/main.yml:16
META: ran handlers

NO MORE HOSTS LEFT *************************************************************

PLAY RECAP *********************************************************************
primary : ok=117 changed=17 unreachable=0 failed=1 skipped=106 rescued=0 ignored=0 `

[mnasiadka]

These are the configs that we use:
https://0efb01d52986d97b758b-f2a50e6f05df4b0e5be60c7b98112049.ssl.cf1.rackcdn.com/884759/6/check/kolla-ansible-centos9s/42010bc/primary/logs/kolla_configs/rabbitmq/index.html

[mnasiadka]

And these are rabbitmq logs: https://0efb01d52986d97b758b-f2a50e6f05df4b0e5be60c7b98112049.ssl.cf1.rackcdn.com/884759/6/check/kolla-ansible-centos9s/42010bc/primary/logs/kolla/rabbitmq/index.html

[mnasiadka]

It's still interesting that on 3.11.16 it doesn't behave that way, and breaks on 3.11.17

[michaelklishin]

I cannot reproduce and do not see any relevant changes in 3.11.17.

After the node boots, what is the output of

rabbitmq-diagnostics listeners

[mnasiadka]

RUNNING HANDLER [rabbitmq : Print listeners] ***********************************
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:25
Using module file /home/zuul/kolla-ansible-venv/lib/python3.9/site-packages/ansible/modules/command.py
Pipelining is enabled.
<172.99.69.77> ESTABLISH SSH CONNECTION FOR USER: None
<172.99.69.77> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/home/zuul/.ansible/cp/88c799d022"' 172.99.69.77 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-txonpmfmouqfrhahbacoqguchsmhwjuv ; /usr/bin/python3'"'"'"'"'"'"'"'"' && sleep 0'"'"''
Escalation succeeded
<172.99.69.77> (0, b'\n{"changed": true, "stdout": "Asking node rabbit@primary to report its protocol listeners ...\nInterface: 192.0.2.1, port: 15672, protocol: http, purpose: HTTP API\nInterface: 192.0.2.1, port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication\nInterface: 192.0.2.1, port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS", "stderr": "", "rc": 0, "cmd": ["docker", "exec", "rabbitmq", "rabbitmq-diagnostics", "listeners"], "start": "2023-05-31 13:01:31.674850", "end": "2023-05-31 13:01:32.715027", "delta": "0:00:01.040177", "msg": "", "invocation": {"module_args": {"_raw_params": "docker exec rabbitmq rabbitmq-diagnostics listeners", "_uses_shell": false, "warn": false, "stdin_add_newline": true, "strip_empty_ends": true, "argv": null, "chdir": null, "executable": null, "creates": null, "removes": null, "stdin": null}}}\n', b'')
changed: [primary] => {
"changed": true,
"cmd": [
"docker",
"exec",
"rabbitmq",
"rabbitmq-diagnostics",
"listeners"
],
"delta": "0:00:01.040177",
"end": "2023-05-31 13:01:32.715027",
"invocation": {
"module_args": {
"_raw_params": "docker exec rabbitmq rabbitmq-diagnostics listeners",
"_uses_shell": false,
"argv": null,
"chdir": null,
"creates": null,
"executable": null,
"removes": null,
"stdin": null,
"stdin_add_newline": true,
"strip_empty_ends": true,
"warn": false
}
},
"msg": "",
"rc": 0,
"start": "2023-05-31 13:01:31.674850",
"stderr": "",
"stderr_lines": [],
"stdout": "Asking node rabbit@primary to report its protocol listeners ...\nInterface: 192.0.2.1, port: 15672, protocol: http, purpose: HTTP API\nInterface: 192.0.2.1, port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication\nInterface: 192.0.2.1, port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS",
"stdout_lines": [
"Asking node rabbit@primary to report its protocol listeners ...",
"Interface: 192.0.2.1, port: 15672, protocol: http, purpose: HTTP API",
"Interface: 192.0.2.1, port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication",
"Interface: 192.0.2.1, port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS"
]
}

And then it fails as in previous snippets

[michaelklishin]

So the interface of all listeners is set to 192.0.2.1 (a specific address). There is a relevant change in 3.11.17 (#8242), I'll try to reproduce again.

[mnasiadka]

Well, what is interesting, out of the whole set of jobs that we have (centos9, rocky9, debian bullseye and ubuntu jammy) it didn't fail on centos9 and here's rabbitmq-diagnostics listeners output:

RUNNING HANDLER [rabbitmq : Print listeners] ***********************************
task path: /home/zuul/kolla-ansible-venv/share/kolla-ansible/ansible/roles/rabbitmq/tasks/restart_services.yml:25
Using module file /home/zuul/kolla-ansible-venv/lib64/python3.9/site-packages/ansible/modules/command.py
Pipelining is enabled.
<158.69.66.73> ESTABLISH SSH CONNECTION FOR USER: None
<158.69.66.73> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o StrictHostKeyChecking=no -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o ConnectTimeout=10 -o 'ControlPath="/home/zuul/.ansible/cp/243f4ded01"' 158.69.66.73 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-tlmfmezarvhixfezurnevcsvjxnhidxj ; /usr/bin/python3'"'"'"'"'"'"'"'"' && sleep 0'"'"''
Escalation succeeded
<158.69.66.73> (0, b'\n{"changed": true, "stdout": "Asking node rabbit@primary to report its protocol listeners ...\nInterface: [::], port: 15672, protocol: http, purpose: HTTP API\nInterface: 192.0.2.1, port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication\nInterface: 192.0.2.1, port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS", "stderr": "", "rc": 0, "cmd": ["docker", "exec", "rabbitmq", "rabbitmq-diagnostics", "listeners"], "start": "2023-05-31 12:55:37.500166", "end": "2023-05-31 12:55:38.427461", "delta": "0:00:00.927295", "msg": "", "invocation": {"module_args": {"_raw_params": "docker exec rabbitmq rabbitmq-diagnostics listeners", "_uses_shell": false, "warn": false, "stdin_add_newline": true, "strip_empty_ends": true, "argv": null, "chdir": null, "executable": null, "creates": null, "removes": null, "stdin": null}}}\n', b'')
changed: [primary] => {
"changed": true,
"cmd": [
"docker",
"exec",
"rabbitmq",
"rabbitmq-diagnostics",
"listeners"
],
"delta": "0:00:00.927295",
"end": "2023-05-31 12:55:38.427461",
"invocation": {
"module_args": {
"_raw_params": "docker exec rabbitmq rabbitmq-diagnostics listeners",
"_uses_shell": false,
"argv": null,
"chdir": null,
"creates": null,
"executable": null,
"removes": null,
"stdin": null,
"stdin_add_newline": true,
"strip_empty_ends": true,
"warn": false
}
},
"msg": "",
"rc": 0,
"start": "2023-05-31 12:55:37.500166",
"stderr": "",
"stderr_lines": [],
"stdout": "Asking node rabbit@primary to report its protocol listeners ...\nInterface: [::], port: 15672, protocol: http, purpose: HTTP API\nInterface: 192.0.2.1, port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication\nInterface: 192.0.2.1, port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS",
"stdout_lines": [
"Asking node rabbit@primary to report its protocol listeners ...",
"Interface: [::], port: 15672, protocol: http, purpose: HTTP API",
"Interface: 192.0.2.1, port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication",
"Interface: 192.0.2.1, port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS"
]
}

[mnasiadka]

Ah, centos9 is pinned to 3.11.16 - that's why it works

[michaelklishin]

After inspecting the function in question I so far fail to see what could have changed in 3.11.17 to make Ranch fail to access its ETS table. The function was last updated three years ago.

We'll need to collect the list of ETS tables on the node. I will put together a rabbitmqctl eval to do that later.

Also, this happens in Docker, and I am trying this in a host OS.

[michaelklishin]

@mnasiadka when the node boots, what does

rabbitmqctl eval '[ets:info(T) || T <- ets:all()].' --formatter pretty_table

output? (please redirect the output to a file and attach the file here, it can be several pages long)

[michaelklishin]

Another experiment, please: if you remove the 2:2 (or replace it with 4:4) from your VM flag list, does it make any difference? The node I am trying with has access to 10 cores.

[michaelklishin]

Perhaps

rabbitmqctl eval '[ets:info(T) || T <- ets:all()].' --formatter pretty_table

would be easier to read formatting-wise, I've updated my comment above accordingly :)

[michaelklishin]

and one more:

rabbitmqctl eval 'io:format("~p~n", [ets:tab2list(ranch_server)]).'

that would list all entries in the table that is being queried right before the exception.

[michaelklishin]

I managed to reproduce the issue with the following config file:

management.tcp.ip = 192.168.10.29

listeners.tcp.default = 192.168.10.29:5672
listeners.ssl.default  = 192.168.10.29:5671

ssl_options.cacertfile = /path/to/tls-gen.git/basic/result/ca_certificate.pem
ssl_options.certfile   = /path/to/tls-gen.git/basic/result/server_certificate.pem
ssl_options.keyfile    = /path/to/tls-gen.git/basic/result/server_key.pem

[michaelklishin]

I am pairing on it with @lhoguin.

[michaelklishin]

#8440

[michaelklishin]

Trying to reproduce with 3.12.0-rc.4 now because it would suck to ship 3.12.0 with this known issue :)

[michaelklishin]

Yes, it is affected as well.