Add structlog (#47)

* Add structlog framework

* bump

dnstapir/structlog.py

@@ -0,0 +1,76 @@
+"""
+structlog helpers based on code from https://wazaari.dev/blog/fastapi-structlog-integration
+"""
+
+import logging
+
+import structlog
+from structlog.types import EventDict, Processor
+
+
+def drop_color_message_key(_, __, event_dict: EventDict) -> EventDict:
+    """
+    Uvicorn logs the message a second time in the extra `color_message`, but we don't
+    need it. This processor drops the key from the event dict if it exists.
+    """
+    event_dict.pop("color_message", None)
+    return event_dict
+
+
+def setup_logging(json_logs: bool = False, log_level: str = "INFO") -> None:
+    timestamper = structlog.processors.TimeStamper(fmt="iso")
+
+    shared_processors: list[Processor] = [
+        structlog.contextvars.merge_contextvars,
+        structlog.stdlib.add_logger_name,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.PositionalArgumentsFormatter(),
+        structlog.stdlib.ExtraAdder(),
+        drop_color_message_key,
+        timestamper,
+        structlog.processors.StackInfoRenderer(),
+    ]
+
+    if json_logs:
+        # Format the exception only for JSON logs, as we want to pretty-print them when
+        # using the ConsoleRenderer
+        shared_processors.append(structlog.processors.format_exc_info)
+
+    structlog.configure(
+        processors=shared_processors
+        + [
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        cache_logger_on_first_use=True,
+    )
+
+    log_renderer = structlog.processors.JSONRenderer() if json_logs else structlog.dev.ConsoleRenderer()
+
+    formatter = structlog.stdlib.ProcessorFormatter(
+        # These run ONLY on `logging` entries that do NOT originate within
+        # structlog.
+        foreign_pre_chain=shared_processors,
+        # These run on ALL entries after the pre_chain is done.
+        processors=[
+            # Remove _record & _from_structlog.
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            log_renderer,
+        ],
+    )
+
+    # Reconfigure the root logger to use our structlog formatter, effectively emitting the logs via structlog
+    handler = logging.StreamHandler()
+    handler.setFormatter(formatter)
+    root_logger = logging.getLogger()
+    root_logger.addHandler(handler)
+    root_logger.setLevel(log_level.upper())
+
+    for _log in ["uvicorn", "uvicorn.error"]:
+        # Make sure the logs are handled by the root logger
+        logging.getLogger(_log).handlers.clear()
+        logging.getLogger(_log).propagate = True
+
+    # Uvicorn logs are re-emitted with more context. We effectively silence them here
+    logging.getLogger("uvicorn.access").handlers.clear()
+    logging.getLogger("uvicorn.access").propagate = False

dnstapir/structlog_starlette.py

@@ -0,0 +1,40 @@
+import time
+import uuid
+from collections.abc import Awaitable, Callable
+
+import structlog
+from starlette.middleware.base import BaseHTTPMiddleware
+from starlette.requests import Request
+from starlette.responses import Response
+
+
+class LoggingMiddleware(BaseHTTPMiddleware):
+    async def dispatch(self, request: Request, call_next: Callable[[Request], Awaitable[Response]]) -> Response:
+        logger = structlog.get_logger()
+        request_id = str(uuid.uuid4())
+
+        with structlog.contextvars.bound_contextvars(request_id=request_id):
+            logger.bind(
+                method=request.method,
+                path=request.url.path,
+            ).info(
+                f"Processing {request.method} request to {request.url.path}",
+            )
+
+            request.state.start_time = time.perf_counter()
+            request.state.request_id = request_id
+            response = await call_next(request)
+            elapsed = time.perf_counter() - request.state.start_time
+
+            logger.bind(
+                path=request.url.path,
+                method=request.method,
+                status_code=response.status_code,
+                elapsed=elapsed,
+            ).info(
+                f"Processed {request.method} request to {request.url.path} in {elapsed:.3f} seconds",
+            )
+
+            response.headers["X-Request-ID"] = request_id
+
+            return response