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

simplyblock_cli/clibase.py

@@ -6,6 +6,7 @@
 import re
 import sys
 import time
+import uuid
 import argcomplete
 
 from simplyblock_core import cluster_ops, utils, db_controller, constants
@@ -75,6 +76,7 @@ def _format_result(data, *, json: bool) -> str:
 class CLIWrapperBase:
 
     def __init__(self):
+        utils.request_id_var.set(uuid.uuid4().hex[:8])
         self.parser.add_argument("--cmd", help='cmd', nargs='+')
         argcomplete.autocomplete(self.parser)
 

simplyblock_core/utils/__init__.py

@@ -1,4 +1,5 @@
 # coding=utf-8
+import contextvars
 import glob
 import json
 import logging
@@ -12,6 +13,7 @@
 import sys
 import uuid
 import time
+
 from datetime import datetime, timezone
 from typing import Union, Any, Optional, Tuple, List, Dict, Iterable
 
@@ -39,6 +41,15 @@
 from . import pci as pci_utils
 from .helpers import parse_thread_siblings_list
 
+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
+
+
 CONFIG_KEYS = [
     "app_thread_core",
     "jm_cpu_core",
@@ -729,8 +740,13 @@ def get_logger(name=""):
         # client-port-block window (2026-07-20 FD-0 reboot: block 2s -> 20s).
         # The QueueHandler removes that contention without dropping lines or
         # changing the level; falls back to the direct handler on setup error.
+        # Filter is on the logger, not the handler: it must run synchronously
+        # on the emitting thread to read the caller's contextvars.ContextVar,
+        # before the record crosses into the QueueHandler/listener thread
+        # below (which has no access to the emitting thread's context).
+        logg.addFilter(RequestIdFilter())
         logger_handler = logging.StreamHandler(stream=sys.stderr)
-        logger_handler.setFormatter(logging.Formatter('%(asctime)s: %(thread)d: %(levelname)s: %(message)s'))
+        logger_handler.setFormatter(logging.Formatter('%(asctime)s: %(thread)d: [%(request_id)s] %(levelname)s: %(message)s'))
         try:
             logg.addHandler(make_async_handler(logger_handler))
         except Exception:

simplyblock_web/app.py

@@ -6,6 +6,7 @@
 import ssl
 import sys
 import time
+import uuid
 
 from fastapi import FastAPI, Request
 from fastapi.middleware.wsgi import WSGIMiddleware
@@ -34,8 +35,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'
 ))
 access_logger.addHandler(_access_handler)
@@ -49,13 +51,21 @@ class AccessLogMiddleware(BaseHTTPMiddleware):
     async def dispatch(self, request: Request, call_next):
         client_ip = request.client.host if request.client else '-'
         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)
 
         # Query strings can carry credentials (?secret=…, ?token=…) and have
         # no type info to mask by, so log the path only.
         path = request.url.path
 
         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', '-')
@@ -72,6 +82,7 @@ async def dispatch(self, request: Request, call_next):
                 'duration_ms': duration_ms,
             },
         )
+        core_utils.request_id_var.reset(token)
         return response