Configuring logging for Web applications

tl;dr: You can easily configure your web applications with Python logging, so that logged messages can go into web-application-specific log files (or other destinations) even for multiple web applications in the same Python process, and have those logs contain request-specific information such as remote user IP address, request method and others. Demonstration scripts are here and here, copy them to the same initially empty folder and run webapptest.py in that folder, and then look at app*.log. Look at the InjectingFilter class - that's the core of the solution. Read on for more information.

In a recent post on Reddit, Armin Ronacher, developer of Werkzeug and Jinja among other things, had this to say:

I don't know a setup of logging that would work out for me. But maybe you do and could share. Say I am a library called by anyone and use three or five loggers without any handlers. Now in the same Python process are two different web applications, each independently but using the same library. How can each of these applications have their own log where all logging messages from that library are redirected to the correct one of these application's log files (the correct one is the one where all calls were issued by the same handling thread) including additional information such as current IP and HTTP request method. I tried, I failed.

Now, Armin has recently been working on his own logging library, and saying at conferences and in other public fora that he's done this mainly because he thinks Python logging is not really suited to Web applications. This, despite the fact that it's used in Google App Engine, Pylons, Tornado and other Web application platforms, by the many developers that use them. Now Armin can make a little arm-waving FUD go a long way, and I was very glad to have an actual problem statement from him that I could try to nail with a solution. I'm pleased to say it only took around ten minutes or so of work to come up with something which seems to solve his problem for him. His response? "This is actually quite neat ..." ;-)

To illustrate the solution, I first wrote a simple module which represents the library. This demonstration example only uses one logger, but it could use three or five loggers and the solution would be the same. Here is the library module, christened webapplib.py:

import logging
import time

logger = logging.getLogger(__name__)

def useful():
    logger.debug('Hello from webapplib!')
    time.sleep(0.01)

The useful() function represents a call into the library from a Web application; this call will be made during request processing. The time.sleep() call is there to simulate real activity, so that multiple threads will definitely be running at the same time processing requests, for a more realistic scenario.

The next step was to construct a test harness which simulates requests and web applications. First, the request:

class Request:
    def __init__(self, method, ip):
        self.method = method
        self.ip = ip

REQUESTS = [
    Request('GET', '192.168.2.20'),
    Request('POST', '192.168.2.20'),
    Request('GET', '192.168.2.21'),
    Request('POST', '192.168.2.21'),
    Request('GET', '192.168.2.22'),
    Request('POST', '192.168.2.22'),
]

The dummy Request class just has HTTP method and IP, as example attributes which need to be put into the logs. The REQUESTS array is just a list of dummy requests which will be sent, during the test run, to the dummy web applications.

Next, we need to consider how to simulate the Web applications. Let's start with the following skeleton snippet:

import logging

root = logging.getLogger()
root.setLevel(logging.DEBUG)

formatter = logging.Formatter('%(asctime)s %(threadName)-11s %(appName)s %(name)-9s %(ip)s %(method)-4s %(message)s')

class WebApp:
    def __init__(self, name):
        self.name = name
        handler = logging.FileHandler(name + '.log', 'w')
        handler.setFormatter(formatter)
        root.addHandler(handler)
        self.num_requests = 0

    def process_request(self, request):
        self.num_requests += 1
        logger.debug('Request processing started')
        webapplib.useful()
        logger.debug('Request processing finished')

Now the appName, method and ip in the format string are not part of the normal set of attributes which are part of logging: they are extra request-specific attributes which we want to inject into all log messages. In order for the format string to have the desired effect, attributes with those names will need to be added to the LogRecord for the event being logged, before formatting takes place; we'll come to that in a bit.

The WebApp class, representing a dummy web application, is fairly straightforward: we initialize a FileHandler for that application in the constructor, based on its name, set its formatter, and add it to the root logger.

We maintain a counter of requests processed by each WebApp instance. This counter is incremented in process_request, which we will call from our top-level test harness to simulate processing a request. This method logs two DEBUG messages, and calls into the common webapplib library's useful() method, which will also log a DEBUG message. So in total, each processed request should result in 3 lines in the log.

Before looking at the specifics of the solution to the problem, let's see what the top-level test harness looks like:

def main():
    app1 = WebApp('app1')
    app2 = WebApp('app2')
    apps = [app1, app2]
    threads = []
    #Add a common handler which will capture all events
    handler = logging.FileHandler('app.log', 'w')
    handler.setFormatter(formatter)
    root.addHandler(handler)
    #while True:
    for i in xrange(1000):
        try:
            app = choice(apps)
            request = choice(REQUESTS)
            t = threading.Thread(target=app.process_request, args=(request,))
            threads.append(t)
            t.start()
        except KeyboardInterrupt:
            break    
    for t in threads:
        t.join()
    for app in apps:
        print '%s processed %s requests' % (app.name, app.num_requests)
    
if __name__ == '__main__':
    main()

So the test harness creates two dummy Web applications called app1 and app2, and sends a thousand requests (chosen at random from our array of pre-constructed requests) to an app which is also chosen at random. A FileHandler for 'app.log' is created and added to the root logger, which will capture all logging (i.e. across all Web applications). Each request is processed on a separate thread.

So far, we've described the simulation artefacts and the overall structure of the test harness. Now let's look at the core of the solution. Let's review the problems we have to solve:

• Each LogRecord needs the relevant thread-specific information injected into it before formatting.
• The handler for each of the application-specific logs needs to filter out any record which is not intended for that log.

We can solve both of these by using an appropriate Filter subclass. We'll call it InjectingFilter, because it injects data into the LogRecord as well as acting as a filter. But how will it work? We'll use a threading.local object to hold thread-specific state which is needed by the filter. Here's the first cut of what InjectingFilter looks like:

import threading

tlocal = threading.local()

class InjectingFilter(logging.Filter):
    def filter(self, record):
        record.method = tlocal.request.method
        record.ip = tlocal.request.ip
        return True

This shows just the injection logic of the filter, and not any filtering logic. The thread-local object tlocal will hold a reference to the request currently being processed, which the filter uses to inject HTTP method and IP address into the LogRecord. This request needs to be set into the thread-local in WebApp.process_request, which now looks like this:

    def process_request(self, request):
        tlocal.request = request
        self.num_requests += 1
        logger.debug('Request processing started')
        webapplib.useful()
        logger.debug('Request processing finished')

So far, so good. Next, we need to implement the filtering part: this is done by attaching, to each app-specific handler, an app-specific filter. In order to operate effectively, the filter needs to know whether the current thread belongs to its Web application (in which case, the record is accepted for processing) or not (in which case, the record is rejected). One easy way of doing this is to ensure that the WebApp maintains a set of names of the threads it's currently using, and the filter can just check if the current thread belongs to its app's set. So we need to keep a reference to the app in the filter, and this also allows the injection of the appName attribute into the LogRecord. So the WebApp class will now look like this (simple implementation):

class WebApp:
    def __init__(self, name):
        self.name = name
        self.threads = set()
        handler = logging.FileHandler(name + '.log', 'w')
        f = InjectingFilter(self)
        handler.setFormatter(formatter)
        handler.addFilter(f)
        root.addHandler(handler)
        self.num_requests = 0

    def process_request(self, request):
        tlocal.request = request
        tlocal.appName = self.name
        tname = threading.currentThread().getName()
        self.threads.add(tname)
        self.num_requests += 1
        try:
            logger.debug('Request processing started')
            webapplib.useful()
            logger.debug('Request processing finished')
        finally:
            self.threads.remove(tname)

and the InjectingFilter class will look like this  (simple implementation):

class InjectingFilter(logging.Filter):
    def __init__(self, app):
        self.app = app

    def filter(self, record):
        record.method = tlocal.request.method
        record.ip = tlocal.request.ip
        record.appName = tlocal.appName
        tname = threading.currentThread().getName()
        return tname in self.app.threads

You can pick up the whole script as webapptest.py from here, and use it with the webapplib.py script shown as the first code in this post. What happens if we run it?

vinay@zeta-lucid:~/projects/scratch$ python webapptest.py
app1 processed 506 requests
app2 processed 494 requests
vinay@zeta-lucid:~/projects/scratch$ wc -l app*.log
  1518 app1.log
  1482 app2.log
  3000 app.log
  6000 total 

So the app.log file contains all the log messages - 3 per request, for a total of 3000 - and the lines in app1.log and app2.log add up to 3000 too, which looks promising. Plus the individual line counts for these files are 3 x the number of requests processed, so that's also consistent. Let's look at the first few lines of each file:

vinay@zeta-lucid:~/projects/scratch$ head app.log app1.log app2.log
==> app.log <==
2010-09-17 16:11:48,226 Thread-1    app1 __main__  192.168.2.20 GET  Request processing started
2010-09-17 16:11:48,227 Thread-1    app1 webapplib 192.168.2.20 GET  Hello from webapplib!
2010-09-17 16:11:48,228 Thread-2    app1 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,229 Thread-2    app1 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,230 Thread-3    app2 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,230 Thread-3    app2 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,231 Thread-4    app1 __main__  192.168.2.22 POST Request processing started
2010-09-17 16:11:48,232 Thread-4    app1 webapplib 192.168.2.22 POST Hello from webapplib!
2010-09-17 16:11:48,233 Thread-5    app2 __main__  192.168.2.21 GET  Request processing started
2010-09-17 16:11:48,233 Thread-5    app2 webapplib 192.168.2.21 GET  Hello from webapplib!

==> app1.log <==
2010-09-17 16:11:48,226 Thread-1    app1 __main__  192.168.2.20 GET  Request processing started
2010-09-17 16:11:48,227 Thread-1    app1 webapplib 192.168.2.20 GET  Hello from webapplib!
2010-09-17 16:11:48,228 Thread-2    app1 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,229 Thread-2    app1 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,231 Thread-4    app1 __main__  192.168.2.22 POST Request processing started
2010-09-17 16:11:48,232 Thread-4    app1 webapplib 192.168.2.22 POST Hello from webapplib!
2010-09-17 16:11:48,236 Thread-7    app1 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,236 Thread-7    app1 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,237 Thread-8    app1 __main__  192.168.2.22 POST Request processing started
2010-09-17 16:11:48,238 Thread-8    app1 webapplib 192.168.2.22 POST Hello from webapplib!

==> app2.log <==
2010-09-17 16:11:48,230 Thread-3    app2 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,230 Thread-3    app2 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,233 Thread-5    app2 __main__  192.168.2.21 GET  Request processing started
2010-09-17 16:11:48,233 Thread-5    app2 webapplib 192.168.2.21 GET  Hello from webapplib!
2010-09-17 16:11:48,234 Thread-6    app2 __main__  192.168.2.22 GET  Request processing started
2010-09-17 16:11:48,235 Thread-6    app2 webapplib 192.168.2.22 GET  Hello from webapplib!
2010-09-17 16:11:48,239 Thread-9    app2 __main__  192.168.2.20 POST Request processing started
2010-09-17 16:11:48,239 Thread-9    app2 webapplib 192.168.2.20 POST Hello from webapplib!
2010-09-17 16:11:48,241 Thread-3    app2 __main__  192.168.2.21 POST Request processing finished
2010-09-17 16:11:48,244 Thread-5    app2 __main__  192.168.2.21 GET  Request processing finished

So app.log contains interspersed messages from app1 and app2, but app1.log seems to contain just app1 messages, and app2.log seems to contain just app2 messages. This is encouraging, and we can confirm with:

vinay@zeta-lucid:~/projects/scratch$ grep app1 app1.log | wc -l
1518
vinay@zeta-lucid:~/projects/scratch$ grep app2 app1.log | wc -l
0
vinay@zeta-lucid:~/projects/scratch$ grep app2 app2.log | wc -l
1482
vinay@zeta-lucid:~/projects/scratch$ grep app1 app2.log | wc -l
0

The log lines all contain appName, request method and IP address, as required, Job done, it seems.

Of course, this is a test scenario with dummy requests and web applications implemented simplistically, but the principle of the solution will apply equally to real web application server environments.