From 5f218aaac579699f6d2a77d5821e0f532bcd0fa3 Mon Sep 17 00:00:00 2001
From: Matt Van Horn <455140+mvanhorn@users.noreply.github.com>
Date: Sun, 19 Apr 2026 09:24:52 -0700
Subject: [PATCH] fix: always log planner subqueries to stderr
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

The prior pipeline.py only logged the planner outcome when an external
--plan was passed ("[Planner] Using external plan (N subqueries)").
The internal LLM planner and the deterministic fallback ran silently,
so retrieval-breadth failures were invisible without --debug.

After plan finalization, emit a unified trace:

  [Planner] Plan: intent=X, freshness=Y, cluster_mode=Z, subqueries=N, source=external|llm|deterministic
  [Planner]   sq1 label=... search="..." sources=[...]
  [Planner]   sq2 ...

Stderr only; does not touch the user-facing stdout synthesis. The
source= annotation distinguishes --plan (external), provider-backed
(llm), and deterministic paths — so when the 2026-04-19 Hermes Agent
Use Cases failure mode recurs, the trace tells the user which path ran
and what subqueries it produced.

Tests: added test_planner_trace_always_fires_on_mock_run which captures
stderr on a mock pipeline run and asserts the summary + per-subquery
lines appear.
---
 scripts/lib/pipeline.py   | 31 ++++++++++++++++++++++++++++++-
 tests/test_pipeline_v3.py | 24 ++++++++++++++++++++++++
 2 files changed, 54 insertions(+), 1 deletion(-)

diff --git a/scripts/lib/pipeline.py b/scripts/lib/pipeline.py
index 9057208..81ee240 100644
--- a/scripts/lib/pipeline.py
+++ b/scripts/lib/pipeline.py
@@ -204,7 +204,7 @@ def run(
         plan = planner._sanitize_plan(
             external_plan, topic, available, requested_sources, depth,
         )
-        print(f"[Planner] Using external plan ({len(plan.subqueries)} subqueries)", file=sys.stderr)
+        plan_source = "external"
     else:
         plan = planner.plan_query(
             topic=topic,
@@ -215,6 +215,14 @@ def run(
             model=None if mock else runtime.planner_model,
             context=config.get("_auto_resolve_context", ""),
         )
+        # Source labelling: the fallback path annotates notes with "fallback-plan"
+        # or "deterministic-comparison-plan"; anything else came from the LLM.
+        if any("fallback" in note or "deterministic" in note for note in (plan.notes or [])):
+            plan_source = "deterministic"
+        elif not mock and reasoning_provider and runtime.planner_model:
+            plan_source = "llm"
+        else:
+            plan_source = "deterministic"
 
     # Safety net: ensure grounding appears in all subqueries even if the planner
     # omits it. This is redundant when the planner includes grounding via
@@ -224,6 +232,27 @@ def run(
             if "grounding" not in sq.sources:
                 sq.sources.append("grounding")
 
+    # Always-on planner trace. Emits one summary line plus one per subquery
+    # so retrieval-breadth failures like the 2026-04-19 Hermes Agent Use Cases
+    # disaster are visible without --debug. Stderr only; does not leak into
+    # the user-facing stdout synthesis.
+    print(
+        f"[Planner] Plan: intent={plan.intent}, freshness={plan.freshness_mode}, "
+        f"cluster_mode={plan.cluster_mode}, subqueries={len(plan.subqueries)}, "
+        f"source={plan_source}",
+        file=sys.stderr,
+    )
+    if plan.subqueries:
+        for index, sq in enumerate(plan.subqueries, start=1):
+            sources_str = ",".join(sq.sources) if sq.sources else "(none)"
+            print(
+                f"[Planner]   sq{index} label={sq.label} "
+                f'search="{sq.search_query}" sources=[{sources_str}]',
+                file=sys.stderr,
+            )
+    else:
+        print("[Planner]   (no subqueries in plan)", file=sys.stderr)
+
     bundle = schema.RetrievalBundle(artifacts={"grounding": []})
 
     # Project-mode or person-mode GitHub: run once before the main subquery loop
diff --git a/tests/test_pipeline_v3.py b/tests/test_pipeline_v3.py
index e1cc799..cc16f35 100644
--- a/tests/test_pipeline_v3.py
+++ b/tests/test_pipeline_v3.py
@@ -28,6 +28,30 @@ class PipelineV3Tests(unittest.TestCase):
         self.assertIn("grounding", report.items_by_source)
         self.assertEqual("gemini", report.provider_runtime.reasoning_provider)
 
+    def test_planner_trace_always_fires_on_mock_run(self):
+        """Unit 5: The unified planner trace emits one summary line plus one
+        line per subquery on every run, regardless of --debug. 2026-04-19
+        Hermes Agent Use Cases failure: retrieval-breadth issues were invisible
+        because the internal planner path logged nothing.
+        """
+        import io
+        import contextlib
+        buf = io.StringIO()
+        with contextlib.redirect_stderr(buf):
+            pipeline.run(
+                topic="test topic",
+                config={"LAST30DAYS_REASONING_PROVIDER": "gemini"},
+                depth="quick",
+                requested_sources=["reddit", "x", "grounding"],
+                mock=True,
+            )
+        output = buf.getvalue()
+        self.assertIn("[Planner] Plan: intent=", output)
+        self.assertIn("subqueries=", output)
+        self.assertIn("source=", output)
+        # At least one per-subquery line.
+        self.assertIn("[Planner]   sq1 label=", output)
+
 
 class TestSourceFetchCap(unittest.TestCase):
     """X source fetch count must be capped by MAX_SOURCE_FETCHES."""