Last active
March 17, 2021 03:52
-
-
Save messa/c538fc267550ec67a1fed244183dcf1e to your computer and use it in GitHub Desktop.
Aiohttp request_id logging
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
# 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') |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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