From ef5c8565c82e58ec056a89621ce456551ec50455 Mon Sep 17 00:00:00 2001 From: Olexis Date: Fri, 31 Jul 2026 13:29:42 +0300 Subject: [PATCH 1/2] fix(manual-qa): port async-dispatch trace recovery + hook-timing fixes into bundle MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Claude Code's current build dispatches the Agent tool asynchronously (an immediate "launched" acknowledgment, with real per-dispatch usage delivered later via messages on the orchestrator's own transcript) instead of the synchronous, blocking dispatch this pipeline was designed around. Left as-is, that silently breaks per-TC metrics for any project on this bundle re-run today: benchmark-tc-hook.mjs's real-time PostToolUse capture never sees usage data, so tcs[] and tokens_by_agent go empty and the whole session's tokens get misattributed to test-run-lead. The same async-dispatch behavior also makes the SubagentStop hook fire on every orchestrator pause while a background task is still running, not just on the real test-reporter completion, repeatedly wiping in-flight trace data before a suite finishes. A related but separate issue: the ccusage pre-snapshot taken at SessionStart is usually captured before Claude Code's own usage logs have indexed the brand-new session at all, so session-level token/cost figures silently fall back to summing every session on the machine instead of just this run's. All three were root-caused and fixed against real runs in qa-project this week, then synced into elitea-testing/qa-challenges (2026-07-31) — this change ports the same three fixes into the bundle so any project installing manual-qa from here on gets them too: - scripts/resolve-subagent-traces.mjs (new): backfills the tc-trace from the orchestrator transcript's own / blocks instead of trusting benchmark-tc-hook.mjs's real-time capture. Wired into benchmark-stop, which now also resolves the true parent transcript for SubagentStop firings (this bundle copy didn't have that resolution at all yet, unlike elitea-testing/qa-challenges — ported as a prerequisite). - benchmark-stop: re-derives real subagent identity from the payload's own agent_type field (empty string on a premature firing, "test-reporter" only on the genuine completion) instead of trusting the SubagentStop matcher, which doesn't reliably filter on affected Claude Code builds; elapsed-time-since-last-dispatch kept as a secondary net for payload shapes without that field. Debug logging added (gitignored via the existing *.log rule) so any future payload-shape drift is directly observable instead of re-diagnosed from scratch. - scripts/ccusage-wait.sh (new) + its use in benchmark-session-start and benchmark-preflight: retries ccusage session --json for up to 60s of real elapsed time (not a fixed attempt count — an earlier count-based attempt was disproven by real timing data) until this session's own entry appears, instead of a single immediate un-retried call. benchmark-preflight now also verifies session-start's snapshot is actually scoped before reusing it, rather than propagating an unscoped give-up forward. Deliberately NOT touched: build-run-metrics.mjs's turns/tokens_by_model/ subagent_dispatches instrumentation is still absent from this bundle copy (a separate, previously-deferred porting decision, see project memory) — transcript_path is resolved in benchmark-stop only as far as resolve-subagent-traces.mjs needs it, not plumbed into build-run-metrics.mjs itself. hooks/README.md's file count updated (10 -> 12) for the two new scripts; no other docs/behavior changed. Verified end-to-end in isolated scratch directories against real captured data: replayed real SubagentStop payloads (captured live in qa-project) to confirm the premature-firing guard skips correctly and proceeds on the genuine completion; ran resolve-subagent-traces.mjs against a real orchestrator transcript and confirmed its output matches that run's actual Performance Metrics table exactly; ran ccusage-wait.sh against a real, already-indexed session id and confirmed immediate scoped match; ran the full benchmark-stop -> resolve-subagent-traces.mjs -> build-run-metrics.mjs chain and confirmed real per-TC tokens/tool_uses in the output with turns/tokens_by_model correctly still absent (out of scope for this change). --- bundles/manual-qa/hooks/README.md | 2 +- .../hooks/scripts/benchmark-preflight | 78 +++++++- .../hooks/scripts/benchmark-session-start | 37 +++- .../manual-qa/hooks/scripts/benchmark-stop | 172 +++++++++++++++++- .../manual-qa/hooks/scripts/ccusage-wait.sh | 111 +++++++++++ .../hooks/scripts/resolve-subagent-traces.mjs | 151 +++++++++++++++ 6 files changed, 538 insertions(+), 13 deletions(-) create mode 100644 bundles/manual-qa/hooks/scripts/ccusage-wait.sh create mode 100644 bundles/manual-qa/hooks/scripts/resolve-subagent-traces.mjs diff --git a/bundles/manual-qa/hooks/README.md b/bundles/manual-qa/hooks/README.md index acb33b9e..85d98822 100644 --- a/bundles/manual-qa/hooks/README.md +++ b/bundles/manual-qa/hooks/README.md @@ -30,7 +30,7 @@ This merges 5 hook events (`SessionStart`, `PreToolUse`, `PostToolUse`, `SubagentStop`, `SessionEnd`) into `.claude/settings.json` under groups tagged `"_bundle": "manual-qa"` (merge-not-clobber — your other hooks and other bundles' hooks are left untouched; `.claude/settings.json.bak` is -written first), and copies 10 files into `.claude/hooks/manual-qa/`. +written first), and copies 12 files into `.claude/hooks/manual-qa/`. Nothing in `agents/` or `skills/` is touched — this is additive only. ## What to expect after a run diff --git a/bundles/manual-qa/hooks/scripts/benchmark-preflight b/bundles/manual-qa/hooks/scripts/benchmark-preflight index 29c456e0..9db1b7fb 100644 --- a/bundles/manual-qa/hooks/scripts/benchmark-preflight +++ b/bundles/manual-qa/hooks/scripts/benchmark-preflight @@ -2,14 +2,49 @@ # PreToolUse[Agent] hook — fires before every sub-agent call. # On the first call of a session: captures first_dispatch_at timestamp, # resolves a ccusage pre-snapshot, then creates the benchmark state file. -# Subsequent calls are no-ops (state file already exists). +# Subsequent calls are no-ops for THAT part (state file already exists) but +# still refresh LAST_DISPATCH_FILE below — see its own comment for why. # # Files are scoped by session_id (2026-07-22 fix) — see benchmark-session-start # for why (prevents concurrent-session/test-fixture collisions). +# +# RETRY-FOR-SCOPING RACE (ported 2026-07-31 from qa-project, round 4): +# benchmark-session-start now retry-waits for `ccusage session --json` to +# actually contain this session's own entry before writing SESSION_PRE_FILE +# — see ccusage-wait.sh for the timing evidence and why session-start's own +# retry can still, legitimately, sometimes come back empty-handed (its retry +# budget is bounded; the gap it's racing against isn't fully understood yet +# — see that file). +# +# That means SESSION_PRE_FILE existing is NOT the same thing as it being +# actually SCOPED — it may be session-start's own unscoped give-up snapshot. +# Blindly `cp`-ing it forward (the old behavior) would propagate that failure +# into this run's real metrics even though, empirically, a real dispatch +# fires WAY later than session start (48s in the one real case measured so +# far) — by which point the session has near-certainly already appeared in +# ccusage (its own first usage entry showed up in ~2-3s in every real sample +# collected). So: check whether SESSION_PRE_FILE is actually scoped before +# trusting it; if not, this hook gets its OWN, much-later-timed shot via the +# same retry helper rather than inheriting session-start's early failure. +# +# Both this hook and session-start are registered `async: true`, so a fast +# orchestrator's first dispatch can also fire before session-start's own +# retry loop has finished AT ALL (SESSION_PRE_FILE doesn't exist yet) — same +# fix applies there too (see the `elif` below). Worst case this means two +# independent `ccusage session --json` retry loops run briefly in parallel — +# wasteful in CLI calls, not incorrect (each just converges to whatever it +# finds); simpler than adding a separate "wait for the OTHER hook's file +# instead" coordination layer for a race this narrow. set -euo pipefail PROJECT_DIR="${CLAUDE_PROJECT_DIR:-$PWD}" STATE_DIR="${PROJECT_DIR}/.claude" +# ccusage-wait.sh lives next to this script (bundle-installed), not at +# /scripts/ — resolve self-relatively, same pattern benchmark-stop +# already uses for build-run-metrics.mjs. +HOOK_DIR="$(cd "$(dirname "$0")" && pwd)" +# shellcheck source=ccusage-wait.sh +. "${HOOK_DIR}/ccusage-wait.sh" payload="$(cat 2>/dev/null || true)" sid="$(printf '%s' "$payload" | node -e " @@ -25,8 +60,21 @@ STATE_FILE="${STATE_DIR}/benchmark-state${SID_SUFFIX}.json" TRACE_FILE="${STATE_DIR}/benchmark-tc-trace${SID_SUFFIX}.jsonl" PRE_FILE="${STATE_DIR}/benchmark-pre${SID_SUFFIX}.json" SESSION_PRE_FILE="${STATE_DIR}/benchmark-session-pre${SID_SUFFIX}.json" +LAST_DISPATCH_FILE="${STATE_DIR}/benchmark-last-dispatch-at${SID_SUFFIX}.txt" +CCUSAGE_WAIT_DEBUG_LOG="${STATE_DIR}/benchmark-ccusage-wait-debug.log" + +# Refresh on EVERY dispatch (ported 2026-07-31 from qa-project — see +# benchmark-stop's own "PREMATURE-FIRING GUARD" comment for the full +# incident writeup). Cheap unconditional write, independent of the +# first-dispatch-only STATE_FILE init below: benchmark-stop uses "how long +# since the most recent dispatch" to tell a genuine test-reporter completion +# (always 40s+ in every real sample collected) apart from a premature +# same-tool-call-cycle firing (always under 12s in every real sample +# collected) — see that script. +mkdir -p "$STATE_DIR" +date -u +%Y-%m-%dT%H:%M:%SZ > "$LAST_DISPATCH_FILE" 2>/dev/null || true -# Only act on the first dispatch of this session. +# Only act on the first dispatch of this session for everything below. [ -f "$STATE_FILE" ] && exit 0 mkdir -p "$STATE_DIR" @@ -40,9 +88,33 @@ first_dispatch_at="$(date -u +%Y-%m-%dT%H:%M:%SZ)" # from this dispatch onward, matching the old behavior) if session-start's # snapshot isn't there — e.g. that hook wasn't wired, or this project was # updated mid-session and only got the new benchmark-preflight. -if [ -f "$SESSION_PRE_FILE" ]; then +session_pre_is_scoped=0 +if [ -f "$SESSION_PRE_FILE" ] && [ -n "$sid" ]; then + if node -e " + try{ + const p=JSON.parse(require('fs').readFileSync('${SESSION_PRE_FILE}','utf8')); + process.exit((p.session||[]).some(s=>s.period==='${sid}')?0:1); + }catch{process.exit(1);} + " 2>/dev/null; then + session_pre_is_scoped=1 + fi +fi + +if [ "$session_pre_is_scoped" = 1 ]; then + cp "$SESSION_PRE_FILE" "$PRE_FILE" +elif [ -n "$sid" ]; then + # Either session-start hasn't written SESSION_PRE_FILE yet (race), or it + # did but gave up unscoped (see header note) — this hook's own, later + # timing gives it a much better real shot; retry fresh rather than + # inheriting session-start's outcome either way. + wait_for_scoped_ccusage "$sid" "$PRE_FILE" "$CCUSAGE_WAIT_DEBUG_LOG" "preflight-fallback" || true +elif [ -f "$SESSION_PRE_FILE" ]; then + # No session_id to retry-match against, but session-start's snapshot + # (unscoped or not) is still better than nothing. cp "$SESSION_PRE_FILE" "$PRE_FILE" else + # No session_id and no session-start snapshot at all -- nothing to + # retry-match against, one immediate snapshot as last resort. ccusage session --json > "$PRE_FILE" 2>/dev/null \ || printf '{}' > "$PRE_FILE" fi diff --git a/bundles/manual-qa/hooks/scripts/benchmark-session-start b/bundles/manual-qa/hooks/scripts/benchmark-session-start index d6c6d9c3..f262738c 100644 --- a/bundles/manual-qa/hooks/scripts/benchmark-session-start +++ b/bundles/manual-qa/hooks/scripts/benchmark-session-start @@ -18,10 +18,31 @@ # correctly re-baselines too, matching Claude Code's own semantics (today, # with fixed filenames, /clear did NOT reset the baseline — a deliberate # behavior improvement, confirmed with Olha). +# +# RETRY-FOR-SCOPING (ported 2026-07-31 from qa-project, round 4): this hook +# fires at the very first moment of a brand-new session, before Claude +# Code's own usage logs (which ccusage reads from) have anything for this +# session id yet — a single un-retried `ccusage session --json` call here +# almost always misses its own session's `period` entry, silently degrading +# every downstream token/cost figure to "full_session_unscoped" (summed +# across every session ever recorded on the machine — confirmed on a real +# qa-project run, and confirmed AGAIN on the very next real run after an +# initial attempt-count-based retry fix — see ccusage-wait.sh for the full +# incident writeup: what actually failed wasn't the timing estimate, still +# unresolved is whether `sleep` reliably blocks in this hook's real +# execution context). See ccusage-wait.sh (sourced below) for the retry +# mechanism itself and why benchmark-preflight now does more than just +# reuse SESSION_PRE_FILE when it exists. set -euo pipefail PROJECT_DIR="${CLAUDE_PROJECT_DIR:-$PWD}" STATE_DIR="${PROJECT_DIR}/.claude" +# ccusage-wait.sh lives next to this script (bundle-installed), not at +# /scripts/ — resolve self-relatively, same pattern benchmark-stop +# already uses for build-run-metrics.mjs. +HOOK_DIR="$(cd "$(dirname "$0")" && pwd)" +# shellcheck source=ccusage-wait.sh +. "${HOOK_DIR}/ccusage-wait.sh" payload="$(cat 2>/dev/null || true)" sid="$(printf '%s' "$payload" | node -e " @@ -35,12 +56,24 @@ SID_SUFFIX="${sid:+-$sid}" # empty sid -> empty suffix -> today's exact fi TS_FILE="${STATE_DIR}/benchmark-session-started-at${SID_SUFFIX}.txt" SESSION_PRE_FILE="${STATE_DIR}/benchmark-session-pre${SID_SUFFIX}.json" +CCUSAGE_WAIT_DEBUG_LOG="${STATE_DIR}/benchmark-ccusage-wait-debug.log" mkdir -p "$STATE_DIR" if [ ! -f "$TS_FILE" ]; then date -u +%Y-%m-%dT%H:%M:%SZ > "$TS_FILE" 2>/dev/null || true - ccusage session --json > "$SESSION_PRE_FILE" 2>/dev/null \ - || printf '{}' > "$SESSION_PRE_FILE" + if [ -n "$sid" ]; then + # async: true in hooks.json -- this hook never blocks the user's + # interactive session, so it's safe to spend up to the full budget here + # (currently 60s of real elapsed time, not attempt-count-based -- see + # ccusage-wait.sh header for why that changed). + wait_for_scoped_ccusage "$sid" "$SESSION_PRE_FILE" "$CCUSAGE_WAIT_DEBUG_LOG" "session-start" || true + else + # No session_id on this payload at all (older Claude Code / unusual + # invocation) -- nothing to retry-match against, take one snapshot as + # before rather than burning the full retry window for nothing. + ccusage session --json > "$SESSION_PRE_FILE" 2>/dev/null \ + || printf '{}' > "$SESSION_PRE_FILE" + fi # Opportunistic cleanup: remove session-scoped ephemeral files older than 7 # days — left behind by sessions that crashed/were force-killed before ever diff --git a/bundles/manual-qa/hooks/scripts/benchmark-stop b/bundles/manual-qa/hooks/scripts/benchmark-stop index b05d4433..f310c145 100644 --- a/bundles/manual-qa/hooks/scripts/benchmark-stop +++ b/bundles/manual-qa/hooks/scripts/benchmark-stop @@ -24,11 +24,51 @@ # possibly much later. Round 2 (this version) adds `SubagentStop` as the # precise, immediate anchor, keeping `SessionEnd` only as a fallback. # -# (This bundle copy doesn't plumb transcript_path through to -# build-run-metrics.mjs at all yet — see the sibling elitea-testing/ -# qa-challenges copies for the transcript_path resolution SubagentStop needs, -# since its own transcript_path points at the reporter's own transcript, not -# the orchestrator's. Not applicable here until that feature gap is ported.) +# `SubagentStop`'s own `transcript_path` field points at the dispatched +# subagent's OWN (small) transcript — e.g. test-reporter's — not the +# orchestrator's main thread. Resolved below (ported 2026-07-31 from the +# sibling elitea-testing/qa-challenges copies) so resolve-subagent-traces.mjs +# (also ported this round — see its own header) has the right transcript to +# read. NOTE: this is a narrower port than those two siblings' own +# transcript_path handling — this bundle copy's build-run-metrics.mjs still +# does NOT accept/consume a transcript_path argument at all (no `turns`/ +# `countTurns()` here — that's a separate, previously-deferred feature gap, +# out of scope for this change) — transcript_path is resolved here ONLY for +# resolve-subagent-traces.mjs's sake, not passed through to +# build-run-metrics.mjs's own invocation below. +# +# PREMATURE-FIRING GUARD (ported 2026-07-31 from qa-project, where this was +# found and fixed across three rounds — full incident writeup kept there, +# summarized here): the `matcher: "test-reporter"` filter configured in +# hooks.json for this SubagentStop binding does NOT reliably restrict +# firings to test-reporter dispatches on newer Claude Code builds — observed +# firing repeatedly per session, on every orchestrator pause while a +# dispatched task was still running in the background, not on actual +# sub-agent completions. This is a Claude-Code-runtime-level behavior, not a +# project-specific bug, so it applies to any project installing this bundle +# too, once re-run under the same Claude Code version. +# +# Fix: re-derive the real subagent identity from the payload's own +# `agent_type` field rather than trusting the matcher. Ground-truth real-run +# evidence (qa-project, 2026-07-30): this field is always PRESENT on +# affected builds, but `""` (empty string) on every premature firing and the +# real dispatched name ("test-reporter") only on the one genuine completion +# — a naive `if (p[k])` truthy check treats `""` as "not found" and fails +# open, so the empty-string case must be handled explicitly ("not-done", not +# "unknown"). Also tried gating on the payload's `background_tasks: +# [{id, status, ...}]` list (any `status: "running"` entry meaning "not +# really done") — DISPROVEN on the same real log: the ONE genuine +# test-reporter completion still carried background_tasks showing ITS OWN +# task as `status: "running"` (a snapshot-ordering quirk), which would have +# false-positive-skipped the one firing actually wanted. Not used here +# either, for the same reason. A secondary, field-independent signal (elapsed +# wall-clock time since the session's most-recent Agent dispatch) is kept as +# a fallback net for payload shapes with no agent-identity field at all. +# +# DEBUG LOGGING: every SubagentStop firing's raw payload is appended to +# benchmark-stop-debug.log (gitignored scratch, not part of any commit) — +# this is what confirmed the real field/value behavior above; kept on so any +# future payload-shape change surfaces the same way. # # Files are scoped by session_id (2026-07-22 fix, round 3) — see # benchmark-session-start for why (prevents concurrent-session/test-fixture @@ -52,14 +92,28 @@ STATE_DIR="${PROJECT_DIR}/.claude" # back-compat, legacy unscoped) to actually process. compgen -G "${STATE_DIR}/benchmark-tc-trace*.jsonl" > /dev/null 2>&1 || exit 0 -# Read hook payload for session_id (field may be absent — that's fine). +# Read hook payload for hook_event_name/session_id/transcript_path (fields +# may be absent — that's fine, downstream treats all as optional). payload="$(cat 2>/dev/null || true)" +hook_event_name="$(printf '%s' "$payload" | node -e " + const c=[];process.stdin.on('data',d=>c.push(d)); + process.stdin.on('end',()=>{ + try{const p=JSON.parse(Buffer.concat(c).toString()); + console.log(p.hook_event_name||'');}catch{}process.exit(0); + });" 2>/dev/null || true)" sid="$(printf '%s' "$payload" | node -e " const c=[];process.stdin.on('data',d=>c.push(d)); process.stdin.on('end',()=>{ try{const p=JSON.parse(Buffer.concat(c).toString()); console.log(p.session_id||p.sessionId||'');}catch{}process.exit(0); });" 2>/dev/null || true)" +transcript_path="$(printf '%s' "$payload" | node -e " + const c=[];process.stdin.on('data',d=>c.push(d)); + process.stdin.on('end',()=>{ + try{const p=JSON.parse(Buffer.concat(c).toString()); + console.log(p.transcript_path||'');}catch{}process.exit(0); + });" 2>/dev/null || true)" + sid="${sid//[^A-Za-z0-9._-]/}" SID_SUFFIX="${sid:+-$sid}" @@ -69,11 +123,100 @@ PRE_FILE="${STATE_DIR}/benchmark-pre${SID_SUFFIX}.json" POST_FILE="${STATE_DIR}/benchmark-post${SID_SUFFIX}.json" SESSION_PRE_FILE="${STATE_DIR}/benchmark-session-pre${SID_SUFFIX}.json" SESSION_STARTED_AT_FILE="${STATE_DIR}/benchmark-session-started-at${SID_SUFFIX}.txt" +LAST_DISPATCH_FILE="${STATE_DIR}/benchmark-last-dispatch-at${SID_SUFFIX}.txt" +DEBUG_LOG="${STATE_DIR}/benchmark-stop-debug.log" + +# DEBUG LOGGING — see header note. Best-effort, never fatal. +{ + printf '[%s] hook_event_name=%s sid=%s\n' "$(date -u +%Y-%m-%dT%H:%M:%SZ)" "${hook_event_name:-}" "${sid:-}" + printf ' raw payload: %s\n' "$payload" +} >> "$DEBUG_LOG" 2>/dev/null || true + +# PREMATURE-FIRING GUARDS — see header note. Both guards are SubagentStop- +# only; SessionEnd (matcher "*") always proceeds unfiltered, same as before. +if [ "$hook_event_name" = "SubagentStop" ]; then + # Primary: agent-identity re-check. Three-way result: "not-done" (positive + # premature signal — field present but empty) / "mismatch" (some OTHER + # agent's real completion) / "unknown" (field(s) absent entirely — fail + # open, same safety net as before). Deliberately does NOT look at + # background_tasks (tried, disproven — see header note). + guard_verdict="$(printf '%s' "$payload" | node -e " + const c=[];process.stdin.on('data',d=>c.push(d)); + process.stdin.on('end',()=>{ + try{ + const p=JSON.parse(Buffer.concat(c).toString()); + const keys=['agent_type','subagent_type','agentType','agent_name','agentName','name']; + for (const k of keys) { + if (k in p) { + const v = p[k]; + if (v === '') { console.log('not-done'); process.exit(0); } + if (v) { console.log(v === 'test-reporter' ? 'match' : 'mismatch:' + v); process.exit(0); } + } + } + console.log('unknown'); + }catch{ console.log('unknown'); } + process.exit(0); + });" 2>/dev/null || echo unknown)" + case "$guard_verdict" in + not-done) + printf ' [guard] SKIP (agent_type present but empty -- not yet a real completion)\n' >> "$DEBUG_LOG" 2>/dev/null || true + exit 0 + ;; + mismatch:*) + printf ' [guard] SKIP (agent-type mismatch: %s)\n' "${guard_verdict#mismatch:}" >> "$DEBUG_LOG" 2>/dev/null || true + exit 0 + ;; + match) + : # genuine test-reporter completion — proceed + ;; + unknown) + : # no usable signal on this payload shape — fall through to secondary net + ;; + esac + + # Secondary net: elapsed-time re-check — only reached when the above found + # no usable field at all ("unknown"). Real-data-derived threshold from + # qa-project (2026-07-30): every premature firing landed 8-12s after the + # most recent dispatch, every genuine completion took 40s+. + if [ "$guard_verdict" = "unknown" ] && [ -f "$LAST_DISPATCH_FILE" ]; then + last_dispatch_at="$(cat "$LAST_DISPATCH_FILE" 2>/dev/null || true)" + if [ -n "$last_dispatch_at" ]; then + now_epoch="$(date -u +%s)" + last_epoch="$(date -u -d "$last_dispatch_at" +%s 2>/dev/null || true)" + if [ -n "$last_epoch" ]; then + elapsed_ms=$(( (now_epoch - last_epoch) * 1000 )) + PREMATURE_FIRING_THRESHOLD_MS=20000 + if [ "$elapsed_ms" -lt "$PREMATURE_FIRING_THRESHOLD_MS" ]; then + printf ' [guard] SKIP (elapsed %sms since last dispatch, threshold %sms)\n' "$elapsed_ms" "$PREMATURE_FIRING_THRESHOLD_MS" >> "$DEBUG_LOG" 2>/dev/null || true + exit 0 + fi + fi + fi + fi +fi + +printf ' [guard] PROCEED (build-run-metrics will run)\n' >> "$DEBUG_LOG" 2>/dev/null || true # Nothing to do if THIS session's (scoped) trace doesn't exist — e.g. the # pre-check above matched a *different* session's legacy/scoped trace file. [ -f "$TRACE_FILE" ] || exit 0 +# SubagentStop's own transcript_path is the REPORTER's own (small) transcript +# — useless for resolve-subagent-traces.mjs, which needs the ORCHESTRATOR's +# main thread (that's where Claude Code delivers usage +# data for async Agent dispatches — see that script's header). Claude Code +# names a session's MAIN transcript ".jsonl" directly under +# ~/.claude/projects//, while subagent transcripts live one +# level deeper under "/subagents/agent-*.jsonl" — so find the +# parent by searching for a file named after the session id (a UUID, unique +# per machine) rather than re-deriving Claude Code's own project-slug +# algorithm. Falls back to empty (same as today when transcript_path is +# simply absent) if nothing matches — never fatal. +if [ "$hook_event_name" = "SubagentStop" ] && [ -n "${sid:-}" ]; then + parent_transcript="$(find "${HOME:-$USERPROFILE}/.claude/projects" -maxdepth 2 -name "${sid}.jsonl" 2>/dev/null | head -n1 || true)" + [ -n "$parent_transcript" ] && transcript_path="$parent_transcript" +fi + # Read state written by benchmark-preflight / benchmark-tc. first_dispatch_at="" pre_file="$PRE_FILE" @@ -94,7 +237,22 @@ session_started_at="$(cat "$SESSION_STARTED_AT_FILE" 2>/dev/null || true)" ccusage session --json > "$POST_FILE" 2>/dev/null \ || printf '{}' > "$POST_FILE" +# Backfill/rebuild the tc-trace from the main transcript's own +# messages (see resolve-subagent-traces.mjs header for +# the full incident writeup — benchmark-tc-hook.mjs's real-time PostToolUse +# capture doesn't work under async Agent dispatch, but each dispatch's real +# usage numbers are still reliably delivered to the orchestrator's own +# transcript once the sub-agent finishes, regardless of dispatch model). +# No-op (leaves TRACE_FILE as-is) if it can't find anything — never fatal, +# never blocks the fallback SessionEnd path. +if [ -n "${transcript_path:-}" ]; then + node "${HOOK_DIR}/resolve-subagent-traces.mjs" "$transcript_path" "$TRACE_FILE" 2>/dev/null || true +fi + # Assemble metrics (errors are non-fatal — hook must not block Claude). +# NOTE: transcript_path is deliberately NOT passed here — see header note, +# this bundle copy's build-run-metrics.mjs doesn't accept/consume it (no +# turns/countTurns() here yet, a separate deferred feature gap). node "${HOOK_DIR}/build-run-metrics.mjs" \ "$pre_file" \ "$first_dispatch_at" \ @@ -105,4 +263,4 @@ node "${HOOK_DIR}/build-run-metrics.mjs" \ 2>/dev/null || true # Clean up session state so the next run starts fresh. -rm -f "$STATE_FILE" "$TRACE_FILE" "$PRE_FILE" "$POST_FILE" "$SESSION_STARTED_AT_FILE" "$SESSION_PRE_FILE" +rm -f "$STATE_FILE" "$TRACE_FILE" "$PRE_FILE" "$POST_FILE" "$SESSION_STARTED_AT_FILE" "$SESSION_PRE_FILE" "$LAST_DISPATCH_FILE" diff --git a/bundles/manual-qa/hooks/scripts/ccusage-wait.sh b/bundles/manual-qa/hooks/scripts/ccusage-wait.sh new file mode 100644 index 00000000..f8e8300f --- /dev/null +++ b/bundles/manual-qa/hooks/scripts/ccusage-wait.sh @@ -0,0 +1,111 @@ +#!/usr/bin/env bash +# Shared helper — sourced by benchmark-session-start (primary caller) and +# benchmark-preflight (fallback caller, when session-start's own snapshot +# isn't ready yet / isn't actually scoped). Not itself a hook; not +# registered in settings.json. +# +# WHY THIS EXISTS (found 2026-07-30, qa-project debug session, round 4): +# build-run-metrics.mjs's ccusage scoping (session.tokens_coverage == +# "full_session") requires an entry with `period === sid` in BOTH the pre +# and post `ccusage session --json` snapshots. The pre snapshot used to be +# taken with a single, un-retried `ccusage session --json` call at the very +# first moment of a brand-new session — before Claude Code's own usage logs +# (which ccusage reads from) necessarily have anything for this session id +# yet. Confirmed live (RUN-2026-07-30-020): pre-side lookup missed, session +# fell back to "full_session_unscoped" (delta summed across every session +# ever recorded on the machine). +# +# ROUND 4a (first attempt, attempt-count-based retry, DISPROVEN): measured +# three real sessions' "first transcript line -> first ccusage-visible usage +# entry" gap at 2.76s/2.92s/3.20s and built a 15-attempts-x-1s-sleep loop +# around that. On the very next real run (RUN-2026-07-30-021, sid +# 3e5468e5-...) it still came back unscoped — debug log claimed "NOT found +# after 15 attempts (~15s)" at a wall-clock timestamp only ~2s after that +# session's own first transcript line. That's not possible if the loop +# genuinely spent ~15-30s on 15 real sleep+ccusage cycles — either `sleep 1` +# isn't reliably blocking for a full second in this hook's real execution +# context (spawned via the cmd.exe -> bash.exe chain in run-hook.cmd, +# `async: true`), or something else about that environment behaves +# differently than a directly-sourced/called test of this same function +# (confirmed: three different attempts to replicate the exact real spawn +# chain from outside gave three DIFFERENT behaviors — one hung 2+ minutes, +# one silently failed to parse stdin/sid at all — inconclusive, not a clean +# repro either way). +# +# ROUND 4b (this version): rather than keep guessing at what's wrong with +# attempt-count timing in that execution context, made the loop's exit +# condition REAL WALL-CLOCK ELAPSED TIME (checked via `date +%s` every +# iteration) instead of a fixed attempt count. This is robust regardless of +# whether `sleep` blocks correctly or whether each `ccusage` call's own cost +# drifts over the session (both measured to become real possibilities, not +# separately proven or disproven) — if sleep is broken, the loop just spins +# through more ccusage calls faster instead of fewer, but still can't exit +# before TOTAL_BUDGET_S of real time has genuinely elapsed. Total budget +# raised to 60s (from a real ~15-30s design) purely as safety margin given +# the round-4a evidence undermines confidence in any tightly-tuned number; +# every attempt's own timestamp + elapsed-so-far is now logged (not just the +# final outcome) so the NEXT real run gives unambiguous ground truth on +# which failure mode (if any) is real, instead of another indirect +# inference. +# +# Usage: wait_for_scoped_ccusage [] [