<p dir="auto">Celery workers become stuck/deadlocked when using Redis broker in Celery 3.1.17.<br>
Reproduced in 3.1.0 and 3.1.16 as well.</p>
<p dir="auto"><strong>Issue does not occur in current Celery master (3.2.0a2).</strong><br>
<strong>Issue does not occur with RabbitMQ as broker.</strong><br>
<strong>Reproducable on Linux and Mac OS.</strong></p>
<h3 dir="auto">Environment</h3>
<ul dir="auto">
<li>Scientific Linux release 6.5 or Mac OS 10.10.2</li>
<li>Python 2.7.9</li>
<li>Redis 2.8.9</li>
<li>Celery 3.1.0, 3.1.16, 3.1.17</li>
<li>virtualenv 12.0.5</li>
</ul>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="software -&gt; celery:3.1.17 (Cipater) kombu:3.0.24 py:2.7.9
            billiard:3.3.0.19 redis:2.10.3
platform -&gt; system:Linux arch:64bit, ELF imp:CPython
loader   -&gt; celery.loaders.app.AppLoader
settings -&gt; transport:redis results:disabled

BROKER_URL: 'redis://localhost:6380/0'"><pre class="notranslate"><code class="notranslate">software -&gt; celery:3.1.17 (Cipater) kombu:3.0.24 py:2.7.9
            billiard:3.3.0.19 redis:2.10.3
platform -&gt; system:Linux arch:64bit, ELF imp:CPython
loader   -&gt; celery.loaders.app.AppLoader
settings -&gt; transport:redis results:disabled

BROKER_URL: 'redis://localhost:6380/0'
</code></pre></div>
<p dir="auto"><strong>redis.conf</strong></p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="# close the connection after a client is idle for N seconds
timeout 0"><pre class="notranslate"><code class="notranslate"># close the connection after a client is idle for N seconds
timeout 0
</code></pre></div>
<p dir="auto"><strong>celeryconfig.py</strong></p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="BROKER_URL = 'redis://localhost:6380/0'"><pre class="notranslate"><code class="notranslate">BROKER_URL = 'redis://localhost:6380/0'
</code></pre></div>
<p dir="auto"><strong>tasks.py</strong></p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="from celery import Celery
import celeryconfig

import time

app = Celery('tasks')
app.config_from_object(celeryconfig)

@app.task
def myTask(id):
    return id"><pre class="notranslate"><code class="notranslate">from celery import Celery
import celeryconfig

import time

app = Celery('tasks')
app.config_from_object(celeryconfig)

@app.task
def myTask(id):
    return id
</code></pre></div>
<p dir="auto"><strong>test_client.py</strong></p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="from multiprocessing import Pool
from tasks import myTask 

def run(task_id):
   myTask.delay(1)

num_tasks = 20000
pool = Pool(processes=4)
pool.map(run, xrange(num_tasks))
pool.close()
pool.join()"><pre class="notranslate"><code class="notranslate">from multiprocessing import Pool
from tasks import myTask 

def run(task_id):
   myTask.delay(1)

num_tasks = 20000
pool = Pool(processes=4)
pool.map(run, xrange(num_tasks))
pool.close()
pool.join()
</code></pre></div>
<h3 dir="auto">Reproducing</h3>
<ol dir="auto">
<li>Ran test_client.py to submit 20K tasks.</li>
<li>Started two concurrent workers (<code class="notranslate">-Ofair</code> doesn't make a difference):</li>
</ol>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="celery -A tasks worker --loglevel=DEBUG --concurrency=3 [-Ofair]"><pre class="notranslate"><code class="notranslate">celery -A tasks worker --loglevel=DEBUG --concurrency=3 [-Ofair]
</code></pre></div>
<ol dir="auto">
<li>After ~10-20K of processed tasks, workers stuck/deadlocked.</li>
</ol>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="[2015-01-21 17:40:31,304: DEBUG/MainProcess] Task accepted: tasks.regulatorTask[6d2be28f-4d97-43b3-84dd-ad28b3a9d0f7] pid:13242
[2015-01-21 17:40:31,305: DEBUG/MainProcess] Task accepted: tasks.regulatorTask[6d798559-3e1e-4fe8-a813-065696d8a1df] pid:13243
[2015-01-21 17:40:31,306: INFO/MainProcess] Received task: tasks.regulatorTask[6adbe350-2d5e-4a92-89d9-4bbd63973aa6]
[2015-01-21 17:40:31,306: DEBUG/MainProcess] TaskPool: Apply &lt;function _fast_trace_task at 0x7f3436baf848&gt; (args:('tasks.regulatorTask', '6adbe350-2d5e-4a92-89d9-4bbd63973aa6', (1,), {}, {'utc': True, u'is_eager': False, 'chord': None, u'group': None, 'args': (1,), 'retries': 0, u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'celery', u'exchange': u'celery'}, 'expires': None, u'hostname': 'celery@dev6-cig-c53d391f.ewr01.tumblr.net', 'task': 'tasks.regulatorTask', 'callbacks': None, u'correlation_id': u'6adbe350-2d5e-4a92-89d9-4bbd63973aa6', 'errbacks': None, 'timelimit': (None, None), 'taskset': None, 'kwargs': {}, 'eta': None, u'reply_to': u'7d9537ab-0a15-34eb-afa2-aafc60e63b1a', 'id': '6adbe350-2d5e-4a92-89d9-4bbd63973aa6', u'headers': {}}) kwargs:{})
[2015-01-21 17:40:31,307: INFO/MainProcess] Task tasks.regulatorTask[6d2be28f-4d97-43b3-84dd-ad28b3a9d0f7] succeeded in 0.00572886499867s: 1
[2015-01-21 17:40:31,308: INFO/MainProcess] Task tasks.regulatorTask[6d798559-3e1e-4fe8-a813-065696d8a1df] succeeded in 0.00644170500163s: 1"><pre class="notranslate"><code class="notranslate">[2015-01-21 17:40:31,304: DEBUG/MainProcess] Task accepted: tasks.regulatorTask[6d2be28f-4d97-43b3-84dd-ad28b3a9d0f7] pid:13242
[2015-01-21 17:40:31,305: DEBUG/MainProcess] Task accepted: tasks.regulatorTask[6d798559-3e1e-4fe8-a813-065696d8a1df] pid:13243
[2015-01-21 17:40:31,306: INFO/MainProcess] Received task: tasks.regulatorTask[6adbe350-2d5e-4a92-89d9-4bbd63973aa6]
[2015-01-21 17:40:31,306: DEBUG/MainProcess] TaskPool: Apply &lt;function _fast_trace_task at 0x7f3436baf848&gt; (args:('tasks.regulatorTask', '6adbe350-2d5e-4a92-89d9-4bbd63973aa6', (1,), {}, {'utc': True, u'is_eager': False, 'chord': None, u'group': None, 'args': (1,), 'retries': 0, u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'celery', u'exchange': u'celery'}, 'expires': None, u'hostname': 'celery@dev6-cig-c53d391f.ewr01.tumblr.net', 'task': 'tasks.regulatorTask', 'callbacks': None, u'correlation_id': u'6adbe350-2d5e-4a92-89d9-4bbd63973aa6', 'errbacks': None, 'timelimit': (None, None), 'taskset': None, 'kwargs': {}, 'eta': None, u'reply_to': u'7d9537ab-0a15-34eb-afa2-aafc60e63b1a', 'id': '6adbe350-2d5e-4a92-89d9-4bbd63973aa6', u'headers': {}}) kwargs:{})
[2015-01-21 17:40:31,307: INFO/MainProcess] Task tasks.regulatorTask[6d2be28f-4d97-43b3-84dd-ad28b3a9d0f7] succeeded in 0.00572886499867s: 1
[2015-01-21 17:40:31,308: INFO/MainProcess] Task tasks.regulatorTask[6d798559-3e1e-4fe8-a813-065696d8a1df] succeeded in 0.00644170500163s: 1
</code></pre></div>
<p dir="auto"><code class="notranslate">strace</code> indicates workers blocking on I/O read from Redis</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="Process 13241 attached - interrupt to quit
read(13,

Process 13242 attached - interrupt to quit
read(17,

Process 13243 attached - interrupt to quit
read(9,"><pre class="notranslate"><code class="notranslate">Process 13241 attached - interrupt to quit
read(13,

Process 13242 attached - interrupt to quit
read(17,

Process 13243 attached - interrupt to quit
read(9,
</code></pre></div>
<h3 dir="auto">Notables</h3>
<ul dir="auto">
<li>adding a connection <code class="notranslate">timeout</code> in Redis will cause deadlock to release after timeout period</li>
<li>specifying a <code class="notranslate">CELERYD_TASK_TIME_LIMIT</code> does not prevent/release the deadlock</li>
<li>single worker execution (<code class="notranslate">--concurrency=1</code>) works properly</li>
</ul>
<p dir="auto">So I have been battling this issue for a few days now but it's really hard to figure out exactly what causes it. I had a repro for a day on an amazon machine but unfortunately it was a spot instance and I no longer have access to it.  I tried to make another repro on the weekend and failed.  Here is what I'm observing:</p>
<ul dir="auto">
<li>two amazon machines (does not matter if in vpc or not)</li>
<li>install redis on one, celery on the other</li>
<li>run celery with four prefork workers</li>
<li>spam the queue with lots of tasks</li>
</ul>
<p dir="auto">After some period of time everything will lock up.  Ways I have seen this recover:</p>
<ul dir="auto">
<li>restart celery</li>
<li><code class="notranslate">CLIENT KILL</code> from the redis server (this will trigger some epoll errors).</li>
</ul>
<p dir="auto">We have a customer who also seems to have a related issue but it recovers after 30 minutes.  I have not have a way to reproduce this issue, but it might be related to the client timeout on redis.</p>
<p dir="auto">Things I know other than that:</p>
<ul dir="auto">
<li>strace: when it hangs, it's trying to read from a redis socket.</li>
<li>the read is _read_from_socket in SocketBuffer in py-redis</li>
<li>changing timeouts on the redis side changes nothing</li>
<li>enabling keepalives changes nothing</li>
<li>a dummy python script that does BLPOP in a loop against the redis server with a second script that puts items into the queue does not get stuck.</li>
</ul>
<p dir="auto">I have a few theories on what this could be but I'm honestly at the end of my understanding of the issue.  What I see is that kombu internally catches down random epoll errors and when I add some prints there I can see that I get epoll errors even though the socket seems alive and happy.  I'm wondering if it could be possible that for some reason wrong fds are attempted to be registered with that thing.</p>
<p dir="auto">Versions used:</p>
<ul dir="auto">
<li>kombu==3.0.26</li>
<li>celery==3.1.18</li>
<li>redis==2.10.3</li>
<li>Redis server: 3.0.4</li>
<li>Happens with at least ubuntu 14.04</li>
</ul>
<p dir="auto">I have since tried to reproduce this again on another amazon machine and it does not appear to happen.  I'm not entirely sure what triggers it but it seems like the socket py-redis tries to read from is not what it thinks it is.  The socket was from what I can tell in ESTABLISHED.</p>
<p dir="auto">I'm completely out of ideas how to continue debugging this especially because it's impossible for me to reproduce on anything other than this particular amazon machine.  It does not appear on OS X, on two linux VMs running in virtualbox, not happening from one of my linux servers on hetzner to another one there and I could also not reproduce it form hetzner to amazon though in that particular case I saw some other artifacts that might have prevented debugging this (in particular the performance was quite bad and it continued on for a day without incidents).</p>
<p dir="auto">I first thought this mighe be <a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="26829016" data-permission-text="Title is private" data-url="https://github.com/celery/celery/issues/1845" data-hovercard-type="issue" data-hovercard-url="/celery/celery/issues/1845/hovercard" href="https://github.com/celery/celery/issues/1845">#1845</a> but from what I can tell there is no high CPU usage involved.  It just blocks on a read.  If I can help in any way with investigating this further, please let me know.</p>