client unexpectedly closed TCP connection with status check

[unclewizard]

Checklist

software -> celery:4.1.0 (latentcall) kombu:4.1.0 py:2.7.12
            billiard:3.5.0.3 py-amqp:2.2.2
platform -> system:Linux arch:64bit, ELF imp:CPython
loader   -> celery.loaders.app.AppLoader
settings -> transport:amqp results:disabled

Steps to reproduce

Follow the "first steps with django" documentation to create a barebones celery app: http://docs.celeryproject.org/en/latest/django/first-steps-with-django.html

For a broker, use RabbitMQ 3.6.11. I have also tested with RabbitMQ 3.6.12. I set my broker in settings.py as follows:

BROKER_URL = 'amqp://guest:guest@localhost:5672/'

Finally, run celery worker -A appname status

Expected behavior

No warnings in the broker logs

Actual behavior

The rabbitmq server prints the following output (depending on configuration it may show up in the log file. For me it was in /var/log/rabbitmq/rabbit@vagrant-ubuntu-trusty-64.log)

=WARNING REPORT==== 31-Oct-2017::23:56:19 ===
closing AMQP connection <0.663.0> (127.0.0.1:35985 -> 127.0.0.1:5672, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

The status check reports "OK" and the worker is consuming tasks normally, so this doesn't appear to be a connectivity or network issue.

This wouldn't be so bad, but it also seems to trigger a memory leak at the broker. If you run this 1000s of times, you will notice the rabbitmq memory usage increase even without queueing any actual messages.

[thedrow]

This does not look like a bug in Celery. However I'll need more information to determine that.
Can you reproduce this on another network? Without a VM?
This happens when there is not enough memory (or other resources) for the broker.

Also, please try to set the connect_timeout to a higher value, it should solve your issue.

[ananyashandilya1102]

@unclewizard @thedrow I am getting the same issue. Was this resolved? Can you help me with the solution?

[thedrow]

Without more details I can't be helpful.
I think this issue should be closed as it is not actionable.

If any of you think you have found the root cause of the issue please report a new issue about it.

[srinu230]

Hi i am also facing same issue

018-08-30 09:59:22.323 [warning] <0.21673.0> closing AMQP connection <0.21673.0> (127.0.0.1:53706 -> 127.0.0.1:5672, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

i am using Brokerurl : amqp://guest:guest@localhost:5672//
and
app = Celery('tasks', broker=broker_url(), include='task_helpers')
app.conf.update(
CELERY_IGNORE_RESULT=True,
CELERY_ENABLE_UTC=not settings.USE_LOCAL_TIMEZONE,
CELERY_TIMEZONE='US/Eastern',
CELERYD_PREFETCH_MULTIPLIER=BATCH_FLUSH_EVERY * 2,
accept_content=['pickle', 'json', 'application/json'],
CELERY_TASK_SERIALIZER='pickle', # Default value; TODO: change this to msgpack
CELERY_RESULT_SERIALIZER='pickle', # Default value; TODO: change this to msgpack
CELERY_ROUTES={
'tasks.function1': {'queue': 'persistence'},
'tasks.function2': {'queue': 'persistence'},
'tasks.function3': {'queue': 'persistence'},
},
CELERY_DISABLE_RATE_LIMITS=True, # We don't use them and it's recommended to disable if not using

#BROKER_CONNECTION_TIMEOUT = 15

)

It is adding conneting to rabbitMq and not getting databack
when i run every time queues count increasing and same time getting above error.

client unexpectedly closed TCP connection
2018-08-30 09:59:22.255 [info] <0.21673.0> accepting AMQP connection <0.21673.0> (127.0.0.1:53706 -> 127.0.0.1:5672)
2018-08-30 09:59:22.257 [info] <0.21673.0> connection <0.21673.0> (127.0.0.1:53706 -> 127.0.0.1:5672): user 'guest' authenticated and granted access to vhost '/'
2018-08-30 09:59:22.323 [warning] <0.21673.0> closing AMQP connection <0.21673.0> (127.0.0.1:53706 -> 127.0.0.1:5672, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

Could you Please helpme about why i am not getting databack
below list installed

alembic 0.8.6
amqp 1.4.9
anyjson 0.3.3
Babel 2.6.0
backports.ssl-match-hostname 3.5.0.1
billiard 3.3.0.23
celery 3.1.0
certifi 2018.8.24
cffi 1.8.3
chardet 3.0.4
commandr 1.3.2
crcmod 1.7
flower 0.9.1
GeoAlchemy2 0.3.0
idna 2.7
kombu 3.0.37
Mako 1.0.7
MarkupSafe 1.0
pip 18.0
psycopg2 2.6.2
pycparser 2.18
pydot 1.2.4
pymongo 3.2.2
pyparsing 2.2.0
python-editor 1.0.3
pytz 2018.5
requests 2.19.1
setuptools 40.2.0
Shapely 1.3.0
SQLAlchemy 1.0.12
sqlalchemy-schemadisplay 1.3
tornado 4.2
tzlocal 1.2.2
urllib3 1.23
wheel 0.31.1

[xlanor]

Am getting the same issue.

=INFO REPORT==== 16-Sep-2018::05:17:42 ===
accepting AMQP connection <0.22297.5> (127.0.0.1:33752 -> 127.0.0.1:5672)

=INFO REPORT==== 16-Sep-2018::05:17:42 ===
connection <0.22297.5> (127.0.0.1:33752 -> 127.0.0.1:5672): user 'guest' authenticated and granted access to vhost '/'

=WARNING REPORT==== 16-Sep-2018::05:17:42 ===
closing AMQP connection <0.22297.5> (127.0.0.1:33752 -> 127.0.0.1:5672, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

My logs are flooded with this, hundreds of times in the same time frame.

It always starts with this:

=ERROR REPORT==== 16-Sep-2018::05:49:26 ===
closing AMQP connection <0.6725.20> (127.0.0.1:50504 -> 127.0.0.1:5672):
missed heartbeats from client, timeout: 60s

=INFO REPORT==== 16-Sep-2018::05:49:41 ===
accepting AMQP connection <0.6824.20> (127.0.0.1:50842 -> 127.0.0.1:5672)

=INFO REPORT==== 16-Sep-2018::05:49:41 ===
connection <0.6824.20> (127.0.0.1:50842 -> 127.0.0.1:5672): user 'guest' authenticated and granted access to vhost '/'

=WARNING REPORT==== 16-Sep-2018::05:49:41 ===
closing AMQP connection <0.6824.20> (127.0.0.1:50842 -> 127.0.0.1:5672, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

=INFO REPORT==== 16-Sep-2018::05:49:41 ===
accepting AMQP connection <0.6837.20> (127.0.0.1:50844 -> 127.0.0.1:5672)

=INFO REPORT==== 16-Sep-2018::05:49:41 ===
connection <0.6837.20> (127.0.0.1:50844 -> 127.0.0.1:5672): user 'guest' authenticated and granted access to vhost '/'

=WARNING REPORT==== 16-Sep-2018::05:49:41 ===
closing AMQP connection <0.6837.20> (127.0.0.1:50844 -> 127.0.0.1:5672, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

EDIT: Just saw #4895 . Will attempt to downgrade celery.

[auvipy]

are you using the latest celery?

[xlanor]

are you using the latest celery?

I'm using 4.2.1 as reported in #4895 . I will now attempt a downgrade to 4.1.1 to see if that resolves the issue.

Downgrading to 4.1.1 seems to have fixed the issue for me. I will test it further to see if the issue is still prevalent.

[auvipy]

then it might be a regression

[ghost]

Can reproduce exactly the same issue as xlanor and downgrading to 4.1.1 fixed it also for me.

[uniqueg]

So can I. Back to 4.1.1.

[ingmferrer]

I'm having this same issue and the downgrade to 4.1.1 seems to fix this.

[sloria]

We are also running into this issue. Downgrading to 4.1.1 fixes it, but this is not a feasible workaround for us because 4.2.0 contains some critical bugfixes, including a fix for #4223 .

Is the 4.1.x release line still supported? Will bug fixes be backported?

[thedrow]

We don't have the resources to maintain two versions currently.
We'd rather invest our effort in investigating bugs like these.

[sloria]

Understandable. Let us know if there is any further information we can provide to help diagnose this issue.

Thanks for all your hard work!

[thedrow]

At this point, any new information would be good.
Finding the offending commit would be awesome.

[auvipy]

For me I had the same issue with connection dropped after 25 minutes with the long running task. This looked similar for both parties - RabbitMQ and celery reported that another peer reset the connection.
Finally I've discovered that this was related to Docker (I run my celery inside Docker). Quick workaround was to run containers with --net host and it seems to work now.

For additional info see your net.ipv4.tcp_keepalive_time setting (sysctl) and the following article: https://success.mirantis.com/article/ipvs-connection-timeout-issue

or we should mention this in the docs?

[boldrack]

Unfortunately This issue still persists in version 5.0.5 . Is there any workaround for this ?

[auvipy]

Unfortunately This issue still persists in version 5.0.5 . Is there any workaround for this ?

did you check #4355 (comment) ?

[ShanthaDodmane]

The link mentioned in this comment #4355 (comment) is asking us to login to salesforce.com :(

[nicolaerosia]

I'm seeing this when I do celery ping, e.g.

celery inspect ping -d celery@${HOSTNAME}

RabbitMQ:

[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.299663+00:00 [info] <0.13830.5> accepting AMQP connection <0.13830.5> (10.10.186.247:36212 -> 10.10.196.154:5672)
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.305745+00:00 [info] <0.13830.5> connection <0.13830.5> (10.10.186.247:36212 -> 10.10.196.154:5672): user 'root' authenticated and granted access to vhost '/'
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.345957+00:00 [info] <0.13847.5> accepting AMQP connection <0.13847.5> (10.10.186.247:36214 -> 10.10.196.154:5672)
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.365854+00:00 [info] <0.13847.5> connection <0.13847.5> (10.10.186.247:36214 -> 10.10.196.154:5672): user 'root' authenticated and granted access to vhost '/'
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.414558+00:00 [warn] <0.13847.5> closing AMQP connection <0.13847.5> (10.10.186.247:36214 -> 10.10.196.154:5672, vhost: '/', user: 'root'):
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.414558+00:00 [warn] <0.13847.5> client unexpectedly closed TCP connection
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.414734+00:00 [warn] <0.13830.5> closing AMQP connection <0.13830.5> (10.10.186.247:36212 -> 10.10.196.154:5672, vhost: '/', user: 'root'):
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.414734+00:00 [warn] <0.13830.5> client unexpectedly closed TCP connection

I will try to debug celery, it feels like the connection is not properly closed after being opened.

[nicolaerosia]

OK, I did debug a bit and found the culprit to be the connection pool in kombu:

broker_pool_limit = 0

results in a nice RabbitMQ log:

[pod/rabbitmq-0/rabbitmq] 2021-09-20 10:47:52.021612+00:00 [info] <0.22524.5> accepting AMQP connection <0.22524.5> (127.0.0.1:57356 -> 127.0.0.1:5672)
[pod/rabbitmq-0/rabbitmq] 2021-09-20 10:47:54.134131+00:00 [info] <0.22524.5> connection <0.22524.5> (127.0.0.1:57356 -> 127.0.0.1:5672): user 'root' authenticated and granted access to vhost '/'
[pod/rabbitmq-0/rabbitmq] 2021-09-20 10:48:01.602229+00:00 [info] <0.22546.5> accepting AMQP connection <0.22546.5> (127.0.0.1:57458 -> 127.0.0.1:5672)
[pod/rabbitmq-0/rabbitmq] 2021-09-20 10:48:03.962610+00:00 [info] <0.22546.5> connection <0.22546.5> (127.0.0.1:57458 -> 127.0.0.1:5672): user 'root' authenticated and granted access to vhost '/'
[pod/rabbitmq-0/rabbitmq] 2021-09-20 10:48:08.972621+00:00 [info] <0.22546.5> closing AMQP connection <0.22546.5> (127.0.0.1:57458 -> 127.0.0.1:5672, vhost: '/', user: 'root')
[pod/rabbitmq-0/rabbitmq] 2021-09-20 10:48:17.274228+00:00 [info] <0.22524.5> closing AMQP connection <0.22524.5> (127.0.0.1:57356 -> 127.0.0.1:5672, vhost: '/', user: 'root')

I guess the problem lies in the teardown of the pool? @auvipy does this ring any bell? :)

anyway, I don't understand why for a ping we need two connections, any idea?

[auvipy]

OK, I did debug a bit and found the culprit to be the connection pool in kombu:

broker_pool_limit = 0

does changing the value here improve anything?

[nicolaerosia]

yes, the connections are closed gracefully, I no longer see the warnings in RabbitMQ log:

[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.414558+00:00 [warn] <0.13847.5> closing AMQP connection <0.13847.5> (10.10.186.247:36214 -> 10.10.196.154:5672, vhost: '/', user: 'root'):
[pod/rabbitmq-0/rabbitmq] 2021-09-20 07:18:21.414558+00:00 [warn] <0.13847.5> client unexpectedly closed TCP connection

[auvipy]

instead of closing I am moving this to discussion

[iamnotagentleman]

@auvipy any progress for this problem? i think this problem cause high cpu usages too.

[samims]

Hello all, any solution? Getting same for the celery 4.4.2

[invi-code]

hello everyone did anyone got the solution?

[unitysipu]

iirc broker_pool_limit = 0 fixed this for me as well

[iglesiasroberto14]

Same here. Happening at least since version 4.1, when we decided to disable the broker pool as a workaround (broker_pool_limit=0). Now we upgraded to the latest available version (5.2.7), but it's still happening. I wasn't able to find the root cause. We need to enable broker pool, because we have too much tcp overhead, every task starts and finishes a new TCP connection, resulting in tens of thousands of connections every day.

Versions:

/ # pip freeze | grep -E '(amqp|celery|kombu)'
amqp==5.1.1
celery==5.2.7
kombu==5.2.4

I'd be glad to collaborate, but celery and kombu projects are a bit messy, and I can't find where the problem is. So... any hint is welcomed.

[ppiekars]

I did some steps as a proof of concept:

I had hard time finding any logic that would close the producer pool explicitly. I've put kombu.pools.reset() inside on_close method for the WorkController class. However, it looked like for some cases it was closing the underlying TCP connection directly, without sending the appropriate close message first. As a quick fix, I've requested explicit resource closure by putting res.close() inside force_close_all method, just before self.collect_resource(res) (in kombu library). This did the trick and now starting up and shutting down workers does not result in unexpectedly closing TCP connections.
There's one catch. There is still no logic on closing connections within forked worker processes. I've put kombu.pools.reset() inside billiard pool receive function, just before raise SystemExit(EX_FAILURE).
Now, forked processes close the connections gracefully.

These changes cannot be implemented as is for obvious reasons 😄 But maybe it will help find the correct path for solving the issue.

@auvipy maybe you could chime in on that, commenting whether it makes sense to implement this kind of pool closing during the shutdown, both in the main process and forked processes as well. Same thing can be implemented as a global pool cleanup during various commands like status or inspect ping.

[auvipy]

It would be easier for me to comment/share my opinion if you can share some working/draft code example. of course with relevant test in the form of a PR?

[ooyamatakehisa]

I have the same error.

2023-07-11 04:19:03.601367+00:00 [warning] <0.986.0> closing AMQP connection <0.986.0> (172.18.0.5:35116 -> 172.18.0.2:5672, vhost: '/', user: 'guest'):
2023-07-11 04:19:03.601367+00:00 [warning] <0.986.0> client unexpectedly closed TCP connection

I'm not sure sharing my environmet helps but the following is my env just in case.

• using docker-compose
• broker is rabbitmq:3.12.0-management container
• celery version is celery==5.3.1
• worker's base image is centos/python-38-centos7

[MugdhaHardikar-GSLab]

I am also facing similar issue. My detailed analysis is mentioned here
Versions:
rabbitmq: 3.12.7
Celery : 5.1.2
Mongo: 5.0.21

Is it recommended to change the celery version?
I have tried setting "broker_pool_limit" during worker creation. It has not helped me.

[MugdhaHardikar-GSLab]

Adding below in celery app configuration solved my issue:

•        broker_pool_limit=0,
  

•        broker_transport_options={'confirm_publish': True},