docs: plan daemon-logging

doc/dev/07-roadmap.md

@@ -86,6 +86,8 @@ order — none started yet, each is a `/pick-task` candidate:
    risk-limit visibility incl. daily-loss usage); `last_error` on
    `/api/strategies` (a stopped unit is indistinguishable from a crashed one).
 
+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/`.
+
 4. [ ] **Ops readiness** (not engine code): daemon under **systemd** (restart
    policy + an alert when the process dies — today it is a `nohup` from a
    terminal session); a **multi-week paper soak** on the real-data books

doc/dev/plans/daemon-logging/00-plan.md

@@ -0,0 +1,90 @@
+---
+plan: daemon-logging
+kind: global
+status: planning
+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
+---
+
+# daemon-logging — structured, timestamped, rotated daemon logs
+
+## Goal
+
+Make the daemon **auditable from its log alone**. The 2026-07-14 health audit
+had to reconstruct everything from the API and the SQLite books because
+`logs/daemon.log` is a bare shell redirect of untimestamped rich-console
+prints: no per-line timestamps, no per-strategy-unit lines, no order/skip
+trail, no rotation, and 10 process incarnations interleaved in one file.
+
+What the audit measured (the evidence this epic answers):
+
+- The strings `alloc1-binance`, `order`, `submit`, `evaluat` **never appear**
+  in the log; the only cadence signal is the aggregate
+  `daemon tick: stepped 2 strategy(ies)` line.
+- `PortfolioRunner` already logs the `prepare_leg` decisions — at `DEBUG`
+  (`portfolio_runner.py:704/715`), with **no handler configured**, so they are
+  invisible; only `WARNING+` escapes via logging's last-resort stderr handler
+  (that is how `portfolio_feed`'s corrupted-parquet/lag warnings reached the
+  redirect file).
+- Realised tick cadence over 47 h was **~74 s vs the nominal 60 s** (2304
+  ticks where ~2832 were expected) with a single APScheduler misfire line ever
+  logged; `scheduler.add_job(_tick, trigger)` (`cli/main.py:1287`) sets no
+  explicit `coalesce` / `misfire_grace_time` / `max_instances`.
+- Whether alloc1-kraken's post-genesis silence is dust-skips (expected at
+  capital 100) or a stall is **not answerable from the log** — after this epic
+  it is one grep.
+
+## Decomposition
+
+1. **01-log-setup** — the logging spine: `LoggingConfig` (level, dir,
+   retention), `configure_daemon_logging()` with a midnight
+   `TimedRotatingFileHandler` and ISO-8601 timestamps carrying the numeric tz
+   offset, daemon lifecycle lines routed through it, tracebacks captured via
+   `logger.exception`.
+2. **02-unit-event-trail** — per-unit INFO story: rebalance summary line,
+   leg round-up/skip reasons (elevated from invisible DEBUG), fill lines,
+   supervisor state transitions; pinned anti-spam rule (a no-new-bar tick adds
+   zero INFO lines).
+3. **03-tick-timing-metrics** — per-tick and per-unit durations measured and
+   logged (WARN on overrun), explicit APScheduler semantics
+   (`coalesce=True, misfire_grace_time=interval, max_instances=1`), additive
+   `/api/health` + `/api/strategies` timing fields — proves or refutes the
+   74 s-cadence hypothesis.
+
+## Leaf checklist
+
+- [ ] 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
+
+## Dependencies
+
+`01 → 02 → 03`, strictly serial (`parallel: false` everywhere): 02 and 03
+both touch `supervisor.py`, and 03 extends the tick line 01 introduces and the
+summary line 02 introduces.
+
+## Done criteria
+
+- The audit's unanswerable questions become greps on `logs/daemon.log`: when
+  did each unit last evaluate / trade / skip and **why** (skip reasons carry
+  the exact Decimals from `LegDecision.reason`).
+- Every line timestamped ISO-8601 **with numeric tz offset** (the audit burned
+  time on UTC-vs-CEST ambiguity).
+- Rotation active: `daemon.log` + dated backups, retention 14 days; one file
+  no longer accumulates incarnations.
+- `/api/health` carries `last_tick_duration_ms` / `ticks_total` /
+  `ticks_overrun`; `/api/strategies` rows carry `last_step_duration_ms` — all
+  **additive** (public-contract rule: never change existing fields).
+- Verification never touches the live daemon (port 8000) — every leaf verifies
+  on a **scratch instance** (port 8099, scratch book copies, read-only dccd
+  store).
+
+## Release / restart runbook note
+
+The production daemon keeps running the released version during the epic. At
+the post-release restart (maintainer-authorized): stop the daemon, archive the
+legacy unrotated file to `logs/archive/daemon-pre-rotation-20260714.log`, and
+restart **without** the shell `>> logs/daemon.log` redirect (the file handler
+now owns the file; a shell redirect would double-write). That restart is the
+moment the old log gets cleaned — not before (the running process holds the
+fd).

doc/dev/plans/daemon-logging/01-log-setup.md

@@ -0,0 +1,129 @@
+---
+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: <scratchpad>/logs}`, same read-only dccd `data_path`.
+2. Run `trading-bot start --serve -c <scratch manifest>` (venv python,
+   foreground or background **without** any shell redirect), let it tick
+   ≥ 3 minutes, then SIGINT.
+3. Read `<scratchpad>/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).

doc/dev/plans/daemon-logging/02-unit-event-trail.md

@@ -0,0 +1,113 @@
+---
+plan: daemon-logging/02-unit-event-trail
+kind: leaf
+status: planned
+complexity: medium
+depends: [01]
+parallel: false
+branch: feat/daemon-unit-event-logs
+pr: ""
+---
+
+# 02 — Per-unit event trail: evaluations, orders, skips, fills
+
+## Goal
+
+The log tells each unit's story. After this leaf, "why hasn't alloc1-kraken
+traded since genesis?" is answered by grepping `logs/daemon.log`: every
+completed rebalance logs a summary, every round-up/skip logs its
+`LegDecision.reason` (the exact Decimals and the binding minimum), every
+submit and fill logs identifiers and amounts. Pinned anti-spam rule: a
+steady-state tick where nothing happened adds **zero** INFO lines.
+
+## Files to change
+
+- `trading_bot/application/portfolio_runner.py` — summary line + elevate the
+  leg-decision/submit DEBUGs (`:704`, `:715`) to the pinned INFO formats
+- `trading_bot/application/order_fill_sync.py` — INFO per fill applied
+- `trading_bot/application/supervisor.py` — unit state-transition lines
+  (started / stopped / step error)
+- `trading_bot/application/service_factory.py` — thread the unit name where a
+  component lacks it (see step 4)
+- `trading_bot/tests/application/` — extend the runner / fill-sync /
+  supervisor tests with `caplog` assertions
+
+## Steps
+
+Pinned line formats (key=value prefix, grep-stable; all through the module
+loggers `logging.getLogger(__name__)` that already exist):
+
+1. **Rebalance summary** — in `PortfolioRunner`, one INFO at the end of each
+   *evaluated* rebalance (a new bar was consumed, whether or not orders
+   resulted):
+   `unit=<name> rebalance asof=<bar ts ISO-UTC> legs=<n> submitted=<n> round_up=<n> skipped=<n> on_target=<n>`
+   The runner already counts these outcomes to return the submitted count —
+   accumulate the four counters alongside.
+2. **Leg decisions** — in `_prepare_delta` (`portfolio_runner.py:704/715`
+   today): `round_up` and `skip` decisions log **INFO**
+   `unit=<name> leg <symbol> <action>: <LegDecision.reason>`;
+   plain `submit` passthroughs stay DEBUG (the router/summary already tell
+   that story — no double INFO per order).
+3. **Order lifecycle** — the runner is per-unit and awaits the router, so it
+   logs (no router signature change):
+   - accepted: `unit=<name> order submitted cid=<client_order_id> <side> <qty> <symbol> @ <limit px|mkt> venue_id=<id>`
+     (INFO — replaces/absorbs the `:715` DEBUG);
+   - refused/rejected: WARN with the same prefix + `reason=<…>`.
+4. **Fills** — `OrderFillSync` applies every fill; give it an optional
+   `unit_name: str | None = None` constructor param (additive, default keeps
+   current signature working), threaded from `service_factory` where each
+   unit's sync is built. On apply: INFO
+   `unit=<name> fill cid=<cid> <signed qty> @ <price> fee=<fee> <fee_asset|quote>`.
+5. **Supervisor transitions** — INFO on unit start/stop, ERROR (with
+   `logger.exception`) when a unit's `step` raises. A tick that evaluates
+   nothing (no new bar) logs at DEBUG only.
+6. **Anti-spam check** — with INFO level and no new daily bar, one hour of
+   ticks must add only the ~60 heartbeat lines from leaf 01 — nothing per
+   unit. (Two units × 1440 min/day of per-unit INFO would bury the signal.)
+7. Secrets: none of these lines may include tokens/keys — amounts, ids,
+   symbols, reasons only (`LegDecision.reason` carries only Decimals and
+   minimum names by construction).
+
+## Tests
+
+- Runner rebalance with a mixed outcome (≥1 submit, ≥1 skip via a venue-min
+  spec): `caplog` shows the summary line with correct counters, the skip's
+  INFO line containing the `LegDecision.reason` text, the submit's INFO line
+  with cid; counters sum to `legs`.
+- No-new-bar tick: `caplog` at INFO gains **zero** unit lines.
+- `OrderFillSync` with `unit_name="u1"`: fill application logs the pinned
+  format incl. `fee_asset`; with `unit_name=None`: line still valid (prefix
+  `unit=?` or omitted — pick one and test it).
+- Supervisor: step exception → ERROR with traceback in `caplog`.
+- Full suite + `ruff check trading_bot/` green.
+
+## Verification on real data
+
+Scratch instance (same recipe as leaf 01 — port 8099, scratch book copies,
+read-only real dccd store, **never** port 8000 / `var/` originals):
+
+1. Point the scratch manifest at **fresh empty books** (no copies) so genesis
+   funding + the first rebalance fire immediately on start — the same real
+   signal path as 2026-07-12, on today's real bars.
+2. Run ≥ 3 minutes; SIGINT.
+3. Report verbatim from the scratch log: both units' rebalance summary lines,
+   at least one real `skip` line with its full `LegDecision.reason` (expected
+   in numbers: at capital 100, most kraken legs sit below the venue minimum —
+   this excerpt IS the documented answer to the kraken-silence question), at
+   least one submitted-order line and its fill line with matching cid.
+4. Cross-check one logged fill against the scratch book
+   (`sqlite3 <scratch>.sqlite 'select …'`): cid, qty, price match — the log
+   never claims a fill the store does not have.
+5. Confirm the live daemon untouched (port 8000 responds, pid unchanged).
+
+## Closeout
+
+- CHANGELOG `### Added`: "per-unit daemon log trail: rebalance summaries,
+  round-up/skip reasons (venue minimums), order submits and fills with ids —
+  a unit's inactivity is now explained by the log (#XX)".
+- ADR if judged non-trivial: lifecycle logging lives in the runner (per-unit,
+  sees router outcomes) instead of the router (shared, unit-blind) — rejected:
+  threading a LoggerAdapter through the router.
+- `06-status.md`: soak observability note — kraken dust-skip visibility.
+- Tick leaf 02 in `00-plan.md`; archive this leaf file. Roadmap line stays
+  (leaf 03 open).