Hub: Log Request ID

Generate a unique request ID for each connection and prepend the ID for
every log entry. This makes it possible to trace individual requests in
the logs.

not_my_board/_hub.py

@@ -100,6 +100,7 @@ async def _on_startup():
 
 @asgineer.to_asgi
 async def _handle_request(request):
+    util.generate_log_request_id()
     hub = request.scope["state"]["hub"]
     response = (404, {}, "Page not found")
 

not_my_board/_util/__init__.py

@@ -12,7 +12,7 @@
     run_concurrently,
     run_in_thread,
 )
-from ._logging import configure_logging
+from ._logging import configure_logging, generate_log_request_id
 from ._matching import find_matching
 from ._parser import parse_time
 

not_my_board/_util/_logging.py

@@ -1,5 +1,7 @@
+import contextvars
 import logging
 import sys
+import uuid
 
 import colorlog
 
@@ -10,6 +12,7 @@
     logging.INFO: "<6>",
     logging.DEBUG: "<7>",
 }
+_request_id = contextvars.ContextVar("request_id")
 
 
 def configure_logging(level):
@@ -25,7 +28,7 @@ def configure_logging(level):
 
         if sys.stderr.isatty():
             formatter = colorlog.ColoredFormatter(
-                "%(asctime)s %(light_black)s%(name)s %(log_color)s%(message)s",
+                "%(asctime)s %(light_black)s%(request_id)s%(name)s %(log_color)s%(message)s",
                 log_colors={
                     "DEBUG": "light_black",
                     "INFO": "reset",
@@ -35,13 +38,26 @@ def configure_logging(level):
                 },
             )
         else:
-            formatter = _PrintKFormatter("%(level_prefix)s%(name)s %(message)s")
+            formatter = _PrintKFormatter(
+                "%(level_prefix)s%(request_id)s%(name)s %(message)s"
+            )
 
         handler.setFormatter(formatter)
+        handler.addFilter(_inject_request_id)
         root.addHandler(handler)
 
 
 class _PrintKFormatter(logging.Formatter):
     def format(self, record):
         record.level_prefix = _PRINTK_PREFIXES.get(record.levelno, "")
         return super().format(record)
+
+
+def generate_log_request_id():
+    _request_id.set(str(uuid.uuid4()))
+
+
+def _inject_request_id(record):
+    request_id = _request_id.get(None)
+    record.request_id = f"{request_id} " if request_id else ""
+    return True