Skip to content

Commit 82900ed

Browse files
Fix three runtime defects that silently corrupted metering and parsing
An unreachable max_seconds poisoned the deadline guard process-wide. setitimer raises OverflowError past the platform's time_t, and it raises *after* the SIGALRM handler is installed and the process-wide slot taken — both were left that way, so every later guard found the slot held and fell back to the async-exception mechanism, which cannot unwind a blocking syscall. Measured: a 0.3s ceiling honoured at 0.30s, then at 5.00s after a single 1e10 run. Arming is undone on failure now, and the armed delay is clamped to what both mechanisms accept. Every async def node double-charged its token re-reports. The re-report ledger was keyed by threading.get_ident(), but on_llm_end is sync, so under ainvoke LangChain dispatches it to a worker thread while the body stays on the event loop. The automatic charge found no ledger, never recorded the call, and the node's named re-report — the documented free path — was charged again. Any node using charge_usage, AgentNode._charge_tokens or planner.proposal._charge reported double its real spend and hit max_tokens at half its declared allowance. The ledger is a contextvars scope now, verified to propagate across that hop; nesting also stops discarding the enclosing node's ledger. A bracket in the model's prose hijacked JSON extraction, because only the first { or [ was ever tried. "Based on the context [lines 3-5]: {...}" was rejected as unparseable, and — worse — 'Analysis (note [1]): {"supported": false}' returned a valid [1], substituting a fabricated value for the verifier's actual answer. Every opener is tried now and the longest parse wins, which also prefers a complete structure over a nested fragment. Junk still returns None, so the caller's fail-closed path is unchanged. A node's end event also reported the movement of the run's *shared* meter rather than its own spend, so overlapping fan-out workers each absorbed their siblings' concurrent charges: three workers costing 8 tokens each traced as 24/16/8, and metrics and cost both reported 48 for 24 tokens of real work, doubling the estimated bill purely because the work ran in parallel. Attribution now comes from a per-node scope on the meter. Each fix ships a test that fails without it, confirmed by stashing the source and watching them go red. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 241b272 commit 82900ed

7 files changed

Lines changed: 395 additions & 37 deletions

File tree

grapharc/runtime/budget.py

Lines changed: 126 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -13,11 +13,12 @@
1313

1414
from __future__ import annotations
1515

16+
import contextvars
1617
import ctypes
1718
import signal
1819
import threading
1920
import time
20-
from collections.abc import Iterator
21+
from collections.abc import Callable, Iterator
2122
from contextlib import contextmanager
2223
from typing import Any
2324

@@ -71,7 +72,7 @@ def _call_key(source: Any) -> Any:
7172

7273

7374
class _MeteredCalls:
74-
"""The model calls the usage callback charged on one thread, by identity.
75+
"""The model calls the usage callback charged in one node scope, by identity.
7576
7677
Not a count of tokens: a re-report is recognised because it names the same
7778
call, never because it happens to be the same number of tokens.
@@ -101,6 +102,30 @@ def claim(self, source: Any) -> bool:
101102
return True
102103

103104

105+
class _NodeScope:
106+
"""One node execution's re-report ledger and its own share of the spend.
107+
108+
`tokens` exists because the run's meter is shared: subtracting a
109+
before/after reading off it attributed every *sibling's* concurrent spend to
110+
whichever fan-out worker happened to be running at the time. This counts only
111+
the charges made inside this scope, so the same work costs the same whether
112+
it runs in parallel or one at a time.
113+
"""
114+
115+
__slots__ = ("ledger", "tokens")
116+
117+
def __init__(self) -> None:
118+
self.ledger = _MeteredCalls()
119+
self.tokens = 0
120+
121+
122+
# The node scope a re-report may claim a metered call from, as (meter, scope).
123+
# Context-scoped rather than thread-scoped: see `BudgetMeter.automatic_scope`.
124+
_METERED_SCOPE: contextvars.ContextVar[tuple[Any, _NodeScope] | None] = (
125+
contextvars.ContextVar("grapharc_metered_scope", default=None)
126+
)
127+
128+
104129
class BudgetMeter:
105130
"""Thread-safe per-run usage accountant.
106131
@@ -116,7 +141,6 @@ def __init__(self, budget: Budget) -> None:
116141
self._iterations = 0
117142
self._tokens = 0
118143
self._started_at = time.monotonic()
119-
self._metered: dict[int, _MeteredCalls] = {}
120144

121145
def charge_iteration(self, n: int = 1) -> None:
122146
with self._lock:
@@ -142,39 +166,80 @@ def charge_tokens(self, n: int, *, automatic: bool = False, source: Any = None)
142166
run early and is visible in `snapshot()`; under-reporting is invisible
143167
and arrives on the bill. Pass `source=` to be exact.
144168
145-
Two shipped callers still charge an unnamed integer for a call the
146-
callback already metered — `grapharc.testing.charge_usage` and
147-
`AgentNode._charge_tokens` — so a node using either pays twice. Both
148-
hold the message: `charge_tokens(total, source=message)` fixes them, and
149-
keeps working when they run outside a graph, where nothing metered the
150-
call and the charge must land.
169+
All three shipped re-reporters now name their source — `testing.
170+
charge_usage`, `AgentNode._charge_tokens` and `planner.proposal._charge`
171+
each pass `source=message` — so none of them pays twice, and each still
172+
works outside a graph, where nothing metered the call and the charge must
173+
land.
174+
175+
What the source is matched against is a *node scope*, not a thread; see
176+
`automatic_scope` for why that distinction was load-bearing.
151177
"""
152178
with self._lock:
153-
metered = self._metered.get(threading.get_ident())
179+
scope = self._current_scope()
154180
if automatic:
155181
self._tokens += n
156-
if metered is not None and source is not None:
157-
metered.record(source)
182+
self._attribute(scope, n)
183+
if scope is not None and source is not None:
184+
scope.ledger.record(source)
158185
return
159-
if source is not None and metered is not None and metered.claim(source):
186+
if source is not None and scope is not None and scope.ledger.claim(source):
160187
return
161188
self._tokens += n
189+
self._attribute(scope, n)
190+
191+
@staticmethod
192+
def _attribute(scope: _NodeScope | None, n: int) -> None:
193+
"""Credit `n` to the node scope that spent it. Only charges that actually
194+
landed on the run total get here, so a dropped re-report is not counted."""
195+
if scope is not None:
196+
scope.tokens += n
197+
198+
def _current_scope(self) -> _NodeScope | None:
199+
"""This node execution's scope, or None outside any. Caller holds the lock."""
200+
entry = _METERED_SCOPE.get()
201+
# The meter is part of the key so a scope opened by one meter — the
202+
# planner runs a sub-meter inside the run's — cannot lend its scope to
203+
# a charge made against another.
204+
return entry[1] if entry is not None and entry[0] is self else None
205+
206+
def scope_tokens(self) -> int | None:
207+
"""Tokens charged inside the current node scope, or None outside one.
208+
209+
What a single node execution actually spent, as opposed to how the run's
210+
shared total moved while it happened to be running.
211+
"""
212+
with self._lock:
213+
scope = self._current_scope()
214+
return None if scope is None else scope.tokens
162215

163216
@contextmanager
164217
def automatic_scope(self) -> Iterator[None]:
165218
"""Bound the window in which a metered call may be re-reported for free.
166219
167-
Scoped per thread and opened once per node, so a re-report in one node
168-
can never claim a call metered by another.
220+
Scoped to the calling *context* and opened once per node, so a re-report
221+
in one node can never claim a call metered by another.
222+
223+
A `contextvars` scope rather than a thread-keyed one, because the runtime's
224+
usage callback does not always run on the thread the node body runs on.
225+
`on_llm_end` is sync, so under `ainvoke`/`astream` LangChain dispatches it
226+
to a worker thread while the body stays on the event loop. Keyed by thread
227+
ident, the automatic charge then found no ledger, never recorded the call,
228+
and the node's *named* re-report — the documented free path — was charged a
229+
second time: every `async def` node using `charge_usage`, `AgentNode.
230+
_charge_tokens` or `planner.proposal._charge` reported double its real
231+
spend and hit `max_tokens` at half its declared allowance. LangChain copies
232+
the context across that hop, so the callback and the body share one ledger.
233+
234+
Contexts also nest properly. `reset(token)` restores an enclosing scope's
235+
ledger, where popping a thread-keyed entry discarded it — so an inner scope
236+
used to make the outer node's remaining re-reports pay twice.
169237
"""
170-
ident = threading.get_ident()
171-
with self._lock:
172-
self._metered[ident] = _MeteredCalls()
238+
token = _METERED_SCOPE.set((self, _NodeScope()))
173239
try:
174240
yield
175241
finally:
176-
with self._lock:
177-
self._metered.pop(ident, None)
242+
_METERED_SCOPE.reset(token)
178243

179244
@property
180245
def iterations(self) -> int:
@@ -255,6 +320,15 @@ def snapshot(self) -> dict[str, float | int]:
255320
# node alive; the cost while a node is being torn down is one timer per 50ms.
256321
_REARM_SECONDS = 0.05
257322

323+
# The longest delay both mechanisms can actually be armed with. `setitimer`
324+
# raises `OverflowError` past the platform's `time_t` (~2**31 seconds), and
325+
# `threading.Timer` accepts a larger value but crashes its own thread once the
326+
# underlying `wait` exceeds `threading.TIMEOUT_MAX`. A `max_seconds` beyond this
327+
# is ~68 years, which no process reaches, so clamping the *armed delay* costs no
328+
# enforcement: the deadline is still computed from the meter, and the guard's
329+
# exit-time check still refuses a node that overran.
330+
_MAX_ARMABLE_SECONDS = min(2.0**31 - 1, threading.TIMEOUT_MAX)
331+
258332

259333
def _async_raise(thread_id: int, exc: type[BaseException] | None) -> None:
260334
"""Queue `exc` in another thread, or clear a queued one when `exc` is None."""
@@ -329,18 +403,29 @@ def detail() -> str:
329403
state: dict[str, Any] = {"armed": True, "fired": False, "timer": None}
330404
lock = threading.Lock()
331405
thread_id = threading.get_ident()
332-
use_signal = _signal_slot_available() and _SIGNAL_SLOT.acquire(blocking=False)
333-
334-
if use_signal:
406+
# What the timers are armed with, as opposed to what the deadline *is*.
407+
armable = min(remaining, _MAX_ARMABLE_SECONDS)
408+
409+
def arm_signal() -> Callable[[], None] | None:
410+
"""Arm SIGALRM and return its disarm, or return None to use mechanism 2.
411+
412+
Arming is undone on failure rather than left half-done. `setitimer`
413+
rejects a `remaining` beyond the platform's `time_t` — `float("inf")`,
414+
or a plausible "effectively unlimited" like `1e10` — and it raises
415+
*after* the handler is installed and the slot is taken. Letting that
416+
propagate leaked both for the life of the process: every later guard
417+
found the slot held and silently degraded to mechanism 2, which cannot
418+
unwind a blocking syscall, and a stray SIGALRM anywhere in the program
419+
would raise `NodeDeadlineExceeded` citing a finished run's meter.
420+
"""
421+
if not (_signal_slot_available() and _SIGNAL_SLOT.acquire(blocking=False)):
422+
return None
335423

336424
def on_alarm(signum: int, frame: object) -> None:
337425
state["fired"] = True
338426
raise NodeDeadlineExceeded(detail())
339427

340428
previous_handler = signal.signal(signal.SIGALRM, on_alarm)
341-
# The third argument is the repeat interval: the kernel re-arms the
342-
# alarm for us, so a swallowed SIGALRM is followed by another one.
343-
signal.setitimer(signal.ITIMER_REAL, remaining, _REARM_SECONDS)
344429

345430
def disarm() -> None:
346431
# An alarm landing mid-disarm raises out of `setitimer`, so the
@@ -350,6 +435,20 @@ def disarm() -> None:
350435
finally:
351436
signal.signal(signal.SIGALRM, previous_handler)
352437
_SIGNAL_SLOT.release()
438+
439+
try:
440+
# The third argument is the repeat interval: the kernel re-arms the
441+
# alarm for us, so a swallowed SIGALRM is followed by another one.
442+
signal.setitimer(signal.ITIMER_REAL, armable, _REARM_SECONDS)
443+
except (OverflowError, OSError, ValueError):
444+
disarm()
445+
return None
446+
return disarm
447+
448+
disarm_signal = arm_signal()
449+
450+
if disarm_signal is not None:
451+
disarm = disarm_signal
353452
else:
354453

355454
def fire() -> None:
@@ -371,7 +470,7 @@ def rearm(delay: float) -> None:
371470
timer.start()
372471

373472
with lock:
374-
rearm(remaining)
473+
rearm(armable)
375474

376475
def disarm() -> None:
377476
with lock:

grapharc/runtime/graph.py

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -657,11 +657,20 @@ def _leave(
657657
# one, so `observe.cost` can keep a measured figure apart from a
658658
# rate-card estimate instead of recording a guess as a fact.
659659
models = getattr(usage, "models", ())
660+
# This node's own spend, from the meter's per-node scope, not the movement
661+
# of the run's shared total while the node ran. Under fan-out those differ:
662+
# the workers' windows overlap, so every worker used to be credited with
663+
# each sibling's concurrent spend — three workers costing 8 tokens each
664+
# traced as 24/16/8, and `metrics` and `cost` both reported 48 for 24
665+
# tokens of real work, doubling the estimated bill purely because the work
666+
# ran in parallel. Falls back to the difference when no scope was open, so
667+
# a caller driving `_leave` outside `charging()` still gets a figure.
668+
spent = getattr(usage, "tokens", None)
660669
emit(
661670
"end",
662671
state_delta=delta,
663672
duration_ms=duration_ms,
664-
tokens=ctx.meter.tokens - tokens_before,
673+
tokens=ctx.meter.tokens - tokens_before if spent is None else spent,
665674
cost_usd=getattr(usage, "cost_usd", None),
666675
model=models[0] if len(models) == 1 else None,
667676
)

grapharc/runtime/parsing.py

Lines changed: 29 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -21,11 +21,8 @@
2121
_FENCE = re.compile(r"```(?:json|JSON)?\s*(.*?)```", re.DOTALL)
2222

2323

24-
def _balanced_span(text: str) -> str | None:
25-
"""The first balanced {...} or [...] region, ignoring braces inside strings."""
26-
start = next((i for i, ch in enumerate(text) if ch in "{["), None)
27-
if start is None:
28-
return None
24+
def _span_from(text: str, start: int) -> str | None:
25+
"""The balanced {...} or [...] region opening at `start`, or None if unclosed."""
2926
opener = text[start]
3027
closer = "}" if opener == "{" else "]"
3128
depth = 0
@@ -52,20 +49,44 @@ def _balanced_span(text: str) -> str | None:
5249
return None
5350

5451

52+
def _balanced_spans(text: str) -> list[str]:
53+
"""Every balanced {...} or [...] region, longest first.
54+
55+
Every opener is tried, not just the first one in the text. Taking only the
56+
first meant any bracket in the model's *prose* hijacked the span and the real
57+
JSON was never reached: `Based on the context [lines 3-5]: {...}` yielded the
58+
unparseable `[lines 3-5]` and the reply was rejected, and — worse —
59+
`Analysis (note [1]): {"supported": false}` yielded a perfectly valid `[1]`,
60+
substituting a fabricated value for the model's actual answer.
61+
62+
Longest first is what makes the ranking safe. It prefers a complete structure
63+
over both a prose fragment that happens to parse and a nested piece of the
64+
answer itself, so `{"claims": [{...}]}` returns the whole object rather than
65+
the inner list.
66+
"""
67+
spans = [
68+
span
69+
for i, ch in enumerate(text)
70+
if ch in "{[" and (span := _span_from(text, i)) is not None
71+
]
72+
return sorted(spans, key=len, reverse=True)
73+
74+
5575
def extract_json(content: Any) -> Any | None:
5676
"""Best-effort JSON from a model reply. None when nothing valid is found."""
5777
text = content if isinstance(content, str) else str(content)
5878
text = text.strip()
5979
if not text:
6080
return None
6181

82+
# Whole reply first, then the fence, then balanced spans: the earlier a
83+
# candidate is, the more of the model's reply it accounts for, so a fenced
84+
# top-level array still wins over any span found inside it.
6285
candidates = [text]
6386
fenced = _FENCE.search(text)
6487
if fenced:
6588
candidates.append(fenced.group(1).strip())
66-
span = _balanced_span(text)
67-
if span:
68-
candidates.append(span)
89+
candidates.extend(_balanced_spans(text))
6990

7091
for candidate in candidates:
7192
try:

grapharc/runtime/usage.py

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,11 @@ def __init__(self, meter: BudgetMeter) -> None:
7676
# `observe.cost` keeps recorded and estimated figures apart.
7777
self.cost_usd: float | None = None
7878
self.models: list[str] = []
79+
# This node execution's own token spend, stamped by `charging` when the
80+
# scope closes. Read from the meter's node scope rather than differenced
81+
# off the run total, which credited a fan-out worker with whatever its
82+
# siblings spent while it was running.
83+
self.tokens = 0
7984

8085
def _record_price(self, response: LLMResult) -> None:
8186
"""Accumulate the price a backend reported through `llm_output`.
@@ -129,12 +134,19 @@ def charging(meter: BudgetMeter) -> Iterator[MeterCallbackHandler]:
129134
130135
Also opens the meter's automatic scope, so a call metered here can be
131136
re-reported by hand inside this block — and only inside it.
137+
138+
On the way out it stamps the scope's token tally onto the handler. Callers
139+
read `handler.tokens` after the block has closed — the node wrapper reports
140+
it on the node's `end` event — and by then the scope itself is gone.
132141
"""
133142
handler = MeterCallbackHandler(meter)
134143
token = _ACTIVE_HANDLER.set(handler)
135144
try:
136145
with meter.automatic_scope():
137-
yield handler
146+
try:
147+
yield handler
148+
finally:
149+
handler.tokens = meter.scope_tokens() or 0
138150
finally:
139151
_ACTIVE_HANDLER.reset(token)
140152

0 commit comments

Comments
 (0)