From b510902af3bbe13680ca7e59bc23997966f211fe Mon Sep 17 00:00:00 2001
From: Jeff Smith <jeff@unbiasedgeek.com>
Date: Wed, 8 Apr 2026 16:22:13 -0600
Subject: [PATCH] Mirror trace steps to operational logger
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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>
---
 researchers/web/trace.py | 29 +++++++++++++++++++++++++++++
 1 file changed, 29 insertions(+)

diff --git a/researchers/web/trace.py b/researchers/web/trace.py
index 886e0a0..1c8e5fb 100644
--- a/researchers/web/trace.py
+++ b/researchers/web/trace.py
@@ -14,6 +14,27 @@ import uuid
 from pathlib import Path
 from typing import Any, Optional
 
+from obs import get_logger
+
+# Actions that get promoted to INFO in the operational log. Everything
+# else logs at DEBUG so the default INFO level shows ~6-8 milestones per
+# research call instead of 20+ chatty per-step events. Set
+# MARCHWARDEN_LOG_LEVEL=DEBUG to see all steps.
+_INFO_ACTIONS = frozenset(
+    {
+        "start",
+        "iteration_start",
+        "synthesis_start",
+        "synthesis_complete",
+        "synthesis_error",
+        "synthesis_build_error",
+        "budget_exhausted",
+        "complete",
+    }
+)
+
+_log = get_logger("marchwarden.researcher.trace")
+
 
 class TraceLogger:
     """Logs research steps to a JSONL file.
@@ -74,6 +95,14 @@ class TraceLogger:
 
         self._writer.write(json.dumps(entry, default=str) + "\n")
         self._writer.flush()
+
+        # Mirror the trace step into the operational logger so admins
+        # can watch progress in real time. trace_id and researcher are
+        # already bound in contextvars by WebResearcher.research, so
+        # they automatically appear on every line.
+        log_method = _log.info if action in _INFO_ACTIONS else _log.debug
+        log_method(action, step=self._step_counter, decision=decision, **kwargs)
+
         return entry
 
     def read_entries(self) -> list[dict]: