diff --git a/CHANGELOG.md b/CHANGELOG.md index 3e1c249..ad9cb0d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- **Daemon logs are real logs** — the daemon path writes `logs/daemon.log` + through a midnight-rotating handler (14-day retention) with ISO-8601 local + timestamps carrying the numeric tz offset; level/dir/retention configurable + via the manifest's new optional `logging:` section + (`application/log_setup.py`); tick errors now log their traceback + (previously invisible — no handler existed). Interactive CLI output + unchanged. (#226) + ### Changed ### Fixed diff --git a/doc/dev/03-decisions.md b/doc/dev/03-decisions.md index 2830c08..791085e 100644 --- a/doc/dev/03-decisions.md +++ b/doc/dev/03-decisions.md @@ -6,6 +6,22 @@ rejected approaches as tombstones. --- +### 2026-07-14 Daemon logging spine: root handlers, offset timestamps (PR #226) [accepted] +- **Choice**: the daemon's logging config lives in `application/log_setup.py` + and wires the **root** logger with two owned, tagged handlers (midnight + `TimedRotatingFileHandler` + stderr stream); third-party namespaces + (`apscheduler`/`uvicorn`/`httpx`/`websockets`) are capped at WARNING; + timestamps are **local ISO-8601 with the numeric UTC offset**. +- **Why**: one spine, N emitters — the runner/router/feed module loggers + (some already emitting into the void) flow into the rotated file without + knowing it exists; the owned-handler tag makes re-configuration idempotent + (no double-writes under tests or embedding); the explicit offset kills the + UTC-vs-CEST ambiguity that burned the 2026-07-14 audit. +- **Rejected alternatives**: UTC-only timestamps (the operator reads local + time; the offset carries both); per-module handlers (drift + duplication); + wiring in `interfaces/cli` (the seam is application-level composition, + reusable by a future systemd entrypoint). + ### 2026-07-12 The venue oracle is an accounting identity; fees carry their asset (PR #223) [accepted] - **Choice**: on a real venue the canary asserts the **identity** — our fills == venue-reported fills, per-asset balance deltas == the fills math diff --git a/doc/dev/06-status.md b/doc/dev/06-status.md index 984f2e3..b34334c 100644 --- a/doc/dev/06-status.md +++ b/doc/dev/06-status.md @@ -183,6 +183,11 @@ engine code: **real-key live enablement** (validate Kraken private endpoints + venue-level idempotency against a real-key sandbox, then flip `live_enabled`) — the one maintainer step in [`07-roadmap.md`](07-roadmap.md). +- **`daemon-logging` in flight (1/3)**: the logging spine landed (rotated, + tz-offset-timestamped `logs/daemon.log`, manifest `logging:` section, tick + tracebacks). Next: the per-unit event trail (leaf 02), tick-timing metrics + (leaf 03). Plan: `plans/daemon-logging/`. + ## Known gaps / deferred - ~~**Final project name**~~ — **decided**: kept as `trading_bot` (with `dccd` / diff --git a/doc/dev/plans/daemon-logging/00-plan.md b/doc/dev/plans/daemon-logging/00-plan.md index c68363b..e80b436 100644 --- a/doc/dev/plans/daemon-logging/00-plan.md +++ b/doc/dev/plans/daemon-logging/00-plan.md @@ -1,7 +1,7 @@ --- plan: daemon-logging kind: global -status: planning +status: executing roadmap: "3b. [ ] **Daemon observability — structured logs** (surfaced by the 2026-07-14 health audit; prereq for #4's systemd alerting + soak evidence): timestamped rotated `logs/daemon.log`, per-unit evaluation/order/skip trail, tick-duration metrics on `/api/health` (additive). Plan: `plans/daemon-logging/`." release_on_done: true --- @@ -53,7 +53,7 @@ What the audit measured (the evidence this epic answers): ## Leaf checklist -- [ ] 01 log-setup — `feat/daemon-log-setup` — medium +- [x] 01 log-setup — `feat/daemon-log-setup` — medium - [ ] 02 unit-event-trail — `feat/daemon-unit-event-logs` — medium - [ ] 03 tick-timing-metrics — `feat/tick-timing-metrics` — medium diff --git a/doc/dev/plans/daemon-logging/01-log-setup.md b/doc/dev/plans/daemon-logging/01-log-setup.md deleted file mode 100644 index 12dcba9..0000000 --- a/doc/dev/plans/daemon-logging/01-log-setup.md +++ /dev/null @@ -1,129 +0,0 @@ ---- -plan: daemon-logging/01-log-setup -kind: leaf -status: planned -complexity: medium -depends: [] -parallel: false -branch: feat/daemon-log-setup -pr: "" ---- - -# 01 — Logging spine: config, rotation, timestamps - -## Goal - -A real logging setup for the daemon path: ISO-8601-timestamped (with numeric -tz offset), midnight-rotated, level-configurable via the manifest; the -existing daemon lifecycle lines routed through it; tick errors captured with -tracebacks. Interactive CLI commands (`status`, `kpi`, `canary`, …) keep their -rich-console output unchanged — this leaf touches only the daemon -(`start --serve` / `_run_daemon`) path. - -## Files to change - -- `trading_bot/application/log_setup.py` — **new**: `configure_daemon_logging()` -- `trading_bot/application/config.py` — new `LoggingConfig` model + optional - `logging:` section on `AppConfig` -- `trading_bot/interfaces/cli/main.py` — daemon path only: call the setup, - route lifecycle prints through a logger -- `trading_bot/tests/application/test_log_setup.py` — **new** -- `trading_bot/tests/application/test_config.py` — extend - -## Steps - -1. `LoggingConfig(BaseModel)` in `config.py`, mirroring the existing section - models (`StorageConfig` / `UIConfig` style): - - `level: str = "INFO"` — validated case-insensitively against - `logging.getLevelNamesMapping()`; stored upper-case. - - `dir: Path = Path("logs")` — resolved like the other relative paths in - the manifest (relative to the CWD the daemon runs from, as today). - - `retention_days: int = 14` — `ge=1`. - - Field on `AppConfig`: `logging: LoggingConfig = Field(default_factory=LoggingConfig)` - — **additive**, a manifest without a `logging:` section keeps defaults. -2. `log_setup.py` — `configure_daemon_logging(cfg: LoggingConfig) -> None`: - - Create `cfg.dir` if missing; attach to the **root logger**: - `TimedRotatingFileHandler(cfg.dir / "daemon.log", when="midnight", - backupCount=cfg.retention_days, encoding="utf-8")` + a - `StreamHandler(sys.stderr)` with the same formatter (systemd/journal - still sees output; harmless under nohup). - - Formatter: `%(asctime)s %(levelname)-8s %(name)s — %(message)s` with - `formatTime` overridden to - `datetime.fromtimestamp(record.created).astimezone().isoformat(timespec="milliseconds")` - — local time **with numeric offset** (`2026-07-14T13:35:40.123+02:00`). - The offset is non-negotiable (audit finding: UTC-vs-CEST ambiguity). - - Levels: root at `cfg.level`; cap the noisy third-party namespaces — - `logging.getLogger(ns).setLevel(logging.WARNING)` for `apscheduler`, - `uvicorn`, `uvicorn.access`, `httpx`, `websockets` — so INFO stays the - engine's story (APScheduler misfire WARNINGs still flow). - - **Idempotent**: tag the handlers it owns (attribute marker) and remove - stale owned handlers on re-call — a second call must not double-write. -3. `cli/main.py` daemon path (`_run_daemon`): call - `configure_daemon_logging(config.logging)` right after the manifest loads; - then route the lifecycle lines through `logger = logging.getLogger("trading_bot.daemon")`: - - `"daemon started (mode=…): N strateg(ies), tick=…"` → `logger.info` - (keep the `_console.print` too — interactive foreground UX unchanged). - - the per-tick `"daemon tick: stepped N strategy(ies)"` → `logger.info` - (drop the console print for this one — it is daemon-only noise). - - `"daemon tick error: …"` (`cli/main.py:1279`) → `logger.exception(...)` - — tracebacks land in the file (invisible today). - - `"daemon stopped (all strategies shut down)"` → `logger.info` + console. -4. No change to `portfolio_feed`/`portfolio_runner`/`order_router` loggers in - this leaf — the handler existing is what makes their WARNINGs land in the - rotated file; elevating the per-unit story is leaf 02. -5. Secrets discipline: the formatter adds no context beyond - time/level/name/message; grep the touched lines for any credential-adjacent - value (none expected — assert in review). - -## Tests - -- `test_log_setup.py`: - - handler wiring: after configure, root has exactly one owned - `TimedRotatingFileHandler` (`when == "MIDNIGHT"`, `backupCount == cfg.retention_days`) - and one owned `StreamHandler`; calling configure twice leaves exactly one - of each (idempotence). - - formatter: an emitted record's line matches - `^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}[+-]\d{2}:\d{2} ` - and contains the level and logger name. - - level: `cfg.level="DEBUG"` makes a DEBUG record reach the file; - `apscheduler` logger is capped at WARNING. - - file: the log file is created under a tmp_path dir passed as `cfg.dir`. -- `test_config.py`: `LoggingConfig` defaults; invalid level rejected; - `retention_days=0` rejected; manifest YAML without `logging:` yields - defaults; with a `logging: {level: debug}` section parses and upper-cases. -- Full suite + `ruff check trading_bot/` green. - -## Verification on real data - -**Never touch the live daemon (port 8000) or `var/` originals.** Scratch -instance instead: - -1. Build a scratch manifest in the session scratchpad: copy of - `configs/dashboard.yaml` with `ui.port: 8099`, a throwaway `ui.token`, - `db_path`s pointing at **copies** of the two books in the scratchpad, - `logging: {dir: /logs}`, same read-only dccd `data_path`. -2. Run `trading-bot start --serve -c ` (venv python, - foreground or background **without** any shell redirect), let it tick - ≥ 3 minutes, then SIGINT. -3. Read `/logs/daemon.log` and report verbatim: the - `daemon started` line, ≥ 2 tick lines ~60 s apart, the `daemon stopped` - line — every line timestamped with a `+02:00`-style offset; confirm the - handler's `backupCount`/`when` by introspection in the tests (rotation - itself is unit-tested; the real check here is file creation + format + - flow). -4. Confirm the live daemon on port 8000 was untouched - (`curl -s 127.0.0.1:8000/health` unchanged, pid 1348485 still running). - -## Closeout - -- CHANGELOG `### Added`: "daemon logs: timestamped (ISO-8601 with tz offset), - midnight-rotated `logs/daemon.log` (retention 14 d), level via the manifest - `logging:` section; tick errors now carry tracebacks (#XX)". -- ADR: logging config lives in `application/` (composition seam, domain stays - pure); root-logger handlers + third-party namespace caps; local-time ISO - timestamps **with offset** (rejected: UTC-only — operator reads local; - rejected: per-module handlers — one spine, N emitters). -- `06-status.md`: note the daemon-logs spine landed (leaf 1/3 of - `daemon-logging`). -- Tick leaf 01 in `00-plan.md`; archive this leaf file. Roadmap line stays - (leaves 02–03 open). diff --git a/trading_bot/application/config.py b/trading_bot/application/config.py index 5374385..e35ea9e 100644 --- a/trading_bot/application/config.py +++ b/trading_bot/application/config.py @@ -58,6 +58,7 @@ from __future__ import annotations +import logging import os import pathlib from decimal import Decimal @@ -77,6 +78,7 @@ "StrategyConfig", "PortfolioStrategyConfig", "RiskConfig", + "LoggingConfig", "AppConfig", ] @@ -671,6 +673,54 @@ def _require_token_for_non_loopback(self) -> UIConfig: return self +class LoggingConfig(BaseModel): + """How the **daemon** logs — level, destination directory, retention. + + The daemon path (``trading-bot start [--serve]``) routes its lifecycle and + per-tick lines through the standard-library :mod:`logging` root logger, + wired by :func:`~trading_bot.application.log_setup.configure_daemon_logging` + to a midnight-rotated ``daemon.log`` (plus ``stderr``, so systemd/journal + still sees output). This model is the manifest's optional ``logging:`` + section that tunes that wiring; interactive CLI commands (``status`` / + ``kpi`` / ``canary`` / ...) keep their rich-console output and ignore it. + The section is **additive** — a manifest with no ``logging:`` key keeps + every default below. + + Parameters + ---------- + level : str, optional + Root log level, validated case-insensitively against the standard + library's level names (:func:`logging.getLevelNamesMapping` — ``DEBUG`` + / ``INFO`` / ``WARNING`` / ``ERROR`` / ``CRITICAL`` and their aliases) + and stored **upper-case**. Defaults to ``"INFO"`` — the engine's own + story, with the noisy third-party namespaces capped at ``WARNING`` by + the setup. + dir : pathlib.Path, optional + Directory the rotated ``daemon.log`` (and its dated backups) is written + to. A relative path (the default ``Path("logs")``) resolves against the + working directory the daemon runs from, like the other manifest paths; + it is created if missing. + retention_days : int, optional + Number of dated backups the midnight rotation keeps (``backupCount``); + older files are pruned. Must be ``>= 1``. Defaults to ``14``. + + """ + + level: str = "INFO" + dir: pathlib.Path = pathlib.Path("logs") + retention_days: int = Field(default=14, ge=1) + + @field_validator("level") + @classmethod + def _valid_level(cls, v: str) -> str: + """Accept any standard level name case-insensitively; store it upper-case.""" + upper = v.strip().upper() + if upper not in logging.getLevelNamesMapping(): + valid = ", ".join(sorted(logging.getLevelNamesMapping())) + raise ValueError(f"level {v!r} is not a valid log level (one of: {valid})") + return upper + + class AppConfig(BaseModel): """Top-level engine configuration — brokers, strategies and risk. @@ -757,6 +807,11 @@ class AppConfig(BaseModel): storage : StorageConfig, optional Where state is persisted (SQLite) and where the bars feed reads data from (dccd dir). Defaults to all-unset (each layer's own default). + logging : LoggingConfig, optional + How the **daemon** path logs (level / directory / retention) — consumed + by :func:`~trading_bot.application.log_setup.configure_daemon_logging`. + Additive: a manifest with no ``logging:`` section keeps the defaults + (INFO, ``logs/``, 14 days). Interactive CLI commands ignore it. Examples -------- @@ -787,6 +842,7 @@ class AppConfig(BaseModel): risk: RiskConfig = Field(default_factory=RiskConfig) storage: StorageConfig = Field(default_factory=StorageConfig) ui: UIConfig = Field(default_factory=UIConfig) + logging: LoggingConfig = Field(default_factory=LoggingConfig) @field_validator("display_currency") @classmethod diff --git a/trading_bot/application/log_setup.py b/trading_bot/application/log_setup.py new file mode 100644 index 0000000..d25b14f --- /dev/null +++ b/trading_bot/application/log_setup.py @@ -0,0 +1,148 @@ +"""Daemon logging spine — rotated, ISO-8601-timestamped, manifest-configurable. + +The interactive CLI commands (``status`` / ``kpi`` / ``canary`` / ...) render to +a rich console and are unaffected by this module. The **daemon** path +(``trading-bot start [--serve]``) is different: it runs headless for days, so its +story has to land somewhere durable. :func:`configure_daemon_logging` wires the +standard-library :mod:`logging` root logger — driven by the manifest's optional +``logging:`` section (:class:`~trading_bot.application.config.LoggingConfig`) — to + +* a :class:`~logging.handlers.TimedRotatingFileHandler` that rolls + ``/daemon.log`` at **midnight** and keeps ``retention_days`` dated + backups, and +* a :class:`~logging.StreamHandler` on ``stderr`` (so a systemd/journal unit — + or a plain ``nohup`` redirect — still captures the same lines). + +Both share a formatter whose timestamp is **local time with a numeric UTC +offset** (e.g. ``2026-07-14T13:35:40.123+02:00``): unambiguous across a DST +change and directly sortable/greppable. The engine's own namespaces log at the +configured ``level`` (INFO by default); the noisy third-party namespaces +(:data:`NOISY_NAMESPACES`) are capped at ``WARNING`` so INFO stays the engine's +story (an APScheduler *misfire* WARNING still flows). + +The setup is **idempotent**: it tags the handlers it installs +(:data:`OWNED_HANDLER_ATTR`) and removes its own stale handlers on a re-call, so +a second invocation never double-writes and never disturbs handlers attached by +anything else (pytest, an embedding host, ...). + +Secrets discipline: the formatter adds nothing beyond time / level / logger name +/ message — no request bodies, no credentials. Callers stay responsible for never +passing a credential-adjacent value into a log record. +""" + +from __future__ import annotations + +# Built-in +import logging +import sys +from datetime import datetime +from logging.handlers import TimedRotatingFileHandler + +# Local +from trading_bot.application.config import LoggingConfig + +__all__ = [ + "configure_daemon_logging", + "OWNED_HANDLER_ATTR", + "NOISY_NAMESPACES", +] + +#: Attribute stamped ``True`` on every handler this module installs, so a re-call +#: can find and drop exactly its own handlers (idempotence) without touching any +#: handler attached by something else. +OWNED_HANDLER_ATTR = "_trading_bot_daemon_owned" + +#: Third-party logger namespaces capped at ``WARNING`` so INFO stays the engine's +#: story rather than framework chatter. An APScheduler misfire WARNING (a real +#: signal the daemon fell behind) is >= WARNING, so it still reaches the file. +NOISY_NAMESPACES: tuple[str, ...] = ( + "apscheduler", + "uvicorn", + "uvicorn.access", + "httpx", + "websockets", +) + +#: The shared log-line layout: ISO timestamp, padded level, logger name, message. +_LOG_FORMAT = "%(asctime)s %(levelname)-8s %(name)s — %(message)s" + + +class _OffsetIsoFormatter(logging.Formatter): + """A :class:`logging.Formatter` whose ``asctime`` is local ISO-8601 with offset. + + Overrides :meth:`logging.Formatter.formatTime` to render the record's + creation time as local time carrying a **numeric UTC offset** (e.g. + ``2026-07-14T13:35:40.123+02:00``), millisecond precision. The offset is what + makes a line unambiguous across a DST change; ``datefmt`` is ignored on + purpose so every line is uniform. + """ + + def formatTime( # noqa: N802 - overriding the stdlib camelCase hook + self, record: logging.LogRecord, datefmt: str | None = None + ) -> str: + """Return the record's local creation time as ISO-8601 with numeric offset.""" + # A naive local datetime, then `.astimezone()` attaches the local offset. + return ( + datetime.fromtimestamp(record.created) + .astimezone() + .isoformat(timespec="milliseconds") + ) + + +def configure_daemon_logging(cfg: LoggingConfig) -> None: + """Wire the root logger for the daemon: rotated file + stderr, per ``cfg``. + + Attaches an owned :class:`~logging.handlers.TimedRotatingFileHandler` (rolls + ``cfg.dir / "daemon.log"`` at midnight, keeps ``cfg.retention_days`` backups) + and an owned :class:`~logging.StreamHandler` on ``stderr`` to the root logger, + both using the :class:`_OffsetIsoFormatter`; sets the root level to + ``cfg.level`` and caps :data:`NOISY_NAMESPACES` at ``WARNING``. Creates + ``cfg.dir`` if missing. + + Idempotent: any handler this module previously installed (tagged + :data:`OWNED_HANDLER_ATTR`) is removed and closed first, so a second call + leaves exactly one owned handler of each kind — no double-writing — and + handlers owned by anything else are left untouched. + + Parameters + ---------- + cfg : LoggingConfig + The resolved ``logging:`` section (level / directory / retention). + + Returns + ------- + None + + """ + cfg.dir.mkdir(parents=True, exist_ok=True) + root = logging.getLogger() + + # Idempotence: drop (and close) only the handlers this module installed + # before, so a re-call never accumulates duplicates. + for handler in list(root.handlers): + if getattr(handler, OWNED_HANDLER_ATTR, False): + root.removeHandler(handler) + handler.close() + + formatter = _OffsetIsoFormatter(_LOG_FORMAT) + + file_handler = TimedRotatingFileHandler( + cfg.dir / "daemon.log", + when="midnight", + backupCount=cfg.retention_days, + encoding="utf-8", + ) + file_handler.setFormatter(formatter) + setattr(file_handler, OWNED_HANDLER_ATTR, True) + root.addHandler(file_handler) + + stream_handler = logging.StreamHandler(sys.stderr) + stream_handler.setFormatter(formatter) + setattr(stream_handler, OWNED_HANDLER_ATTR, True) + root.addHandler(stream_handler) + + # `cfg.level` is a validated, upper-cased level name — `setLevel` accepts it. + root.setLevel(cfg.level) + + for namespace in NOISY_NAMESPACES: + logging.getLogger(namespace).setLevel(logging.WARNING) diff --git a/trading_bot/interfaces/cli/main.py b/trading_bot/interfaces/cli/main.py index 42a52f6..48a8e18 100644 --- a/trading_bot/interfaces/cli/main.py +++ b/trading_bot/interfaces/cli/main.py @@ -47,6 +47,7 @@ import asyncio import contextlib import dataclasses +import logging import math import os import pathlib @@ -71,6 +72,7 @@ from trading_bot.application.config import AppConfig, BrokerConfig, StrategyConfig from trading_bot.application.data_feed import BARS_SCHEMA, InMemoryFeed from trading_bot.application.instrument_specs import InstrumentSpecResolver +from trading_bot.application.log_setup import configure_daemon_logging from trading_bot.application.performance_service import PerformanceService from trading_bot.application.run_app import run_app from trading_bot.application.service_factory import Engine, build_engine @@ -105,6 +107,11 @@ #: The shared rich console every command prints through. _console = Console() +#: The daemon's lifecycle/tick logger. Only the daemon path (``start [--serve]``) +#: emits through it, after :func:`~trading_bot.application.log_setup.configure_daemon_logging` +#: has wired the root handlers; interactive commands print to ``_console`` instead. +_daemon_logger = logging.getLogger("trading_bot.daemon") + #: Default synthetic-feed length (bars) when no ``--bars`` file is given — long #: enough for the default 10/30 MA windows to warm up and cross at least once. _SYNTHETIC_BARS = 80 @@ -1265,6 +1272,11 @@ async def _run_daemon( from trading_bot.application.supervisor import StrategySupervisor + # Wire the durable logging spine before anything logs: the daemon runs + # headless for days, so its lifecycle/tick lines (and any WARNING from the + # runners/router) must land in the rotated file, not just fly past on stderr. + configure_daemon_logging(config.logging) + supervisor = StrategySupervisor(config, dccd_client=dccd_client) # type: ignore[arg-type] await supervisor.start_all() @@ -1272,11 +1284,11 @@ async def _tick() -> None: try: stepped = await supervisor.step_all() if stepped: - _console.print( - f"[dim]daemon tick: stepped {stepped} strategy(ies)[/dim]" - ) + # Daemon-only noise: to the log file, not the console. + _daemon_logger.info("daemon tick: stepped %d strategy(ies)", stepped) except Exception as exc: # noqa: BLE001 - never let a tick kill the daemon - _console.print(f"[red]daemon tick error:[/red] {exc}") + # `exception` captures the traceback into the file (invisible before). + _daemon_logger.exception("daemon tick error: %s", exc) trigger = ( CronTrigger.from_crontab(cron) @@ -1286,10 +1298,17 @@ async def _tick() -> None: scheduler = AsyncIOScheduler() job = scheduler.add_job(_tick, trigger) scheduler.start() + _tick_desc = cron or f"every {interval:g}s" + _daemon_logger.info( + "daemon started (mode=%s): %d strateg(ies), tick=%s", + config.mode, + len(supervisor.names()), + _tick_desc, + ) _console.print( f"[green]daemon started[/green] (mode={config.mode}): " f"{len(supervisor.names())} strateg(ies), " - f"tick={cron or f'every {interval:g}s'}" + f"tick={_tick_desc}" ) def _schedule_info() -> dict[str, Any]: @@ -1397,6 +1416,7 @@ def _on_shutdown_signal() -> None: finally: scheduler.shutdown(wait=False) await supervisor.shutdown() + _daemon_logger.info("daemon stopped (all strategies shut down)") _console.print("[green]daemon stopped[/green] (all strategies shut down)") diff --git a/trading_bot/tests/application/test_config.py b/trading_bot/tests/application/test_config.py index 9dd9a58..bec4f6b 100644 --- a/trading_bot/tests/application/test_config.py +++ b/trading_bot/tests/application/test_config.py @@ -26,7 +26,7 @@ StorageConfig, StrategyConfig, ) -from trading_bot.application.config import PortfolioStrategyConfig +from trading_bot.application.config import LoggingConfig, PortfolioStrategyConfig #: The shipped runnable paper config (resolved from the repo root). EXAMPLE_CONFIG = ( @@ -860,3 +860,89 @@ def test_ui_config_loopback_without_token_is_allowed() -> None: cfg = AppConfig.model_validate({"mode": "paper", "ui": {"host": host}}) assert cfg.ui.host == host assert cfg.ui.token is None + + +# --- LoggingConfig (daemon logging spine — level/dir/retention) ------------ # + + +def test_logging_config_defaults() -> None: + """A bare ``LoggingConfig`` is INFO / ``logs`` / 14-day retention.""" + cfg = LoggingConfig() + assert cfg.level == "INFO" + assert cfg.dir == pathlib.Path("logs") + assert cfg.retention_days == 14 + + +def test_app_config_logging_defaults_when_section_absent() -> None: + """A manifest with no ``logging:`` section keeps the defaults (additive).""" + cfg = AppConfig.model_validate({"mode": "paper"}) + assert isinstance(cfg.logging, LoggingConfig) + assert cfg.logging.level == "INFO" + assert cfg.logging.dir == pathlib.Path("logs") + assert cfg.logging.retention_days == 14 + + +def test_logging_level_is_upper_cased_case_insensitively() -> None: + """A lower-case ``level`` validates and is stored upper-case.""" + cfg = AppConfig.model_validate({"logging": {"level": "debug"}}) + assert cfg.logging.level == "DEBUG" + + +def test_logging_invalid_level_rejected() -> None: + """A ``level`` that is not a standard log-level name is rejected.""" + with pytest.raises(ValidationError): + AppConfig.model_validate({"logging": {"level": "verbose"}}) + + +def test_logging_retention_days_zero_rejected() -> None: + """``retention_days`` must be ``>= 1`` — zero is rejected.""" + with pytest.raises(ValidationError): + AppConfig.model_validate({"logging": {"retention_days": 0}}) + + +def test_logging_retention_days_negative_rejected() -> None: + """A negative ``retention_days`` is rejected.""" + with pytest.raises(ValidationError): + AppConfig.model_validate({"logging": {"retention_days": -1}}) + + +def test_logging_section_parses_from_yaml(tmp_path) -> None: # noqa: ANN001 + """A ``logging:`` section parses (level upper-cased, dir/retention set).""" + path = tmp_path / "with-logging.yml" + path.write_text( + textwrap.dedent( + """\ + mode: paper + logging: + level: debug + dir: /var/log/trading_bot + retention_days: 30 + """ + ) + ) + cfg = AppConfig.from_yaml(path) + assert cfg.logging.level == "DEBUG" + assert cfg.logging.dir == pathlib.Path("/var/log/trading_bot") + assert cfg.logging.retention_days == 30 + + +def test_logging_absent_yaml_section_yields_defaults(tmp_path) -> None: # noqa: ANN001 + """A YAML manifest without ``logging:`` yields the default LoggingConfig.""" + path = tmp_path / "no-logging.yml" + path.write_text("mode: paper\n") + cfg = AppConfig.from_yaml(path) + assert cfg.logging.level == "INFO" + assert cfg.logging.dir == pathlib.Path("logs") + assert cfg.logging.retention_days == 14 + + +def test_logging_section_round_trips_through_yaml(tmp_path) -> None: # noqa: ANN001 + """The ``logging:`` section survives a ``to_yaml``/``from_yaml`` round-trip.""" + cfg = AppConfig.model_validate( + {"mode": "paper", "logging": {"level": "warning", "retention_days": 7}} + ) + path = tmp_path / "m.yaml" + cfg.to_yaml(path) + reloaded = AppConfig.from_yaml(path) + assert reloaded.logging.level == "WARNING" + assert reloaded.logging.retention_days == 7 diff --git a/trading_bot/tests/application/test_log_setup.py b/trading_bot/tests/application/test_log_setup.py new file mode 100644 index 0000000..ecd2d4b --- /dev/null +++ b/trading_bot/tests/application/test_log_setup.py @@ -0,0 +1,167 @@ +"""Tests for :func:`~trading_bot.application.log_setup.configure_daemon_logging`. + +These prove the daemon logging spine wires as intended: the root logger gains +exactly one owned rotated-file handler and one owned stderr handler, a second +call does not double them (idempotence), each line is ISO-8601 with a numeric UTC +offset, the configured level reaches the file while the noisy third-party +namespaces are capped at WARNING, and the log directory/file are created under +the manifest-declared ``dir``. + +Test hygiene: :func:`configure_daemon_logging` mutates *process-global* logging +state (the root logger's handlers/level and a few namespace levels). The +``restore_root_logging`` fixture snapshots and restores all of it around every +test so the wider suite's own logging is never polluted. +""" + +from __future__ import annotations + +import logging +import re +from collections.abc import Iterator +from logging.handlers import TimedRotatingFileHandler +from pathlib import Path + +import pytest + +from trading_bot.application.config import LoggingConfig +from trading_bot.application.log_setup import ( + NOISY_NAMESPACES, + OWNED_HANDLER_ATTR, + configure_daemon_logging, +) + +#: A regex for one emitted line: ISO-8601 local time with a numeric UTC offset +#: (e.g. ``2026-07-14T13:35:40.123+02:00``) followed by a space then the level. +_ISO_OFFSET_LINE = re.compile( + r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}[+-]\d{2}:\d{2} " +) + + +@pytest.fixture +def restore_root_logging() -> Iterator[None]: + """Snapshot and restore the process-global logging state around a test. + + Saves the root logger's handlers + level and every capped-namespace level, + then on teardown removes/closes any handler the test installed and puts the + original handlers, root level and namespace levels back — so a test that + wires the daemon logging never leaks handlers into the rest of the suite. + """ + root = logging.getLogger() + saved_handlers = root.handlers[:] + saved_level = root.level + saved_ns_levels = {ns: logging.getLogger(ns).level for ns in NOISY_NAMESPACES} + try: + yield + finally: + for handler in root.handlers[:]: + if handler not in saved_handlers: + root.removeHandler(handler) + handler.close() + for handler in saved_handlers: + if handler not in root.handlers: + root.addHandler(handler) + root.setLevel(saved_level) + for ns, level in saved_ns_levels.items(): + logging.getLogger(ns).setLevel(level) + + +def _owned(kind: type[logging.Handler]) -> list[logging.Handler]: + """The root logger's owned handlers whose *exact* type is ``kind``.""" + return [ + h + for h in logging.getLogger().handlers + if getattr(h, OWNED_HANDLER_ATTR, False) and type(h) is kind + ] + + +def test_configure_wires_one_owned_file_and_stream_handler( + tmp_path: Path, restore_root_logging: None +) -> None: + """After configure, root has exactly one owned rotated-file + one stderr handler.""" + cfg = LoggingConfig(dir=tmp_path / "logs", retention_days=7) + configure_daemon_logging(cfg) + + file_handlers = _owned(TimedRotatingFileHandler) + stream_handlers = _owned(logging.StreamHandler) + assert len(file_handlers) == 1 + assert len(stream_handlers) == 1 + + fh = file_handlers[0] + assert isinstance(fh, TimedRotatingFileHandler) + assert fh.when == "MIDNIGHT" + assert fh.backupCount == 7 + + +def test_configure_is_idempotent(tmp_path: Path, restore_root_logging: None) -> None: + """A second configure leaves exactly one owned handler of each kind (no doubling).""" + cfg = LoggingConfig(dir=tmp_path / "logs") + configure_daemon_logging(cfg) + configure_daemon_logging(cfg) + + assert len(_owned(TimedRotatingFileHandler)) == 1 + assert len(_owned(logging.StreamHandler)) == 1 + + +def test_formatter_is_iso_with_numeric_offset( + tmp_path: Path, restore_root_logging: None +) -> None: + """An emitted line is ISO-8601 with a numeric offset and carries level + name.""" + configure_daemon_logging(LoggingConfig(dir=tmp_path / "logs")) + logging.getLogger("trading_bot.daemon.test").info("hello world") + + line = _last_log_line(tmp_path / "logs" / "daemon.log") + assert _ISO_OFFSET_LINE.match(line), line + assert "INFO" in line + assert "trading_bot.daemon.test" in line + assert "hello world" in line + + +def test_level_debug_reaches_file_and_noisy_namespaces_capped( + tmp_path: Path, restore_root_logging: None +) -> None: + """``level=DEBUG`` lets a DEBUG record reach the file; apscheduler stays WARNING.""" + configure_daemon_logging(LoggingConfig(dir=tmp_path / "logs", level="DEBUG")) + + logging.getLogger("trading_bot.daemon.test").debug("a debug line") + contents = (tmp_path / "logs" / "daemon.log").read_text() + assert "a debug line" in contents + + # The noisy namespaces are floored at WARNING regardless of the root level. + assert logging.getLogger("apscheduler").level == logging.WARNING + for ns in NOISY_NAMESPACES: + assert logging.getLogger(ns).level == logging.WARNING + + +def test_default_level_info_drops_debug( + tmp_path: Path, restore_root_logging: None +) -> None: + """At the default INFO level, a DEBUG record does not reach the file.""" + configure_daemon_logging(LoggingConfig(dir=tmp_path / "logs")) + + logging.getLogger("trading_bot.daemon.test").debug("should-not-appear") + logging.getLogger("trading_bot.daemon.test").info("should-appear") + contents = (tmp_path / "logs" / "daemon.log").read_text() + assert "should-not-appear" not in contents + assert "should-appear" in contents + + +def test_log_dir_and_file_created(tmp_path: Path, restore_root_logging: None) -> None: + """A missing (nested) ``dir`` is created and the log file appears on first emit.""" + log_dir = tmp_path / "nested" / "logs" + assert not log_dir.exists() + + configure_daemon_logging(LoggingConfig(dir=log_dir)) + assert log_dir.is_dir() + + logging.getLogger("trading_bot.daemon.test").info("x") + assert (log_dir / "daemon.log").is_file() + + +def _last_log_line(path: Path) -> str: + """Flush the owned handlers and return the last non-empty line of ``path``.""" + for handler in logging.getLogger().handlers: + if getattr(handler, OWNED_HANDLER_ATTR, False): + handler.flush() + lines = [ln for ln in path.read_text().splitlines() if ln.strip()] + assert lines, f"no log lines written to {path}" + return lines[-1]