Fix problems with correlation IDs in logging.

src/programming/Ligare/programming/patterns/dependency_injection.py

@@ -76,7 +76,7 @@ def formatMessage(self, record: logging.LogRecord) -> dict[str, Any]:  # pyright
         KeyError is raised if an unknown attribute is provided in the fmt_dict.
         """
         return {
-            fmt_key: record.__dict__[fmt_val]
+            fmt_key: record.__dict__.get(fmt_val, None)
             for fmt_key, fmt_val in self.fmt_dict.items()
         }
 
@@ -118,22 +118,24 @@ def __init__(
         name: str | None = None,
         log_level: int | str = logging.INFO,
         log_to_stdout: bool = False,
+        formatter: JSONFormatter | None = None,
     ) -> None:
         super().__init__(name, log_level, log_to_stdout)
 
-        formatter = JSONFormatter({
-            "level": "levelname",
-            "message": "message",
-            "file": "pathname",
-            "func": "funcName",
-            "line": "lineno",
-            "loggerName": "name",
-            "processName": "processName",
-            "processID": "process",
-            "threadName": "threadName",
-            "threadID": "thread",
-            "timestamp": "asctime",
-        })
+        if not formatter:
+            formatter = JSONFormatter({
+                "level": "levelname",
+                "message": "message",
+                "file": "pathname",
+                "func": "funcName",
+                "line": "lineno",
+                "loggerName": "name",
+                "processName": "processName",
+                "processID": "process",
+                "threadName": "threadName",
+                "threadID": "thread",
+                "timestamp": "asctime",
+            })
 
         handler = logging.StreamHandler()
         handler.formatter = formatter

src/web/Ligare/web/middleware/consts.py

@@ -2,7 +2,7 @@
 String constants used by :ref:`Ligare.web`.
 """
 
-CORRELATION_ID_HEADER = "X-Correlation-Id"
+REQUEST_ID_HEADER = "X-Correlation-Id"
 REQUEST_COOKIE_HEADER = "Cookie"
 RESPONSE_COOKIE_HEADER = "Set-Cookie"
 CORS_ACCESS_CONTROL_ALLOW_ORIGIN_HEADER = "Access-Control-Allow-Origin"

src/web/Ligare/web/middleware/dependency_injection.py

@@ -15,16 +15,68 @@
 from injector import Binder, Injector, Module
 from Ligare.programming.dependency_injection import ConfigModule
 from Ligare.programming.patterns.dependency_injection import (
+    JSONFormatter,
     JSONLoggerModule,
     LoggerModule,
 )
 from Ligare.web.application import Config as AppConfig
+from Ligare.web.middleware.openapi import (
+    CorrelationIdMiddleware,
+    RequestIdMiddleware,
+    get_trace_id,
+)
 from starlette.types import ASGIApp, Receive, Scope, Send
 from typing_extensions import override
 
 from . import RegisterMiddlewareCallback, TFlaskApp
 
 
+class WebJSONFormatter(JSONFormatter):
+    @override
+    def __init__(
+        self,
+        fmt_dict: dict[str, str] | None = None,
+        time_format: str = "%Y-%m-%dT%H:%M:%S",
+        msec_format: str = "%s.%03dZ",
+    ):
+        super().__init__(fmt_dict, time_format, msec_format)
+
+    @override
+    def formatMessage(self, record: logging.LogRecord) -> dict[str, Any]:
+        format = super().formatMessage(record)
+        correlation_ids = get_trace_id()
+        format["correlationId"] = correlation_ids.CorrelationId
+        format["requestId"] = correlation_ids.RequestId
+        return format
+
+
+class WebJSONLoggerModule(JSONLoggerModule):
+    @override
+    def __init__(
+        self,
+        name: str | None = None,
+        log_level: int | str = logging.INFO,
+        log_to_stdout: bool = False,
+        formatter: JSONFormatter | None = None,
+    ) -> None:
+        formatter = WebJSONFormatter({
+            "level": "levelname",
+            "message": "message",
+            "file": "pathname",
+            "func": "funcName",
+            "line": "lineno",
+            "loggerName": "name",
+            "processName": "processName",
+            "processID": "process",
+            "threadName": "threadName",
+            "threadID": "thread",
+            "timestamp": "asctime",
+            "correlationId": "correlationId",
+            "requestId": "requestId",
+        })
+        super().__init__(name, log_level, log_to_stdout, formatter)
+
+
 class MiddlewareRoutine(Protocol):
     def __call__(
         self, scope: Scope, receive: Receive, send: Send, *args: Any
@@ -53,7 +105,7 @@ def configure(self, binder: Binder) -> None:
         app_config = binder.injector.get(AppConfig)
         log_level = app_config.logging.log_level.upper()
         if app_config.logging.format == "JSON":
-            binder.install(JSONLoggerModule(self._flask_app.name, log_level))
+            binder.install(WebJSONLoggerModule(self._flask_app.name, log_level))
         else:
             binder.install(LoggerModule(self._flask_app.name, log_level))
 
@@ -110,6 +162,8 @@ def configure_dependencies(
 
     if isinstance(app, FlaskApp):
         app.add_middleware(OpenAPIEndpointDependencyInjectionMiddleware(flask_injector))
+        app.add_middleware(CorrelationIdMiddleware)
+        app.add_middleware(RequestIdMiddleware)
 
         # For every module registered, check if any are "middleware" type modules.
         # if they are, they need to be registered with the application.

src/web/Ligare/web/middleware/flask/__init__.py

@@ -17,7 +17,6 @@
 from ...config import Config
 from ..consts import (
     CONTENT_SECURITY_POLICY_HEADER,
-    CORRELATION_ID_HEADER,
     CORS_ACCESS_CONTROL_ALLOW_CREDENTIALS_HEADER,
     CORS_ACCESS_CONTROL_ALLOW_METHODS_HEADER,
     CORS_ACCESS_CONTROL_ALLOW_ORIGIN_HEADER,
@@ -26,6 +25,7 @@
     ORIGIN_HEADER,
     OUTGOING_RESPONSE_MESSAGE,
     REQUEST_COOKIE_HEADER,
+    REQUEST_ID_HEADER,
     RESPONSE_COOKIE_HEADER,
 )
 
@@ -81,21 +81,21 @@ def _get_correlation_id(log: Logger) -> str:
 
 def _get_correlation_id_from_headers(log: Logger) -> str:
     try:
-        correlation_id = request.headers.get(CORRELATION_ID_HEADER)
+        correlation_id = request.headers.get(REQUEST_ID_HEADER)
 
         if correlation_id:
             # validate format
             _ = uuid.UUID(correlation_id)
         else:
             correlation_id = str(uuid4())
             log.info(
-                f'Generated new UUID "{correlation_id}" for {CORRELATION_ID_HEADER} request header.'
+                f'Generated new UUID "{correlation_id}" for {REQUEST_ID_HEADER} request header.'
             )
 
         return correlation_id
 
     except ValueError as e:
-        log.warning(f"Badly formatted {CORRELATION_ID_HEADER} received in request.")
+        log.warning(f"Badly formatted {REQUEST_ID_HEADER} received in request.")
         raise e
 
 
@@ -107,11 +107,11 @@ def _get_correlation_id_from_json_logging(log: Logger) -> str | None:
         _ = uuid.UUID(correlation_id)
         return correlation_id
     except ValueError as e:
-        log.warning(f"Badly formatted {CORRELATION_ID_HEADER} received in request.")
+        log.warning(f"Badly formatted {REQUEST_ID_HEADER} received in request.")
         raise e
     except Exception as e:
         log.debug(
-            f"Error received when getting {CORRELATION_ID_HEADER} header from `json_logging`. Possibly `json_logging` is not configured, and this is not an error.",
+            f"Error received when getting {REQUEST_ID_HEADER} header from `json_logging`. Possibly `json_logging` is not configured, and this is not an error.",
             exc_info=e,
         )
 
@@ -195,7 +195,7 @@ def _wrap_all_api_responses(response: Response, config: Config, log: Logger):
         config.web.security.cors.allow_methods
     )
 
-    response.headers[CORRELATION_ID_HEADER] = correlation_id
+    response.headers[REQUEST_ID_HEADER] = correlation_id
 
     if config.web.security.csp:
         response.headers[CONTENT_SECURITY_POLICY_HEADER] = config.web.security.csp