Django request logging

I'm a big believer in the utility of web application logging. Over the years I've almost always found it more useful than debuggers in diagnosing problems. The difficulty is achieving good logging. Here's a solution for Django projects that I'm pretty happy with.

To me, good logging means it's possible to:

• Use the standard logging mechanisms of the language or framework.
• Easily trace an entire request, even on a busy site where multiple requests are logging concurrently.
• Consolidate logs from multiple web servers.
• Route logging from separate sites or applications to separate destinations.

I've come up with some Django middleware and supporting code that works with Python's stock logging module and syslog-ng to achieve this.

Components

The module (unimaginatively called drlog) includes the aforementioned middleware, an implementation of Python's logging.Logger, and some code to configure it all when imported by your Django settings module.

drlog.middleware.RequestLoggingMiddleware

To trace a request through the logs, it needs a unique identifier. If you're using Apache, mod_unique_id can provide this, and the middleware will use this in preference to generating one. If it's not available, one will be generated by hashing some of the request data.

The unique identifier and the request itself are added to thread-local storage, for use by the Logger implementation.

drlog.RequestLogger

Python's logging module lets you configure custom logging formats, including named variables to be interpolated from any extra context you can give it. This logger sets up that extra context using the thread-local info saved by the middleware, so you can include the unique request ID and other request metadata in your log messages.

Configuration

Django

In your settings.py, add drlog.middleware.RequestLoggingMiddleware to your MIDDLEWARE_CLASSES setting.

By default, logging will be directed to sys.stderr. Under Apache, this means it will appear in the error log you've configured for the virtual host, or in the server's global error log. To configure another destination, configure an implementation of Python's logging.Handler and assign it to DRLOG_HANDLER in your settings.py. To route to syslog:

from logging.handlers import SysLogHandler
DRLOG_HANDLER = SysLogHandler()

You can also set DRLOG_APP_NAME to identify your Django project. This helps distinguish logging from multiple virtual hosts, and with syslog-ng, lets you route their output to different destinations.

Finally, if you want to change the format of log messages, do so with the DRLOG_FORMAT setting. The default looks like this:

[%(asctime)s %(REMOTE_ADDR)s %(request_id)s %(name)s %(levelname)s] %(message)s

syslog-ng

Here's an excerpt from my syslog-ng configuration:

# route logging from the Fairview site to its own files,
# named using the date
destination df_django_fc {
 file("/var/log/django/fairview/$R_YEAR$R_MONTH$R_DAY.log");
};

# filter that uses the Django project name 
# from the DRLOG_APP_NAME setting
filter f_django_fc {
 program("^fairview$");
};

# tie it all together: filter all incoming messages, 
# routing anything from program name "fairview"
#  to a file named using the date, e.g.
# /var/log/django/fairview/20080305.log
log {
 source(s_all);
 filter(f_django_fc);
 destination(df_django_fc);
};

The result

The content of the log file looks like this with the default format:

[2008-03-03T22:21:42.361+05:00 127.0.0.1] [10.0.0.1 ehq5aCR87Ek blog.models.Entry._get_related_entries INFO] related_entries: {}

The first two fields are the timestamp and logging host as recorded by syslog-ng. The next brackets contain the client IP address, the unique request ID, the logging category (in this case, from logging.getLogger('blog.models.Entry._get_related_entries')) and the logging level. The rest is the actual log message.

This site runs and logs on a single server, but you can see how it would be possible to run syslog-ng on a central log host, with each web server's logging easily traceable.

Note that since the drlog module commandeers Python's root logger (to allow you to log with logging.info() instead of having to instantiate a logger with logger.getLogger), it spoofs the extra context that comes from a request when you're logging in a context where one is not available. Otherwise the missing info would cause KeyError exceptions in the logging calls. So for example, when the logging system is configured, you see this:

[2008-03-03T22:25:52.210+05:00 127.0.0.1] [? ? root INFO] drlog configured; root logger: <drlog.RequestLogger instance at 0x8b1236c>, level: 20, handlers: [<logging.handlers.SysLogHandler instance at 0x8b0ceec>], format: 'fairview: [%(REMOTE_ADDR)s %(request_id)s %(name)s %(levelname)s] %(message)s'

The client IP and request ID are fudged with question marks.

Shortcomings, notes, suggestions

I've only used this with Apache running under Ubuntu Linux, and I've only tested Python's SysLogHandler and StreamHandler, but you should be able to plug in other implementations, like the NTEventLogHandler.

One of the reasons I went with syslog-ng was that it allowed me to sidestep the issue of permissions on log files when using mod_python or mod_wsgi in embedded mode. I ran into problems when logging from both the Web server and processes run from cron or the shell. If you're running under FastCGI or mod_wsgi's daemon mode, and don't need to log from multiple machines, you might be able to get by with a much simpler setup using a handler like the TimedRotatingFileHandler.

There is a syslog-ng agent for Windows that can forward logging to a syslog-ng server. It's part of the commercial syslog-ng Premium Edition. Presumably there are other ways to consolidate logging on Windows, but I'm not familiar with any good ones.

Update: I've found a couple of free ways to forward Windows event logging to a remote syslog server:

• Snare Agent for Windows
• NTSyslog

If you do get this working with these or other logging solutions, please leave a comment letting everyone know how you did it.