From 39ec313015be04faa4fa7378a3601924bcf6f98f Mon Sep 17 00:00:00 2001 From: tend-agent <270458913+tend-agent@users.noreply.github.com> Date: Thu, 6 Aug 2026 09:05:55 +0000 Subject: [PATCH 1/6] fix(claude-action): account a cancelled session from its session JSONL MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- claude/action.yaml | 48 ++--- generator/tests/test_shared_steps.py | 187 ++++++++++++++++++ .../tend-ci-runner/scripts/token-report.sh | 14 +- shared/steps/compute-token-usage.sh | 99 ++++++++++ 4 files changed, 312 insertions(+), 36 deletions(-) create mode 100755 shared/steps/compute-token-usage.sh diff --git a/claude/action.yaml b/claude/action.yaml index 6ed13d15..1bd89586 100644 --- a/claude/action.yaml +++ b/claude/action.yaml @@ -104,7 +104,10 @@ outputs: description: >- JSON object with token usage: input_tokens, output_tokens, cache_creation_input_tokens, cache_read_input_tokens, turns, - model, cost_usd + model, cost_usd, partial. `partial` is true when the run emitted no + result event (typically a cancellation) and the counts were + reconstructed from the session log; `cost_usd` is null in that case, + since only the result event carries it. value: ${{ steps.tokens.outputs.usage }} runs: @@ -527,14 +530,10 @@ runs: echo "" >> "$GITHUB_STEP_SUMMARY" fi - # Parse the stream-json the headless run wrote to stdout. It is NDJSON (one - # SDK message event per line) containing one or more `type: "result"` - # events. Sessions that use `run_in_background: true` Bash emit a second - # `result` on wakeup; `usage.*` and `num_turns` are per-event, while - # `total_cost_usd` is cumulative. Sum the per-event fields across all - # entries and take cost from the last. Output shape mirrors the interactive - # harness so downstream consumers (review-reviewers' evidence gist, - # token-report.sh, dashboards) don't branch on harness. + # Account the run's token usage from the stream-json the headless run wrote + # to stdout, falling back to the session JSONL when the run was cancelled + # before it emitted a `type: "result"` event. Both parsers live in + # compute-token-usage.sh so pytest can cover them. - name: Token usage if: always() id: tokens @@ -555,29 +554,9 @@ runs: cp -a "${AGENT_HOME}/.claude/projects/." "$LOGS_DIR/" 2>/dev/null || true cp -a "$RUNNER_TEMP/tend-claude-stderr.log" "$LOGS_DIR/" 2>/dev/null || true - if [ -n "${STREAM_JSON:-}" ] && [ -s "$STREAM_JSON" ]; then - USAGE=$(jq -s -c --arg model "$MODEL" ' - (map(select(.type == "result"))) as $rs | - if ($rs | length) == 0 then - {input_tokens:0, output_tokens:0, cache_creation_input_tokens:0, - cache_read_input_tokens:0, turns:0, model:$model, cost_usd:0} - else - ($rs | last) as $r | - { - input_tokens: ([$rs[].usage.input_tokens // 0] | add), - output_tokens: ([$rs[].usage.output_tokens // 0] | add), - cache_creation_input_tokens: ([$rs[].usage.cache_creation_input_tokens // 0] | add), - cache_read_input_tokens: ([$rs[].usage.cache_read_input_tokens // 0] | add), - turns: ([$rs[].num_turns // 0] | add), - model: $model, - cost_usd: (($r.total_cost_usd // 0) * 100 | round / 100) - } - end - ' "$STREAM_JSON" 2>/dev/null || echo '') - fi - if [ -z "${USAGE:-}" ]; then - USAGE='{"input_tokens":0,"output_tokens":0,"cache_creation_input_tokens":0,"cache_read_input_tokens":0,"turns":0,"model":"'"$MODEL"'","cost_usd":0}' - fi + # Runs after the copy above, so the fallback can read the session JSONL. + USAGE=$(LOGS_DIR="$LOGS_DIR" \ + bash "${{ github.action_path }}/../shared/steps/compute-token-usage.sh") echo "$USAGE" > "$LOGS_DIR/token-usage.json" echo "usage=$(jq -c . <<< "$USAGE")" >> "$GITHUB_OUTPUT" @@ -593,7 +572,7 @@ runs: fi jq -r ' - def usd: tostring | if test("\\.") then split(".") | "\(.[0]).\((.[1] + "00")[:2])" else . + ".00" end | "$" + .; + def usd: if . == null then "unknown" else tostring | if test("\\.") then split(".") | "\(.[0]).\((.[1] + "00")[:2])" else . + ".00" end | "$" + . end; "## Token Usage", "| Metric | Value |", "|--------|-------|", @@ -604,6 +583,9 @@ runs: "| Cost | \(.cost_usd | usd) |", "| Turns | \(.turns) |", "", + if .partial then + "*Reconstructed from the session log: this run emitted no result event (most often a cancellation), so the token counts are its own but the cost is not recoverable.*" + else empty end, "*Cost at API list prices — a large multiple of the effective rate on Claude Code subscriptions.*" ' <<< "$USAGE" >> "$GITHUB_STEP_SUMMARY" diff --git a/generator/tests/test_shared_steps.py b/generator/tests/test_shared_steps.py index 1814d22b..900ef06b 100644 --- a/generator/tests/test_shared_steps.py +++ b/generator/tests/test_shared_steps.py @@ -17,6 +17,7 @@ REPO_ROOT = Path(__file__).resolve().parents[2] MARK_NOTIFICATION_READ = REPO_ROOT / "shared" / "steps" / "mark-notification-read.sh" +COMPUTE_TOKEN_USAGE = REPO_ROOT / "shared" / "steps" / "compute-token-usage.sh" # `gh api` stand-in. Records every invocation so a test can assert which calls # the script made, and fails the run-metadata fetch when FAIL_RUN_META is set. @@ -146,3 +147,189 @@ def test_mark_notification_read_leaves_activity_newer_than_the_run( assert result.returncode == 0, result.stderr assert not any("-X PATCH" in c for c in _calls(gh_env)) + + +# --- compute-token-usage.sh ------------------------------------------------- +# +# Fixtures below mirror the shapes observed in real uploaded artifacts. Two +# properties drive the tests: +# +# 1. Both files record each assistant message roughly twice, so any sum has to +# deduplicate by `.message.id` or it lands ~2x high. +# 2. The stream-json's assistant events are non-final (`stop_reason: null`): +# their `usage.output_tokens` is the message-start placeholder (single +# digits), not the finished count. Only the session JSONL carries final +# per-message usage. Reconstructing from the stream-json therefore +# under-counts output by orders of magnitude, while input and cache fields +# — known at message start — happen to match. + + +def _assistant(msg_id: str, usage: dict[str, int], *, final: bool) -> dict[str, object]: + return { + "type": "assistant", + "message": { + "id": msg_id, + "stop_reason": "end_turn" if final else None, + "usage": usage, + }, + } + + +def _ndjson(path: Path, lines: list[dict[str, object]]) -> Path: + path.write_text("".join(json.dumps(line) + "\n" for line in lines)) + return path + + +# Final per-message usage, as the session JSONL records it. +FINAL_USAGE = [ + { + "input_tokens": 10, + "output_tokens": 3000, + "cache_creation_input_tokens": 1000, + "cache_read_input_tokens": 20000, + }, + { + "input_tokens": 5, + "output_tokens": 1500, + "cache_creation_input_tokens": 500, + "cache_read_input_tokens": 40000, + }, +] +# The same two messages as the stream-json emits them: input/cache identical, +# output still at its message-start placeholder. +STREAM_USAGE = [dict(u, output_tokens=6) for u in FINAL_USAGE] + + +def _session_jsonl(logs_dir: Path) -> Path: + """A cancelled session's JSONL: real usage, each message duplicated.""" + project = logs_dir / "-home-runner-work-repo-repo" + project.mkdir(parents=True, exist_ok=True) + lines: list[dict[str, object]] = [{"type": "user"}] + for i, usage in enumerate(FINAL_USAGE): + entry = _assistant(f"msg_{i}", usage, final=True) + lines += [entry, dict(entry), {"type": "user"}] + lines.append({"type": "user"}) + return _ndjson(project / "session.jsonl", lines) + + +def _cancelled_stream(tmp_path: Path) -> Path: + """Stream-json for the same session: assistant events, no `result`.""" + lines: list[dict[str, object]] = [{"type": "system"}] + for i, usage in enumerate(STREAM_USAGE): + entry = _assistant(f"msg_{i}", usage, final=False) + lines += [entry, dict(entry), {"type": "user"}] + return _ndjson(tmp_path / "stream.json", lines) + + +def _usage(tmp_path: Path, *, stream: Path | None, logs_dir: Path) -> dict[str, object]: + result = subprocess.run( + ["bash", str(COMPUTE_TOKEN_USAGE)], + env={ + "PATH": "/usr/bin:/bin:/usr/local/bin", + "MODEL": "opus", + "LOGS_DIR": str(logs_dir), + "STREAM_JSON": str(stream) if stream else "", + }, + capture_output=True, + text=True, + ) + assert result.returncode == 0, result.stderr + return json.loads(result.stdout) + + +def test_token_usage_reconstructs_a_cancelled_session(tmp_path: Path) -> None: + """A cancelled session must be accounted from its session JSONL. + + `tend-review` runs with `cancel-in-progress: true`, so cancellation is + routine — and a cancelled session never emits a `type: "result"` event. + The step is `if: always()`, so it still writes token-usage.json and still + uploads the artifact; only the accounting is lost. Reporting zeros for a + run that did real work (and may already have posted a review) biases every + downstream total by the cancellation rate. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + _session_jsonl(logs_dir) + + usage = _usage(tmp_path, stream=_cancelled_stream(tmp_path), logs_dir=logs_dir) + + assert usage["output_tokens"] == 4500, ( + f"cancelled session reported output_tokens={usage['output_tokens']}; " + "the session JSONL records 4500 across two messages" + ) + assert usage["input_tokens"] == 15 + assert usage["cache_creation_input_tokens"] == 1500 + assert usage["cache_read_input_tokens"] == 60000 + # Three `user` lines bracket the two assistant turns; num_turns counts the + # turns between them. + assert usage["turns"] == 3 + assert usage["partial"] is True, ( + "a reconstructed total must be distinguishable from a run that " + "genuinely cost nothing" + ) + + +def test_token_usage_ignores_stream_json_placeholder_output(tmp_path: Path) -> None: + """The fallback must not sum the stream-json's non-final assistant events. + + They carry `stop_reason: null` and a message-start `output_tokens`, so + summing them under-counts output by orders of magnitude while input and + cache fields still match — a wrong number that looks plausible. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + _session_jsonl(logs_dir) + + usage = _usage(tmp_path, stream=_cancelled_stream(tmp_path), logs_dir=logs_dir) + + stream_sum = sum(u["output_tokens"] for u in STREAM_USAGE) + assert usage["output_tokens"] != stream_sum, ( + "summed the stream-json's placeholder output_tokens" + ) + + +def test_token_usage_prefers_result_events_when_present(tmp_path: Path) -> None: + """A completed session still reports straight from its `result` events.""" + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + _session_jsonl(logs_dir) + stream = _ndjson( + tmp_path / "stream.json", + [ + _assistant("msg_0", STREAM_USAGE[0], final=False), + { + "type": "result", + "num_turns": 14, + "total_cost_usd": 1.2563179999999998, + "usage": { + "input_tokens": 23, + "output_tokens": 9406, + "cache_creation_input_tokens": 62655, + "cache_read_input_tokens": 789006, + }, + }, + ], + ) + + usage = _usage(tmp_path, stream=stream, logs_dir=logs_dir) + + assert usage["output_tokens"] == 9406 + assert usage["turns"] == 14 + assert usage["cost_usd"] == 1.26 + assert usage["partial"] is False + + +def test_token_usage_reports_zero_when_the_agent_never_ran(tmp_path: Path) -> None: + """No stream and no session JSONL is a genuine zero, not a partial total. + + A run that dies in preflight really did cost nothing; flagging it partial + would push a fabricated unknown into the reports. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + + usage = _usage(tmp_path, stream=None, logs_dir=logs_dir) + + assert usage["output_tokens"] == 0 + assert usage["cost_usd"] == 0 + assert usage["partial"] is False diff --git a/plugins/tend-ci-runner/scripts/token-report.sh b/plugins/tend-ci-runner/scripts/token-report.sh index 7ac4f87d..456c061d 100755 --- a/plugins/tend-ci-runner/scripts/token-report.sh +++ b/plugins/tend-ci-runner/scripts/token-report.sh @@ -97,14 +97,18 @@ for row in "${ROWS[@]}"; do continue fi - # Aggregate across matrix jobs (each job produces its own token-usage.json) + # Aggregate across matrix jobs (each job produces its own token-usage.json). + # `partial` marks a run whose counts were reconstructed from the session log + # because it emitted no result event — its tokens are real but its cost is + # unrecoverable, so the cost column under-counts by however many there are. USAGE=$(cat "${USAGE_FILES[@]}" | jq -s '{ input_tokens: (map(.input_tokens) | add), output_tokens: (map(.output_tokens) | add), cache_creation_input_tokens: (map(.cache_creation_input_tokens) | add), cache_read_input_tokens: (map(.cache_read_input_tokens) | add), turns: (map(.turns) | add), - cost_usd: (map(.cost_usd // 0) | add) + cost_usd: (map(.cost_usd // 0) | add), + partial: (map(.partial // false) | any) }') jq -c --argjson usage "$USAGE" ' @@ -123,7 +127,8 @@ jq -s '{ cache_creation_input_tokens: (map(.cache_creation_input_tokens) | add // 0), cache_read_input_tokens: (map(.cache_read_input_tokens) | add // 0), turns: (map(.turns) | add // 0), - cost_usd: (map(.cost_usd) | add // 0 | . * 100 | round / 100) + cost_usd: (map(.cost_usd) | add // 0 | . * 100 | round / 100), + partial_runs: (map(select(.partial)) | length) } }' "$ENTRIES" | tee "$WORKDIR/report.json" @@ -138,6 +143,9 @@ jq -r ' "\n\(.runs | length) runs since '"$SINCE"'", "Totals: \(.totals.input_tokens | fmt) in, \(.totals.output_tokens | fmt) out, \(.totals.cache_creation_input_tokens | fmt) cache-create, \(.totals.cache_read_input_tokens | fmt) cache-read, \(.totals.cost_usd | usd) cost", + (if .totals.partial_runs > 0 then + "\(.totals.partial_runs) run(s) emitted no result event (typically cancelled): tokens counted, cost not recoverable — the cost total is a floor." + else empty end), "", (["WORKFLOW", "RUNS", "INPUT", "OUTPUT", "CACHE-CREATE", "CACHE-READ", "COST"] | @tsv), (.runs | group_by(.workflow) | map({ diff --git a/shared/steps/compute-token-usage.sh b/shared/steps/compute-token-usage.sh new file mode 100755 index 00000000..be11d96c --- /dev/null +++ b/shared/steps/compute-token-usage.sh @@ -0,0 +1,99 @@ +#!/usr/bin/env bash +# Computes the run's token accounting and prints it as one JSON object. +# +# Reads (env): +# STREAM_JSON - the headless run's stream-json (NDJSON of SDK message events) +# LOGS_DIR - consolidated log dir; holds the agent's session JSONL +# MODEL - model name, copied through to the output +# +# Output shape mirrors the interactive harness so downstream consumers +# (review-reviewers' evidence gist, token-report.sh, dashboards) don't branch +# on harness. + +set -euo pipefail + +MODEL=${MODEL:-} +LOGS_DIR=${LOGS_DIR:-} + +USAGE="" + +# Primary path: the stream-json's `type: "result"` events. Sessions that use +# `run_in_background: true` Bash emit a second `result` on wakeup; `usage.*` +# and `num_turns` are per-event, while `total_cost_usd` is cumulative. Sum the +# per-event fields across all entries and take cost from the last. +if [ -n "${STREAM_JSON:-}" ] && [ -s "$STREAM_JSON" ]; then + USAGE=$(jq -s -c --arg model "$MODEL" ' + (map(select(.type == "result"))) as $rs | + if ($rs | length) == 0 then + empty + else + ($rs | last) as $r | + { + input_tokens: ([$rs[].usage.input_tokens // 0] | add), + output_tokens: ([$rs[].usage.output_tokens // 0] | add), + cache_creation_input_tokens: ([$rs[].usage.cache_creation_input_tokens // 0] | add), + cache_read_input_tokens: ([$rs[].usage.cache_read_input_tokens // 0] | add), + turns: ([$rs[].num_turns // 0] | add), + model: $model, + cost_usd: (($r.total_cost_usd // 0) * 100 | round / 100), + partial: false + } + end + ' "$STREAM_JSON" 2>/dev/null || echo '') +fi + +# Fallback: no `result` event. A cancelled session never emits one, and +# `tend-review` runs with `cancel-in-progress: true`, so this is routine rather +# than exotic — the run may have done dozens of turns and already posted its +# review. Reconstruct from the session JSONL the step has just consolidated +# into LOGS_DIR (uploaded for every repo, unlike the raw stream-json). +# +# Read the session JSONL, NOT the stream-json, even though both carry +# `type: "assistant"` events. The stream-json's are non-final +# (`stop_reason: null`): `usage.output_tokens` is the message-start +# placeholder — single digits against thousands — while the input and cache +# fields, known at message start, do match. Summing the stream's events would +# under-count output by orders of magnitude and look plausible doing it. The +# session JSONL's per-message usage reproduces the `result` event's four token +# fields exactly. +# +# Both files record each assistant message roughly twice, hence unique_by(.id). +if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then + mapfile -t SESSION_FILES < <(find "$LOGS_DIR" -name '*.jsonl' -type f) + if [ ${#SESSION_FILES[@]} -gt 0 ]; then + USAGE=$(jq -s -c --arg model "$MODEL" ' + ([.[] | select(.type == "assistant" and .message.id != null) + | {id: .message.id, u: .message.usage}] | unique_by(.id)) as $ms | + if ($ms | length) == 0 then + empty + else + { + input_tokens: ([$ms[].u.input_tokens // 0] | add // 0), + output_tokens: ([$ms[].u.output_tokens // 0] | add // 0), + cache_creation_input_tokens: ([$ms[].u.cache_creation_input_tokens // 0] | add // 0), + cache_read_input_tokens: ([$ms[].u.cache_read_input_tokens // 0] | add // 0), + # The prompt that opens the session is a `user` line but not a turn. + turns: ([([.[] | select(.type == "user")] | length) - 1, 0] | max), + model: $model, + # Only `result.total_cost_usd` carries cost, and that is the event we + # do not have. `null` says unknown; a `0` here would repeat the bug + # this fallback exists to fix, one field down. + cost_usd: null, + partial: true + } + end + ' "${SESSION_FILES[@]}" 2>/dev/null || echo '') + fi +fi + +# Neither a result event nor any assistant message: the agent never ran (a +# preflight failure, say). That run genuinely cost nothing, so report a real +# zero rather than flagging an unknown. +if [ -z "${USAGE:-}" ]; then + USAGE=$(jq -n -c --arg model "$MODEL" ' + {input_tokens:0, output_tokens:0, cache_creation_input_tokens:0, + cache_read_input_tokens:0, turns:0, model:$model, cost_usd:0, + partial:false}') +fi + +printf '%s\n' "$USAGE" From 56b44bd9c89d0eb56b2fccacaa6be3cb83ed493a Mon Sep 17 00:00:00 2001 From: tend-agent <270458913+tend-agent@users.noreply.github.com> Date: Thu, 6 Aug 2026 09:17:01 +0000 Subject: [PATCH 2/6] fix(compute-token-usage): keep subagent transcripts out of the reconstruction MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Each `Task` subagent writes its own `/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. --- generator/tests/test_shared_steps.py | 52 ++++++++++++++++++++++++++-- shared/steps/compute-token-usage.sh | 8 ++++- 2 files changed, 57 insertions(+), 3 deletions(-) diff --git a/generator/tests/test_shared_steps.py b/generator/tests/test_shared_steps.py index 900ef06b..438c1787 100644 --- a/generator/tests/test_shared_steps.py +++ b/generator/tests/test_shared_steps.py @@ -151,7 +151,7 @@ def test_mark_notification_read_leaves_activity_newer_than_the_run( # --- compute-token-usage.sh ------------------------------------------------- # -# Fixtures below mirror the shapes observed in real uploaded artifacts. Two +# Fixtures below mirror the shapes observed in real uploaded artifacts. Three # properties drive the tests: # # 1. Both files record each assistant message roughly twice, so any sum has to @@ -162,6 +162,8 @@ def test_mark_notification_read_leaves_activity_newer_than_the_run( # per-message usage. Reconstructing from the stream-json therefore # under-counts output by orders of magnitude, while input and cache fields # — known at message start — happen to match. +# 3. A session that ran a `Task` has a second transcript under +# `/subagents/`, whose usage the `result` event does not count. def _assistant(msg_id: str, usage: dict[str, int], *, final: bool) -> dict[str, object]: @@ -200,8 +202,24 @@ def _ndjson(path: Path, lines: list[dict[str, object]]) -> Path: STREAM_USAGE = [dict(u, output_tokens=6) for u in FINAL_USAGE] +# A `Task` subagent's own transcript, which real artifacts carry alongside the +# session it belongs to. Its usage is not in the `result` event, so nothing +# here may reach the totals. +SUBAGENT_USAGE = { + "input_tokens": 300, + "output_tokens": 7000, + "cache_creation_input_tokens": 40000, + "cache_read_input_tokens": 900000, +} + + def _session_jsonl(logs_dir: Path) -> Path: - """A cancelled session's JSONL: real usage, each message duplicated.""" + """A cancelled session's JSONL: real usage, each message duplicated. + + Writes the subagent transcript beside it too — `/subagents/` is + how Claude Code lays a `Task` out on disk, and `cp -a .../projects/.` + copies the subtree into LOGS_DIR. + """ project = logs_dir / "-home-runner-work-repo-repo" project.mkdir(parents=True, exist_ok=True) lines: list[dict[str, object]] = [{"type": "user"}] @@ -209,6 +227,17 @@ def _session_jsonl(logs_dir: Path) -> Path: entry = _assistant(f"msg_{i}", usage, final=True) lines += [entry, dict(entry), {"type": "user"}] lines.append({"type": "user"}) + + subagents = project / "session" / "subagents" + subagents.mkdir(parents=True, exist_ok=True) + _ndjson( + subagents / "agent-a1b2c3.jsonl", + [ + {"type": "user"}, + _assistant("msg_sub", SUBAGENT_USAGE, final=True), + {"type": "user"}, + ], + ) return _ndjson(project / "session.jsonl", lines) @@ -288,6 +317,25 @@ def test_token_usage_ignores_stream_json_placeholder_output(tmp_path: Path) -> N ) +def test_token_usage_ignores_subagent_transcripts(tmp_path: Path) -> None: + """Subagent transcripts must not be slurped into the reconstruction. + + Every `Task` writes its own `/subagents/agent-*.jsonl`, but the + `result` event this fallback stands in for counts only the main loop. + Summing both inflates each field — turns roughly doubles — so a partial + run would no longer be comparable with a complete one. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + _session_jsonl(logs_dir) + + usage = _usage(tmp_path, stream=_cancelled_stream(tmp_path), logs_dir=logs_dir) + + assert usage["output_tokens"] == 4500, "summed the subagent's output_tokens" + assert usage["cache_read_input_tokens"] == 60000, "summed the subagent's cache" + assert usage["turns"] == 3, "counted the subagent's `user` lines as turns" + + def test_token_usage_prefers_result_events_when_present(tmp_path: Path) -> None: """A completed session still reports straight from its `result` events.""" logs_dir = tmp_path / "logs" diff --git a/shared/steps/compute-token-usage.sh b/shared/steps/compute-token-usage.sh index be11d96c..45b3c919 100755 --- a/shared/steps/compute-token-usage.sh +++ b/shared/steps/compute-token-usage.sh @@ -58,8 +58,14 @@ fi # fields exactly. # # Both files record each assistant message roughly twice, hence unique_by(.id). +# +# Skip `/subagents/agent-*.jsonl` — each `Task` subagent gets its +# own transcript there, and `cp -a .../projects/.` brings the subtree along. +# The `result` event this path reconstructs counts only the main loop, so +# slurping the subagents alongside it inflates every field (turns roughly +# doubles) and makes partial runs incomparable with complete ones. if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then - mapfile -t SESSION_FILES < <(find "$LOGS_DIR" -name '*.jsonl' -type f) + mapfile -t SESSION_FILES < <(find "$LOGS_DIR" -name '*.jsonl' -type f -not -path '*/subagents/*') if [ ${#SESSION_FILES[@]} -gt 0 ]; then USAGE=$(jq -s -c --arg model "$MODEL" ' ([.[] | select(.type == "assistant" and .message.id != null) From ebfe90a55dc4ca1c40db8daa5fdc5cc73c958e15 Mon Sep 17 00:00:00 2001 From: tend-agent <270458913+tend-agent@users.noreply.github.com> Date: Thu, 6 Aug 2026 09:20:52 +0000 Subject: [PATCH 3/6] fix(token-report): mark partial runs in the per-run and per-workflow 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. --- .../tend-ci-runner/scripts/token-report.sh | 23 +++++++++++++------ 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/plugins/tend-ci-runner/scripts/token-report.sh b/plugins/tend-ci-runner/scripts/token-report.sh index 456c061d..e2adc5ba 100755 --- a/plugins/tend-ci-runner/scripts/token-report.sh +++ b/plugins/tend-ci-runner/scripts/token-report.sh @@ -141,11 +141,13 @@ jq -r ' def usd: tostring | if test("\\.") then split(".") | "\(.[0]).\((.[1] + "00")[:2])" else . + ".00" end | "$" + .; + # A partial run contributes tokens but no cost, so every cost it lands in — + # its own row, its workflow row, the total — is a floor, not the spend. Mark + # those cells with a trailing `+` so a reconstructed run never reads as free. + def floor_marker: if . then "+" else "" end; + "\n\(.runs | length) runs since '"$SINCE"'", - "Totals: \(.totals.input_tokens | fmt) in, \(.totals.output_tokens | fmt) out, \(.totals.cache_creation_input_tokens | fmt) cache-create, \(.totals.cache_read_input_tokens | fmt) cache-read, \(.totals.cost_usd | usd) cost", - (if .totals.partial_runs > 0 then - "\(.totals.partial_runs) run(s) emitted no result event (typically cancelled): tokens counted, cost not recoverable — the cost total is a floor." - else empty end), + "Totals: \(.totals.input_tokens | fmt) in, \(.totals.output_tokens | fmt) out, \(.totals.cache_creation_input_tokens | fmt) cache-create, \(.totals.cache_read_input_tokens | fmt) cache-read, \(.totals.cost_usd | usd)\(.totals.partial_runs > 0 | floor_marker) cost", "", (["WORKFLOW", "RUNS", "INPUT", "OUTPUT", "CACHE-CREATE", "CACHE-READ", "COST"] | @tsv), (.runs | group_by(.workflow) | map({ @@ -155,14 +157,21 @@ jq -r ' o: (map(.output_tokens) | add), cc: (map(.cache_creation_input_tokens) | add), cr: (map(.cache_read_input_tokens) | add), - cost: (map(.cost_usd) | add | . * 100 | round / 100) + cost: (map(.cost_usd) | add | . * 100 | round / 100), + partial: (map(.partial // false) | any) }) | sort_by(.cr) | reverse | .[] | - [.w, (.n | tostring), (.i | fmt), (.o | fmt), (.cc | fmt), (.cr | fmt), (.cost | usd)] | @tsv), + [.w, (.n | tostring), (.i | fmt), (.o | fmt), (.cc | fmt), (.cr | fmt), ((.cost | usd) + (.partial | floor_marker))] | @tsv), "", (["RUN", "WORKFLOW", "INPUT", "OUTPUT", "CACHE-CREATE", "CACHE-READ", "COST", "TIME"] | @tsv), (.runs | sort_by(.created_at) | reverse | .[] | - [(.run_id | tostring), .workflow, (.input_tokens | fmt), (.output_tokens | fmt), (.cache_creation_input_tokens | fmt), (.cache_read_input_tokens | fmt), (.cost_usd | usd), .created_at[:16]] | @tsv) + [(.run_id | tostring), .workflow, (.input_tokens | fmt), (.output_tokens | fmt), (.cache_creation_input_tokens | fmt), (.cache_read_input_tokens | fmt), ((.cost_usd | usd) + (.partial // false | floor_marker)), .created_at[:16]] | @tsv) ' "$WORKDIR/report.json" | column -t >&2 echo >&2 "" +# Printed outside the table's `column -t`, which would otherwise align a prose +# line into the table's columns. +PARTIAL_RUNS=$(jq -r '.totals.partial_runs' "$WORKDIR/report.json") +if [ "$PARTIAL_RUNS" -gt 0 ]; then + echo >&2 "$PARTIAL_RUNS run(s) emitted no result event (typically cancelled): tokens counted, cost not recoverable. A '+' marks a cost that is a floor rather than the spend." +fi echo >&2 "Cost at API list prices — a large multiple of the effective rate on Claude Code subscriptions." From d4f76d25b6fc22b054927254370046f1110a2f5a Mon Sep 17 00:00:00 2001 From: tend-agent <270458913+tend-agent@users.noreply.github.com> Date: Thu, 6 Aug 2026 09:34:32 +0000 Subject: [PATCH 4/6] fix(compute-token-usage): parse the NDJSON line-at-a-time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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. --- generator/tests/test_shared_steps.py | 52 +++++++++++++++++++ .../tend-ci-runner/scripts/token-report.sh | 4 +- shared/steps/compute-token-usage.sh | 14 ++++- 3 files changed, 66 insertions(+), 4 deletions(-) diff --git a/generator/tests/test_shared_steps.py b/generator/tests/test_shared_steps.py index 438c1787..24174276 100644 --- a/generator/tests/test_shared_steps.py +++ b/generator/tests/test_shared_steps.py @@ -367,6 +367,58 @@ def test_token_usage_prefers_result_events_when_present(tmp_path: Path) -> None: assert usage["partial"] is False +def test_token_usage_survives_a_truncated_final_line(tmp_path: Path) -> None: + """A half-written line costs that line, not the run's whole accounting. + + A cancelled process can be killed mid-append, leaving its session JSONL + ending in a partial entry. `jq -s` aborts the file on the first parse + error and the `|| echo ''` swallows it, which would drop the run into the + "agent never ran" branch — republishing the all-zero `partial: false` + payload this fallback exists to replace, now indistinguishable from a + genuine preflight no-op. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + session = _session_jsonl(logs_dir) + session.write_text(session.read_text() + '{"type":"assistant","mess') + + usage = _usage(tmp_path, stream=_cancelled_stream(tmp_path), logs_dir=logs_dir) + + assert usage["output_tokens"] == 4500, "a truncated tail zeroed the totals" + assert usage["turns"] == 3 + assert usage["partial"] is True + + +def test_token_usage_survives_a_truncated_stream_json_line(tmp_path: Path) -> None: + """The same truncation on the stream-json must not lose a `result` event. + + Falling through to the session JSONL would still report the tokens, but as + `partial` with an unknown cost — a needless downgrade when the result event + itself parsed fine. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + _session_jsonl(logs_dir) + stream = _ndjson( + tmp_path / "stream.json", + [ + { + "type": "result", + "num_turns": 14, + "total_cost_usd": 1.25, + "usage": {"input_tokens": 23, "output_tokens": 9406}, + }, + ], + ) + stream.write_text(stream.read_text() + '{"type":"resu') + + usage = _usage(tmp_path, stream=stream, logs_dir=logs_dir) + + assert usage["output_tokens"] == 9406 + assert usage["cost_usd"] == 1.25 + assert usage["partial"] is False + + def test_token_usage_reports_zero_when_the_agent_never_ran(tmp_path: Path) -> None: """No stream and no session JSONL is a genuine zero, not a partial total. diff --git a/plugins/tend-ci-runner/scripts/token-report.sh b/plugins/tend-ci-runner/scripts/token-report.sh index e2adc5ba..4e99751d 100755 --- a/plugins/tend-ci-runner/scripts/token-report.sh +++ b/plugins/tend-ci-runner/scripts/token-report.sh @@ -54,7 +54,7 @@ for prefix in "${PREFIXES[@]}"; do done if [ ${#WORKFLOWS[@]} -eq 0 ]; then - echo '{"runs":[],"totals":{"input_tokens":0,"output_tokens":0,"cache_creation_input_tokens":0,"cache_read_input_tokens":0,"turns":0,"cost_usd":0}}' + echo '{"runs":[],"totals":{"input_tokens":0,"output_tokens":0,"cache_creation_input_tokens":0,"cache_read_input_tokens":0,"turns":0,"cost_usd":0,"partial_runs":0}}' exit 0 fi @@ -68,7 +68,7 @@ done RUN_COUNT=$(echo "$ALL_RUNS" | jq 'length') if [ "$RUN_COUNT" -eq 0 ]; then - echo '{"runs":[],"totals":{"input_tokens":0,"output_tokens":0,"cache_creation_input_tokens":0,"cache_read_input_tokens":0,"turns":0,"cost_usd":0}}' + echo '{"runs":[],"totals":{"input_tokens":0,"output_tokens":0,"cache_creation_input_tokens":0,"cache_read_input_tokens":0,"turns":0,"cost_usd":0,"partial_runs":0}}' exit 0 fi diff --git a/shared/steps/compute-token-usage.sh b/shared/steps/compute-token-usage.sh index 45b3c919..ecb4202d 100755 --- a/shared/steps/compute-token-usage.sh +++ b/shared/steps/compute-token-usage.sh @@ -17,12 +17,21 @@ LOGS_DIR=${LOGS_DIR:-} USAGE="" +# Both parsers below read their NDJSON as raw text and parse line by line +# (`-R -s`, then `map(fromjson? // empty)`) rather than letting jq decode the +# stream. `jq -s` aborts the whole file on the first malformed line, and the +# `|| echo ''` that follows swallows the error — so one bad line would zero the +# run's accounting rather than cost that line. A killed process truncating its +# final append is the likeliest way to get one, which is exactly the +# cancellation case this script exists to account for. + # Primary path: the stream-json's `type: "result"` events. Sessions that use # `run_in_background: true` Bash emit a second `result` on wakeup; `usage.*` # and `num_turns` are per-event, while `total_cost_usd` is cumulative. Sum the # per-event fields across all entries and take cost from the last. if [ -n "${STREAM_JSON:-}" ] && [ -s "$STREAM_JSON" ]; then - USAGE=$(jq -s -c --arg model "$MODEL" ' + USAGE=$(jq -R -s -c --arg model "$MODEL" ' + split("\n") | map(fromjson? // empty) | (map(select(.type == "result"))) as $rs | if ($rs | length) == 0 then empty @@ -67,7 +76,8 @@ fi if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then mapfile -t SESSION_FILES < <(find "$LOGS_DIR" -name '*.jsonl' -type f -not -path '*/subagents/*') if [ ${#SESSION_FILES[@]} -gt 0 ]; then - USAGE=$(jq -s -c --arg model "$MODEL" ' + USAGE=$(jq -R -s -c --arg model "$MODEL" ' + split("\n") | map(fromjson? // empty) | ([.[] | select(.type == "assistant" and .message.id != null) | {id: .message.id, u: .message.usage}] | unique_by(.id)) as $ms | if ($ms | length) == 0 then From 9c8e1b17031cbe7790c6e935e1370c7777f7ee39 Mon Sep 17 00:00:00 2001 From: tend-agent <270458913+tend-agent@users.noreply.github.com> Date: Thu, 6 Aug 2026 09:43:59 +0000 Subject: [PATCH 5/6] fix(compute-token-usage): terminate each session file before slurping MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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. --- generator/tests/test_shared_steps.py | 29 ++++++++++++++++++++++++++++ shared/steps/compute-token-usage.sh | 11 ++++++++--- 2 files changed, 37 insertions(+), 3 deletions(-) diff --git a/generator/tests/test_shared_steps.py b/generator/tests/test_shared_steps.py index 24174276..49b57d22 100644 --- a/generator/tests/test_shared_steps.py +++ b/generator/tests/test_shared_steps.py @@ -389,6 +389,35 @@ def test_token_usage_survives_a_truncated_final_line(tmp_path: Path) -> None: assert usage["partial"] is True +def test_token_usage_survives_a_truncated_line_beside_a_second_session( + tmp_path: Path, +) -> None: + """A truncated file must not take the next file's first line with it. + + `jq -R -s` concatenates its inputs into one string before `split("\\n")` + runs, so a file ending without a newline would join its partial last line + to the next file's first line and `fromjson?` would drop the pair. The + files are read through `awk 1`, which terminates each one. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir() + session = _session_jsonl(logs_dir) + session.write_text(session.read_text() + '{"type":"assistant","mess') + + # Sorts after the truncated file, so it is the one glued onto its tail. + second = logs_dir / "-home-runner-work-repo-repo2" + second.mkdir() + _ndjson( + second / "session.jsonl", + [_assistant("msg_second", FINAL_USAGE[1], final=True), {"type": "user"}], + ) + + usage = _usage(tmp_path, stream=_cancelled_stream(tmp_path), logs_dir=logs_dir) + + assert usage["output_tokens"] == 6000, "lost the second session's first message" + assert usage["partial"] is True + + def test_token_usage_survives_a_truncated_stream_json_line(tmp_path: Path) -> None: """The same truncation on the stream-json must not lose a `result` event. diff --git a/shared/steps/compute-token-usage.sh b/shared/steps/compute-token-usage.sh index ecb4202d..ca8dda41 100755 --- a/shared/steps/compute-token-usage.sh +++ b/shared/steps/compute-token-usage.sh @@ -74,9 +74,14 @@ fi # slurping the subagents alongside it inflates every field (turns roughly # doubles) and makes partial runs incomparable with complete ones. if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then - mapfile -t SESSION_FILES < <(find "$LOGS_DIR" -name '*.jsonl' -type f -not -path '*/subagents/*') + mapfile -t SESSION_FILES < <(find "$LOGS_DIR" -name '*.jsonl' -type f -not -path '*/subagents/*' | sort) if [ ${#SESSION_FILES[@]} -gt 0 ]; then - USAGE=$(jq -R -s -c --arg model "$MODEL" ' + # `awk 1` rather than jq's own file arguments: `-R -s` concatenates the + # files into one string before `split("\n")` sees it, so a file that ends + # without a newline — the truncation case above — would glue its last line + # to the next file's first line and `fromjson?` would drop both. awk ends + # every file on a newline, so a truncated tail costs only itself. + USAGE=$(awk 1 "${SESSION_FILES[@]}" | jq -R -s -c --arg model "$MODEL" ' split("\n") | map(fromjson? // empty) | ([.[] | select(.type == "assistant" and .message.id != null) | {id: .message.id, u: .message.usage}] | unique_by(.id)) as $ms | @@ -98,7 +103,7 @@ if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then partial: true } end - ' "${SESSION_FILES[@]}" 2>/dev/null || echo '') + ' 2>/dev/null || echo '') fi fi From c7f2f6e05d4e73bbfbca1472d2cd348eac03e14c Mon Sep 17 00:00:00 2001 From: tend-agent <270458913+tend-agent@users.noreply.github.com> Date: Thu, 6 Aug 2026 09:52:08 +0000 Subject: [PATCH 6/6] fix(compute-token-usage): subtract one opening prompt per session, not one total MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- generator/tests/test_shared_steps.py | 3 +++ shared/steps/compute-token-usage.sh | 9 ++++++--- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/generator/tests/test_shared_steps.py b/generator/tests/test_shared_steps.py index 49b57d22..cfb0c6bf 100644 --- a/generator/tests/test_shared_steps.py +++ b/generator/tests/test_shared_steps.py @@ -415,6 +415,9 @@ def test_token_usage_survives_a_truncated_line_beside_a_second_session( usage = _usage(tmp_path, stream=_cancelled_stream(tmp_path), logs_dir=logs_dir) assert usage["output_tokens"] == 6000, "lost the second session's first message" + # p2 contributes its opening prompt and no turn of its own. The subtraction + # is per session, so pooling the files must not count that prompt as one. + assert usage["turns"] == 3, "counted the second session's prompt as a turn" assert usage["partial"] is True diff --git a/shared/steps/compute-token-usage.sh b/shared/steps/compute-token-usage.sh index ca8dda41..f5200d6d 100755 --- a/shared/steps/compute-token-usage.sh +++ b/shared/steps/compute-token-usage.sh @@ -81,7 +81,8 @@ if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then # without a newline — the truncation case above — would glue its last line # to the next file's first line and `fromjson?` would drop both. awk ends # every file on a newline, so a truncated tail costs only itself. - USAGE=$(awk 1 "${SESSION_FILES[@]}" | jq -R -s -c --arg model "$MODEL" ' + USAGE=$(awk 1 "${SESSION_FILES[@]}" | jq -R -s -c --arg model "$MODEL" \ + --argjson sessions "${#SESSION_FILES[@]}" ' split("\n") | map(fromjson? // empty) | ([.[] | select(.type == "assistant" and .message.id != null) | {id: .message.id, u: .message.usage}] | unique_by(.id)) as $ms | @@ -93,8 +94,10 @@ if [ -z "${USAGE:-}" ] && [ -n "$LOGS_DIR" ] && [ -d "$LOGS_DIR" ]; then output_tokens: ([$ms[].u.output_tokens // 0] | add // 0), cache_creation_input_tokens: ([$ms[].u.cache_creation_input_tokens // 0] | add // 0), cache_read_input_tokens: ([$ms[].u.cache_read_input_tokens // 0] | add // 0), - # The prompt that opens the session is a `user` line but not a turn. - turns: ([([.[] | select(.type == "user")] | length) - 1, 0] | max), + # The prompt that opens a session is a `user` line but not a turn, and + # the files are pooled by the time this runs — so subtract one per + # session, not one overall. + turns: ([([.[] | select(.type == "user")] | length) - $sessions, 0] | max), model: $model, # Only `result.total_cost_usd` carries cost, and that is the event we # do not have. `null` says unknown; a `0` here would repeat the bug