Tornado: How to keep reference of HTTP request in logging ?

[rmedaer]

I'm using (a lot) logging through tornado.log. Each time I implement a little bit more complex handler, I'm adding some tornado.log.gen_log.debug("I'm doing some stuff"); to keep trace of what I'm doing and obviously to help maintenance and debugging.

However, since tornado has a great asynchronous pattern, I have logs mixed across simultaneous requests. It makes debugging impossible !

The easiest solution would be to add reference of HTTP request concerned by the log line. The question is then: _how to do it ?_

[noxiouz]

AFAIK, the most relevant solution is to keep track of request using http://www.tornadoweb.org/en/stable/stack_context.html It's like coroutine-local storage.
But I ended up with a solution when I attach request.logger = ContextAdapter(inherited from logging.LoggerAdapter) with generated trace_id.

[rmedaer]

@noxiouz : then I should inherit my handlers from "LoggerHandler" .. or is it better to do a decorator to monkey patch handler and/or its methods ?
Do you have an example ?
Thanks in advance,

[noxiouz]

Lots of details hide what you really need, but:
https://github.com/cocaine/cocaine-tools/blob/master/cocaine/proxy/proxy.py#L212 - it's inside decorator, where I attached context information.(https://docs.python.org/3/library/logging.html#loggeradapter-objects)
Also, the format should contain trace_id field like this https://github.com/cocaine/cocaine-tools/blob/master/cocaine/proxy/proxy.py#L959.
That's the adapter itself: https://github.com/cocaine/cocaine-tools/blob/master/cocaine/proxy/logutils.py#L4

The only disadvantage is you need to log everything using request.logger. It might be an issue to gather logs from libraries which rely on the globally accessible logger.

Unfortunately, I have no example with stack_context right now

[noxiouz]

@rmedaer that's an example with stack_context. I believe it's the best approach:

#!/usr/bin/env python
import random
import uuid
import logging

import tornado.web
import tornado.ioloop
import tornado.options
import tornado.log

from tornado.stack_context import run_with_stack_context, StackContext
from tornado import gen

class Context(object):
    class Data(object):
        def __init__(self, request_id=0):
            self.request_id = request_id

        def __eq__(self, other):
            return self.request_id == other.request_id

    _data = Data()

    def __init__(self, request_id=0):
        self.current_data = Context.Data(request_id=request_id)
        self.old_data = None

    def __enter__(self):
        if Context._data == self.current_data:
            return

        # Keep previous context data
        self.old_context_data = Context.Data(
            request_id=Context._data.request_id,
        )

        Context._data = self.current_data

    def __exit__(self, exc_type, exc_value, traceback):
        if self.old_data is not None:
            Context._data = self.old_data

class ContextFilter(logging.Filter):
    def filter(self, record):
        request_id = Context._data.request_id
        record.request_id = request_id
        return True


def wrap(coro):
    @gen.coroutine
    def dec(self):
        request_id = uuid.uuid4().hex
        yield run_with_stack_context(StackContext(lambda: Context(request_id)), lambda: coro(self))
    return dec


class MainHandler(tornado.web.RequestHandler):
    @wrap
    @gen.coroutine
    def get(self):
        sleep = random.randint(1, 10)
        tornado.log.access_log.info("BEFORE SLEEP %d seconds", sleep)
        yield gen.sleep(sleep)
        self.write("Hello, world")
        tornado.log.access_log.info("AFTER SLEEP %d", sleep)


def make_app():
    return tornado.web.Application([
        (r"/", MainHandler),
    ])

if __name__ == "__main__":
    tornado.options.parse_command_line()
    handler = logging.StreamHandler()
    handler.setFormatter(logging.Formatter(fmt="WITH REQUEST ID: %(levelname)1.1s %(request_id)s %(message)s"))
    handler.addFilter(ContextFilter())
    tornado.log.access_log.addHandler(handler)
    app = make_app()
    app.listen(8888)
    tornado.ioloop.IOLoop.current().start()

Example of logs:

WITH REQUEST ID: I 098f093d0e9944a29fdac03ddc91f0a8 BEFORE SLEEP 4 seconds
[I 171215 22:43:26 tornado_stack_context:63] BEFORE SLEEP 4 seconds
WITH REQUEST ID: I dd6ba836cb7647b2bdc5537a653032d4 BEFORE SLEEP 6 seconds
[I 171215 22:43:26 tornado_stack_context:63] BEFORE SLEEP 6 seconds
WITH REQUEST ID: I 0a683f7ae1324d0bb2b31429e61e6c00 BEFORE SLEEP 1 seconds
[I 171215 22:43:26 tornado_stack_context:63] BEFORE SLEEP 1 seconds
WITH REQUEST ID: I dc34ce70d35941bba70c735a4d8d94fb BEFORE SLEEP 6 seconds
[I 171215 22:43:26 tornado_stack_context:63] BEFORE SLEEP 6 seconds
WITH REQUEST ID: I f4ef0158a151444da4550d0a2b55d175 BEFORE SLEEP 2 seconds
[I 171215 22:43:26 tornado_stack_context:63] BEFORE SLEEP 2 seconds
WITH REQUEST ID: I 0a683f7ae1324d0bb2b31429e61e6c00 AFTER SLEEP 1
[I 171215 22:43:27 tornado_stack_context:66] AFTER SLEEP 1
WITH REQUEST ID: I 0a683f7ae1324d0bb2b31429e61e6c00 200 GET / (::1) 1008.32ms
[I 171215 22:43:27 web:2063] 200 GET / (::1) 1008.32ms
WITH REQUEST ID: I 9520a508b33649679647010eb66bf69a BEFORE SLEEP 3 seconds
[I 171215 22:43:27 tornado_stack_context:63] BEFORE SLEEP 3 seconds
WITH REQUEST ID: I f4ef0158a151444da4550d0a2b55d175 AFTER SLEEP 2
[I 171215 22:43:28 tornado_stack_context:66] AFTER SLEEP 2
WITH REQUEST ID: I f4ef0158a151444da4550d0a2b55d175 200 GET / (::1) 2005.08ms
[I 171215 22:43:28 web:2063] 200 GET / (::1) 2005.08ms
WITH REQUEST ID: I e4982de7bc5a4f5099f4deef8f8d2a09 BEFORE SLEEP 6 seconds
[I 171215 22:43:28 tornado_stack_context:63] BEFORE SLEEP 6 seconds

[bdarnell]

This is the sort of thing that stack context is designed for, but it has flaws: it slows things down, and it's incompatible with async def coroutines (which are the way of the future). I've considered deprecating it and removing it from future versions of tornado. I wouldn't recommend using it for anything operationally critical, although adding a bit of extra context to log messages should be fine.

There is a proposal to add a similar feature which would work with async def in future versions of python.

[rmedaer]

@noxiouz thank you for the example. I also found the following example which is using private _execute function to call the StackContext.

I used both of them to implement it using class decorator:

# -*- coding: utf-8 -*-

import threading
from tornado.stack_context import StackContext
from logging import Filter
from uuid import uuid4

class RequestContextData(object):
    def __init__(self, request_id=0):
        self.request_id = request_id

    def __eq__(self, other):
        return self.request_id == other.request_id

class RequestContext(object):

    _state = threading.local()
    _state.data = RequestContextData()
    _data = None

    class __metaclass__(type):
        @property
        def data(cls):
            if not hasattr(cls._state, 'data'):
                return RequestContextData()
            return cls._state.data

    def __init__(self, request_id=0):
        self._data = RequestContextData(request_id=request_id)

    def __enter__(self):
        self._prev_data = self.__class__.data
        self.__class__._state.data = self._data

    def __exit__(self, exc_type, exc_value, traceback):
        self.__class__._state.data = self._prev_data
        del self._prev_data
        return False

class RequestContextFilter(Filter):
    def filter(self, record):
        request_id = RequestContext.data.request_id

        if not request_id:
            return True

        record.msg = str(request_id) + ': ' + record.msg

        return True

def contextualize_logging(handler):
    """
    This class decorator is contextualizing the HTTP request in logging.
    """

    def wrap_execute(_execute):
        def wrapper(self, transforms, *args, **kwargs):
            request_id = uuid4().hex
            with StackContext(lambda: RequestContext(request_id)):
                return _execute(self, transforms, *args, **kwargs)

        return wrapper

    handler._execute = wrap_execute(handler._execute)
    return handler

Instead of add new Record property, I modify the msg with request_id if set.

[rmedaer]

Hi guys,

I'm waking up this issue because of next Tornado release (6.0) where stack_context is deprecated: see https://github.com/tornadoweb/tornado/blob/f6e98e279bf78d2984351062906eb100a7303c35/docs/releases/v5.1.0.rst#tornadostack_context

Few questions:

• How can we implement the same feature ? I guess using contextvars which is available from Python 3.7 ?
• Could we plan to embed this feature in Tornado itself ?

[bdarnell]

Yes, contextvars is the future for this sort of thing (or explicitly passing data around where it is needed). Unfortunately in order to be compatible with async def native coroutines, it requires support in the Python runtime, so we can't emulate this feature in Tornado alone.

[bdarnell]

The contextvars module will work as expected in Tornado 6.0 and Python 3.7 (tested in #2561).