Source code for trader.logging_setup

"""Application logging (requirements §11).

Deliberately narrow: one rotating file handler, attached to the `trader`
logger and to every third-party logger this app is known to trigger, and one
helper that renders a config safely.

**Why third-party loggers get the same handler explicitly, rather than
relying on propagation.** `yfinance` logs through `logging.getLogger
('yfinance')` — a sibling of `"trader"`, not a child of it, so it never
inherited the handler attached here. With no handler anywhere in ITS
ancestor chain either (the root logger has none by default), those records
fell through to Python's built-in `logging.lastResort` handler: a bare
`StreamHandler(sys.stderr)` with no formatter, printing just the raw
message. Confirmed live, 2026-08-21: `daemon-error.log` filled with lines
like `HTTP Error 404: {"quoteSummary": ...}` — a real yfinance-logged ERROR
(an ETF with no fundamentals, an already-handled, expected case — see
`marketdata/analysts.py`) with none of the `%(asctime)s %(levelname)s
%(name)s` context every line in `trader.log` carries, making a deploy's
"check the error log" step impossible to read at a glance. `_THIRD_PARTY_
LOGGER_NAMES` is deliberately a short, explicit list — not the root logger —
so a future noisy DEBUG-level library does not silently start writing to
this file just because it happens to log through the standard module.

The helper is not a convenience. `EffectiveTradingConfig` marks its credential
fields `repr=False`, so `repr(config)` is safe — but `dataclasses.asdict()`
walks the fields directly and returns the secrets in clear text. Logging is the
first thing in this codebase that writes to a durable file, so the first
`logger.debug("config=%s", asdict(config))` would put a live Alpaca key on disk.
Log `safe_config_summary(config)` instead, never the config.
"""

import logging
from logging.handlers import RotatingFileHandler
from pathlib import Path

from pydantic import ValidationError
from sqlalchemy.engine import make_url

from trader.config.loader import EffectiveTradingConfig
from trader.errors import ConfigError

__all__ = ["LOGGER_NAME", "configure_logging", "safe_config_summary"]

LOGGER_NAME = "trader"

#: Third-party loggers known to emit records this app cares about seeing,
#: with no handler of their own. Each gets `configure_logging`'s handler
#: attached directly, same as `"trader"` — see the module docstring for why
#: this is an explicit list rather than the root logger.
_THIRD_PARTY_LOGGER_NAMES = ("yfinance",)

_DEFAULT_LOG_PATH = Path("logs/trader.log")
_MAX_BYTES = 5 * 1024 * 1024
_BACKUP_COUNT = 3


class _LazyDirRotatingFileHandler(RotatingFileHandler):
    """A `RotatingFileHandler` that creates its parent directory lazily.

    Constructed with `delay=True`, the base class already defers opening the
    file itself until the first record is emitted — so a process that
    configures logging but never logs anything (e.g. printing `--help`)
    never touches the filesystem. But `FileHandler.__init__` still resolves
    `baseFilename` eagerly and nothing else creates the parent directory, so
    without this override the *first* emit from a real run would fail with
    `FileNotFoundError`. Overriding `_open()` — the base class's own hook for
    "actually touch the filesystem now" — creates the directory at exactly
    the moment the delayed open happens, so "never logs" still means "creates
    nothing" and "does log" still works.
    """

    def _open(self) -> object:
        Path(self.baseFilename).parent.mkdir(parents=True, exist_ok=True)
        return super()._open()




def configure_logging(level: int | None = None, log_path: Path | None = None) -> None:
    """Attach a rotating file handler to the `trader` logger.

    Idempotent: calling twice does not double every log line.

    `level=None` means "read `LOG_LEVEL` from the environment". An explicit
    level still wins, which is what keeps the tests in this module independent
    of whatever the developer has in their own `.env`.

    Deliberately does not create `path.parent` here. The handler is built
    with `delay=True`, so nothing is opened or created on disk until the
    first record is actually emitted — a command that configures logging and
    then does nothing else (every CLI command's `--help`, via the app
    callback) creates no `logs/` directory as a side effect of printing
    usage text.

    Raises `ConfigError`, not pydantic's `ValidationError`, when `LOG_LEVEL`
    is unrecognised. This runs from the Typer app callback, before any
    command's own `try`/`except TraderError` block, so an uncaught
    `ValidationError` would print a raw traceback instead of the one-line
    `Error: ...` every other bad config value in this app produces — the
    valid values were still named, just buried in ten lines of rich
    formatting a typo does not deserve. Wrapping it here means the CLI only
    ever has to handle `TraderError`, not pydantic's error type as well.

    `Settings()` validates every field at once, not just `log_level` — so a
    bad `TRADING_MODE` raises the same `ValidationError` this function is
    watching for. Relabelling unconditionally previously turned that into
    "Invalid LOG_LEVEL: ... trading_mode ...", which sends whoever is
    debugging a safety-relevant typo to the wrong line of `.env`. Only
    relabel when every error pydantic reports is on `log_level`; anything
    else re-raises the original `ValidationError` untouched, exactly as it
    propagated before this wrapping existed.
    """
    from trader.config.settings import Settings

    if level is not None:
        resolved = level
    else:
        try:
            resolved = logging.getLevelNamesMapping()[Settings().log_level.value]
        except ValidationError as exc:
            if all(error["loc"] == ("log_level",) for error in exc.errors()):
                raise ConfigError(f"Invalid LOG_LEVEL: {exc}") from exc
            raise
    path = log_path or _DEFAULT_LOG_PATH

    logger = logging.getLogger(LOGGER_NAME)
    logger.setLevel(resolved)

    for existing in list(logger.handlers):
        logger.removeHandler(existing)
        existing.close()

    handler = _LazyDirRotatingFileHandler(
        path,
        maxBytes=_MAX_BYTES,
        backupCount=_BACKUP_COUNT,
        encoding="utf-8",
        delay=True,
    )
    handler.setFormatter(
        logging.Formatter("%(asctime)s %(levelname)-8s %(name)s %(message)s")
    )
    logger.addHandler(handler)

    # Same handler instance, not a second one per logger: one open file, one
    # rotation state, formatted identically to every `trader.*` line. Levels
    # are deliberately left alone here — `resolved` (the operator's own
    # `LOG_LEVEL`) is never applied to these, so setting it to DEBUG for the
    # app's own logging never also turns on a third-party library's DEBUG
    # chatter; each keeps whatever level it already had (yfinance's own
    # default, absent an explicit `setLevel`, is WARNING).
    for name in _THIRD_PARTY_LOGGER_NAMES:
        third_party_logger = logging.getLogger(name)
        for existing in list(third_party_logger.handlers):
            third_party_logger.removeHandler(existing)
            existing.close()
        third_party_logger.addHandler(handler)





def safe_config_summary(config: EffectiveTradingConfig) -> dict[str, str]:
    """Render a config for logging with the credentials removed.

    Returns only the operational fields. `api_key` and `api_secret` are absent
    by construction rather than masked, so a future field added to the config
    cannot leak through this function by default.
    """
    return {
        "trading_mode": config.trading_mode.value,
        "live_trading_enabled": str(config.live_trading_enabled),
        # `render_as_string(hide_password=True)`, never a bare `str(...)` —
        # `config.database_url` carries a real Postgres password (issue #26),
        # and this function's whole contract is "credentials removed".
        "database_url": make_url(config.database_url).render_as_string(
            hide_password=True
        ),
        # Whether `assert_live_orders_allowed()` would pass — which it does in
        # paper mode, since the gate exists to stop *real-money* orders. Named
        # `gate_passes` rather than `live_orders_allowed` because the latter
        # reads as "this account trades live", which is a different question.
        "gate_passes": str(not config.is_live or config.live_trading_enabled),
    }