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:
python
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:
python
# 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 thanerror, 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,
python
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:
python
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:
python
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:
python
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:
python
logging.config.dictConfig({
# ...
'loggers': {
# ...
# Don't log this module at all
'noisy_module': {
'level': 'NOTSET',
'propagate': False,
},
},
})
Local Request Logging
One nicety 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:
python
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!
