7.0.0-alpha.2 - Unexpected Exception: Unable to read data from the transport connection: Connection reset by peer

[lukebakken]

Discussed in #1463

^{Originally posted by plewam January 7, 2024}
I am currently testing the 7.0.0-alpha.2 release. I have set the AutomaticRecoveryEnabled to true. During the consume of messages from my remote server my VM somehow had it's network connection interrupted for a short period of time. I use all the new async methods.

During this short outage I receive these events from the library. Please not that these are my own logging texts.

1. (Channel) ChannelShutdown
2. (Consumer) ConsumerCancelled
3. (Consumer) Shutdown

RabbitMQ model was shutdown. ReplyText was <"Unexpected Exception: Unable to read data from the transport connection: Connection reset by peer.">

RabbitMQ consumer was cancelled. Consumer tag <"71cd2fcf-0f86-477b-86d6-c9bf0518b51e">

RabbitMQ consumer was shut down. ReplyText <"Unexpected Exception: Unable to read data from the transport connection: Connection reset by peer.">. Initiator <Library>

However I would expect the channel and consumer to automatically recover. Can somebody maybe give me some tips? Or is this issue already known?

[lukebakken]

@plewam thank you for continuing to test the next release of this library. Some questions:

• After the network interruption, your consumer did not resume consuming messages?
• What was logged by RabbitMQ at the same time as the interruption? Log messages from about 5 minutes before and after the interruption would be great. This information will be very valuable, if you have it.

I will work on a test to reproduce this scenario.

[lukebakken]

@plewam - if you have time, please check out my test application in this PR:

https://github.com/rabbitmq/rabbitmq-dotnet-client/pull/1466/files

It sets up a connection for the consumer, and a different one for the publisher.

My test environment is all Windows 11 pro. I start up RabbitMQ 3.12.11 (Erlang 26.2.1) in one terminal window, then I start up a Toxiproxy server in another, and set up a proxy like this:

Start server in one console:

.\toxiproxy-server.exe

Set up proxy in another:

 .\toxiproxy-cli.exe create --listen 55672 --upstream 5672 rmq-localhost

Then, start up the test console application:

.\projects\gh-1464\bin\Debug\net6.0\gh-1464.exe

Let it start publishing and consuming, then abruptly kill and restore the consumer's connection this way:

.\toxiproxy-cli.exe toggle rmq-localhost; Start-Sleep -Seconds 1; .\toxiproxy-cli.exe toggle rmq-localhost

You can see the consumer is eventually restored and consumes the ready messages.

There must be something different in your code, can you share a runnable example?

[plewam]

@lukebakken In regards to your questions:

1. The consumer did not continue consuming messages
2. I collected the logs from the rabbitmq server, however its not that much, see below (The last two entries should be the ones you are looking for. Generally the connections is relatively unstable)

BTW: The rmq server I connected to has version 3.11.8 and erlang 25.2.2. I can upgrade it if you want.

Logs

2024-01-07 01:05:22.263000-04:00 [warning] <0.11783.31> closing AMQP connection <0.11783.31> (10.40.1.240:55748 -> 172.20.178.47:47490, vhost: '/', user: 'logreader'):
2024-01-07 01:05:22.263000-04:00 [warning] <0.11783.31> client unexpectedly closed TCP connection
2024-01-07 01:15:09.120000-04:00 [info] <0.12842.31> accepting AMQP connection <0.12842.31> (10.40.1.240:45558 -> 172.20.178.47:47490)
2024-01-07 01:15:11.915000-04:00 [info] <0.12842.31> connection <0.12842.31> (10.40.1.240:45558 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 01:46:12.019000-04:00 [error] <0.12842.31> closing AMQP connection <0.12842.31> (10.40.1.240:45558 -> 172.20.178.47:47490):
2024-01-07 01:46:12.019000-04:00 [error] <0.12842.31> missed heartbeats from client, timeout: 60s
2024-01-07 01:46:24.632000-04:00 [info] <0.12969.31> accepting AMQP connection <0.12969.31> (10.40.1.240:35704 -> 172.20.178.47:47490)
2024-01-07 01:46:26.487000-04:00 [info] <0.12969.31> connection <0.12969.31> (10.40.1.240:35704 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 02:33:14.885000-04:00 [warning] <0.12969.31> closing AMQP connection <0.12969.31> (10.40.1.240:35704 -> 172.20.178.47:47490, vhost: '/', user: 'logreader'):
2024-01-07 02:33:14.885000-04:00 [warning] <0.12969.31> client unexpectedly closed TCP connection
2024-01-07 02:33:23.542000-04:00 [info] <0.13804.31> accepting AMQP connection <0.13804.31> (10.40.1.240:50840 -> 172.20.178.47:47490)
2024-01-07 02:33:24.849000-04:00 [info] <0.13804.31> connection <0.13804.31> (10.40.1.240:50840 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 03:06:24.898000-04:00 [error] <0.13804.31> closing AMQP connection <0.13804.31> (10.40.1.240:50840 -> 172.20.178.47:47490):
2024-01-07 03:06:24.898000-04:00 [error] <0.13804.31> missed heartbeats from client, timeout: 60s
2024-01-07 03:06:30.406000-04:00 [info] <0.14615.31> accepting AMQP connection <0.14615.31> (10.40.1.240:55446 -> 172.20.178.47:47490)
2024-01-07 03:06:30.919000-04:00 [info] <0.14615.31> connection <0.14615.31> (10.40.1.240:55446 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 05:09:31.107000-04:00 [error] <0.14615.31> closing AMQP connection <0.14615.31> (10.40.1.240:55446 -> 172.20.178.47:47490):
2024-01-07 05:09:31.107000-04:00 [error] <0.14615.31> missed heartbeats from client, timeout: 60s
2024-01-07 05:09:38.677000-04:00 [info] <0.15609.31> accepting AMQP connection <0.15609.31> (10.40.1.240:34510 -> 172.20.178.47:47490)
2024-01-07 05:09:43.350000-04:00 [info] <0.15609.31> connection <0.15609.31> (10.40.1.240:34510 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 07:05:43.455000-04:00 [warning] <0.15609.31> closing AMQP connection <0.15609.31> (10.40.1.240:34510 -> 172.20.178.47:47490, vhost: '/', user: 'logreader'):
2024-01-07 07:05:43.455000-04:00 [warning] <0.15609.31> client unexpectedly closed TCP connection
2024-01-07 07:14:55.131000-04:00 [info] <0.16609.31> accepting AMQP connection <0.16609.31> (10.40.1.240:34012 -> 172.20.178.47:47490)
2024-01-07 07:14:55.637000-04:00 [info] <0.16609.31> connection <0.16609.31> (10.40.1.240:34012 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 08:02:53.237000-04:00 [warning] <0.16609.31> closing AMQP connection <0.16609.31> (10.40.1.240:34012 -> 172.20.178.47:47490, vhost: '/', user: 'logreader'):
2024-01-07 08:02:53.237000-04:00 [warning] <0.16609.31> client unexpectedly closed TCP connection
2024-01-07 08:12:01.223000-04:00 [info] <0.17464.31> accepting AMQP connection <0.17464.31> (10.40.1.240:53490 -> 172.20.178.47:47490)
2024-01-07 08:12:01.729000-04:00 [info] <0.17464.31> connection <0.17464.31> (10.40.1.240:53490 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 08:40:52.457000-04:00 [warning] <0.17464.31> closing AMQP connection <0.17464.31> (10.40.1.240:53490 -> 172.20.178.47:47490, vhost: '/', user: 'logreader'):
2024-01-07 08:40:52.457000-04:00 [warning] <0.17464.31> client unexpectedly closed TCP connection
2024-01-07 08:40:57.962000-04:00 [info] <0.18248.31> accepting AMQP connection <0.18248.31> (10.40.1.240:44906 -> 172.20.178.47:47490)
2024-01-07 08:41:07.971000-04:00 [error] <0.18248.31> closing AMQP connection <0.18248.31> (10.40.1.240:44906 -> 172.20.178.47:47490):
2024-01-07 08:41:07.971000-04:00 [error] <0.18248.31> {handshake_timeout,frame_header}
2024-01-07 08:41:25.489000-04:00 [info] <0.18253.31> accepting AMQP connection <0.18253.31> (10.40.1.240:38782 -> 172.20.178.47:47490)
2024-01-07 08:41:33.155000-04:00 [info] <0.18253.31> connection <0.18253.31> (10.40.1.240:38782 -> 172.20.178.47:47490): user 'logreader' authenticated and granted access to vhost '/'
2024-01-07 08:45:20.791000-04:00 [warning] <0.18253.31> closing AMQP connection <0.18253.31> (10.40.1.240:38782 -> 172.20.178.47:47490, vhost: '/', user: 'logreader'):
2024-01-07 08:45:20.791000-04:00 [warning] <0.18253.31> client unexpectedly closed TCP connection

[plewam]

@lukebakken Is there a way to pass in a logger into the library, e.g. the https://github.com/rabbitmq/rabbitmq-stream-dotnet-client is doing that quite good.

[lukebakken]

Unfortunately, there isn't a way to pass in a logger at this point in time.

Thank you for the logs. Some more questions:

• Do you know at what time your consuming application experienced the issue, so I can correlate it to the logs you provided?
• Do you know what kind of network interruption happened? For instance, was it like pulling the plug on an Ethernet cord?

[lukebakken]

@plewam this PR adds a test case that tests what happens when a TCP RESET is encountered - #1466

I have yet to reproduce what you report. Once the tests pass for that PR, I will merge it, close this issue, and publish a new alpha release for you to continue testing.

Thank you!

[lukebakken]

@plewam the next alpha will be available soon via NuGet - https://github.com/rabbitmq/rabbitmq-dotnet-client/releases/tag/v7.0.0-alpha.3

https://www.nuget.org/packages/RabbitMQ.Client/7.0.0-alpha.3

[plewam]

@lukebakken Thank you very much. As of now I have not encountered this issue again. I will deploy alpha 3 soon onto my testing environment