Skip to content

chord of chains with groups: body duplication and invalid task execution order #5947

Closed
#5984
Closed
chord of chains with groups: body duplication and invalid task execution order#5947
#5984

Description

@the-owl
the-owl
opened on Jan 31, 2020

Checklist

  • I have verified that the issue exists against the master branch of Celery.
  • This has already been asked to the discussion group first.
  • I have read the relevant section in the
    contribution guide
    on reporting bugs.
  • I have checked the issues list
    for similar or identical bug reports.
  • I have checked the pull requests list
    for existing proposed fixes.
  • I have checked the commit log
    to find out if the bug was already fixed in the master branch.
  • I have included all related issues and possible duplicate issues
    in this issue (If there are none, check this box anyway).

Mandatory Debugging Information

  • I have included the output of celery -A proj report in the issue.
    (if you are not able to do this, then at least specify the Celery
    version affected).
  • I have verified that the issue exists against the master branch of Celery.
  • I have included the contents of pip freeze in the issue.
  • I have included all the versions of all the external dependencies required
    to reproduce this bug.

Optional Debugging Information

  • I have tried reproducing the issue on more than one Python version
    and/or implementation.
  • I have tried reproducing the issue on more than one message broker and/or
    result backend.
  • I have tried reproducing the issue on more than one version of the message
    broker and/or result backend.
  • I have tried reproducing the issue on more than one operating system.
  • I have tried reproducing the issue on more than one workers pool.
  • I have tried reproducing the issue with autoscaling, retries,
    ETA/Countdown & rate limits disabled.
  • I have tried reproducing the issue after downgrading
    and/or upgrading Celery and its dependencies.

Related Issues

  • None

Possible Duplicates

  • None

Environment & Settings

Celery version: 4.4.0

celery report Output: 

software -> celery:4.4.0 (cliffs) kombu:4.6.7 py:3.7.3
            billiard:3.6.1.0 py-amqp:2.5.2
platform -> system:Linux arch:64bit, ELF
            kernel version:5.0.0-37-generic imp:CPython
loader   -> celery.loaders.app.AppLoader
settings -> transport:amqp results:redis://redis/

CELERY_BROKER_URL: 'amqp://guest:********@rabbit:5672//'
CELERY_RESULT_BACKEND: 'redis://redis/'
CELERY_TASK_SERIALIZER: 'json'
is_overridden: <bound method Settings.is_overridden of <Settings "app.settings">>
beat_schedule: {}
task_routes: {
 'app.tasks.*': {'queue': 'main'}}

Steps to Reproduce

  1. Start celery worker with --concurrency 8 and -O fair using code from test case below
  2. Call a broken task via celery -A app.celery_app call app.tasks.bug.task
  3. Call a correct task via celery -A app.celery_app call app.tasks.bug.task_correct

Required Dependencies

  • Minimal Python Version: N/A or Unknown
  • Minimal Celery Version: N/A or Unknown
  • Minimal Kombu Version: N/A or Unknown
  • Minimal Broker Version: N/A or Unknown
  • Minimal Result Backend Version: N/A or Unknown
  • Minimal OS and/or Kernel Version: N/A or Unknown
  • Minimal Broker Client Version: N/A or Unknown
  • Minimal Result Backend Client Version: N/A or Unknown

Python Packages

pip freeze Output: 

aiohttp==3.6.2
amqp==2.5.2
asgiref==3.2.3
async-timeout==3.0.1
attrs==19.3.0
billiard==3.6.1.0
celery==4.4.0
certifi==2019.9.11
chardet==3.0.4
curlify==2.2.1
decorator==4.4.1
defusedxml==0.6.0
Django==3.0.2
django-braces==1.13.0
django-cors-headers==3.1.1
django-filter==2.2.0
django-oauth-toolkit==1.2.0
django-rest-framework-social-oauth2==1.1.0
django-templated-mail==1.1.1
djangorestframework==3.11.0
djoser==2.0.3
drf-nested-routers==0.91
facebook-business==5.0.0
ffmpeg-python==0.2.0
future==0.18.1
idna==2.8
ImageHash==4.0
imageio==2.6.1
imageio-ffmpeg==0.3.0
importlib-metadata==1.3.0
kombu==4.6.7
more-itertools==8.0.2
moviepy==1.0.1
multidict==4.5.2
numpy==1.17.4
oauthlib==3.1.0
Pillow==6.2.0
proglog==0.1.9
psycopg2-binary==2.8.3
PyJWT==1.7.1
pymongo==3.9.0
pyslack==0.5.0
python3-openid==3.1.0
pytz==2019.2
PyWavelets==1.1.1
redis==3.3.8
requests==2.22.0
requests-oauthlib==1.2.0
rest-social-auth==3.0.0
scipy==1.3.2
sentry-sdk==0.13.5
six==1.12.0
slackclient==2.3.0
social-auth-app-django==3.1.0
social-auth-core==3.2.0
sqlparse==0.3.0
tqdm==4.39.0
urllib3==1.25.6
vine==1.3.0
yarl==1.3.0
zipp==0.6.0

Other Dependencies

Details

N/A

Minimally Reproducible Test Case

Details 

from time import sleep

from celery import chord, group

from app.celery_app import app


@app.task
def task():
    chord([
        a.s(1) | group([b.si(), b.si()]),
        a.s(3) | group([b.si(), b.si()]),
    ])(c.si())
    

@app.task
def task_correct():
    chord([
        a.s(1) | group([b.si(), b.si()]) | dummy.si(),
        a.s(3) | group([b.si(), b.si()]) | dummy.si(),
    ])(c.si())


@app.task
def dummy():
    pass


@app.task
def a(delay):
    sleep(delay)


@app.task
def b():
    pass


@app.task
def c():
    pass

Expected Behavior

I expect the tasks to complete in the following order:
A B B A B B C

Actual Behavior

Task C gets duplicated:

[2020-01-31 13:48:40,765: INFO/MainProcess] Received task: app.tasks.bug.task[9d35ec5f-a268-4db9-9068-1e27fe64cef9]  
[2020-01-31 13:48:40,817: INFO/MainProcess] Received task: app.tasks.bug.a[b2833570-bca5-4875-ab6d-e3ec339f36d1]  
[2020-01-31 13:48:40,824: INFO/MainProcess] Received task: app.tasks.bug.a[3d49f0d7-6b1a-4937-ac1c-29bac230e533]  
[2020-01-31 13:48:40,828: INFO/ForkPoolWorker-8] Task app.tasks.bug.task[9d35ec5f-a268-4db9-9068-1e27fe64cef9] succeeded in 0.06039188499562442s: None
[2020-01-31 13:48:41,864: INFO/MainProcess] Received task: app.tasks.bug.b[796bcd9f-f548-4282-9f6d-16ddb3ddc29b]  
[2020-01-31 13:48:41,867: INFO/ForkPoolWorker-8] Task app.tasks.bug.b[796bcd9f-f548-4282-9f6d-16ddb3ddc29b] succeeded in 0.001961939036846161s: None
[2020-01-31 13:48:41,869: INFO/MainProcess] Received task: app.tasks.bug.b[eacaa3ce-cc71-4daf-8e62-8d24f9322c7b]  
[2020-01-31 13:48:41,871: INFO/ForkPoolWorker-9] Task app.tasks.bug.a[b2833570-bca5-4875-ab6d-e3ec339f36d1] succeeded in 1.0521306470036507s: None
[2020-01-31 13:48:41,884: INFO/ForkPoolWorker-8] Task app.tasks.bug.b[eacaa3ce-cc71-4daf-8e62-8d24f9322c7b] succeeded in 0.013368424959480762s: None
[2020-01-31 13:48:41,884: INFO/MainProcess] Received task: app.tasks.bug.c[8e50636b-a440-454e-a6fe-57bb7595b82f]  
[2020-01-31 13:48:41,886: INFO/ForkPoolWorker-8] Task app.tasks.bug.c[8e50636b-a440-454e-a6fe-57bb7595b82f] succeeded in 0.0010153759503737092s: None
[2020-01-31 13:48:43,880: INFO/MainProcess] Received task: app.tasks.bug.b[07eb9c18-1303-4517-b95b-d555de1d6315]  
[2020-01-31 13:48:43,884: INFO/ForkPoolWorker-8] Task app.tasks.bug.b[07eb9c18-1303-4517-b95b-d555de1d6315] succeeded in 0.0018030810169875622s: None
[2020-01-31 13:48:43,887: INFO/MainProcess] Received task: app.tasks.bug.b[7ebaf58a-28f5-4170-86fb-61c3b5ee1909]  
[2020-01-31 13:48:43,887: INFO/ForkPoolWorker-2] Task app.tasks.bug.a[3d49f0d7-6b1a-4937-ac1c-29bac230e533] succeeded in 3.0580567660508677s: None
[2020-01-31 13:48:43,892: INFO/ForkPoolWorker-8] Task app.tasks.bug.b[7ebaf58a-28f5-4170-86fb-61c3b5ee1909] succeeded in 0.004260396934114397s: None
[2020-01-31 13:48:43,893: INFO/MainProcess] Received task: app.tasks.bug.c[8e50636b-a440-454e-a6fe-57bb7595b82f]  
[2020-01-31 13:48:43,896: INFO/ForkPoolWorker-8] Task app.tasks.bug.c[8e50636b-a440-454e-a6fe-57bb7595b82f] succeeded in 0.000999139971099794s: None

Actual execution order is weird, and task C is executed twice.

But when you add a dummy task to the end of each chain, execution order becomes correct (as seen in task_correct task):

[2020-01-31 15:13:00,867: INFO/MainProcess] Received task: app.tasks.bug.task_correct[d9dd4fb3-8df9-4c39-8b3d-e8892f9d6fef]  
[2020-01-31 15:13:00,928: INFO/MainProcess] Received task: app.tasks.bug.a[e7eb341f-3c10-4bb0-9dee-2cfa38354005]  
[2020-01-31 15:13:00,939: INFO/MainProcess] Received task: app.tasks.bug.a[c13967b3-b53a-4005-9249-dffa4b6122af]  
[2020-01-31 15:13:00,941: INFO/ForkPoolWorker-8] Task app.tasks.bug.task_correct[d9dd4fb3-8df9-4c39-8b3d-e8892f9d6fef] succeeded in 0.07147384795825928s: None
[2020-01-31 15:13:01,974: INFO/MainProcess] Received task: app.tasks.bug.b[88ceb430-5056-40a1-ae82-cfd95d27845e]  
[2020-01-31 15:13:01,977: INFO/MainProcess] Received task: app.tasks.bug.b[3a354338-edb7-447b-9d40-855e9e386531]  
[2020-01-31 15:13:01,977: INFO/ForkPoolWorker-9] Task app.tasks.bug.a[e7eb341f-3c10-4bb0-9dee-2cfa38354005] succeeded in 1.0470000900095329s: None
[2020-01-31 15:13:01,978: INFO/ForkPoolWorker-8] Task app.tasks.bug.b[88ceb430-5056-40a1-ae82-cfd95d27845e] succeeded in 0.0024882910074666142s: None
[2020-01-31 15:13:02,008: INFO/MainProcess] Received task: app.tasks.bug.dummy[2b9094d8-fe73-43b3-9a2a-c5ad756b3e22]  
[2020-01-31 15:13:02,009: INFO/ForkPoolWorker-3] Task app.tasks.bug.b[3a354338-edb7-447b-9d40-855e9e386531] succeeded in 0.02914690098259598s: None
[2020-01-31 15:13:02,013: INFO/ForkPoolWorker-8] Task app.tasks.bug.dummy[2b9094d8-fe73-43b3-9a2a-c5ad756b3e22] succeeded in 0.002397596021182835s: None
[2020-01-31 15:13:03,989: INFO/MainProcess] Received task: app.tasks.bug.b[fafd28c6-55d0-41c5-a035-1d4da0d6067b]  
[2020-01-31 15:13:03,992: INFO/MainProcess] Received task: app.tasks.bug.b[ea8c9c21-f860-4268-b44c-6faa8ba66dc2]  
[2020-01-31 15:13:03,993: INFO/ForkPoolWorker-8] Task app.tasks.bug.b[fafd28c6-55d0-41c5-a035-1d4da0d6067b] succeeded in 0.0024769710144028068s: None
[2020-01-31 15:13:03,994: INFO/ForkPoolWorker-2] Task app.tasks.bug.a[c13967b3-b53a-4005-9249-dffa4b6122af] succeeded in 3.050520417978987s: None
[2020-01-31 15:13:04,001: INFO/ForkPoolWorker-9] Task app.tasks.bug.b[ea8c9c21-f860-4268-b44c-6faa8ba66dc2] succeeded in 0.006369335926137865s: None
[2020-01-31 15:13:04,001: INFO/MainProcess] Received task: app.tasks.bug.dummy[998aa572-9010-4991-856a-191cf1741680]  
[2020-01-31 15:13:04,021: INFO/MainProcess] Received task: app.tasks.bug.c[976f5323-1505-41c6-ad01-e0e720c4b5c7]  
[2020-01-31 15:13:04,021: INFO/ForkPoolWorker-8] Task app.tasks.bug.dummy[998aa572-9010-4991-856a-191cf1741680] succeeded in 0.018995660939253867s: None
[2020-01-31 15:13:04,023: INFO/ForkPoolWorker-9] Task app.tasks.bug.c[976f5323-1505-41c6-ad01-e0e720c4b5c7] succeeded in 0.0012671550503000617s: None

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions