Pika ConnectionResetError(104, 'Connection reset by peer') having 2 connections using threads

[Raphael Hippe]

I have posted this question on stackoverflow as well. I read that the community mostly uses this google groups though. Since I can't figure out how to format code here I am linking the SO post as well. 

I am running into the following error with pika

pika.exceptions.StreamLostError: Stream connection lost: ConnectionResetError(104, 'Connection reset by peer')

I've read on stackoverflow and other sources that the origin of this error are missed heartbeats and that threading should be the solution. I've also seen from this talk that it is recommended to have 2 connections. One for consuming and one for producing. From the pika repository I found this solution for creating threads for doing the work load and not miss heartbeats. From the pika FAQ I also know that pika is not threadsafe and thus every connection needs to run in it's own thread.

Based on that I designed my service to have a Consumer and a Producer object which run in their own thread and the consumer thread creates a new thread for "doing the work".

Here is the full example of my service implementation. It is not my exact service implementation but the general structure and idea are the same. Locally and in my docker setup the service, so far, runs fine most of the times. But deployed on my test servers it often runs into the connection reset error.

Are there any flaws with my service implementation? Or could the issue be with my RabbitMQ configuration? (I am using the RabbitMQ Bitnami 3.11.8-0 image, which runs on an AWS EC2 instance. I have not changed any of the default configuration.)

I am a bit stuck and not quite sure what to try next. So I am grateful for any pointers or suggestions.

Thanks!

[Luke Bakken]

Thanks for providing a complete example.

What is logged by RabbitMQ when you see the  ConnectionResetError?

[Raphael Hippe]

Hi, 

all I can find so far is this
2023-07-18 16:21:59.933513+00:00 [info] <0.30741.56> accepting AMQP connection <0.30741.56> (35.158.114.168:56762 -> 172.31.7.254:5672)
2023-07-18 16:21:59.935736+00:00 [info] <0.30741.56> connection <0.30741.56> (35.158.114.168:56762 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 16:21:59.942566+00:00 [info] <0.30741.56> closing AMQP connection <0.30741.56> (35.158.114.168:56762 -> 172.31.7.254:5672, vhost: '/', user: 'user')

it's from /opt/bitnami/rabbitmq/var/log/rabbitmq/rab...@localhost.log

are those the logs of interest or are there others?

Thanks

[Luke Bakken]

Hmm all that suggests is that the connection was extremely short-lived, but still closed correctly. 

"Connection reset by peer" is an abrupt connection terminaton.

Do you have a load balancer in place?

[Raphael Hippe]

I am not using any load balancer for this EC2 at the moment. It only has security groups opening the necessary ports. I don't think I've configured any timeouts on AWS side. I am not 100% what the bitnami RabbitMQ image has configured. 

RabbitMQ is running on an AWS EC2 t3.micro instance. Could it be an issue that this instance is not powerful enough?

[Luke Bakken]

I doubt the instance size is the issue.

Can you provide more context from the RabbitMQ logs around the same time as the exception?

[Raphael Hippe]

Here's a bigger portion of the same log

2023-07-18 15:00:11.865304+00:00 [info] <0.30460.56> accepting AMQP connection <0.30460.56> (18.194.233.44:43492 -> 172.31.7.254:5672)
2023-07-18 15:00:11.868108+00:00 [info] <0.30460.56> connection <0.30460.56> (18.194.233.44:43492 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 15:00:11.912051+00:00 [info] <0.30460.56> closing AMQP connection <0.30460.56> (18.194.233.44:43492 -> 172.31.7.254:5672, vhost: '/', user: 'user')
2023-07-18 15:00:12.504141+00:00 [info] <0.30483.56> accepting AMQP connection <0.30483.56> (18.194.233.44:43496 -> 172.31.7.254:5672)
2023-07-18 15:00:12.507070+00:00 [info] <0.30483.56> connection <0.30483.56> (18.194.233.44:43496 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 15:00:12.553637+00:00 [info] <0.30483.56> closing AMQP connection <0.30483.56> (18.194.233.44:43496 -> 172.31.7.254:5672, vhost: '/', user: 'user')
2023-07-18 15:00:16.590170+00:00 [info] <0.30506.56> accepting AMQP connection <0.30506.56> (52.59.147.24:51006 -> 172.31.7.254:5672)
2023-07-18 15:00:16.595064+00:00 [info] <0.30506.56> connection <0.30506.56> (52.59.147.24:51006 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 15:00:16.636071+00:00 [warning] <0.30506.56> closing AMQP connection <0.30506.56> (52.59.147.24:51006 -> 172.31.7.254:5672, vhost: '/', user: 'user'):
2023-07-18 15:00:16.636071+00:00 [warning] <0.30506.56> client unexpectedly closed TCP connection
2023-07-18 15:01:06.553025+00:00 [info] <0.30526.56> accepting AMQP connection <0.30526.56> (18.194.233.44:33498 -> 172.31.7.254:5672)
2023-07-18 15:01:06.556002+00:00 [info] <0.30526.56> connection <0.30526.56> (18.194.233.44:33498 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 15:01:06.560375+00:00 [info] <0.30526.56> closing AMQP connection <0.30526.56> (18.194.233.44:33498 -> 172.31.7.254:5672, vhost: '/', user: 'user')
2023-07-18 15:01:20.732025+00:00 [info] <0.30541.56> accepting AMQP connection <0.30541.56> (18.194.233.44:60432 -> 172.31.7.254:5672)
2023-07-18 15:01:20.734771+00:00 [info] <0.30541.56> connection <0.30541.56> (18.194.233.44:60432 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 15:01:20.739652+00:00 [info] <0.30541.56> closing AMQP connection <0.30541.56> (18.194.233.44:60432 -> 172.31.7.254:5672, vhost: '/', user: 'user')
2023-07-18 15:02:57.892065+00:00 [error] <0.28557.56> closing AMQP connection <0.28557.56> (18.193.43.106:41876 -> 172.31.7.254:5672):
2023-07-18 15:02:57.892065+00:00 [error] <0.28557.56> missed heartbeats from client, timeout: 60s
2023-07-18 15:02:57.892982+00:00 [error] <0.28555.56> closing AMQP connection <0.28555.56> (18.193.43.106:41878 -> 172.31.7.254:5672):
2023-07-18 15:02:57.892982+00:00 [error] <0.28555.56> missed heartbeats from client, timeout: 60s
2023-07-18 15:57:49.888893+00:00 [info] <0.30674.56> accepting AMQP connection <0.30674.56> (167.94.145.58:47610 -> 172.31.7.254:5672)
2023-07-18 15:57:49.889053+00:00 [error] <0.30674.56> closing AMQP connection <0.30674.56> (167.94.145.58:47610 -> 172.31.7.254:5672):
2023-07-18 15:57:49.889053+00:00 [error] <0.30674.56> amqp1_0_plugin_not_enabled
2023-07-18 16:00:14.668309+00:00 [info] <0.30683.56> accepting AMQP connection <0.30683.56> (52.59.147.24:40786 -> 172.31.7.254:5672)
2023-07-18 16:00:14.672086+00:00 [info] <0.30683.56> connection <0.30683.56> (52.59.147.24:40786 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 16:00:14.713448+00:00 [warning] <0.30683.56> closing AMQP connection <0.30683.56> (52.59.147.24:40786 -> 172.31.7.254:5672, vhost: '/', user: 'user'):
2023-07-18 16:00:14.713448+00:00 [warning] <0.30683.56> client unexpectedly closed TCP connection

2023-07-18 16:21:59.933513+00:00 [info] <0.30741.56> accepting AMQP connection <0.30741.56> (35.158.114.168:56762 -> 172.31.7.254:5672)
2023-07-18 16:21:59.935736+00:00 [info] <0.30741.56> connection <0.30741.56> (35.158.114.168:56762 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 16:21:59.942566+00:00 [info] <0.30741.56> closing AMQP connection <0.30741.56> (35.158.114.168:56762 -> 172.31.7.254:5672, vhost: '/', user: 'user')

2023-07-18 17:00:12.740711+00:00 [info] <0.30828.56> accepting AMQP connection <0.30828.56> (52.59.147.24:58608 -> 172.31.7.254:5672)
2023-07-18 17:00:12.745434+00:00 [info] <0.30828.56> connection <0.30828.56> (52.59.147.24:58608 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 17:00:12.789791+00:00 [warning] <0.30828.56> closing AMQP connection <0.30828.56> (52.59.147.24:58608 -> 172.31.7.254:5672, vhost: '/', user: 'user'):
2023-07-18 17:00:12.789791+00:00 [warning] <0.30828.56> client unexpectedly closed TCP connection
2023-07-18 18:00:18.830718+00:00 [info] <0.30956.56> accepting AMQP connection <0.30956.56> (52.59.147.24:48552 -> 172.31.7.254:5672)
2023-07-18 18:00:18.835776+00:00 [info] <0.30956.56> connection <0.30956.56> (52.59.147.24:48552 -> 172.31.7.254:5672): user 'user' authenticated and granted access to vhost '/'
2023-07-18 18:00:18.875934+00:00 [warning] <0.30956.56> closing AMQP connection <0.30956.56> (52.59.147.24:48552 -> 172.31.7.254:5672, vhost: '/', user: 'user'):
2023-07-18 18:00:18.875934+00:00 [warning] <0.30956.56> client unexpectedly closed TCP connection

[Luke Bakken]

Thanks. What would be helpful is to know when the exception occurred so I can correlate it to this log. Is this application the only one running?

[Raphael Hippe]

I run tests again today in order to provide more detailed logs for you, but today it ran 10 times smoothly. 
I will try it again tomorrow and come back to this. 

But from your responses so far, I gather that I am not doing things completely wrong so far?