aiohttp-request-id-logging

Motivation

When logging from an async application (e.g. aiohttp web application), log messages from different async tasks, http requests etc. are intertwined and you cannot surely tell which line was generated by what request. For example:

2020-01-15 15:35:37,501  INFO: Processing transfer id 1234
2020-01-15 15:35:37,976  INFO: Processing transfer id 5678
2020-01-15 15:35:38,201 ERROR: Oh no, something bad has happened! Cannot finish the transfer.
2020-01-15 15:35:38,504  INFO: 127.0.0.1 [15/Jan/2020:14:35:36 +0000] "GET / HTTP/1.1" 200 165 "-" "curl/7.68.0"
2020-01-15 15:35:38,982  INFO: 127.0.0.1 [15/Jan/2020:14:35:36 +0000] "GET / HTTP/1.1" 500 165 "-" "curl/7.68.0"

So, which transfer has failed? The one with id 1234, or the one with id 5678?

Of course, ideally the error message should contain also the transfer id. But it is not always this case, or you may want to inspect also other log messages that were logged by that specific task/request.

When you start to use this library in your aiohttp web application, this is how your log messages will look like:

2020-01-15 15:58:47,238  INFO: [req:O5bvIlU] Processing GET / (__main__:hello)
2020-01-15 15:58:47,950  INFO: [req:xtMacpA] Processing GET / (__main__:hello)
2020-01-15 15:58:48,240  INFO: [req:O5bvIlU] Processing transfer id 1234
2020-01-15 15:58:48,953  INFO: [req:xtMacpA] Processing transfer id 5678
2020-01-15 15:58:49,182 ERROR: [req:xtMacpA] Oh no, something bad has happened! Cannot finish the transfer.
2020-01-15 15:58:49,242  INFO: [req:O5bvIlU] 127.0.0.1 "GET / HTTP/1.1" 200 165 "-" "curl/7.68.0"
2020-01-15 15:58:49,959  INFO: [req:xtMacpA] 127.0.0.1 "GET / HTTP/1.1" 500 165 "-" "curl/7.68.0"

Installation

$ python3 -m pip install https://github.com/messa/aiohttp-request-id-logging/archive/v0.0.6.zip

Or add this line to requirements.txt:

aiohttp-request-id-logging @ https://github.com/messa/aiohttp-request-id-logging/archive/v0.0.6.zip

Usage

from aiohttp.web import Application, Response, RouteTableDef, run_app
from aiohttp.web_log import AccessLogger
from aiohttp_request_id_logging import (
    setup_logging_request_id_prefix,
    request_id_middleware,
    RequestIdContextAccessLogger)

routes = RouteTableDef()

@routes.get('/')
async def hello(request):
    return Response(text="Hello, world!\n")

logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s [%(threadName)s] %(name)-26s %(levelname)5s: %(requestIdPrefix)s%(message)s')

setup_logging_request_id_prefix()

app = Application(middlewares=[request_id_middleware()])
app.router.add_routes(routes)

run_app(app, access_log_class=RequestIdContextAccessLogger)

For more complete example see demo.py.

How it works

This library helps you to add request (correlation) id to the log messages in a few steps:

request_id_middleware(): Generate random request_id for each aiohttp request and
- store it in a ContextVar aiohttp_request_id_logging.request_id
- store it also in request['request_id']
setup_logging_request_id_prefix(): Modify logging record factory so that the request_id is attached to every logging record created
- so you should modify your log format, for example logging.basicConfig(format=... %(levelname)5s: %(requestIdPrefix)s%(message)s')
Because the aiohttp access logging happens out of the middleware scope, the request id ContextVar would be already resetted. So RequestIdContextAccessLogger is provided that adds the request_id to the access log message.
If you use Sentry, a request_id tag is added when the request is processed.

Sentry integration will be active only if you have sentry_sdk installed.

Alternatives

TODO: find other solutions to this problem, perhaps also from different frameworks or platforms

Links

In general, you should be familiar with Aiohttp documentation related to production deployment:

This is where this started: https://stackoverflow.com/a/58801740/196206