Make the shipped plan trace complete and stop counting planner spend twice

The shipped registry withheld the trace recorder from its PlannerNode and
Materializer, so `grapharc plan` wrote a file holding only admission/round/
stop: no plan event saying what was proposed and what it cost, and — because
the built subgraph inherits the materializer's recorder — no start/end pair
for any node the loop executed. Three nodes ran and none of them appeared.
README's "the trace holds ... the executed nodes' own start/end pairs" was
true of a hand-wired loop and false of the one the command drives. Both
collaborators get the recorder now, and the phase counts are asserted.

With the plan event present, a second defect became live: the round event
also carried the planner's tokens, and metrics, cost and replay all add
events they cannot place inside a node on top of node totals. The planner's
spend was therefore counted once as `plan` and again as `round` — meter
1979, metrics 2558. A round's duration_ms was worse, since it encloses the
plan plus every node the round ran. Neither is on the event now; both are on
its state_delta as round_tokens / round_iterations / round_duration_ms,
where no reader sums them, so what a round spent stays answerable from the
file without being added to the totals a second time.

RoundRecord.iterations was declared and never assigned, so every round
reported 0 while the run's meter counted the same work. _charge_back already
read the figure and discarded it; it is carried through _Execution now.

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

Author: Shashankss1205

grapharc/examples/plan_incident.py

@@ -163,7 +163,16 @@ def build_loop(
     # the same object, and a node body could otherwise widen it between rounds.
     registry.freeze()
     return GovernedLoop(
-        planner=PlannerNode(model, name="incident", catalog=registry.catalog()),
+        # The planner and the materializer get the recorder too. Without it the
+        # run's own trace held only `admission`/`round`/`stop`: no `plan` event
+        # saying what was proposed and what it cost, and — because the built
+        # subgraph inherits the materializer's recorder — no `start`/`end` pair
+        # for any node the loop actually executed. README's "the executed nodes'
+        # own start/end pairs" was true of a hand-wired loop and false of the
+        # shipped one, which is the one `grapharc plan` drives.
+        planner=PlannerNode(
+            model, name="incident", catalog=registry.catalog(), trace=trace
+        ),
         checker=AdmissionChecker(
             registry=registry,
             edge_policy=edge_policy or default_edge_policy(),
@@ -173,6 +182,7 @@ def build_loop(
             registry=registry,
             state_schema=state_schema or IncidentState,
             writes=writes if writes is not None else WRITES,
+            trace=trace,
         ),
         budget=budget,
         limits=limits,

grapharc/planner/loop.py

@@ -248,6 +248,10 @@ class _Execution(NamedTuple):
     materialization_error: str = ""
     execution_error: str = ""
     hard_stop: LoopStop | None = None
+    # The sub-run's iteration count, so the round can report what it spent.
+    # `_charge_back` folds this into the run's meter either way; carrying it here
+    # is what lets `RoundRecord.iterations` hold a figure instead of always 0.
+    iterations: int = 0
 
     @property
     def failure(self) -> str:
@@ -482,6 +486,7 @@ def close(**fields: Any) -> None:
                 execution_error=attempt.execution_error,
                 executed=attempt.executed,
                 progressed=progressed,
+                iterations=attempt.iterations,
             )
 
         if stop is None:
@@ -593,15 +598,22 @@ def _execute(
                 budget=budget,
             )
         except BudgetExceeded as exc:
-            self._charge_back(compiled, meter)
+            iterations = self._charge_back(compiled, meter)
             return _Execution(
-                state=state, execution_error=exc.reason, hard_stop=LoopStop.BUDGET_EXHAUSTED
+                state=state,
+                execution_error=exc.reason,
+                hard_stop=LoopStop.BUDGET_EXHAUSTED,
+                iterations=iterations,
             )
         except Exception as exc:  # noqa: BLE001 - a failed subgraph is a replanning input
-            self._charge_back(compiled, meter)
-            return _Execution(state=state, execution_error=f"raised {exc!r}")
-        self._charge_back(compiled, meter)
-        return _Execution(executed=True, state=self._initial_state(raw))
+            iterations = self._charge_back(compiled, meter)
+            return _Execution(
+                state=state, execution_error=f"raised {exc!r}", iterations=iterations
+            )
+        iterations = self._charge_back(compiled, meter)
+        return _Execution(
+            executed=True, state=self._initial_state(raw), iterations=iterations
+        )
 
     def _round_budget(self, meter: BudgetMeter) -> Budget:
         """This round's ceiling: exactly what the run has left, per dimension.
@@ -618,18 +630,21 @@ def _round_budget(self, meter: BudgetMeter) -> Budget:
         )
 
     @staticmethod
-    def _charge_back(compiled: Any, meter: BudgetMeter) -> None:
+    def _charge_back(compiled: Any, meter: BudgetMeter) -> int:
         """Fold the round's spend into the run's meter, whether or not it finished.
 
         The sub-run's meter is a separate accountant with its own ceiling; the
         loop's meter never saw those calls, so this charge is new spend rather
         than a re-report and is counted unnamed on purpose.
+
+        Returns the sub-run's iteration count, for the round to record.
         """
         sub = getattr(compiled, "last_run", None)
         if sub is None:
-            return
+            return 0
         meter.charge_tokens(sub.meter.tokens)
         meter.charge_iteration(sub.meter.iterations)
+        return sub.meter.iterations
 
     # -- recording ------------------------------------------------------------
 
@@ -648,8 +663,14 @@ def _record(
             ctx,
             node=f"{self.name}:round{record.round}",
             phase="round",
-            duration_ms=record.duration_ms,
-            tokens=record.tokens,
+            # No `tokens=` and no `duration_ms=`: a round is an *envelope*, not a
+            # measurement. Its tokens are the planner's, already reported by the
+            # `plan` event, and its duration encloses that plan plus every node
+            # the round executed. `metrics`, `cost` and `replay` sum node totals
+            # *plus* every event they cannot place inside a node — and `round` is
+            # one of those — so reporting either here counted the same spend
+            # twice. `RoundRecord` still carries both for callers reading the
+            # returned `LoopResult`; what changes is only what lands on the trace.
             state_delta={
                 "round": record.round,
                 "proposal_id": record.proposal.proposal_id if record.proposal else "",
@@ -660,6 +681,12 @@ def _record(
                 "executed": record.executed,
                 "progressed": record.progressed,
                 "stop": stop.value if stop is not None else "",
+                # The envelope's own figures, under names no reader sums. What a
+                # round spent stays answerable from the file; what it spent is
+                # just no longer added to the totals a second time.
+                "round_tokens": record.tokens,
+                "round_iterations": record.iterations,
+                "round_duration_ms": round(record.duration_ms, 2),
             },
             error=problem or None,
         )

tests/test_cli.py

@@ -1011,6 +1011,46 @@ def test_plan_runs_the_governed_loop_and_reports_every_round(tmp_path, capsys):
     assert "round 2: admitted" in out
 
 
+def test_plan_traces_the_plan_and_every_node_it_executed(tmp_path, capsys):
+    """README's "the trace holds an `admission` event per round, a `round` event
+    per round, the executed nodes' own `start`/`end` pairs and one `stop` event".
+
+    That was true of a hand-wired loop and false of the shipped registry, which is
+    the one this command drives: it withheld the recorder from the `PlannerNode`
+    and the `Materializer`, so the file held no `plan` event and — because the
+    built subgraph inherits the materializer's recorder — no `start`/`end` pair
+    for any node the loop ran. Three nodes executed and none of them appeared.
+    """
+    from grapharc.observe import cost, metrics
+    from grapharc.observe.trace import TraceRecorder
+
+    path = tmp_path / "t.jsonl"
+    code, payload, _ = call_json(["plan", "look into the outage", "--trace", str(path)], capsys)
+    assert code == 0
+
+    recorder = TraceRecorder(path)
+    events = recorder.read_events()
+    run_id = events[0].run_id
+    phases = {phase: 0 for phase in ("plan", "admission", "round", "start", "end", "stop")}
+    for event in events:
+        if event.phase in phases:
+            phases[event.phase] += 1
+
+    assert phases["plan"] == 2, "the planner's own event is missing"
+    assert phases["admission"] == 2
+    assert phases["round"] == 2
+    assert phases["stop"] == 1
+    # The admitted round ran three nodes; each owes a start/end pair.
+    assert phases["start"] == 3
+    assert phases["end"] == 3
+
+    summary = metrics.summarize(recorder, run_id)
+    assert summary.nodes_executed == 3
+    assert set(summary.per_node) == {"triage", "patch", "verify"}
+    # And the two readers of that one file still agree with each other.
+    assert cost.attribute(recorder, run_id).tokens == summary.tokens
+
+
 def test_plan_json_carries_the_rounds_and_the_stop_reason(tmp_path, capsys):
     code, payload, _ = call_json(
         ["plan", "look into the outage", "--trace", str(tmp_path / "t.jsonl")], capsys

tests/test_planner_loop.py

@@ -821,6 +821,64 @@ def test_a_run_plans_admits_executes_and_reaches_the_goal(trace):
     assert result.usage["tokens"] > 0
 
 
+def test_a_round_records_the_iterations_it_spent(trace):
+    """`RoundRecord.iterations` was declared and never assigned, so every round
+    reported 0 while the run's meter counted the same work."""
+    loop, _model, _bodies = build_loop(
+        [plan(("read", "fetch"), ("write", "summarise"))],
+        trace=trace,
+        goal_reached=goal_is_done,
+    )
+
+    result = loop.run("summarise the incident", LoopState())
+
+    assert [r.iterations for r in result.rounds] == [2]
+    assert sum(r.iterations for r in result.rounds) == result.usage["iterations"]
+
+
+def test_the_planners_tokens_are_counted_once_not_once_per_round(trace):
+    """A `round` event is an envelope, not a measurement.
+
+    Its tokens are the planner's, already reported by the `plan` event, and both
+    land in the set `metrics`/`cost` add on top of node totals — so the planner's
+    spend was charged to the report twice.
+    """
+    from grapharc.observe import cost, metrics
+
+    loop, _model, _bodies = build_loop(
+        [plan(("read", "fetch"), ("write", "summarise"))],
+        trace=trace,
+        goal_reached=goal_is_done,
+    )
+    result = loop.run("summarise the incident", LoopState(), run_id="r1")
+
+    real = result.usage["tokens"]
+    assert real > 0
+    assert metrics.summarize(trace, "r1").tokens == real
+    assert cost.attribute(trace, "r1").tokens == real
+
+
+def test_a_round_event_still_reports_what_the_round_itself_spent(trace):
+    """Removing the double count must not remove the information."""
+    loop, _model, _bodies = build_loop(
+        [plan(("read", "fetch"), ("write", "summarise"))],
+        trace=trace,
+        goal_reached=goal_is_done,
+    )
+    loop.run("summarise the incident", LoopState(), run_id="r1")
+
+    rounds = [e for e in trace.read_events("r1") if e.phase == "round"]
+    assert rounds, "the round event went missing"
+    for event in rounds:
+        # Not in the typed fields any reader sums...
+        assert event.tokens is None
+        assert event.duration_ms is None
+        # ...but still answerable from the file.
+        assert event.state_delta["round_tokens"] > 0
+        assert event.state_delta["round_iterations"] == 2
+        assert event.state_delta["round_duration_ms"] >= 0
+
+
 def test_a_rejection_reaches_the_planner_and_the_next_proposal_completes_the_run():
     """The replanning edge of ARCHITECTURE §2: rejected + reason -> propose again."""
     loop, model, bodies = build_loop(