ask/celery — Issue #587: Concurrent chords receive results from other chords, or None (RabbitMQ, django-celery)
Author: chrischamberlin
Created: 2012-01-12 22:18:18+00:00
State: open

If I fire off multiple chords in quick succession, each with a different task set, Celery often returns the wrong results to the chord task. That is, some of the subtask results in the list returned to the chord task should have gone to a different task or are set to None. If I add sleep() calls so each chord finishes before the next is launched, this problem goes away.

I'm running:
Current trunk for:
ask/celery@c86a7df55887ef5da1e837bb5198e120453deec8
ask/django-celery@8a45edd4e280247d5f893dd9ae5e327d2f07c6c3
ask/kombu@ec2e37f807db276f253dabc19d002a6f2b1ed518
Django 1.3.1
Python 2.6.1
PostgreSQL 9.0.2 (via the Django ORM)
RabbitMQ 2.7.0

Here's a tasks.py file that, for me, reproduces the problem fairly reliably. I have this in an otherwise empty Django app, and call `launch()` from a shell.

```python
import celery.task
import random
import logging
import time

logger = logging.getLogger(__name__)

@celery.task.task
def my_subtask(cid, sid, rv):
t = random.randrange(4,8)
time.sleep(t)
logger.warning("my_subtask(%s,%s) done (returning %s)", cid, sid, rv)
return rv

@celery.task.task
def chord_finish(stresults, ci):
if any([v is None or v < ci * 100 or v >= (ci+1) * 100 for v in stresults]):
logger.error("chord %s: unexpected results: %s", ci, stresults)
return "NO"
else:
logger.warning("chord %s: success: %s", ci, stresults)
return "YES"

def launch(numchord=8):
for c in xrange(numchord):
subtasks = [my_subtask.subtask((c, s, c * 100 + s)) for s in xrange(c+1)]
chord_subtask = chord_finish.subtask(kwargs={"ci": c})
celery.task.chord(subtasks)(chord_subtask)
```

I've used between 4 and 16 worker processes; this makes no difference. I expect the results in `chord_finish()` to be a list like [200, 201, 202]; if I run only one chord, I get this. But if I run multiple chords, I get something like the log below.

```
[2012-01-12 14:44:20,474: WARNING/PoolWorker-4] my_subtask(4,1) done (returning 401)
[2012-01-12 14:44:21,273: WARNING/PoolWorker-2] my_subtask(4,0) done (returning 400)
[2012-01-12 14:44:22,089: WARNING/PoolWorker-1] my_subtask(0,0) done (returning 0)
[2012-01-12 14:44:22,549: WARNING/PoolWorker-3] my_subtask(4,2) done (returning 402)
[2012-01-12 14:44:27,354: WARNING/PoolWorker-2] my_subtask(4,4) done (returning 404)
(......deleted...)
[2012-01-12 14:44:48,694: ERROR/PoolWorker-4] chord 1: unexpected results: [0, 201]
[2012-01-12 14:44:51,394: WARNING/PoolWorker-1] my_subtask(3,0) done (returning 300)
[2012-01-12 14:44:51,405: ERROR/PoolWorker-1] chord 2: unexpected results: [0, 201, None]
[2012-01-12 14:44:52,695: WARNING/PoolWorker-2] my_subtask(3,2) done (returning 302)
[2012-01-12 14:44:52,706: ERROR/PoolWorker-2] chord 3: unexpected results: [200, 201, 202, None]
[2012-01-12 14:44:53,796: WARNING/PoolWorker-4] my_subtask(3,3) done (returning 303)
[2012-01-12 14:44:54,830: WARNING/PoolWorker-3] my_subtask(3,1) done (returning 301)
[2012-01-12 14:44:54,840: ERROR/PoolWorker-3] chord 4: unexpected results: [None, 401, 402, 403, 404]
[2012-01-12 14:44:58,491: WARNING/PoolWorker-1] my_subtask(7,0) done (returning 700)
[2012-01-12 14:44:58,876: WARNING/PoolWorker-4] my_subtask(7,2) done (returning 702)
[2012-01-12 14:44:58,886: ERROR/PoolWorker-4] chord 6: unexpected results: [None, 601, 602, 603, None, 605, 606]
[2012-01-12 14:44:59,793: WARNING/PoolWorker-2] my_subtask(7,1) done (returning 701)
[2012-01-12 14:44:59,803: ERROR/PoolWorker-2] chord 7: unexpected results: [602, 603, None, 605, 606, None, 502, 503]
[2012-01-12 14:44:59,918: WARNING/PoolWorker-3] my_subtask(7,3) done (returning 703)
[2012-01-12 14:44:59,930: ERROR/PoolWorker-3] chord 5: unexpected results: [500, 501, 502, 503, None, 505]
[2012-01-12 14:45:04,813: WARNING/PoolWorker-2] my_subtask(7,6) done (returning 706)
[2012-01-12 14:45:04,944: WARNING/PoolWorker-3] my_subtask(7,7) done (returning 707)
[2012-01-12 14:45:05,570: WARNING/PoolWorker-1] my_subtask(7,4) done (returning 704)
[2012-01-12 14:45:05,970: WARNING/PoolWorker-4] my_subtask(7,5) done (returning 705)
```