M2.5.1: Structured application logger #27

Merged

archeious merged 1 commit from feat/structured-logging into main

2026-04-08 21:48:11 +00:00

claude-code commented

2026-04-08 21:47:09 +00:00

Collaborator

Closes Issue #24

Summary

Adds an operational logging layer (obs/) using structlog, separate from the existing JSONL trace logs. Traces remain the researcher provenance audit trail; these new logs cover system events (startup, errors, MCP transport, research lifecycle) and are designed to be ingested into OpenSearch from day one.

Backend

structlog with two renderers selectable via MARCHWARDEN_LOG_FORMAT=json|console
Auto-detects: console when stderr is a TTY, JSON otherwise — dev is human-readable, shipped runs emit OpenSearch-ready JSON without configuration
stdlib logging (anthropic SDK, httpx, mcp SDK) funneled through the same pipeline; noisy loggers quieted to WARN unless DEBUG is requested
Logs go to stderr so MCP stdio stdout stays clean
Optional rotating file via MARCHWARDEN_LOG_FILE=1

Context binding

At the start of each research() call, trace_id and researcher are bound via structlog.contextvars. Every downstream log line in that scope automatically carries them — no threading through call sites. Cleared on completion.

Wired into

cli.main.cli — configures logging on startup; logs ask_started/ask_completed/ask_failed
researchers.web.server.main — configures logging on startup; logs mcp_server_starting
researchers.web.agent.research — binds trace context; logs research_started/research_completed

Verified

JSON output:

{"question": "test", "depth": "balanced", "event": "ask_started", "logger": "marchwarden.cli", "level": "info", "timestamp": "2026-04-08T21:46:24.769726Z"}
{"confidence": 0.91, "citations": 10, "tokens_used": 44649, "event": "research_completed", "researcher": "web", "trace_id": "test-123", "logger": "marchwarden.cli", "level": "info", "timestamp": "2026-04-08T21:46:24.770025Z"}

Console output:

2026-04-08T21:46:30.932Z [info     ] research_completed             [marchwarden.cli] citations=10 confidence=0.91 researcher=web trace_id=abc
2026-04-08T21:46:30.932Z [warning  ] budget_exhausted               [marchwarden.cli] budget=20000 researcher=web tokens=20623 trace_id=abc

Tests

6 new tests covering JSON format, console format, contextvar propagation, level filtering, idempotency, and auto-configure-on-first-use. 94/94 passing.

Out of scope

Cost ledger (M2.5.2 / Issue #25)
marchwarden costs command (M2.5.3 / Issue #26)
OpenSearch ingestion infra

Closes Issue #24 ## Summary Adds an operational logging layer (`obs/`) using **structlog**, separate from the existing JSONL trace logs. Traces remain the researcher provenance audit trail; these new logs cover system events (startup, errors, MCP transport, research lifecycle) and are designed to be ingested into OpenSearch from day one. ## Backend - **structlog** with two renderers selectable via `MARCHWARDEN_LOG_FORMAT=json|console` - Auto-detects: console when stderr is a TTY, JSON otherwise — dev is human-readable, shipped runs emit OpenSearch-ready JSON without configuration - stdlib `logging` (anthropic SDK, httpx, mcp SDK) funneled through the same pipeline; noisy loggers quieted to WARN unless DEBUG is requested - Logs go to **stderr** so MCP stdio stdout stays clean - Optional rotating file via `MARCHWARDEN_LOG_FILE=1` ## Context binding At the start of each `research()` call, `trace_id` and `researcher` are bound via `structlog.contextvars`. Every downstream log line in that scope automatically carries them — no threading through call sites. Cleared on completion. ## Wired into - `cli.main.cli` — configures logging on startup; logs `ask_started`/`ask_completed`/`ask_failed` - `researchers.web.server.main` — configures logging on startup; logs `mcp_server_starting` - `researchers.web.agent.research` — binds trace context; logs `research_started`/`research_completed` ## Verified JSON output: ```json {"question": "test", "depth": "balanced", "event": "ask_started", "logger": "marchwarden.cli", "level": "info", "timestamp": "2026-04-08T21:46:24.769726Z"} {"confidence": 0.91, "citations": 10, "tokens_used": 44649, "event": "research_completed", "researcher": "web", "trace_id": "test-123", "logger": "marchwarden.cli", "level": "info", "timestamp": "2026-04-08T21:46:24.770025Z"} ``` Console output: ``` 2026-04-08T21:46:30.932Z [info ] research_completed [marchwarden.cli] citations=10 confidence=0.91 researcher=web trace_id=abc 2026-04-08T21:46:30.932Z [warning ] budget_exhausted [marchwarden.cli] budget=20000 researcher=web tokens=20623 trace_id=abc ``` ## Tests 6 new tests covering JSON format, console format, contextvar propagation, level filtering, idempotency, and auto-configure-on-first-use. **94/94 passing.** ## Out of scope - Cost ledger (M2.5.2 / Issue #25) - `marchwarden costs` command (M2.5.3 / Issue #26) - OpenSearch ingestion infra

claude-code added 1 commit 2026-04-08 21:47:09 +00:00

M2.5.1: Structured application logger via structlog (#24 ) 8a62f6b014

Adds an operational logging layer separate from the JSONL trace
audit logs. Operational logs cover system events (startup, errors,
MCP transport, research lifecycle); JSONL traces remain the
researcher provenance audit trail.

Backend: structlog with two renderers selectable via
MARCHWARDEN_LOG_FORMAT (json|console). Defaults to console when
stderr is a TTY, json otherwise — so dev runs are human-readable
and shipped runs (containers, automation) emit OpenSearch-ready
JSON without configuration.

Key features:
- Named loggers per component: marchwarden.cli,
  marchwarden.mcp, marchwarden.researcher.web
- MARCHWARDEN_LOG_LEVEL controls global level (default INFO)
- MARCHWARDEN_LOG_FILE=1 enables a 10MB-rotating file at
  ~/.marchwarden/logs/marchwarden.log
- structlog contextvars bind trace_id + researcher at the start
  of each research() call so every downstream log line carries
  them automatically; cleared on completion
- stdlib logging is funneled through the same pipeline so noisy
  third-party loggers (httpx, anthropic) get the same formatting
  and quieted to WARN unless DEBUG is requested
- Logs to stderr to keep MCP stdio stdout clean

Wired into:
- cli.main.cli — configures logging on startup, logs ask_started/
  ask_completed/ask_failed
- researchers.web.server.main — configures logging on startup,
  logs mcp_server_starting
- researchers.web.agent.research — binds trace context, logs
  research_started/research_completed

Tests verify JSON and console formats, contextvar propagation,
level filtering, idempotency, and auto-configure-on-first-use.
94/94 tests passing.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>