fix(claude-action): account a cancelled session from its session JSONL - #873
fix(claude-action): account a cancelled session from its session JSONL#873tend-agent wants to merge 7 commits into
Conversation
A cancelled run never emits a `type: "result"` event, and the Token usage step fell through to hardcoded zeros — so a run that did dozens of turns, and may already have posted its review, reported turns=0, output_tokens=0, $0.00. tend-review runs with cancel-in-progress: true, so this biases every downstream total by the cancellation rate. Reconstruct from the session JSONL the step has already consolidated into LOGS_DIR: dedup assistant messages by .message.id and sum their usage. On five real sessions this reproduces the result event's four token fields and num_turns exactly. Read the session JSONL rather than the stream-json, even though both carry type:"assistant" events. The stream-json's are non-final (stop_reason: null), so usage.output_tokens is the message-start placeholder — single digits against thousands — while input and cache fields do match. Summing those would under-count output by orders of magnitude and look plausible doing it. cost_usd is null on this path (only the result event carries it) and a new partial flag marks the reconstruction, so a cancelled run is distinguishable from one that genuinely cost nothing. token-report.sh counts partial runs and labels its cost total a floor. Closes #871
tend-agent
left a comment
There was a problem hiding this comment.
The reconstruction is sound and I reproduced the parity claim independently — stripping the result event from run 31086697446's stream-json, the fallback returns in 23, out 9406, cc 62655, cr 789006, turns 14, identical to the uploaded token-usage.json. One defect, though, which the five-artifact validation missed because none of those sessions used a subagent.
find "$LOGS_DIR" -name '*.jsonl' also sweeps in the subagent transcripts. Claude Code writes each Task subagent to its own file at <project-dir>/<session-id>/subagents/agent-*.jsonl, and cp -a "${AGENT_HOME}/.claude/projects/." copies that subtree into LOGS_DIR before the script runs. jq -s then concatenates them with the main session, so every field is summed across main + subagents — while the result event the fallback is meant to reproduce counts only the main loop. Partial runs come out systematically inflated, which is the same bias the PR is removing, just pointing the other way, and review-runs compares windows across a mix of both.
Measured on the five artifacts from run 31085980872 (four of the five used a subagent), against each one's real result event:
current vs. -not -path '*/subagents/*', per artifact
| Artifact | subagent files | result truth |
current | with the filter |
|---|---|---|---|---|
0801511f |
0 | cr 929081, turns 21 |
identical | identical |
1036604a |
1 | in 45, cr 2329226, turns 35 |
in 335, cr 3275484, turns 71 |
identical |
6b47f9f6 |
1 | in 28, cr 1257813, turns 23 |
in 198, cr 1923032, turns 63 |
identical |
b7c8bde7 |
1 | in 49, cc 88041, cr 2497878, turns 34 |
in 195, cc 127174, cr 3113453, turns 52 |
identical |
cdcbac03 |
1 | in 62, cr 3537381, turns 44 |
in 376, cr 4817836, turns 83 |
identical |
turns roughly doubles and cache_read_input_tokens runs 25–40% high; with the filter all five match the result event exactly, including the ones that already matched.
Worth extending _session_jsonl to drop a second file under <session>/subagents/ — that shape is what the fixture is missing, and it's why test_token_usage_reconstructs_a_cancelled_session passes today.
Separately, token-report.sh marks partial runs only in the totals footnote — the per-run and per-workflow rows still render a reconstructed run's cost as $0.00, which is the "partial run looks free" reading the cost_usd: null choice exists to avoid.
…truction Each `Task` subagent writes its own `<session-id>/subagents/agent-*.jsonl`, which `cp -a .../projects/.` copies into LOGS_DIR, so the fallback's `find ... -name '*.jsonl'` slurped them alongside the main session. The `result` event the fallback stands in for counts only the main loop, so every field came out high — measured against five real artifacts, turns roughly doubled and cache_read ran 25-40% over. With the subtree excluded all five reconstruct their result event exactly.
…rows The totals footnote was the only place a reconstructed run was visible; its own row and its workflow's row still rendered `$0.00`, which is the "partial run looks free" reading that `cost_usd: null` exists to prevent. Suffix every cost cell a partial run lands in with `+`, so the number reads as a floor. The footnote itself moves out of the `column -t` pipe, which was aligning its prose across the table's columns.
|
Both points fixed. Subagent transcripts — applied as suggested in 56b44bd. The fixture now writes a
While moving that, the footnote turned out to be going through the table's Rendered against a synthetic report (run 1 partial, run 3 pre-`partial` artifact)
|
tend-agent
left a comment
There was a problem hiding this comment.
Both of the previous round's points check out. I re-ran the reconstruction against the five real artifacts from run 31085980872 — with the -not -path '*/subagents/*' filter every one of them now matches its uploaded token-usage.json exactly, including the four that used a Task (e.g. b7c8bde7: in 49, out 35674, cc 88041, cr 2497878, turns 34, identical). I also confirmed the on-disk shape the filter assumes: subagent lines live only in <session>/subagents/agent-*.jsonl, carry isSidechain: true, and share no message.id with the main transcript, so there's no double-count left behind. The + markers render as described.
One remaining defect, on the fallback's own failure mode.
A single unparseable line collapses the reconstruction back to a silent zero. jq -s aborts on the first parse error, and the || echo '' swallows it — USAGE comes back empty, so control falls through to the "agent never ran" branch and emits {…all zeros…, cost_usd: 0, partial: false}. That's the exact payload this PR exists to stop emitting, except now it also claims partial: false, so nothing downstream can tell it apart from a genuine preflight no-op. The likeliest producer of a malformed line is the very event the fallback is for: a killed process truncating its final append. Reproduced by lopping 40 bytes off a real session JSONL:
intact vs. truncated final line, same file
intact: {"input_tokens":49,"output_tokens":35674,"cache_creation_input_tokens":88041,"cache_read_input_tokens":2497878,"turns":34,"cost_usd":null,"partial":true}
truncated: {"input_tokens":0,"output_tokens":0,"cache_creation_input_tokens":0,"cache_read_input_tokens":0,"turns":0,"cost_usd":0,"partial":false}
jq -s on the truncated file: parse error: Unfinished JSON term at EOF at line 119.
Parsing line-at-a-time and dropping what won't parse fixes it — the inline suggestion switches to -R -s with split("\n") | map(fromjson? // empty), which leaves the rest of the program untouched (.[] still walks the entry array, so the turns count is unaffected). On the intact file it returns the same numbers to the token; on the truncated one it recovers the full accounting instead of zeroing. Worth a fifth test alongside the others — truncate the fixture's last line and assert the totals survive with partial: true, which is what distinguishes this from the preflight-zero case the fourth test already covers.
Unrelated and much smaller: partial_runs was added to totals on the main path, but the two early-exit payloads in token-report.sh (no workflows found, no runs found) still emit a totals without it, so a consumer reading .totals.partial_runs gets null there rather than 0. Both are outside this diff — happy to push the two-key fix if you'd rather not respin for it.
`jq -s` aborts a file on its first parse error and the `|| echo ''` after it swallows the failure, so one malformed line emptied USAGE and dropped the run into the "agent never ran" branch — republishing the all-zero `partial: false` payload this script exists to replace, now indistinguishable from a genuine preflight no-op. A killed process truncating its final append is the likeliest way to get such a line, which is the cancellation case the fallback is for. Read the input as raw text and parse each line on its own, so a bad line costs that line rather than the run's accounting. Applied to the stream-json parser too: a truncated tail there would otherwise discard an intact `result` event and downgrade the run to a costless reconstruction. Also fills in `partial_runs: 0` on token-report.sh's two early-exit payloads, which returned a `totals` without the key the main path now emits.
|
Confirmed and fixed in d4f76d2 — the truncated-tail case is the one path where this PR's failure mode reappears wearing Took the suggestion, and applied the same The |
tend-agent
left a comment
There was a problem hiding this comment.
The truncation fix checks out, and the extension to the stream-json parser is the right call — a truncated line there discards an intact result event and downgrades the run to a costless reconstruction, which is the same loss one notch smaller.
Verified independently: -R -s + map(fromjson? // empty) is at exact parity with the old jq -s on real session logs — 114, 232 and 137 entries from three uploaded artifacts, identical under both forms, and the stream-json is strictly one object per line (333/333 on run 31088056313), so nothing in the real shape depends on jq's multi-line decoding. Full generator suite passes (345), shellcheck clean on both changed scripts. Both new tests fail against the pre-fix form as described.
One residual, deliberately not a blocker: jq -R -s concatenates its file arguments into a single string before split("\n") runs, so a file that doesn't end in a newline gets its last line glued to the next file's first line — and both are then dropped by fromjson?. That is the same missing-trailing-newline condition this commit exists to handle, so it only bites when find returns more than one non-subagent session JSONL and the truncated one sorts first:
reproduction, and why it is latent
logs/p1/a.jsonl 3 lines + truncated tail (no trailing newline)
logs/p2/b.jsonl intact, first line is an assistant message (1500 output tokens)
current output_tokens 3000 <- b.jsonl's first message lost with a.jsonl's tail
awk 1 "${SESSION_FILES[@]}" | jq -R -s ...
output_tokens 4500
jq -s on the same pair aborts outright (parse error: Invalid literal at line 4), so this is a residual gap in an improvement, not a regression — the old form zeroed the whole run where this loses one message.
It is also unreachable on current artifacts: all seven claude-session-logs* artifacts I sampled (runs 31088714507, 31086994731, 31088056313, 31089521118, 31087348366, 31088952587, 31087588292) contain exactly one non-subagent session JSONL, so the two files never meet. Closing it costs an awk 1 pipe plus dropping the file arguments from the closing line — worth doing if a second session file ever shows up in LOGS_DIR, not worth a respin now.
Nothing else outstanding from the earlier rounds; the subagent filter and the + markers still hold, and partial_runs: 0 on the two early-exit payloads matches the main path's shape.
`jq -R -s` concatenates its file arguments into one string before `split("\n")`
runs, so a file that ends without a newline glues its last line to the next
file's first line and `fromjson?` drops both. That is exactly the truncated
tail the previous commit set out to tolerate, so the two conditions coincide.
Read the files through `awk 1`, which ends every file on a newline, and sort
the `find` output so the order is stable. Unreachable on today's artifacts —
they carry one non-subagent session JSONL each — but it costs a pipe to close.
|
Closed the residual in 9c8e1b1 rather than leaving it — the condition that triggers it (a file with no trailing newline) is the same truncation the previous commit exists to tolerate, so the two coincide by construction rather than by coincidence, and it's a pipe: That's everything from the three rounds; I'm treating the review as settled unless something new turns up. Full suite 346 passing, shellcheck clean. |
tend-agent
left a comment
There was a problem hiding this comment.
The awk 1 fix closes the last round's residual, verified independently rather than from the commit message: reverting just the pipe (restoring jq -R -s ... "${SESSION_FILES[@]}") fails test_token_usage_survives_a_truncated_line_beside_a_second_session with assert 4500 == 6000 and nothing else, so the test is pinned to exactly the glued-line behaviour and the fix is minimal. Full generator suite 346 passing, shellcheck clean. I also checked the awk implementation the runners actually use — the sandbox here has gawk, but ubuntu-latest resolves awk to mawk 1.3.4, which grows its record buffer dynamically (10 MB single-line JSONL passes through byte-identical), so a large tool_result line won't hit a record-length limit and drop the pipeline into the all-zero branch.
One residual in the same multi-file scenario, recorded rather than raised as a blocker — the fix is a restructure, not a line, and the scenario is the one you established is unreachable on today's artifacts.
turns doesn't compose across session files: the opening-prompt subtraction is applied once to the pooled count, not once per file. turns: ([([.[] | select(.type == "user")] | length) - 1, 0] | max) runs after all files are concatenated, so every session past the first has its own prompt counted as a turn. Measured against the script directly, with the new test's own shape (a second session contributing one user line and no turn of its own):
single file vs. the same file plus a second session
p1 alone {"output_tokens":4500,"turns":3,...}
p1 + p2 {"output_tokens":6000,"turns":4,...}
output_tokens composes correctly (4500 + 1500); turns should still be 3, since p2 contributes only its prompt. With a realistically-shaped second session (user, assistant, assistant, user — one real turn) the pooled count gives 5 against a true 4, so the error is one turn per extra file regardless of that file's length.
So the new test encodes the two-file shape with the token fields correct and turns off by one. Not worth a respin while LOGS_DIR carries one non-subagent session JSONL — worth knowing if a second one ever shows up, since that is also the moment the awk 1 fix starts earning its keep. Everything from the earlier rounds still holds: the subagent filter, the + floor markers, partial_runs: 0 on both early-exit payloads, and cost_usd: null reaching token-report.sh as a // 0 floor rather than a spend.
…t one total The files are pooled before `turns` is counted, so the single `- 1` that drops a session's opening prompt only ever discounted the first file's — every extra session past it had its prompt counted as a turn. Pass the file count in and subtract per session. Same multi-file scenario as the previous commit, and unreachable for the same reason (one non-subagent session JSONL per artifact today), but the two share a trigger: whenever the `awk 1` fix starts mattering, this one does too.
|
Fixed in c7f2f6e — it turned out to be a line rather than a restructure: pass the file count in as Worth doing despite being unreachable today, since it shares its trigger with the That's four rounds with each finding real; I'll leave further non-blockers to the maintainer's call rather than keep respinning. Full suite 346 passing, shellcheck clean. |
tend-agent
left a comment
There was a problem hiding this comment.
The last round's turns finding is closed. Verified against the script directly rather than from the test: with p1 (three user lines, three assistant messages, 4500 output) alongside a second session contributing only its opening prompt and one 1500-token message, turns now reads the same pooled as it does for p1 alone, while output_tokens still composes to 6000 — so the subtraction tracks session count without the token fields regressing. Reverting just - $sessions to - 1 fails test_token_usage_survives_a_truncated_line_beside_a_second_session on the new assertion and nothing else. test_shared_steps.py 11 passing, and test/lint/test-proxy/test-worker are green on this commit.
Nothing outstanding from the four rounds: the subagent filter, the -R -s line-at-a-time parsing on both parsers, the awk 1 file termination, the + floor markers and partial_runs: 0 on the early-exit payloads all still hold. Self-authored, so this stands as a COMMENT rather than an approval — it needs a human's merge either way.
One residual in the same multi-file scenario, recorded not raised
The subtraction assumes every pooled file contributes exactly one opening prompt, and the max(…, 0) clamps only the total, so a file with no user line at all subtracts a prompt that isn't there:
p1 (3 user lines) + a second file with an assistant line and no user line
turns 1, against a true 2
Fixing it properly means counting per file, which awk 1 has already erased by the time jq runs — a restructure for a sub-case of a scenario that needs a second non-subagent session JSONL in LOGS_DIR to occur at all, and then a transcript missing its own head. Not worth a fifth respin; noting it so the next reader of this line knows the assumption it rests on.
# Conflicts: # generator/tests/test_shared_steps.py
Problem
The Claude action's
Token usagestep hardcoded an all-zerostoken-usage.jsonwhenever the stream-json carried notype: "result"entry. A cancelled session never emits one, and the step isif: always()— so it still ran, still uploaded the artifact, and still reportedturns=0, output_tokens=0, cost_usd=0for a run that may have done dozens of turns and already posted its review.tend-reviewusescancel-in-progress: true, so cancellation is routine rather than exotic, and everything readingtoken-usage.json(token-report.sh, thereview-reviewersevidence gist,review-runs' per-window cost line) under-counted by the cancellation rate. The bias isn't constant either — it scales with push cadence, which is one of the axesreview-runscompares windows along.This is distinct from #302 / #437, which were about taking the last result entry instead of summing across several. This is the zero result entries case.
Solution
Reconstruct the accounting from the session JSONL the step has already consolidated into
LOGS_DIR— deduplicatingtype: "assistant"lines by.message.idand summing.message.usage. That file is uploaded for every repo, unlike the raw stream-json (preserved only on tend's own repo).The reconstruction must read the session JSONL, not the stream-json, even though both carry
type: "assistant"events. Verified against real artifacts, the stream-json's assistant events are non-final (stop_reason: null):usage.output_tokensis the message-start placeholder, single digits against thousands. The input and cache fields, known at message start, do match — so summing the stream's events under-counts output by orders of magnitude while three of four fields look right. On run 31086697446 that filter yieldsoutput_tokens=46against a true 9406.Two secondary choices, both of which #871 explicitly left to judgement:
cost_usd: null, not0. Onlyresult.total_cost_usdcarries cost, and emitting0would repeat the reported bug one field down — a partial run looking free. Deriving it from a hardcoded per-model price table reproduces the reported cost to the cent, but pins price maintenance inside the action, so this leaves it unknown instead.partial: truemarker, so consumers can tell "cancelled, partial accounting" from "ran and cost nothing".token-report.shcounts partial runs and labels its cost total a floor; the step summary renders cost asunknownand notes the reconstruction.partialis absent on the Codex harness's output, which is unaffected — consumers read it as.partial // false.The parsing moved into
shared/steps/compute-token-usage.shso pytest can cover both paths, matching howmark-notification-read.shis tested.Testing
Four tests in
generator/tests/test_shared_steps.py, with fixtures mirroring the shapes observed in real artifacts. The reproduction (test_token_usage_reconstructs_a_cancelled_session) fails against the pre-fix logic withoutput_tokens=0and passes after. A companion test locks in that the fallback doesn't sum the stream-json's placeholder output, since that filter would produce a plausible-looking wrong number.Beyond the fixtures, the fallback was validated against five real uploaded artifacts by stripping the
resultevent from each stream-json to simulate cancellation. It reproduces the result event's four token fields andnum_turnsexactly on all five:resulteventin 23, out 9406, cc 62655, cr 789006, turns 14in 31, out 6111, cc 15350, cr 1091736, turns 18in 25, out 8283, cc 71292, cr 895126, turns 16in 17, out 3501, cc 52293, cr 536771, turns 11in 21, out 4781, cc 14443, cr 731210, turns 13That also confirms the
turns = (count of type:"user" lines) - 1relation #871 flagged as empirical — it holds on the session JSONL, but not on the stream-json, where it is off by two on every session checked.Full generator suite passes (342 tests);
shellcheckandruffclean.Closes #871 — automated triage