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