Python Logging: Group logs which belong to one req

Question

Is there a way to group logs of a python web application which belong to one web request?

Example:

2015-02-11 13:06:32 myapp.middleware.MYAPPMiddleware: INFO     Login of user foo was successful
2015-02-11 13:06:32 myapp.middleware.MYAPPMiddleware: INFO     Login of user bar failed
2015-02-11 13:06:32 myapp.send_mails: INFO     failed to send mail to [e-mail]

The above log lines are unrelated to each other.

How can you solve this the pythonic way?

Answer 1

Log entries in their essence are designed to be independent from each other.
The correct way to connect them together is to include some contextual information into the entries to filter by when looking through the logs later.

Here's a example of a Sharepoint log record with such information:

Timestamp               Process             TID     Area                    Category                    EventID Level       Message     Correlation
02/26/2015 17:49:19.65  w3wp.exe (0x1F40)   0x2358  SharePoint Foundation   Logging Correlation Data    xmnv    Medium      Name=Request (POST:http://reserver2:80/pest/_vti_bin/sitedata.asmx) d1e2b688-e0b2-481e-98ce-497a11acab44

In Python logging docs, Adding contextual information to your logging output recommends either of two methods: using a LoggerAdapter or a Filter.

LoggerAdapter is used like this (examples are based on those in the docs):

class AddConnIdAdapter(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        return <augment_message(msg,arbitrary_info)>, kwargs
la = AddConnIdAdapter(<logger>,extra=<parameters, saved in self.extra>)
<...>
la.info(<message>)

Filter is used like this:

#Either all messages should have custom fields
# or the Formatter used should support messages
# both with and without custom fields
logging.basicConfig(<...>,format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
class AddClientInfo(logging.Filter):
    #override __init__ or set attributes to specify parameters
    def filter(self, record):
        record.ip = <get_client_ip()>
        record.user = <get_client_name()>
        return True    #do not filter out anything
l=<logger()>
l.addFilter(AddClientInfo()) #can attach to either loggers or handlers
<...>
l.info('message')

As you can see, the difference is LoggerAdapter is non-transparent while Filter is transparent. In the examples, the former modifies the message text while the latter sets custom attributes (and actually writing them requires cooperation of the Formatter used) but in fact, both can do both.

So, the former is more useful if you only need to add the context to some messages while the latter is more fit to augment all, or a large portion of, the messages being logged.

Answer 2

You can assign random UUID to each request in init method, and add it to all log messages.

For example, in Tornado:

class MainRequestHandler(RequestHandler):
    def __init__(self, application, request):
        super(MainRequestHandler, self).__init__(application, request)
        self.uuid = uuid.uuid4()
        logging.info("%s | %s %s %s",
                     self.uuid,
                     request.method,
                     request.full_url(),
                     request.remote_ip)

As result, you will be able to grep log by this UUID to find all messages which belong to separate request.