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
@@ -67,6 +68,7 @@ def f(arg):
 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
 from docker import DockerClient
@@ -37,6 +39,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",
@@ -691,7 +702,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

@@ -6,6 +6,7 @@
 import ssl
 import sys
 import time
+import uuid
 
 from fastapi import FastAPI, Request
 from fastapi.middleware.wsgi import WSGIMiddleware
@@ -26,8 +27,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)
@@ -41,13 +43,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)
 
         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', '-')
@@ -64,6 +74,7 @@ async def dispatch(self, request: Request, call_next):
                 'duration_ms': duration_ms,
             },
         )
+        core_utils.request_id_var.reset(token)
         return response