Mirror trace steps to the operational logger #32

Merged

archeious merged 1 commit from feat/per-step-logging into main

2026-04-08 22:23:02 +00:00

claude-code commented

2026-04-08 22:22:25 +00:00

Collaborator

Problem

The trace JSONL captures every step of a research call (search, fetch, iteration boundaries, synthesis), but the structured operational log only fired at research_started / research_completed. Administrators had no real-time visibility into agent progress.

Change

TraceLogger.log_step now also emits a structlog event using the same action name, fields, and step counter. trace_id and researcher are already bound in contextvars by WebResearcher.research, so every line carries them automatically — no plumbing needed at the call sites.

Volume control

A curated set of milestone actions logs at INFO:

start, iteration_start, synthesis_start, synthesis_complete, synthesis_error, synthesis_build_error, budget_exhausted, complete

Chatty per-tool actions log at DEBUG:

web_search, web_search_complete, fetch_url, fetch_url_complete, agent_message

Default MARCHWARDEN_LOG_LEVEL=INFO shows ~9 lines per call. MARCHWARDEN_LOG_LEVEL=DEBUG shows everything (~13+ depending on tool calls). OpenSearch can ingest at DEBUG always.

Verified end-to-end

"What is the highest peak in Utah?" at INFO:

research_started               [marchwarden.researcher.web]
start                          [marchwarden.researcher.trace]   step=1
iteration_start                [marchwarden.researcher.trace]   step=2
iteration_start                [marchwarden.researcher.trace]   step=5
synthesis_start                [marchwarden.researcher.trace]   step=8
synthesis_complete             [marchwarden.researcher.trace]   step=9
complete                       [marchwarden.researcher.trace]   step=10
research_completed             [marchwarden.researcher.web]
cost_recorded                  [marchwarden.costs]

Every line carried trace_id=3152d79d-... and researcher=web in the bound context.

110/110 tests still passing.

## Problem The trace JSONL captures every step of a research call (search, fetch, iteration boundaries, synthesis), but the structured operational log only fired at `research_started` / `research_completed`. Administrators had no real-time visibility into agent progress. ## Change `TraceLogger.log_step` now also emits a structlog event using the same action name, fields, and step counter. `trace_id` and `researcher` are already bound in contextvars by `WebResearcher.research`, so every line carries them automatically — no plumbing needed at the call sites. ## Volume control A curated set of **milestone actions logs at INFO**: - `start`, `iteration_start`, `synthesis_start`, `synthesis_complete`, `synthesis_error`, `synthesis_build_error`, `budget_exhausted`, `complete` Chatty per-tool actions log at **DEBUG**: - `web_search`, `web_search_complete`, `fetch_url`, `fetch_url_complete`, `agent_message` Default `MARCHWARDEN_LOG_LEVEL=INFO` shows ~9 lines per call. `MARCHWARDEN_LOG_LEVEL=DEBUG` shows everything (~13+ depending on tool calls). OpenSearch can ingest at DEBUG always. ## Verified end-to-end "What is the highest peak in Utah?" at INFO: ``` research_started [marchwarden.researcher.web] start [marchwarden.researcher.trace] step=1 iteration_start [marchwarden.researcher.trace] step=2 iteration_start [marchwarden.researcher.trace] step=5 synthesis_start [marchwarden.researcher.trace] step=8 synthesis_complete [marchwarden.researcher.trace] step=9 complete [marchwarden.researcher.trace] step=10 research_completed [marchwarden.researcher.web] cost_recorded [marchwarden.costs] ``` Every line carried `trace_id=3152d79d-...` and `researcher=web` in the bound context. 110/110 tests still passing.

claude-code added 1 commit 2026-04-08 22:22:26 +00:00

Mirror trace steps to operational logger b510902af3

The trace JSONL captures every step of a research call (search,
fetch, iteration boundaries, synthesis), but the structured
operational log only fired at research_started / research_completed,
giving administrators no real-time visibility into agent progress.

Have TraceLogger.log_step also emit a structlog event using the
same action name, fields, and step counter. trace_id and researcher
are already bound in contextvars by WebResearcher.research, so
every line carries them automatically — no plumbing needed.

Volume control: a curated set of milestone actions logs at INFO
(start, iteration_start, synthesis_start/complete/error, budget_-
exhausted, complete). Chatty per-tool actions (web_search,
fetch_url and their *_complete pairs) log at DEBUG. Default
MARCHWARDEN_LOG_LEVEL=INFO shows ~9 lines per call;
MARCHWARDEN_LOG_LEVEL=DEBUG shows everything.

This keeps dev stderr readable while making full step visibility
one env var away — and OpenSearch can ingest at DEBUG always.

Verified end-to-end: Utah peak query at INFO produces 9 milestone
log lines, at DEBUG produces 13.

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