python - Django logging on Heroku

Question

I know this question was already asked several times, but I just can't get it to work. I already spent half a day trying dozens of combinations, and again now and it is still not working.

In my code, I am logging at several parts, like within a try-except or to log some infos from management commands. I'm doing just very normal stuff, that is working on several local installs and on some Nginx servers.

A python file like this one :

import logging
logger = logging.getLogger(__name__)
logger.info('some important infos')

With following as minimal settings.py (I tried without stream indication, without the loggers specified, with named loggers, almost all possible combinations and I also tried much more complex ones)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'stream': sys.stdout
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'propagate': True,
            'level': 'INFO',
        },
        '': {
            'handlers': ['console'],
            'level': 'INFO',
        }
    }
}

Then also simply tested from the shell heroku run python

import logging
level = logging.INFO
handler = logging.StreamHandler()
handler.setLevel(level)
handler.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
logger = logging.getLogger('info')
logger.addHandler(handler)
logger.setLevel(level) #even if not required...
logger.info('logging test')

The last one may show up as "print" statement in the console, but neither here nor from the command or the server, nothing never shows up in heroku logs....

EDIT: actually I have some entries showing up, application logs like following, just not mine:

2013-09-20T15:00:16.405492+00:00 heroku[run.2036]: Process exited with status 0
2013-09-20T15:00:17+00:00 app[heroku-postgres]: source=HEROKU_POSTGRESQL_OLIVE sample[...]
2013-09-20T14:59:47.403049+00:00 heroku[router]: at=info method=GET path=/
2013-09-20T14:59:16.304397+00:00 heroku[web.1]: source=web.1 dyno=heroku [...]

I also tried to look for entries using several addons. I had for a moment at the beginning newrelic, which I then also deactivated from the WSGI start-up. I don't remember if at that time it worked well, the free test period of newrelic is rather short.

Well, I don't know what I could try else... Thanks for any hint

Answer 1

Logging on Heroku from Django can be tricky at first, but it's actually not that horrible to get set up.

This following logging definition (goes into your settings file) defined two formatters. The verbose one matches the logging format Heroku itself uses. It also defines two handlers, a null handler (shouldn't need to be used) and a console handler - the console handler is what you want to use with Heroku. The reason for this is that logging on Heroku works by a simple stream logger, logging any output made to stdout/stderr. Lastly, I've defined one logger called testlogger - this part of the logging definition goes like normal for logging definitions.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': ('%(asctime)s [%(process)d] [%(levelname)s] ' +
                       'pathname=%(pathname)s lineno=%(lineno)s ' +
                       'funcname=%(funcName)s %(message)s'),
            'datefmt': '%Y-%m-%d %H:%M:%S'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        }
    },
    'handlers': {
        'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler',
        },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose'
        }
    },
    'loggers': {
        'testlogger': {
            'handlers': ['console'],
            'level': 'INFO',
        }
    }
}

Next up, how to use this. In this simple case, you can do the following in any other file in your Django project, to write to this specific logger we defined (testlogger). Remember that by the logger definition in our settings file, any log message INFO or above will be output.

import logging
logger = logging.getLogger('testlogger')
logger.info('This is a simple log message')

Answer 2

In my case, I did have a valid logging setting

LOGGING = {...}

Unfortunately it was being ignored because, at the bottom of my setting file, I was calling

django_heroku.settings(locals())

This was overwriting my logging setting so the solution was

django_heroku.settings(locals(), logging=False)

This looks as though it might disable logging but it actually just skips heroku's own logging config.

---

As a side note, I would use this code when debugging Django logging problems because it should more or less always work with the Django defaults:

import logging
logger = logging.getLogger('django.server')
logger.error('some important infos')

See Django's default logging config

You can then change the logger, the message level and the logging settings to work out exactly what the problem is.

Answer 3

You need to 'activate' your loggers manually. You can do this per module, like 'blog.views'. It will pick up submodules, so to log the whole blog app, just put in 'blog'.

If you leave it empty, it will log everything not handled before and with propagate=True (not the default). This will also log all of Django, which means on debug level you will get SQL queries in your logs.

'loggers': {
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'blog.views': {
            'handlers': ['console'],
        },
        'blog': {
            'handlers': ['console'],
        },
        '': {
            'handlers': ['console'],
            'level': 'DEBUG',  # Not recommended.
        }
    }

Answer 4

I had the same problem where my custom logger was not caught by Django and so it would only show my ERROR level messages but without passing through the Django logging system. Formatters and the likes would have no effect on the outputted message and I could not get message of INFO level to show at all.

I finally found the culprit and it seems to be heroku's django settings tool itself. If you look into the source there, you see it installs a testlogger and does not merge in the custom loggers you may have setup yourself.

The solution is to do the heroku call like this:

django_heroku.settings(locals(), logging=False)

Or better yet, don't use it at all anymore since this package is no longer maintained anyway.