Django Celery Logging Best Practice

Question

I'm trying to get Celery logging working with Django. I have logging set-up in settings.py to go to console (that works fine as I'm hosting on Heroku). At the top of each module, I have:

import logging
logger = logging.getLogger(__name__)

And in my tasks.py, I have:

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

That works fine for logging calls from a task and I get output like this:

2012-11-13T18:05:38+00:00 app[worker.1]: [2012-11-13 18:05:38,527: INFO/PoolWorker-2] Syc feed is starting

But if that task then calls a method in another module, e.g. a queryset method, I get duplicate log entries, e.g.

2012-11-13T18:00:51+00:00 app[worker.1]: [INFO] utils.generic_importers.ftp_processor process(): File xxx.csv already imported. Not downloaded
2012-11-13T18:00:51+00:00 app[worker.1]: [2012-11-13 18:00:51,736: INFO/PoolWorker-6] File xxx.csv already imported. Not downloaded

I think I could use

CELERY_HIJACK_ROOT_LOGGER = False

to just use the Django logging but this didn't work when I tried it and even if I did get it to work, I would lose the "PoolWorker-6" bit which I do want. (Incidentally, I can't figure out how to get the task name to display in the log entry from Celery, as the docs seems to indicate that it should).

I suspect I'm missing something simple here.

Answer 1

When your logger initialized in the beginning of "another module" it links to another logger. Which handle your messages. It can be root logger, or usually I see in Django projects - logger with name ''.

Best way here, is overriding your logging config:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'simple': {
            'format': '%(levelname)s %(message)s',
             'datefmt': '%y %b %d, %H:%M:%S',
            },
        },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'celery': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'filename': 'celery.log',
            'formatter': 'simple',
            'maxBytes': 1024 * 1024 * 100,  # 100 mb
        },
    },
    'loggers': {
        'celery': {
            'handlers': ['celery', 'console'],
            'level': 'DEBUG',
        },
    }
}

from logging.config import dictConfig
dictConfig(LOGGING)

In this case I suppose it should work as you assume.

P.S. dictConfig added in Python2.7+.