logging: add requestID for access logs, application logs and traceback logs

simplyblock_core/utils/__init__.py

@@ -1,4 +1,5 @@
 # coding=utf-8
+import contextvars
 import glob
 import json
 import logging
@@ -12,6 +13,14 @@
 import sys
 import uuid
 import time
+
+request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar('request_id', default='-')
+
+
+class RequestIdFilter(logging.Filter):
+    def filter(self, record):
+        record.request_id = request_id_var.get()
+        return True
 from datetime import datetime, timezone
 from typing import Union, Any, Optional, Tuple, List, Dict, Iterable
 from docker import DockerClient
@@ -646,7 +655,8 @@ def get_logger(name=""):
 
     if not logg.hasHandlers():
         logger_handler = logging.StreamHandler(stream=sys.stdout)
-        logger_handler.setFormatter(logging.Formatter('%(asctime)s: %(thread)d: %(levelname)s: %(message)s'))
+        logger_handler.addFilter(RequestIdFilter())
+        logger_handler.setFormatter(logging.Formatter('%(asctime)s: %(thread)d: [%(request_id)s] %(levelname)s: %(message)s'))
         logg.addHandler(logger_handler)
         # gelf_handler = GELFTCPHandler('0.0.0.0', constants.GELF_PORT)
         # logg.addHandler(gelf_handler)

simplyblock_web/app.py

@@ -5,6 +5,7 @@
 import ssl
 import sys
 import time
+import uuid
 
 from fastapi import FastAPI, Request
 from fastapi.middleware.wsgi import WSGIMiddleware
@@ -23,8 +24,9 @@
 
 access_logger = logging.getLogger('simplyblock_web.access')
 _access_handler = logging.StreamHandler(stream=sys.stdout)
+_access_handler.addFilter(core_utils.RequestIdFilter())
 _access_handler.setFormatter(logging.Formatter(
-    '%(asctime)s %(levelname)s %(client_ip)s'
+    '%(asctime)s %(levelname)s [%(request_id)s] %(client_ip)s'
     ' "%(message)s" %(status_code)s %(request_size)s %(response_size)s %(duration_ms).2fms "%(user_agent)s"'
 ))
 access_logger.addHandler(_access_handler)
@@ -39,13 +41,21 @@ async def dispatch(self, request: Request, call_next):
         client_ip = request.client.host if request.client else '-'
         user_agent = request.headers.get('user-agent', '-')
         request_size = request.headers.get('content-length', '-')
+        request_id = request.headers.get('x-request-id') or uuid.uuid4().hex[:8]
+        token = core_utils.request_id_var.set(request_id)
 
         path = request.url.path
         if request.url.query:
             path = f'{path}?{request.url.query}'
 
         start = time.monotonic()
-        response = await call_next(request)
+        try:
+            response = await call_next(request)
+        except Exception:
+            logger.exception('Unhandled exception during %s %s (%.1fms)',
+                             request.method, path, (time.monotonic() - start) * 1000)
+            core_utils.request_id_var.reset(token)
+            raise
         duration_ms = (time.monotonic() - start) * 1000
 
         response_size = response.headers.get('content-length', '-')
@@ -63,6 +73,7 @@ async def dispatch(self, request: Request, call_next):
                 'duration_ms': duration_ms,
             },
         )
+        core_utils.request_id_var.reset(token)
         return response