Log unique request IDs with Pyramid

For a Pyramid project, I have been looking for a way to stick a unique request ID on every generated log lines. I wanted something like:

2012-08-02 15:19:55,402 INFO  [worker 4][request=SOME_UNIQUE_ID] Message here!

This way I can grep through my logs for a particular request ID and extract all logs lines generated by this one request. This is especially useful when multiple requests have interlaced log lines in the output.

Dog tag of a request

Generate a unique ID

First off, we have to generate a unique ID for each request and have it accessible directly on the object:

>>> request.id
'cc30495a-73ba-40be-978f-49cc64822049'

For this, we need to extend the default Request class used by Pyramid with our own class.

from uuid import uuid4

from pyramid.request import Request
from pyramid.decorator import reify

class MyRequest(Request):
    @reify
    def id(self):
        return str(uuid4())

Then we have to configure our Pyramid project -- in the main __init__.py file -- to use this request class of ours.

# import our MyRequest class
# ...

def main(global_config, **settings):
    config = Configurator(settings=settings)
    config.set_request_factory(MyRequest)

Great. Now all our requests will have the request.id attribute.

Inject the unique ID in the logs

Now we have to find a way to print the request ID in our logs. Some options:

1. Create a custom logging method that retrieves the request object by using the get_current_request() functionality of Pyramid and inject the request ID in the log message. This solution is not very elegant as we have to maintain a homemade logger and change all our code to use it. Booooring.
2. Create a Pyramid Tween to hack in the request ID into thread's name, e.g., "worker 4" that is already shown in our logs. Now THAT sounds like fun! :)

The tween

So here is our tween.

import threading

def hack_thread_name_tween_factory(handler, registry):
    def hack_thread_name_tween(request):
        # Hack in the request ID inside the thread's name
        current_thread = threading.current_thread()
        original_name = current_thread.name
        current_thread.name = "%s][request=%s" % (original_name, request.id)
        try:
            response = handler(request)
        finally:
            # Restore the thread's original name when done
            current_thread.name = original_name
        return response
    return hack_thread_name_tween

Now let's configure our Pyramid project to use that tween.

# import our MyRequest class
# ...

def main(global_config, **settings):
    config = Configurator(settings=settings)
    config.set_request_factory(MyRequest)
    config.add_tween('myproject.lib.tweens.hack_thread_name_tween_factory')

And here is the resulting log when hitting your server!

2012-08-02 15:19:55,402 INFO  [worker 4][request=cc30495a-73ba-40be-978f-49cc64822049] Message here!

Now whenever we see something wrong in our logs, we can grep the request ID of the culprit and find out how it behaved.

$ grep cc30495a-73ba-40be-978f-49cc64822049 app-out.log
2012-08-02 15:19:55,402 INFO  [worker 4][request=cc30495a-73ba-40be-978f-49cc64822049] All is good here!
2012-08-02 15:19:55,524 INFO  [worker 4][request=cc30495a-73ba-40be-978f-49cc64822049] Everything's a-ok!
2012-08-02 15:19:55,598 ERROR [worker 4][request=cc30495a-73ba-40be-978f-49cc64822049] Aaah, I'm failing here!

The faster way

Of course, you could skip the subclassing of the Request class and generate the UUID directly in the tween. But I thought it might come in handy to have the request.id available for future reference, besides from the fact that I already had a custom Request class for other purpose.