Kombu: Connection Issues with Redis

[alexkahn]

I have a celery instance running as a worker process on heroku with heroku redis. About every minute (the amount of time after which heroku redis kills idle connections) this comes up in my logs:

Dec 12 14:34:40 app/worker.1:  [2015-12-12 16:34:40,387: WARNING/MainProcess] consumer: Connection to broker lost. Trying to re-establish the connection... 
Dec 12 14:34:40 app/worker.1:  Traceback (most recent call last): 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 278, in start 
Dec 12 14:34:40 app/worker.1:      blueprint.start(self) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/bootsteps.py", line 123, in start 
Dec 12 14:34:40 app/worker.1:      step.start(parent) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 821, in start 
Dec 12 14:34:40 app/worker.1:      c.loop(*c.loop_args()) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/loops.py", line 76, in asynloop 
Dec 12 14:34:40 app/worker.1:      next(loop) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/hub.py", line 285, in create_loop 
Dec 12 14:34:40 app/worker.1:      poll_timeout = fire_timers(propagate=propagate) if scheduled else 1 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/hub.py", line 144, in fire_timers 
Dec 12 14:34:40 app/worker.1:      entry() 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/timer.py", line 64, in __call__ 
Dec 12 14:34:40 app/worker.1:      return self.fun(*self.args, **self.kwargs) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/timer.py", line 132, in _reschedules 
Dec 12 14:34:40 app/worker.1:      return fun(*args, **kwargs) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 322, in maybe_restore_messages 
Dec 12 14:34:40 app/worker.1:      num=channel.unacked_restore_limit, 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 188, in restore_visible 
Dec 12 14:34:40 app/worker.1:      self.unacked_mutex_expire): 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/contextlib.py", line 17, in __enter__ 
Dec 12 14:34:40 app/worker.1:      return self.gen.next() 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 112, in Mutex 
Dec 12 14:34:40 app/worker.1:      i_won = client.setnx(name, lock_id) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/redis/client.py", line 1097, in setnx 
Dec 12 14:34:40 app/worker.1:      return self.execute_command('SETNX', name, value) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/redis/client.py", line 575, in execute_command 
Dec 12 14:34:40 app/worker.1:      connection.disconnect() 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 819, in disconnect 
Dec 12 14:34:40 app/worker.1:      channel._on_connection_disconnect(self) 
Dec 12 14:34:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 476, in _on_connection_disconnect 
Dec 12 14:34:40 app/worker.1:      raise get_redis_ConnectionError() 
Dec 12 14:34:40 app/worker.1:  ConnectionError 
Dec 12 14:34:40 app/worker.1:  [2015-12-12 16:34:40,452: INFO/MainProcess] Connected to redis://h:**@***************:********// 
Dec 12 14:34:40 app/worker.1:  [2015-12-12 16:34:40,480: INFO/MainProcess] mingle: searching for neighbors 
Dec 12 14:34:41 app/worker.1:  [2015-12-12 16:34:41,535: INFO/MainProcess] mingle: all alone

This is a recent phenomenon, it started last night and isn't foiled by a process restart. Could this possibly be a result of any updates or the like?

Running python 2.7.11
amqp==1.4.8
anyjson==0.3.3
billiard==3.3.0.22
celery==3.1.19
kombu==3.0.30
pytz==2015.7
redis==2.10.5
Django==1.8.7
django-redis-cache==1.6.5

[ask]

Try installing: pip install -U https://github.com/celery/kombu/zipball/3.0#egg=kombu

I will prepare a release with this fix shortly

[alexkahn]

Getting a 404 on the URL (tried curl and pip)

[ask]

https://github.com/celery/kombu/zipball/3.0#egg=kombu

[alexkahn]

I appreciate the work, it didn't really solve the problem but I've since stopped using Heroku redis in production which seems to have been the trick.

[chernavin]

I'm still getting this error.

File "/webapps/sp_cabinet/local/lib/python2.7/site-packages/redis/connection.py", line 921, in disconnect
    connection.disconnect()
  File "/webapps/sp_cabinet/local/lib/python2.7/site-packages/kombu/transport/redis.py", line 835, in disconnect
    channel._on_connection_disconnect(self)
  File "/webapps/sp_cabinet/local/lib/python2.7/site-packages/kombu/transport/redis.py", line 491, in _on_connection_disconnect
    raise get_redis_ConnectionError()
ConnectionError
[2015-12-21 22:42:49,168: INFO/MainProcess] Connected to redis://localhost:6379/0

celery==3.1.19
kombu==3.0.32
redis==2.10.5
Django==1.6.5

On start everythng is OK.
Worker handles tasks and periodically loses connection.
Then connection recovers and tasks keep handling.
I noticed that connection loses exactly when new task comes.

[kgrinberg]

I'm experiencing this as well, same as OP, but with kombu==3.0.32

Setting the server connection timeout to 0 (no timeout) "fixed" the issue, at least for the past few days. However, that doesn't seem sustainable, because the # of connections keeps rising (since not all clients always close their connections, at least on Heroku).

So if I understand the root issue correctly, Celery's reconnect after the server closes the connection isn't working correctly. (Unfortunately I'm not sure why).

Is there any other debug info that would be helpful?

[alexkahn]

Other commenters have joined, figured re-opening this was appropriate.

[agurinov]

have this problem

[kgrinberg]

I just ran a bunch of tests, and can confirm that the bug reported by OP was introduced in 3.0.30 (it doesn't happen for me with 3.0.29, _does_ happen with 3.0.30, 31, 32).

To repro, I set the Heroku redis server timeout to something very short (10 seconds) and tried my app with the various versions of kombu pinned (3.0.29 - 3.0.32, omitting 3.0.31 since it had that localhost bug).

Looking at the changelog, between that and the actual traceback (see below), 60edf5626545539472e1ca1b7714e3cf33b8ea4d looks to be the commit in question (though I assume that change was made for a reason, so just reverting would be unwise!)

My traceback for 3.0.29 is identical to the OP; for 3.0.32, it's as follows:

Dec 23 13:33:40 app/worker.1:  consumer: Connection to broker lost. Trying to re-establish the connection... 
Dec 23 13:33:40 app/worker.1:  Traceback (most recent call last): 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 278, in start 
Dec 23 13:33:40 app/worker.1:      blueprint.start(self) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/bootsteps.py", line 123, in start 
Dec 23 13:33:40 app/worker.1:      step.start(parent) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 821, in start 
Dec 23 13:33:40 app/worker.1:      c.loop(*c.loop_args()) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/loops.py", line 76, in asynloop 
Dec 23 13:33:40 app/worker.1:      next(loop) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/hub.py", line 340, in create_loop 
Dec 23 13:33:40 app/worker.1:      cb(*cbargs) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 991, in on_readable 
Dec 23 13:33:40 app/worker.1:      self._callbacks[queue](message) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/virtual/__init__.py", line 534, in _callback 
Dec 23 13:33:40 app/worker.1:      self.qos.append(message, message.delivery_tag) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 148, in append 
Dec 23 13:33:40 app/worker.1:      dumps([message._raw, EX, RK])) \ 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/redis/client.py", line 2628, in execute 
Dec 23 13:33:40 app/worker.1:      conn.disconnect() 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 835, in disconnect 
Dec 23 13:33:40 app/worker.1:      channel._on_connection_disconnect(self) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 489, in _on_connection_disconnect 
Dec 23 13:33:40 app/worker.1:      self._disconnect_pools() 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 477, in _disconnect_pools 
Dec 23 13:33:40 app/worker.1:      self._async_pool.disconnect() 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/redis/connection.py", line 921, in disconnect 
Dec 23 13:33:40 app/worker.1:      connection.disconnect() 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 835, in disconnect 
Dec 23 13:33:40 app/worker.1:      channel._on_connection_disconnect(self) 
Dec 23 13:33:40 app/worker.1:    File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 491, in _on_connection_disconnect 
Dec 23 13:33:40 app/worker.1:      raise get_redis_ConnectionError() 
Dec 23 13:33:40 app/worker.1:  ConnectionError 
Dec 23 13:33:40 app/worker.1:  Connected to redis://h:**@*******:*****// 
Dec 23 13:33:40 app/worker.1:  mingle: searching for neighbors 
Dec 23 13:33:41 app/worker.1:  mingle: all alone 

@alexkahn did you switch to a non-Heroku redis, or away from redis entirely? (Trying to figure out if the issue is specific to Heroku).

[ask]

Could you please try this patch?

[ask]

A bit quick there, the two patches please :)

[kgrinberg]

Sorry, having a hard time getting this to install on Heroku from requirements.txt

-e git://github.com/celery/kombu.git@7fc856cffc16a0af93e5227f845e2a8ba93b2a31#egg=kombu

doesn't work. I'll just vendor it - it'll take me a few minutes (everything's a _bit_ more complicated w/Heroku).

I need to step away right now, but will be able to give this a proper test in a few hours. Thanks for all your work!

[ask]

Hot tip: Don't use git, use the github zipballs feature:

http://github.com/celery/kombu/zipball/master#egg=kombu

without the -e

[kgrinberg]

Sorry for the delay - same error, unfortunately.

[alexkahn]

@kgrinberg I just moved off of Heroku Redis - I think their configuration of Redis with hard connection timeouts was the root of the issue but I am still using Redis for messaging.

[flavianh]

Getting the issue here too with kombu==3.0.32, I had upgraded from 3.0.29. I'm reverting to 3.0.29.

[starplanet]

have this problem too. My environment is following:
celery 3.1.19
redis 2.10.5
kombu 3.0.32

[ask]

@kgrinberg That's odd, using the master branch with celery 3.1 cannot possibly work at all, so did you port the patch over?

[kgrinberg]

@ask Gah. You're absolutely right. My apologies. I didn't notice it at first because of how Heroku caches eggs.

I redeployed to a "clean" app and got the expected error. Would you suggest trying the master branch with celery 4rc1, or can you port the patch to the 3.0 branch? (Or I can do it, probably tomorrow).

[ask]

@kgrinberg I just ported it now, please try: pip install https://github.com/celery/kombu/zipball/3.0 :)

[kgrinberg]

@ask I'll run some more tests tonight (heading out for a few hours), but so far so good!

(Basically it looks good but I want to run a few more tests to make sure I didn't make the same mistake as last time).

[kgrinberg]

I can confirm that I can reproduce the problem with 3.0.32, and it's fixed in 57cb12442f6713e5bdca3ac37ae452210539cb52

Thank you! A new PyPI release would obviously be awesome at some point - at least for my case, looks like this fixes things. (I'd be great if the others who reported this can test as well).

[kgrinberg]

@traxair @starplanet can you confirm if the latest and greatest fixes it for you? It'd be great to get another data point besides me!

https://github.com/celery/kombu/zipball/3.0

[flavianh]

I only could replicate the issue on my prod servers, so that's a bit complicated for me, sorry...

[Chronial]

I think I have the same issue – I will deploy the new version and see if changes anything.

[Chronial]

Yes, the issue is now fixed for me.

[starplanet]

It works fine for me now. But I can’t confirm whether it can work reliably, don't lost task when reconnect to redis broker. I haven’t run my program for a long time, just several hours. I need more test. After a long time test, I will give a feedback again.

在 2016年1月6日，上午12:54，Kevin Grinberg [email protected] 写道：

@traxair https://github.com/traxair @starplanet https://github.com/starplanet can you confirm if the latest and greatest fixes it for you? It'd be great to get another data point besides me!

https://github.com/celery/kombu/zipball/3.0 https://github.com/celery/kombu/zipball/3.0
—
Reply to this email directly or view it on GitHub https://github.com/celery/kombu/issues/550#issuecomment-169059490.

[dkingman]

I can confirm this issue is still present with

kombu==3.0.32
celery==3.1.19

running on Heroku.

2016-01-07T21:03:51.716218+00:00 app[worker.1]: [2016-01-07 21:03:51,703: WARNING/MainProcess] consumer: Connection to broker lost. Trying to re-establish the connection...
2016-01-07T21:03:51.716222+00:00 app[worker.1]: Traceback (most recent call last):
2016-01-07T21:03:51.716223+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 129, in _read_from_socket
2016-01-07T21:03:51.716224+00:00 app[worker.1]:     raise socket.error(SERVER_CLOSED_CONNECTION_ERROR)
2016-01-07T21:03:51.716225+00:00 app[worker.1]: OSError: Connection closed by server.
2016-01-07T21:03:51.716226+00:00 app[worker.1]: 
2016-01-07T21:03:51.716227+00:00 app[worker.1]: During handling of the above exception, another exception occurred:
2016-01-07T21:03:51.716227+00:00 app[worker.1]: 
2016-01-07T21:03:51.716228+00:00 app[worker.1]: Traceback (most recent call last):
2016-01-07T21:03:51.716229+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 577, in read_response
2016-01-07T21:03:51.716229+00:00 app[worker.1]:     response = self._parser.read_response()
2016-01-07T21:03:51.716230+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 238, in read_response
2016-01-07T21:03:51.716231+00:00 app[worker.1]:     response = self._buffer.readline()
2016-01-07T21:03:51.716232+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 168, in readline
2016-01-07T21:03:51.716232+00:00 app[worker.1]:     self._read_from_socket()
2016-01-07T21:03:51.716233+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 143, in _read_from_socket
2016-01-07T21:03:51.716234+00:00 app[worker.1]:     (e.args,))
2016-01-07T21:03:51.716234+00:00 app[worker.1]: redis.exceptions.ConnectionError: Error while reading from socket: ('Connection closed by server.',)
2016-01-07T21:03:51.716235+00:00 app[worker.1]: 
2016-01-07T21:03:51.716235+00:00 app[worker.1]: During handling of the above exception, another exception occurred:
2016-01-07T21:03:51.716236+00:00 app[worker.1]: 
2016-01-07T21:03:51.716240+00:00 app[worker.1]:     return execute(conn, stack, raise_on_error)
2016-01-07T21:03:51.716237+00:00 app[worker.1]: Traceback (most recent call last):
2016-01-07T21:03:51.716240+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/client.py", line 2503, in _execute_transaction
2016-01-07T21:03:51.716239+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/client.py", line 2626, in execute
2016-01-07T21:03:51.716241+00:00 app[worker.1]:     self.parse_response(connection, '_')
2016-01-07T21:03:51.716241+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/client.py", line 2584, in parse_response
2016-01-07T21:03:51.716242+00:00 app[worker.1]:     self, connection, command_name, **options)
2016-01-07T21:03:51.716243+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/client.py", line 585, in parse_response
2016-01-07T21:03:51.716244+00:00 app[worker.1]:     response = connection.read_response()
2016-01-07T21:03:51.716244+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 579, in read_response
2016-01-07T21:03:51.716245+00:00 app[worker.1]:     self.disconnect()
2016-01-07T21:03:51.716246+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 835, in disconnect
2016-01-07T21:03:51.716246+00:00 app[worker.1]:     channel._on_connection_disconnect(self)
2016-01-07T21:03:51.716247+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 489, in _on_connection_disconnect
2016-01-07T21:03:51.716266+00:00 app[worker.1]:     self._disconnect_pools()
2016-01-07T21:03:51.716267+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 477, in _disconnect_pools
2016-01-07T21:03:51.716267+00:00 app[worker.1]:     self._async_pool.disconnect()
2016-01-07T21:03:51.716268+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 921, in disconnect
2016-01-07T21:03:51.716268+00:00 app[worker.1]:     connection.disconnect()
2016-01-07T21:03:51.716269+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 835, in disconnect
2016-01-07T21:03:51.716269+00:00 app[worker.1]:     channel._on_connection_disconnect(self)
2016-01-07T21:03:51.716270+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 491, in _on_connection_disconnect
2016-01-07T21:03:51.716271+
00:00 app[worker.1]:     raise get_redis_ConnectionError()
2016-01-07T21:03:51.716271+00:00 app[worker.1]: redis.exceptions.ConnectionError
2016-01-07T21:03:51.716272+00:00 app[worker.1]: 
2016-01-07T21:03:51.716272+00:00 app[worker.1]: During handling of the above exception, another exception occurred:
2016-01-07T21:03:51.716273+00:00 app[worker.1]: 
2016-01-07T21:03:51.716274+00:00 app[worker.1]: Traceback (most recent call last):
2016-01-07T21:03:51.716274+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/celery/worker/consumer.py", line 278, in start
2016-01-07T21:03:51.716275+00:00 app[worker.1]:     blueprint.start(self)
2016-01-07T21:03:51.716276+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/celery/bootsteps.py", line 123, in start
2016-01-07T21:03:51.716276+00:00 app[worker.1]:     step.start(parent)
2016-01-07T21:03:51.716277+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/celery/worker/consumer.py", line 821, in start
2016-01-07T21:03:51.716277+00:00 app[worker.1]:     c.loop(*c.loop_args())
2016-01-07T21:03:51.716278+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/celery/worker/loops.py", line 76, in asynloop
2016-01-07T21:03:51.716278+00:00 app[worker.1]:     next(loop)
2016-01-07T21:03:51.716279+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/async/hub.py", line 340, in create_loop
2016-01-07T21:03:51.716280+00:00 app[worker.1]:     cb(*cbargs)
2016-01-07T21:03:51.716280+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 991, in on_readable
2016-01-07T21:03:51.716281+00:00 app[worker.1]:     self._callbacks[queue](message)
2016-01-07T21:03:51.716281+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/virtual/__init__.py", line 534, in _callback
2016-01-07T21:03:51.716282+00:00 app[worker.1]:     self.qos.append(message, message.delivery_tag)
2016-01-07T21:03:51.716283+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 148, in append
2016-01-07T21:03:51.716283+00:00 app[worker.1]:     dumps([message._raw, EX, RK])) \
2016-01-07T21:03:51.716287+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/client.py", line 2628, in execute
2016-01-07T21:03:51.716288+00:00 app[worker.1]:     conn.disconnect()
2016-01-07T21:03:51.716289+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 835, in disconnect
2016-01-07T21:03:51.716289+00:00 app[worker.1]:     channel._on_connection_disconnect(self)
2016-01-07T21:03:51.716290+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 489, in _on_connection_disconnect
2016-01-07T21:03:51.716291+00:00 app[worker.1]:     self._disconnect_pools()
2016-01-07T21:03:51.716291+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 477, in _disconnect_pools
2016-01-07T21:03:51.716292+00:00 app[worker.1]:     self._async_pool.disconnect()
2016-01-07T21:03:51.716292+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/redis/connection.py", line 921, in disconnect
2016-01-07T21:03:51.716293+00:00 app[worker.1]:     connection.disconnect()
2016-01-07T21:03:51.716293+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 835, in disconnect
2016-01-07T21:03:51.716294+00:00 app[worker.1]:     channel._on_connection_disconnect(self)
2016-01-07T21:03:51.716295+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python3.5/site-packages/kombu/transport/redis.py", line 491, in _on_connection_disconnect
2016-01-07T21:03:51.716295+00:00 app[worker.1]:     raise get_redis_ConnectionError()
2016-01-07T21:03:51.716325+00:00 app[worker.1]: redis.exceptions.ConnectionError

[Chronial]

@dkingman This is known. The fix is not part of any release yet. You need to use the current dev version (https://github.com/celery/kombu/zipball/3.0) to test the fix.

[dkingman]

@Chronial

https://github.com/celery/kombu/zipball/3.0 installs 3.0.32 which still has the issue. Am I missing something?

[Chronial]

It just claims to be 3.0.32, but is in fact newer. Here you can see the difference: https://github.com/celery/kombu/compare/v3.0.32...3.0

[dkingman]

Good call. I didn't realize pip freeze wouldn't suffice, but it makes sense now.

[ask]

kombu 3.0.33 is on PyPI already!

[StephenAlanBuckley]

I'm running into this issue with
celery==3.1.20
redis==2.10.5
kombu==3.0.33

2016-02-19T23:03:30.162004+00:00 app[worker.1]: [2016-02-19 23:03:30,161: INFO/MainProcess] Connected to redis://redistogo:**@*.redistogo.com:*/0
2016-02-19T23:03:30.288574+00:00 app[worker.1]: [2016-02-19 23:03:30,288: INFO/MainProcess] mingle: searching for neighbors
2016-02-19T23:03:31.356568+00:00 app[worker.1]: [2016-02-19 23:03:31,356: INFO/MainProcess] mingle: all alone
2016-02-19T23:03:31.549615+00:00 app[worker.1]: [2016-02-19 23:03:31,548: WARNING/MainProcess] consumer: Connection to broker lost. Trying to re-establish the connection...
2016-02-19T23:03:31.549626+00:00 app[worker.1]: Traceback (most recent call last):
2016-02-19T23:03:31.549628+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 279, in start
2016-02-19T23:03:31.549630+00:00 app[worker.1]:     blueprint.start(self)
2016-02-19T23:03:31.549631+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/bootsteps.py", line 123, in start
2016-02-19T23:03:31.549632+00:00 app[worker.1]:     step.start(parent)
2016-02-19T23:03:31.549633+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 838, in start
2016-02-19T23:03:31.549634+00:00 app[worker.1]:     c.loop(*c.loop_args())
2016-02-19T23:03:31.549635+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/loops.py", line 76, in asynloop
2016-02-19T23:03:31.549637+00:00 app[worker.1]:     next(loop)
2016-02-19T23:03:31.549638+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/hub.py", line 274, in create_loop
2016-02-19T23:03:31.549639+00:00 app[worker.1]:     tick_callback()
2016-02-19T23:03:31.549639+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 974, in on_poll_start
2016-02-19T23:03:31.549640+00:00 app[worker.1]:     cycle_poll_start()
2016-02-19T23:03:31.549641+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 308, in on_poll_start
2016-02-19T23:03:31.549643+00:00 app[worker.1]:     self._register_LISTEN(channel)
2016-02-19T23:03:31.549644+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 298, in _register_LISTEN
2016-02-19T23:03:31.549645+00:00 app[worker.1]:     self._register(channel, channel.subclient, 'LISTEN')
2016-02-19T23:03:31.549646+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 274, in _register
2016-02-19T23:03:31.549647+00:00 app[worker.1]:     client.connection.connect()
2016-02-19T23:03:31.549648+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/redis/connection.py", line 449, in connect
2016-02-19T23:03:31.549649+00:00 app[worker.1]:     self.disconnect()
2016-02-19T23:03:31.549650+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 835, in disconnect
2016-02-19T23:03:31.549651+00:00 app[worker.1]:     channel._on_connection_disconnect(self)
2016-02-19T23:03:31.549652+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 489, in _on_connection_disconnect
2016-02-19T23:03:31.549652+00:00 app[worker.1]:     self._disconnect_pools()
2016-02-19T23:03:31.549654+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 477, in _disconnect_pools
2016-02-19T23:03:31.549655+00:00 app[worker.1]:     self._async_pool.disconnect()
2016-02-19T23:03:31.549655+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/redis/connection.py", line 921, in disconnect
2016-02-19T23:03:31.549656+00:00 app[worker.1]:     connection.disconnect()
2016-02-19T23:03:31.549657+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 835, in disconnect
2016-02-19T23:03:31.549658+00:00 app[worker.1]:     channel._on_connection_disconnect(self)
2016-02-19T23:03:31.549659+00:00 app[worker.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 491, in _on_connection_disconnect
2016-02-19T23:03:31.549660+00:00 app[worker.1]:     raise get_redis_ConnectionError()
2016-02-19T23:03:31.549661+00:00 app[worker.1]: ConnectionError
2016-02-19T23:03:31.799810+00:00 app[worker.1]: [2016-02-19 23:03:31,799: INFO/MainProcess] Connected to redis://redistogo:**@*.redistogo.com:*/0

[StephenAlanBuckley]

Also on heroku

[StephenAlanBuckley]

@ask kombu 3.0.33 is supposed to have resolved this issue if I'm reading this thread correctly? Happy to do any debugging- I tried uninstalling and then reinstalling kombu from the linked zipball but it's also been updated so I ended up back on 3.0.33

[ask]

@StephenAlanBuckley The bug was about transient connections bringing the persistent connections down, but register_LISTEN is a persistent connection so it should propagate the disconnect if a connection cannot be made

[durden]

I'm seeing the same problem as @StephenAlanBuckley on heroku. Is this a new bug or still related to this thread?

[robbyt]

We were having the same bug with 3.0.33, and it's gone away after downgrading to 3.0.29.

Can I provide any more debugging information?

[kgrinberg]

I'm not sure how relevant this is, but I'm noticing that in the "newer" variant of this issue, it's connecting to RedisToGo, whereas the initial report (and my experience) was about connecting to Heroku Redis. Although RedisToGo is offered as a Heroku add-on, it's a separate service - with a (potentially) different configuration.

To the extent that it's a potential issue in kombu, that may not be relevant - but to the extent that it's related to the Redis server it's connecting to, that's something to check (and perhaps try with Heroku Redis, if that's an option for you).

[robbyt]

For our environment, we're using Rackspace cloud servers, and the version of Redis is the Ubuntu 12.04 supplied version, 2:2.2.12-1build1. So I'm not sure if the issue is related to the server version.

@kgrinberg Do you know what versions of Redis are in those environments?

However, we are using an older version of Python, also supplied by Ubuntu 12.04, version 2.7.3-0ubuntu2.2.

[durden]

My situation is a bit different. I've been seeing it while using Heroku Redis, but only the free 'hobby' level service. I upgraded to the 'Premium 0' service and this error seemed to vanish. Is that a clue?

[ask]

Guess it could be related to the timeout redis configuration value, this should be set at 0 if possible, so that idle clients are not disconnected.

[robbyt]

@ask it's possible that cloud provider networks are quietly terminating the TCP connection, and the Redis driver thinks its still open.

Imho, if Kombu follows semantic versioning, changing the behavior of the Redis client pooling should have probably been released as a minor point release rather than just a patch.

[lylepratt]

We were constantly receiving this error until we downgraded to 3.0.29

[Chronial]

You should create a new issue for this new bug.

[RafaAguilar]

Same issue here with:

kombu==3.0.35
celery==3.1.23
redis==2.10.5

 . . .
  File "path/venv/lib/python3.4/site-packages/kombu/transport/redis.py", line 498, in _on_connection_disconnect
    raise get_redis_ConnectionError()
redis.exceptions.ConnectionError

[robbyt]

To work around this problem in newer versions of Kombu, disable the new broker pool feature by setting BROKER_POOL_LIMIT = 0. re: http://docs.celeryproject.org/en/latest/configuration.html#broker-pool-limit

[RafaAguilar]

@robbyt: can you say which specific configuration, with above's throws this:

TypeError: __init__() got an unexpected keyword argument 'socket_keepalive_options'

[emaniacs]

I got the same issue here with:

kombu==3.0.35
celery==3.1.23
redis==2.10.5

  File "path/venv/lib/python3.4/site-packages/kombu/transport/redis.py", line 498, in _on_connection_disconnect
    raise get_redis_ConnectionError()
redis.exceptions.ConnectionError

[emaniacs]

I got this problem when i set password for redis.
Temporary fix, just remove or comment requirepass password on redis.conf

[skoczen]

Just tossing this here, in case it helps someone who gets here from google, as I did. Lots of errors that look like the above bugs are cropping up right now (have been for ~the past 3 days) if you're using RedisToGo on heroku. Some of the workarounds help (.29 works, for instance, but has the UUID problems.), but don't solve it.

Actual Fix: RedisToGo is the problem. Switching to another redis provider (I went to heroku redis) will fix it.

Despite the pulling of your hair, if you're on RedisToGo, it's likely not actually a problem with kombu.

[alexanthony813]

@skoczen is 100% right, take it out on RedisToGo. I had the exact same problem.

[cloutiertyler]

I'm not using RedisToGo, but a regular instance of Redis and I am getting this error with

kombu==3.0.35
celery==3.1.23
redis==2.8.22

[cloutiertyler]

For the record here, we found that the issue was we need to upgrade our Python version to at least 2.7.10. We were getting this error with 2.7.5.

[nakiba]

I had the same problem:

celery==3.1.23
kombu==3.0.25
redis==3.2.3
python==2.7.11

[mkuchen]

@ask having the same problem with a Heroku redis instance. Seems to happen when some tasks terminate, while attempting to disconnect.

celery==3.1.23
kombu==3.0.35
redis==2.10.3
python==2.7.11

Full stack trace:

2016-08-31T13:19:29.961631+00:00 app[worker_instance.1]: WARNING consumer: Connection to broker lost. Trying to re-establish the connection...
2016-08-31T13:19:29.961647+00:00 app[worker_instance.1]: Traceback (most recent call last):
2016-08-31T13:19:29.961648+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 279, in start
2016-08-31T13:19:29.961649+00:00 app[worker_instance.1]:     blueprint.start(self)
2016-08-31T13:19:29.961650+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/bootsteps.py", line 123, in start
2016-08-31T13:19:29.961651+00:00 app[worker_instance.1]:     step.start(parent)
2016-08-31T13:19:29.961651+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/consumer.py", line 838, in start
2016-08-31T13:19:29.961652+00:00 app[worker_instance.1]:     c.loop(*c.loop_args())
2016-08-31T13:19:29.961652+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/celery/worker/loops.py", line 76, in asynloop
2016-08-31T13:19:29.961653+00:00 app[worker_instance.1]:     next(loop)
2016-08-31T13:19:29.961654+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/async/hub.py", line 340, in create_loop
2016-08-31T13:19:29.961655+00:00 app[worker_instance.1]:     cb(*cbargs)
2016-08-31T13:19:29.961655+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 1000, in on_readable
2016-08-31T13:19:29.961656+00:00 app[worker_instance.1]:     item = self.cycle.on_readable(fileno)
2016-08-31T13:19:29.961657+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 331, in on_readable
2016-08-31T13:19:29.961657+00:00 app[worker_instance.1]:     return chan.handlers[type]()
2016-08-31T13:19:29.961658+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 659, in _brpop_read
2016-08-31T13:19:29.961659+00:00 app[worker_instance.1]:     self.client.connection.disconnect()
2016-08-31T13:19:29.961659+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 854, in disconnect
2016-08-31T13:19:29.961660+00:00 app[worker_instance.1]:     channel._on_connection_disconnect(self)
2016-08-31T13:19:29.961661+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 496, in _on_connection_disconnect
2016-08-31T13:19:29.961661+00:00 app[worker_instance.1]:     self._disconnect_pools()
2016-08-31T13:19:29.961662+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 484, in _disconnect_pools
2016-08-31T13:19:29.961662+00:00 app[worker_instance.1]:     self._async_pool.disconnect()
2016-08-31T13:19:29.961663+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/redis/connection.py", line 898, in disconnect
2016-08-31T13:19:29.961664+00:00 app[worker_instance.1]:     connection.disconnect()
2016-08-31T13:19:29.961665+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 854, in disconnect
2016-08-31T13:19:29.961665+00:00 app[worker_instance.1]:     channel._on_connection_disconnect(self)
2016-08-31T13:19:29.961666+00:00 app[worker_instance.1]:   File "/app/.heroku/python/lib/python2.7/site-packages/kombu/transport/redis.py", line 498, in _on_connection_disconnect
2016-08-31T13:19:29.961666+00:00 app[worker_instance.1]:     raise get_redis_ConnectionError()
2016-08-31T13:19:29.961667+00:00 app[worker_instance.1]: ConnectionError
2016-08-31T13:19:29.962487+00:00 app[worker_instance.1]: WARNING Restoring 3 unacknowledged message(s).

In my particular case it's when running members of a chord.

[lambacck]

I've done some digging on this since I'm having the same issue. It appears to be an interaction between _brpop_read calling disconnect on a connection and _async_pool overriding disconnect on the RedisClient to get _on_connection_disconnect to run. When that happens it checks to see if .close() has been called and if not raises a redis ConnectionError: https://github.com/celery/kombu/blob/3.0/kombu/transport/redis.py#L497.

The commit that introduced the problem I'm having appears to be introduced here: https://github.com/celery/kombu/commit/60edf5626545539472e1ca1b7714e3cf33b8ea4d where the check on _closing was introduced and makes it only valid to call _on_connection_disconnect after calling close. The two operations (redis client disconnect calling _on_connection_disconnect and _on_connection_disconnect is only valid after calling close()) are mutually incompatible. So either something needs to call close on the pool or there needs to be two paths through the _on_connection_disconnect logic or places that call disconnect need to expect a ConnectionError to be raised somehow.

[rickwargo]

I also received this issue, although not on heroku. I believe it occurred because redis killed the connection stating in the log that cmd=psubscribe scheduled to be closed ASAP for overcoming of output buffer limits.

I updated the limits and will monitor and report if this reoccurs.

celery==3.1.24
redis==2.10.5
hiredis==0.2.0
kombu==3.0.37
python==3.5.2

My call stack:

[2016-10-26 19:04:05,346: WARNING/MainProcess] consumer: Connection to broker lost. Trying to re-establish the connection...
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/celery/worker/consumer.py", line 280, in start
    blueprint.start(self)
  File "/usr/local/lib/python3.5/dist-packages/celery/bootsteps.py", line 123, in start
    step.start(parent)
  File "/usr/local/lib/python3.5/dist-packages/celery/worker/consumer.py", line 884, in start
    c.loop(*c.loop_args())
  File "/usr/local/lib/python3.5/dist-packages/celery/worker/loops.py", line 76, in asynloop
    next(loop)
  File "/usr/local/lib/python3.5/dist-packages/kombu/async/hub.py", line 274, in create_loop
    tick_callback()
  File "/usr/local/lib/python3.5/dist-packages/kombu/transport/redis.py", line 1006, in on_poll_start
    [add_reader(fd, on_readable, fd) for fd in cycle.fds]
  File "/usr/local/lib/python3.5/dist-packages/kombu/transport/redis.py", line 1006, in <listcomp>
    [add_reader(fd, on_readable, fd) for fd in cycle.fds]
  File "/usr/local/lib/python3.5/dist-packages/kombu/async/hub.py", line 210, in add_reader
    return self.add(fds, callback, READ | ERR, args)
  File "/usr/local/lib/python3.5/dist-packages/kombu/async/hub.py", line 162, in add
    self.poller.register(fd, flags)
  File "/usr/local/lib/python3.5/dist-packages/kombu/utils/eventio.py", line 77, in register
    self._epoll.register(fd, events)
OSError: [Errno 9] Bad file descriptor

[paradite]

For me the issue is fixed (for Heroku) by simply updating kombu to 3.0.33:

-kombu==3.0.30
+kombu==3.0.33

I am using

celery==3.1.18
kombu==3.0.33
redis==2.10.3

Hope that helps.

[dharanpdarsana]

I am also getting the same error with :

python==2.7.12
redis==3.2.3
kombu==4.0.2
Django==1.10.3
celery==4.0.2
amqp==2.1.1
billiard==3.5.0.2
pytz==2016.7
Django==1.10.3o

[BigFishhhh]

Traceback (most recent call last):
File "bridger.py", line 97, in
bridger.start_listen()
File "bridger.py", line 54, in start_listen
self.generate_task(item)
File "bridger.py", line 85, in generate_task
set(queue=queue, routing_key=route_key), queue=queue, routing_key=route_key)
File "/usr/local/lib/python2.7/site-packages/celery-3.1.25-py2.7.egg/celery/app/task.py", line 573, in apply_async
*dict(self._get_exec_options(), *options)
File "/usr/local/lib/python2.7/site-packages/celery-3.1.25-py2.7.egg/celery/app/base.py", line 354, in send_task
reply_to=reply_to or self.oid, *options
File "/usr/local/lib/python2.7/site-packages/celery-3.1.25-py2.7.egg/celery/app/amqp.py", line 310, in publish_task
*kwargs
File "/usr/local/lib/python2.7/site-packages/kombu/messaging.py", line 172, in publish
routing_key, mandatory, immediate, exchange, declare)
File "/usr/local/lib/python2.7/site-packages/kombu/connection.py", line 470, in _ensured
interval_max)
File "/usr/local/lib/python2.7/site-packages/kombu/connection.py", line 382, in ensure_connection
interval_start, interval_step, interval_max, callback)
File "/usr/local/lib/python2.7/site-packages/kombu/utils/__init__.py", line 246, in retry_over_time
return fun(args, *kwargs)
File "/usr/local/lib/python2.7/site-packages/kombu/connection.py", line 250, in connect
return self.connection
File "/usr/local/lib/python2.7/site-packages/kombu/connection.py", line 756, in connection
self._connection = self._establish_connection()
File "/usr/local/lib/python2.7/site-packages/kombu/connection.py", line 711, in _establish_connection
conn = self.transport.establish_connection()
File "/usr/local/lib/python2.7/site-packages/kombu/transport/virtual/__init__.py", line 809, in establish_connection
self._avail_channels.append(self.create_channel(self))
File "/usr/local/lib/python2.7/site-packages/kombu/transport/virtual/__init__.py", line 791, in create_channel
channel = self.Channel(connection)
File "/usr/local/lib/python2.7/site-packages/kombu/transport/redis.py", line 466, in __init__
self._disconnect_pools()
File "/usr/local/lib/python2.7/site-packages/kombu/transport/redis.py", line 484, in _disconnect_pools
self._async_pool.disconnect()
File "build/bdist.linux-x86_64/egg/redis/connection.py", line 921, in disconnect

File "/usr/local/lib/python2.7/site-packages/kombu/transport/redis.py", line 866, in disconnect
channel._on_connection_disconnect(self)
File "/usr/local/lib/python2.7/site-packages/kombu/transport/redis.py", line 498, in _on_connection_disconnect
raise get_redis_ConnectionError()
redis.exceptions.ConnectionError

[auvipy]

have you tried with all the latest release?

[BigFishhhh]

@auvipy i tried kombu 3.0.29 ,now it's OK