Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
Aiohttp request_id logging
# 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')
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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment