New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tasks received but not executing #3759

Open
grantmcconnaughey opened this Issue Jan 13, 2017 · 24 comments

Comments

@grantmcconnaughey

grantmcconnaughey commented Jan 13, 2017

I have tasks that are received but will not execute. This the output of celery worker:

$ celery worker -A myapp.celeryapp --loglevel=INFO
[tasks]
  . myapp.tasks.trigger_build

[2017-01-12 23:34:25,206: INFO/MainProcess] Connected to sqs://13245:**@localhost//
[2017-01-12 23:34:25,391: INFO/MainProcess] celery@ip-111-11-11-11 ready.
[2017-01-12 23:34:27,700: INFO/MainProcess] Received task: myapp.tasks.trigger_build[b248771c-6dd5-469d-bc53-eaf63c4f6b60]

I have tried adding -Ofair when running celery worker but that did not help. Some other info that might be helpful:

  • Celery always receives 8 tasks, although there are about 100 messages waiting to be picked up.
  • About once in every 4 or 5 times a task actually will run and complete, but then it gets stuck again.
  • This is the result of ps aux. Notice that it is running celery in 3 different processes (not sure why) and one of them has 99.6% CPU utilization, even though it's not completing any tasks or anything.
$ ps aux | grep celery
nobody    7034 99.6  1.8 382688 74048 ?        R    05:22  18:19 python2.7 celery worker -A myapp.celeryapp --loglevel=INFO
nobody    7039  0.0  1.3 246672 55664 ?        S    05:22   0:00 python2.7 celery worker -A myapp.celeryapp --loglevel=INFO
nobody    7040  0.0  1.3 246672 55632 ?        S    05:22   0:00 python2.7 celery worker -A myapp.celeryapp --loglevel=INFO

Steps to reproduce

Below are my settings and report.

CELERY_BROKER_URL = 'sqs://%s:%s@' % (AWS_ACCESS_KEY_ID, AWS_SECRET_ACCESS_KEY.replace('/', '%2F'))
CELERY_BROKER_TRANSPORT = 'sqs'
CELERY_BROKER_TRANSPORT_OPTIONS = {
    'region': 'us-east-1',
    'visibility_timeout': 60 * 30,
    'polling_interval': 0.3,
    'queue_name_prefix': 'myapp-',
}
CELERY_BROKER_HEARTBEAT = 0
CELERY_BROKER_POOL_LIMIT = 1
CELERY_BROKER_CONNECTION_TIMEOUT = 10

CELERY_DEFAULT_QUEUE = 'myapp'
CELERY_QUEUES = (
    Queue('myapp', Exchange('default'), routing_key='default'),
)

CELERY_ALWAYS_EAGER = False
CELERY_ACKS_LATE = True
CELERY_TASK_PUBLISH_RETRY = True
CELERY_DISABLE_RATE_LIMITS = False

CELERY_IGNORE_RESULT = True
CELERY_SEND_TASK_ERROR_EMAILS = False
CELERY_TASK_RESULT_EXPIRES = 600

CELERY_RESULT_BACKEND = 'django-db'
CELERY_TIMEZONE = TIME_ZONE

CELERY_TASK_SERIALIZER = 'json'
CELERY_ACCEPT_CONTENT = ['application/json']

CELERYD_PID_FILE = "/var/celery_%N.pid"
CELERYD_HIJACK_ROOT_LOGGER = False
CELERYD_PREFETCH_MULTIPLIER = 1
CELERYD_MAX_TASKS_PER_CHILD = 1000
$ celery report -A myapp.celeryapp

software -> celery:4.0.2 (latentcall) kombu:4.0.2 py:2.7.12
            billiard:3.5.0.2 sqs:N/A
platform -> system:Linux arch:64bit, ELF imp:CPython
loader   -> celery.loaders.app.AppLoader
settings -> transport:sqs results:django-db

Expected behavior

I expect the jobs to be picked up and executed.

Actual behavior

The tasks are received but nothing happens. My celery log file contains nothing except that the task was received.

@anekix

This comment has been minimized.

Show comment
Hide comment
@anekix

anekix Jan 13, 2017

Did you try using loglevel=DEBUG ? what messages you get?

anekix commented Jan 13, 2017

Did you try using loglevel=DEBUG ? what messages you get?

@grantmcconnaughey

This comment has been minimized.

Show comment
Hide comment
@grantmcconnaughey

grantmcconnaughey Jan 13, 2017

Hey @anekix, here is the output when using loglevel=debug:

Click me
[2017-01-12 22:54:08,512: DEBUG/MainProcess] | Worker: Preparing bootsteps.
[2017-01-12 22:54:08,513: DEBUG/MainProcess] | Worker: Building graph...
[2017-01-12 22:54:08,513: DEBUG/MainProcess] | Worker: New boot order: {Beat, Timer, Hub, Pool, Autoscaler, StateDB, Consumer}
[2017-01-12 22:54:08,571: DEBUG/MainProcess] | Consumer: Preparing bootsteps.
[2017-01-12 22:54:08,571: DEBUG/MainProcess] | Consumer: Building graph...
[2017-01-12 22:54:08,614: DEBUG/MainProcess] | Consumer: New boot order: {Connection, Events, Mingle, Tasks, Control, Agent, Heart, Gossip, event loop}

 -------------- celery@ip-172-31-29-186 v4.0.2 (latentcall)
---- **** -----
--- * ***  * -- Linux-4.4.35-33.55.amzn1.x86_64-x86_64-with-glibc2.2.5 2017-01-12 22:54:08
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> app:         myapp:0x7fee4e3f6c50
- ** ---------- .> transport:   sqs://12345:**@localhost//
- ** ---------- .> results:
- *** --- * --- .> concurrency: 2 (prefork)
-- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
--- ***** -----
 -------------- [queues]
                .> celery           exchange=celery(direct) key=celery


[tasks]
  . celery.accumulate
  . celery.backend_cleanup
  . celery.chain
  . celery.chord
  . celery.chord_unlock
  . celery.chunks
  . celery.group
  . celery.map
  . celery.starmap
  . myapp.utils.trigger_build

[2017-01-12 22:54:08,674: DEBUG/MainProcess] | Worker: Starting Hub
[2017-01-12 22:54:08,674: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:08,675: DEBUG/MainProcess] | Worker: Starting Pool
[2017-01-12 22:54:09,051: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,052: DEBUG/MainProcess] | Worker: Starting Consumer
[2017-01-12 22:54:09,052: DEBUG/MainProcess] | Consumer: Starting Connection
[2017-01-12 22:54:09,112: DEBUG/MainProcess] Using access key provided by client.
[2017-01-12 22:54:09,112: DEBUG/MainProcess] Using secret key provided by client.
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Method: GET
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Path: /
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Data:
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Headers: {}
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Host: queue.amazonaws.com
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Port: 443
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Params: {'Action': 'ListQueues', 'Version': '2012-11-05', 'QueueNamePrefix': 'myapp-'}
[2017-01-12 22:54:09,130: DEBUG/MainProcess] establishing HTTPS connection: host=queue.amazonaws.com, kwargs={'port': 443, 'timeout': 70}
[2017-01-12 22:54:09,130: DEBUG/MainProcess] Token: None
[2017-01-12 22:54:09,130: DEBUG/MainProcess] CanonicalRequest:
GET
/
Action=ListQueues&QueueNamePrefix=myapp-&Version=2012-11-05
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,131: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
8065b7fac1faba261c990901ca5abcb1a550dee6d4f659a0c3cdce0b8bf196f7
[2017-01-12 22:54:09,131: DEBUG/MainProcess] Signature:
474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee
[2017-01-12 22:54:09,131: DEBUG/MainProcess] Final headers: {'Content-Length': '0', 'Host': u'queue.amazonaws.com', 'Authorization': u'AWS4-HMAC-SHA256 Credential=sqsusername/20170113/us-east-1/sqs/aws4_request,SignedHeaders=host;x-amz-date,Signature=474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee', 'X-Amz-Date': '20170113T045409Z', 'User-Agent': 'Boto/2.45.0 Python/2.7.12 Linux/4.4.35-33.55.amzn1.x86_64'}
[2017-01-12 22:54:09,143: DEBUG/MainProcess] wrapping ssl socket; CA certificate file=/opt/python/run/venv/local/lib/python2.7/site-packages/boto/cacerts/cacerts.txt
[2017-01-12 22:54:09,203: DEBUG/MainProcess] validating server certificate: hostname=queue.amazonaws.com, certificate hosts=['sqs.us-east-1.amazonaws.com', 'queue.amazonaws.com']
[2017-01-12 22:54:09,224: DEBUG/MainProcess] Response headers: [('x-amzn-requestid', 'a6bf1f03-1f97-5191-b903-4ff14026ecde'), ('content-length', '321'), ('server', 'Server'), ('connection', 'keep-alive'), ('date', 'Fri, 13 Jan 2017 04:54:09 GMT'), ('content-type', 'text/xml')]
[2017-01-12 22:54:09,224: DEBUG/MainProcess] <?xml version="1.0"?><ListQueuesResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/"><ListQueuesResult><QueueUrl>https://queue.amazonaws.com/634337638384/myapp-celery</QueueUrl></ListQueuesResult><ResponseMetadata><RequestId>a6bf1f03-1f97-5191-b903-4ff14026ecde</RequestId></ResponseMetadata></ListQueuesResponse>
[2017-01-12 22:54:09,226: INFO/MainProcess] Connected to sqs://sqsusername:**@localhost//
[2017-01-12 22:54:09,226: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,226: DEBUG/MainProcess] | Consumer: Starting Events
[2017-01-12 22:54:09,248: DEBUG/MainProcess] Using access key provided by client.
[2017-01-12 22:54:09,248: DEBUG/MainProcess] Using secret key provided by client.
[2017-01-12 22:54:09,248: DEBUG/MainProcess] Method: GET
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Path: /
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Data:
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Headers: {}
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Host: queue.amazonaws.com
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Port: 443
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Params: {'Action': 'ListQueues', 'Version': '2012-11-05', 'QueueNamePrefix': 'myapp-'}
[2017-01-12 22:54:09,249: DEBUG/MainProcess] establishing HTTPS connection: host=queue.amazonaws.com, kwargs={'port': 443, 'timeout': 70}
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Token: None
[2017-01-12 22:54:09,250: DEBUG/MainProcess] CanonicalRequest:
GET
/
Action=ListQueues&QueueNamePrefix=myapp-&Version=2012-11-05
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,250: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
8065b7fac1faba261c990901ca5abcb1a550dee6d4f659a0c3cdce0b8bf196f7
[2017-01-12 22:54:09,250: DEBUG/MainProcess] Signature:
474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee
[2017-01-12 22:54:09,250: DEBUG/MainProcess] Final headers: {'Content-Length': '0', 'Host': u'queue.amazonaws.com', 'Authorization': u'AWS4-HMAC-SHA256 Credential=sqsusername/20170113/us-east-1/sqs/aws4_request,SignedHeaders=host;x-amz-date,Signature=474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee', 'X-Amz-Date': '20170113T045409Z', 'User-Agent': 'Boto/2.45.0 Python/2.7.12 Linux/4.4.35-33.55.amzn1.x86_64'}
[2017-01-12 22:54:09,265: DEBUG/MainProcess] wrapping ssl socket; CA certificate file=/opt/python/run/venv/local/lib/python2.7/site-packages/boto/cacerts/cacerts.txt
[2017-01-12 22:54:09,324: DEBUG/MainProcess] validating server certificate: hostname=queue.amazonaws.com, certificate hosts=['sqs.us-east-1.amazonaws.com', 'queue.amazonaws.com']
[2017-01-12 22:54:09,345: DEBUG/MainProcess] Response headers: [('x-amzn-requestid', 'becab27e-0829-501e-82f1-e28c5798fced'), ('content-length', '321'), ('server', 'Server'), ('connection', 'keep-alive'), ('date', 'Fri, 13 Jan 2017 04:54:09 GMT'), ('content-type', 'text/xml')]
[2017-01-12 22:54:09,346: DEBUG/MainProcess] <?xml version="1.0"?><ListQueuesResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/"><ListQueuesResult><QueueUrl>https://queue.amazonaws.com/634337638384/myapp-celery</QueueUrl></ListQueuesResult><ResponseMetadata><RequestId>becab27e-0829-501e-82f1-e28c5798fced</RequestId></ResponseMetadata></ListQueuesResponse>
[2017-01-12 22:54:09,346: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,347: DEBUG/MainProcess] | Consumer: Starting Tasks
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Method: GET
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Path: /634337638384/myapp-celery
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Data:
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Headers: {}
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Host: queue.amazonaws.com
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Port: 443
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Params: {'Action': 'GetQueueAttributes', 'Version': '2012-11-05', 'AttributeName': 'ApproximateNumberOfMessages'}
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Token: None
[2017-01-12 22:54:09,350: DEBUG/MainProcess] CanonicalRequest:
GET
/634337638384/myapp-celery
Action=GetQueueAttributes&AttributeName=ApproximateNumberOfMessages&Version=2012-11-05
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,350: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
1836657840ef8f87ff2c004e5cb4d4df1872363ed72ccd2a1cc7ea42d30d89ce
[2017-01-12 22:54:09,350: DEBUG/MainProcess] Signature:
5a7b82b74e92a591dd16e7df10723fe9131ff1f4edae117ea3e937631cc0a247
[2017-01-12 22:54:09,350: DEBUG/MainProcess] Final headers: {'Content-Length': '0', 'Host': u'queue.amazonaws.com', 'Authorization': u'AWS4-HMAC-SHA256 Credential=sqsusername/20170113/us-east-1/sqs/aws4_request,SignedHeaders=host;x-amz-date,Signature=5a7b82b74e92a591dd16e7df10723fe9131ff1f4edae117ea3e937631cc0a247', 'X-Amz-Date': '20170113T045409Z', 'User-Agent': 'Boto/2.45.0 Python/2.7.12 Linux/4.4.35-33.55.amzn1.x86_64'}
[2017-01-12 22:54:09,365: DEBUG/MainProcess] Response headers: [('x-amzn-requestid', 'f9638762-8b99-5fc3-991a-d790d428b330'), ('content-length', '358'), ('server', 'Server'), ('connection', 'keep-alive'), ('date', 'Fri, 13 Jan 2017 04:54:09 GMT'), ('content-type', 'text/xml')]
[2017-01-12 22:54:09,366: DEBUG/MainProcess] <?xml version="1.0"?><GetQueueAttributesResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/"><GetQueueAttributesResult><Attribute><Name>ApproximateNumberOfMessages</Name><Value>98</Value></Attribute></GetQueueAttributesResult><ResponseMetadata><RequestId>f9638762-8b99-5fc3-991a-d790d428b330</RequestId></ResponseMetadata></GetQueueAttributesResponse>
[2017-01-12 22:54:09,366: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,366: DEBUG/MainProcess] | Consumer: Starting Heart
[2017-01-12 22:54:09,367: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,367: DEBUG/MainProcess] | Consumer: Starting event loop
[2017-01-12 22:54:09,367: INFO/MainProcess] celery@ip-172-31-29-186 ready.
[2017-01-12 22:54:09,367: DEBUG/MainProcess] | Worker: Hub.register Pool...
[2017-01-12 22:54:09,368: DEBUG/MainProcess] basic.qos: prefetch_count->8
[2017-01-12 22:54:09,407: DEBUG/MainProcess] Using access key provided by client.
[2017-01-12 22:54:09,407: DEBUG/MainProcess] Using secret key provided by client.
[2017-01-12 22:54:09,407: DEBUG/MainProcess] HTTP queue.amazonaws.com//634337638384/myapp-celery headers={} body=
[2017-01-12 22:54:09,408: DEBUG/MainProcess] CanonicalRequest:
GET
/634337638384/myapp-celery
Action=ReceiveMessage&MaxNumberOfMessages=8&Version=2012-11-05&WaitTimeSeconds=10
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,408: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
0619f00c31c123e8d41136f1c249e7a2fd53e92a4a465a8a34ad123019528483
[2017-01-12 22:54:09,408: DEBUG/MainProcess] Signature:
96dae1d75e731b8c101fb360903bc4a52dad60e9c69f07e291c729a19e826bd5
[2017-01-12 22:54:11,688: INFO/MainProcess] Received task: myapp.utils.trigger_build[860a2935-b4b5-4dff-958d-fa073af7a50d]
[2017-01-12 22:54:11,688: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fee4dccc7d0> (args:(u'myapp.utils.trigger_build', u'860a2935-b4b5-4dff-958d-fa073af7a50d', {u'origin': u'gen30688@ip-172-31-29-186', u'lang': u'py', u'task': u'myapp.utils.trigger_build', u'group': None, u'root_id': u'860a2935-b4b5-4dff-958d-fa073af7a50d', u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'celery', u'exchange': u''}, u'expires': None, u'correlation_id': u'860a2935-b4b5-4dff-958d-fa073af7a50d', u'retries': 0, u'timelimit': [None, None], u'argsrepr': u'(278,)', u'eta': None, u'parent_id': None, u'reply_to': u'42d01bf5-595c-389b-8f3d-49e6440a7c03', u'id': u'860a2935-b4b5-4dff-958d-fa073af7a50d', u'kwargsrepr': u"{'branch': 'pyup-initial-update', 'commit_sha': 'f584425dc400384cff7bf36444ef1e6ea0a4063a'}"}, '[[278], {"branch": "pyup-initial-update", "commit_sha": "f584425dc400384cff7bf36444ef1e6ea0a4063a"}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', u'application/json', u'utf-8') kwargs:{})
[2017-01-12 22:54:11,688: INFO/MainProcess] Received task: myapp.utils.trigger_build[5a478d2a-57aa-4a20-bb2f-006c0088f998]
[2017-01-12 22:54:11,689: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fee4dccc7d0> (args:(u'myapp.utils.trigger_build', u'5a478d2a-57aa-4a20-bb2f-006c0088f998', {u'origin': u'gen30688@ip-172-31-29-186', u'lang': u'py', u'task': u'myapp.utils.trigger_build', u'group': None, u'root_id': u'5a478d2a-57aa-4a20-bb2f-006c0088f998', u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'celery', u'exchange': u''}, u'expires': None, u'correlation_id': u'5a478d2a-57aa-4a20-bb2f-006c0088f998', u'retries': 0, u'timelimit': [None, None], u'argsrepr': u'(278,)', u'eta': None, u'parent_id': None, u'reply_to': u'42d01bf5-595c-389b-8f3d-49e6440a7c03', u'id': u'5a478d2a-57aa-4a20-bb2f-006c0088f998', u'kwargsrepr': u"{'branch': 'pyup-initial-update', 'commit_sha': 'a58f4a736fd8ceefb8cb114dc0455bf6bd08e352'}"}, '[[278], {"branch": "pyup-initial-update", "commit_sha": "a58f4a736fd8ceefb8cb114dc0455bf6bd08e352"}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', u'application/json', u'utf-8') kwargs:{})
[2017-01-12 22:54:11,689: INFO/MainProcess] Received task: myapp.utils.trigger_build[0aee79e5-68e9-43a3-84a2-906a18da51f0]
[2017-01-12 22:54:11,689: INFO/MainProcess] Received task: myapp.utils.trigger_build[6d3e6431-254c-4abb-ab69-16fcb7c08494]
[2017-01-12 22:54:11,689: INFO/MainProcess] Received task: myapp.utils.trigger_build[c8ea784d-23c3-4961-89b1-5e31044baa78]
[2017-01-12 22:54:11,690: INFO/MainProcess] Received task: myapp.utils.trigger_build[699595ba-22d9-4af4-b21c-6cc247c6a5f2]
[2017-01-12 22:54:11,690: INFO/MainProcess] Received task: myapp.utils.trigger_build[24d8d627-c07b-497c-a138-4275298c0b3a]
[2017-01-12 22:54:11,690: INFO/MainProcess] Received task: myapp.utils.trigger_build[6ccefa24-39e7-4093-b4be-bf06dcb6b382]

grantmcconnaughey commented Jan 13, 2017

Hey @anekix, here is the output when using loglevel=debug:

Click me
[2017-01-12 22:54:08,512: DEBUG/MainProcess] | Worker: Preparing bootsteps.
[2017-01-12 22:54:08,513: DEBUG/MainProcess] | Worker: Building graph...
[2017-01-12 22:54:08,513: DEBUG/MainProcess] | Worker: New boot order: {Beat, Timer, Hub, Pool, Autoscaler, StateDB, Consumer}
[2017-01-12 22:54:08,571: DEBUG/MainProcess] | Consumer: Preparing bootsteps.
[2017-01-12 22:54:08,571: DEBUG/MainProcess] | Consumer: Building graph...
[2017-01-12 22:54:08,614: DEBUG/MainProcess] | Consumer: New boot order: {Connection, Events, Mingle, Tasks, Control, Agent, Heart, Gossip, event loop}

 -------------- celery@ip-172-31-29-186 v4.0.2 (latentcall)
---- **** -----
--- * ***  * -- Linux-4.4.35-33.55.amzn1.x86_64-x86_64-with-glibc2.2.5 2017-01-12 22:54:08
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> app:         myapp:0x7fee4e3f6c50
- ** ---------- .> transport:   sqs://12345:**@localhost//
- ** ---------- .> results:
- *** --- * --- .> concurrency: 2 (prefork)
-- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
--- ***** -----
 -------------- [queues]
                .> celery           exchange=celery(direct) key=celery


[tasks]
  . celery.accumulate
  . celery.backend_cleanup
  . celery.chain
  . celery.chord
  . celery.chord_unlock
  . celery.chunks
  . celery.group
  . celery.map
  . celery.starmap
  . myapp.utils.trigger_build

[2017-01-12 22:54:08,674: DEBUG/MainProcess] | Worker: Starting Hub
[2017-01-12 22:54:08,674: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:08,675: DEBUG/MainProcess] | Worker: Starting Pool
[2017-01-12 22:54:09,051: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,052: DEBUG/MainProcess] | Worker: Starting Consumer
[2017-01-12 22:54:09,052: DEBUG/MainProcess] | Consumer: Starting Connection
[2017-01-12 22:54:09,112: DEBUG/MainProcess] Using access key provided by client.
[2017-01-12 22:54:09,112: DEBUG/MainProcess] Using secret key provided by client.
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Method: GET
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Path: /
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Data:
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Headers: {}
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Host: queue.amazonaws.com
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Port: 443
[2017-01-12 22:54:09,113: DEBUG/MainProcess] Params: {'Action': 'ListQueues', 'Version': '2012-11-05', 'QueueNamePrefix': 'myapp-'}
[2017-01-12 22:54:09,130: DEBUG/MainProcess] establishing HTTPS connection: host=queue.amazonaws.com, kwargs={'port': 443, 'timeout': 70}
[2017-01-12 22:54:09,130: DEBUG/MainProcess] Token: None
[2017-01-12 22:54:09,130: DEBUG/MainProcess] CanonicalRequest:
GET
/
Action=ListQueues&QueueNamePrefix=myapp-&Version=2012-11-05
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,131: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
8065b7fac1faba261c990901ca5abcb1a550dee6d4f659a0c3cdce0b8bf196f7
[2017-01-12 22:54:09,131: DEBUG/MainProcess] Signature:
474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee
[2017-01-12 22:54:09,131: DEBUG/MainProcess] Final headers: {'Content-Length': '0', 'Host': u'queue.amazonaws.com', 'Authorization': u'AWS4-HMAC-SHA256 Credential=sqsusername/20170113/us-east-1/sqs/aws4_request,SignedHeaders=host;x-amz-date,Signature=474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee', 'X-Amz-Date': '20170113T045409Z', 'User-Agent': 'Boto/2.45.0 Python/2.7.12 Linux/4.4.35-33.55.amzn1.x86_64'}
[2017-01-12 22:54:09,143: DEBUG/MainProcess] wrapping ssl socket; CA certificate file=/opt/python/run/venv/local/lib/python2.7/site-packages/boto/cacerts/cacerts.txt
[2017-01-12 22:54:09,203: DEBUG/MainProcess] validating server certificate: hostname=queue.amazonaws.com, certificate hosts=['sqs.us-east-1.amazonaws.com', 'queue.amazonaws.com']
[2017-01-12 22:54:09,224: DEBUG/MainProcess] Response headers: [('x-amzn-requestid', 'a6bf1f03-1f97-5191-b903-4ff14026ecde'), ('content-length', '321'), ('server', 'Server'), ('connection', 'keep-alive'), ('date', 'Fri, 13 Jan 2017 04:54:09 GMT'), ('content-type', 'text/xml')]
[2017-01-12 22:54:09,224: DEBUG/MainProcess] <?xml version="1.0"?><ListQueuesResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/"><ListQueuesResult><QueueUrl>https://queue.amazonaws.com/634337638384/myapp-celery</QueueUrl></ListQueuesResult><ResponseMetadata><RequestId>a6bf1f03-1f97-5191-b903-4ff14026ecde</RequestId></ResponseMetadata></ListQueuesResponse>
[2017-01-12 22:54:09,226: INFO/MainProcess] Connected to sqs://sqsusername:**@localhost//
[2017-01-12 22:54:09,226: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,226: DEBUG/MainProcess] | Consumer: Starting Events
[2017-01-12 22:54:09,248: DEBUG/MainProcess] Using access key provided by client.
[2017-01-12 22:54:09,248: DEBUG/MainProcess] Using secret key provided by client.
[2017-01-12 22:54:09,248: DEBUG/MainProcess] Method: GET
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Path: /
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Data:
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Headers: {}
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Host: queue.amazonaws.com
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Port: 443
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Params: {'Action': 'ListQueues', 'Version': '2012-11-05', 'QueueNamePrefix': 'myapp-'}
[2017-01-12 22:54:09,249: DEBUG/MainProcess] establishing HTTPS connection: host=queue.amazonaws.com, kwargs={'port': 443, 'timeout': 70}
[2017-01-12 22:54:09,249: DEBUG/MainProcess] Token: None
[2017-01-12 22:54:09,250: DEBUG/MainProcess] CanonicalRequest:
GET
/
Action=ListQueues&QueueNamePrefix=myapp-&Version=2012-11-05
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,250: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
8065b7fac1faba261c990901ca5abcb1a550dee6d4f659a0c3cdce0b8bf196f7
[2017-01-12 22:54:09,250: DEBUG/MainProcess] Signature:
474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee
[2017-01-12 22:54:09,250: DEBUG/MainProcess] Final headers: {'Content-Length': '0', 'Host': u'queue.amazonaws.com', 'Authorization': u'AWS4-HMAC-SHA256 Credential=sqsusername/20170113/us-east-1/sqs/aws4_request,SignedHeaders=host;x-amz-date,Signature=474691a52ba85c3c842e5ecb29eadbcf693a5388e8c17a2706291151c93cfaee', 'X-Amz-Date': '20170113T045409Z', 'User-Agent': 'Boto/2.45.0 Python/2.7.12 Linux/4.4.35-33.55.amzn1.x86_64'}
[2017-01-12 22:54:09,265: DEBUG/MainProcess] wrapping ssl socket; CA certificate file=/opt/python/run/venv/local/lib/python2.7/site-packages/boto/cacerts/cacerts.txt
[2017-01-12 22:54:09,324: DEBUG/MainProcess] validating server certificate: hostname=queue.amazonaws.com, certificate hosts=['sqs.us-east-1.amazonaws.com', 'queue.amazonaws.com']
[2017-01-12 22:54:09,345: DEBUG/MainProcess] Response headers: [('x-amzn-requestid', 'becab27e-0829-501e-82f1-e28c5798fced'), ('content-length', '321'), ('server', 'Server'), ('connection', 'keep-alive'), ('date', 'Fri, 13 Jan 2017 04:54:09 GMT'), ('content-type', 'text/xml')]
[2017-01-12 22:54:09,346: DEBUG/MainProcess] <?xml version="1.0"?><ListQueuesResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/"><ListQueuesResult><QueueUrl>https://queue.amazonaws.com/634337638384/myapp-celery</QueueUrl></ListQueuesResult><ResponseMetadata><RequestId>becab27e-0829-501e-82f1-e28c5798fced</RequestId></ResponseMetadata></ListQueuesResponse>
[2017-01-12 22:54:09,346: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,347: DEBUG/MainProcess] | Consumer: Starting Tasks
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Method: GET
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Path: /634337638384/myapp-celery
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Data:
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Headers: {}
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Host: queue.amazonaws.com
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Port: 443
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Params: {'Action': 'GetQueueAttributes', 'Version': '2012-11-05', 'AttributeName': 'ApproximateNumberOfMessages'}
[2017-01-12 22:54:09,349: DEBUG/MainProcess] Token: None
[2017-01-12 22:54:09,350: DEBUG/MainProcess] CanonicalRequest:
GET
/634337638384/myapp-celery
Action=GetQueueAttributes&AttributeName=ApproximateNumberOfMessages&Version=2012-11-05
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,350: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
1836657840ef8f87ff2c004e5cb4d4df1872363ed72ccd2a1cc7ea42d30d89ce
[2017-01-12 22:54:09,350: DEBUG/MainProcess] Signature:
5a7b82b74e92a591dd16e7df10723fe9131ff1f4edae117ea3e937631cc0a247
[2017-01-12 22:54:09,350: DEBUG/MainProcess] Final headers: {'Content-Length': '0', 'Host': u'queue.amazonaws.com', 'Authorization': u'AWS4-HMAC-SHA256 Credential=sqsusername/20170113/us-east-1/sqs/aws4_request,SignedHeaders=host;x-amz-date,Signature=5a7b82b74e92a591dd16e7df10723fe9131ff1f4edae117ea3e937631cc0a247', 'X-Amz-Date': '20170113T045409Z', 'User-Agent': 'Boto/2.45.0 Python/2.7.12 Linux/4.4.35-33.55.amzn1.x86_64'}
[2017-01-12 22:54:09,365: DEBUG/MainProcess] Response headers: [('x-amzn-requestid', 'f9638762-8b99-5fc3-991a-d790d428b330'), ('content-length', '358'), ('server', 'Server'), ('connection', 'keep-alive'), ('date', 'Fri, 13 Jan 2017 04:54:09 GMT'), ('content-type', 'text/xml')]
[2017-01-12 22:54:09,366: DEBUG/MainProcess] <?xml version="1.0"?><GetQueueAttributesResponse xmlns="http://queue.amazonaws.com/doc/2012-11-05/"><GetQueueAttributesResult><Attribute><Name>ApproximateNumberOfMessages</Name><Value>98</Value></Attribute></GetQueueAttributesResult><ResponseMetadata><RequestId>f9638762-8b99-5fc3-991a-d790d428b330</RequestId></ResponseMetadata></GetQueueAttributesResponse>
[2017-01-12 22:54:09,366: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,366: DEBUG/MainProcess] | Consumer: Starting Heart
[2017-01-12 22:54:09,367: DEBUG/MainProcess] ^-- substep ok
[2017-01-12 22:54:09,367: DEBUG/MainProcess] | Consumer: Starting event loop
[2017-01-12 22:54:09,367: INFO/MainProcess] celery@ip-172-31-29-186 ready.
[2017-01-12 22:54:09,367: DEBUG/MainProcess] | Worker: Hub.register Pool...
[2017-01-12 22:54:09,368: DEBUG/MainProcess] basic.qos: prefetch_count->8
[2017-01-12 22:54:09,407: DEBUG/MainProcess] Using access key provided by client.
[2017-01-12 22:54:09,407: DEBUG/MainProcess] Using secret key provided by client.
[2017-01-12 22:54:09,407: DEBUG/MainProcess] HTTP queue.amazonaws.com//634337638384/myapp-celery headers={} body=
[2017-01-12 22:54:09,408: DEBUG/MainProcess] CanonicalRequest:
GET
/634337638384/myapp-celery
Action=ReceiveMessage&MaxNumberOfMessages=8&Version=2012-11-05&WaitTimeSeconds=10
host:queue.amazonaws.com
x-amz-date:20170113T045409Z

host;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
[2017-01-12 22:54:09,408: DEBUG/MainProcess] StringToSign:
AWS4-HMAC-SHA256
20170113T045409Z
20170113/us-east-1/sqs/aws4_request
0619f00c31c123e8d41136f1c249e7a2fd53e92a4a465a8a34ad123019528483
[2017-01-12 22:54:09,408: DEBUG/MainProcess] Signature:
96dae1d75e731b8c101fb360903bc4a52dad60e9c69f07e291c729a19e826bd5
[2017-01-12 22:54:11,688: INFO/MainProcess] Received task: myapp.utils.trigger_build[860a2935-b4b5-4dff-958d-fa073af7a50d]
[2017-01-12 22:54:11,688: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fee4dccc7d0> (args:(u'myapp.utils.trigger_build', u'860a2935-b4b5-4dff-958d-fa073af7a50d', {u'origin': u'gen30688@ip-172-31-29-186', u'lang': u'py', u'task': u'myapp.utils.trigger_build', u'group': None, u'root_id': u'860a2935-b4b5-4dff-958d-fa073af7a50d', u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'celery', u'exchange': u''}, u'expires': None, u'correlation_id': u'860a2935-b4b5-4dff-958d-fa073af7a50d', u'retries': 0, u'timelimit': [None, None], u'argsrepr': u'(278,)', u'eta': None, u'parent_id': None, u'reply_to': u'42d01bf5-595c-389b-8f3d-49e6440a7c03', u'id': u'860a2935-b4b5-4dff-958d-fa073af7a50d', u'kwargsrepr': u"{'branch': 'pyup-initial-update', 'commit_sha': 'f584425dc400384cff7bf36444ef1e6ea0a4063a'}"}, '[[278], {"branch": "pyup-initial-update", "commit_sha": "f584425dc400384cff7bf36444ef1e6ea0a4063a"}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', u'application/json', u'utf-8') kwargs:{})
[2017-01-12 22:54:11,688: INFO/MainProcess] Received task: myapp.utils.trigger_build[5a478d2a-57aa-4a20-bb2f-006c0088f998]
[2017-01-12 22:54:11,689: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fee4dccc7d0> (args:(u'myapp.utils.trigger_build', u'5a478d2a-57aa-4a20-bb2f-006c0088f998', {u'origin': u'gen30688@ip-172-31-29-186', u'lang': u'py', u'task': u'myapp.utils.trigger_build', u'group': None, u'root_id': u'5a478d2a-57aa-4a20-bb2f-006c0088f998', u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'celery', u'exchange': u''}, u'expires': None, u'correlation_id': u'5a478d2a-57aa-4a20-bb2f-006c0088f998', u'retries': 0, u'timelimit': [None, None], u'argsrepr': u'(278,)', u'eta': None, u'parent_id': None, u'reply_to': u'42d01bf5-595c-389b-8f3d-49e6440a7c03', u'id': u'5a478d2a-57aa-4a20-bb2f-006c0088f998', u'kwargsrepr': u"{'branch': 'pyup-initial-update', 'commit_sha': 'a58f4a736fd8ceefb8cb114dc0455bf6bd08e352'}"}, '[[278], {"branch": "pyup-initial-update", "commit_sha": "a58f4a736fd8ceefb8cb114dc0455bf6bd08e352"}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', u'application/json', u'utf-8') kwargs:{})
[2017-01-12 22:54:11,689: INFO/MainProcess] Received task: myapp.utils.trigger_build[0aee79e5-68e9-43a3-84a2-906a18da51f0]
[2017-01-12 22:54:11,689: INFO/MainProcess] Received task: myapp.utils.trigger_build[6d3e6431-254c-4abb-ab69-16fcb7c08494]
[2017-01-12 22:54:11,689: INFO/MainProcess] Received task: myapp.utils.trigger_build[c8ea784d-23c3-4961-89b1-5e31044baa78]
[2017-01-12 22:54:11,690: INFO/MainProcess] Received task: myapp.utils.trigger_build[699595ba-22d9-4af4-b21c-6cc247c6a5f2]
[2017-01-12 22:54:11,690: INFO/MainProcess] Received task: myapp.utils.trigger_build[24d8d627-c07b-497c-a138-4275298c0b3a]
[2017-01-12 22:54:11,690: INFO/MainProcess] Received task: myapp.utils.trigger_build[6ccefa24-39e7-4093-b4be-bf06dcb6b382]
@imanhodjaev

This comment has been minimized.

Show comment
Hide comment
@imanhodjaev

imanhodjaev Jan 13, 2017

@grantmcconnaughey I see you defined a single queue so now when start worker you should specify queue

celery worker -A myapp.celeryapp -Q myapp --loglevel=INFO

and when calling task it is better to pass queue kwarg like

mytask.delay(queue='myapp')

imanhodjaev commented Jan 13, 2017

@grantmcconnaughey I see you defined a single queue so now when start worker you should specify queue

celery worker -A myapp.celeryapp -Q myapp --loglevel=INFO

and when calling task it is better to pass queue kwarg like

mytask.delay(queue='myapp')

@grantmcconnaughey

This comment has been minimized.

Show comment
Hide comment
@grantmcconnaughey

grantmcconnaughey Jan 13, 2017

@imanhodjaev If I only have one queue in my settings then shouldn't the worker command and delaying a task both default to that queue? So I shouldn't need to specify it, I think.

Is that incorrect?

grantmcconnaughey commented Jan 13, 2017

@imanhodjaev If I only have one queue in my settings then shouldn't the worker command and delaying a task both default to that queue? So I shouldn't need to specify it, I think.

Is that incorrect?

@rafales

This comment has been minimized.

Show comment
Hide comment
@rafales

rafales Jan 13, 2017

@grantmcconnaughey it's a bug in celery, I ran into the same thing today and found out what's wrong: #3712

We'll have to wait for a fix.

rafales commented Jan 13, 2017

@grantmcconnaughey it's a bug in celery, I ran into the same thing today and found out what's wrong: #3712

We'll have to wait for a fix.

@imanhodjaev

This comment has been minimized.

Show comment
Hide comment
@imanhodjaev

imanhodjaev Jan 16, 2017

@grantmcconnaughey I was unable to run tasks this way to so I decided to force tasks to run in specific queues by setting queue option. I think it is a bug as @rafales already wrote.

imanhodjaev commented Jan 16, 2017

@grantmcconnaughey I was unable to run tasks this way to so I decided to force tasks to run in specific queues by setting queue option. I think it is a bug as @rafales already wrote.

@blueyed

This comment has been minimized.

Show comment
Hide comment
@blueyed

blueyed Jun 28, 2017

Contributor

I've seen the same issue when using kombu master as of now.

The workaround seems to be using the "solo" pool (-P solo, or via http://docs.celeryproject.org/en/latest/userguide/configuration.html#worker-pool).

Contributor

blueyed commented Jun 28, 2017

I've seen the same issue when using kombu master as of now.

The workaround seems to be using the "solo" pool (-P solo, or via http://docs.celeryproject.org/en/latest/userguide/configuration.html#worker-pool).

@1Arpit

This comment has been minimized.

Show comment
Hide comment
@1Arpit

1Arpit Sep 21, 2017

Facing the same issue, workaround from @blueyed worked for me.

1Arpit commented Sep 21, 2017

Facing the same issue, workaround from @blueyed worked for me.

@auvipy auvipy added this to the v4.2 milestone Dec 19, 2017

@auvipy

This comment has been minimized.

Show comment
Hide comment
@auvipy

auvipy Dec 19, 2017

Member

celery/kombu#817 work in progress

Member

auvipy commented Dec 19, 2017

celery/kombu#817 work in progress

@auvipy

This comment has been minimized.

Show comment
Hide comment
@auvipy

auvipy Dec 19, 2017

Member

@AlexHill do you have time to take a look on fixing the issue?

Member

auvipy commented Dec 19, 2017

@AlexHill do you have time to take a look on fixing the issue?

@auvipy auvipy modified the milestones: v4.2, v5.0.0 Jan 13, 2018

@auvipy

This comment has been minimized.

Show comment
Hide comment
@auvipy

auvipy Jan 16, 2018

Member

@dagrooms52 yes as no one contributed... you are free to take over

Member

auvipy commented Jan 16, 2018

@dagrooms52 yes as no one contributed... you are free to take over

@lambsteak

This comment has been minimized.

Show comment
Hide comment
@lambsteak

lambsteak Feb 8, 2018

Hey I was having the same problem but then I realized that the tasks scheduled in celery were in utc timezone whereas I was expecting time in my local timezone and that was the problem for me. I resolved it and the tasks are getting executed for me now as expected.

lambsteak commented Feb 8, 2018

Hey I was having the same problem but then I realized that the tasks scheduled in celery were in utc timezone whereas I was expecting time in my local timezone and that was the problem for me. I resolved it and the tasks are getting executed for me now as expected.

@auvipy

This comment has been minimized.

Show comment
Hide comment
@auvipy

auvipy Feb 8, 2018

Member

so this is not actually a bug at all?

Member

auvipy commented Feb 8, 2018

so this is not actually a bug at all?

@dagrooms52

This comment has been minimized.

Show comment
Hide comment
@dagrooms52

dagrooms52 Feb 8, 2018

That isn't even the OP, I wouldn't jump so quickly to have one user's mistake stand for everyone else's.

My server only uses UTC time in all instances, so @lambsteak seems to have had a one-off mistake.

dagrooms52 commented Feb 8, 2018

That isn't even the OP, I wouldn't jump so quickly to have one user's mistake stand for everyone else's.

My server only uses UTC time in all instances, so @lambsteak seems to have had a one-off mistake.

@auvipy auvipy modified the milestones: v5.0.0, v4.3 May 28, 2018

@prinsherbert

This comment has been minimized.

Show comment
Hide comment
@prinsherbert

prinsherbert Jun 13, 2018

@imanhodjaev

mytask.delay(12, queue='myapp')

Results in TypeError: mytask() got an unexpected keyword argument 'queue'

prinsherbert commented Jun 13, 2018

@imanhodjaev

mytask.delay(12, queue='myapp')

Results in TypeError: mytask() got an unexpected keyword argument 'queue'

@hotea

This comment has been minimized.

Show comment
Hide comment
@hotea

hotea Jul 10, 2018

I change the broker from rabbitmq to redis temporarily solved this. I think maybe the reason is rabbitmq's version........

hotea commented Jul 10, 2018

I change the broker from rabbitmq to redis temporarily solved this. I think maybe the reason is rabbitmq's version........

@vanyakosmos

This comment has been minimized.

Show comment
Hide comment
@vanyakosmos

vanyakosmos Jul 12, 2018

My problem was that I tried to call tasks group (with allow_join_result) from another task and it causes deadlock and simply stoped executing task w/o any errors.

vanyakosmos commented Jul 12, 2018

My problem was that I tried to call tasks group (with allow_join_result) from another task and it causes deadlock and simply stoped executing task w/o any errors.

@lucheol

This comment has been minimized.

Show comment
Hide comment
@lucheol

lucheol Jul 14, 2018

@hotea, I change broker too, but not solve this issue to me.

lucheol commented Jul 14, 2018

@hotea, I change broker too, but not solve this issue to me.

@blueyed

This comment has been minimized.

Show comment
Hide comment
@blueyed

blueyed Jul 17, 2018

Contributor

JFI: the workaround I've mentioned in #3759 (comment) still works for me.

Contributor

blueyed commented Jul 17, 2018

JFI: the workaround I've mentioned in #3759 (comment) still works for me.

@mbaragiola

This comment has been minimized.

Show comment
Hide comment
@mbaragiola

mbaragiola Aug 10, 2018

Hi, I have the same problem. I'm using Python 3.6, Django 1.11.15, Celery 4.2 and Redis 4.0.2.

I detected that my periodic tasks are being properly sent by celerybeat but it seems the worker isn't running them. This is a simple test task which I configured to run every one minute. The task is loaded and gets send every one minute, but it never runs (because I don't see the HELLO! string on my output):

from celery.utils.log import get_task_logger
from turnapp.celery import app

logger = get_task_logger(__name__)

@app.task
def say_hello():
    print("HELLO!")
    logger.info("HELLO!")
    return "HELLO!"

I get no error messages and everything seems to be working fine. Still I don't get the HELLO! message.

celeryworkerdev_1  | [2018-08-10 19:06:32,229: INFO/MainProcess] default@8516f3a70571 ready.
celerybeatdev_1    | [2018-08-10 19:08:30,044: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:35,051: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:40,060: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:45,069: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:50,077: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celeryworkerdev_1  | [2018-08-10 19:06:32,230: DEBUG/MainProcess] basic.qos: prefetch_count->4
celerybeatdev_1    | [2018-08-10 19:08:55,084: DEBUG/MainProcess] beat: Waking up in 4.91 seconds.
celerybeatdev_1    | [2018-08-10 19:09:00,001: INFO/MainProcess] Scheduler: Sending due task gymnasium_say-hello (gymnasium.say_hello)
celerybeatdev_1    | [2018-08-10 19:09:00,002: DEBUG/MainProcess] gymnasium.say_hello sent. id->ef0a2715-185e-49da-89a0-a9f65b4ed05a
celerybeatdev_1    | [2018-08-10 19:09:00,003: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:05,010: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:10,019: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:15,024: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:20,032: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:25,038: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:30,045: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:35,052: DEBUG/MainProcess] beat: Synchronizing schedule...
celerybeatdev_1    | [2018-08-10 19:09:35,053: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-10 19:09:35,071: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:40,077: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:45,083: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:50,089: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:55,097: DEBUG/MainProcess] beat: Waking up in 4.89 seconds.
celerybeatdev_1    | [2018-08-10 19:10:00,001: INFO/MainProcess] Scheduler: Sending due task gymnasium_say-hello (gymnasium.say_hello)
celerybeatdev_1    | [2018-08-10 19:10:00,006: DEBUG/MainProcess] gymnasium.say_hello sent. id->a3085879-4f27-415e-8683-aeea42fb15de
celerybeatdev_1    | [2018-08-10 19:10:00,007: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:10:05,015: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.

These are my settings:

CELERY_REDIS_HOSTNAME = env.get(
    'CELERY_REDIS_HOSTNAME',
    default='broker-master'
)
CELERY_REDIS_PORT = env.get('CELERY_REDIS_PORT', default=6379)
CELERY_REDIS_DB = env.get('CELERY_REDIS_DB', default=0)
CELERY_BROKER_URL = env.get('CELERY_BROKER_URL', default='')

if not CELERY_BROKER_URL:
    CELERY_BROKER_URL = 'redis://{hostname}:{port}/{db}'.format(
       hostname=CELERY_REDIS_HOSTNAME,
       port=CELERY_REDIS_PORT,
       db=CELERY_REDIS_DB
    )

CELERY_BROKER_POOL_LIMIT = 1
CELERY_BROKER_CONNECTION_TIMEOUT = 10

CELERY_ENABLE_UTC = True
CELERY_TIMEZONE = 'UTC'

CELERY_DEFAULT_QUEUE = 'default'
CELERY_QUEUES = (
    Queue('default', Exchange('default'), routing_key='default')
)

CELERY_ALWAYS_EAGER = False
CELERY_ACKS_LATE = True
CELERY_TASK_PUBLISH_RETRY = True
CELERY_DISABLE_RATE_LIMITS = False

CELERY_RESULT_BACKEND = 'django-db'

And my running commands are (using @blueyed workaround):

Beat:

celery beat -A myapp -l INFO -S django --loglevel=debug

Worker:

celery worker -A myapp -Q default -n default@%h -l DEBUG -P solo

Am I missing something? Thanks in advance!

mbaragiola commented Aug 10, 2018

Hi, I have the same problem. I'm using Python 3.6, Django 1.11.15, Celery 4.2 and Redis 4.0.2.

I detected that my periodic tasks are being properly sent by celerybeat but it seems the worker isn't running them. This is a simple test task which I configured to run every one minute. The task is loaded and gets send every one minute, but it never runs (because I don't see the HELLO! string on my output):

from celery.utils.log import get_task_logger
from turnapp.celery import app

logger = get_task_logger(__name__)

@app.task
def say_hello():
    print("HELLO!")
    logger.info("HELLO!")
    return "HELLO!"

I get no error messages and everything seems to be working fine. Still I don't get the HELLO! message.

celeryworkerdev_1  | [2018-08-10 19:06:32,229: INFO/MainProcess] default@8516f3a70571 ready.
celerybeatdev_1    | [2018-08-10 19:08:30,044: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:35,051: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:40,060: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:45,069: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:08:50,077: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celeryworkerdev_1  | [2018-08-10 19:06:32,230: DEBUG/MainProcess] basic.qos: prefetch_count->4
celerybeatdev_1    | [2018-08-10 19:08:55,084: DEBUG/MainProcess] beat: Waking up in 4.91 seconds.
celerybeatdev_1    | [2018-08-10 19:09:00,001: INFO/MainProcess] Scheduler: Sending due task gymnasium_say-hello (gymnasium.say_hello)
celerybeatdev_1    | [2018-08-10 19:09:00,002: DEBUG/MainProcess] gymnasium.say_hello sent. id->ef0a2715-185e-49da-89a0-a9f65b4ed05a
celerybeatdev_1    | [2018-08-10 19:09:00,003: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:05,010: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:10,019: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:15,024: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:20,032: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:25,038: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:30,045: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:35,052: DEBUG/MainProcess] beat: Synchronizing schedule...
celerybeatdev_1    | [2018-08-10 19:09:35,053: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-10 19:09:35,071: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:40,077: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:45,083: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:50,089: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:09:55,097: DEBUG/MainProcess] beat: Waking up in 4.89 seconds.
celerybeatdev_1    | [2018-08-10 19:10:00,001: INFO/MainProcess] Scheduler: Sending due task gymnasium_say-hello (gymnasium.say_hello)
celerybeatdev_1    | [2018-08-10 19:10:00,006: DEBUG/MainProcess] gymnasium.say_hello sent. id->a3085879-4f27-415e-8683-aeea42fb15de
celerybeatdev_1    | [2018-08-10 19:10:00,007: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.
celerybeatdev_1    | [2018-08-10 19:10:05,015: DEBUG/MainProcess] beat: Waking up in 5.00 seconds.

These are my settings:

CELERY_REDIS_HOSTNAME = env.get(
    'CELERY_REDIS_HOSTNAME',
    default='broker-master'
)
CELERY_REDIS_PORT = env.get('CELERY_REDIS_PORT', default=6379)
CELERY_REDIS_DB = env.get('CELERY_REDIS_DB', default=0)
CELERY_BROKER_URL = env.get('CELERY_BROKER_URL', default='')

if not CELERY_BROKER_URL:
    CELERY_BROKER_URL = 'redis://{hostname}:{port}/{db}'.format(
       hostname=CELERY_REDIS_HOSTNAME,
       port=CELERY_REDIS_PORT,
       db=CELERY_REDIS_DB
    )

CELERY_BROKER_POOL_LIMIT = 1
CELERY_BROKER_CONNECTION_TIMEOUT = 10

CELERY_ENABLE_UTC = True
CELERY_TIMEZONE = 'UTC'

CELERY_DEFAULT_QUEUE = 'default'
CELERY_QUEUES = (
    Queue('default', Exchange('default'), routing_key='default')
)

CELERY_ALWAYS_EAGER = False
CELERY_ACKS_LATE = True
CELERY_TASK_PUBLISH_RETRY = True
CELERY_DISABLE_RATE_LIMITS = False

CELERY_RESULT_BACKEND = 'django-db'

And my running commands are (using @blueyed workaround):

Beat:

celery beat -A myapp -l INFO -S django --loglevel=debug

Worker:

celery worker -A myapp -Q default -n default@%h -l DEBUG -P solo

Am I missing something? Thanks in advance!

@vishnuku

This comment has been minimized.

Show comment
Hide comment
@vishnuku

vishnuku Aug 12, 2018

Can you try below given command
Worker:
celery worker -A myapp --loglevel=INFO --without-gossip --without-mingle --without-heartbeat -Ofair

vishnuku commented Aug 12, 2018

Can you try below given command
Worker:
celery worker -A myapp --loglevel=INFO --without-gossip --without-mingle --without-heartbeat -Ofair

@mbaragiola

This comment has been minimized.

Show comment
Hide comment
@mbaragiola

mbaragiola Aug 12, 2018

@vishnuku Still I get no result, but a different output:

celeryworkerdev_1  |  -------------- celery@3d0d6e6a5527 v4.2.0 (windowlicker)
celeryworkerdev_1  | ---- **** ----- 
celeryworkerdev_1  | --- * ***  * -- Linux-4.9.89-boot2docker-x86_64-with-debian-9.4 2018-08-12 18:45:39
celeryworkerdev_1  | -- * - **** --- 
celeryworkerdev_1  | - ** ---------- [config]
celeryworkerdev_1  | - ** ---------- .> app:         turnapp:0x7f6d88496320
celeryworkerdev_1  | - ** ---------- .> transport:   redis://broker-master:6379/0
celeryworkerdev_1  | - ** ---------- .> results:     
celeryworkerdev_1  | - *** --- * --- .> concurrency: 1 (prefork)
celeryworkerdev_1  | -- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
celeryworkerdev_1  | --- ***** ----- 
celeryworkerdev_1  |  -------------- [queues]
celeryworkerdev_1  |                 .> celery           exchange=celery(direct) key=celery
celeryworkerdev_1  |                 
celeryworkerdev_1  | 
celeryworkerdev_1  | [tasks]
celeryworkerdev_1  |   . billing.tasks.charge_period
celeryworkerdev_1  |   . billing.tasks.finish_period
celeryworkerdev_1  |   . billing.tasks.process_webhook_event
celeryworkerdev_1  |   . djcelery_email_send_multiple
celeryworkerdev_1  |   . gymnasium.tasks.create_classes
celeryworkerdev_1  |   . gymnasium.tasks.say_hello
celeryworkerdev_1  |   . turnapp.celery.debug_task
celeryworkerdev_1  | 
celeryworkerdev_1  | [2018-08-12 18:45:40,062: INFO/MainProcess] Connected to redis://broker-master:6379/0
celeryworkerdev_1  | [2018-08-12 18:45:40,091: WARNING/MainProcess] /usr/local/lib/python3.6/site-packages/celery/fixups/django.py:200: UserWarning: Using settings.DEBUG leads to a memory leak, never use this setting in production environments!
celeryworkerdev_1  |   warnings.warn('Using settings.DEBUG leads to a memory leak, never '
celerybeatdev_1    | celery beat v4.2.0 (windowlicker) is starting.
celerybeatdev_1    | __    -    ... __   -        _
celerybeatdev_1    | LocalTime -> 2018-08-12 18:45:40
celerybeatdev_1    | Configuration ->
celerybeatdev_1    |     . broker -> redis://broker-master:6379/0
celerybeatdev_1    |     . loader -> celery.loaders.app.AppLoader
celerybeatdev_1    |     . scheduler -> django_celery_beat.schedulers.DatabaseScheduler
celerybeatdev_1    | 
celerybeatdev_1    |     . logfile -> [stderr]@%DEBUG
celerybeatdev_1    |     . maxinterval -> 5.00 seconds (5s)
celerybeatdev_1    | [2018-08-12 18:45:40,201: DEBUG/MainProcess] Setting default socket timeout to 30
celerybeatdev_1    | [2018-08-12 18:45:40,203: INFO/MainProcess] beat: Starting...
celerybeatdev_1    | [2018-08-12 18:45:40,204: DEBUG/MainProcess] DatabaseScheduler: initial read
celerybeatdev_1    | [2018-08-12 18:45:40,204: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-12 18:45:40,209: DEBUG/MainProcess] DatabaseScheduler: Fetching database schedule
celerybeatdev_1    | [2018-08-12 18:45:40,220: DEBUG/MainProcess] Current schedule:
celerybeatdev_1    | <ModelEntry: celery.backend_cleanup celery.backend_cleanup(*[], **{}) <crontab: 0 4 * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_create-classes gymnasium.create_classes(*[], **{}) <crontab: 0 * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: billing_finish-period billing.finish_period(*[], **{}) <crontab: * * * 1 * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_say-hello gymnasium.say_hello(*[], **{}) <crontab: * * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | [2018-08-12 18:45:40,282: INFO/MainProcess] DatabaseScheduler: Schedule changed.
celerybeatdev_1    | [2018-08-12 18:45:40,283: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-12 18:45:40,284: DEBUG/MainProcess] DatabaseScheduler: Fetching database schedule
celerybeatdev_1    | [2018-08-12 18:45:40,290: DEBUG/MainProcess] Current schedule:
celerybeatdev_1    | <ModelEntry: celery.backend_cleanup celery.backend_cleanup(*[], **{}) <crontab: 0 4 * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_say-hello gymnasium.say_hello(*[], **{}) <crontab: * * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_create-classes gymnasium.create_classes(*[], **{}) <crontab: 0 * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: billing_finish-period billing.finish_period(*[], **{}) <crontab: * * * 1 * (m/h/d/dM/MY)>>
celerybeatdev_1    | [2018-08-12 18:45:40,291: DEBUG/MainProcess] beat: Ticking with max interval->5.00 seconds
celeryworkerdev_1  | [2018-08-12 18:45:40,092: INFO/MainProcess] celery@3d0d6e6a5527 ready.
celeryworkerdev_1  | [2018-08-12 18:45:40,319: ERROR/MainProcess] Received unregistered task of type 'gymnasium.say_hello'.
celeryworkerdev_1  | The message has been ignored and discarded.
celeryworkerdev_1  | 
celeryworkerdev_1  | Did you remember to import the module containing this task?
celeryworkerdev_1  | Or maybe you're using relative imports?
celeryworkerdev_1  | 
celeryworkerdev_1  | Please see
celeryworkerdev_1  | http://docs.celeryq.org/en/latest/internals/protocol.html
celeryworkerdev_1  | for more information.
celeryworkerdev_1  | 
celeryworkerdev_1  | The full contents of the message body was:
celeryworkerdev_1  | b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]' (77b)
celeryworkerdev_1  | Traceback (most recent call last):
celeryworkerdev_1  |   File "/usr/local/lib/python3.6/site-packages/celery/worker/consumer/consumer.py", line 563, in on_task_received
celeryworkerdev_1  |     strategy = strategies[type_]
celerybeatdev_1    | [2018-08-12 18:45:40,302: INFO/MainProcess] Scheduler: Sending due task gymnasium_say-hello (gymnasium.say_hello)
celerybeatdev_1    | [2018-08-12 18:45:40,323: DEBUG/MainProcess] beat: Synchronizing schedule...
celerybeatdev_1    | [2018-08-12 18:45:40,324: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-12 18:45:40,336: DEBUG/MainProcess] gymnasium.say_hello sent. id->3efd2b27-bb51-49d6-8672-f42dda54229c
celerybeatdev_1    | [2018-08-12 18:45:40,338: INFO/MainProcess] Scheduler: Sending due task gymnasium_create-classes (gymnasium.create_classes)
celerybeatdev_1    | [2018-08-12 18:45:40,344: DEBUG/MainProcess] gymnasium.create_classes sent. id->ae73789c-35d9-4c62-adb9-c6a78a43875d
celeryworkerdev_1  | KeyError: 'gymnasium.say_hello'
celeryworkerdev_1  | [2018-08-12 18:45:40,351: ERROR/MainProcess] Received unregistered task of type 'gymnasium.create_classes'.
celeryworkerdev_1  | The message has been ignored and discarded.
celeryworkerdev_1  | 
celeryworkerdev_1  | Did you remember to import the module containing this task?
celeryworkerdev_1  | Or maybe you're using relative imports?
celeryworkerdev_1  | 
celeryworkerdev_1  | Please see
celeryworkerdev_1  | http://docs.celeryq.org/en/latest/internals/protocol.html
celeryworkerdev_1  | for more information.
celeryworkerdev_1  | 
celeryworkerdev_1  | The full contents of the message body was:
celeryworkerdev_1  | b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]' (77b)
celeryworkerdev_1  | Traceback (most recent call last):
celeryworkerdev_1  |   File "/usr/local/lib/python3.6/site-packages/celery/worker/consumer/consumer.py", line 563, in on_task_received
celeryworkerdev_1  |     strategy = strategies[type_]

mbaragiola commented Aug 12, 2018

@vishnuku Still I get no result, but a different output:

celeryworkerdev_1  |  -------------- celery@3d0d6e6a5527 v4.2.0 (windowlicker)
celeryworkerdev_1  | ---- **** ----- 
celeryworkerdev_1  | --- * ***  * -- Linux-4.9.89-boot2docker-x86_64-with-debian-9.4 2018-08-12 18:45:39
celeryworkerdev_1  | -- * - **** --- 
celeryworkerdev_1  | - ** ---------- [config]
celeryworkerdev_1  | - ** ---------- .> app:         turnapp:0x7f6d88496320
celeryworkerdev_1  | - ** ---------- .> transport:   redis://broker-master:6379/0
celeryworkerdev_1  | - ** ---------- .> results:     
celeryworkerdev_1  | - *** --- * --- .> concurrency: 1 (prefork)
celeryworkerdev_1  | -- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
celeryworkerdev_1  | --- ***** ----- 
celeryworkerdev_1  |  -------------- [queues]
celeryworkerdev_1  |                 .> celery           exchange=celery(direct) key=celery
celeryworkerdev_1  |                 
celeryworkerdev_1  | 
celeryworkerdev_1  | [tasks]
celeryworkerdev_1  |   . billing.tasks.charge_period
celeryworkerdev_1  |   . billing.tasks.finish_period
celeryworkerdev_1  |   . billing.tasks.process_webhook_event
celeryworkerdev_1  |   . djcelery_email_send_multiple
celeryworkerdev_1  |   . gymnasium.tasks.create_classes
celeryworkerdev_1  |   . gymnasium.tasks.say_hello
celeryworkerdev_1  |   . turnapp.celery.debug_task
celeryworkerdev_1  | 
celeryworkerdev_1  | [2018-08-12 18:45:40,062: INFO/MainProcess] Connected to redis://broker-master:6379/0
celeryworkerdev_1  | [2018-08-12 18:45:40,091: WARNING/MainProcess] /usr/local/lib/python3.6/site-packages/celery/fixups/django.py:200: UserWarning: Using settings.DEBUG leads to a memory leak, never use this setting in production environments!
celeryworkerdev_1  |   warnings.warn('Using settings.DEBUG leads to a memory leak, never '
celerybeatdev_1    | celery beat v4.2.0 (windowlicker) is starting.
celerybeatdev_1    | __    -    ... __   -        _
celerybeatdev_1    | LocalTime -> 2018-08-12 18:45:40
celerybeatdev_1    | Configuration ->
celerybeatdev_1    |     . broker -> redis://broker-master:6379/0
celerybeatdev_1    |     . loader -> celery.loaders.app.AppLoader
celerybeatdev_1    |     . scheduler -> django_celery_beat.schedulers.DatabaseScheduler
celerybeatdev_1    | 
celerybeatdev_1    |     . logfile -> [stderr]@%DEBUG
celerybeatdev_1    |     . maxinterval -> 5.00 seconds (5s)
celerybeatdev_1    | [2018-08-12 18:45:40,201: DEBUG/MainProcess] Setting default socket timeout to 30
celerybeatdev_1    | [2018-08-12 18:45:40,203: INFO/MainProcess] beat: Starting...
celerybeatdev_1    | [2018-08-12 18:45:40,204: DEBUG/MainProcess] DatabaseScheduler: initial read
celerybeatdev_1    | [2018-08-12 18:45:40,204: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-12 18:45:40,209: DEBUG/MainProcess] DatabaseScheduler: Fetching database schedule
celerybeatdev_1    | [2018-08-12 18:45:40,220: DEBUG/MainProcess] Current schedule:
celerybeatdev_1    | <ModelEntry: celery.backend_cleanup celery.backend_cleanup(*[], **{}) <crontab: 0 4 * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_create-classes gymnasium.create_classes(*[], **{}) <crontab: 0 * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: billing_finish-period billing.finish_period(*[], **{}) <crontab: * * * 1 * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_say-hello gymnasium.say_hello(*[], **{}) <crontab: * * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | [2018-08-12 18:45:40,282: INFO/MainProcess] DatabaseScheduler: Schedule changed.
celerybeatdev_1    | [2018-08-12 18:45:40,283: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-12 18:45:40,284: DEBUG/MainProcess] DatabaseScheduler: Fetching database schedule
celerybeatdev_1    | [2018-08-12 18:45:40,290: DEBUG/MainProcess] Current schedule:
celerybeatdev_1    | <ModelEntry: celery.backend_cleanup celery.backend_cleanup(*[], **{}) <crontab: 0 4 * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_say-hello gymnasium.say_hello(*[], **{}) <crontab: * * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: gymnasium_create-classes gymnasium.create_classes(*[], **{}) <crontab: 0 * * * * (m/h/d/dM/MY)>>
celerybeatdev_1    | <ModelEntry: billing_finish-period billing.finish_period(*[], **{}) <crontab: * * * 1 * (m/h/d/dM/MY)>>
celerybeatdev_1    | [2018-08-12 18:45:40,291: DEBUG/MainProcess] beat: Ticking with max interval->5.00 seconds
celeryworkerdev_1  | [2018-08-12 18:45:40,092: INFO/MainProcess] celery@3d0d6e6a5527 ready.
celeryworkerdev_1  | [2018-08-12 18:45:40,319: ERROR/MainProcess] Received unregistered task of type 'gymnasium.say_hello'.
celeryworkerdev_1  | The message has been ignored and discarded.
celeryworkerdev_1  | 
celeryworkerdev_1  | Did you remember to import the module containing this task?
celeryworkerdev_1  | Or maybe you're using relative imports?
celeryworkerdev_1  | 
celeryworkerdev_1  | Please see
celeryworkerdev_1  | http://docs.celeryq.org/en/latest/internals/protocol.html
celeryworkerdev_1  | for more information.
celeryworkerdev_1  | 
celeryworkerdev_1  | The full contents of the message body was:
celeryworkerdev_1  | b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]' (77b)
celeryworkerdev_1  | Traceback (most recent call last):
celeryworkerdev_1  |   File "/usr/local/lib/python3.6/site-packages/celery/worker/consumer/consumer.py", line 563, in on_task_received
celeryworkerdev_1  |     strategy = strategies[type_]
celerybeatdev_1    | [2018-08-12 18:45:40,302: INFO/MainProcess] Scheduler: Sending due task gymnasium_say-hello (gymnasium.say_hello)
celerybeatdev_1    | [2018-08-12 18:45:40,323: DEBUG/MainProcess] beat: Synchronizing schedule...
celerybeatdev_1    | [2018-08-12 18:45:40,324: INFO/MainProcess] Writing entries...
celerybeatdev_1    | [2018-08-12 18:45:40,336: DEBUG/MainProcess] gymnasium.say_hello sent. id->3efd2b27-bb51-49d6-8672-f42dda54229c
celerybeatdev_1    | [2018-08-12 18:45:40,338: INFO/MainProcess] Scheduler: Sending due task gymnasium_create-classes (gymnasium.create_classes)
celerybeatdev_1    | [2018-08-12 18:45:40,344: DEBUG/MainProcess] gymnasium.create_classes sent. id->ae73789c-35d9-4c62-adb9-c6a78a43875d
celeryworkerdev_1  | KeyError: 'gymnasium.say_hello'
celeryworkerdev_1  | [2018-08-12 18:45:40,351: ERROR/MainProcess] Received unregistered task of type 'gymnasium.create_classes'.
celeryworkerdev_1  | The message has been ignored and discarded.
celeryworkerdev_1  | 
celeryworkerdev_1  | Did you remember to import the module containing this task?
celeryworkerdev_1  | Or maybe you're using relative imports?
celeryworkerdev_1  | 
celeryworkerdev_1  | Please see
celeryworkerdev_1  | http://docs.celeryq.org/en/latest/internals/protocol.html
celeryworkerdev_1  | for more information.
celeryworkerdev_1  | 
celeryworkerdev_1  | The full contents of the message body was:
celeryworkerdev_1  | b'[[], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]' (77b)
celeryworkerdev_1  | Traceback (most recent call last):
celeryworkerdev_1  |   File "/usr/local/lib/python3.6/site-packages/celery/worker/consumer/consumer.py", line 563, in on_task_received
celeryworkerdev_1  |     strategy = strategies[type_]
@vishnuku

This comment has been minimized.

Show comment
Hide comment
@vishnuku

vishnuku Aug 13, 2018

You can see the current list of registered tasks in the celery.registry.TaskRegistry class. Could be that your celeryconfig (in the current directory) is not in PYTHONPATH so celery can't find it and falls back to defaults. Simply specify it explicitly when starting celery.
celeryd --loglevel=INFO --settings=celeryconfig

You can also set --loglevel=DEBUG and you should probably see the problem immediately.

vishnuku commented Aug 13, 2018

You can see the current list of registered tasks in the celery.registry.TaskRegistry class. Could be that your celeryconfig (in the current directory) is not in PYTHONPATH so celery can't find it and falls back to defaults. Simply specify it explicitly when starting celery.
celeryd --loglevel=INFO --settings=celeryconfig

You can also set --loglevel=DEBUG and you should probably see the problem immediately.

@mbaragiola

This comment has been minimized.

Show comment
Hide comment
@mbaragiola

mbaragiola Aug 13, 2018

@vishnuku You mean these?

celeryworkerdev_1  | [tasks]
celeryworkerdev_1  |   . billing.tasks.charge_period
celeryworkerdev_1  |   . billing.tasks.finish_period
celeryworkerdev_1  |   . billing.tasks.process_webhook_event
celeryworkerdev_1  |   . djcelery_email_send_multiple
celeryworkerdev_1  |   . gymnasium.tasks.create_classes
celeryworkerdev_1  |   . gymnasium.tasks.say_hello
celeryworkerdev_1  |   . turnapp.celery.debug_task

I don't know why that KeyError popped up there, it didn't happen before your flags and it's not happening now (even running with your flags). But the tasks seem to be properly loaded and sent

mbaragiola commented Aug 13, 2018

@vishnuku You mean these?

celeryworkerdev_1  | [tasks]
celeryworkerdev_1  |   . billing.tasks.charge_period
celeryworkerdev_1  |   . billing.tasks.finish_period
celeryworkerdev_1  |   . billing.tasks.process_webhook_event
celeryworkerdev_1  |   . djcelery_email_send_multiple
celeryworkerdev_1  |   . gymnasium.tasks.create_classes
celeryworkerdev_1  |   . gymnasium.tasks.say_hello
celeryworkerdev_1  |   . turnapp.celery.debug_task

I don't know why that KeyError popped up there, it didn't happen before your flags and it's not happening now (even running with your flags). But the tasks seem to be properly loaded and sent

pypt added a commit to berkmancenter/mediacloud that referenced this issue Sep 27, 2018

Revert "allow configuraiton of celery worker concurrency in mediaword…
…s.yml"

* Undocumented in mediawords.yml
* Not even used in production
* Running a job per-process is more KISS and works just fine
* Hits Celery's concurrency bugs, e.g.:

    celery/celery#3759

This reverts commit aff92fa.

pypt added a commit to berkmancenter/mediacloud that referenced this issue Sep 27, 2018

pypt added a commit to berkmancenter/mediacloud that referenced this issue Oct 17, 2018

Celery has a bug that makes workers stall for minutes or even hours b…
…efore running the next task with concurrency enabled (which is the default):

celery/celery#3759 (comment)

This was preventing out extractor's queue from catching up. The workaround for the bug above is to use single-threaded "solo" pool (which I have enabled recently), but said pool has yet another bug that prevents heartbeats from being sent to RabbitMQ:

celery/celery#3430

...the workaround for which is *not* to use "solo" pool.

Given that our extractor's queue is now largely empty and we can afford to wait a little bit, let's revert "solo" pool change.

Fixes #481.

This reverts commit 88c3c21.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment