diff --git a/CHANGELOG.md b/CHANGELOG.md index fb3226f..5e4a429 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,10 @@ and "used to be true" — the two things a reader most needs kept apart. Entries are newest-last within a release, matching the order they were written. +## Unreleased + +- a run **stopped for overspending reported spending nothing**. Tokens were attributed from `end` events, and a node the budget interrupts emits `error` instead — so `grapharc metrics` answered `tokens: 0` for a run whose own enforcement message named the figure that stopped it (`max_tokens reached (51/5)`). The audit trail lost precisely the number the stop was about, and per-node attribution dropped the most expensive node in the run. Every `error` event is now stamped with what its node spent, exactly as `end` is, and both `summarize` and the cost report count it; sub-events inside a node remain a breakdown of its total rather than an addition, so the disjointness that kept `ends + orphans` from double-counting is unchanged, and `RunCost.tokens == RunMetrics.tokens` still holds. + ## 0.1.3 - `grapharc plan` drives the governed loop; `PolicyEngine.edge_policy()` compiles the TOML document into the gate `AdmissionChecker` consults, and `grapharc plan --policy` is the caller; `grapharc demo --memory PATH` hands the shipped graphs the durable SQLite store. diff --git a/docs/cookbook/01-basics.md b/docs/cookbook/01-basics.md index c4f8861..28a0dc2 100644 --- a/docs/cookbook/01-basics.md +++ b/docs/cookbook/01-basics.md @@ -803,7 +803,7 @@ Output: {'attempt': 1, 'graph': 'counter', 'node': 'load', 'phase': 'start', 'step': 1} {'attempt': 1, 'graph': 'counter', 'node': 'load', 'phase': 'end', 'step': 1, 'state_delta': {'items': ['a', 'b', 'c']}, 'tokens': 0} {'attempt': 1, 'graph': 'counter', 'node': 'count', 'phase': 'start', 'step': 2} -{'attempt': 1, 'graph': 'counter', 'node': 'count', 'phase': 'error', 'step': 2, 'error': "ValueError('the counter is not implemented yet')"} +{'attempt': 1, 'graph': 'counter', 'node': 'count', 'phase': 'error', 'step': 2, 'tokens': 0, 'error': "ValueError('the counter is not implemented yet')"} ``` The four fields the snippet filtered out are on every line too: `ts` (ISO-8601 UTC), @@ -823,8 +823,12 @@ So, by phase: node never returns. - **`end`** adds `state_delta` (exactly the validated update that was applied), `duration_ms`, and `tokens` charged during that node. -- **`error`** adds `duration_ms` and `error` — `repr()` of the exception, so the type - is preserved. There is no `state_delta`, because a node that raised wrote nothing. +- **`error`** adds `duration_ms`, `error` — `repr()` of the exception, so the type is + preserved — and `tokens`, the spend charged during that node before it failed. + There is no `state_delta`, because a node that raised wrote nothing. The token + count is there for the same reason `end` carries one: a run stopped *for* + overspending used to report having spent nothing, because the only number the + audit trail read was on the event an interrupted node never writes. **Why it works this way.** `start` and `end` share a step number; the pair is the node execution. That means step numbers do not order the file — read events in file diff --git a/grapharc/observe/metrics.py b/grapharc/observe/metrics.py index c33e92b..ddafb35 100644 --- a/grapharc/observe/metrics.py +++ b/grapharc/observe/metrics.py @@ -53,7 +53,14 @@ def summarize(recorder: TraceRecorder, run_id: str) -> RunMetrics | None: # Work the reconstruction could not place inside any node. Disjoint from # `ends` by construction, so adding it cannot double-count a node total. orphans = replay(recorder, run_id).orphan_sub_events - measured = [*ends, *orphans] + # `errors` are measured too, and for the same reason `ends` are: the kernel + # stamps a node's terminal event with what that node spent, whichever way it + # ended. Counting only `end` meant a run *stopped for overspending* reported + # `tokens: 0` — the audit trail losing precisely the spend that triggered + # enforcement. Sub-events inside a node are a breakdown of its total rather + # than an addition to it, so the disjointness that makes `ends + orphans` + # safe holds here unchanged. + measured = [*ends, *errors, *orphans] reason = None # Scanned across every event, not just `end`: an agent writes its # `termination_reason` on a `stop` event, and that is still why it stopped. diff --git a/grapharc/observe/replay.py b/grapharc/observe/replay.py index 90efe3f..e347b6c 100644 --- a/grapharc/observe/replay.py +++ b/grapharc/observe/replay.py @@ -136,8 +136,12 @@ def tokens(self) -> int: token it spent in `orphan_sub_events`, and reporting zero for it was the audit trail contradicting itself. The two sets are disjoint, so nothing is counted twice. + + A node that *failed* counts too. Its terminal `error` event carries what + it spent, exactly as an `end` does, so excluding it here reported zero + tokens for a run the budget stopped for spending too many. """ - return sum(e.tokens for e in self.executions if e.ok) + sum( + return sum(e.tokens for e in self.executions) + sum( e.tokens or 0 for e in self.orphan_sub_events ) diff --git a/grapharc/runtime/graph.py b/grapharc/runtime/graph.py index 71708c0..dd1e984 100644 --- a/grapharc/runtime/graph.py +++ b/grapharc/runtime/graph.py @@ -710,7 +710,12 @@ def _leave( try: result, delta = self._check_result(f"node {name!r}", writes, result) except (WritePermissionError, StateTypeError, GraphRoutingError) as err: - emit("error", duration_ms=duration_ms, error=str(err)) + emit( + "error", + duration_ms=duration_ms, + error=str(err), + tokens=ctx.meter.tokens - tokens_before, + ) raise # Tokens are charged mid-node by the usage callback, so this is the @@ -718,7 +723,16 @@ def _leave( try: ctx.meter.check_tokens() except BudgetExceeded as exc: - emit("error", duration_ms=duration_ms, error=f"budget: {exc.reason}") + # Stamped with what the node spent, exactly as `end` is. Without it + # the run stopped *for overspending* and then reported spending + # nothing, which is the audit trail losing the one number the stop + # was about. + emit( + "error", + duration_ms=duration_ms, + error=f"budget: {exc.reason}", + tokens=ctx.meter.tokens - tokens_before, + ) raise # The provider's own price for every model call made inside this node, @@ -765,8 +779,14 @@ async def awrapped(state: Any, config: RunnableConfig) -> Any: except BaseException as exc: # BaseException, not Exception: an async node is stopped by # cancellation, which is not an Exception, and a stop with no - # trace line is a stop nobody can audit afterwards. - emit("error", duration_ms=(time.perf_counter() - t0) * 1000, error=repr(exc)) + # trace line is a stop nobody can audit afterwards. Carries + # the node's spend for the same reason `end` does. + emit( + "error", + duration_ms=(time.perf_counter() - t0) * 1000, + error=repr(exc), + tokens=ctx.meter.tokens - tokens_before, + ) raise return self._leave( name, @@ -800,7 +820,12 @@ def wrapped(state: Any, config: RunnableConfig) -> Any: # ^C, which is a KeyboardInterrupt and not an Exception, and a # stop with no trace line is a stop nobody can audit afterwards. # The exception is re-raised untouched; only the record is new. - emit("error", duration_ms=(time.perf_counter() - t0) * 1000, error=repr(exc)) + emit( + "error", + duration_ms=(time.perf_counter() - t0) * 1000, + error=repr(exc), + tokens=ctx.meter.tokens - tokens_before, + ) raise return self._leave( name, diff --git a/tests/test_budget_enforcement.py b/tests/test_budget_enforcement.py index 55dcc44..ae15770 100644 --- a/tests/test_budget_enforcement.py +++ b/tests/test_budget_enforcement.py @@ -665,3 +665,43 @@ def slow(state): def test_a_deadline_exceeded_is_a_budget_exceeded(): """Callers that already catch BudgetExceeded must keep catching timeouts.""" assert issubclass(NodeDeadlineExceeded, BudgetExceeded) + + +def test_a_run_stopped_for_overspending_reports_what_it_spent(tmp_path): + """The audit trail must not lose the spend the stop was about. + + Tokens were attributed on `end` events only, and an interrupted node emits + `error` instead — so a run killed *for* exceeding `max_tokens` reported + `tokens: 0`, contradicting the enforcement message that named the figure. + """ + import json + + from grapharc.observe.metrics import summarize + from grapharc.observe.replay import replay + from grapharc.observe.trace import TraceRecorder + + class State(GraphARCState): + out: str = "" + + def spend(state: State) -> dict: + model = ScriptedChatModel(responses=["x" * 200], on_exhausted="repeat") + return {"out": str(model.invoke("hi").content)[:10]} + + trace = TraceRecorder(tmp_path / "t.jsonl") + g = GraphARC(State, name="overspend", trace=trace, budget=Budget(max_tokens=5)) + g.add_node("spend", spend, writes={"out"}) + g.add_edge(START, "spend") + g.add_edge("spend", END) + + with pytest.raises(BudgetExceeded) as caught: + g.compile().invoke({}) + + spent = int(str(caught.value).split("(")[1].split("/")[0]) + assert spent > 0, "the meter charged something, or this test proves nothing" + + run_id = json.loads((tmp_path / "t.jsonl").read_text().splitlines()[0])["run_id"] + metrics = summarize(trace, run_id) + assert metrics.tokens == spent, "the audit trail must agree with the enforcement" + assert metrics.errors == 1 + # The cost report and the audit trail must never disagree. + assert replay(trace, run_id).tokens == metrics.tokens diff --git a/tests/test_cookbook_basics.py b/tests/test_cookbook_basics.py index 52783aa..9d4e536 100644 --- a/tests/test_cookbook_basics.py +++ b/tests/test_cookbook_basics.py @@ -565,6 +565,7 @@ def count(state: State) -> dict: "node": "count", "phase": "error", "step": 2, + "tokens": 0, "error": "ValueError('the counter is not implemented yet')", }, ]