Twisted. How to write a unique prefix to the log for each request

I have twisted server. It is run with plugin. I want to write unique prefix for each entry depending on the request.

This means that when user1 make a request, it will generate a unique string that will be prefixed the log records (only for this request). When user2 will make a request it will be another unique prefix for the record to the log.

I think it's should be log observer logger, but how to group records between user requests?

Solution

There are several parts to this question.

First, the easy part - how do you give a log event a custom prefix? There are several ways to go about this, of course. You could do something very, very simple:

from twisted.python.log import msg

def myLog(message):
    msg("my prefix" + message)

That is, just prefix the log message with the desired prefix. This is probably not what you really want though, since it mangles your log message and mixes the prefix text in with the log message in a way that's hard to reverse (consider some logged messages might come from a different system and not have any prefix - but how will you tell?).

So instead of using a prefix, you can use another key in the log event:

from twisted.python.log import msg

def myLog(message):
    msg(message, system="my prefix")

This will cause the log event that is emitted to look sort of (not exactly, close enough) like:

{"message": message, "system": "my prefix"}

And the "system" key happens to be a special one. It is recognized by the default file log observer in Twisted and its contents end up in the log message written to the file:

2013-07-23 06:25:35-0400 [my prefix] message

You may not want to co-opt the "system" key for your user-based information though. After all, the system is probably something to do with the HTTP server. The user is not a system.

You can pass msg any other keyword arguments you want though:

from twisted.python.log import msg

def myLog(message):
    msg(message, userIdentifier="alice")

userIdentifier will be ignored by the file log observers that ship with Twisted, but you can write your own observer that will pay attention to it. For example:

from twisted.python.log import FileLogObserver, textFromEventDict, addObserver

class MyObserver(FileLogObserver):
    def emit(self, event):
        text = textFromEventDict(event)
        if text and event.get("userIdentifier"):
            adjusted = event.copy()
            adjusted["message"] = "(%s) %s" % (event["userIdentifier"], text)
            FileLogObserver.emit(self, adjusted)

addObserver(MyObserver(...).emit)

This gives you an observer that notices your special kind of log events and modifies their text before sending them on to the normal file writing logic. I've just done some simple text formatting here, but you could do something better like writing each user's events to their own dedicated log file or use a structured log format that's easier to parse.

I hope this is all useful so far, but it doesn't help you actually get the correct user identifier into particular log events. So far every user is "alice".

First, let's see how we can make it possible to vary the user. One way is by making userIdentifier a parameter:

from twisted.python.log import msg

def myLog(message, userIdentifier):
    msg(message, userIdentifier=userIdentifier)

Of course, myLog now looks a little silly. You could just call msg. Perhaps you want something a little more automatic than this. You can wrap a user identifier up in a callable so you don't have to keep passing it in:

from functools import partial

from twisted.python.log import msg

aliceLog = partial(msg, userIdentifier="alice")

Now you can log events for alice just by doing aliceLog("login"). You probably don't want to define this at the top-level, since you don't know a username yet, and presumably you'll have multiple users. Fortunately you can make these at any time pretty easily.

Let's leave that aside for now and consider how you'll identify your users.

There are a lot of ways, so I'm just going to assume that request.getUser() is suitable. Replace this with whatever other mechanism you'd actually like to use.

Now you need to keep track of this information. One simple approach is to pass it as an argument to any code that wants to log an event related to the user. I hope this isn't actually a burden, since any code that wants to log an event related to a user probably already needs to know which user it is acting for.

This gets into a slightly hairy area of Twisted Web. The traversal system (that is, getChild) is pretty flexible and depending on how you use it, the way you pass information to its ultimate consumer can vary widely.

One way to do this is with a transparent IResource wrapper. The idea here is you insert an IResource into your hierarchy that doesn't consume any segments, just inspects the request and creates some useful state, such as a user identifier. For example,

from twisted.web.resource import IResource
from twisted.python.components import proxyForInterface

class GiveChildrenUserInfo(proxyForInterface(IResource)):
    def getChild(self, request, segment):
        child = self.original.getChild(request, segment)
        child.setUser(request.getUser())
        return GiveChildrenUserInfo(child)

rootResource = GiveChildrenUserInfo(actualRootResource)
...

Notice two things about this. First, I have invented a setUser method that all your resources must now implement. It will be called on every resource with the user taken from the request. Now those resources can use that user information - for example to call msg(message, userIdentifier=user) or to define such a log helper using partial as demonstrated above.

There's still potentially a lot of ground related to logging that I haven't covered here, but I hope this is enough to get you started and demonstrate some of the possible directions.