fix: always log planner subqueries to stderr
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.
This commit is contained in:
+30
-1
@@ -204,7 +204,7 @@ def run(
|
|||||||
plan = planner._sanitize_plan(
|
plan = planner._sanitize_plan(
|
||||||
external_plan, topic, available, requested_sources, depth,
|
external_plan, topic, available, requested_sources, depth,
|
||||||
)
|
)
|
||||||
print(f"[Planner] Using external plan ({len(plan.subqueries)} subqueries)", file=sys.stderr)
|
plan_source = "external"
|
||||||
else:
|
else:
|
||||||
plan = planner.plan_query(
|
plan = planner.plan_query(
|
||||||
topic=topic,
|
topic=topic,
|
||||||
@@ -215,6 +215,14 @@ def run(
|
|||||||
model=None if mock else runtime.planner_model,
|
model=None if mock else runtime.planner_model,
|
||||||
context=config.get("_auto_resolve_context", ""),
|
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
|
# Safety net: ensure grounding appears in all subqueries even if the planner
|
||||||
# omits it. This is redundant when the planner includes grounding via
|
# omits it. This is redundant when the planner includes grounding via
|
||||||
@@ -224,6 +232,27 @@ def run(
|
|||||||
if "grounding" not in sq.sources:
|
if "grounding" not in sq.sources:
|
||||||
sq.sources.append("grounding")
|
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": []})
|
bundle = schema.RetrievalBundle(artifacts={"grounding": []})
|
||||||
|
|
||||||
# Project-mode or person-mode GitHub: run once before the main subquery loop
|
# Project-mode or person-mode GitHub: run once before the main subquery loop
|
||||||
|
|||||||
@@ -28,6 +28,30 @@ class PipelineV3Tests(unittest.TestCase):
|
|||||||
self.assertIn("grounding", report.items_by_source)
|
self.assertIn("grounding", report.items_by_source)
|
||||||
self.assertEqual("gemini", report.provider_runtime.reasoning_provider)
|
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):
|
class TestSourceFetchCap(unittest.TestCase):
|
||||||
"""X source fetch count must be capped by MAX_SOURCE_FETCHES."""
|
"""X source fetch count must be capped by MAX_SOURCE_FETCHES."""
|
||||||
|
|||||||
Reference in New Issue
Block a user