RabbitMQ shutdown on noproc reason

[aravindchidambaram]

I am using the RabbitMQ Server 3.9.5
and Erlang 24

2021-11-13 07:16:44.894000+05:30 [info] <0.23125.6> connection <0.23125.6> ([::1]:52350 -> [::1]:5672): user 'guest' authenticated and granted access to vhost '/'
2021-11-13 07:16:44.895000+05:30 [info] <0.23125.6> closing AMQP connection <0.23125.6> ([::1]:52350 -> [::1]:5672, vhost: '/', user: 'guest')
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>     supervisor: {<0.23131.6>,rabbit_channel_sup}
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>     errorContext: shutdown_error
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>     reason: noproc
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>     offender: [{pid,<0.23134.6>},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                {id,channel},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                {mfargs,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                    {rabbit_channel,start_link,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                        [1,<0.23125.6>,<0.23132.6>,<0.23125.6>,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                         <<"[::1]:52350 -> [::1]:5672">>,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                         rabbit_framing_amqp_0_9_1,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                         {user,<<"guest">>,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                             [administrator],
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                             [{rabbit_auth_backend_internal,none}]},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                         <<"/">>,
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                         [{<<"publisher_confirms">>,bool,true},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                          {<<"exchange_exchange_bindings">>,bool,true},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                          {<<"basic.nack">>,bool,true},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                          {<<"consumer_cancel_notify">>,bool,true},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                          {<<"connection.blocked">>,bool,true},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                          {<<"authentication_failure_close">>,bool,true}],
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                         <0.23126.6>,<0.23133.6>]}},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                {restart_type,intrinsic},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                {shutdown,70000},
2021-11-13 07:16:44.896000+05:30 [error] <0.23131.6>                {child_type,worker}]
2021-11-13 07:16:48.397000+05:30 [info] <0.23144.6> accepting AMQP connection <0.23144.6> ([::1]:52351 -> [::1]:5672)

[lhoguin]

You can ignore it. This will be gone once supervisor2 has been brought up to date with supervisor.

[JamesTGrant]

Here's a nice BASH and Python harness which can be used to show the problem relably.
Running the first /tmp/pyfun - which has the release(), never causes RabbitMQ server process crash.
Running the 2nd /tmp/pyfun - which causes the RabbitMQ server to do the disconnection due to the client TCP socket closure regularly causes RabbitMQ server process crashes. Within an hour I'd expect to see two or three.

#!/bin/bash

#This is BASH

#this does not show the problem, RabbitMQ client disconnects nicely
cat << EOF > /tmp/pyfun
from kombu import Connection
import time
server_url = "amqp://guest:guest@rabbitmq-ha:5672/?heartbeat=30"
c1 = Connection(server_url)
c2 = Connection(server_url)
c1.connect()
c2.connect()
time.sleep(30)
c1.release()
c2.release()
exit()
EOF

#this does show the problem, RabbitMQ client connection closed at TCP layer, RabbitMQ closes coresponding connection
cat << EOF > /tmp/pyfun
from kombu import Connection
import time
server_url = "amqp://guest:guest@rabbitmq-ha:5672/?heartbeat=30"
c1 = Connection(server_url)
c2 = Connection(server_url)
c1.connect()
c2.connect()
time.sleep(30)
exit()
EOF

while true; do
/bin/python3 /tmp/pyfun
sleep 30
done

[JamesTGrant]

@michaelklishin @lukebakken I hope you are both well. I'm happy that I've provided a pathological test harness (see code above) to show the issue in any current RabbitMQ cluster of one or more nodes. I think the problem is real and can lead to messages getting lost from the system - and I think we agree the problem is within RabbitMQ/Erlang. Whilst I can mitigate the likelyhood of provoking this bug in my systems by improving client behaviour, I can not prevent this occuring as cluster degridation lifecycle events will cause the RabbitMQ/Server to exercise this (sometimes errant) functionality. Are you happy to acknowledge this is a bug and, if so is there a way I can track it? Kindest regards and thank you.

[michaelklishin]

I'm afraid I do not acknowledge that this is a bug in either RabbitMQ or Erlang.

This is a behavior of your client which abruptly terminates. RabbitMQ detects this condition
and closes its end of the connection. This can happen in any realistic
distributed system. I am not sure what your expectations are.

Because abrupt TCP connection closure can be problematic for publishers, there is a protocol
feature and a connection recovery procedure that is provided by some clients or can be
re-created manually in others. This is documented in Publishers guide as well as the guide on consumer acknowledgements and publisher confirms. Your example uses neither of those features,
so data loss is possible. There is nothing RabbitMQ or Erlang cannot do about client
publishers not getting through. RabbitMQ can and does acknowledge publishes it has received
back to the client.

I am not certain that Kombu supports publisher confirms. A few years ago it did not support
a lot of data safety and operational features. It is a client we would highly recommend
against in favor of Pika which does support publisher confirms.

[JamesTGrant]

hi @michaelklishin - thank you for the reply. It is very helpful. My example above is the most simple way to cause the erro log to output the messages that concern me - it is simply a harness to create connections, and have the connections be unexpectedly lost. I am aware that there is no acknowledge/confirm for this example - it's just a simple example to provide the most simple harness to provoke the erro condition.
My question is: The erro logs which sometimes (not every time) appear as a result of the unexpected connection loss. These do not happen on every unexpected TCP connection closure. Some of these logs appear to be process crashes, it's these occasional crashes which I'm suggesting are a bug. (https://github.com/rabbitmq/rabbitmq-server/files/9018744/rabbitmqProcesscrashOnClosingConnection.txt) for example:

2022-06-30 08:09:27.726750+00:00 [warn] <0.27844.233> client unexpectedly closed TCP connection
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>     supervisor: {<0.27837.233>,rabbit_channel_sup_sup}
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>     errorContext: shutdown_error
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>     reason: shutdown
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>     offender: [{nb_children,1},
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>                {id,channel_sup},
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>                {mfargs,{rabbit_channel_sup,start_link,[]}},
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>                {restart_type,temporary},
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>                {shutdown,infinity},
2022-06-30 08:09:27.727405+00:00 [erro] <0.27837.233>                {child_type,supervisor}]

2022-06-30 08:19:27.719969+00:00 [warn] <0.28670.233> client unexpectedly closed TCP connection
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>     supervisor: {<0.28938.233>,rabbit_channel_sup}
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>     errorContext: shutdown_error
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>     reason: noproc
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>     offender: [{pid,<0.28954.233>},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                {id,channel},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                {mfargs,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                    {rabbit_channel,start_link,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                        [1,<0.28670.233>,<0.28940.233>,<0.28670.233>,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                         <<"10.1.0.15:29267 -> 10.4.0.15:5672">>,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                         rabbit_framing_amqp_0_9_1,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                         {user,<<"guest">>,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                             [administrator],
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                             [{rabbit_auth_backend_internal,none}]},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                         <<"/">>,
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                         [{<<"authentication_failure_close">>,bool,true},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                          {<<"basic.nack">>,bool,true},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                          {<<"connection.blocked">>,bool,false},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                          {<<"consumer_cancel_notify">>,bool,true},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                          {<<"publisher_confirms">>,bool,true}],
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                         <0.28929.233>,<0.28943.233>]}},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                {restart_type,intrinsic},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                {shutdown,70000},
2022-06-30 08:19:27.720494+00:00 [erro] <0.28938.233>                {child_type,worker}]

[michaelklishin]

Yes, getting rid of this error report (logged by the runtime) makes sense. We have a couple of ideas, it's not a matter of removing a log line in our own code, unfortunately. We will have to port some Erlang 24 changes to one of our bundled modules.

[aravindchidambaram]

But the port 15672 is not listening when I run the rabbitmq-diagnostics status command and so for same, I couldn't able to access my management dashboard at localhost:15672

[michaelklishin]

I will convert this issue to a GitHub discussion. Currently GitHub will automatically close and lock the issue even though your question will be transferred and responded to elsewhere. This is to let you know that we do not intend to ignore this but this is how the current GitHub conversion mechanism makes it seem for the users :(

[michaelklishin]

@aravindchidambaram the exception you have shared happened when a connection was closed. There is also evidence of a connection being accepted at the end of the log.

We have no evidence of this exception being connected to any rabbitmq-diagnostics output at all but [port 15672 is not used for AMQP 0-9-1/AMQP 1.0 connections](От меня немного отстал саппорт, сейчас опишу, как прошла туристическая часть моего дня) which you are looking at in the log. It is used by the HTTP API and management UI that must be enabled via a plugin.

[jipock-morgan]

I see this hasn't been officially answered yet. I was experiencing this very error message yesterday on our development server and after a change in a custom library, the error stopped happening. The problem was frequent, yet intermittent. When it occurred, RabbitMQ's log had similar entries.

TL;DR:
Make sure you don't have some sort of other functions / processes that are closing the connection on your end when they shouldn't be.

Versions:
RabbitMQ version: 3.11.2
Erlang 25.0.2
RabbitMQ.Client (for .NET 6 project): 6.4.0

We have a more developer-friendly wrapper library over the RabbitMQ.Client, which is built to add logging and be a little more friendly to developers when consuming / publishing to RabbitMQ. The issue for me was that this wrapper library was clearing connection / channel objects prior to creating a RabbitMQ consumer. Ordinarily, this should be a problem, since it the first time it is run, there shouldn't be any connection / channels present yet. But, in an application using this library, it was making both channel / connections in another thread. The wrapper library does not use static functions or singletons, so I don't know why this would happen (I haven't checked the RabbitMQ.Client source code yet), but taking out this connection clearing routine fixed the issue. There also are not lingering connections either, so it turned out to be entirely unnecessary.

Error log

2022-11-28 16:05:03.275000-05:00 [warning] <0.11737.35> closing AMQP connection <0.11737.35> (10.242.193.206:64722 -> 10.142.231.1:5671 - VM-DEVMACHINE - Virtual Host: cache - Exchange: cache.resources, vhost: 'cache', user: 'cache_user'):
2022-11-28 16:05:03.275000-05:00 [warning] <0.11737.35> client unexpectedly closed TCP connection
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>     supervisor: {<0.11743.35>,rabbit_channel_sup}
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>     errorContext: shutdown_error
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>     reason: noproc
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>     offender: [{pid,<0.11746.35>},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                {id,channel},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                {mfargs,
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                    {rabbit_channel,start_link,
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                        [1,<0.11737.35>,<0.11740.35>,<0.11737.35>,
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                         <<"10.242.193.1:64722 -> 10.142.231.1:5671">>,
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                         rabbit_framing_amqp_0_9_1,
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                         {user,<<"cache_user">>,[],
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                             [{rabbit_auth_backend_internal,none}]},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                         <<"cache">>,
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                         [{<<"publisher_confirms">>,bool,true},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                          {<<"exchange_exchange_bindings">>,bool,true},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                          {<<"basic.nack">>,bool,true},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                          {<<"consumer_cancel_notify">>,bool,true},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                          {<<"connection.blocked">>,bool,true},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                          {<<"authentication_failure_close">>,bool,true}],
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                         <0.11738.35>,<0.11745.35>]}},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                {restart_type,intrinsic},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                {shutdown,70000},
2022-11-28 16:05:03.275000-05:00 [error] <0.11743.35>                {child_type,worker}]

[lukebakken]

This is the relevant message:

client unexpectedly closed TCP connection

Which, is exactly what your client did 😄 It must not be closing / disposing of RabbitMQ.Client objects correctly.

Also, check out how I re-formatted the error log you provided.

[jipock-morgan]

Yep - Thank you for the tip. I'll have to remember the details / summary tags.

Perhaps your reply and my TL;DR might save someone some needless debugging in the future.