aiohttp_request_id_logging.py

# 05_aiohttp.py

from aiohttp import web
from aiohttp.web_log import AccessLogger
from asyncio import CancelledError
from contextvars import ContextVar
import asyncio
import logging
import secrets

logger = logging.getLogger(__name__)


# contextvar that contains given request tracing id
request_id = ContextVar('request_id')


def setup_log_record_factory():
    '''
    Wrap logging request factory so that [{request_id}] is prepended to each message
    '''
    old_factory = logging.getLogRecordFactory()

    def new_factory(*args, **kwargs):
        record = old_factory(*args, **kwargs)
        req_id = request_id.get(None)
        if req_id:
            record.msg = f'[{req_id}] {record.msg}'
        return record

    logging.setLogRecordFactory(new_factory)


async def hello(request):
    '''
    Sample hello world handler.

    It sleeps and logs so that you can test the behavior of running
    multiple parallel handlers.
    '''
    logger.info('Started processing request')
    await asyncio.sleep(1)
    logger.info('Doing something')
    await asyncio.sleep(1)
    return web.Response(text="Hello, world!\n")


logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s %(name)-14s %(levelname)s: %(message)s')

setup_log_record_factory()


@web.middleware
async def add_request_id_middleware(request, handler):
    '''
    Aiohttp middleware that sets request_id contextvar and request['request_id']
    to some random value identifying the given request.
    '''
    req_id = secrets.token_urlsafe(5).replace('_', 'x').replace('-', 'X')
    request['request_id'] = req_id
    token = request_id.set(req_id)
    try:
        try:
            return await handler(request)
        except CancelledError as e:
            logger.info('(Cancelled)')
            raise e
    finally:
        request_id.reset(token)


app = web.Application(middlewares=[add_request_id_middleware])
app.add_routes([web.get('/', hello)])


class CustomAccessLogger (AccessLogger):

    def log(self, request, response, time):
        token = request_id.set(request['request_id'])
        try:
            super().log(request, response, time)
        finally:
            request_id.reset(token)


web.run_app(
    app,
    access_log_class=CustomAccessLogger,
    access_log_format=AccessLogger.LOG_FORMAT.replace(' %t ', ' ') + ' %Tf')

example.txt

Before:

2019-11-11 13:22:29,636 __main__       INFO: Started processing request
2019-11-11 13:22:29,637 __main__       INFO: Started processing request
2019-11-11 13:22:29,638 __main__       INFO: Started processing request
2019-11-11 13:22:30,638 __main__       INFO: Doing something
2019-11-11 13:22:30,638 __main__       INFO: Doing something
2019-11-11 13:22:31,639 aiohttp.access INFO: 127.0.0.1 "GET / HTTP/1.1" 200 165 "-" "curl/7.66.0" 2.002373
2019-11-11 13:22:31,641 aiohttp.access INFO: 127.0.0.1 "GET / HTTP/1.1" 200 165 "-" "curl/7.66.0" 2.003226


After:

2019-11-11 13:23:39,428 __main__       INFO: [ZSb66s4] Started processing request
2019-11-11 13:23:39,428 __main__       INFO: [lf4uJnU] Started processing request
2019-11-11 13:23:39,428 __main__       INFO: [tAFSV5w] Started processing request
2019-11-11 13:23:39,921 __main__       INFO: [tAFSV5w] (Cancelled)
2019-11-11 13:23:40,428 __main__       INFO: [ZSb66s4] Doing something
2019-11-11 13:23:40,429 __main__       INFO: [lf4uJnU] Doing something
2019-11-11 13:23:41,430 aiohttp.access INFO: [ZSb66s4] 127.0.0.1 "GET / HTTP/1.1" 200 165 "-" "curl/7.66.0" 2.001927
2019-11-11 13:23:41,430 aiohttp.access INFO: [lf4uJnU] 127.0.0.1 "GET / HTTP/1.1" 200 165 "-" "curl/7.66.0" 2.002659