celeryd not working all tasks marked as pending and events not being processed

[edulix]

I'm using debian, django 1.4, celery 3.0.11, django-celery 3.0.11, rabbitmq.

The tasks I create are not being executed, celery events -d does not even list anything. It's working fine locally in my computer and in another server I have installed my django app, but not in this other server.

This is the output of celeryd:
$ ./manage.py celeryd -E --loglevel=DEBUG

-------------- celery@tic v3.0.11 (Chiastic Slide)
---- **** -----
--- * *** * -- [Configuration]
-- * - **** --- . broker: amqp://agora@127.0.0.1:5672//

• ** ---------- . app: default:0x8f3cd4c (djcelery.loaders.DjangoLoader)
• ** ---------- . concurrency: 4 (processes)
• ** ---------- . events: ON
• ** ----------
• *** --- * --- [Queues]
  -- ******* ---- . celery: exchange:celery(direct) binding:celery
  --- ***** -----

[Tasks]
. agora_site.agora_core.tasks.add
. agora_site.agora_core.tasks.end_election
. agora_site.agora_core.tasks.start_election
. celery.backend_cleanup
. celery.chain
. celery.chord
. celery.chord_unlock
. celery.chunks
. celery.group
. celery.map
. celery.starmap

[2012-10-19 15:39:25,915: DEBUG/MainProcess] [Worker] Loading modules.
[2012-10-19 15:39:25,916: DEBUG/MainProcess] [Worker] Claiming components.
[2012-10-19 15:39:25,916: DEBUG/MainProcess] [Worker] Building boot step graph.
[2012-10-19 15:39:25,917: DEBUG/MainProcess] [Worker] New boot order: {ev, queues, beat, pool, mediator, autoreloader, timers, state-db, autoscaler, consumer}
[2012-10-19 15:39:25,918: DEBUG/MainProcess] Starting celery.worker.hub.Hub...
[2012-10-19 15:39:25,918: DEBUG/MainProcess] celery.worker.hub.Hub OK!
[2012-10-19 15:39:25,918: DEBUG/MainProcess] Starting celery.concurrency.processes.TaskPool...
[2012-10-19 15:39:25,920: WARNING/MainProcess] /usr/local/lib/python2.7/dist-packages/billiard/forking.py:455: UserWarning: Will add directory '/home/agora/agora-ciudadana' to path! This is necessary to accommodate pre-Django 1.4 layouts using setup_environ.
You can skip this warning by adding a DJANGO_SETTINGS_MODULE=settings environment variable.

W_OLD_DJANGO_LAYOUT % os.path.realpath(project_dir)
[2012-10-19 15:39:25,923: DEBUG/MainProcess] celery.concurrency.processes.TaskPool OK!
[2012-10-19 15:39:25,923: DEBUG/MainProcess] Starting celery.worker.consumer.Consumer...
[2012-10-19 15:39:25,924: WARNING/MainProcess] /usr/local/lib/python2.7/dist-packages/djcelery/loaders.py:132: UserWarning: Using settings.DEBUG leads to a memory leak, never use this setting in production environments!
warnings.warn("Using settings.DEBUG leads to a memory leak, never "
[2012-10-19 15:39:25,924: WARNING/MainProcess] celery@tic ready.
[2012-10-19 15:39:25,924: DEBUG/MainProcess] consumer: Re-establishing connection to the broker...
[2012-10-19 15:39:25,926: DEBUG/MainProcess] Start from server, version: 8.0, properties: {u'information': u'Licensed under the MPL. See http://www.rabbitmq.com/', u'product': u'RabbitMQ', u'copyright': u'Copyright (C) 2007-2012 VMware, Inc.', u'capabilities': {}, u'platform': u'Erlang/OTP', u'version': u'2.8.4'}, mechanisms: [u'PLAIN', u'AMQPLAIN'], locales: [u'en_US']
[2012-10-19 15:39:25,926: DEBUG/MainProcess] Open OK! known_hosts []
[2012-10-19 15:39:25,926: INFO/MainProcess] consumer: Connected to amqp://agora@127.0.0.1:5672//.
[2012-10-19 15:39:25,927: DEBUG/MainProcess] using channel_id: 1
[2012-10-19 15:39:25,927: DEBUG/MainProcess] Channel open
[2012-10-19 15:39:25,928: DEBUG/MainProcess] consumer: basic.qos: prefetch_count->16
[2012-10-19 15:39:25,928: DEBUG/MainProcess] using channel_id: 2
[2012-10-19 15:39:25,929: DEBUG/MainProcess] Channel open

Compared to the output of the other two pcs where it works fine, I'm missing a " DEBUG/MainProcess] consumer: Ready to accept tasks!" at the end. When I launch tasks, I see no extra output in the celeryd daemon even though it's in debug mode. And tasks are all marked as pending:

$ ./manage.py shell
Python 2.7.3rc2 (default, Apr 22 2012, 22:35:38)
Type "copyright", "credits" or "license" for more information.

IPython 0.13 -- An enhanced Interactive Python.
? -> Introduction and overview of IPython's features.
%quickref -> Quick reference.
help -> Python's own help system.
object? -> Details about 'object', use 'object??' for extra details.

In [1]: from agora_site.agora_core.tasks import add

In [2]: r = add.delay(1,1)

In [3]: r.state
Out[3]: u'PENDING'

If I launch celery events, it says in the bottom "No workers discovered" and when I launch tasks, no task appears. Of course in the other servers this works, it says there's one worker and taks appear and are successful. By the Way I'm testing with one sime add task that adds two numbers as you can see.

ninkotech told in irc that this might be a time issue and I certainly seemed to have time differences between the time shown by the date command and the time shown in the debug output of celeryd. I updated to django-celery 3.0.11, and I set system time correctly, and now both celeryd and system show exactly the same time, so that seems NOT to be the problem.

He also suggested to test setting HEARTBEAT_EXPIRE_WINDOW to 9000 instead of 200 that is the default in celery/events/state.py. Tried that, saw no difference.

Also, this is what I can see in rabbitmq:

rabbitmqctl list_queues name messages consumers | grep celery

celery 0 0
celeryev.eead6ce7-a743-4072-ac50-e149dc5fc8d8 0 1
celeryev.850b7c4f-7573-4851-b8d2-8156cde1dc25 0 1
celeryev.9de075ea-e42c-4025-bd80-d256608ec2e6 0 0
celeryev.85de6b46-d488-42b8-abe0-89246d7e573a 0 1
celeryev.37d1246e-f3bd-44f7-bba3-0b814fd57d3a 0 1
celeryev.6f475617-6ce2-43ef-b3ad-bec8db7c5517 0 1
tic.celery.pidbox 0 13
celeryev.3c509384-7869-456d-bb13-c8dce9f5b90e 0 1

The number 13 (number of consumers) have changed, previously I've had 9 for example. and the celeryev lines, one is added each time I execute celeryev -d it seems.

I'm really out of options, I don't know what I can do now. Might it be a bug?

[23doors]

Out of curiosity, which broker transport are you using? Did you specify it? If not, do you have librabbitmq installed? Could you try setting pyamqp broker transport? Just wondering if this is somehow related to some of issues I am having.

[edulix]

The broker transport I was using is the default one, as you can see in the line:

[2012-10-19 15:39:25,926: INFO/MainProcess] consumer: Connected to amqp://agora@127.0.0.1:5672//.

I've installed librabbitmq and it still shows exactly the same problem. I've installed py-amqp and configured django-celery to use it, and again the same problem appears. The only line that seems to change is the one above, that now is:
[2012-10-20 11:05:20,727: INFO/MainProcess] consumer: Connected to pyamqp://agora@127.0.0.1:5672//.

But still I'm not getting " DEBUG/MainProcess] consumer: Ready to accept tasks!"

[ask]

Why do you have 13 consumers on the same pidbox? That should mean you have 13 workers running with the same name

[edulix]

they were probably blocked. This information seems to be important, the connections seems to be blocked. If I start fresh the rabbitmq and start a worker, then list connections in rabbitmq, I get:

rabbitmqctl list_connections

Listing connections ...
guest 127.0.0.1 35217 blocking
...done.

If I try to execute a task, I get:

rabbitmqctl list_connections

Listing connections ...
guest 127.0.0.1 35257 blocking
guest 127.0.0.1 35286 blocked
...done.

I'm currently executing the worker with command "celery -A tasks_celery worker -l DEBUG" and the following tasks.celery.py:

from celery import Celery

celery = Celery('tasks', backend='amqp', broker='amqp://guest@localhost:5672//')

@celery.task
def add(x, y):
return x + y

In local, where everything works, I get:

rabbitmqctl list_connections

Listing connections ...
guest 127.0.0.1 60538 running
guest 127.0.0.1 60505 running

[ask]

Does the rabbit logs say anything?

[edulix]

In the end I solved this by modifying the minimum disk space needed for rabbitmq. The problem was that because I was executing rabbitmq in a virtual server, it had too little disk space.