Django Long Running Processes

The most commonly suggested solution for long running processes is to use Celery. I suspect that if you need scalabilty or high volume, etc… Celery is the best solution. That said,  I have been down the Celery rabbit hole more than once. It has never been pleasant. Since my needs are more modest, maybe there is a better alternative?

My needs involve running process that might run for 15 minutes or so. The process might run a dozen times/day and be launched by as many users. The process must be launch-able from the website by authorized users.

I have solved this problem by going to the polar opposite of Celery – cron. Every minute cron would launch a custom django command. That command would look in a database table for tasks and get input data from the database. When a task was completed, that fact was written to the database table. Honestly, this approach has worked well. Never-the-less, I always wonder if there is a stable, simple, robust solution that lies somewhere between cron and Celery.

Maybe RedisRQ and Django RQ? These are my notes so that a year from now, when this issue comes up again, I can get up to speed quickly.

Step 1: Install Redis and Start Redis Server

These instructions are pretty good.

Step 2: Is Redis Server Working?

Maybe you installed Redis Server a long time ago and you want to see if it’s still working? Go here.

Or you could type:

$ redis-cli ping
PONG

Step 3: Install RQ

pip install rq

Step 4: Install and Configure django-rq

Go here.

Step 5: Read the RQ Docs

Seriously – read the RQ docs. They are brief and to-the-point.

Step 6: Daemonize the RQ Workers

If you use supervisord , here is the Ansible template I use to do that:

[program:django_rq]
command= {{ virtualenv_path }}/bin/python manage.py rqworker high default low
stdout_logfile = /var/log/redis/redis_6379.log

numprocs=1

directory={{ django_manage_path }}
environment = DJANGO_SETTINGS_MODULE="{{ django_settings_import }}",PATH="{{ virtualenv_path }}/bin"
user = vagrant
stopsignal=TERM

autostart=true
autorestart=true


[program:rqscheduler]
command={{ virtualenv_path }}/bin/python manage.py rqscheduler
stdout_logfile = /var/log/redis/rq_scheduler.log

numprocs=1

directory={{ django_manage_path }}
environment = DJANGO_SETTINGS_MODULE="{{ django_settings_import }}",PATH="{{ virtualenv_path }}/bin"
user = vagrant
stopsignal=TERM

autostart=true
autorestart=true

Reflections

I do not recall all the problems I had with Celery. After reviewing the RQ solution above, it is clear that one of the advantages of that solution is the documentation is really good. Or at least it clearly and directly addressed what I was trying to do.

Additionally, I wish I would have implemented this a long time ago. It is so easy to use. And it’s so freeing to to be able to run long processes.

Reflections part Deux, Troubleshooting and Gotchas

It’s coming back to me. The supervisor config in the original post started the daemon OK. But it turns out there was an error in the config that caused the queued processes to fail. Finding and fixing that bug was a pain in the ass. Maybe my troubles with Celery were really troubles with supervisor? Down the rabbit hole we go!

It turns out that the Django RQ Queue Statistics are helpful for debugging. They show failed tasks along with a Python traceback! Very nice. In my case, I was getting the error:

ImportError: No module named XXXX

Clearly one of my paths in the supervisor conf file was wrong. Time to start hacking:

  1. Edit conf file
  2. Run supervisorctl stop django_rq
  3. Run supervisorctl start django_rq
  4. Queue a task
  5. It failed again? How is that possible? Back to step 1

GOTCHA! After a while you notice the changes you are making are not having any effect. And then you recall that to reload the config file you must run:

service supervisor restart

Now my config file works. All I have to do is figure out which of the ever cludgier hacks I made can be removed. The config file above has been updated.

Son of Reflections part Deux – Adding PATH to Supervisor Config

I thought I had it working. Then when I added a slightly more complex task that interacted with the database, it failed with an ImportError. After flailing around for a while, I found that adding a PATH to the supervisor environment variable solved the problem.

During my flailing, I found this blog post. Lots of great ideas.

Still Falling Down the Rabbit Hole – Logging to the Rescue

Everything was working almost every where… except with the daemonized workers on the server. Luckily, Django-RQ now comes with logging. I implemented the logging in the Django settings files as per the docs, restarted the dev server, and… no logging. Turns out you have to restart the workers.

Also, although the docs show the use of a logging class made for rq (rq.utils.ColorizingStreamHandler), it turns out you can use logging.FileHandler, which is what you want for debugging the code when running from a daemonized worker.

For what it’s worth, it turns out the problem was with the python locale module. The docs say something about it not being thread safe. The function locale.getlocale() returned a value when the workers were run via the dev server, but it returned None when run from a daemonized worker.

Advertisements

Celery Logging

When you start Celery, there is a flag for setting the logging level:

celery worker -A my_app -E -l WARNING --concurrency=1

Simple enough. There is a similar flag for Celery beat. The problem is that even if you set the level fairly high and you are running celery beat, you will still get DEBUG and INFO level logging info every time Celery beat runs. This can create a huge log file of useless information.

It seems there is a bug somewhere in the logging system. This post suggests that django-debug-toolbar can be the culprit. Unfortunately for me, I am not running django-debug-toolbar. Apparently some other 3rd party app is causing the problem.

My solution is simple. I created a cron job to clear the file every hour, using the command:

cat /dev/null > /path/to/logfile

Django, Celery and Memory Use

Disclaimer: These are the notes of a Celery/RabbitMQ/Linux noob. Not sure how generalizable they are.

A lot of the Django projects I develop have a small number of users and run pretty light-weight tasks. Thus server costs SHOULD be pretty low. However, they also frequently involve asynchronous, “long-running” tasks, such as creating reports, etc… One common way to handle these tasks is with Celery and RabbitMQ.

For my needs, Celery and RabbitMQ are massive overkill. Despite that, I use them because they are well documented and very stable. There are two promising alternatives:

Neither one is beyond v 0.5. In other projects, I have used a combination of cron and custom django commands. That has worked well, but it does not seem as flexible as something like Celery.

The biggest problem with Celery and RabbitMQ is memory use. For my basic Django project, running all by itself in Vagrant, the command “ps aux”, shows these memory values in percent:

  • django – 6%
  • gunicorn – 3%
  • supervisor – 3%
  • postgres – 6 processes – 6%
  • rabbitmq beam.smp – 8%
  • other rabbitmq – 4 processes – negligible
  • celery beat – 8%
  • celery workers – 3 processes – 24%

This is with no tasks running or web requests coming in. It seems crazy to me to devote 40% of memory to Celery and friends. Maybe I can do some tuning.

I am not sure why I have 3 Celery workers. I am guessing one is enough. Here is my command to start Celery:

celery worker -A my_app -E -l info --concurrency=2

this is what gave 3 processes. When I set concurrency to 1, I got 2 processes. I also got two processes with:

celery worker -A my_app -E -l info --autoscale=3,1

OK, so it looks like I will need to accept 16% for celery workers. Maybe I can improve things by switching to Redis?

I installed Redis using the quick start guide and the defaults. Redis memory usage is negligible. Should you switch to Redis? It depends. There are other important differences. Google RabbitMQ vs Redis. For many of my projects, memory use trumps the other differences.

Celery Debugging, Tricks, Etc…

I am not sure why, but Celery takes me forever to get working. Here are some notes for getting it working with Django.

Celery Troubleshooting

Lets say you have Supervisor daemonizing Celery. You can see the Celery processes are running with:

ps aux | grep celery

But things are not quite right yet. What to do? For troubleshooting, things will go a lot quicker if you do not run Celery as a daemon. Just cd to your manage.py dir and run:

celery worker -A <my_project> -E -l debug -B

This will give you lots of messages and is a lot easier to start and stop.

Restarting Supervisor

As you are debugging, you might discover errors in your Supervisor scripts. After you make changes to the Supervisor scripts, you need to restart supervisor:

service supervisor restart

Celery Beat

If you want to run periodic tasks, Celery beat is the answer. In the past, I started Celery using the -B flag in my command for starting Celery. But the docs say you should not use this in production. Instead of the -B flag, setup beat in production as shown here.

Celery Logging

In the Celery docs, they recommend setting up task logging like this:

from celery.utils.log import get_task_logger
logger = get_task_logger(__name__)

Easy enough. But where do those messages go? As is, you would think they would go to the root logger. If you did not setup the root logger, then they should go to Streamhandler, which should send them to stdout. I setup stdout in supervisor to write to a file, yet no celery logging appears there.

Others have suggested that Celery mucks with the logger tree. Maybe that’s true. In any case you can “kind of” solve it by creating a ‘celery’ logger handler. I say “kind of” because I still cannot figure out where Celery Beat tasks log to. In any case, the logger code is below.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'simple': {
            'format': '%(levelname)s %(message)s',
            'datefmt': '%y %b %d, %H:%M:%S',
            },
        },
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse'
        }
    },
    'handlers': {
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        },
        'celery': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': normpath(join(SITE_ROOT, 'celery.log')),
            'formatter': 'simple',
        }
    },
    'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': True,
        },
        'celery': {
            'handlers': ['celery'],
            'level': 'DEBUG',
        }
    }
}

Celery Beat: Connection refused

In my case, this error was due to RabbitMQ being down. Running:

ps aux | grep rabbit

Showed only:

/usr/lib/erlang/erts-5.8.5/bin/epmd -daemon

To start RabbitMQ, run:

sudo rabbitmq-server -detached

Now you should see a bunch of new RabbitMQ processes.

Stopping Celery Worker Processes

If you use Supervisor to start and stop Celery, you will notice that you are accumulating worker processes. Evidently starting with supervisor creates workers, but stopping does not shut them down. I tried various settings in my supervisor config file, with no luck. I have googled it and not found an answer. So for now I am using a shell command to handle this:

ps auxww | grep 'celery worker' | awk '{print $2}' | xargs kill -9

This is from the Celery docs.