Release v0.15.0

CHANGELOG.md

@@ -16,6 +16,46 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Removed
 
+## [0.15.0] - 2026-07-14
+
+### 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)
+- **Per-unit daemon log trail** — every evaluated rebalance logs one
+  grep-stable summary (`unit=… rebalance asof=… legs/submitted/round_up/
+  skipped/on_target`, counters partitioning the universe); round-up/skip leg
+  decisions log their full `LegDecision.reason` (the exact Decimals and the
+  binding venue minimum) at INFO; order submits (cid, side, qty, px,
+  venue id) at INFO and refusals at WARN; each applied fill logs
+  cid/qty/price/fee/fee-asset (`OrderFillSync.unit_name`, additive); unit
+  start/stop/step-error transitions logged. Anti-spam pinned: an idle tick
+  (no new bar) adds zero per-unit lines — a unit's inactivity is now
+  explained by the log. (#227)
+- **Tick timing measured and pinned (closes the `daemon-logging` epic)** —
+  every tick's duration is logged on the heartbeat (`in <s.mmm>s`, WARN on
+  interval overrun) and per-unit step durations captured; the tick job's
+  APScheduler semantics are now explicit (`coalesce=True`, `max_instances=1`,
+  `misfire_grace_time=interval` — the 1 s default grace silently skipped late
+  ticks, the measured source of the audit's ~74 s-vs-60 s cadence shortfall);
+  additive API fields: `/api/health` `last_tick_duration_ms` / `last_tick_ts` /
+  `ticks_total` / `ticks_overrun`, `/api/strategies` `last_step_duration_ms`.
+  Real-data check: steady-state ticks ~2 s, first tick (data load) ~46 s —
+  the duration hypothesis refuted, the misfire one confirmed as the fix. (#228)
+
+### Changed
+
+### Fixed
+
+### Deprecated
+
+### Removed
+
 ## [0.14.0] - 2026-07-12
 
 ### Added

doc/dev/03-decisions.md

@@ -6,6 +6,61 @@ rejected approaches as tombstones.
 
 ---
 
+### 2026-07-14 Tick scheduler semantics pinned; timing is a health signal (PR #228)  [accepted]
+- **Choice**: the daemon tick job runs with explicit `coalesce=True`,
+  `max_instances=1`, `misfire_grace_time=interval` (cron triggers: fixed
+  30 s); every tick's duration is measured (heartbeat `in <s.mmm>s`, WARN on
+  interval overrun) and exposed additively on `/api/health`
+  (`last_tick_duration_ms`/`last_tick_ts`/`ticks_total`/`ticks_overrun`) and
+  `/api/strategies` (`last_step_duration_ms`). Per-unit duration lives on
+  the API field only, measured in the supervisor's `step` `finally` (counted
+  even when the step raises).
+- **Why**: APScheduler's **1 s default misfire grace silently skips** a tick
+  that fires late — the measured cause of the audit's ~74 s realised cadence
+  vs the 60 s nominal (real-data check: steady-state ticks ~2 s, first tick
+  ~46 s data load — duration never exceeds the interval, so skips, not
+  overruns, explain the shortfall). `max_instances=1` guarantees two ticks
+  never race one engine.
+- **Rejected alternatives**: raising the tick interval (hides the problem);
+  gathering units concurrently inside a tick (the per-unit lock serializes
+  anyway; complexity without cadence benefit); putting per-unit duration on
+  the leaf-02 rebalance line (emitted inside the runner, before the outer
+  step timing exists).
+
+### 2026-07-14 Unit event trail: runner-attributed lines, bus and log are two sinks (PR #227)  [accepted]
+- **Choice**: order-lifecycle log lines live in the **runner** (per-unit, sees
+  the router's outcome and the unit name) — not the shared router; the new
+  module-logger INFO/WARN lines are emitted **alongside** the existing
+  EventBus `LogEvent`s, not instead (the bus feeds the SSE dashboard, the
+  logger feeds `daemon.log` — two sinks, two audiences). `OrderFillSync`
+  gains an additive `unit_name` for fill attribution; supervisor step errors
+  are logged with traceback then **re-raised** (attribution without
+  swallowing the CLI tick's safety net).
+- **Why**: threading unit identity through the shared router would touch its
+  signature for a logging concern; the runner already owns the name and the
+  outcome. Replacing the bus emits would have silently unplugged the
+  dashboard's live log feed.
+- **Rejected alternatives**: per-unit `LoggerAdapter` injected into the
+  router (signature churn); replacing `LogEvent`s with logging (breaks SSE);
+  logging every idle tick per unit (2 units × 1440 min/day of noise — the
+  anti-spam rule is pinned in the plan).
+
+### 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

doc/dev/06-status.md

@@ -120,6 +120,17 @@ and `CHANGELOG.md` for what shipped.
 - **E1–E11 + the multi-asset/portfolio unit** shipped; the pre-production safety
   hardening (audit) is wired in (see *Where things stand*). `CHANGELOG.md` + git log are
   authoritative for what shipped per release.
+- **`daemon-logging` (2026-07-14, PRs #226–#228)**: the daemon is auditable
+  from its log alone — rotated, tz-offset-timestamped `logs/daemon.log`
+  (manifest `logging:` section), per-unit rebalance summaries + round-up/skip
+  `LegDecision.reason`s + order/fill lines (a unit's inactivity is now
+  explained by the log), tick durations on the heartbeat + additive
+  `/api/health`//`api/strategies` timing fields. Root-caused the 2026-07-14
+  audit's ~74 s-vs-60 s cadence shortfall: APScheduler's 1 s default misfire
+  grace silently skipped late ticks (steady-state ticks measure ~2 s; first
+  tick ~46 s data load) — the job now runs `coalesce=True`, `max_instances=1`,
+  `misfire_grace_time=interval`. The legacy unrotated log gets archived at the
+  post-release daemon restart.
 - **`paper-integrity` (2026-07-11, PRs #190–#194)**: paper ids unique across
   engine lifetimes, fills reach the tracked order + store row (`OrderFillSync`,
   startup healing), reconcile persists orphan-closes, restart/replay E2E.
@@ -183,6 +194,7 @@ 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).
 
+
 ## Known gaps / deferred
 
 - ~~**Final project name**~~ — **decided**: kept as `trading_bot` (with `dccd` /

pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "trading_bot"
-version = "0.14.0"
+version = "0.15.0"
 description = "Execution & orchestration layer of the trading triptych — live strategies, order routing, risk. Hexagonal, async-first."
 readme = "README.md"
 license = { text = "MIT" }

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

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
+  ``<dir>/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)