Django Logging, The Right Way

Good logging is critical to debugging and troubleshooting problems. Not only is it helpful in local development, but in production it’s indispensable. When reviewing logs for an issue, it’s rare to hear somebody say, “We have too much logging in our app.” but common to hear the converse. So, with that in mind, let’s get started.

A Crash Course in Python Loggers

At the top of every file, you should have something like this:

import logging

logger = logging.getLogger(__name__)

__name__ will evaluate to the dotted Python path of the module, e.g. myproject/myapp/views.py will use myproject.myapp.views. Now we can use that logger throughout the file like so:

# A simple string logged at the "warning" level
logger.warning("Your log message is here")

# A string with a variable at the "info" level
logger.info("The value of var is %s", var)

# Logging the traceback for a caught exception
try:
function_that_might_raise_index_error()
except IndexError:
# equivalent to logger.error(msg, exc_info=True)
logger.exception("Something bad happened")

Note: Python’s loggers will handle inserting variables into your log message if you pass them as arguments in the logging function. If the log does not need to be output, the variable substitution won’t ever occur, helping avoid a small performance hit for a log that will never be used.

Pepper your code liberally with these logging statements. Here’s the rule of thumb I use for log levels:

  • debug: Info not needed for regular operation, but useful in development.
  • info: Info that's helpful during regular operation.
  • warning: Info that could be problematic, but is non-urgent.
  • error: Info that is important and likely requires prompt attention.
  • critical: I don't find myself using this in practice, but if you need one higher than error, here it is

Where to Log

Your app should not be concerned with where its logs go. Instead, it should log everything to the console (stdout/stderr) and let the server decide what to do with it from there. Typically this is put in a dedicated (and logrotated) file, captured by the Systemd journal or Docker, sent to a separate service such as ElasticSearch, or some combination of those. Log storage is a deployment concern, not an application concern.

The only thing your app does need to concern itself with is the format of the logs. Typically this is just a string with the relevant data, but if your server already adds a timestamp to the log, you probably want to exclude it from your own formatter. Likewise, if your log aggregator can accept JSON, a formatter like python-json-logger may be more appropriate.

Configuring the Logger

Writing to loggers in Python is easy. Configuring them to go to the right place is more challenging than you’d expect. I’ll start by bypassing Django’s default logging as described in my previous post. That will provide us with a blank slate to work with.

Setting up Sentry

Error reporting services are critical for any non-trivial site. By default these catch uncaught exceptions, notify you of the problem (only once per incident), and provide a nice interface to see the state of the app when the exception occurred. My favorite service for this is Sentry.

We can take Sentry one-step further by sending any log messages that are warning or higher to the service as well. These would otherwise be lost in a sea of log files that in-practice rarely get reviewed. To do this, we'll add a "root" logger which serves as a catch-all for any logs that are sent from any Python module. That looks something like this in the Django settings,

import logging.config
LOGGING_CONFIG = None
logging.config.dictConfig({
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'console': {
# exact format is not important, this is the minimum information
'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
},
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'formatter': 'console',
},
# Add Handler for Sentry for `warning` and above
'sentry': {
'level': 'WARNING',
'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler',
},
},
'loggers': {
# root logger
'': {
'level': 'WARNING',
'handlers': ['console', 'sentry'],
},
},
})

Logging From Your Application

While you may only want to know about warnings and errors from your third-party dependencies, you typically want much deeper insight into your application code. Ideally, your code all lives under a single namespace so it can be captured with a single addition to the loggers. Let's assume your project uses the namespace myproject, building on the code from above you would add this:

logging.config.dictConfig({
# ...
'loggers': {
'': {
'level': 'WARNING',
'handlers': ['console', 'sentry'],
},
'myproject': {
'level': 'INFO',
'handlers': ['console', 'sentry'],
# required to avoid double logging with root logger
'propagate': False,
},
},
})

But what if you want to investigate something in your application deeper with debug logging? Having to commit new code and deploy it feels like overkill. This is a great use-case for environment variables. We can modify the previous stanza to look like this:

import os
LOGLEVEL = os.environ.get('LOGLEVEL', 'info').upper()
logging.config.dictConfig({
# ...
'loggers': {
'': {
'level': 'WARNING',
'handlers': ['console', 'sentry'],
},
'myproject': {
'level': LOGLEVEL,
'handlers': ['console', 'sentry'],
# required to avoid double logging with root logger
'propagate': False,
},
},
})

Now our application logging will default to info, but can easily be increased temporarily by setting the environment variable LOGLEVEL=debug. Alternatively, if log storage is not an issue, consider always logging at the debug level. They are easy enough to filter out with a simple grep or via your log visualization tool, e.g. Kibana.

Cutting out the Noise

Once you have your logging setup and running, you may find some modules log information that you don’t really care about and only serve to create extra noise (I’m looking at you newrelic). For these modules, we can add another logger to tune them out. The first option is to log them to the console, but avoid propagating them to the root logger which would send them to Sentry:

logging.config.dictConfig({
# ...
'loggers': {
'': {
'level': 'WARNING',
'handlers': ['console', 'sentry'],
},
'myproject': {
'level': LOGLEVEL,
'handlers': ['console', 'sentry'],
# required to avoid double logging with root logger
'propagate': False,
},
# Don't send this module's logs to Sentry
'noisy_module': {
'level':'ERROR',
'handlers': ['console'],
'propagate': False,
},
},
})

If you find they are too noisy, even for the console, we can drop them altogether:

logging.config.dictConfig({
# ...
'loggers': {
# ...
# Don't log this module at all
'noisy_module': {
'level': 'NOTSET',
'propagate': False,
},
},
})

Local Request Logging

Once niceity in Django’s default config is request logging with runserver. By overridding Django’s config, we lose it, but it is easy enough to add back in:

from django.utils.log import DEFAULT_LOGGING
logging.config.dictConfig({
# ...
'formatters': {
# ...
'django.server': DEFAULT_LOGGING['formatters']['django.server'],
},
'handlers' {
# ...
'django.server': DEFAULT_LOGGING['handlers']['django.server'],
},
'loggers': {
# ...
'django.server': DEFAULT_LOGGING['loggers']['django.server'],
},
})

This technique is a little brittle, since it depends on some internals that could change between releases, but it should be easier to detect breakages than doing a direct copy/paste from Django’s source.

Go Forth and Log!

For a complete example of Django logging from this post, see this gist. If you have any other tips or tricks to share, we’d love to hear them!


Originally published at lincolnloop.com.

One clap, two clap, three clap, forty?

By clapping more or less, you can signal to us which stories really stand out.