app/core/logging_config.py

"""Structured JSON logging configuration.

When ``setup_json_logging()`` is called, every log record emitted by the
process is formatted as a single-line JSON object:

    {
        "ts": "2026-05-29T14:32:01.123Z",
        "level": "INFO",
        "logger": "docdoe.backend",
        "request_id": "abc-123",
        "msg": "Generation completed",
        "extra_key": "extra_value"   // any extra fields attached to the record
    }

The ``request_id`` is pulled from the ``request_id_ctx_var`` context variable
(set by ``request_id_middleware``), so every log line is correlated to the
HTTP request that produced it.

Usage (in ``main.py`` lifespan)::

    from app.core.logging_config import setup_json_logging
    setup_json_logging()
"""
from __future__ import annotations

import json
import logging
import time
from typing import Any


# Fields that are already top-level in our schema — skip re-adding them as extras
_SKIP_ATTRS = frozenset({
    "args",
    "asctime",
    "created",
    "exc_info",
    "exc_text",
    "filename",
    "funcName",
    "levelname",
    "levelno",
    "lineno",
    "message",
    "module",
    "msecs",
    "msg",
    "name",
    "pathname",
    "process",
    "processName",
    "relativeCreated",
    "stack_info",
    "thread",
    "threadName",
    "request_id",  # handled separately
    "taskName",
})


class JsonFormatter(logging.Formatter):
    """Emit each log record as a single-line JSON object."""

    def format(self, record: logging.LogRecord) -> str:
        # Populate record.message as the standard Formatter does — pytest caplog
        # and other handlers rely on this side-effect.
        record.message = record.getMessage()

        # ISO-8601 timestamp with milliseconds
        ts = (
            time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(record.created))
            + f".{int(record.msecs):03d}Z"
        )

        # Pull request_id that was injected by RequestIDFilter (or context var)
        request_id = getattr(record, "request_id", None)
        if not request_id:
            try:
                from app.utils.request_id import request_id_ctx_var
                request_id = request_id_ctx_var.get("-")
            except Exception:
                request_id = "-"

        log_obj: dict[str, Any] = {
            "ts": ts,
            "level": record.levelname,
            "logger": record.name,
            "request_id": request_id,
            "msg": record.getMessage(),
        }

        # Attach any extra fields the caller passed via `extra={...}`
        for key, value in record.__dict__.items():
            if key not in _SKIP_ATTRS and not key.startswith("_"):
                try:
                    json.dumps(value)  # only include JSON-serialisable extras
                    log_obj[key] = value
                except (TypeError, ValueError):
                    log_obj[key] = repr(value)

        # Exception info
        if record.exc_info:
            log_obj["exc"] = self.formatException(record.exc_info)
        if record.stack_info:
            log_obj["stack"] = self.formatStack(record.stack_info)

        return json.dumps(log_obj, ensure_ascii=False)


def setup_json_logging() -> None:
    """Replace all existing log handlers with a JSON formatter.

    Safe to call multiple times (idempotent — checks for existing JsonFormatter).
    """
    formatter = JsonFormatter()
    root = logging.getLogger()

    if root.handlers:
        for handler in root.handlers:
            if not isinstance(handler.formatter, JsonFormatter):
                handler.setFormatter(formatter)
    else:
        # No handlers yet (e.g. before uvicorn starts) — add a StreamHandler
        handler = logging.StreamHandler()
        handler.setFormatter(formatter)
        root.addHandler(handler)