rabbitmqctl shutdown logs errors regards dynamic ssl connections

[dreiucker]

Hello RabbitMQ team,

I'm currently testing RabbitMQ 3.11.x and I'm getting error logs when using rabbitmqctl shutdown. I'm using the standard SSL config with tlsv1.2 and tlsv1.3 and didn't hand any problems on 3.9.x with that configuration.

Question
Can someone reproduce that error when using Erlang 3.11.x + SSL config?
I'm not an Erlang expert so does this kind of harsh shutdown of the tls_sender will created problems or is that something that is okay to be overlooked.

System info
I know we could migrate to 3.11.8 but I haven't seen anything in the release notes regards that SSL error.
RabbitMQ: v3.11.2
Erlang: v25.1.2

Erlang
I had a look through the last Erlang releases and saw an update regard tls_sender and error logs at
https://www.erlang.org/patches/otp-25.2
However, it is not really about closing down channels but about making updates so it may be only a coincidence.

Error logs

2023-02-03 15:07:39.344901+00:00 [info] <0.2770.0> RabbitMQ is asked to stop...
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0> Stopping RabbitMQ applications and their dependencies in the following order:
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_shovel_management
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_management
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_prometheus
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_web_dispatch
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     cowboy
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     cowlib
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_management_agent
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_stomp
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_delayed_message_exchange
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_jms_topic_exchange
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_shovel
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_mqtt
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbit
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbitmq_prelaunch
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     amqp_client
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     rabbit_common
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     prometheus
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     ra
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     accept
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     os_mon
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     sysmon_handler
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     amqp10_client
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     osiris
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>     mnesia
2023-02-03 15:07:39.442347+00:00 [info] <0.2770.0>
2023-02-03 15:07:39.442923+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_shovel_management'
2023-02-03 15:07:39.443188+00:00 [notice] <0.44.0> Application rabbitmq_shovel_management exited with reason: stopped
2023-02-03 15:07:39.443460+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_management'
2023-02-03 15:07:39.451243+00:00 [warning] <0.708.0> HTTP listener registry could not find context rabbitmq_management_tls
2023-02-03 15:07:39.453883+00:00 [notice] <0.44.0> Application rabbitmq_management exited with reason: stopped
2023-02-03 15:07:39.454027+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_prometheus'
2023-02-03 15:07:39.454758+00:00 [warning] <0.708.0> HTTP listener registry could not find context rabbitmq_prometheus_tcp
2023-02-03 15:07:39.460719+00:00 [notice] <0.44.0> Application rabbitmq_prometheus exited with reason: stopped
2023-02-03 15:07:39.460883+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_web_dispatch'
2023-02-03 15:07:39.464151+00:00 [notice] <0.44.0> Application rabbitmq_web_dispatch exited with reason: stopped
2023-02-03 15:07:39.464319+00:00 [info] <0.2770.0> Stopping application 'cowboy'
2023-02-03 15:07:39.467008+00:00 [notice] <0.44.0> Application cowboy exited with reason: stopped
2023-02-03 15:07:39.467139+00:00 [info] <0.2770.0> Stopping application 'cowlib'
2023-02-03 15:07:39.467244+00:00 [notice] <0.44.0> Application cowlib exited with reason: stopped
2023-02-03 15:07:39.467424+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_management_agent'
2023-02-03 15:07:39.470589+00:00 [notice] <0.44.0> Application rabbitmq_management_agent exited with reason: stopped
2023-02-03 15:07:39.470739+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_stomp'
2023-02-03 15:07:39.471323+00:00 [info] <0.791.0> stopped STOMP TLS listener on 0.0.0.0:61614
2023-02-03 15:07:39.473993+00:00 [notice] <0.44.0> Application rabbitmq_stomp exited with reason: stopped
2023-02-03 15:07:39.474122+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_delayed_message_exchange'
2023-02-03 15:07:39.475829+00:00 [notice] <0.44.0> Application rabbitmq_delayed_message_exchange exited with reason: stopped
2023-02-03 15:07:39.475959+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_jms_topic_exchange'
2023-02-03 15:07:39.476067+00:00 [notice] <0.44.0> Application rabbitmq_jms_topic_exchange exited with reason: stopped
2023-02-03 15:07:39.476272+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_shovel'
2023-02-03 15:07:39.479016+00:00 [notice] <0.44.0> Application rabbitmq_shovel exited with reason: stopped
2023-02-03 15:07:39.479154+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_mqtt'
2023-02-03 15:07:39.479725+00:00 [info] <0.831.0> stopped MQTT TLS listener on 0.0.0.0:8883
2023-02-03 15:07:39.482067+00:00 [notice] <0.44.0> Application rabbitmq_mqtt exited with reason: stopped
2023-02-03 15:07:39.482202+00:00 [info] <0.2770.0> Stopping application 'rabbit'
2023-02-03 15:07:39.482762+00:00 [info] <0.251.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping unregistration.
2023-02-03 15:07:39.483016+00:00 [info] <0.901.0> stopped TLS (SSL) listener on 0.0.0.0:5671
2023-02-03 15:07:39.484337+00:00 [info] <0.881.0> stopped TCP listener on 127.0.0.1:5672
2023-02-03 15:07:39.485361+00:00 [info] <0.2772.0> Closing all connections in vhost '/' on node 'rabbitmq@m-1' because the vhost is stopping
2023-02-03 15:07:39.485856+00:00 [info] <0.626.0> Stopping message store for directory '/data/mnesia/rabbitmq@m-1/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent'
2023-02-03 15:07:39.502783+00:00 [info] <0.626.0> Message store for directory '/data/mnesia/rabbitmq@m-1/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent' is stopped
2023-02-03 15:07:39.503490+00:00 [info] <0.622.0> Stopping message store for directory '/data/mnesia/rabbitmq@m-1/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/msg_store_transient'
2023-02-03 15:07:39.510209+00:00 [info] <0.622.0> Message store for directory '/data/mnesia/rabbitmq@m-1/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/msg_store_transient' is stopped
2023-02-03 15:07:39.513689+00:00 [info] <0.569.0> Management plugin: to stop collect_statistics.
2023-02-03 15:07:44.519577+00:00 [notice] <0.44.0> Application rabbit exited with reason: stopped
2023-02-03 15:07:44.519808+00:00 [info] <0.2770.0> Stopping application 'rabbitmq_prelaunch'
2023-02-03 15:07:44.522588+00:00 [notice] <0.44.0> Application rabbitmq_prelaunch exited with reason: stopped
2023-02-03 15:07:44.522798+00:00 [info] <0.2770.0> Stopping application 'amqp_client'
2023-02-03 15:07:44.524995+00:00 [notice] <0.44.0> Application amqp_client exited with reason: stopped
2023-02-03 15:07:44.525132+00:00 [info] <0.2770.0> Stopping application 'rabbit_common'
2023-02-03 15:07:44.525664+00:00 [notice] <0.44.0> Application rabbit_common exited with reason: stopped
2023-02-03 15:07:44.525892+00:00 [info] <0.2770.0> Stopping application 'prometheus'
2023-02-03 15:07:44.527670+00:00 [notice] <0.44.0> Application prometheus exited with reason: stopped
2023-02-03 15:07:44.527949+00:00 [info] <0.2770.0> Stopping application 'ra'
2023-02-03 15:07:44.531782+00:00 [notice] <0.44.0> Application ra exited with reason: stopped
2023-02-03 15:07:44.531926+00:00 [info] <0.2770.0> Stopping application 'accept'
2023-02-03 15:07:44.532067+00:00 [notice] <0.44.0> Application accept exited with reason: stopped
2023-02-03 15:07:44.532280+00:00 [info] <0.2770.0> Stopping application 'os_mon'
2023-02-03 15:07:44.534505+00:00 [notice] <0.44.0> Application os_mon exited with reason: stopped
2023-02-03 15:07:44.534639+00:00 [info] <0.2770.0> Stopping application 'sysmon_handler'
2023-02-03 15:07:44.536366+00:00 [notice] <0.44.0> Application sysmon_handler exited with reason: stopped
2023-02-03 15:07:44.536494+00:00 [info] <0.2770.0> Stopping application 'amqp10_client'
2023-02-03 15:07:44.541517+00:00 [notice] <0.44.0> Application amqp10_client exited with reason: stopped
2023-02-03 15:07:44.541672+00:00 [info] <0.2770.0> Stopping application 'osiris'
2023-02-03 15:07:44.543553+00:00 [notice] <0.44.0> Application osiris exited with reason: stopped
2023-02-03 15:07:44.543691+00:00 [info] <0.2770.0> Stopping application 'mnesia'
2023-02-03 15:07:44.546782+00:00 [notice] <0.44.0> Application mnesia exited with reason: stopped
2023-02-03 15:07:44.546919+00:00 [info] <0.2770.0> Successfully stopped RabbitMQ and its dependencies
Gracefully halting Erlang VM
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0> Halting Erlang VM with the following applications:
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     amqp10_common
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     observer_cli
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     redbug
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     runtime_tools
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     stdout_formatter
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     seshat
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     gen_batch_server
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     aten
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     ranch
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     inets
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     systemd
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     enough
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     cuttlefish
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     credentials_obfuscation
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     recon
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     thoas
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     xmerl
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     tools
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     syntax_tools
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     ssl
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     public_key
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     asn1
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     crypto
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     compiler
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     sasl
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     stdlib
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>     kernel
2023-02-03 15:07:44.547399+00:00 [info] <0.2770.0>
2023-02-03 15:07:44.563827+00:00 [warning] <0.179.0> TLS distribution: unexpected message: {'EXIT',<0.178.0>,shutdown}
2023-02-03 15:07:44.563827+00:00 [warning] <0.179.0>
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>     supervisor: {<0.260.0>,tls_dyn_connection_sup}
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>     errorContext: child_terminated
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>     reason: killed
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>     offender: [{pid,<0.262.0>},
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>                {id,sender},
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>                {mfargs,{tls_sender,start_link,undefined}},
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>                {restart_type,temporary},
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>                {significant,false},
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>                {shutdown,5000},
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>                {child_type,worker}]
2023-02-03 15:07:44.565551+00:00 [error] <0.260.0>
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>     supervisor: {<0.259.0>,tls_dyn_connection_sup}
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>     errorContext: child_terminated
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>     reason: killed
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>     offender: [{pid,<0.261.0>},
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>                {id,sender},
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>                {mfargs,{tls_sender,start_link,undefined}},
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>                {restart_type,temporary},
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>                {significant,false},
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>                {shutdown,5000},
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>                {child_type,worker}]
2023-02-03 15:07:44.565746+00:00 [error] <0.259.0>
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>     supervisor: {<0.2756.0>,tls_dyn_connection_sup}
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>     errorContext: child_terminated
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>     reason: killed
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>     offender: [{pid,<0.2757.0>},
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>                {id,sender},
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>                {mfargs,{tls_sender,start_link,undefined}},
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>                {restart_type,temporary},
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>                {significant,false},
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>                {shutdown,5000},
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>                {child_type,worker}]
2023-02-03 15:07:44.565913+00:00 [error] <0.2756.0>
2023-02-03 15:07:48.225162+00:00 [warning] <0.158.0> TLS distribution: unexpected message: {'EXIT',<0.157.0>,shutdown}
2023-02-03 15:07:48.225162+00:00 [warning] <0.158.0>
2023-02-03 15:07:51.821264+00:00 [notice] <0.44.0> Application syslog exited with reason: stopped

[michaelklishin]

This is a runtime message that complains about an unexpected TLS message on a shutting down connection. tls_sender is a module from Erlang/OTP's TLS implementation.

[dreiucker]

So the answer is more or less that is an Erlang problem and has nothing to do with normal RabbitMQ operation? And I should look for Erlang support at another place.

So it doesn't seem to be impacting RabbitMQ operations from your view?

[michaelklishin]

Yes, that RabbitMQ cannot avoid a warning in an OTP module. Maybe Erlang maintainers would be interested in silencing it but they may argue that such warnings are justified.

[michaelklishin]

If the node is shutting down, warnings on connections that will inevitably stop very soon can be ignored. I don't see an alternative, you don't want to halt node termination (even if you could do that easily) because of one timing-sensitive event on one connection.

[dreiucker]

Ok, that's all what I wanted to know. Thank you.

[lukebakken]

This error can be ignored. It appears that you are using TLS for inter-node communication since I can see TLS distribution in the log. The error message is generated here: https://github.com/erlang/otp/blob/OTP-25.1.2/lib/ssl/src/inet_tls_dist.erl#L248

It seems odd that {'EXIT',<0.178.0>,shutdown} didn't match here, however: https://github.com/erlang/otp/blob/OTP-25.1.2/lib/ssl/src/inet_tls_dist.erl#L243

I'll look into it further and will report it to the Erlang team.

[lukebakken]

erlang/otp#6810

erlang/otp#6810 (comment)