Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host

[Doru Popa]

Hi!

I'm getting this error on a win2019 server machine:

I'm using RabbitMQ 3.9.14 on Erlang 24.3.3

any hints on what is wrong?

2023-04-25 08:52:08.097 -04:00 [Fatal] A fatal exception was encountered during startup.
Waters.MessageBus.MessagingCommunicationException: Connection to the Message Bus could not be established.
 ---> RabbitMQ.Client.Exceptions.BrokerUnreachableException: None of the specified endpoints were reachable
 ---> System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
 ---> System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.BinaryWriter.Write(Byte[] buffer)
   at RabbitMQ.Client.Impl.SocketFrameHandler.Write(Byte[] buffer)
   at RabbitMQ.Client.Impl.SocketFrameHandler.SendHeader()
   at RabbitMQ.Client.Framing.Impl.Connection.StartAndTune()
   at RabbitMQ.Client.Framing.Impl.Connection.Open(Boolean insist)
   at RabbitMQ.Client.Framing.Impl.Connection..ctor(IConnectionFactory factory, Boolean insist, IFrameHandler frameHandler, String clientProvidedName)
   at RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.Init(IFrameHandler fh)
   at RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.Init(IEndpointResolver endpoints)
   at RabbitMQ.Client.ConnectionFactory.CreateConnection(IEndpointResolver endpointResolver, String clientProvidedName)
   --- End of inner exception stack trace ---
   at RabbitMQ.Client.ConnectionFactory.CreateConnection(IEndpointResolver endpointResolver, String clientProvidedName)
   at RabbitMQ.Client.ConnectionFactory.CreateConnection()
   at Waters.MessageBus.RabbitMq.RabbitMqConnector.EstablishConnection()
   at Waters.MessageBus.RabbitMq.RabbitMqTopicReceiver..ctor(String topicName, String topicFilter)
   at Waters.MessageBus.RabbitMq.RabbitMqBusfactory.CreateTopicReceiver(String topic, String topicFilter)
   --- End of inner exception stack trace ---
   at Waters.MessageBus.RabbitMq.RabbitMqBusfactory.CreateTopicReceiver(String topic, String topicFilter)
   at Waters.Lindisfarne.Acquisition.AcquisitionMessageReceiver.Receive(Func`2 action)
   at Waters.Biopharm.Web.Services.Acquisition.AcquisitionCompletedHandler.StartListening()
   at Waters.Biopharm.Web.Program.StartMessageHandlers(IWebHost host)
   at Waters.Biopharm.Web.Program.Main(String[] args)

in the rabbitmq logs i have this error:

2023-04-25 08:52:03.080000-04:00 [info] <0.26378.26> accepting AMQP connection <0.26378.26> ([::1]:61817 -> [::1]:5671)
2023-04-25 08:52:03.080000-04:00 [error] <0.26378.26> closing AMQP connection <0.26378.26> ([::1]:61817 -> [::1]:5671):
2023-04-25 08:52:03.080000-04:00 [error] <0.26378.26> {handshake_timeout,handshake}
2023-04-25 08:52:09.018000-04:00 [warning] <0.26275.26> closing AMQP connection <0.26275.26> ([::1]:61804 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 08:52:09.018000-04:00 [warning] <0.26275.26> client unexpectedly closed TCP connection
2023-04-25 08:52:09.018000-04:00 [warning] <0.26291.26> closing AMQP connection <0.26291.26> ([::1]:61805 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 08:52:09.018000-04:00 [warning] <0.26291.26> client unexpectedly closed TCP connection
2023-04-25 08:52:09.018000-04:00 [warning] <0.26329.26> closing AMQP connection <0.26329.26> ([::1]:61807 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 08:52:09.018000-04:00 [warning] <0.26329.26> client unexpectedly closed TCP connection
2023-04-25 08:52:09.018000-04:00 [warning] <0.26313.26> closing AMQP connection <0.26313.26> ([::1]:61806 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 08:52:09.018000-04:00 [warning] <0.26313.26> client unexpectedly closed TCP connection
2023-04-25 08:52:09.018000-04:00 [warning] <0.26345.26> closing AMQP connection <0.26345.26> ([::1]:61808 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 08:52:09.018000-04:00 [warning] <0.26345.26> client unexpectedly closed TCP connection

[Michal Kuratczyk]

Since both sides believe the other one did something unexpected, my first guess would be some firewall / intrusion detection system that misidentifies this connections attempt as suspicious and terminates it.

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/2beca425-9471-4d44-98fa-89bd31982e05n%40googlegroups.com.

--

Michał

RabbitMQ team

[Doru Popa]

and the ports blocked would be this ones? 5672 and 5671?

2023-03-07 10:54:09.937000-05:00 [info] <0.505.0> Ready to start client connection listeners
2023-03-07 10:54:09.937000-05:00 [info] <0.620.0> started TCP listener on [::]:5672
2023-03-07 10:54:09.937000-05:00 [info] <0.638.0> started TCP listener on 0.0.0.0:5672
2023-03-07 10:54:09.937000-05:00 [info] <0.658.0> started TLS (SSL) listener on [::]:5671
2023-03-07 10:54:09.937000-05:00 [info] <0.678.0> started TLS (SSL) listener on 0.0.0.0:5671
2023-03-07 10:54:10.046000-05:00 [info] <0.505.0> Server startup complete; 4 plugins started.
2023-03-07 10:54:10.046000-05:00 [info] <0.505.0>  * rabbitmq_auth_mechanism_ssl
2023-03-07 10:54:10.046000-05:00 [info] <0.505.0>  * rabbitmq_management
2023-03-07 10:54:10.046000-05:00 [info] <0.505.0>  * rabbitmq_web_dispatch
2023-03-07 10:54:10.046000-05:00 [info] <0.505.0>  * rabbitmq_management_agent
...

[Doru Popa]

I found also in the log error's like this:

2023-04-25 07:05:24.462000-04:00 [warning] <0.12659.26> closing AMQP connection <0.12659.26> ([::1]:51149 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 07:05:24.462000-04:00 [warning] <0.12659.26> client unexpectedly closed TCP connection
2023-04-25 07:05:24.462000-04:00 [warning] <0.12643.26> closing AMQP connection <0.12643.26> ([::1]:51148 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 07:05:24.462000-04:00 [warning] <0.12643.26> client unexpectedly closed TCP connection
2023-04-25 07:05:24.462000-04:00 [warning] <0.12621.26> closing AMQP connection <0.12621.26> ([::1]:51147 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 07:05:24.462000-04:00 [warning] <0.12621.26> client unexpectedly closed TCP connection
2023-04-25 07:05:24.462000-04:00 [warning] <0.12675.26> closing AMQP connection <0.12675.26> ([::1]:51150 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 07:05:24.462000-04:00 [warning] <0.12675.26> client unexpectedly closed TCP connection
2023-04-25 07:05:24.462000-04:00 [warning] <0.12605.26> closing AMQP connection <0.12605.26> ([::1]:51146 -> [::1]:5671, vhost: '/', user: 'unifi_mq_user'):
2023-04-25 07:05:24.462000-04:00 [warning] <0.12605.26> client unexpectedly closed TCP connection
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>     supervisor: {<0.12665.26>,rabbit_channel_sup}
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>     errorContext: shutdown_error
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>     reason: noproc
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>     offender: [{pid,<0.12668.26>},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                {id,channel},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                {mfargs,
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                    {rabbit_channel,start_link,
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                        [1,<0.12659.26>,<0.12666.26>,<0.12659.26>,
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                         <<"[::1]:51149 -> [::1]:5671">>,
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                         rabbit_framing_amqp_0_9_1,
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                         {user,<<"unifi_mq_user">>,[],
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                             [{rabbit_auth_backend_internal,none}]},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                         <<"/">>,
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                         [{<<"publisher_confirms">>,bool,true},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                          {<<"exchange_exchange_bindings">>,bool,true},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                          {<<"basic.nack">>,bool,true},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                          {<<"consumer_cancel_notify">>,bool,true},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                          {<<"connection.blocked">>,bool,true},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                          {<<"authentication_failure_close">>,bool,true}],
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                         <0.12660.26>,<0.12667.26>]}},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                {restart_type,intrinsic},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                {shutdown,70000},
2023-04-25 07:05:24.463000-04:00 [error] <0.12665.26>                {child_type,worker}]
2023-04-25 07:06:35.732000-04:00 [info] <0.12784.26> accepting AMQP connection <0.12784.26> ([::1]:51247 -> [::1]:5671)
2023-04-25 07:06:35.732000-04:00 [error] <0.12784.26> closing AMQP connection <0.12784.26> ([::1]:51247 -> [::1]:5671):
2023-04-25 07:06:35.732000-04:00 [error] <0.12784.26> {handshake_timeout,handshake}
2023-04-25 07:06:40.737000-04:00 [info] <0.12804.26> accepting AMQP connection <0.12804.26> ([::1]:51292 -> [::1]:5671)
2023-04-25 07:06:40.769000-04:00 [info] <0.12804.26> connection <0.12804.26> ([::1]:51292 -> [::1]:5671): user 'unifi_mq_user' authenticated and granted access to vhost '/'
2023-04-25 07:06:40.800000-04:00 [info] <0.12820.26> accepting AMQP connection <0.12820.26> ([::1]:51293 -> [::1]:5671)
2023-04-25 07:06:40.800000-04:00 [info] <0.12820.26> connection <0.12820.26> ([::1]:51293 -> [::1]:5671): user 'unifi_mq_user' authenticated and granted access to vhost '/'
2023-04-25 07:06:40.816000-04:00 [info] <0.12842.26> accepting AMQP connection <0.12842.26> ([::1]:51294 -> [::1]:5671)
2023-04-25 07:06:40.831000-04:00 [info] <0.12842.26> connection <0.12842.26> ([::1]:51294 -> [::1]:5671): user 'unifi_mq_user' authenticated and granted access to vhost '/'
2023-04-25 07:06:40.847000-04:00 [info] <0.12858.26> accepting AMQP connection <0.12858.26> ([::1]:51295 -> [::1]:5671)
2023-04-25 07:06:40.847000-04:00 [info] <0.12858.26> connection <0.12858.26> ([::1]:51295 -> [::1]:5671): user 'unifi_mq_user' authenticated and granted access to vhost '/'
2023-04-25 07:06:40.865000-04:00 [info] <0.12874.26> accepting AMQP connection <0.12874.26> ([::1]:51296 -> [::1]:5671)
2023-04-25 07:06:40.869000-04:00 [info] <0.12874.26> connection <0.12874.26> ([::1]:51296 -> [::1]:5671): user 'unifi_mq_user' authenticated and granted access to vhost '/'

[Michal Kuratczyk]

That error is just noise. Yes, 5671 is the AMQP port of the connections. 

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/d1a7c29b-b870-4800-a262-f14aacf1a224n%40googlegroups.com.

--

Michał

RabbitMQ team

[Doru Popa]

I've block the port 5671 with firewall exceptions, but I can't reproduce the error;

2 more details about the machine were the error occur:

1. it has no internet connection

2. we use our own certificate for rabbitmq and this settings

                        {fail_if_no_peer_cert,true},
                        {verify,verify_peer}]},
          {ssl_listeners,[5671]},
  {consumer_timeout, undefined},
          {auth_mechanisms,['EXTERNAL','AMQPLAIN','PLAIN']}]}].

could ssl/tls configuration causing this issue?

thx for you support!

[Michal Kuratczyk]

I didn't notice this before but yes, {handshake_timeout,handshake} would suggest a TLS timeout. I don't know what could cause this.

I'd probably start with tcpdump/wireshark to see what's going over the network.

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/583b3224-d3d4-40b4-a849-04b754627c86n%40googlegroups.com.

--

Michał

RabbitMQ team

[Doru Popa]

are there any log's that I can grab from rabbitmq that will help me troubleshoot this issue?

[Michal Kuratczyk]

You can set debug logging level to perhaps get something more but I doubt it.

We spoke about two log lines - a time out and a TCP connection reset. In either case, there is not much

RabbitMQ can log about it - it just didn't receive anything (time out) or received a "I don't want to talk to you"

packet (TCP connection reset).

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/9579db70-23f8-45a6-a5c1-ed398bdcb428n%40googlegroups.com.

--

Michał

RabbitMQ team