feat(logging): JSON formatter so structured log fields survive

src/main.py

@@ -27,11 +27,17 @@
 from .middleware.metrics import setup_metrics
 from .services.rate_limit_service import RateLimitService
 from .telemetry import init_telemetry, shutdown_telemetry
+from .utils.logging_config import configure_logging
 from .workers.pii_worker import start_pii_worker
 from .workers.timeout_worker import start_timeout_worker
 
-# Configure logging
-logging.basicConfig(level=settings.log_level, format="%(asctime)s - %(name)s - %(levelname)s - %(message)s")
+# Configure logging. JSON in production so the structured fields the
+# middleware attaches via extra={} (path, status, latency, identity) are
+# queryable downstream; human-readable text in local dev.
+configure_logging(
+    level=settings.log_level,
+    json_format=(settings.environment == "production"),
+)
 
 # Silence noisy third-party loggers (they flood DEBUG with base64 payloads, auth signatures, etc.)
 for _noisy_logger in ("botocore", "boto3", "urllib3", "httpcore", "httpx", "s3transfer", "python_multipart"):

src/utils/logging_config.py

@@ -0,0 +1,79 @@
+"""Application logging configuration.
+
+The request/response middleware attaches structured fields to log records
+via ``logging``'s ``extra={}`` mechanism (path, status code, latency,
+authenticated identity). The stdlib's default formatter renders only the
+fields named in its format string, so every one of those extras is
+silently dropped.
+
+This module provides a JSON formatter that emits the extras, plus a
+``configure_logging`` helper. JSON is used in production (so CloudWatch
+Logs Insights, Loki, etc. can query the fields); plain text is kept for
+local development where logs are read by eye.
+"""
+
+from __future__ import annotations
+
+import datetime
+import json
+import logging
+
+# LogRecord attributes that the stdlib sets itself. Anything on a record
+# that is *not* in this set was supplied by the caller via extra={} and is
+# what we want to surface.
+_STANDARD_ATTRS = frozenset({
+    "name", "msg", "args", "levelname", "levelno", "pathname", "filename",
+    "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName",
+    "created", "msecs", "relativeCreated", "thread", "threadName",
+    "processName", "process", "taskName", "message", "asctime",
+})
+
+
+class JsonFormatter(logging.Formatter):
+    """Format log records as single-line JSON, including ``extra`` fields."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        payload: dict[str, object] = {
+            "timestamp": datetime.datetime.fromtimestamp(
+                record.created, tz=datetime.UTC
+            ).isoformat(),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+        }
+
+        # Caller-supplied extras (the whole point of this formatter).
+        for key, value in record.__dict__.items():
+            if key not in _STANDARD_ATTRS and not key.startswith("_"):
+                payload[key] = value
+
+        if record.exc_info:
+            payload["exc_info"] = self.formatException(record.exc_info)
+        if record.stack_info:
+            payload["stack_info"] = self.formatStack(record.stack_info)
+
+        # default=str so non-serialisable values (UUIDs, datetimes) degrade
+        # gracefully instead of crashing the log call.
+        return json.dumps(payload, default=str)
+
+
+def configure_logging(level: str, *, json_format: bool) -> None:
+    """Install a single root handler with the chosen formatter.
+
+    Args:
+        level: Root log level (``DEBUG``, ``INFO``, ...).
+        json_format: ``True`` for JSON output (production), ``False`` for
+            the human-readable text format (local development).
+    """
+    handler = logging.StreamHandler()
+    if json_format:
+        handler.setFormatter(JsonFormatter())
+    else:
+        handler.setFormatter(
+            logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
+        )
+
+    root = logging.getLogger()
+    root.handlers.clear()
+    root.addHandler(handler)
+    root.setLevel(level)

tests/unit/utils/test_logging_config.py

@@ -0,0 +1,93 @@
+"""Tests for JSON logging configuration."""
+
+import json
+import logging
+import uuid
+
+import pytest
+from src.utils.logging_config import JsonFormatter, configure_logging
+
+pytestmark = pytest.mark.unit
+
+
+def _record(**extra) -> logging.LogRecord:
+    """Build a LogRecord with optional extra fields, the way logging does."""
+    record = logging.LogRecord(
+        name="src.test",
+        level=logging.INFO,
+        pathname=__file__,
+        lineno=1,
+        msg="hello %s",
+        args=("world",),
+        exc_info=None,
+    )
+    for key, value in extra.items():
+        setattr(record, key, value)
+    return record
+
+
+def test_formats_valid_json_with_core_fields():
+    out = json.loads(JsonFormatter().format(_record()))
+    assert out["level"] == "INFO"
+    assert out["logger"] == "src.test"
+    assert out["message"] == "hello world"  # %-args rendered
+    assert "timestamp" in out
+
+
+def test_includes_extra_fields():
+    out = json.loads(JsonFormatter().format(_record(
+        path="/api/v1/documents",
+        status_code=200,
+        user_sub="zach",
+    )))
+    assert out["path"] == "/api/v1/documents"
+    assert out["status_code"] == 200
+    assert out["user_sub"] == "zach"
+
+
+def test_does_not_emit_standard_record_internals():
+    out = json.loads(JsonFormatter().format(_record()))
+    # Internal LogRecord attributes must not leak into the payload.
+    for noise in ("args", "msg", "levelno", "pathname", "thread"):
+        assert noise not in out
+
+
+def test_non_serialisable_extra_degrades_gracefully():
+    job_id = uuid.uuid4()
+    out = json.loads(JsonFormatter().format(_record(job_id=job_id)))
+    # default=str keeps the log call from crashing on a UUID.
+    assert out["job_id"] == str(job_id)
+
+
+def test_includes_exception_info():
+    try:
+        raise ValueError("boom")
+    except ValueError:
+        import sys
+        record = _record()
+        record.exc_info = sys.exc_info()
+        out = json.loads(JsonFormatter().format(record))
+    assert "exc_info" in out
+    assert "ValueError: boom" in out["exc_info"]
+
+
+def test_configure_logging_json_installs_json_formatter():
+    try:
+        configure_logging(level="INFO", json_format=True)
+        root = logging.getLogger()
+        assert len(root.handlers) == 1
+        assert isinstance(root.handlers[0].formatter, JsonFormatter)
+        assert root.level == logging.INFO
+    finally:
+        logging.getLogger().handlers.clear()
+
+
+def test_configure_logging_text_installs_plain_formatter():
+    try:
+        configure_logging(level="DEBUG", json_format=False)
+        root = logging.getLogger()
+        assert len(root.handlers) == 1
+        assert not isinstance(root.handlers[0].formatter, JsonFormatter)
+        assert root.level == logging.DEBUG
+    finally:
+        logging.getLogger().handlers.clear()