3.11.12 error,badarg,'connection.open'

[mnasiadka]

Describe the bug

Since 3.11.12 was release - OpenStack Kolla upstream CI is failing with clients connection to RabbitMQ.

Error seen in rabbitmq logs:
2023-03-31 06:55:53.743686+00:00 [info] <0.1773.0> accepting AMQP connection <0.1773.0> (192.0.2.1:37930 -> 192.0.2.1:5671)
2023-03-31 06:55:53.745159+00:00 [info] <0.1773.0> connection <0.1773.0> (192.0.2.1:37930 -> 192.0.2.1:5671) has a client-provided name: nova-compute:7:b0433a5a-b2e5-4a6c-ab35-a094c2324377
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> closing AMQP connection <0.1764.0> (192.0.2.1:37922 -> 192.0.2.1:5671 - nova-scheduler:7:b9262bd9-0796-4970-a94a-7860894d2048):
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {handshake_error,opening,0,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {error,badarg,'connection.open',
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{ets,lookup_element,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [ranch_server,{listener_sup,{acceptor,{0,0,0,0,0,0,0,0},5671}},2],
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{error_info,#{cause => badkey,module => erl_stdlib_errors}}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {ranch_server,get_listener_sup,1,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{file,"src/ranch_server.erl"},{line,122}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {ranch,info,1,[{file,"src/ranch.erl"},{line,434}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {rabbit_reader,is_over_node_connection_limit,1,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{file,"rabbit_reader.erl"},{line,1329}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {rabbit_reader,handle_method0,2,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{file,"rabbit_reader.erl"},{line,1225}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {rabbit_reader,handle_method0,3,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{file,"rabbit_reader.erl"},{line,1128}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {rabbit_reader,handle_input,3,
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> [{file,"rabbit_reader.erl"},{line,1042}]},
2023-03-31 06:55:56.391423+00:00 [error] <0.1764.0> {rabbit_reader,recvloop,4,[{file,"rabbit_reader.erl"},{line,472}]}]}}

CI rabbitmq logs: https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_7b7/878209/21/check/kolla-ansible-rocky9/7b7d31f/primary/logs/kolla/rabbitmq/rabbit%40primary.txt

CI client service logs:
https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_7b7/878209/21/check/kolla-ansible-rocky9/7b7d31f/primary/logs/kolla/nova/nova-compute.txt

CI RabbitMQ config:
https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_7b7/878209/21/check/kolla-ansible-rocky9/7b7d31f/primary/logs/kolla_configs/rabbitmq/index.html

Reproduction steps

1. Deploy OpenStack using kolla-ansible with RabbitMQ 3.11.12

...

Expected behavior

Working.

Additional context

No response

[michaelklishin]

I'm afraid deploying OpenStack is not a reproduction step because there are hundreds of possible variables involved.

[michaelklishin]

We need some information about the client: what it is, what version is used, you haven't mentioned that TLS is involved (it can be seen from the port), that kind of thing.

But the function in the stack trace is indeed something that was introduced in #7593/#7753. But that's the only thing we can tell. Plenty of client test suites happily pass.

[mnasiadka]

client is OpenStack Nova written in python, using oslo.messaging (OpenStack library for MQ) that is using amqp python library version 5.1.1
Yes, the connection is TLS

[michaelklishin]

listeners.tcp = none
listeners.ssl.1 = 192.0.2.1:5671
cluster_partition_handling = pause_minority

management.listener.ip = 192.0.2.1
management.listener.port = 15672
management.load_definitions = /etc/rabbitmq/definitions.json

cluster_formation.peer_discovery_backend = rabbit_peer_discovery_classic_config
cluster_formation.classic_config.nodes.0 = rabbit@primary

# https://www.rabbitmq.com/ssl.html
ssl_options.certfile = /etc/rabbitmq/certs/rabbitmq-cert.pem
ssl_options.keyfile = /etc/rabbitmq/certs/rabbitmq-key.pem

RABBITMQ_NODENAME=rabbit@primary
RABBITMQ_LOG_BASE=/var/log/kolla/rabbitmq
RABBITMQ_DIST_PORT=25672
RABBITMQ_PID_FILE=/var/lib/rabbitmq/mnesia/rabbitmq.pid
RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS="-kernel inetrc '/etc/rabbitmq/erl_inetrc' +S 2:2 +sbwt none +sbwtdcpu none +sbwtdio none"
RABBITMQ_CTL_ERL_ARGS=""

export ERL_EPMD_ADDRESS=192.0.2.1
export ERL_EPMD_PORT=4369
export ERL_INETRC=/etc/rabbitmq/erl_inetrc

[
  {kernel, [
    {inet_dist_use_interface, {192,0,2,1}},
    {inet_dist_listen_min, 25672},
    {inet_dist_listen_max, 25672}
  ]}
].

[michaelklishin]

Unfortunately I cannot reproduce this exception using the above config.

[michaelklishin]

Wait, I can now but have no idea what exact tweak did it.

[michaelklishin]

@mnasiadka can you please run rabbitmqctl eval 'ets:tab2list(ranch_server).' against one of your RabbitMQ nodes?

[michaelklishin]

Great! Will share them here once the pipeline produces a new alpha release now that #7788 is merged.

[mnasiadka]

ets:tab2list(ranch_server). output:

[{{addr,{acceptor,{192,0,2,1},5671}},{{192,0,2,1},5671}},
{{addr,{acceptor,{0,0,0,0,0,0,0,0},15672}},{{192,0,2,1},15672}},
{{listener_start_args,{acceptor,{192,0,2,1},5671}},
[{acceptor,{192,0,2,1},5671},
ranch_ssl,
#{connection_type => supervisor,handshake_timeout => 5000,
max_connections => infinity,num_acceptors => 10,num_conns_sups => 1,
socket_opts =>
[{ip,{192,0,2,1}},
{port,5671},
inet,
{backlog,128},
{nodelay,true},
{linger,{true,0}},
{exit_on_close,false},
{versions,['tlsv1.3','tlsv1.2','tlsv1.1',tlsv1]},
{keyfile,"/etc/rabbitmq/certs/rabbitmq-key.pem"},
{certfile,"/etc/rabbitmq/certs/rabbitmq-cert.pem"}]},
rabbit_connection_sup,[]]},
{{listener_start_args,{acceptor,{0,0,0,0,0,0,0,0},15672}},
[{acceptor,{0,0,0,0,0,0,0,0},15672},
ranch_tcp,
#{socket_opts => [{ip,{192,0,2,1}},{port,15672}]},
cowboy_clear,
#{env =>
#{rabbit_listener =>
[{cowboy_opts,[{sendfile,false}]},
{ip,"192.0.2.1"},
{port,15672}]},
middlewares => [rabbit_cowboy_middleware,cowboy_router,cowboy_handler],
sendfile => false,
stream_handlers =>
[rabbit_cowboy_stream_h,cowboy_compress_h,cowboy_stream_h]}]},
{{listener_sup,{acceptor,{192,0,2,1},5671}},<12372.882.0>},
{{listener_sup,{acceptor,{0,0,0,0,0,0,0,0},15672}},<12372.847.0>},
{{max_conns,{acceptor,{192,0,2,1},5671}},infinity},
{{max_conns,{acceptor,{0,0,0,0,0,0,0,0},15672}},1024},
{{proto_opts,{acceptor,{192,0,2,1},5671}},[]},
{{proto_opts,{acceptor,{0,0,0,0,0,0,0,0},15672}},
#{env =>
#{rabbit_listener =>
[{cowboy_opts,[{sendfile,false}]},
{ip,"192.0.2.1"},
{port,15672}]},
middlewares => [rabbit_cowboy_middleware,cowboy_router,cowboy_handler],
sendfile => false,
stream_handlers =>
[rabbit_cowboy_stream_h,cowboy_compress_h,cowboy_stream_h]}},
{{stats_counters,{acceptor,{192,0,2,1},5671}},
{atomics,#Ref<12372.1340721260.587857922.187902>}},
{{stats_counters,{acceptor,{0,0,0,0,0,0,0,0},15672}},
{atomics,#Ref<12372.1340721260.587857921.190232>}},
{{trans_opts,{acceptor,{192,0,2,1},5671}},
#{connection_type => supervisor,handshake_timeout => 5000,
max_connections => infinity,num_acceptors => 10,num_conns_sups => 1,
socket_opts =>
[{ip,{192,0,2,1}},
{port,5671},
inet,
{backlog,128},
{nodelay,true},
{linger,{true,0}},
{exit_on_close,false},
{versions,['tlsv1.3','tlsv1.2','tlsv1.1',tlsv1]},
{keyfile,"/etc/rabbitmq/certs/rabbitmq-key.pem"},
{certfile,"/etc/rabbitmq/certs/rabbitmq-cert.pem"}]}},
{{trans_opts,{acceptor,{0,0,0,0,0,0,0,0},15672}},
#{socket_opts => [{ip,{192,0,2,1}},{port,15672}]}},
{{conns_sup,{acceptor,{192,0,2,1},5671},1},<12372.884.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},1},<12372.849.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},2},<12372.850.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},3},<12372.851.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},4},<12372.852.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},5},<12372.853.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},6},<12372.854.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},7},<12372.855.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},8},<12372.856.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},9},<12372.857.0>},
{{conns_sup,{acceptor,{0,0,0,0,0,0,0,0},15672},10},<12372.858.0>}]

[osfrickler]

see https://paste.opendev.org/show/bHLf5Ze68ysz2nU6ZUBO for the output. if you point me to a .deb I can test with that
update: github didn't update and show me that there is already a reply, sorry for the duplicate

[michaelklishin]

Here's an RPM. A Debian package will be uploaded to the same Cloudsmith repo shortly.

[michaelklishin]

OK, all (types of) packages with #7788 included should not be available from this Cloudsmith repo. You can download them and install using dnf or dpkg -i if that'd be more convenient than setting up a repo.

[michaelklishin]

https://github.com/rabbitmq/rabbitmq-server-binaries-dev/releases/tag/v3.11.13-alpha.2 and https://cloudsmith.io/~rabbitmq/repos/rabbitmq-server-dev/packages/ now include alpha packages with #7788. We'll produce a new release as soon as we have a confirmation that the changes does resolve the issue @osfrickler @mnasiadka 🙏

[osfrickler]

I can confirm that https://dl.cloudsmith.io/public/rabbitmq/rabbitmq-server-dev/deb/ubuntu/pool/jammy/main/r/ra/rabbitmq-server_3.11.13~alpha.2-1/rabbitmq-server_3.11.13~alpha.2-1_all.deb fixes the issue for me.

[michaelklishin]

Hooray, thank you! I'll proceed with the release then.

[michaelklishin]

https://github.com/rabbitmq/rabbitmq-server/releases/tag/v3.11.13 is out.