Rename and clean up logging and starlette (#48)

* Rename and clean up logging and starlette

* Verify log_level

Author: jschlyter

dnstapir/logging.py

@@ -1,52 +1,83 @@
-import logging.config
-from datetime import datetime
-from typing import Any
-
-from jsonformatter import JsonFormatter as _JsonFormatter
-
-TIMESTAMP_FORMAT = "%Y-%m-%dT%H:%M:%S.%f%z"
-
-LOGGING_RECORD_CUSTOM_FORMAT = {
-    "time": "asctime",
-    # "Created": "created",
-    # "RelativeCreated": "relativeCreated",
-    "name": "name",
-    # "Levelno": "levelno",
-    "levelname": "levelname",
-    "process": "process",
-    "thread": "thread",
-    # "threadName": "threadName",
-    # "Pathname": "pathname",
-    # "Filename": "filename",
-    # "Module": "module",
-    # "Lineno": "lineno",
-    # "FuncName": "funcName",
-    "message": "message",
-}
-
-LOGGING_CONFIG_JSON: dict[str, Any] = {
-    "version": 1,
-    "disable_existing_loggers": False,
-    "formatters": {
-        "json": {
-            "class": "dnstapir.logging.JsonFormatter",
-            "format": LOGGING_RECORD_CUSTOM_FORMAT,
-        },
-    },
-    "handlers": {
-        "json": {"class": "logging.StreamHandler", "formatter": "json"},
-    },
-    "root": {"handlers": ["json"], "level": "DEBUG"},
-}
-
-
-class JsonFormatter(_JsonFormatter):
-    def formatTime(self, record, datefmt=None) -> str:
-        dt = datetime.fromtimestamp(record.created).astimezone()
-        return dt.strftime(TIMESTAMP_FORMAT)
-
-
-def configure_json_logging() -> dict[str, Any]:
-    """Configure JSON logging and return configuration dictionary"""
-    logging.config.dictConfig(LOGGING_CONFIG_JSON)
-    return LOGGING_CONFIG_JSON
+"""
+structlog helpers based on code from https://wazaari.dev/blog/fastapi-structlog-integration
+"""
+
+import logging
+
+import structlog
+from structlog.types import EventDict, Processor
+
+VALID_LOG_LEVELS = set(["CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG"])
+
+
+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:
+    """Set up logging"""
+
+    if log_level.upper() not in VALID_LOG_LEVELS:
+        raise ValueError(f"Invalid log level: {log_level}")
+
+    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 dnstapir/starlette.pydnstapir/structlog_starlette.py renamed to dnstapir/starlette.py

@@ -1,3 +1,5 @@
+"""Starlette middleware and other utilities"""
+
 import time
 import uuid
 from collections.abc import Awaitable, Callable

dnstapir/structlog.py

@@ -7,7 +7,6 @@ readme = "README.md"
 
 [tool.poetry.dependencies]
 python = "^3.11"
-jsonformatter = "^0.3.2"
 opentelemetry-api = { version = "^1.28.1", optional = true }
 opentelemetry-exporter-otlp = { version = "^1.28.1", optional = true }
 opentelemetry-instrumentation-botocore = { version = ">=0.48b0", optional = true }

poetry.lock

@@ -1,9 +1,9 @@
-import logging
+import structlog
 
-from dnstapir.logging import configure_json_logging
+from dnstapir.logging import setup_logging
 
 
 def test_logging():
-    configure_json_logging()
-    logger = logging.getLogger(__name__)
-    logger.warning("Hello world")
+    setup_logging(json_logs=False, log_level="INFO")
+    logger = structlog.getLogger()
+    logger.warning("Hello %s", "world", foo="bar")