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..70a066bf 100644 --- a/bundles/manual-qa/hooks/scripts/benchmark-stop +++ b/bundles/manual-qa/hooks/scripts/benchmark-stop @@ -24,11 +24,56 @@ # 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, which is what `countTurns()` in +# build-run-metrics.mjs actually wants to count test-run-lead's own turns. +# Resolved below (ported 2026-07-31, together with build-run-metrics.mjs's +# own turns/subagent_dispatches/orchestrator_cost_pct/tokens_by_model/ +# cache_read_share_pct/models_used feature set — this bundle copy used to +# carry a leaner, older subset while knowledge/metrics-format.md already +# documented the fuller schema; this closes that doc/code gap and is also a +# prerequisite for resolve-subagent-traces.mjs, ported the same round — see +# its own header) — same technique the sibling elitea-testing/qa-challenges +# copies already used: 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. +# +# 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 +97,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 +128,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,6 +242,18 @@ 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). node "${HOOK_DIR}/build-run-metrics.mjs" \ "$pre_file" \ @@ -102,7 +262,8 @@ node "${HOOK_DIR}/build-run-metrics.mjs" \ "${sid:-}" \ "$POST_FILE" \ "${session_started_at:-}" \ + "${transcript_path:-}" \ 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/build-run-metrics.mjs b/bundles/manual-qa/hooks/scripts/build-run-metrics.mjs index 8f48d141..7f1d46cf 100644 --- a/bundles/manual-qa/hooks/scripts/build-run-metrics.mjs +++ b/bundles/manual-qa/hooks/scripts/build-run-metrics.mjs @@ -5,7 +5,7 @@ // 3. Latest RUN-*.md report in reports/ (for run_id, suite, result data) // // Usage (called by benchmark-stop hook): -// node build-run-metrics.mjs [session_started_at] +// node build-run-metrics.mjs [session_started_at] [transcript_path] // // Writes: reports/metrics/RUN-YYYY-MM-DD-NNN.json // Appends ## Timing Breakdown / ## ccusage Session Delta sections to @@ -23,6 +23,17 @@ // if other sessions may have run concurrently. // "subagents_only" — no ccusage pre/post data at all; only sub-agent // (tc-trace) token counts are available. +// +// NOTE: kept in sync by hand with the sibling copies at elitea-testing/scripts/ +// and qa-challenges/scripts/ — same logic; only PROJECT_DIR derivation differs +// below, since this copy is installed to .claude/hooks/manual-qa/ by the +// bundle installer instead of staying at /scripts/. Full feature +// parity (turns/subagent_dispatches/orchestrator_cost_pct/tokens_by_model/ +// cache_read_share_pct/scopedModelsUsed/models_used) ported into this bundle +// copy 2026-07-31 — previously a leaner, older subset lived here (no +// countTurns(), no per-model/per-agent breakdown) while +// knowledge/metrics-format.md already documented the fuller schema; this +// port closes that doc/code gap. import { readFileSync, writeFileSync, appendFileSync, readdirSync, existsSync, mkdirSync, statSync } from 'fs'; import { join } from 'path'; @@ -33,7 +44,7 @@ import { join } from 'path'; // not /scripts/. const PROJECT_DIR = process.env.CLAUDE_PROJECT_DIR || process.cwd(); -const [,, preFile, firstDispatchAt, tcTraceFile, sid, postFile, sessionStartedAt] = process.argv; +const [,, preFile, firstDispatchAt, tcTraceFile, sid, postFile, sessionStartedAt, transcriptPath] = process.argv; // --- Read inputs --- @@ -46,6 +57,29 @@ function readJsonFromFd(path) { return readJsonSafe(path); } +// Counts model exchanges ("turns", per the tokenomics-dataset glossary: one +// request<->response exchange) from the Claude Code transcript JSONL that +// the Stop hook payload points to via `transcript_path`. Nothing else in +// this pipeline counts turns today — every other session/ccusage source is +// silent on it. Missing/unreadable transcript -> null, never fatal (hooks +// must not block Claude). +function countTurns(path) { + if (!path || !existsSync(path)) return null; + try { + const lines = readFileSync(path, 'utf8').trim().split('\n').filter(Boolean); + let turns = 0; + for (const line of lines) { + try { + const entry = JSON.parse(line); + if (entry.type === 'assistant') turns++; + } catch { /* skip malformed transcript lines */ } + } + return turns || null; + } catch { + return null; + } +} + const preCcusage = readJsonSafe(preFile); const postCcusage = readJsonFromFd(postFile); @@ -92,19 +126,11 @@ function modelPricingFamily(modelId) { } // Last-known-good literal model ids — used ONLY when ccusage gives us -// nothing at all to resolve a real id from (no scoped session match). These -// WILL go stale the next time Anthropic ships new default models — same as -// every other hand-maintained constant in this file (see header: kept in -// sync by hand across repos). Update by hand when that happens; nothing -// here is self-updating. -// -// NOTE: this bundle copy predates the elitea-testing/qa-challenges sibling -// scripts' `turns` / `subagent_dispatches` / `orchestrator_cost_pct` / -// `tokens_by_model` / `cache_read_share_pct` instrumentation (no -// scopedModelsUsed here either) — that feature gap is a separate, -// larger porting task, not fixed by this change. Only the model-key -// pricing-lookup fix below (this table + modelPricingFamily) was ported -// here, matching what actually exists in this file today. +// nothing at all to resolve a real id from (no scoped session match; see +// scopedModelsUsed below). These WILL go stale the next time Anthropic +// ships new default models — same as every other hand-maintained constant +// in this file (see header: kept in sync by hand across repos). Update by +// hand when that happens; nothing here is self-updating. const FALLBACK_MAIN_AGENT_MODEL_ID = 'claude-sonnet-4-5-20250929'; const FALLBACK_SUPPORT_AGENT_MODEL_ID = 'claude-haiku-4-5-20251001'; @@ -178,7 +204,8 @@ const session = {}; let tokensCoverage = 'subagents_only'; let ccusageBlock = null; let costBlock = null; // populated here for the scoped path; unscoped path fills it in later, once `model` is resolved -let scopedModel = null; // model(s) ccusage says actually ran this session, if we got a scoped match +let scopedModel = null; // model(s) ccusage says actually ran this session, if we got a scoped match (joined string, back-compat) +let scopedModelsUsed = null; // same, as an actual array (tokenomics-dataset `models_used`) const preHasData = Object.keys(preCcusage).length > 0 && (preCcusage.session ?? preCcusage.daily); const postHasData = Object.keys(postCcusage).length > 0 && (postCcusage.session ?? postCcusage.daily); @@ -225,7 +252,10 @@ if (preHasData && postHasData) { if (scoped) { // Real model(s) used, straight from ccusage — may be more than one if // the session mixed models (e.g. a Haiku sub-agent alongside Sonnet). - if (postEntry.modelsUsed?.length) scopedModel = postEntry.modelsUsed.join('+'); + if (postEntry.modelsUsed?.length) { + scopedModel = postEntry.modelsUsed.join('+'); + scopedModelsUsed = postEntry.modelsUsed; + } // Cost from ccusage's own already-priced per-model breakdown — correct // even for mixed-model sessions or offline cached pricing, so we don't @@ -262,6 +292,7 @@ session.pre_flight_duration_ms = (sessionStartMs && firstDispatchMs) : null; session.total_session_duration_ms = sessionStartMs ? endMs - sessionStartMs : null; session.total_tool_uses = tcTraces.reduce((sum, t) => sum + (t.tool_uses ?? 0), 0) || null; +session.turns = countTurns(transcriptPath); // Support-agent aggregates (reporter, etc.) const supportTokens = supportTraces.reduce((s, t) => s + (t.total_tokens ?? 0), 0); @@ -271,12 +302,27 @@ session.support_agent_tokens = supportTokens || null; session.support_agent_tool_uses = supportToolUses || null; session.support_agent_duration_ms = supportDurationMs || null; +// Count of subagent/sub-task dispatches this session (tokenomics-dataset +// field: `subagent_dispatches`) — every Agent-tool call this session made, +// TC runners plus support agents (reporter, etc.) alike. Already implicit +// in the trace file; just never surfaced as its own field before. +session.subagent_dispatches = tcTraces.length + supportTraces.length; + // Orchestrator overhead = total minus TC runners minus support agents const tcTokens = tcTraces.reduce((s, t) => s + (t.total_tokens ?? 0), 0); session.orchestrator_tokens = session.total_tokens != null ? Math.max(0, session.total_tokens - tcTokens - supportTokens) : null; +// Token-based proxy for the tokenomics-dataset field `orchestrator_cost_pct` +// (share of cost on the main thread vs subagents). We don't have a true +// per-dispatch cost split, so this approximates via token share instead — +// close enough here since the orchestrator and TC-runner subagents run the +// same model (sonnet); documented as a proxy, not a real cost split. +session.orchestrator_cost_pct = (session.orchestrator_tokens != null && session.total_tokens) + ? Math.round((session.orchestrator_tokens / session.total_tokens) * 1000) / 10 + : null; + const tcDurationMs = tcTraces.reduce((s, t) => s + (t.duration_ms ?? 0), 0); session.tc_total_duration_ms = tcDurationMs || null; session.orchestrator_duration_ms = session.duration_ms != null @@ -369,6 +415,102 @@ if (session.orchestrator_tokens != null) { } session.tokens_by_agent = Object.keys(tokensByAgent).length ? tokensByAgent : null; +// --- Per-model token breakdown (tokenomics-dataset `tokens_by_model` / +// `cache_read_share_pct`) --- +// +// This system's agents are not single-model: test-reporter runs on haiku, +// every other manual-qa agent (test-run-lead, test-runner, test-sizer, +// test-author, app-profiler) runs on sonnet — see each agent's AGENT.md +// frontmatter `model:` field. benchmark-tc-hook.mjs already tags every +// dispatch's trace line with role: 'test-runner' | 'support', and 'support' +// IS the haiku reporter, so we regroup the trace's own per-type token +// counts (already recorded per dispatch) by role into a per-model +// breakdown — no new instrumentation needed. +// +// The KEYS of that breakdown must be real model ids so they line up with +// `primary_model` / `models_used` downstream (build-tokenomics-report.mjs +// derives primary_model from this map's own keys — see its comment). We +// can't get a real id per dispatch: PostToolUse's Agent tool_response has +// no model/modelUsed field (confirmed against Claude Code's hook docs), so +// benchmark-tc-hook.mjs cannot be made to tag traces with one. Instead we +// take ccusage's own scoped modelsUsed[] for the WHOLE session +// (scopedModelsUsed, resolved above) and assign its haiku-looking entry to +// the support/reporter bucket and its other entry to the main +// orchestrator+runner bucket. Only fall back to a literal last-known-good id +// when ccusage gave us no scoped match at all (full_session_unscoped / +// subagents_only paths). +function resolveAgentModelIds(modelsUsed) { + if (!modelsUsed?.length) { + return { main: FALLBACK_MAIN_AGENT_MODEL_ID, support: FALLBACK_SUPPORT_AGENT_MODEL_ID }; + } + const haikuId = modelsUsed.find(m => /haiku/i.test(m)); + // Single-model session (only test-runner dispatched, no reporter ran; or + // ccusage only ever reports one entry): pick the first non-haiku id, or + // just modelsUsed[0] if every entry happens to look like haiku. + const mainId = modelsUsed.find(m => !/haiku/i.test(m)) ?? modelsUsed[0]; + return { main: mainId, support: haikuId ?? FALLBACK_SUPPORT_AGENT_MODEL_ID }; +} + +function sumTraceField(traces, field) { + return traces.reduce((s, t) => s + (t[field] ?? 0), 0); +} + +let tokensByModel = null; +if (session.total_tokens != null) { + const { main: mainModelId, support: supportModelId } = resolveAgentModelIds(scopedModelsUsed); + + const supportByType = { + input: sumTraceField(supportTraces, 'input_tokens'), + output: sumTraceField(supportTraces, 'output_tokens'), + cache_create: sumTraceField(supportTraces, 'cache_creation_input_tokens'), + cache_read: sumTraceField(supportTraces, 'cache_read_input_tokens'), + }; + // Everything not attributed to the haiku reporter — orchestrator + TC-runner + // subagents — is the main model. + const mainByType = { + input: Math.max(0, (session.input_tokens ?? 0) - supportByType.input), + output: Math.max(0, (session.output_tokens ?? 0) - supportByType.output), + cache_create: Math.max(0, (session.cache_creation_input_tokens ?? 0) - supportByType.cache_create), + cache_read: Math.max(0, (session.cache_read_input_tokens ?? 0) - supportByType.cache_read), + }; + tokensByModel = { [mainModelId]: mainByType }; + if (supportTokens > 0) { + if (supportModelId === mainModelId) { + // Degenerate case: main and support resolved to the SAME id (e.g. a + // modelsUsed[] where every entry looks like haiku). Merge into the + // one bucket instead of letting one key silently clobber the other. + tokensByModel[mainModelId] = { + input: tokensByModel[mainModelId].input + supportByType.input, + output: tokensByModel[mainModelId].output + supportByType.output, + cache_create: tokensByModel[mainModelId].cache_create + supportByType.cache_create, + cache_read: tokensByModel[mainModelId].cache_read + supportByType.cache_read, + }; + } else { + tokensByModel[supportModelId] = supportByType; + } + } +} +session.tokens_by_model = tokensByModel; + +// Cache-read *cost* share (distinct from cache-read *token* share, which +// runs higher — see docs/metrics-framework.md's "cache efficiency"). Uses +// our own MODEL_PRICING table against the per-model breakdown above so +// numerator and denominator come from the same estimate — independent of +// whether the headline session.cost_usd came from ccusage's own scoped +// pricing or our fallback table. +let cacheReadSharePct = null; +if (tokensByModel) { + let totalCostEst = 0; + let cacheReadCostEst = 0; + for (const [modelKey, t] of Object.entries(tokensByModel)) { + const pricing = MODEL_PRICING[modelPricingFamily(modelKey)]; + totalCostEst += calcCost(pricing, t.input, t.output, t.cache_create, t.cache_read); + cacheReadCostEst += (t.cache_read * pricing.cache_read) / 1_000_000; + } + cacheReadSharePct = totalCostEst > 0 ? Math.round((cacheReadCostEst / totalCostEst) * 1000) / 10 : null; +} +session.cache_read_share_pct = cacheReadSharePct; + // --- Locate latest RUN-*.md report to pull run_id and pass/fail data --- function findLatestRunReport() { @@ -459,6 +601,13 @@ if (reportPath) { // default — it reflects what actually ran, including mixed-model sessions. if (scopedModel) model = scopedModel; +// tokenomics-dataset `models_used` — prefer ccusage's own scoped detection +// (real, authoritative); fall back to what we inferred from the trace's +// role split (see tokens_by_model above), then to the single resolved +// `model` string as a last resort. +session.models_used = scopedModelsUsed + ?? (tokensByModel ? Object.keys(tokensByModel) : (model ? [model] : null)); + // --- Build per-TC array --- // Merge trace data with results from report @@ -554,10 +703,11 @@ const output = { writeFileSync(outPath, JSON.stringify(output, null, 2) + '\n'); console.log(`[build-run-metrics] wrote ${outPath}`); -// Durable, append-only ledger of every completed run (unfiltered, on -// purpose — see elitea-testing/qa-challenges sibling copies for rationale). -// A per-run RUN-.json can still be lost to a filesystem mistake or a -// future bug; this file never gets rewritten, only appended to. +// Durable, append-only ledger of every completed run (including the +// unknown-suite/orphaned-session synthetic path above — unfiltered, on +// purpose: any filtering logic here would itself be one more thing that can +// go stale). A per-run RUN-.json can still be lost to a filesystem +// mistake or a future bug; this file never gets rewritten, only appended to. const ledgerPath = join(metricsDir, 'all-runs.jsonl'); appendFileSync(ledgerPath, JSON.stringify(output) + '\n'); console.log(`[build-run-metrics] appended to ${ledgerPath}`); 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 [] [