Aiohttp request_id logging

aiohttp_request_id_logging.py

# BTW. I have created a library for this: https://github.com/messa/aiohttp-request-id-logging

from aiohttp import web
from aiohttp.web_log import AccessLogger
import asyncio
from asyncio import CancelledError
from contextvars import ContextVar
import logging
import os
import secrets
try:
    import sentry_sdk
except ImportError:
    sentry_sdk = None

logger = logging.getLogger(__name__)

sentry_dsn = os.environ.get('SENTRY_DSN')


# 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}'
        # Sentry groups events by log record message (without attributes), so it
        # is not a good idea to make each message unique. It is better to put the
        # request id into log record attributes.
        record.requestIdPrefix = f'[{req_id}] ' if req_id else ''
        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')

    # here you can try the Sentry error/warning reporting if you want
    if request.query.get('warning'):
        logger.warning('Warning value: %s', request.query['warning'])
    if request.query.get('error'):
        logger.error('Error value: %s', request.query['error'])

    await asyncio.sleep(1)
    return web.Response(text="Hello, world!\n")


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

setup_log_record_factory()

if sentry_sdk and sentry_dsn:
    logger.info('Initializing Sentry SDK')
    sentry_sdk.init(sentry_dsn)


@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(10).replace('_', '').replace('-', '')[:7]
    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