ai-rpg/backend/app/logging_setup.py

"""Structured logging setup.

`LOG_LEVEL` (env) controls the verbosity of:
  - The root Python logger
  - structlog-bound loggers (app.*)
  - Uvicorn's own loggers (`uvicorn`, `uvicorn.access`, `uvicorn.error`,
    `uvicorn.asgi`) — these otherwise stay at INFO regardless of LOG_LEVEL
    because uvicorn configures them itself at startup, before our lifespan
    calls setup_logging(). We forcibly re-level them here.
  - The `sqlalchemy.engine` logger (kept at WARNING unless LOG_LEVEL=DEBUG).

Note: `logging.basicConfig()` is a no-op once the root logger has been
configured (which uvicorn does at import time), so it alone is NOT enough
to honor LOG_LEVEL — we must also call `setLevel()` on each named logger.
"""
from __future__ import annotations

import logging
import sys

import structlog

from app.config import settings


# Loggers whose level must be forced to LOG_LEVEL (uvicorn pre-configures them
# at INFO before our lifespan runs, so basicConfig cannot change them).
_FORCED_LOGGERS = (
    "uvicorn",
    "uvicorn.access",
    "uvicorn.error",
    "uvicorn.asgi",
    "fastapi",
)


def setup_logging() -> None:
    level = getattr(logging, settings.log_level.upper(), logging.INFO)

    # Force the root logger level (affects any logger that doesn't override).
    logging.getLogger().setLevel(level)

    # Also call basicConfig for the formatter (idempotent if already set up).
    logging.basicConfig(
        format="%(message)s",
        stream=sys.stdout,
        level=level,
        force=True,  # python 3.8+: re-init even if already configured
    )

    # Force level on loggers that uvicorn pre-configured.
    for name in _FORCED_LOGGERS:
        lg = logging.getLogger(name)
        lg.setLevel(level)
        # Ensure uvicorn access logs propagate to the root handler.
        lg.propagate = True
        for h in lg.handlers:
            h.setLevel(level)

    # SQLAlchemy is chatty at INFO; keep it at WARNING unless explicitly DEBUG.
    sa_level = logging.DEBUG if level <= logging.DEBUG else logging.WARNING
    logging.getLogger("sqlalchemy.engine").setLevel(sa_level)
    logging.getLogger("sqlalchemy.pool").setLevel(sa_level)
    logging.getLogger("asyncpg").setLevel(sa_level)

    structlog.configure(
        processors=[
            structlog.contextvars.merge_contextvars,
            structlog.processors.add_log_level,
            structlog.processors.TimeStamper(fmt="iso"),
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.processors.JSONRenderer(),
        ],
        wrapper_class=structlog.make_filtering_bound_logger(level),
        context_class=dict,
        logger_factory=structlog.PrintLoggerFactory(file=sys.stdout),
        cache_logger_on_first_use=True,
    )


def get_logger(name: str | None = None):
    return structlog.get_logger(name)