diff --git a/scripts/engine.sh b/scripts/engine.sh index 77b302f4b..56fd97db6 100644 --- a/scripts/engine.sh +++ b/scripts/engine.sh @@ -496,7 +496,12 @@ run_triage() { # Capture output for token estimation when logging is enabled (tee is a no-op otherwise). local _tok_tmp="" if [ -n "${TOKEN_LOG_FILE:-}" ]; then + unset _ENGINE_USAGE_OUT _tok_tmp="$(mktemp 2>/dev/null || true)" + # Per-call usage-sidecar key: a unique mktemp path, exported so the engine's + # pipeline subshell and _record_engine_tokens agree on it. Unique per call → + # concurrent run_agentic/run_duck (review-one-pr.sh) never collide. + [[ -n "$_tok_tmp" ]] && local -x _ENGINE_USAGE_OUT="${_tok_tmp}.usage" fi while [ "$attempt" -le "$RETRY_MAX_ATTEMPTS" ]; do rc=0 @@ -567,7 +572,12 @@ run_agentic() { local tier="${3:-deep}" local _tok_tmp="" rc=0 if [ -n "${TOKEN_LOG_FILE:-}" ]; then + unset _ENGINE_USAGE_OUT _tok_tmp="$(mktemp 2>/dev/null || true)" + # Per-call usage-sidecar key: a unique mktemp path, exported so the engine's + # pipeline subshell and _record_engine_tokens agree on it. Unique per call → + # concurrent run_agentic/run_duck (review-one-pr.sh) never collide. + [[ -n "$_tok_tmp" ]] && local -x _ENGINE_USAGE_OUT="${_tok_tmp}.usage" fi case "$REVIEW_ENGINE" in claude) @@ -688,7 +698,12 @@ run_duck() { local model="$2" local _tok_tmp="" rc=0 if [ -n "${TOKEN_LOG_FILE:-}" ]; then + unset _ENGINE_USAGE_OUT _tok_tmp="$(mktemp 2>/dev/null || true)" + # Per-call usage-sidecar key: a unique mktemp path, exported so the engine's + # pipeline subshell and _record_engine_tokens agree on it. Unique per call → + # concurrent run_agentic/run_duck (review-one-pr.sh) never collide. + [[ -n "$_tok_tmp" ]] && local -x _ENGINE_USAGE_OUT="${_tok_tmp}.usage" fi case "$DUCK_ENGINE" in claude) @@ -842,7 +857,11 @@ run_writer() { # to stdout, not stderr), so is_rate_limited never fired and fallback engines # were never tried. local _tmp rc=0 + unset _ENGINE_USAGE_OUT _tmp="$(mktemp 2>/dev/null || true)" + # Per-call usage-sidecar key (see run_triage); unique mktemp path shared with + # the engine subshell via export. + [[ -n "$_tmp" ]] && local -x _ENGINE_USAGE_OUT="${_tmp}.usage" case "$REVIEW_ENGINE" in claude) diff --git a/scripts/lib/token-metrics.sh b/scripts/lib/token-metrics.sh index ba22b9f1e..e29facda6 100644 --- a/scripts/lib/token-metrics.sh +++ b/scripts/lib/token-metrics.sh @@ -131,18 +131,26 @@ emit_token_record() { # ───────────────────────────────────────────────────────────────────────────── # _engine_usage_sidecar -# Prints the path of the per-process usage sidecar (empty when TOKEN_LOG_FILE is -# unset). Engine invocations often run inside a `cmd | tee` pipeline — i.e. a -# SUBSHELL — so the LAST_* globals they set never reach the parent. Writing usage -# to this file (the filesystem is shared) lets _record_engine_tokens read it back. -# $$ (shell PID) is constant across pipeline subshells: both the writing left-hand -# side and the reading parent see the same value. Separate background processes -# (e.g. `run_agentic &` forking a new process vs `(run_duck) &` running as a -# subshell) each have a distinct $$, so concurrent tier-2 calls never share a -# sidecar file. +# Prints the path of the per-CALL usage sidecar (empty when TOKEN_LOG_FILE is +# unset). Engine invocations run inside a `cmd | tee` pipeline — i.e. a SUBSHELL — +# so the LAST_* globals they set never reach the parent; writing usage to this file +# (the filesystem is shared) lets _record_engine_tokens read it back. +# +# The key must be unique per concurrent engine call AND identical between the +# writer (the pipeline subshell) and the reader (the calling shell). $$ fails the +# first requirement: review-one-pr.sh backgrounds `run_agentic &` and `(run_duck) &` +# at the same time, and $$ stays the parent PID inside both, so they would collide +# on one sidecar. BASHPID fails the second: it differs between the pipe subshell +# and the caller. So each run_* exports _ENGINE_USAGE_OUT, derived from its own +# per-call mktemp file (unique by construction) and inherited by the pipeline +# subshell. The $$ form is only a fallback for any non-concurrent direct caller. _engine_usage_sidecar() { [ -n "${TOKEN_LOG_FILE:-}" ] || return 0 - printf '%s' "${TOKEN_LOG_FILE}.last-usage.$$" + if [[ -n "${_ENGINE_USAGE_OUT:-}" ]]; then + printf '%s' "$_ENGINE_USAGE_OUT" + else + printf '%s' "${TOKEN_LOG_FILE}.last-usage.$$" + fi } # reset_engine_usage diff --git a/tests/dev-lead/unit/test_engine_writer.bats b/tests/dev-lead/unit/test_engine_writer.bats index 76a5e33d5..e3e281bda 100644 --- a/tests/dev-lead/unit/test_engine_writer.bats +++ b/tests/dev-lead/unit/test_engine_writer.bats @@ -486,6 +486,37 @@ STUB [ "$(jq -r '.output_tokens' < "$log")" = "60" ] } +@test "usage: failed mktemp + stale _ENGINE_USAGE_OUT does NOT reuse the stale sidecar" { + # Regression for the per-call-key fix: run_* clears _ENGINE_USAGE_OUT before + # mktemp, so a failed mktemp falls back to estimation instead of reading a prior + # call's sidecar. Without it, the planted 999/9/9/9 below would be logged. + _source_engine "claude" + export STUB_ENGINE_EXIT=0 + export STUB_ENGINE_RESPONSE="verdict" + local log; log=$(mktemp) + export TOKEN_LOG_FILE="$log" + export TEST_OWNED_TOKEN_LOG="$log" + + # A leftover per-call key + sidecar content from a "previous" call. + local stale; stale="$(mktemp)" + printf '999\t9\t9\t9\n' > "$stale" + export _ENGINE_USAGE_OUT="$stale" + + # Force mktemp to fail inside the engine via a PATH shim. + local shim; shim="$(mktemp -d)" + printf '#!/usr/bin/env bash\nexit 1\n' > "$shim/mktemp" + chmod +x "$shim/mktemp" + + PATH="$shim:$PATH" run run_triage "$TEST_PROMPT" + + rm -rf "$shim"; rm -f "$stale"; unset _ENGINE_USAGE_OUT + [ "$status" -eq 0 ] + # The stale cache figures must NOT appear in the record. + [ "$(jq -r '.cache_read_tokens' < "$log")" != "9" ] + [ "$(jq -r '.cache_creation_tokens' < "$log")" != "9" ] + [ "$(jq -r '.input_tokens' < "$log")" != "999" ] +} + @test "token: run_writer_with_fallback logs the fallback engine (not rate-limited primary)" { _source_engine "claude" export DEV_LEAD_DRY_RUN=false diff --git a/tests/dev-lead/unit/test_token_metrics.bats b/tests/dev-lead/unit/test_token_metrics.bats index 485f2ff07..86123033d 100644 --- a/tests/dev-lead/unit/test_token_metrics.bats +++ b/tests/dev-lead/unit/test_token_metrics.bats @@ -246,10 +246,11 @@ teardown() { [ "$LAST_OUTPUT_TOKENS" = "85" ] # 60 candidates + 25 thoughts } -@test "_engine_usage_sidecar: path includes shell PID to isolate parallel invocations" { - # $$ is constant across pipeline subshells (left-hand side inherits parent PID) - # so both the writing subshell and the reading parent agree on the same path, - # while separate background processes each get their own distinct $$. +@test "_engine_usage_sidecar: fallback path is \$\$-keyed when no per-call key set" { + # Without a per-call _ENGINE_USAGE_OUT the sidecar falls back to a $$-keyed path. + # NOTE: $$ does NOT isolate concurrent background jobs (they share the parent PID) + # — per-call isolation comes from _ENGINE_USAGE_OUT (see the concurrency test). + unset _ENGINE_USAGE_OUT local sidecar sidecar="$(_engine_usage_sidecar)" [ -n "$sidecar" ] @@ -320,3 +321,53 @@ line two' run emit_token_record "pr-review" "triage" "claude" "haiku" 100 0 50 "" [ "$status" -eq 0 ] } + +# ── usage sidecar keying (concurrency safety) ───────────────────────────────── + +@test "_engine_usage_sidecar: uses the exported per-call key when set" { + export _ENGINE_USAGE_OUT="$TOKEN_LOG_FILE.callX.usage" + run _engine_usage_sidecar + unset _ENGINE_USAGE_OUT + [ "$output" = "$TOKEN_LOG_FILE.callX.usage" ] +} + +@test "_engine_usage_sidecar: set-but-empty key falls back to \$\$ (mktemp-failure state)" { + # run_* clears _ENGINE_USAGE_OUT before mktemp; if mktemp fails the key is empty/ + # unset and MUST fall back rather than reuse a prior/inherited key. + export _ENGINE_USAGE_OUT="" + run _engine_usage_sidecar + unset _ENGINE_USAGE_OUT + [ "$output" = "$TOKEN_LOG_FILE.last-usage.$$" ] +} + +@test "_engine_usage_sidecar: empty when TOKEN_LOG_FILE is unset" { + unset TOKEN_LOG_FILE _ENGINE_USAGE_OUT + run _engine_usage_sidecar + [ -z "$output" ] +} + +@test "usage sidecar: concurrent calls sharing \$\$ stay isolated (no cross-read)" { + # Reproduces the review-one-pr.sh pattern: two engine calls backgrounded at once. + # Background subshells share the parent's $$, so a $$-keyed sidecar would collide; + # the per-call _ENGINE_USAGE_OUT (unique mktemp path) must keep them isolated. + local dir; dir="$(mktemp -d)" + printf '%s' '{"result":"a","usage":{"input_tokens":111,"cache_read_input_tokens":1,"cache_creation_input_tokens":2,"output_tokens":11}}' > "$dir/a.json" + printf '%s' '{"result":"b","usage":{"input_tokens":222,"cache_read_input_tokens":3,"cache_creation_input_tokens":4,"output_tokens":22}}' > "$dir/b.json" + ( + export _ENGINE_USAGE_OUT="$dir/A.usage" + parse_engine_usage claude "$dir/a.json" + sleep 0.3 # widen the race window for any colliding writer + cut -f1 < "$(_engine_usage_sidecar)" > "$dir/a.out" + ) & + ( + export _ENGINE_USAGE_OUT="$dir/B.usage" + parse_engine_usage claude "$dir/b.json" + sleep 0.3 + cut -f1 < "$(_engine_usage_sidecar)" > "$dir/b.out" + ) & + wait + local a b; a="$(cat "$dir/a.out")"; b="$(cat "$dir/b.out")" + rm -rf "$dir" + [ "$a" = "111" ] + [ "$b" = "222" ] +} diff --git a/tests/token_report.bats b/tests/token_report.bats index 117447fb1..0421c3897 100644 --- a/tests/token_report.bats +++ b/tests/token_report.bats @@ -162,9 +162,11 @@ setup() { run bash -c " set -euo pipefail source '${BATS_TEST_DIRNAME}/../scripts/token_report.sh' - # Simulate the inner conversion loop for a binary-corrupted source file. + # Simulate the inner conversion loop for a corrupted source file. Use truncated + # JSON, which jq rejects deterministically across versions (jq 1.7 exits 0 on + # NUL bytes, so binary input made this test flaky). f='$tmpdir/bad.jsonl' - printf '\x00\x01\x02\x03' > \"\$f\" + printf '{\"a\":' > \"\$f\" dest='$jsonl_dir/999-bad.jsonl' if jq -c --arg repo 'r' 'select(type==\"object\") | . + {repo: \$repo}' \ \"\$f\" > \"\$dest\" 2>/dev/null; then