Skip to content

Fix four metering/tracing defects, and colour the CLI without changing piped output - #11

Merged
Shashankss1205 merged 8 commits into
mainfrom
fix/metering-tracing-and-cli-polish
Jul 30, 2026
Merged

Fix four metering/tracing defects, and colour the CLI without changing piped output#11
Shashankss1205 merged 8 commits into
mainfrom
fix/metering-tracing-and-cli-polish

Conversation

@Shashankss1205

Copy link
Copy Markdown
Collaborator

Four defects in metering and tracing, three earlier runtime fixes, and a CLI restyle that provably does not change piped output.

1552 passed, 12 deselected, 0 failed · ruff check . clean · all 8 demo stages + plan + models green.

What was wrong

Each of these was reproduced before being fixed, and each now has a test that fails without the fix — confirmed by stashing the source and watching it go red.

Defect Cost while open
Unreachable max_seconds poisoned the deadline guard setitimer raised after the SIGALRM handler and process-wide slot were taken, leaking both. A 0.3s ceiling was honoured at 0.30s, then at 5.00s for the rest of the process — falling back to the mechanism that cannot unwind a blocking syscall
Every async def node double-charged token re-reports Ledger keyed by thread ident, but on_llm_end is sync and runs on a worker thread under ainvoke. Nodes reported double their real spend and hit max_tokens at half their allowance
A bracket in model prose hijacked JSON extraction Analysis (note [1]): {"supported": false} returned a valid [1] — a fabricated value substituted for the verifier's actual answer
Fan-out inflated per-node tokens Workers absorbed siblings' concurrent spend: 3 workers × 8 tokens traced as 24/16/8, and metrics/cost reported 48 for 24 tokens — doubling the estimated bill purely for running in parallel
grapharc plan trace was missing most of itself Shipped registry withheld the recorder from PlannerNode and Materializer: no plan event and no start/end pair for any executed node. Three nodes ran; none appeared
Planner spend counted twice The round event repeated the plan event's tokens, and both are summed on top of node totals. Meter 1979, metrics 2558
RoundRecord.iterations always 0 Declared and never assigned; _charge_back read the figure and discarded it

The shipped plan trace went from {admission: 2, round: 2, stop: 1} to {plan: 2, admission: 2, round: 2, start: 3, end: 3, stop: 1}.

A round is now treated as an envelope, not a measurement — its figures moved to 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 double-counted.

CLI

Colour hierarchy on a terminal; byte-identical output when piped. Styling is decided at print time from the stream's own isatty(), which is why no expected block needed touching — tests/test_readme.py and tests/test_cookbook_models.py byte-compare CLI output against the docs, and both harnesses present a non-tty stdout.

Verified: 50/36/32/18 escapes on a pty for plan/models/models --check/demo; zero on every piped stream; ANSI-stripped tty output identical to piped output. NO_COLOR, TERM=dumb, --no-color and --json each yield zero escapes.

Contracts re-checked by hand: --json is one parseable document with 0-byte stderr; a text-mode failure leaves stdout empty with error: … on stderr; viz stays raw pasteable Mermaid; replay/diff emit only the engine formatter's text.

New grapharc/cli/style.py is stdlib only — no dependency added, since rich is not in the lock and the README markets a four-package runtime dep list. No glyphs, boxes or rules even on a terminal, deliberately: README and two cookbook pages print these blocks verbatim, so tty-only decoration would make what a user sees diverge from what the docs show.

Also included

Known gap

The natural regression test for the CLI work — escape-stripped tty output equals piped output — is proven ad-hoc but not committed. Without it, a future change could leak an escape into piped output and no test would catch it. Worth adding before or shortly after merge.

🤖 Generated with Claude Code

Shashankss1205 and others added 8 commits July 30, 2026 04:42
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>
…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>
Human-mode output gains a Claude-Code-style colour hierarchy: dim labels,
accented names and paths, semantic status colour (goal_met and admitted
green, rejected and REFUSED red), and aligned key/value blocks.

The whole design rests on one constraint: styling is decided at print time
from the stream's own isatty(), so piped, redirected and captured output is
byte-identical to before. That is what lets this land without touching a
single expected block — tests/test_readme.py and tests/test_cookbook_models.py
byte-compare CLI output against README.md and docs/cookbook/02-models.md, and
both harnesses present a non-tty stdout. Padding is emitted outside the
escape sequences, so a column is the same character count either way.

Verified: 50/36/32/18 escapes on a pty for plan/models/models --check/demo,
zero escapes on every piped stream, and ANSI-stripped tty output identical to
piped output. NO_COLOR, TERM=dumb, --no-color and --json each yield zero
escapes. The contracts that matter are unchanged — --json is one parseable
document on stdout with zero-byte stderr, a text-mode failure leaves stdout
empty with "error: ..." on stderr, viz stays raw pasteable Mermaid, and
replay/diff still emit only the engine formatter's text.

New grapharc/cli/style.py is stdlib only. No dependency was added: rich is
not in the lock, and the README markets a four-package runtime dep list.

Deliberately no glyphs, boxes or rules, even on a terminal. README and two
cookbook pages print these blocks verbatim, so tty-only decoration would
make what a user sees diverge from what the docs show — drift in the one
direction the byte-comparison tests cannot catch.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The status section now states each defect that was closed and what it cost
while open, in the same register as the rest of the page: the poisoned
deadline guard, the async double-charge, the prose-bracket parser, the
fan-out attribution, and the round event that was a measurement when it
should have been an envelope.

.github/ISSUE_TEMPLATE/task.md fixes the seven-section shape used by the ten
issues opened against this repo, so every future issue arrives with a summary,
why it matters, where in the code with a command to confirm it, what to change,
how to verify, acceptance criteria, and an explicit skill level. It also states
the house rule out loud: a change arrives with a test that fails without it,
checked by reverting the source and watching the test go red.

uv.lock is a stale-lock refresh, not a dependency change: pyproject already
said 0.1.1 while the lock still said 0.1.0a0.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
tests/test_cli_style.py asserts the property the byte-compared doc pages
quietly depend on: strip the escapes from what a terminal receives and it must
equal what a pipe receives, exactly. Both directions are covered, and both were
checked by mutation rather than assumed.

Making enabled() ignore isatty() and always paint leaks colour into pipes; 8 of
these tests catch it. The three doc-comparison tests catch that too, for the
three commands they pin — but they cannot see `models --check`, `demo`, `viz` or
the error path, and they compare only piped output, so a tty-only change to
spacing or line count would pass them while making README describe output no
user sees.

The complementary mutation is the one nothing else caught. Making enabled()
always return False — styling silently never happening at all — leaves 124
tests in test_readme, test_cookbook_models and test_cli passing, because every
one of them observes a non-tty stream. Only the "a terminal received no styling
at all" assertion fails. Without it the feature could rot to a no-op invisibly.

The pty is read with both stdout and stderr on one descriptor, which is the
shape a person sees and also catches an escape written to stderr while stdout
happens to be a terminal. The parent's NO_COLOR and FORCE_COLOR are stripped so
a developer's own environment cannot decide what the test proves.

README's policy paragraph claimed nothing in the package imports
grapharc.policy. That has not been true since `grapharc plan --policy` landed:
cli/plan.py and cli/generate.py both call PolicyEngine.edge_policy(), so the
edge half is governed by a document you can read. The tool half is not —
permission_policy(), check_tool() and approval_router() have no caller outside
grapharc/policy/, so `grapharc agent` still builds its gating from
--allow/--deny/--ask globs. The paragraph now says which half, and points at the
issue tracking the rest.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`models --check` exits 1 on a machine that can reach no real provider,
which is what CI is. The styling contract is that a terminal does not
change the answer, so assert pty and piped exit codes agree instead of
pinning 0, and byte-compare only the commands whose output is
reproducible across two invocations.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@Shashankss1205
Shashankss1205 merged commit 5c9a62a into main Jul 30, 2026
12 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant