[Fixed]-Celery Beat – Worker Consuming Messages, But Never Acks. Them

1👍

I’ve found the solution! It’s the --autoreload flag. Don’t use it.

Lesson #2: Run celery by hand, not via invoke as I was doing. This just makes your life harder by doing bad things to the log output.

It seems the --autoreload flag causes the worker to break for some reason. Here’s a comparison of the logs with the flag present / not.

In the following outputs I’ve changed the task to return "nothing here, yet" rather than print() it.

With --autoreload;

$ celery --autoreload -A ego worker -l debug

[2016-09-27 20:43:15,106: DEBUG/MainProcess] | Worker: Preparing bootsteps.
[2016-09-27 20:43:15,109: DEBUG/MainProcess] | Worker: Building graph...
[2016-09-27 20:43:15,110: DEBUG/MainProcess] | Worker: New boot order: {Timer, Hub, Queues (intra), Pool, Autoscaler, Autoreloader, Beat, StateDB, Consumer}
[2016-09-27 20:43:15,115: DEBUG/MainProcess] | Consumer: Preparing bootsteps.
[2016-09-27 20:43:15,115: DEBUG/MainProcess] | Consumer: Building graph...
[2016-09-27 20:43:15,122: DEBUG/MainProcess] | Consumer: New boot order: {Connection, Events, Mingle, Tasks, Control, Agent, Gossip, Heart, event loop}

 -------------- celery@Slug.local v3.1.23 (Cipater)
---- **** -----
--- * ***  * -- Darwin-16.0.0-x86_64-i386-64bit
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> app:         ego:0x10486f748
- ** ---------- .> transport:   amqp://guest:**@localhost:5672//
- ** ---------- .> results:     disabled://
- *** --- * --- .> concurrency: 8 (prefork)
-- ******* ----
--- ***** ----- [queues]
 -------------- .> celery           exchange=celery(direct) key=celery


[tasks]
  . celery.backend_cleanup
  . celery.chain
  . celery.chord
  . celery.chord_unlock
  . celery.chunks
  . celery.group
  . celery.map
  . celery.starmap
  . ego.celery.account_alerts
  . ledger.tasks.AccountAlerts

[2016-09-27 20:43:15,125: DEBUG/MainProcess] | Worker: Starting Hub
[2016-09-27 20:43:15,125: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:15,125: DEBUG/MainProcess] | Worker: Starting Pool
[2016-09-27 20:43:15,409: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:15,410: DEBUG/MainProcess] | Worker: Starting Autoreloader
[2016-09-27 20:43:15,410: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:15,410: DEBUG/MainProcess] | Worker: Starting Consumer
[2016-09-27 20:43:15,410: DEBUG/MainProcess] | Consumer: Starting Connection
[2016-09-27 20:43:15,420: DEBUG/MainProcess] Start from server, version: 0.9, properties: {'capabilities': {'per_consumer_qos': True, 'direct_reply_to': True, 'basic.nack': True, 'consumer_priorities': True, 'publisher_confirms': True, 'authentication_failure_close': True, 'connection.blocked': True, 'consumer_cancel_notify': True, 'exchange_exchange_bindings': True}, 'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'version': '3.6.5', 'product': 'RabbitMQ', 'cluster_name': 'rabbit@d78e61a6690d', 'copyright': 'Copyright (C) 2007-2016 Pivotal Software, Inc.', 'platform': 'Erlang/OTP'}, mechanisms: ['PLAIN', 'AMQPLAIN'], locales: ['en_US']
[2016-09-27 20:43:15,422: DEBUG/MainProcess] Open OK!
[2016-09-27 20:43:15,422: INFO/MainProcess] Connected to amqp://guest:**@127.0.0.1:5672//
[2016-09-27 20:43:15,422: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:15,422: DEBUG/MainProcess] | Consumer: Starting Events
[2016-09-27 20:43:15,429: DEBUG/MainProcess] Start from server, version: 0.9, properties: {'capabilities': {'per_consumer_qos': True, 'direct_reply_to': True, 'basic.nack': True, 'consumer_priorities': True, 'publisher_confirms': True, 'authentication_failure_close': True, 'connection.blocked': True, 'consumer_cancel_notify': True, 'exchange_exchange_bindings': True}, 'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'version': '3.6.5', 'product': 'RabbitMQ', 'cluster_name': 'rabbit@d78e61a6690d', 'copyright': 'Copyright (C) 2007-2016 Pivotal Software, Inc.', 'platform': 'Erlang/OTP'}, mechanisms: ['PLAIN', 'AMQPLAIN'], locales: ['en_US']
[2016-09-27 20:43:15,430: DEBUG/MainProcess] Open OK!
[2016-09-27 20:43:15,431: DEBUG/MainProcess] using channel_id: 1
[2016-09-27 20:43:15,433: DEBUG/MainProcess] Channel open
[2016-09-27 20:43:15,433: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:15,433: DEBUG/MainProcess] | Consumer: Starting Mingle
[2016-09-27 20:43:15,434: INFO/MainProcess] mingle: searching for neighbors
[2016-09-27 20:43:15,434: DEBUG/MainProcess] using channel_id: 1
[2016-09-27 20:43:15,435: DEBUG/MainProcess] Channel open
[2016-09-27 20:43:16,445: INFO/MainProcess] mingle: all alone
[2016-09-27 20:43:16,445: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:16,445: DEBUG/MainProcess] | Consumer: Starting Tasks
[2016-09-27 20:43:16,451: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:16,451: DEBUG/MainProcess] | Consumer: Starting Control
[2016-09-27 20:43:16,451: DEBUG/MainProcess] using channel_id: 2
[2016-09-27 20:43:16,452: DEBUG/MainProcess] Channel open
[2016-09-27 20:43:16,455: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:16,456: DEBUG/MainProcess] | Consumer: Starting Gossip
[2016-09-27 20:43:16,456: DEBUG/MainProcess] using channel_id: 3
[2016-09-27 20:43:16,456: DEBUG/MainProcess] Channel open
[2016-09-27 20:43:16,467: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:16,467: DEBUG/MainProcess] | Consumer: Starting Heart
[2016-09-27 20:43:16,468: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:43:16,469: DEBUG/MainProcess] | Consumer: Starting event loop
[2016-09-27 20:43:16,470: WARNING/MainProcess] celery@Slug.local ready.
[2016-09-27 20:43:16,470: DEBUG/MainProcess] | Worker: Hub.register Autoreloader...



^C
worker: Hitting Ctrl+C again will terminate all running tasks!

worker: Warm shutdown (MainProcess)
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Worker: Closing Hub...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Worker: Closing Pool...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Worker: Closing Autoreloader...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Worker: Closing Consumer...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Worker: Stopping Consumer...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Consumer: Closing Connection...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Consumer: Closing Events...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Consumer: Closing Mingle...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Consumer: Closing Tasks...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Consumer: Closing Control...
[2016-09-27 20:44:33,368: DEBUG/MainProcess] | Consumer: Closing Gossip...
[2016-09-27 20:44:33,369: DEBUG/MainProcess] | Consumer: Closing Heart...
[2016-09-27 20:44:33,369: DEBUG/MainProcess] | Consumer: Closing event loop...
[2016-09-27 20:44:33,369: DEBUG/MainProcess] | Consumer: Stopping event loop...
[2016-09-27 20:44:33,369: DEBUG/MainProcess] | Consumer: Stopping Heart...
[2016-09-27 20:44:33,369: DEBUG/MainProcess] | Consumer: Stopping Gossip...
[2016-09-27 20:44:33,372: DEBUG/MainProcess] Closed channel #3
[2016-09-27 20:44:33,373: DEBUG/MainProcess] | Consumer: Stopping Control...
[2016-09-27 20:44:33,374: DEBUG/MainProcess] Closed channel #2
[2016-09-27 20:44:33,374: DEBUG/MainProcess] | Consumer: Stopping Tasks...
[2016-09-27 20:44:33,374: DEBUG/MainProcess] Canceling task consumer...
[2016-09-27 20:44:33,375: DEBUG/MainProcess] | Consumer: Stopping Mingle...
[2016-09-27 20:44:33,375: DEBUG/MainProcess] | Consumer: Stopping Events...
[2016-09-27 20:44:33,375: DEBUG/MainProcess] | Consumer: Stopping Connection...
[2016-09-27 20:44:33,375: DEBUG/MainProcess] | Worker: Stopping Autoreloader...
[2016-09-27 20:44:33,375: DEBUG/MainProcess] | Worker: Stopping Pool...
[2016-09-27 20:44:34,388: DEBUG/MainProcess] | Worker: Stopping Hub...
[2016-09-27 20:44:34,388: DEBUG/MainProcess] | Consumer: Shutdown Heart...
[2016-09-27 20:44:34,389: DEBUG/MainProcess] | Consumer: Shutdown Gossip...
[2016-09-27 20:44:34,389: DEBUG/MainProcess] | Consumer: Shutdown Control...
[2016-09-27 20:44:34,389: DEBUG/MainProcess] | Consumer: Shutdown Tasks...
[2016-09-27 20:44:34,389: DEBUG/MainProcess] Canceling task consumer...
[2016-09-27 20:44:34,389: DEBUG/MainProcess] Closing consumer channel...
[2016-09-27 20:44:34,389: DEBUG/MainProcess] | Consumer: Shutdown Events...
[2016-09-27 20:44:34,390: DEBUG/MainProcess] Closed channel #1
[2016-09-27 20:44:34,391: DEBUG/MainProcess] | Consumer: Shutdown Connection...
[2016-09-27 20:44:34,392: DEBUG/MainProcess] Closed channel #1
[2016-09-27 20:44:34,396: DEBUG/MainProcess] removing tasks from inqueue until task handler finished

Without --autoreload (note “redelivered” status of the first two tasks);

$ celery -A ego worker -l debug

[2016-09-27 20:44:42,075: DEBUG/MainProcess] | Worker: Preparing bootsteps.
[2016-09-27 20:44:42,079: DEBUG/MainProcess] | Worker: Building graph...
[2016-09-27 20:44:42,080: DEBUG/MainProcess] | Worker: New boot order: {Timer, Hub, Queues (intra), Pool, Autoscaler, Autoreloader, Beat, StateDB, Consumer}
[2016-09-27 20:44:42,087: DEBUG/MainProcess] | Consumer: Preparing bootsteps.
[2016-09-27 20:44:42,088: DEBUG/MainProcess] | Consumer: Building graph...
[2016-09-27 20:44:42,101: DEBUG/MainProcess] | Consumer: New boot order: {Connection, Agent, Events, Mingle, Gossip, Heart, Tasks, Control, event loop}

 -------------- celery@Slug.local v3.1.23 (Cipater)
---- **** -----
--- * ***  * -- Darwin-16.0.0-x86_64-i386-64bit
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> app:         ego:0x10516f710
- ** ---------- .> transport:   amqp://guest:**@localhost:5672//
- ** ---------- .> results:     disabled://
- *** --- * --- .> concurrency: 8 (prefork)
-- ******* ----
--- ***** ----- [queues]
 -------------- .> celery           exchange=celery(direct) key=celery


[tasks]
  . celery.backend_cleanup
  . celery.chain
  . celery.chord
  . celery.chord_unlock
  . celery.chunks
  . celery.group
  . celery.map
  . celery.starmap
  . ego.celery.account_alerts
  . ledger.tasks.AccountAlerts

[2016-09-27 20:44:42,105: DEBUG/MainProcess] | Worker: Starting Hub
[2016-09-27 20:44:42,105: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:42,105: DEBUG/MainProcess] | Worker: Starting Pool
[2016-09-27 20:44:42,387: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:42,387: DEBUG/MainProcess] | Worker: Starting Consumer
[2016-09-27 20:44:42,388: DEBUG/MainProcess] | Consumer: Starting Connection
[2016-09-27 20:44:42,398: DEBUG/MainProcess] Start from server, version: 0.9, properties: {'copyright': 'Copyright (C) 2007-2016 Pivotal Software, Inc.', 'capabilities': {'publisher_confirms': True, 'authentication_failure_close': True, 'exchange_exchange_bindings': True, 'consumer_priorities': True, 'per_consumer_qos': True, 'consumer_cancel_notify': True, 'direct_reply_to': True, 'basic.nack': True, 'connection.blocked': True}, 'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'platform': 'Erlang/OTP', 'cluster_name': 'rabbit@d78e61a6690d', 'product': 'RabbitMQ', 'version': '3.6.5'}, mechanisms: ['PLAIN', 'AMQPLAIN'], locales: ['en_US']
[2016-09-27 20:44:42,399: DEBUG/MainProcess] Open OK!
[2016-09-27 20:44:42,399: INFO/MainProcess] Connected to amqp://guest:**@127.0.0.1:5672//
[2016-09-27 20:44:42,400: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:42,400: DEBUG/MainProcess] | Consumer: Starting Events
[2016-09-27 20:44:42,408: DEBUG/MainProcess] Start from server, version: 0.9, properties: {'copyright': 'Copyright (C) 2007-2016 Pivotal Software, Inc.', 'capabilities': {'publisher_confirms': True, 'authentication_failure_close': True, 'exchange_exchange_bindings': True, 'consumer_priorities': True, 'per_consumer_qos': True, 'consumer_cancel_notify': True, 'direct_reply_to': True, 'basic.nack': True, 'connection.blocked': True}, 'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'platform': 'Erlang/OTP', 'cluster_name': 'rabbit@d78e61a6690d', 'product': 'RabbitMQ', 'version': '3.6.5'}, mechanisms: ['PLAIN', 'AMQPLAIN'], locales: ['en_US']
[2016-09-27 20:44:42,409: DEBUG/MainProcess] Open OK!
[2016-09-27 20:44:42,409: DEBUG/MainProcess] using channel_id: 1
[2016-09-27 20:44:42,412: DEBUG/MainProcess] Channel open
[2016-09-27 20:44:42,412: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:42,412: DEBUG/MainProcess] | Consumer: Starting Mingle
[2016-09-27 20:44:42,412: INFO/MainProcess] mingle: searching for neighbors
[2016-09-27 20:44:42,413: DEBUG/MainProcess] using channel_id: 1
[2016-09-27 20:44:42,426: DEBUG/MainProcess] Channel open
[2016-09-27 20:44:43,445: INFO/MainProcess] mingle: all alone
[2016-09-27 20:44:43,445: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:43,445: DEBUG/MainProcess] | Consumer: Starting Gossip
[2016-09-27 20:44:43,445: DEBUG/MainProcess] using channel_id: 2
[2016-09-27 20:44:43,446: DEBUG/MainProcess] Channel open
[2016-09-27 20:44:43,450: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:43,450: DEBUG/MainProcess] | Consumer: Starting Heart
[2016-09-27 20:44:43,451: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:43,451: DEBUG/MainProcess] | Consumer: Starting Tasks
[2016-09-27 20:44:43,456: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:43,456: DEBUG/MainProcess] | Consumer: Starting Control
[2016-09-27 20:44:43,456: DEBUG/MainProcess] using channel_id: 3
[2016-09-27 20:44:43,457: DEBUG/MainProcess] Channel open
[2016-09-27 20:44:43,460: DEBUG/MainProcess] ^-- substep ok
[2016-09-27 20:44:43,460: DEBUG/MainProcess] | Consumer: Starting event loop
[2016-09-27 20:44:43,461: WARNING/MainProcess] celery@Slug.local ready.
[2016-09-27 20:44:43,462: DEBUG/MainProcess] | Worker: Hub.register Pool...
[2016-09-27 20:44:43,462: DEBUG/MainProcess] basic.qos: prefetch_count->32
[2016-09-27 20:44:43,463: INFO/MainProcess] Received task: ego.celery.account_alerts[bc4c5b05-6306-4a57-b1a0-eca1e9282c13]
[2016-09-27 20:44:43,463: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x105263950> (args:('ego.celery.account_alerts', 'bc4c5b05-6306-4a57-b1a0-eca1e9282c13', [], {}, {'is_eager': False, 'delivery_info': {'exchange': 'celery', 'routing_key': 'celery', 'redelivered': True, 'priority': 0}, 'correlation_id': 'bc4c5b05-6306-4a57-b1a0-eca1e9282c13', 'expires': None, 'chord': None, 'task': 'ego.celery.account_alerts', 'timelimit': [None, None], 'callbacks': None, 'headers': {}, 'utc': True, 'errbacks': None, 'eta': None, 'kwargs': {}, 'args': [], 'hostname': 'celery@Slug.local', 'taskset': None, 'group': None, 'retries': 0, 'id': 'bc4c5b05-6306-4a57-b1a0-eca1e9282c13', 'reply_to': '656c174e-c251-3e02-8132-df741c11a046'}) kwargs:{})
[2016-09-27 20:44:43,465: DEBUG/MainProcess] Task accepted: ego.celery.account_alerts[bc4c5b05-6306-4a57-b1a0-eca1e9282c13] pid:63322
[2016-09-27 20:44:43,478: INFO/MainProcess] Task ego.celery.account_alerts[bc4c5b05-6306-4a57-b1a0-eca1e9282c13] succeeded in 0.013773033046163619s: 'nothing here, yet'
[2016-09-27 20:44:45,458: INFO/MainProcess] Received task: ego.celery.account_alerts[b7673a47-dd76-4f1d-b414-03744fcfac22]
[2016-09-27 20:44:45,459: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x105263950> (args:('ego.celery.account_alerts', 'b7673a47-dd76-4f1d-b414-03744fcfac22', [], {}, {'is_eager': False, 'delivery_info': {'exchange': 'celery', 'routing_key': 'celery', 'redelivered': True, 'priority': 0}, 'correlation_id': 'b7673a47-dd76-4f1d-b414-03744fcfac22', 'expires': None, 'chord': None, 'task': 'ego.celery.account_alerts', 'timelimit': [None, None], 'callbacks': None, 'headers': {}, 'utc': True, 'errbacks': None, 'eta': None, 'kwargs': {}, 'args': [], 'hostname': 'celery@Slug.local', 'taskset': None, 'group': None, 'retries': 0, 'id': 'b7673a47-dd76-4f1d-b414-03744fcfac22', 'reply_to': '656c174e-c251-3e02-8132-df741c11a046'}) kwargs:{})
[2016-09-27 20:44:45,461: DEBUG/MainProcess] Task accepted: ego.celery.account_alerts[b7673a47-dd76-4f1d-b414-03744fcfac22] pid:63327
[2016-09-27 20:44:45,462: INFO/MainProcess] Task ego.celery.account_alerts[b7673a47-dd76-4f1d-b414-03744fcfac22] succeeded in 0.0010689240298233926s: 'nothing here, yet'
[2016-09-27 20:45:00,002: INFO/MainProcess] Received task: ego.celery.account_alerts[2d464f3a-36f3-4f45-b303-aa477bc30545]
[2016-09-27 20:45:00,002: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x105263950> (args:('ego.celery.account_alerts', '2d464f3a-36f3-4f45-b303-aa477bc30545', [], {}, {'is_eager': False, 'delivery_info': {'exchange': 'celery', 'routing_key': 'celery', 'redelivered': False, 'priority': 0}, 'correlation_id': '2d464f3a-36f3-4f45-b303-aa477bc30545', 'expires': None, 'chord': None, 'task': 'ego.celery.account_alerts', 'timelimit': [None, None], 'callbacks': None, 'headers': {}, 'utc': True, 'errbacks': None, 'eta': None, 'kwargs': {}, 'args': [], 'hostname': 'celery@Slug.local', 'taskset': None, 'group': None, 'retries': 0, 'id': '2d464f3a-36f3-4f45-b303-aa477bc30545', 'reply_to': '656c174e-c251-3e02-8132-df741c11a046'}) kwargs:{})
[2016-09-27 20:45:00,003: DEBUG/MainProcess] Task accepted: ego.celery.account_alerts[2d464f3a-36f3-4f45-b303-aa477bc30545] pid:63321
[2016-09-27 20:45:00,003: INFO/MainProcess] Task ego.celery.account_alerts[2d464f3a-36f3-4f45-b303-aa477bc30545] succeeded in 0.000625498010776937s: 'nothing here, yet'
[2016-09-27 20:46:00,002: INFO/MainProcess] Received task: ego.celery.account_alerts[f8eba8f2-1c48-48bd-a221-2676c735299e]
[2016-09-27 20:46:00,003: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x105263950> (args:('ego.celery.account_alerts', 'f8eba8f2-1c48-48bd-a221-2676c735299e', [], {}, {'is_eager': False, 'delivery_info': {'exchange': 'celery', 'routing_key': 'celery', 'redelivered': False, 'priority': 0}, 'correlation_id': 'f8eba8f2-1c48-48bd-a221-2676c735299e', 'expires': None, 'chord': None, 'task': 'ego.celery.account_alerts', 'timelimit': [None, None], 'callbacks': None, 'headers': {}, 'utc': True, 'errbacks': None, 'eta': None, 'kwargs': {}, 'args': [], 'hostname': 'celery@Slug.local', 'taskset': None, 'group': None, 'retries': 0, 'id': 'f8eba8f2-1c48-48bd-a221-2676c735299e', 'reply_to': '656c174e-c251-3e02-8132-df741c11a046'}) kwargs:{})
[2016-09-27 20:46:00,004: DEBUG/MainProcess] Task accepted: ego.celery.account_alerts[f8eba8f2-1c48-48bd-a221-2676c735299e] pid:63325
[2016-09-27 20:46:00,005: INFO/MainProcess] Task ego.celery.account_alerts[f8eba8f2-1c48-48bd-a221-2676c735299e] succeeded in 0.0016709549818187952s: 'nothing here, yet'

👤pnovotnak

Django: how to set the path for the environ variable "DJANGO_SETTINGS_MODULE"

Source:stackexchange.com

Leave a comment Cancel reply