From 2a8ff8530e2062723cc643321e0f7a9c1401e75a Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Mon, 31 Aug 2026 13:26:31 -0400 Subject: [PATCH 01/16] feat(bin): add the fleet usage ledger harvester and report reader Record what each finished task actually cost. bin/fm-usage-harvest.sh appends one JSON line per harvested task to the gitignored data/usage-ledger.jsonl, and bin/fm-usage-report.sh renders that ledger as a per-model and per-task cost report. The harvester's header is the sole owner of the line schema and of every per-harness usage source. Token usage is read from each worker's own session log. claude sums per-request usage from the encoded project directory, deduping on .message.id because Claude logs one entry per content block. codex sums per-turn token_count deltas from sessions whose recorded cwd matches the task worktree. pi and pi-signed run the same Pi application over one ~/.pi/agent state tree, so one scan covers both: each assistant message record carries one request's usage, bound to the task by the cwd in the log's own session record, with the model reported provider-qualified to match the spelling fm-spawn records in task metadata. Every other harness, a task with a recorded remote_host, and any scan that yields no assistant usage report null tokens with source unavailable, so an available source asserts the same thing for all three parsers. The task window runs from the epoch embedded in the meta's spawn_gen incarnation token to the last status append. Metadata modification time is deliberately not a start source: later writes such as PR registration move it forward to near the end of the task, which collapsed the window to zero and dropped every session log. A relaunch narrows nothing below the turn count's own span, and a start later than the end is pinned rather than inverting the window. Teardown harvests before retiring the task's status presentation, because that retirement deletes state/.status, which supplies both the window and the turn count. The harvest is best effort: a failure warns on stderr and never blocks teardown. Parsers skip a malformed or non-object log line rather than losing the rest of the file, and both the harvester and the report read their TSV rows without collapsing empty fields, so an absent model or harness cannot shift the token columns. --- AGENTS.md | 1 + bin/fm-teardown.sh | 15 + bin/fm-usage-harvest.sh | 438 +++++++++++++++ bin/fm-usage-report.sh | 81 +++ docs/scripts.md | 2 + tests/fm-usage-harvest.test.sh | 949 +++++++++++++++++++++++++++++++++ 6 files changed, 1486 insertions(+) create mode 100755 bin/fm-usage-harvest.sh create mode 100755 bin/fm-usage-report.sh create mode 100755 tests/fm-usage-harvest.test.sh diff --git a/AGENTS.md b/AGENTS.md index d7381427a9e..7b6c87403d4 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -88,6 +88,7 @@ data/ personal fleet records; LOCAL, gitignored as a whole learnings.md fleet-local operational facts and gotchas; LOCAL, gitignored; dated, evidence-backed, curated, and updated with inspect-then-update - rewrite and prune rather than append forever, the same contract as captain.md; created lazily, absent until this home has a learning to store projects.md thin fleet navigation registry recording each project's standing delivery posture; firstmate-private, parsed for mechanical sync and seeding by fm-project-mode.sh (section 6) secondmates.md local and remote secondmate routing table; firstmate-private, maintained by the secondmate seed helpers (section 6) + usage-ledger.jsonl append-only fleet cost ledger, one JSON line per harvested task; written only by bin/fm-usage-harvest.sh, whose header owns the line schema, alongside its .usage-ledger.lock append lock, and read by bin/fm-usage-report.sh /brief.md per-task crewmate brief, or per-secondmate charter brief when kind=secondmate /report.md scout task deliverable, written by the crewmate; survives teardown projects/ cloned repos; gitignored; read-only except under hard rule 1's concrete captain-approved project operation exception diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index e200bc80b0f..d79bc16edcc 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -1,6 +1,9 @@ #!/usr/bin/env bash # Tear down a finished task: return the treehouse worktree, release the Orca # worktree, or retire a secondmate home; kill the recorded runtime endpoint, +# harvest the task's fleet usage-ledger row while its state files still exist +# (best effort: bin/fm-usage-harvest.sh owns that ledger, and a harvest failure +# only warns on stderr rather than blocking teardown), # clear volatile state, and transition this home's backlog item for ship and # scout tasks before reporting success (a secondmate teardown transitions none, # since secondmates are not backlog items), then refresh/prune the project's @@ -710,6 +713,12 @@ remote_secondmate_teardown() { tmp="$SECONDMATE_REG.tmp.$$" grep -vE "^- $ID( |$)" "$SECONDMATE_REG" > "$tmp" || true mv -f -- "$tmp" "$SECONDMATE_REG" + # Best-effort fleet usage harvest runs while the task's state files still + # exist. It must precede the status retirement below, which deletes + # state/.status: without that log the harvest has no task window and no + # turn count. A harvest failure must never block teardown. + "$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ + || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 status_retire_presentation_task "$STATE" "$ID" || return 1 fm_backlog_atomic_transition remove "$STATE/$ID.meta" "task record" "$STATE" || return 1 rm -f -- "$STATE/$ID.turn-ended" @@ -2912,6 +2921,12 @@ fm_backend_clear_transition "$BACKEND" "$STATE" "$T" || true [ -n "$TASK_TMP" ] && rm -rf "$TASK_TMP" remove_pr_poll_artifacts "$STATE" "$ID" || exit 1 retire_busy_state "$STATE" "$ID" "$BUSY_GEN" || exit 1 +# Best-effort fleet usage harvest runs while the task's state files still +# exist. It must precede the status retirement below, which deletes +# state/.status: without that log the harvest has no task window and no +# turn count. A harvest failure must never block teardown. +"$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ + || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 status_retire_presentation_task "$STATE" "$ID" || exit 1 rm -f "$STATE/$ID.turn-ended" \ "$STATE/$ID.pi-ext.ts" "$STATE/$ID.grok-turnend-token" \ diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh new file mode 100755 index 00000000000..c0b3fe83cbe --- /dev/null +++ b/bin/fm-usage-harvest.sh @@ -0,0 +1,438 @@ +#!/usr/bin/env bash +# fm-usage-harvest.sh - append one fleet usage-ledger row for a finished task. +# +# Usage: fm-usage-harvest.sh +# +# Reads state/.meta (harness=, model=, effort=, worktree=; the +# backend window= line is intentionally not consumed because the ledger has no +# window field) plus the task's state/.status timestamps for the task +# window, then sums the worker's own session-log usage into exactly one JSON +# line appended to data/usage-ledger.jsonl. data/usage-ledger.jsonl is +# gitignored runtime data. +# +# Ledger line schema (this file is the single owner of that schema; the +# report script is a consumer): +# {"task":,"harness":,"model":,"effort":, +# "spawned_at":,"completed_at":, +# "wall_secs":,"turns":, +# "input_tokens":,"cached_input_tokens":, +# "output_tokens":,"reasoning_tokens":, +# "source":} +# +# Row scope: a row describes the WHOLE task, spanning every relaunch, and +# wall_secs, the session-log window and turns all report that one span. The +# turn count dictates the scope because it can only be read from +# state/.status, which is appended to across relaunches and carries +# no incarnation delimiter; per-incarnation turns are therefore not derivable +# from durable data, and scoping only the window to an incarnation would +# report whole-task turns against a one-incarnation window and token sum. +# ONE condition narrows a row below that span, and only for a task that was +# actually relaunched: a filesystem that reports no birth time for +# state/.status leaves the meta's spawn_gen as the only durable +# start, and fm-spawn rewrites that token on every relaunch, so wall_secs and +# the token sum then cover the final incarnation while turns still cover the +# whole task. No per-task record of the first spawn survives a relaunch on +# such a host, so a relaunched row there is narrowed rather than wrong; a task +# that was never relaunched always yields a whole-task row on every +# filesystem. +# +# Wall clock: task start epoch -> status-file mtime epoch; the meta file's +# mtime is the fallback end when the status file is absent. +# The start is the EARLIEST durable evidence of the task's first spawn: the +# status file's birth epoch (created on the first spawn, only appended to +# afterwards, and removed only when teardown retires the task) and the epoch +# embedded in the meta's spawn_gen=s.. incarnation token, +# whichever of the two is earlier. fm-spawn writes spawn_gen once per spawn or +# relaunch and never rewrites it afterwards, so it carries the start on a host +# whose filesystem reports no usable birth time; because a relaunch replaces +# it with the relaunch epoch, the status birth is what holds the window open +# over the whole task, which is the narrowing condition stated above. +# The meta file's own mtime is NOT a start source in its own right: later +# meta writes (PR registration, busy-state updates) move it forward to near +# the end of the task and collapse the window. +# Only when neither durable source is available (a task spawned before the +# token existed, on a birthless filesystem) does the start fall back to the +# meta mtime, then the status mtime. +# A start later than the end (a spawn with no status append after it) is +# pinned to the end so spawned_at never postdates completed_at. +# Turn estimate: count of "^working:" lines in the status file. +# +# Per-request usage sources: +# harness=claude: / '-'>/*.jsonl in +# the task window. Claude's logs record no cwd, so that path encoding is +# what binds a log to this task. Each assistant message carries one API +# request's usage at .message.usage (input_tokens, +# cache_read_input_tokens, cache_creation_input_tokens, output_tokens) and +# Claude logs one entry per content block, so requests are deduped by +# .message.id before summing. cached_input_tokens folds cache_read + +# cache_creation (both billed on top of input_tokens); reasoning_tokens +# captures output_tokens_details.thinking_tokens when present (a subset +# of output_tokens). +# harness=codex: /**/*.jsonl in the task window whose +# session_meta cwd equals the meta worktree. Per-turn token_count events +# carry one request's delta at .payload.info.last_token_usage +# (input_tokens, cached_input_tokens, cache_write_input_tokens, +# output_tokens, reasoning_output_tokens); summing those deltas equals the +# final cumulative total. cached_input_tokens folds cached + cache_write +# (subsets of input_tokens); the model comes from the turn_context. +# harness=pi, harness=pi-signed: /**/*.jsonl in the task window +# whose "session" record's cwd equals the meta worktree. Both adapters run +# the same Pi application and share one ~/.pi/agent state tree, so one +# scan covers them. Each assistant "message" record carries one API +# request's usage at .message.usage (input, cacheRead, cacheWrite, output, +# reasoning) and Pi writes one record per message rather than one per +# content block; records are still deduped by the record's own .id where +# present so a replayed line cannot double-count. cached_input_tokens +# folds cacheRead + cacheWrite; reasoning_tokens captures .reasoning (a +# subset of output). The model is reported provider-qualified as +# "/" to match the model spelling fm-spawn records in the +# meta, and bare when the record carries no provider. +# harness=cursor, a task with a recorded remote_host (its worker ran on +# another machine, so its logs are not on this filesystem), an absent log +# tree, or no in-window log that yields this task's assistant usage: token +# fields are null with source "unavailable". Every harness applies that +# one rule, so a source name always asserts a parsed match and never the +# mere presence of an in-window file. +# A corrupt log line is skipped best-effort by the parser, which reads each +# line on its own and keeps the rest of that file's usage. +# +# Idempotent: if the ledger already contains a line whose "task" is +# , the command exits 0 without appending. +# +# Overrides (test seams and alternate homes): +# FM_ROOT_OVERRIDE, FM_HOME, FM_STATE_OVERRIDE, FM_DATA_OVERRIDE as usual +# FM_USAGE_CLAUDE_DIR default $HOME/.claude/projects +# FM_USAGE_CODEX_DIR default $HOME/.codex/sessions +# FM_USAGE_PI_DIR default $HOME/.pi/agent/sessions +# FM_USAGE_LEDGER_LOCK_WAIT seconds to wait for the ledger lock, default 30 +# FM_USAGE_HARVEST_APPEND_DELAY test-only delay inside the ledger critical section +# +# Exit status: 0 on a successful or already-present harvest, 1 on a missing +# task record, missing jq, an unwritable ledger, or a ledger lock still held by +# a live concurrent harvest past FM_USAGE_LEDGER_LOCK_WAIT. Callers that must +# not block (teardown) own their own guard. +set -eu + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +FM_ROOT="${FM_ROOT_OVERRIDE:-$(cd "$SCRIPT_DIR/.." && pwd)}" +FM_HOME="${FM_HOME:-${FM_ROOT_OVERRIDE:-$FM_ROOT}}" +STATE="${FM_STATE_OVERRIDE:-$FM_HOME/state}" +DATA="${FM_DATA_OVERRIDE:-$FM_HOME/data}" +CLAUDE_DIR="${FM_USAGE_CLAUDE_DIR:-${HOME:-}/.claude/projects}" +CODEX_DIR="${FM_USAGE_CODEX_DIR:-${HOME:-}/.codex/sessions}" +PI_DIR="${FM_USAGE_PI_DIR:-${HOME:-}/.pi/agent/sessions}" + +# Portable directory-lock helpers (fm_lock_try_acquire / fm_lock_release) let +# the idempotent check-and-append below run as one critical section, so two +# concurrent harvests of the same task cannot both pass the existence check and +# each append a duplicate row. The acquire is bounded (see below) so it never +# blocks the synchronous teardown caller indefinitely. +# shellcheck source=bin/fm-wake-lib.sh +. "$SCRIPT_DIR/fm-wake-lib.sh" + +err() { printf 'error: %s\n' "$1" >&2; } + +if [ "$#" -ne 1 ] || [ -z "$1" ] || case "$1" in *[!A-Za-z0-9._-]*) true ;; *) false ;; esac; then + err "usage: fm-usage-harvest.sh " + exit 1 +fi +command -v jq >/dev/null 2>&1 || { err "jq is required"; exit 1; } + +ID=$1 +META="$STATE/$ID.meta" +STATUS="$STATE/$ID.status" +[ -f "$META" ] || { err "no task record: $META"; exit 1; } + +meta_get() { # + grep "^$1=" "$META" 2>/dev/null | tail -1 | cut -d= -f2- || true +} +HARNESS=$(meta_get harness) +WORKTREE=$(meta_get worktree) +MODEL_META=$(meta_get model) +EFFORT_META=$(meta_get effort) +# A remote secondmate's worker ran on another machine, so its session logs are +# not on this filesystem. Harvesting the local claude/codex trees for such a +# task would at best find nothing and at worst misattribute an unrelated local +# session that happens to match the worktree path, so a task with a recorded +# remote_host is recorded as source=unavailable without a local scan. +REMOTE_HOST=$(meta_get remote_host) +SPAWN_GEN=$(meta_get spawn_gen) + +file_mtime_epoch() { # + local t + t=$(stat -f %m -- "$1" 2>/dev/null) || t=$(stat -c %Y -- "$1" 2>/dev/null) || return 1 + case "$t" in ''|*[!0-9]*) return 1 ;; esac + printf '%s' "$t" +} +file_birth_epoch() { # + local t + t=$(stat -f %B -- "$1" 2>/dev/null) || t=$(stat -c %W -- "$1" 2>/dev/null) || return 1 + # The plausible-epoch guard keeps GNU stat's filesystem-mode %B output + # (block size) from being misread as a birth time. + case "$t" in ''|*[!0-9]*) return 1 ;; esac + [ "$t" -ge 1000000000 ] 2>/dev/null || return 1 + printf '%s' "$t" +} +iso_from_epoch() { # + date -r "$1" -u +%Y-%m-%dT%H:%M:%SZ 2>/dev/null \ + || date -u -d "@$1" +%Y-%m-%dT%H:%M:%SZ 2>/dev/null \ + || return 1 +} + +spawn_gen_epoch() { # + local e + case "$1" in s[0-9]*) ;; *) return 1 ;; esac + e=${1#s} + e=${e%%.*} + # The same plausible-epoch guard used for birth times rejects a token whose + # leading field is not a real second count. + case "$e" in ''|*[!0-9]*) return 1 ;; esac + [ "$e" -ge 1000000000 ] 2>/dev/null || return 1 + printf '%s' "$e" +} + +END_EPOCH=$(file_mtime_epoch "$STATUS" 2>/dev/null || file_mtime_epoch "$META") +# The two durable first-spawn witnesses are combined by taking the earlier of +# them, so a relaunch (which rewrites spawn_gen but only appends to the status +# log) cannot narrow the window below the span the turn count already covers. +START_GEN=$(spawn_gen_epoch "$SPAWN_GEN" 2>/dev/null || true) +START_BIRTH=$(file_birth_epoch "$STATUS" 2>/dev/null || true) +START_EPOCH= +for start_candidate in "$START_GEN" "$START_BIRTH"; do + [ -n "$start_candidate" ] || continue + if [ -z "$START_EPOCH" ] || [ "$start_candidate" -lt "$START_EPOCH" ]; then + START_EPOCH=$start_candidate + fi +done +[ -n "$START_EPOCH" ] \ + || START_EPOCH=$(file_mtime_epoch "$META" 2>/dev/null || file_mtime_epoch "$STATUS" 2>/dev/null || printf '%s' "$END_EPOCH") +# Pin an impossible start to the end rather than inverting the window, which +# would both report a negative duration and drop every session log. +[ "$START_EPOCH" -le "$END_EPOCH" ] 2>/dev/null || START_EPOCH=$END_EPOCH +WALL=$((END_EPOCH - START_EPOCH)) +TURNS=$(grep -c '^working:' "$STATUS" 2>/dev/null || true) +case "$TURNS" in ''|*[!0-9]*) TURNS=0 ;; esac + +# Ref files pin find's mtime window portably (BSD and GNU find both compare +# against -newer file mtimes, and touch -t exists on both). +REFDIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-harvest.XXXXXX") +LEDGER_LOCK= +LEDGER_LOCK_HELD=0 +harvest_cleanup() { + local rc=$? + [ "$LEDGER_LOCK_HELD" != 1 ] || fm_lock_release "$LEDGER_LOCK" || true + rm -rf -- "$REFDIR" + return "$rc" +} +trap harvest_cleanup EXIT +epoch_to_touch() { # + # Both renderings are LOCAL time because that is what touch -t reads; a UTC + # stamp would shift both window refs by the host's offset and drop real logs. + date -r "$1" +%Y%m%d%H%M.%S 2>/dev/null || date -d "@$1" +%Y%m%d%H%M.%S +} +# find -newer compares sub-second mtimes, so the refs only narrow to +# [START-1, END+1]; the per-file epoch filter below then applies the true +# inclusive whole-second window [START_EPOCH, END_EPOCH]. +touch -t "$(epoch_to_touch "$((START_EPOCH - 1))")" "$REFDIR/start" +touch -t "$(epoch_to_touch "$((END_EPOCH + 1))")" "$REFDIR/end" + +LEDGER="$DATA/usage-ledger.jsonl" + +SRC=unavailable +MODEL_LOG= +matched_files() { # : print in-window *.jsonl paths + local dir=$1 depthargs=() f m + [ -d "$dir" ] || return 0 + if [ -n "$2" ]; then + depthargs=(-maxdepth "$2") + fi + while IFS= read -r f; do + m=$(file_mtime_epoch "$f") || continue + if [ "$m" -ge "$START_EPOCH" ] && [ "$m" -le "$END_EPOCH" ]; then + printf '%s\n' "$f" + fi + done < <(find "$dir" ${depthargs[@]+"${depthargs[@]}"} -type f -name '*.jsonl' \ + -newer "$REFDIR/start" ! -newer "$REFDIR/end" -print 2>/dev/null) || true +} + +IT=null; CT=null; OT=null; RT=null + +# accumulate_usage +# +# The three harness parsers differ only in their jq program; everything around +# it lives here once. Each program reduces one session log to at most one +# "\t\t\t\t\t" row, and emits +# that row ONLY when the log actually yielded assistant usage, so a file that +# parses to nothing leaves the source unavailable. Each program also reads its +# input line by line through "try fromjson", so one corrupt line costs that +# line rather than the whole file's usage. This loop then binds the row to +# this task by the cwd it reports, sums the counts and remembers the first +# model seen. +accumulate_usage() { + local dir=$1 depth=$2 label=$3 prog=$4 + local files f row cwd m it ct ot rt + files=$(matched_files "$dir" "$depth") + [ -n "$files" ] || return 0 + IT=0; CT=0; OT=0; RT=0 + while IFS= read -r f; do + [ -n "$f" ] || continue + # @tsv renders a null field as an empty one, and "IFS=$'\t' read" would + # drop those empty fields because tab is an IFS whitespace character, + # shifting every later field into the wrong variable. Translating the + # separators to the non-whitespace unit separator keeps each field in its + # own slot; @tsv escapes any tab inside a value, so every remaining tab + # byte is a separator. + row=$(jq -Rrn --arg wt "$WORKTREE" "$prog" "$f" 2>/dev/null | tr '\t' '\037') + [ -n "$row" ] || continue + IFS=$'\037' read -r cwd m it ct ot rt <<<"$row" + [ "$cwd" = "$WORKTREE" ] || continue + SRC=$label + [ -n "$m" ] && [ -z "$MODEL_LOG" ] && MODEL_LOG=$m + IT=$((IT + ${it:-0})) + CT=$((CT + ${ct:-0})) + OT=$((OT + ${ot:-0})) + RT=$((RT + ${rt:-0})) + done < 0 then [$wt, .m, .it, .ct, .ot, .rt] | @tsv else empty end' + fi + ;; + codex) + if [ -z "$REMOTE_HOST" ] && [ -n "$WORKTREE" ]; then + # shellcheck disable=SC2016 # jq owns every $ expression in these literal programs. + accumulate_usage "$CODEX_DIR" "" codex-sessions ' + reduce (inputs | try (fromjson | objects) catch empty) as $l + ({cwd:null,n:0,m:null,it:0,ct:0,ot:0,rt:0}; + if $l.type == "session_meta" then + .cwd = ($l.payload.cwd // .cwd) + elif $l.type == "turn_context" and ($l.payload.model // null) != null then + .m = $l.payload.model + elif $l.type == "event_msg" and $l.payload.type == "token_count" + and ($l.payload.info.last_token_usage // null) != null then + .n += 1 + | .it += ($l.payload.info.last_token_usage.input_tokens // 0) + | .ct += (($l.payload.info.last_token_usage.cached_input_tokens // 0) + + ($l.payload.info.last_token_usage.cache_write_input_tokens // 0)) + | .ot += ($l.payload.info.last_token_usage.output_tokens // 0) + | .rt += ($l.payload.info.last_token_usage.reasoning_output_tokens // 0) + else . end) + | if .n > 0 then [.cwd, .m, .it, .ct, .ot, .rt] | @tsv else empty end' + fi + ;; + pi|pi-signed) + if [ -z "$REMOTE_HOST" ] && [ -n "$WORKTREE" ]; then + # shellcheck disable=SC2016 # jq owns every $ expression in these literal programs. + accumulate_usage "$PI_DIR" "" pi-sessions ' + reduce (inputs | try (fromjson | objects) catch empty) as $l + ({cwd:null,seen:{},n:0,m:null,it:0,ct:0,ot:0,rt:0}; + if $l.type == "session" then + .cwd = ($l.cwd // .cwd) + elif $l.type == "message" and $l.message.role == "assistant" + and ($l.message.usage // null) != null then + ($l.id // null) as $id + | if $id != null and .seen[$id] then . else + (if $id == null then . else .seen[$id] = 1 end) + | .n += 1 + | .it += ($l.message.usage.input // 0) + | .ct += (($l.message.usage.cacheRead // 0) + + ($l.message.usage.cacheWrite // 0)) + | .ot += ($l.message.usage.output // 0) + | .rt += ($l.message.usage.reasoning // 0) + | (if .m == null and ($l.message.model // null) != null then + .m = (if ($l.message.provider // null) != null + then ($l.message.provider + "/" + $l.message.model) + else $l.message.model end) + else . end) + end + else . end) + | if .n > 0 then [.cwd, .m, .it, .ct, .ot, .rt] | @tsv else empty end' + fi + ;; +esac + +if [ "$SRC" = unavailable ]; then + MODEL_LOG= + IT=null; CT=null; OT=null; RT=null +fi + +MODEL=${MODEL_LOG:-$MODEL_META} +EFFORT=$EFFORT_META + +SPAWNED=$(iso_from_epoch "$START_EPOCH" || true) +COMPLETED=$(iso_from_epoch "$END_EPOCH" || true) + +mkdir -p -- "$DATA" +# Serialize the check-and-append as one critical section: acquire the ledger +# lock, then test for an existing row for this task and append only when +# absent. Two concurrent harvests of the same task cannot both pass the +# existence test and each append a duplicate row. +# +# The acquire is BOUNDED, not fm_lock_acquire_wait's unbounded spin, because +# this runs synchronously inside teardown: a wedged live holder must never +# block teardown from retiring the task. fm_lock_try_acquire already steals a +# dead owner's lock, so only a live concurrent harvest makes us wait, and its +# critical section is a grep plus an append. If the lock stays busy past the +# bound we give up best-effort (exit 1, which teardown warns on and continues) +# rather than duplicate the row by appending unserialized. +LEDGER_LOCK="$DATA/.usage-ledger.lock" +LEDGER_LOCK_WAIT=${FM_USAGE_LEDGER_LOCK_WAIT:-30} +lock_deadline=$(( $(date +%s) + LEDGER_LOCK_WAIT )) +until fm_lock_try_acquire "$LEDGER_LOCK"; do + if [ "$(date +%s)" -ge "$lock_deadline" ]; then + err "ledger lock busy after ${LEDGER_LOCK_WAIT}s; skipping harvest for $ID" + exit 1 + fi + sleep 0.1 +done +LEDGER_LOCK_HELD=1 +if [ -f "$LEDGER" ] && grep -qF "\"task\":\"$ID\"" "$LEDGER" 2>/dev/null; then + exit 0 +fi +# Test seam: widen the check-to-append window so a concurrency regression (a +# removed lock) is observable deterministically; unset in production. +[ -z "${FM_USAGE_HARVEST_APPEND_DELAY:-}" ] || sleep "$FM_USAGE_HARVEST_APPEND_DELAY" +jq -cn \ + --arg task "$ID" --arg harness "$HARNESS" \ + --arg model "$MODEL" --arg effort "$EFFORT" \ + --arg spawned "$SPAWNED" --arg completed "$COMPLETED" \ + --argjson wall "$WALL" --argjson turns "$TURNS" \ + --argjson it "$IT" --argjson ct "$CT" --argjson ot "$OT" --argjson rt "$RT" \ + --arg source "$SRC" \ + '{task:$task, harness:(if $harness == "" then null else $harness end), + model:(if ($model == "" or $model == "default") then null else $model end), + effort:(if ($effort == "" or $effort == "default") then null else $effort end), + spawned_at:(if $spawned == "" then null else $spawned end), + completed_at:(if $completed == "" then null else $completed end), + wall_secs:$wall, turns:$turns, + input_tokens:$it, cached_input_tokens:$ct, output_tokens:$ot, + reasoning_tokens:$rt, source:$source}' >> "$LEDGER" diff --git a/bin/fm-usage-report.sh b/bin/fm-usage-report.sh new file mode 100755 index 00000000000..28636cb9659 --- /dev/null +++ b/bin/fm-usage-report.sh @@ -0,0 +1,81 @@ +#!/usr/bin/env bash +# fm-usage-report.sh - plain-text reader for data/usage-ledger.jsonl. +# +# Usage: fm-usage-report.sh [ledger-path] +# +# Prints per-model totals and one row per task from the usage ledger written +# by fm-usage-harvest.sh (that file owns the line schema; this script only +# consumes it). With no argument the ledger resolves from the operational +# home exactly as the harvester does. +# +# Output is aligned plain text; an absent or unavailable field renders as +# "-". The ledger's @tsv rows are read over the unit separator rather than the +# tab, because tab is an IFS whitespace character and an empty field would +# otherwise collapse and shift every later column left. +# +# Both renderings are computed BEFORE the first line is printed, so a ledger +# that jq cannot parse fails with a named diagnostic and a non-zero status +# instead of emitting a physical row count above empty sections. +# Exit status: 0 including when the ledger is absent or empty; 1 when the +# ledger exists but does not parse as JSON lines. +set -eu + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +FM_ROOT="${FM_ROOT_OVERRIDE:-$(cd "$SCRIPT_DIR/.." && pwd)}" +FM_HOME="${FM_HOME:-${FM_ROOT_OVERRIDE:-$FM_ROOT}}" +DATA="${FM_DATA_OVERRIDE:-$FM_HOME/data}" + +command -v jq >/dev/null 2>&1 || { printf 'error: jq is required\n' >&2; exit 1; } + +LEDGER=${1:-$DATA/usage-ledger.jsonl} +if [ ! -s "$LEDGER" ]; then + printf 'no usage ledger at %s\n' "$LEDGER" + exit 0 +fi + +# Render both sections first: an unparseable ledger must not be reported as a +# successful run with a row count and empty sections below it. +if ! MODEL_ROWS=$(jq -rs ' + [.[] | select(.source != "unavailable")] | sort_by(.model // "?") | group_by(.model // "?")[] + | [ (.[0].model // "?"), (length | tostring), + (map(.input_tokens // 0) | add | tostring), + (map(.cached_input_tokens // 0) | add | tostring), + (map(.output_tokens // 0) | add | tostring), + (map(.reasoning_tokens // 0) | add | tostring), + (map(.wall_secs // 0) | add | tostring) ] | @tsv' "$LEDGER"); then + printf 'error: %s: ledger is not readable as JSON lines\n' "$LEDGER" >&2 + exit 1 +fi +if ! TASK_ROWS=$(jq -r ' + [ (.task // "-"), (.harness // "-"), + (.model // "-"), (.effort // "-"), + (.input_tokens // "-"), (.cached_input_tokens // "-"), + (.output_tokens // "-"), (.reasoning_tokens // "-"), + (.wall_secs // "-"), (.source // "-") ] | @tsv' "$LEDGER"); then + printf 'error: %s: ledger is not readable as JSON lines\n' "$LEDGER" >&2 + exit 1 +fi + +printf 'usage ledger: %s (%s rows)\n' "$LEDGER" "$(wc -l < "$LEDGER" | tr -d ' ')" +echo +echo "per-model totals (source-available rows):" +printf '%-24s %6s %12s %12s %12s %12s %10s\n' \ + model tasks input cached output reasoning wall_secs +if [ -n "$MODEL_ROWS" ]; then + printf '%s\n' "$MODEL_ROWS" | tr '\t' '\037' | + while IFS=$'\037' read -r model tasks it ct ot rt wall; do + printf '%-24s %6s %12s %12s %12s %12s %10s\n' \ + "$model" "$tasks" "$it" "$ct" "$ot" "$rt" "$wall" + done +fi +echo +echo "per-task rows:" +printf '%-24s %-8s %-20s %-8s %12s %12s %12s %12s %10s %-16s\n' \ + task harness model effort input cached output reasoning wall_secs source +if [ -n "$TASK_ROWS" ]; then + printf '%s\n' "$TASK_ROWS" | tr '\t' '\037' | + while IFS=$'\037' read -r task harness model effort it ct ot rt wall source; do + printf '%-24s %-8s %-20s %-8s %12s %12s %12s %12s %10s %-16s\n' \ + "$task" "$harness" "$model" "$effort" "$it" "$ct" "$ot" "$rt" "$wall" "$source" + done +fi diff --git a/docs/scripts.md b/docs/scripts.md index ec4ba09038e..5ca10f00b40 100644 --- a/docs/scripts.md +++ b/docs/scripts.md @@ -129,6 +129,8 @@ The shared no-mistakes gate refusal for fleet lifecycle entrypoints is summarize | `fm-parent-channel-lib.sh` | Resolve a secondmate home's parent channel and append a captain-facing outcome line to it at most once | | `fm-promote.sh` | Promote a scout task in place to a protected ship task with an explicit delivery mode, and write the ship instructions carrying that mode's definition of done | | `fm-teardown.sh` | Fail-closed teardown: return landed ship worktrees, require completed scout deliverables, retire secondmate homes | +| `fm-usage-harvest.sh` | Append one finished task's token, wall-clock, and turn cost to the gitignored usage ledger (sole owner of the ledger line schema) | +| `fm-usage-report.sh` | Read the usage ledger into a plain-text per-model and per-task cost report | | `fm-harness.sh` | Detect the running harness and resolve crew or secondmate harness, model, and effort | | `fm-lock.sh` | Per-home firstmate session lock | | `fm-x-lib.sh` | Shared Relay config, relay, and reply-threading helpers | diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh new file mode 100755 index 00000000000..78b1e9a6875 --- /dev/null +++ b/tests/fm-usage-harvest.test.sh @@ -0,0 +1,949 @@ +#!/usr/bin/env bash +# Behavior tests for the fleet usage harvester and its report reader. +# Covers claude-log request dedupe and cache folding, codex per-request delta +# sums with cwd/window matching, pi/pi-signed session parsing over the shared +# ~/.pi/agent/sessions tree, the durable spawn_gen task start that survives a +# meta rewritten after the fact, cursor/unavailable null rows, the +# no-double-append idempotency guard, the ledger report rendering including +# its refusal to present an unparseable ledger as a result, and the +# teardown integration properties that the harvest sees the status log and +# that a harvest failure never blocks teardown. Also covers the whole-task row +# scope a relaunch must not narrow, the per-line corrupt-log tolerance, and +# the rule that a source is named only after a log yields assistant usage. +set -u + +# shellcheck source=tests/lib.sh +# shellcheck disable=SC1091 +. "$(dirname "${BASH_SOURCE[0]}")/lib.sh" + +HARVEST="$ROOT/bin/fm-usage-harvest.sh" +REPORT="$ROOT/bin/fm-usage-report.sh" +TEARDOWN="$ROOT/bin/fm-teardown.sh" +TMP_ROOT=$(fm_test_tmproot fm-usage-harvest) + +command -v jq >/dev/null 2>&1 || { echo "skip: jq not found"; exit 0; } + +file_mtime_epoch() { # + local t + t=$(stat -f %m -- "$1" 2>/dev/null) || t=$(stat -c %Y -- "$1" 2>/dev/null) || return 1 + case "$t" in ''|*[!0-9]*) return 1 ;; esac + printf '%s' "$t" +} +file_birth_epoch() { # + local t + t=$(stat -f %B -- "$1" 2>/dev/null) || t=$(stat -c %W -- "$1" 2>/dev/null) || return 1 + case "$t" in ''|*[!0-9]*) return 1 ;; esac + [ "$t" -ge 1000000000 ] 2>/dev/null || return 1 + printf '%s' "$t" +} + +# Portable epoch formatters: BSD date reads an epoch with -r, GNU date with +# -d @. Both forms are tried so the fixtures pin the same timestamps on +# macOS and on the Linux CI runners. touch -t reads its argument as LOCAL +# time, so both renderings here are local; iso_utc below is the ledger's UTC +# spelling and stays UTC. +touch_stamp() { # : touch -t argument + date -r "$1" +%Y%m%d%H%M.%S 2>/dev/null || date -d "@$1" +%Y%m%d%H%M.%S +} +iso_utc() { # : the harvester's ledger timestamp spelling + date -r "$1" -u +%Y-%m-%dT%H:%M:%SZ 2>/dev/null || date -u -d "@$1" +%Y-%m-%dT%H:%M:%SZ +} + +# harvest_case [model] [effort] : create a home with one task +# whose worktree is $TMP_ROOT/wt-, status and meta included, and echo the +# data dir. Exports the FM_USAGE_* fixture dirs per case. +harvest_case() { # [model] [effort] + local id=$1 harness=$2 wt=$3 + local home="$TMP_ROOT/home-$id" + mkdir -p "$home/state" "$home/data" + fm_write_meta "$home/state/$id.meta" \ + "window=firstmate:fm-$id" "endpoint_task_id=$id" "worktree=$wt" \ + "project=$TMP_ROOT/proj-$id" "harness=$harness" "kind=ship" "mode=no-mistakes" \ + "model=${4:-default}" "effort=${5:-default}" + { + printf 'working: started\n' + printf 'working: halfway\n' + printf 'done: finished the task\n' + } > "$home/state/$id.status" + printf '%s\n' "$home/data" +} +export_harvest_env() { # + FM_STATE_OVERRIDE="$1/state" + FM_DATA_OVERRIDE="$1/data" + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/fake-claude/projects" + FM_USAGE_CODEX_DIR="$TMP_ROOT/fake-codex/sessions" + FM_USAGE_PI_DIR="$TMP_ROOT/fake-pi/sessions" + export FM_STATE_OVERRIDE FM_DATA_OVERRIDE FM_USAGE_CLAUDE_DIR FM_USAGE_CODEX_DIR + export FM_USAGE_PI_DIR +} + +# --- claude: request dedupe, cache folding, encoding resolution, window ----- + +claude_case() { + # The worktree path carries a dot segment (as every firstmate home under + # .no-mistakes does) so a slash-only encoding would resolve to the wrong + # on-disk project directory. + local id=usageclaude1 wt="$TMP_ROOT/.no-mistakes/wt-usageclaude1" + local data home state ledger row + data=$(harvest_case "$id" claude "$wt" default default) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + # Claude Code encodes the project directory by mapping BOTH '/' and '.' to + # '-', so the fixture log dir mirrors that full sanitization. + local encoded=${wt//\//-} + encoded=${encoded//./-} + local logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session-a.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgA","model":"claude-test","usage":{"input_tokens":10,"cache_read_input_tokens":100,"cache_creation_input_tokens":20,"output_tokens":30,"output_tokens_details":{"thinking_tokens":5}}}} +{"type":"assistant","message":{"id":"msgA","model":"claude-test","usage":{"input_tokens":10,"cache_read_input_tokens":100,"cache_creation_input_tokens":20,"output_tokens":30,"output_tokens_details":{"thinking_tokens":5}}}} +{"type":"assistant","message":{"id":"msgB","model":"claude-test","usage":{"input_tokens":7,"cache_read_input_tokens":0,"cache_creation_input_tokens":0,"output_tokens":9}}} +{"type":"user","message":{"role":"user"}} +{"type":"assistant","message":{"id":"msgC"}} +JSON + # A request logged outside the task window (future mtime) must be excluded, + # as must a session in a differently encoded sibling directory. + cat > "$logdir/session-future.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgX","model":"claude-test","usage":{"input_tokens":999,"cache_read_input_tokens":0,"cache_creation_input_tokens":0,"output_tokens":999}}} +JSON + touch -t "$(touch_stamp $(( $(file_mtime_epoch "$state/$id.status") + 7200 )))" \ + "$logdir/session-future.jsonl" + mkdir -p "$FM_USAGE_CLAUDE_DIR/wrong-encoded-dir" + printf '%s\n' '{"type":"assistant","message":{"id":"msgY","model":"claude-test","usage":{"input_tokens":777,"output_tokens":777}}}' \ + > "$FM_USAGE_CLAUDE_DIR/wrong-encoded-dir/other.jsonl" + # Seal the window: the status end mtime must not predate the in-window + # session log, or the log correctly falls outside birth -> end. + touch -m -r "$logdir/session-a.jsonl" "$state/$id.status" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "claude harvest should succeed"$'\n'"$out" + ledger="$data/usage-ledger.jsonl" + [ -f "$ledger" ] || fail "claude harvest wrote no ledger" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] || fail "claude harvest wrote more than one ledger line" + row=$(cat "$ledger") + assert_contains "$row" '"task":"usageclaude1"' "claude row names the task" + assert_contains "$row" '"harness":"claude"' "claude row names the harness" + assert_contains "$row" '"model":"claude-test"' "claude row captures the log model" + assert_contains "$row" '"source":"claude-projects"' "claude row names its source" + assert_contains "$row" '"input_tokens":17' "claude input tokens dedupe per request (10+7)" + assert_contains "$row" '"cached_input_tokens":120' "claude cached folds read+creation (100+20+0+0)" + assert_contains "$row" '"output_tokens":39' "claude output tokens (30+9)" + assert_contains "$row" '"reasoning_tokens":5' "claude reasoning captures thinking tokens" + assert_contains "$row" '"turns":2' "claude turn estimate counts working: lines" + assert_contains "$row" '"effort":null' "default effort renders null" + # Wall seconds is birth -> status mtime on this platform; assert the + # computed value equals an independent read of the same file facts. + local end birth wall_expected + end=$(file_mtime_epoch "$state/$id.status") + birth=$(file_birth_epoch "$state/$id.status" || file_mtime_epoch "$state/$id.status") + wall_expected=$((end - birth)) + [ "$wall_expected" -lt 0 ] && wall_expected=0 + assert_contains "$row" "\"wall_secs\":$wall_expected" \ + "claude wall seconds equals status birth -> last-mtime window" + + # Idempotency: a second harvest must not append a duplicate row. + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "second claude harvest should exit 0"$'\n'"$out" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] \ + || fail "second claude harvest double-appended" + pass "claude harvest: per-request dedupe, cache folding, encoding, window, idempotency" +} + +# --- codex: cwd match, window match, delta sums, model capture -------------- + +codex_case() { + local id=usagecodex1 wt="$TMP_ROOT/wt-usagecodex1" + local data home ledger row out + data=$(harvest_case "$id" codex "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + + local d1="$FM_USAGE_CODEX_DIR/2026/08/28" + mkdir -p "$d1" + cat > "$d1/rollout-match.jsonl" < "$d1/rollout-othercwd.jsonl" < "$d1/rollout-future.jsonl" <&1) + expect_code 0 "$?" "codex harvest should succeed"$'\n'"$out" + ledger="$home/data/usage-ledger.jsonl" + row=$(cat "$ledger") + assert_contains "$row" '"harness":"codex"' "codex row names the harness" + assert_contains "$row" '"model":"glm-5.3"' "codex row captures the turn_context model" + assert_contains "$row" '"effort":"high"' "codex row carries meta effort" + assert_contains "$row" '"source":"codex-sessions"' "codex row names its source" + assert_contains "$row" '"input_tokens":150' "codex input sums per-request deltas (100+50)" + assert_contains "$row" '"cached_input_tokens":15' "codex cached folds cached+cache_write (10+5+0)" + assert_contains "$row" '"output_tokens":31' "codex output sums deltas (20+11)" + assert_contains "$row" '"reasoning_tokens":11' "codex reasoning sums deltas (8+3)" + pass "codex harvest: cwd/window matching, delta sums, model capture" +} + +# --- pi / pi-signed: shared session tree, cwd match, per-message usage ------- + +# pi_session_log : one realistic Pi session log. The session +# record carries the cwd; each assistant message record carries one request's +# usage. The second record repeats the first record's id, standing in for a +# replayed line that must not be counted twice. +pi_session_log() { # + cat > "$1" < + local id=$1 harness=$2 wt="$TMP_ROOT/wt-$1" + local data home ledger row out d1 + data=$(harvest_case "$id" "$harness" "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + + # Pi keys its session directories off the worker cwd, but the cwd recorded + # inside the session record is what binds a log to this task, so the fixture + # directory names are deliberately opaque here. + d1="$FM_USAGE_PI_DIR/--encoded-match--" + mkdir -p "$d1" + pi_session_log "$d1/session-match.jsonl" "$wt" + # Same window, different cwd: must be excluded. + mkdir -p "$FM_USAGE_PI_DIR/--encoded-other--" + pi_session_log "$FM_USAGE_PI_DIR/--encoded-other--/session-other.jsonl" /elsewhere + # Matching cwd but outside the task window: must be excluded. + pi_session_log "$d1/session-future.jsonl" "$wt" + touch -t "$(touch_stamp $(( $(file_mtime_epoch "$home/state/$id.status") + 7200 )))" \ + "$d1/session-future.jsonl" + touch -m -r "$d1/session-match.jsonl" "$home/state/$id.status" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "$harness harvest should succeed"$'\n'"$out" + ledger="$home/data/usage-ledger.jsonl" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] || fail "$harness harvest wrote more than one row" + row=$(cat "$ledger") + assert_contains "$row" "\"harness\":\"$harness\"" "$harness row names the harness" + assert_contains "$row" '"source":"pi-sessions"' "$harness row names its source" + assert_contains "$row" '"model":"zai/glm-5.3-flash"' \ + "$harness row reports the provider-qualified log model" + assert_contains "$row" '"input_tokens":111' \ + "$harness input sums one entry per request, replay deduped (100+11)" + assert_contains "$row" '"cached_input_tokens":39' \ + "$harness cached folds cacheRead+cacheWrite (30+4+5+0)" + assert_contains "$row" '"output_tokens":23' "$harness output sums per request (20+3)" + assert_contains "$row" '"reasoning_tokens":8' "$harness reasoning sums per request (7+1)" + assert_contains "$row" '"effort":"high"' "$harness row carries meta effort" + pass "$harness harvest: cwd/window matching, per-request sums, replay dedupe" +} + +# --- spawn_gen: the task start survives a meta rewritten after the fact ------ + +# fm-spawn records spawn_gen=s.. once per incarnation and +# never rewrites it, while later meta writes (PR registration, busy-state +# updates) move the meta mtime forward to near the end of the task. Deriving +# the start from that mtime collapsed the window to zero and dropped every +# session log; the durable token must win. +spawn_gen_case() { + local id=usagespawngen1 wt="$TMP_ROOT/.no-mistakes/wt-usagespawngen1" + local data home state ledger row out base encoded logdir + data=$(harvest_case "$id" claude "$wt" default default) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgS","model":"claude-test","usage":{"input_tokens":42,"output_tokens":6}}} +JSON + + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.4242.7\n' "$((base - 300))" >> "$state/$id.meta" + # The worker's last status line lands at the end of the task; the meta is + # then rewritten (PR registration), dragging its mtime up to the same point. + touch -t "$(touch_stamp "$base")" "$state/$id.status" + touch -t "$(touch_stamp "$base")" "$state/$id.meta" + # A real request logged 200s into the task, inside the true window only. + touch -t "$(touch_stamp $((base - 200)))" "$logdir/session.jsonl" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "spawn_gen harvest should succeed"$'\n'"$out" + ledger="$data/usage-ledger.jsonl" + row=$(cat "$ledger") + assert_contains "$row" '"wall_secs":300' \ + "wall clock spans the spawn token epoch -> last status append" + assert_contains "$row" "\"spawned_at\":\"$(iso_utc $((base - 300)))\"" \ + "spawned_at reports the spawn token epoch" + assert_contains "$row" '"source":"claude-projects"' \ + "the durable window still covers the mid-task session log" + assert_contains "$row" '"input_tokens":42' "the in-window request is summed" + pass "usage harvest: spawn_gen is the durable start, immune to later meta writes" +} + +# A spawn_gen token that is absent or malformed (a task spawned before the +# token existed, or a corrupt record) must fall back to the file-timestamp +# chain rather than producing a bogus start. +spawn_gen_malformed_case() { + local id=usagespawngen2 wt="$TMP_ROOT/wt-usagespawngen2" + local data home state ledger row out base + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + printf 'spawn_gen=not-a-token\n' >> "$state/$id.meta" + base=$(file_mtime_epoch "$state/$id.status") + touch -t "$(touch_stamp "$base")" "$state/$id.status" + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "malformed spawn_gen harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" "\"completed_at\":\"$(iso_utc "$base")\"" \ + "malformed spawn_gen still reports the status-mtime end" + assert_contains "$row" '"wall_secs":0' \ + "malformed spawn_gen falls back to the file-timestamp chain, never a bogus start" + pass "usage harvest: a malformed spawn_gen falls back to file timestamps" +} + +# A spawn token that postdates the last status append (a relaunch with no +# status line after it) must pin the start to the end, never invert the window. +spawn_gen_future_case() { + local id=usagespawngen3 wt="$TMP_ROOT/wt-usagespawngen3" + local data home state row out base + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.1.1\n' "$((base + 600))" >> "$state/$id.meta" + touch -t "$(touch_stamp "$base")" "$state/$id.status" + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "future spawn_gen harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"wall_secs":0' "an impossible start never reports a negative duration" + assert_contains "$row" "\"spawned_at\":\"$(iso_utc "$base")\"" \ + "an impossible start is pinned to the end, never postdating completed_at" + pass "usage harvest: a start later than the end is pinned, not inverted" +} + +# --- cursor: unavailable logs render nulls ---------------------------------- + +cursor_case() { + local id=usagecursor1 wt="$TMP_ROOT/wt-usagecursor1" + local data home ledger row out + data=$(harvest_case "$id" cursor "$wt" cursor-grok-4.5-high "") + home=$(dirname "$data") + export_harvest_env "$home" + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "cursor harvest should succeed"$'\n'"$out" + ledger="$home/data/usage-ledger.jsonl" + row=$(cat "$ledger") + assert_contains "$row" '"model":"cursor-grok-4.5-high"' "cursor row falls back to meta model" + assert_contains "$row" '"input_tokens":null' "cursor input tokens are null" + assert_contains "$row" '"cached_input_tokens":null' "cursor cached tokens are null" + assert_contains "$row" '"output_tokens":null' "cursor output tokens are null" + assert_contains "$row" '"reasoning_tokens":null' "cursor reasoning tokens are null" + assert_contains "$row" '"source":"unavailable"' "cursor row marks source unavailable" + pass "cursor harvest: unavailable source renders null token fields" +} + +# --- claude: window survives a host without usable birth time --------------- + +# A stat shim that reports no birth time (GNU statx unsupported returns 0 for +# %W) while still answering mtime, so the harvest must fall back to the meta +# mtime for the window start instead of collapsing to the status mtime. +# stat_shim_bin [ ] : put a stat shim on PATH +# that answers mtime truthfully while controlling what the harvester reads for +# a birth time. With no birth argument every file reports no usable birth time +# (GNU statx unsupported returns 0 for %W), so the window must fall back; with +# one, only reports . The %Y branch captures the two +# probes into separate assignments, exactly as the harvester's own +# file_mtime_epoch does, so the second read replaces the first's output instead +# of being appended to it (see bin/fm-watch.sh for why the shared-stdout +# `stat -f ... || stat -c ...` form writes a filesystem dump on Linux). +stat_shim_bin() { # [ ] + local dir=$1 statusfile=${2:-} birth=${3:-} + mkdir -p "$dir" + cat > "$dir/stat" </dev/null) \\ + || t=\$(/usr/bin/stat -c %Y -- "\$file" 2>/dev/null) \\ + || exit 1 + printf '%s\\n' "\$t" + ;; + *) exit 1 ;; +esac +SH + chmod +x "$dir/stat" +} + +claude_nobirth_case() { + local id=usagenobirth1 wt="$TMP_ROOT/.no-mistakes/wt-usagenobirth1" + local data home state ledger row out fb base + data=$(harvest_case "$id" claude "$wt" default default) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + local encoded=${wt//\//-} + encoded=${encoded//./-} + local logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgN","model":"claude-test","usage":{"input_tokens":12,"output_tokens":8}}} +JSON + + # Pin an explicit window: status finishes at T, meta was spawned 100s earlier, + # and the session log lands mid-window. Without the meta-mtime start fallback + # the birthless window collapses to [T, T] and drops the earlier log. + base=$(file_mtime_epoch "$state/$id.status") + touch -t "$(touch_stamp "$base")" "$state/$id.status" + touch -t "$(touch_stamp $((base - 100)))" "$state/$id.meta" + touch -t "$(touch_stamp $((base - 50)))" "$logdir/session.jsonl" + + fb="$TMP_ROOT/nobirth-fakebin" + stat_shim_bin "$fb" + out=$(PATH="$fb:$PATH" "$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "birthless claude harvest should succeed"$'\n'"$out" + ledger="$data/usage-ledger.jsonl" + row=$(cat "$ledger") + assert_contains "$row" '"source":"claude-projects"' \ + "birthless harvest still finds the in-window log via the meta-mtime start" + assert_contains "$row" '"input_tokens":12' "birthless harvest sums the in-window usage" + assert_contains "$row" '"wall_secs":100' \ + "birthless window spans meta -> status instead of collapsing to zero" + pass "claude harvest: window survives a host without usable birth time" +} + +# --- remote secondmate: local logs are never harvested for remote work ------ + +remote_case() { + local id=usageremote1 wt="$TMP_ROOT/wt-usageremote1" + local data home ledger row out + data=$(harvest_case "$id" codex "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + # The task ran on a remote secondmate host (fm-spawn records remote_host=). + printf 'remote_host=box.example\n' >> "$home/state/$id.meta" + # Seed a LOCAL codex session whose cwd matches the worktree: without the + # remote-host guard the harvest would misattribute this local session to the + # remote task; with it, the row is honestly unavailable and its tokens null. + local d1="$FM_USAGE_CODEX_DIR/2026/08/28" + mkdir -p "$d1" + cat > "$d1/rollout-localmatch.jsonl" <&1) + expect_code 0 "$?" "remote harvest should succeed"$'\n'"$out" + ledger="$home/data/usage-ledger.jsonl" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] || fail "remote harvest wrote no single row" + row=$(cat "$ledger") + assert_contains "$row" '"source":"unavailable"' \ + "remote task records unavailable, not a local session" + assert_contains "$row" '"input_tokens":null' \ + "remote task tokens are null (no local misattribution)" + pass "remote secondmate harvest: local logs are never misattributed" +} + +# --- concurrency: the ledger lock keeps the append idempotent --------------- + +race_case() { + local id=usagerace1 wt="$TMP_ROOT/wt-usagerace1" + local data home ledger p1 p2 + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + export_harvest_env "$home" + ledger="$home/data/usage-ledger.jsonl" + # Two concurrent harvests with a widened check-to-append window: the ledger + # lock must serialize them so exactly one row is appended. Without the lock + # both pass the existence check and each append, yielding two rows. + FM_USAGE_HARVEST_APPEND_DELAY=1 "$HARVEST" "$id" >/dev/null 2>&1 & + p1=$! + FM_USAGE_HARVEST_APPEND_DELAY=1 "$HARVEST" "$id" >/dev/null 2>&1 & + p2=$! + wait "$p1"; wait "$p2" + [ -f "$ledger" ] || fail "concurrent harvest wrote no ledger" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] \ + || fail "concurrent harvests appended more than one row" + pass "usage harvest: concurrent harvests append exactly one row" +} + +# A held ledger lock must never block the (teardown-synchronous) harvest +# forever: the acquire is bounded, so a second harvest whose lock-wait is +# shorter than the holder's critical section gives up best-effort (non-zero, +# no duplicate row) instead of hanging until the holder releases. +lock_bound_case() { + local id=usagelockbound1 wt="$TMP_ROOT/wt-usagelockbound1" + local data home ledger p1 rc + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + export_harvest_env "$home" + ledger="$home/data/usage-ledger.jsonl" + # Holder keeps the lock across a 4s critical section. + FM_USAGE_HARVEST_APPEND_DELAY=4 "$HARVEST" "$id" >/dev/null 2>&1 & + p1=$! + # Let the holder acquire before the bounded harvester starts spinning. + sleep 1 + rc=0 + FM_USAGE_LEDGER_LOCK_WAIT=1 "$HARVEST" "$id" >/dev/null 2>&1 || rc=$? + [ "$rc" -ne 0 ] \ + || fail "bounded harvest returned 0 while the ledger lock was held" + wait "$p1" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] \ + || fail "bounded give-up appended a duplicate row" + pass "usage harvest: a held ledger lock bounds the acquire, no hang or dup" +} + +# --- report: per-model totals and per-task rows ----------------------------- + +# The ledger's harness field is null when a task record carries no harness= +# line, and the report must keep every later column in its own slot rather +# than shifting the model, effort and token columns one place left. +report_no_harness_case() { + local id=usagenoharness1 wt="$TMP_ROOT/wt-usagenoharness1" + local home ledger out fields + home="$TMP_ROOT/home-$id" + mkdir -p "$home/state" "$home/data" + fm_write_meta "$home/state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "model=nohar-model" "effort=default" + printf 'working: started\n' > "$home/state/$id.status" + FM_STATE_OVERRIDE="$home/state" FM_DATA_OVERRIDE="$home/data" \ + "$HARVEST" "$id" >/dev/null 2>&1 || fail "harness-less harvest failed" + ledger="$home/data/usage-ledger.jsonl" + assert_contains "$(cat "$ledger")" '"harness":null' \ + "an absent harness is recorded as null, like an absent model or effort" + + out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) + expect_code 0 "$?" "report of a harness-less row should succeed"$'\n'"$out" + fields=$(printf '%s\n' "$out" | awk -v t="$id" '$1 == t {print NF"|"$2"|"$3"|"$NF}') + [ "$fields" = "10|-|nohar-model|unavailable" ] \ + || fail "report shifted the harness-less row's columns: [$fields]" + pass "usage report: an absent harness renders as a placeholder without shifting columns" +} + +report_case() { + local out ledger + ledger="$TMP_ROOT/home-usageclaude1/data/usage-ledger.jsonl" + { + cat "$TMP_ROOT/home-usagecodex1/data/usage-ledger.jsonl" + cat "$TMP_ROOT/home-usagepi1/data/usage-ledger.jsonl" + cat "$TMP_ROOT/home-usagecursor1/data/usage-ledger.jsonl" + } >> "$ledger" + out=$(FM_DATA_OVERRIDE="$(dirname "$ledger")" "$REPORT" 2>&1) + expect_code 0 "$?" "report should succeed"$'\n'"$out" + assert_contains "$out" "usage ledger: $ledger (4 rows)" "report names the ledger and row count" + assert_contains "$out" "per-model totals" "report prints per-model totals" + assert_contains "$out" "claude-test" "report lists the claude model" + assert_contains "$out" "glm-5.3" "report lists the codex model" + assert_contains "$out" "zai/glm-5.3-flash" "report lists the provider-qualified pi model" + assert_contains "$out" "usagepi1" "report lists the pi task row" + assert_contains "$out" "usageclaude1" "report lists each task row" + assert_contains "$out" "usagecursor1" "report lists the unavailable task row" + assert_contains "$out" "unavailable" "report shows the unavailable source" + # Missing ledger exits 0 with a note. + out=$(FM_DATA_OVERRIDE="$TMP_ROOT/empty-home" "$REPORT" 2>&1) + expect_code 0 "$?" "report without a ledger should exit 0" + assert_contains "$out" "no usage ledger" "report names the missing ledger" + pass "usage report: per-model totals, per-task rows, missing-ledger tolerance" +} + +# A ledger line that jq cannot parse must fail the report loudly. Reporting +# exit 0 with a physical row count above empty sections presents a truncated +# fleet cost picture as a complete one. +report_malformed_case() { + local home ledger out status + home="$TMP_ROOT/home-usagemalformed" + mkdir -p "$home/data" + ledger="$home/data/usage-ledger.jsonl" + printf '{"task":"usagegood1","model":"good-model","source":"claude","input_tokens":7}\n' > "$ledger" + printf '{"task": truncated\n' >> "$ledger" + + out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) + status=$? + expect_code 1 "$status" "report of an unparseable ledger should fail"$'\n'"$out" + assert_contains "$out" "$ledger" "the failure names the offending ledger" + assert_not_contains "$out" "per-task rows" \ + "a failed report must not print sections it could not compute" + assert_not_contains "$out" "2 rows" \ + "a failed report must not present a physical row count as a result" + + # The same ledger without the truncated line still reports normally, so the + # failure is the parse error and not the new pre-render step. + printf '{"task":"usagegood1","model":"good-model","source":"claude","input_tokens":7}\n' > "$ledger" + out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) + expect_code 0 "$?" "report of a parseable ledger should still succeed"$'\n'"$out" + assert_contains "$out" "good-model" "the repaired ledger still renders its model row" + pass "usage report: an unparseable ledger fails loudly instead of reporting empty sections" +} + +# --- teardown integration: the harvest still sees the task status log ------- + +# Teardown deletes state/.status when it retires the task's status +# presentation. The harvest has to run before that, or it loses both the task +# window and the turn count and every row degrades to a zero-duration, +# zero-turn, source-unavailable line. +teardown_status_case() { + local proj wt id fb state data config out row + id=usageharvtd2 + proj="$TMP_ROOT/td2-proj"; wt="$TMP_ROOT/td2-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + fb="$TMP_ROOT/td2-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/treehouse" + chmod +x "$fb/tmux" "$fb/treehouse" + state="$TMP_ROOT/td2-state"; config="$TMP_ROOT/td2-config"; data="$TMP_ROOT/td2-data" + mkdir -p "$state" "$config" "$data/$id" + printf 'scout findings\n' > "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + { + printf 'working: scouting\n' + printf 'working: still scouting\n' + printf 'done: report written\n' + } > "$state/$id.status" + # A spawn 500s before the last status append, and a meta rewritten right at + # the end, exactly as a real PR registration leaves it. + local base + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.99.3\n' "$((base - 500))" >> "$state/$id.meta" + touch -t "$(touch_stamp "$base")" "$state/$id.meta" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/td2-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/td2-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/td2-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "teardown should succeed"$'\n'"$out" + assert_contains "$out" "teardown $id complete" "teardown completes" + [ ! -e "$state/$id.status" ] || fail "teardown left the status log behind" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"turns":2' \ + "the harvest counted the status log's working lines before teardown removed it" + assert_contains "$row" '"wall_secs":500' \ + "the harvest measured the task window before teardown removed the status log" + pass "teardown integration: the harvest runs while the status log still exists" +} + +# --- teardown integration: harvest failure never blocks teardown ------------ + +teardown_case() { + local proj wt id fb state data config out + id=usageharvtd1 + proj="$TMP_ROOT/td-proj"; wt="$TMP_ROOT/td-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + fb="$TMP_ROOT/td-fakebin" + mkdir -p "$fb" + cat > "$fb/tmux" <<'SH' +#!/usr/bin/env bash +exit 0 +SH + cat > "$fb/treehouse" <<'SH' +#!/usr/bin/env bash +exit 0 +SH + chmod +x "$fb/tmux" "$fb/treehouse" + state="$TMP_ROOT/td-state"; config="$TMP_ROOT/td-config"; data="$TMP_ROOT/td-data" + mkdir -p "$state" "$config" "$data/$id" + printf 'scout findings\n' > "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + printf 'working: scouting\n' > "$state/$id.status" + # The ledger path being a directory forces every append to fail. + mkdir -p "$data/usage-ledger.jsonl" + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/td-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/td-fake-codex" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "teardown must succeed even when the harvest fails"$'\n'"$out" + assert_contains "$out" "warning: usage harvest for $id failed" \ + "teardown warns one line when the harvest fails" + assert_contains "$out" "teardown $id complete" \ + "teardown completes after a harvest failure" + [ -z "$(find "$data" -maxdepth 1 -name 'usage-ledger.jsonl.tmp.*' -print -quit)" ] \ + || fail "a failed harvest left a ledger work file in the data dir" + pass "teardown integration: harvest failure is non-fatal and leaves no work file" +} + +# --- row scope: a relaunch must not narrow the window ----------------------- + +# fm-spawn rewrites spawn_gen on every relaunch but only ever appends to +# state/.status, so turns always span the whole task. A row therefore +# spans the whole task too: the start is the earliest durable first-spawn +# witness, and a later relaunch token must not shorten wall_secs or drop the +# first incarnation's session logs. +relaunch_scope_case() { + local id=usagerelaunch1 wt="$TMP_ROOT/.no-mistakes/wt-usagerelaunch1" + local data home state row out base encoded logdir fb + data=$(harvest_case "$id" claude "$wt" default default) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/first-incarnation.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgR1","model":"claude-test","usage":{"input_tokens":21,"output_tokens":4}}} +JSON + + # The task is born at base, runs for 600s, and is relaunched 300s in, which + # rewrites spawn_gen with the relaunch epoch. The birth time is pinned by a + # stat shim so the case asserts the harvester's rule rather than the + # runner's filesystem support for birth times. + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.4242.9\n' "$((base + 300))" >> "$state/$id.meta" + touch -t "$(touch_stamp $((base + 600)))" "$state/$id.status" + touch -t "$(touch_stamp $((base + 600)))" "$state/$id.meta" + # A request logged by the FIRST incarnation, before the relaunch token. + touch -t "$(touch_stamp $((base + 100)))" "$logdir/first-incarnation.jsonl" + + fb="$TMP_ROOT/relaunch-fakebin" + stat_shim_bin "$fb" "$state/$id.status" "$base" + out=$(PATH="$fb:$PATH" "$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "relaunch-scope harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"wall_secs":600' \ + "wall seconds span the whole task, not the last incarnation" + assert_contains "$row" "\"spawned_at\":\"$(iso_utc "$base")\"" \ + "spawned_at reports the first spawn, not the relaunch" + assert_contains "$row" '"turns":2' "turns count the whole task's working lines" + assert_contains "$row" '"input_tokens":21' \ + "the first incarnation's usage is inside the whole-task window" + assert_contains "$row" '"source":"claude-projects"' \ + "a pre-relaunch session log is still matched" + pass "usage harvest: a relaunch never narrows the row below the turn count's span" +} + +# The one documented condition under which a row narrows below the whole task: +# a filesystem with no birth time leaves spawn_gen as the only durable start, +# and a relaunch has already rewritten it, so wall_secs covers the final +# incarnation while turns still cover the whole task. +relaunch_birthless_case() { + local id=usagerelaunch2 wt="$TMP_ROOT/wt-usagerelaunch2" + local data home state row out base fb + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.4242.9\n' "$((base + 300))" >> "$state/$id.meta" + touch -t "$(touch_stamp $((base + 600)))" "$state/$id.status" + touch -t "$(touch_stamp $((base + 600)))" "$state/$id.meta" + + fb="$TMP_ROOT/relaunch-nobirth-fakebin" + stat_shim_bin "$fb" + out=$(PATH="$fb:$PATH" "$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "birthless relaunch harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"wall_secs":300' \ + "a birthless host narrows a relaunched row to the final incarnation" + assert_contains "$row" "\"spawned_at\":\"$(iso_utc $((base + 300)))\"" \ + "the relaunch token is the only durable start left" + assert_contains "$row" '"turns":2' \ + "turns still span the whole task, as the narrowing condition states" + pass "usage harvest: the birthless relaunch narrowing matches the stated contract" +} + +# --- corrupt lines: one bad line costs that line, not the file -------------- + +# Pi's session logs are append-only, so a truncated tail line is a realistic +# state. The cwd binding lives in the same parse as the usage, so an +# all-or-nothing parser would report the whole task as unavailable. +corrupt_line_case() { + local id=usagecorrupt1 wt="$TMP_ROOT/wt-usagecorrupt1" + local data home row out d1 + data=$(harvest_case "$id" pi "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_PI_DIR/--encoded-corrupt--" + mkdir -p "$d1" + cat > "$d1/session-corrupt.jsonl" <&1) + expect_code 0 "$?" "corrupt-line harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"source":"pi-sessions"' \ + "a corrupt line does not cost the file's cwd binding" + assert_contains "$row" '"input_tokens":49' "the valid records around a corrupt line are summed (40+9)" + assert_contains "$row" '"cached_input_tokens":3' "cached folds across the corrupt line (2+1)" + assert_contains "$row" '"output_tokens":8' "output sums across the corrupt line (6+2)" + assert_contains "$row" '"reasoning_tokens":4' "reasoning sums across the corrupt line (3+1)" + pass "usage harvest: a corrupt log line costs that line, not the file" +} + +# --- a usage record without a model must not shift the token fields --------- + +# The parser hands the loop a model field that can be empty. An empty field +# must stay in its own slot, or the counts land in the wrong ledger columns +# and the model string is reported as a token count. +# A line that parses to valid JSON but is not an object must be skipped like +# any other corrupt line, rather than aborting the parse and costing the file +# its cwd binding along with all of its usage. +nonobject_line_case() { + local id=usagenonobj1 wt="$TMP_ROOT/wt-usagenonobj1" + local data home row out d1 + data=$(harvest_case "$id" pi "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_PI_DIR/--encoded-nonobj--" + mkdir -p "$d1" + cat > "$d1/session-nonobj.jsonl" <&1) + expect_code 0 "$?" "non-object-line harvest should succeed"$' +'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"source":"pi-sessions"' \ + "a non-object line does not cost the file's cwd binding" + assert_contains "$row" '"input_tokens":20' \ + "records around a scalar or array line are still summed (12+8)" + assert_contains "$row" '"output_tokens":4' "output sums across the non-object lines (3+1)" + pass "usage harvest: a valid non-object log line is skipped, not fatal" +} + +missing_model_case() { + local id=usagenomodel1 wt="$TMP_ROOT/wt-usagenomodel1" + local data home row out d1 + data=$(harvest_case "$id" pi "$wt" pi-meta-model high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_PI_DIR/--encoded-nomodel--" + mkdir -p "$d1" + cat > "$d1/session-nomodel.jsonl" <&1) + expect_code 0 "$?" "model-less harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"model":"pi-meta-model"' \ + "a log with no model falls back to the meta model, never to a token count" + assert_contains "$row" '"input_tokens":100' "input stays in its own field" + assert_contains "$row" '"cached_input_tokens":25' "cached stays in its own field (20+5)" + assert_contains "$row" '"output_tokens":30' "output stays in its own field" + assert_contains "$row" '"reasoning_tokens":7' "reasoning stays in its own field" + pass "usage harvest: an absent log model never shifts the token fields" +} + +# --- source names assert a parsed match, for every harness alike ------------ + +# An in-window log that yields no assistant usage must report source +# "unavailable" with null token fields under claude exactly as under codex +# and pi, so the source enum means the same thing across harnesses. +no_usage_case() { + local id=usagenousage1 wt="$TMP_ROOT/.no-mistakes/wt-usagenousage1" + local data home row out encoded logdir + data=$(harvest_case "$id" claude "$wt" claude-meta-model default) + home=$(dirname "$data") + export_harvest_env "$home" + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session-nousage.jsonl" <<'JSON' +{"type":"user","message":{"role":"user"}} +{"type":"assistant","message":{"id":"msgNU"}} +JSON + touch -m -r "$logdir/session-nousage.jsonl" "$home/state/$id.status" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "no-usage harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"source":"unavailable"' \ + "an in-window log that yields no usage is not a source" + assert_contains "$row" '"input_tokens":null' "no parsed usage renders null input tokens" + assert_contains "$row" '"cached_input_tokens":null' "no parsed usage renders null cached tokens" + assert_contains "$row" '"output_tokens":null' "no parsed usage renders null output tokens" + assert_contains "$row" '"reasoning_tokens":null' "no parsed usage renders null reasoning tokens" + assert_contains "$row" '"model":"claude-meta-model"' "the row still reports the meta model" + pass "usage harvest: a source is named only after a log yields assistant usage" +} + +claude_case +claude_nobirth_case +codex_case +pi_case usagepi1 pi +pi_case usagepisigned1 pi-signed +spawn_gen_case +spawn_gen_malformed_case +spawn_gen_future_case +relaunch_scope_case +relaunch_birthless_case +corrupt_line_case +nonobject_line_case +missing_model_case +no_usage_case +cursor_case +remote_case +race_case +lock_bound_case +report_case +report_no_harness_case +report_malformed_case +teardown_status_case +teardown_case From 6aacdafa7d55d113609791d3c637ea7a0ed7c918 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Tue, 1 Sep 2026 14:00:41 -0400 Subject: [PATCH 02/16] no-mistakes(review): normalize codex token semantics, prefilter log scans, drop meta-mtime start --- bin/fm-usage-harvest.sh | 110 ++++++++++---- tests/fm-usage-harvest.test.sh | 256 ++++++++++++++++++++++++++++++--- 2 files changed, 321 insertions(+), 45 deletions(-) diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index c0b3fe83cbe..bb6275ca553 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -19,6 +19,14 @@ # "output_tokens":,"reasoning_tokens":, # "source":} # +# Token invariant, identical for every source: input_tokens counts FRESH, +# uncached input only, and cached_input_tokens counts every input token served +# from or written to a prompt cache, so the two fields are disjoint and their +# sum is the row's whole input side. reasoning_tokens is a subset of +# output_tokens. Each parser below normalizes its harness's own spelling onto +# that one meaning, so a column means the same thing across harnesses and the +# report can sum it over models that were served by different ones. +# # Row scope: a row describes the WHOLE task, spanning every relaunch, and # wall_secs, the session-log window and turns all report that one span. The # turn count dictates the scope because it can only be read from @@ -47,12 +55,15 @@ # whose filesystem reports no usable birth time; because a relaunch replaces # it with the relaunch epoch, the status birth is what holds the window open # over the whole task, which is the narrowing condition stated above. -# The meta file's own mtime is NOT a start source in its own right: later -# meta writes (PR registration, busy-state updates) move it forward to near -# the end of the task and collapse the window. +# The meta file's own mtime is NOT a start source on any path: later meta +# writes (PR registration, busy-state updates) move it forward to near the end +# of the task, which collapses wall_secs and inverts the log-matching window. # Only when neither durable source is available (a task spawned before the # token existed, on a birthless filesystem) does the start fall back to the -# meta mtime, then the status mtime. +# status file's mtime, which collapses the window to the task's last instant +# rather than resting it on a mutable timestamp; with no status file at all +# the start is the end, so the row reports a zero-length window rather than a +# fabricated one. # A start later than the end (a spawn with no status append after it) is # pinned to the end so spawned_at never postdates completed_at. # Turn estimate: count of "^working:" lines in the status file. @@ -64,17 +75,24 @@ # request's usage at .message.usage (input_tokens, # cache_read_input_tokens, cache_creation_input_tokens, output_tokens) and # Claude logs one entry per content block, so requests are deduped by -# .message.id before summing. cached_input_tokens folds cache_read + -# cache_creation (both billed on top of input_tokens); reasoning_tokens -# captures output_tokens_details.thinking_tokens when present (a subset -# of output_tokens). +# .message.id before summing. Claude's own input_tokens already excludes +# both cache counts, so it carries the invariant's fresh input as logged, +# and cached_input_tokens folds cache_read + cache_creation, which are +# billed on top of it; reasoning_tokens captures +# output_tokens_details.thinking_tokens when present. # harness=codex: /**/*.jsonl in the task window whose # session_meta cwd equals the meta worktree. Per-turn token_count events # carry one request's delta at .payload.info.last_token_usage # (input_tokens, cached_input_tokens, cache_write_input_tokens, # output_tokens, reasoning_output_tokens); summing those deltas equals the -# final cumulative total. cached_input_tokens folds cached + cache_write -# (subsets of input_tokens); the model comes from the turn_context. +# final cumulative total. Codex is the one source whose own input_tokens +# COUNTS the cached portion inside itself, which real logs establish +# because total_tokens equals input_tokens + output_tokens on every event +# they record. The ledger therefore folds cached + cache_write into +# cached_input_tokens and subtracts that same sum from the event's +# input_tokens, clamped at zero, so a codex row reports fresh input like +# every other source instead of counting its cached tokens twice. The +# model comes from the turn_context. # harness=pi, harness=pi-signed: /**/*.jsonl in the task window # whose "session" record's cwd equals the meta worktree. Both adapters run # the same Pi application and share one ~/.pi/agent state tree, so one @@ -82,11 +100,14 @@ # request's usage at .message.usage (input, cacheRead, cacheWrite, output, # reasoning) and Pi writes one record per message rather than one per # content block; records are still deduped by the record's own .id where -# present so a replayed line cannot double-count. cached_input_tokens -# folds cacheRead + cacheWrite; reasoning_tokens captures .reasoning (a -# subset of output). The model is reported provider-qualified as -# "/" to match the model spelling fm-spawn records in the -# meta, and bare when the record carries no provider. +# present so a replayed line cannot double-count. Pi's own input is +# already disjoint from its cache counts, verified on real logs where +# input + output + cacheRead equals Pi's own totalTokens, so it carries +# the invariant's fresh input as logged and cached_input_tokens folds +# cacheRead + cacheWrite; reasoning_tokens captures .reasoning. The model +# is reported provider-qualified as "/" to match the +# model spelling fm-spawn records in the meta, and bare when the record +# carries no provider. # harness=cursor, a task with a recorded remote_host (its worker ran on # another machine, so its logs are not on this filesystem), an absent log # tree, or no in-window log that yields this task's assistant usage: token @@ -95,6 +116,14 @@ # mere presence of an in-window file. # A corrupt log line is skipped best-effort by the parser, which reads each # line on its own and keeps the rest of that file's usage. +# The two cwd-bound scans (codex, pi) run inside a synchronous teardown over a +# session tree holding thousands of unrelated sibling logs, so a candidate +# that survives the mtime window is first probed for the cwd on its FIRST +# line, which is where both harnesses write the record carrying it, and is +# skipped without a full parse when that cwd names another worktree. The probe +# only ever REJECTS: a first line that is corrupt or carries no cwd falls +# through to the full parse, and the full parse still admits a file only when +# the cwd it reports equals the meta worktree. # # Idempotent: if the ledger already contains a line whose "task" is # , the command exits 0 without appending. @@ -204,8 +233,11 @@ for start_candidate in "$START_GEN" "$START_BIRTH"; do START_EPOCH=$start_candidate fi done +# The meta's mtime is deliberately absent from this chain: it moves forward on +# every later meta write, so resting the start on it collapses wall_secs and +# inverts the log-matching window. [ -n "$START_EPOCH" ] \ - || START_EPOCH=$(file_mtime_epoch "$META" 2>/dev/null || file_mtime_epoch "$STATUS" 2>/dev/null || printf '%s' "$END_EPOCH") + || START_EPOCH=$(file_mtime_epoch "$STATUS" 2>/dev/null || printf '%s' "$END_EPOCH") # Pin an impossible start to the end rather than inverting the window, which # would both report a negative duration and drop every session log. [ "$START_EPOCH" -le "$END_EPOCH" ] 2>/dev/null || START_EPOCH=$END_EPOCH @@ -257,7 +289,7 @@ matched_files() { # : print in-window *.jsonl paths IT=null; CT=null; OT=null; RT=null -# accumulate_usage +# accumulate_usage # # The three harness parsers differ only in their jq program; everything around # it lives here once. Each program reduces one session log to at most one @@ -268,14 +300,29 @@ IT=null; CT=null; OT=null; RT=null # line rather than the whole file's usage. This loop then binds the row to # this task by the cwd it reports, sums the counts and remembers the first # model seen. +# +# is a jq program run against the file's FIRST LINE only, printing +# the cwd that line records or nothing. A candidate whose probe names a +# different worktree is skipped before the full parse, which keeps a teardown +# from parsing thousands of unrelated sibling sessions in a shared tree. +# The probe can only reject: a first line that is corrupt, is not the session +# record or carries no cwd prints nothing and falls through to the full parse, +# and the full parse below still binds on the cwd the whole file reports. +# An empty probe (claude, whose logs carry no cwd at all) skips the step. accumulate_usage() { - local dir=$1 depth=$2 label=$3 prog=$4 - local files f row cwd m it ct ot rt + local dir=$1 depth=$2 label=$3 probe=$4 prog=$5 + local files f row cwd m it ct ot rt head_cwd files=$(matched_files "$dir" "$depth") [ -n "$files" ] || return 0 IT=0; CT=0; OT=0; RT=0 while IFS= read -r f; do [ -n "$f" ] || continue + if [ -n "$probe" ]; then + head_cwd=$(head -n 1 -- "$f" 2>/dev/null | jq -Rr "$probe" 2>/dev/null) || head_cwd= + if [ -n "$head_cwd" ] && [ "$head_cwd" != "$WORKTREE" ]; then + continue + fi + fi # @tsv renders a null field as an empty one, and "IFS=$'\t' read" would # drop those empty fields because tab is an IFS whitespace character, # shifting every later field into the wrong variable. Translating the @@ -306,7 +353,7 @@ case "$HARNESS" in # Claude's logs carry no cwd, so the encoded directory is the binding and # the row reports the worktree it was resolved from. # shellcheck disable=SC2016 # jq owns every $ expression in these literal programs. - accumulate_usage "$CLAUDE_DIR/$encoded" 1 claude-projects ' + accumulate_usage "$CLAUDE_DIR/$encoded" 1 claude-projects '' ' reduce (inputs | try (fromjson | objects) catch empty) as $l ({seen:{},n:0,m:null,it:0,ct:0,ot:0,rt:0}; if $l.type == "assistant" and ($l.message.usage // null) != null then @@ -330,7 +377,8 @@ case "$HARNESS" in codex) if [ -z "$REMOTE_HOST" ] && [ -n "$WORKTREE" ]; then # shellcheck disable=SC2016 # jq owns every $ expression in these literal programs. - accumulate_usage "$CODEX_DIR" "" codex-sessions ' + accumulate_usage "$CODEX_DIR" "" codex-sessions \ + 'fromjson? | objects | select(.type == "session_meta") | .payload.cwd // empty' ' reduce (inputs | try (fromjson | objects) catch empty) as $l ({cwd:null,n:0,m:null,it:0,ct:0,ot:0,rt:0}; if $l.type == "session_meta" then @@ -339,12 +387,17 @@ case "$HARNESS" in .m = $l.payload.model elif $l.type == "event_msg" and $l.payload.type == "token_count" and ($l.payload.info.last_token_usage // null) != null then - .n += 1 - | .it += ($l.payload.info.last_token_usage.input_tokens // 0) - | .ct += (($l.payload.info.last_token_usage.cached_input_tokens // 0) - + ($l.payload.info.last_token_usage.cache_write_input_tokens // 0)) - | .ot += ($l.payload.info.last_token_usage.output_tokens // 0) - | .rt += ($l.payload.info.last_token_usage.reasoning_output_tokens // 0) + ($l.payload.info.last_token_usage) as $u + | (($u.cached_input_tokens // 0) + + ($u.cache_write_input_tokens // 0)) as $cached + | .n += 1 + # Codex counts the cached tokens inside its own input_tokens, so + # the fresh input the ledger reports is the remainder, clamped at + # zero rather than going negative on a log that breaks that. + | .it += ([(($u.input_tokens // 0) - $cached), 0] | max) + | .ct += $cached + | .ot += ($u.output_tokens // 0) + | .rt += ($u.reasoning_output_tokens // 0) else . end) | if .n > 0 then [.cwd, .m, .it, .ct, .ot, .rt] | @tsv else empty end' fi @@ -352,7 +405,8 @@ case "$HARNESS" in pi|pi-signed) if [ -z "$REMOTE_HOST" ] && [ -n "$WORKTREE" ]; then # shellcheck disable=SC2016 # jq owns every $ expression in these literal programs. - accumulate_usage "$PI_DIR" "" pi-sessions ' + accumulate_usage "$PI_DIR" "" pi-sessions \ + 'fromjson? | objects | select(.type == "session") | .cwd // empty' ' reduce (inputs | try (fromjson | objects) catch empty) as $l ({cwd:null,seen:{},n:0,m:null,it:0,ct:0,ot:0,rt:0}; if $l.type == "session" then diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 78b1e9a6875..343dc2271d7 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -10,6 +10,9 @@ # that a harvest failure never blocks teardown. Also covers the whole-task row # scope a relaunch must not narrow, the per-line corrupt-log tolerance, and # the rule that a source is named only after a log yields assistant usage. +# Also covers the one token convention every parser normalizes onto, the +# first-line cwd probe that rejects an unrelated sibling session before +# parsing it in full, and the report's per-model grouping and column sums. set -u # shellcheck source=tests/lib.sh @@ -22,6 +25,7 @@ TEARDOWN="$ROOT/bin/fm-teardown.sh" TMP_ROOT=$(fm_test_tmproot fm-usage-harvest) command -v jq >/dev/null 2>&1 || { echo "skip: jq not found"; exit 0; } +REAL_JQ=$(command -v jq) file_mtime_epoch() { # local t @@ -166,6 +170,7 @@ codex_case() { {"timestamp":"2026-08-28T15:13:03.851Z","ordinal":0,"type":"session_meta","payload":{"session_id":"s1","cwd":"$wt"}} {"type":"event_msg","payload":{"type":"token_count","info":{"total_token_usage":{"input_tokens":100,"cached_input_tokens":10,"cache_write_input_tokens":5,"output_tokens":20,"reasoning_output_tokens":8},"last_token_usage":{"input_tokens":100,"cached_input_tokens":10,"cache_write_input_tokens":5,"output_tokens":20,"reasoning_output_tokens":8}}}} {"type":"event_msg","payload":{"type":"token_count","info":{"last_token_usage":{"input_tokens":50,"cached_input_tokens":0,"cache_write_input_tokens":0,"output_tokens":11,"reasoning_output_tokens":3}}}} +{"type":"event_msg","payload":{"type":"token_count","info":{"last_token_usage":{"input_tokens":2,"cached_input_tokens":9,"cache_write_input_tokens":0,"output_tokens":1,"reasoning_output_tokens":0}}}} {"type":"turn_context","payload":{"cwd":"$wt","model":"glm-5.3"}} JSON # Same window but a different cwd: must be excluded. @@ -191,11 +196,15 @@ JSON assert_contains "$row" '"model":"glm-5.3"' "codex row captures the turn_context model" assert_contains "$row" '"effort":"high"' "codex row carries meta effort" assert_contains "$row" '"source":"codex-sessions"' "codex row names its source" - assert_contains "$row" '"input_tokens":150' "codex input sums per-request deltas (100+50)" - assert_contains "$row" '"cached_input_tokens":15' "codex cached folds cached+cache_write (10+5+0)" - assert_contains "$row" '"output_tokens":31' "codex output sums deltas (20+11)" - assert_contains "$row" '"reasoning_tokens":11' "codex reasoning sums deltas (8+3)" - pass "codex harvest: cwd/window matching, delta sums, model capture" + # Codex counts its cached tokens inside its own input_tokens, so each event + # contributes only the fresh remainder: (100-15) + (50-0) + max(2-9, 0). + assert_contains "$row" '"input_tokens":135' \ + "codex input reports fresh input, never the cached tokens it already contains" + assert_contains "$row" '"cached_input_tokens":24' \ + "codex cached folds cached+cache_write (10+5+0+9)" + assert_contains "$row" '"output_tokens":32' "codex output sums deltas (20+11+1)" + assert_contains "$row" '"reasoning_tokens":11' "codex reasoning sums deltas (8+3+0)" + pass "codex harvest: cwd/window matching, delta sums, cache normalization, model capture" } # --- pi / pi-signed: shared session tree, cwd match, per-message usage ------- @@ -257,6 +266,171 @@ pi_case() { # pass "$harness harvest: cwd/window matching, per-request sums, replay dedupe" } +# --- one token convention across every parser ------------------------------- + +# The ledger's input_tokens counts FRESH input and cached_input_tokens counts +# everything served from or written to cache, whatever the harness spelled. +# Each fixture below encodes the SAME logical request in its own harness's +# convention: 40 fresh input tokens, 60 cached ones, 7 output and 2 reasoning. +# Claude and Pi log input excluding the cache, Codex logs it including the +# cache, so every row must still report the same four numbers. A parser that +# drifted back to its harness's raw spelling fails here. +token_convention_case() { + local wt id data home ledger row out logdir encoded d1 + + id=usageconvclaude + wt="$TMP_ROOT/.no-mistakes/wt-$id" + data=$(harvest_case "$id" claude "$wt" default default) + home=$(dirname "$data") + export_harvest_env "$home" + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgK","model":"conv-model","usage":{"input_tokens":40,"cache_read_input_tokens":50,"cache_creation_input_tokens":10,"output_tokens":7,"output_tokens_details":{"thinking_tokens":2}}}} +JSON + touch -m -r "$logdir/session.jsonl" "$home/state/$id.status" + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "claude convention harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"input_tokens":40,"cached_input_tokens":60,"output_tokens":7,"reasoning_tokens":2' \ + "claude reports fresh input and folded cache in the ledger's one convention" + + id=usageconvcodex + wt="$TMP_ROOT/wt-$id" + data=$(harvest_case "$id" codex "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_CODEX_DIR/2026/08/29" + mkdir -p "$d1" + cat > "$d1/rollout-conv.jsonl" <&1) + expect_code 0 "$?" "codex convention harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"input_tokens":40,"cached_input_tokens":60,"output_tokens":7,"reasoning_tokens":2' \ + "codex reports the same fresh input as the other parsers, cache counted once" + + id=usageconvpi + wt="$TMP_ROOT/wt-$id" + data=$(harvest_case "$id" pi "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_PI_DIR/--encoded-conv--" + mkdir -p "$d1" + cat > "$d1/session-conv.jsonl" <&1) + expect_code 0 "$?" "pi convention harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"input_tokens":40,"cached_input_tokens":60,"output_tokens":7,"reasoning_tokens":2' \ + "pi reports the same fresh input and folded cache as the other parsers" + pass "usage harvest: every parser normalizes onto one token convention" +} + +# --- candidate scanning is bound before the full parse ---------------------- + +# jq_trace_bin : a jq on PATH that records every session log +# handed to it as a FILE OPERAND before delegating to the real jq. The +# harvester's first-line cwd probe pipes its one line in on stdin, so a path in +# the trace means that whole file was parsed. +jq_trace_bin() { # + mkdir -p "$1" + cat > "$1/jq" <> "$2" ;; + esac +done +exec "$REAL_JQ" "\$@" +SH + chmod +x "$1/jq" +} + +# A busy fleet leaves thousands of sibling sessions in the shared codex and pi +# trees, and the harvest runs synchronously inside teardown, so a candidate +# that the cwd binding will reject must be rejected from its first line rather +# than after a full parse of a large file. +prefilter_case() { + local id wt data home d1 fb trace row out i + + id=usageprefiltercodex + wt="$TMP_ROOT/wt-$id" + data=$(harvest_case "$id" codex "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_CODEX_DIR/2026/08/30" + mkdir -p "$d1" + cat > "$d1/rollout-match.jsonl" < "$d1/rollout-sibling.jsonl" + for i in $(seq 1 2000); do + printf '{"type":"event_msg","payload":{"type":"token_count","info":{"last_token_usage":{"input_tokens":%s,"output_tokens":1}}}}\n' "$i" + done >> "$d1/rollout-sibling.jsonl" + touch -m -r "$d1/rollout-match.jsonl" "$d1/rollout-sibling.jsonl" + touch -m -r "$d1/rollout-match.jsonl" "$home/state/$id.status" + + fb="$TMP_ROOT/prefilter-fakebin" + trace="$TMP_ROOT/prefilter-codex-trace" + : > "$trace" + jq_trace_bin "$fb" "$trace" + out=$(PATH="$fb:$PATH" "$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "codex prefilter harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"input_tokens":30' "the matching codex session is still summed" + assert_contains "$row" '"source":"codex-sessions"' "the matching codex session still names its source" + assert_contains "$(cat "$trace")" "rollout-match.jsonl" \ + "the matching session is parsed in full" + assert_not_contains "$(cat "$trace")" "rollout-sibling.jsonl" \ + "a sibling session from another worktree is rejected without being parsed" + + id=usageprefilterpi + wt="$TMP_ROOT/wt-$id" + data=$(harvest_case "$id" pi "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_PI_DIR/--encoded-prefilter--" + mkdir -p "$d1" + cat > "$d1/session-match.jsonl" < "$d1/session-sibling.jsonl" + for i in $(seq 1 2000); do + printf '{"type":"message","id":"s%s","message":{"role":"assistant","usage":{"input":%s,"output":1}}}\n' "$i" "$i" + done >> "$d1/session-sibling.jsonl" + touch -m -r "$d1/session-match.jsonl" "$d1/session-sibling.jsonl" + touch -m -r "$d1/session-match.jsonl" "$home/state/$id.status" + + trace="$TMP_ROOT/prefilter-pi-trace" + : > "$trace" + jq_trace_bin "$fb" "$trace" + out=$(PATH="$fb:$PATH" "$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "pi prefilter harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"input_tokens":30' "the matching pi session is still summed" + assert_contains "$row" '"source":"pi-sessions"' "the matching pi session still names its source" + assert_contains "$(cat "$trace")" "session-match.jsonl" \ + "the matching pi session is parsed in full" + assert_not_contains "$(cat "$trace")" "session-sibling.jsonl" \ + "a sibling pi session from another worktree is rejected without being parsed" + pass "usage harvest: a non-matching sibling log is rejected before the full parse" +} + # --- spawn_gen: the task start survives a meta rewritten after the fact ------ # fm-spawn records spawn_gen=s.. once per incarnation and @@ -368,11 +542,11 @@ cursor_case() { pass "cursor harvest: unavailable source renders null token fields" } -# --- claude: window survives a host without usable birth time --------------- +# --- claude: the start chain on a host without usable birth time ------------ # A stat shim that reports no birth time (GNU statx unsupported returns 0 for -# %W) while still answering mtime, so the harvest must fall back to the meta -# mtime for the window start instead of collapsing to the status mtime. +# %W) while still answering mtime, so the harvest has to resolve its start +# from the remaining chain rather than from the status file's birth. # stat_shim_bin [ ] : put a stat shim on PATH # that answers mtime truthfully while controlling what the harvester reads for # a birth time. With no birth argument every file reports no usable birth time @@ -430,15 +604,22 @@ claude_nobirth_case() { mkdir -p "$logdir" cat > "$logdir/session.jsonl" <<'JSON' {"type":"assistant","message":{"id":"msgN","model":"claude-test","usage":{"input_tokens":12,"output_tokens":8}}} +JSON + cat > "$logdir/session-before-meta.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgP","model":"claude-test","usage":{"input_tokens":555,"output_tokens":555}}} JSON - # Pin an explicit window: status finishes at T, meta was spawned 100s earlier, - # and the session log lands mid-window. Without the meta-mtime start fallback - # the birthless window collapses to [T, T] and drops the earlier log. + # No spawn_gen token and no usable birth time leaves the status mtime as the + # only immutable start, so the window is the single instant [T, T]. The meta + # is aged 100s to prove it is not a start source on any path: a window opened + # from that mutable timestamp would swallow the pre-meta log below, and a + # meta rewritten to AFTER the last status append would instead collapse the + # window forward and drop the real one. base=$(file_mtime_epoch "$state/$id.status") touch -t "$(touch_stamp "$base")" "$state/$id.status" touch -t "$(touch_stamp $((base - 100)))" "$state/$id.meta" - touch -t "$(touch_stamp $((base - 50)))" "$logdir/session.jsonl" + touch -t "$(touch_stamp "$base")" "$logdir/session.jsonl" + touch -t "$(touch_stamp $((base - 50)))" "$logdir/session-before-meta.jsonl" fb="$TMP_ROOT/nobirth-fakebin" stat_shim_bin "$fb" @@ -447,11 +628,16 @@ JSON ledger="$data/usage-ledger.jsonl" row=$(cat "$ledger") assert_contains "$row" '"source":"claude-projects"' \ - "birthless harvest still finds the in-window log via the meta-mtime start" - assert_contains "$row" '"input_tokens":12' "birthless harvest sums the in-window usage" - assert_contains "$row" '"wall_secs":100' \ - "birthless window spans meta -> status instead of collapsing to zero" - pass "claude harvest: window survives a host without usable birth time" + "the birthless window still matches the log written at the status instant" + assert_contains "$row" '"input_tokens":12' \ + "only the in-window request is summed, not the one predating the status mtime" + assert_contains "$row" '"wall_secs":0' \ + "a birthless start rests on the status mtime, never on the mutable meta mtime" + assert_contains "$row" "\"spawned_at\":\"$(iso_utc "$base")\"" \ + "spawned_at is the status mtime, not the older meta mtime" + assert_contains "$row" "\"completed_at\":\"$(iso_utc "$base")\"" \ + "completed_at is the last status append" + pass "claude harvest: a birthless host never falls back to the mutable meta mtime" } # --- remote secondmate: local logs are never harvested for remote work ------ @@ -590,6 +776,39 @@ report_case() { pass "usage report: per-model totals, per-task rows, missing-ledger tolerance" } +# The per-model section groups on the model and sums each token column, so the +# numbers themselves are the contract. A ledger written here by hand pins them +# exactly: two tasks share one model across two different harnesses, a third +# task carries another model, and a fourth is source-unavailable. +report_model_totals_case() { + local home ledger out fields + home="$TMP_ROOT/home-usagetotals" + mkdir -p "$home/data" + ledger="$home/data/usage-ledger.jsonl" + cat > "$ledger" <<'JSON' +{"task":"agg1","harness":"claude","model":"agg-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":100,"turns":2,"input_tokens":10,"cached_input_tokens":20,"output_tokens":30,"reasoning_tokens":4,"source":"claude-projects"} +{"task":"agg2","harness":"codex","model":"agg-model","effort":"high","spawned_at":null,"completed_at":null,"wall_secs":200,"turns":1,"input_tokens":1,"cached_input_tokens":2,"output_tokens":3,"reasoning_tokens":1,"source":"codex-sessions"} +{"task":"agg3","harness":"claude","model":"other-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":7,"turns":1,"input_tokens":5,"cached_input_tokens":6,"output_tokens":7,"reasoning_tokens":8,"source":"claude-projects"} +{"task":"agg4","harness":"cursor","model":"agg-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":900,"turns":1,"input_tokens":null,"cached_input_tokens":null,"output_tokens":null,"reasoning_tokens":null,"source":"unavailable"} +JSON + out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) + expect_code 0 "$?" "report of the totals ledger should succeed"$'\n'"$out" + + # model tasks input cached output reasoning wall_secs, in that order. + fields=$(printf '%s\n' "$out" | awk '$1 == "agg-model" {print $2"|"$3"|"$4"|"$5"|"$6"|"$7}') + [ "$fields" = "2|11|22|33|5|300" ] \ + || fail "per-model totals for agg-model are wrong: [$fields]" + fields=$(printf '%s\n' "$out" | awk '$1 == "other-model" {print $2"|"$3"|"$4"|"$5"|"$6"|"$7}') + [ "$fields" = "1|5|6|7|8|7" ] \ + || fail "per-model totals for other-model are wrong: [$fields]" + # Both agg-model rows still appear per task, so the grouping folded them + # rather than the report dropping one. + assert_contains "$out" "agg1" "the per-task section still lists the first task" + assert_contains "$out" "agg2" "the per-task section still lists the second task" + assert_contains "$out" "agg4" "the per-task section still lists the unavailable task" + pass "usage report: per-model rows group on the model and sum each column" +} + # A ledger line that jq cannot parse must fail the report loudly. Reporting # exit 0 with a physical row count above empty sections presents a truncated # fleet cost picture as a complete one. @@ -929,6 +1148,8 @@ claude_nobirth_case codex_case pi_case usagepi1 pi pi_case usagepisigned1 pi-signed +token_convention_case +prefilter_case spawn_gen_case spawn_gen_malformed_case spawn_gen_future_case @@ -943,6 +1164,7 @@ remote_case race_case lock_bound_case report_case +report_model_totals_case report_no_harness_case report_malformed_case teardown_status_case From cdf4236b4856656df46844c3d36298cfaa0374d2 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Tue, 1 Sep 2026 14:13:25 -0400 Subject: [PATCH 03/16] no-mistakes(review): subtract only evidence-backed cached tokens in codex parser --- bin/fm-usage-harvest.sh | 30 ++++++++++++++++--------- tests/fm-usage-harvest.test.sh | 41 ++++++++++++++++++++++++++++++---- 2 files changed, 56 insertions(+), 15 deletions(-) diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index bb6275ca553..0b918007931 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -86,13 +86,19 @@ # (input_tokens, cached_input_tokens, cache_write_input_tokens, # output_tokens, reasoning_output_tokens); summing those deltas equals the # final cumulative total. Codex is the one source whose own input_tokens -# COUNTS the cached portion inside itself, which real logs establish +# COUNTS cached_input_tokens inside itself, which real logs establish # because total_tokens equals input_tokens + output_tokens on every event -# they record. The ledger therefore folds cached + cache_write into -# cached_input_tokens and subtracts that same sum from the event's -# input_tokens, clamped at zero, so a codex row reports fresh input like -# every other source instead of counting its cached tokens twice. The -# model comes from the turn_context. +# carrying usage. The ledger therefore subtracts cached_input_tokens from +# the event's input_tokens, clamped at zero, so a codex row reports fresh +# input like every other source instead of counting its cached tokens +# twice. Whether cache_write_input_tokens is inside input_tokens too is +# UNKNOWN, assumed neither way, because that field is zero in every +# observed session: it is folded into cached_input_tokens but NOT +# subtracted, since subtracting an uncontained field would silently +# under-count fresh input. If it ever turns up non-zero, re-check whether +# total_tokens still equals input_tokens + output_tokens on such an event, +# which is the arithmetic that settles containment. The model comes from +# the turn_context. # harness=pi, harness=pi-signed: /**/*.jsonl in the task window # whose "session" record's cwd equals the meta worktree. Both adapters run # the same Pi application and share one ~/.pi/agent state tree, so one @@ -388,14 +394,16 @@ case "$HARNESS" in elif $l.type == "event_msg" and $l.payload.type == "token_count" and ($l.payload.info.last_token_usage // null) != null then ($l.payload.info.last_token_usage) as $u - | (($u.cached_input_tokens // 0) - + ($u.cache_write_input_tokens // 0)) as $cached | .n += 1 - # Codex counts the cached tokens inside its own input_tokens, so + # Codex counts cached_input_tokens inside its own input_tokens, so # the fresh input the ledger reports is the remainder, clamped at # zero rather than going negative on a log that breaks that. - | .it += ([(($u.input_tokens // 0) - $cached), 0] | max) - | .ct += $cached + # cache_write_input_tokens is NOT subtracted: no observed log + # establishes whether it is inside input_tokens. + | .it += ([(($u.input_tokens // 0) + - ($u.cached_input_tokens // 0)), 0] | max) + | .ct += (($u.cached_input_tokens // 0) + + ($u.cache_write_input_tokens // 0)) | .ot += ($u.output_tokens // 0) | .rt += ($u.reasoning_output_tokens // 0) else . end) diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 343dc2271d7..0b8a744e5a7 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -196,9 +196,9 @@ JSON assert_contains "$row" '"model":"glm-5.3"' "codex row captures the turn_context model" assert_contains "$row" '"effort":"high"' "codex row carries meta effort" assert_contains "$row" '"source":"codex-sessions"' "codex row names its source" - # Codex counts its cached tokens inside its own input_tokens, so each event - # contributes only the fresh remainder: (100-15) + (50-0) + max(2-9, 0). - assert_contains "$row" '"input_tokens":135' \ + # Codex counts cached_input_tokens inside its own input_tokens, so each event + # contributes only the fresh remainder: (100-10) + (50-0) + max(2-9, 0). + assert_contains "$row" '"input_tokens":140' \ "codex input reports fresh input, never the cached tokens it already contains" assert_contains "$row" '"cached_input_tokens":24' \ "codex cached folds cached+cache_write (10+5+0+9)" @@ -307,7 +307,7 @@ JSON cat > "$d1/rollout-conv.jsonl" <&1) @@ -336,6 +336,38 @@ JSON pass "usage harvest: every parser normalizes onto one token convention" } +# Codex's input_tokens is known to contain cached_input_tokens, and that is +# the only field the ledger subtracts from it. Whether cache_write_input_tokens +# is inside input_tokens too is untestable from real logs, which report it as +# zero everywhere, so it is folded into the cached column and left in the fresh +# input rather than being subtracted on a hunch: subtracting an uncontained +# field would under-count fresh input and the clamp would hide it. +codex_cache_write_case() { + local id=usagecodexwrite wt="$TMP_ROOT/wt-usagecodexwrite" + local data home row out d1 + data=$(harvest_case "$id" codex "$wt" default high) + home=$(dirname "$data") + export_harvest_env "$home" + d1="$FM_USAGE_CODEX_DIR/2026/08/31" + mkdir -p "$d1" + cat > "$d1/rollout-write.jsonl" <&1) + expect_code 0 "$?" "codex cache-write harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"input_tokens":50' \ + "only the cached tokens codex counts inside input are subtracted (80-30)" + assert_contains "$row" '"cached_input_tokens":55' \ + "cache_write is still counted in the cached column (30+25)" + assert_contains "$row" '"output_tokens":6' "cache_write never touches the output column" + pass "codex harvest: cache_write is folded into cached, never subtracted from input" +} + # --- candidate scanning is bound before the full parse ---------------------- # jq_trace_bin : a jq on PATH that records every session log @@ -1149,6 +1181,7 @@ codex_case pi_case usagepi1 pi pi_case usagepisigned1 pi-signed token_convention_case +codex_cache_write_case prefilter_case spawn_gen_case spawn_gen_malformed_case From 63699ce2e93ff65b47e6f98471942aa5d3241292 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Tue, 1 Sep 2026 14:28:05 -0400 Subject: [PATCH 04/16] no-mistakes(review): document harness-switch narrowing, pin final-incarnation model --- bin/fm-usage-harvest.sh | 47 ++++++++++----- tests/fm-usage-harvest.test.sh | 102 ++++++++++++++++++++++++++++++++- 2 files changed, 135 insertions(+), 14 deletions(-) diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index 0b918007931..6039484fc5d 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -34,14 +34,24 @@ # no incarnation delimiter; per-incarnation turns are therefore not derivable # from durable data, and scoping only the window to an incarnation would # report whole-task turns against a one-incarnation window and token sum. -# ONE condition narrows a row below that span, and only for a task that was -# actually relaunched: a filesystem that reports no birth time for -# state/.status leaves the meta's spawn_gen as the only durable -# start, and fm-spawn rewrites that token on every relaunch, so wall_secs and -# the token sum then cover the final incarnation while turns still cover the -# whole task. No per-task record of the first spawn survives a relaunch on -# such a host, so a relaunched row there is narrowed rather than wrong; a task -# that was never relaunched always yields a whole-task row on every +# TWO conditions narrow a row below that span, both only for a task that was +# actually relaunched. +# First, a filesystem that reports no birth time for state/.status +# leaves the meta's spawn_gen as the only durable start, and fm-spawn rewrites +# that token on every relaunch, so wall_secs and the token sum then cover the +# final incarnation while turns still cover the whole task. No per-task record +# of the first spawn survives a relaunch on such a host, so a relaunched row +# there is narrowed rather than wrong. +# Second, a relaunch may switch the harness, and the meta records only the +# final incarnation's harness, so the scan below reads only that harness's log +# tree: the TOKEN fields and the session-log window they are summed over then +# cover the final harness alone, and an earlier incarnation's usage under a +# different harness is not summed. wall_secs, turns, spawned_at and +# completed_at still span the whole task in that case, so only the token +# fields and their window narrow. Summing every incarnation across different +# harness trees is separate follow-up work and is deliberately not attempted +# here. +# A task that was never relaunched always yields a whole-task row on every # filesystem. # # Wall clock: task start epoch -> status-file mtime epoch; the meta file's @@ -122,6 +132,12 @@ # mere presence of an in-window file. # A corrupt log line is skipped best-effort by the parser, which reads each # line on its own and keeps the rest of that file's usage. +# Matching logs are scanned in a deterministic order, oldest mtime first and +# ties broken by path, and the row's model is the one recorded by the LAST +# such log that yielded usage, so a task relaunched onto another model on the +# same harness reports the final incarnation's model, which is the one the +# meta itself records. The same inputs therefore always produce the same model +# field. It falls back to the meta model when no log yields one. # The two cwd-bound scans (codex, pi) run inside a synchronous teardown over a # session tree holding thousands of unrelated sibling logs, so a candidate # that survives the mtime window is first probed for the cwd on its FIRST @@ -284,13 +300,17 @@ matched_files() { # : print in-window *.jsonl paths if [ -n "$2" ]; then depthargs=(-maxdepth "$2") fi + # find's enumeration order is unspecified, so the mtime it already read is + # promoted to a sort key: oldest first, ties broken by path. The caller + # depends on that order to resolve the model to the last incarnation's. while IFS= read -r f; do m=$(file_mtime_epoch "$f") || continue if [ "$m" -ge "$START_EPOCH" ] && [ "$m" -le "$END_EPOCH" ]; then - printf '%s\n' "$f" + printf '%s\t%s\n' "$m" "$f" fi done < <(find "$dir" ${depthargs[@]+"${depthargs[@]}"} -type f -name '*.jsonl' \ - -newer "$REFDIR/start" ! -newer "$REFDIR/end" -print 2>/dev/null) || true + -newer "$REFDIR/start" ! -newer "$REFDIR/end" -print 2>/dev/null) \ + | LC_ALL=C sort -t "$(printf '\t')" -k1,1n -k2,2 | cut -f2- } IT=null; CT=null; OT=null; RT=null @@ -304,8 +324,9 @@ IT=null; CT=null; OT=null; RT=null # parses to nothing leaves the source unavailable. Each program also reads its # input line by line through "try fromjson", so one corrupt line costs that # line rather than the whole file's usage. This loop then binds the row to -# this task by the cwd it reports, sums the counts and remembers the first -# model seen. +# this task by the cwd it reports, sums the counts and keeps the model of the +# LAST matching log in matched_files' oldest-first order, which is the final +# incarnation's. # # is a jq program run against the file's FIRST LINE only, printing # the cwd that line records or nothing. A candidate whose probe names a @@ -340,7 +361,7 @@ accumulate_usage() { IFS=$'\037' read -r cwd m it ct ot rt <<<"$row" [ "$cwd" = "$WORKTREE" ] || continue SRC=$label - [ -n "$m" ] && [ -z "$MODEL_LOG" ] && MODEL_LOG=$m + [ -n "$m" ] && MODEL_LOG=$m IT=$((IT + ${it:-0})) CT=$((CT + ${ct:-0})) OT=$((OT + ${ot:-0})) diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 0b8a744e5a7..159675eb901 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -12,7 +12,9 @@ # the rule that a source is named only after a log yields assistant usage. # Also covers the one token convention every parser normalizes onto, the # first-line cwd probe that rejects an unrelated sibling session before -# parsing it in full, and the report's per-model grouping and column sums. +# parsing it in full, the report's per-model grouping and column sums, the +# documented harness-switch narrowing, and deterministic final-incarnation +# model attribution. set -u # shellcheck source=tests/lib.sh @@ -1044,6 +1046,102 @@ relaunch_birthless_case() { pass "usage harvest: the birthless relaunch narrowing matches the stated contract" } +# fm-spawn's --relaunch may switch the harness, and it rewrites the meta with +# only the new incarnation's harness. The token fields then cover the final +# harness alone, while wall_secs and turns still span the whole task. This case +# pins that documented narrowing from both sides: a widened scan that summed +# the earlier harness's log, and a scan narrowed to the final incarnation's +# window, would each change a number asserted here. +harness_switch_case() { + local id=usageharnessswitch wt="$TMP_ROOT/.no-mistakes/wt-usageharnessswitch" + local data home state row out base encoded logdir d1 + data=$(harvest_case "$id" codex "$wt" default high) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.4242.3\n' "$((base - 600))" >> "$state/$id.meta" + touch -t "$(touch_stamp "$base")" "$state/$id.status" + + # The first incarnation ran under claude and left its own session log inside + # the task window, at the encoded project directory the claude parser reads. + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/first-harness.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgH","model":"claude-test","usage":{"input_tokens":700,"output_tokens":70}}} +JSON + touch -t "$(touch_stamp $((base - 500)))" "$logdir/first-harness.jsonl" + + # The task was relaunched onto codex, which is what the meta records. + d1="$FM_USAGE_CODEX_DIR/2026/09/01" + mkdir -p "$d1" + cat > "$d1/rollout-second.jsonl" <&1) + expect_code 0 "$?" "harness-switch harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"source":"codex-sessions"' \ + "the row names the final incarnation's harness tree" + assert_contains "$row" '"input_tokens":9' \ + "tokens cover the final harness only, never the earlier harness's log" + assert_contains "$row" '"output_tokens":3' \ + "the earlier harness's output is not summed either" + assert_contains "$row" '"wall_secs":600' \ + "wall seconds still span the whole task across the harness switch" + assert_contains "$row" '"turns":2' \ + "turns still count the whole task's working lines" + pass "usage harvest: a harness switch narrows the tokens only, as documented" +} + +# A relaunch onto another model on the SAME harness leaves both incarnations' +# logs in the window, and the row has one model field. It must be the final +# incarnation's, and it must not depend on the order the filesystem enumerates +# the logs in: the older log is created first here, so a first-log-wins rule +# reports the superseded model. +model_final_incarnation_case() { + local id=usagemodelfinal wt="$TMP_ROOT/.no-mistakes/wt-usagemodelfinal" + local data home state row out base encoded logdir + data=$(harvest_case "$id" claude "$wt" meta-fallback-model default) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session-a-first.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgM1","model":"first-incarnation-model","usage":{"input_tokens":5,"output_tokens":1}}} +JSON + cat > "$logdir/session-b-second.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgM2","model":"final-incarnation-model","usage":{"input_tokens":7,"output_tokens":2}}} +JSON + + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.4242.4\n' "$((base - 600))" >> "$state/$id.meta" + touch -t "$(touch_stamp "$base")" "$state/$id.status" + touch -t "$(touch_stamp $((base - 400)))" "$logdir/session-a-first.jsonl" + touch -t "$(touch_stamp $((base - 100)))" "$logdir/session-b-second.jsonl" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "model-attribution harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"model":"final-incarnation-model"' \ + "the row reports the last incarnation's model, not the first log's" + assert_contains "$row" '"input_tokens":12' \ + "both incarnations' usage is still summed on one harness (5+7)" + assert_contains "$row" '"output_tokens":3' "both incarnations' output is summed (1+2)" + pass "usage harvest: the model is the final incarnation's, whatever the scan order" +} + # --- corrupt lines: one bad line costs that line, not the file -------------- # Pi's session logs are append-only, so a truncated tail line is a realistic @@ -1188,6 +1286,8 @@ spawn_gen_malformed_case spawn_gen_future_case relaunch_scope_case relaunch_birthless_case +harness_switch_case +model_final_incarnation_case corrupt_line_case nonobject_line_case missing_model_case From 33b44e090e59ce82eff439c18d9d17c129d43453 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 06:28:28 -0400 Subject: [PATCH 05/16] no-mistakes(review): scan to harvest instant, harvest secondmate children --- bin/fm-teardown.sh | 13 +++- bin/fm-usage-harvest.sh | 42 ++++++++-- tests/fm-usage-harvest.test.sh | 138 ++++++++++++++++++++++++++++++--- 3 files changed, 176 insertions(+), 17 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index d79bc16edcc..a06d4f4d68d 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -3,7 +3,9 @@ # worktree, or retire a secondmate home; kill the recorded runtime endpoint, # harvest the task's fleet usage-ledger row while its state files still exist # (best effort: bin/fm-usage-harvest.sh owns that ledger, and a harvest failure -# only warns on stderr rather than blocking teardown), +# only warns on stderr rather than blocking teardown; a forced secondmate +# teardown harvests each of that home's children the same way before their own +# records retire), # clear volatile state, and transition this home's backlog item for ship and # scout tasks before reporting success (a secondmate teardown transitions none, # since secondmates are not backlog items), then refresh/prune the project's @@ -2573,6 +2575,15 @@ cleanup_firstmate_home_children() { child_busy_gen=$(cat "$sub_state/$child_id.busy-gen" 2>/dev/null || true) fi retire_busy_state "$sub_state" "$child_id" "$child_busy_gen" || return 1 + # A local secondmate's children ran on this filesystem, so their session + # logs are here to harvest. The child's records are read from its own + # home, and the row is appended to the ledger of the home running this + # cleanup, which is the one that outlives the child home removed below. + # Best effort, exactly as at the other retirement sites: a failure warns + # and never changes this cleanup's own outcome. + FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ + "$FM_ROOT/bin/fm-usage-harvest.sh" "$child_id" >/dev/null \ + || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 status_retire_presentation_task "$sub_state" "$child_id" || return 1 fm_backlog_atomic_transition remove "$sub_state/$child_id.meta" "task record" "$sub_state" || return 1 rm -f "$sub_state/$child_id.turn-ended" \ diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index 6039484fc5d..8886967e323 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -76,6 +76,17 @@ # fabricated one. # A start later than the end (a spawn with no status append after it) is # pinned to the end so spawned_at never postdates completed_at. +# The window the SESSION LOGS are matched against runs from that same start to +# the HARVEST INSTANT, which is later than completed_at. A crewmate appends +# its final status line from inside an agent turn, so the harness writes that +# turn's tool result and its closing assistant entry into the session log +# after the append returns, and matching at file granularity against +# completed_at drops the whole log rather than its tail. The harvest instant +# bounds that extension without an arbitrary grace period: the harvest runs +# inside this task's own teardown, while the task still holds its worktree, so +# a later task cannot yet have written into the same pooled worktree slot. +# wall_secs, spawned_at and completed_at are unaffected and still rest on the +# status file. # Turn estimate: count of "^working:" lines in the status file. # # Per-request usage sources: @@ -267,6 +278,18 @@ WALL=$((END_EPOCH - START_EPOCH)) TURNS=$(grep -c '^working:' "$STATUS" 2>/dev/null || true) case "$TURNS" in ''|*[!0-9]*) TURNS=0 ;; esac +# The LOG-matching window ends at the harvest instant rather than at +# END_EPOCH: a crewmate appends its final status line from inside an agent +# turn, so the harness writes that turn's tool result and closing assistant +# entry into its own session log after the append returns, and a file-level +# filter cut at END_EPOCH drops the whole log rather than just its tail. The +# harvest instant is bounded and owned by this task, because it runs inside +# this task's own teardown while the task still holds its worktree, so no +# later task can yet have written into the same pooled worktree slot. +SCAN_END_EPOCH=$(date +%s 2>/dev/null || printf '%s' "$END_EPOCH") +case "$SCAN_END_EPOCH" in ''|*[!0-9]*) SCAN_END_EPOCH=$END_EPOCH ;; esac +[ "$SCAN_END_EPOCH" -ge "$END_EPOCH" ] 2>/dev/null || SCAN_END_EPOCH=$END_EPOCH + # Ref files pin find's mtime window portably (BSD and GNU find both compare # against -newer file mtimes, and touch -t exists on both). REFDIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-harvest.XXXXXX") @@ -285,10 +308,10 @@ epoch_to_touch() { # date -r "$1" +%Y%m%d%H%M.%S 2>/dev/null || date -d "@$1" +%Y%m%d%H%M.%S } # find -newer compares sub-second mtimes, so the refs only narrow to -# [START-1, END+1]; the per-file epoch filter below then applies the true -# inclusive whole-second window [START_EPOCH, END_EPOCH]. +# [START-1, SCAN_END+1]; the per-file epoch filter below then applies the true +# inclusive whole-second window [START_EPOCH, SCAN_END_EPOCH]. touch -t "$(epoch_to_touch "$((START_EPOCH - 1))")" "$REFDIR/start" -touch -t "$(epoch_to_touch "$((END_EPOCH + 1))")" "$REFDIR/end" +touch -t "$(epoch_to_touch "$((SCAN_END_EPOCH + 1))")" "$REFDIR/end" LEDGER="$DATA/usage-ledger.jsonl" @@ -305,7 +328,7 @@ matched_files() { # : print in-window *.jsonl paths # depends on that order to resolve the model to the last incarnation's. while IFS= read -r f; do m=$(file_mtime_epoch "$f") || continue - if [ "$m" -ge "$START_EPOCH" ] && [ "$m" -le "$END_EPOCH" ]; then + if [ "$m" -ge "$START_EPOCH" ] && [ "$m" -le "$SCAN_END_EPOCH" ]; then printf '%s\t%s\n' "$m" "$f" fi done < <(find "$dir" ${depthargs[@]+"${depthargs[@]}"} -type f -name '*.jsonl' \ @@ -484,7 +507,7 @@ mkdir -p -- "$DATA" # this runs synchronously inside teardown: a wedged live holder must never # block teardown from retiring the task. fm_lock_try_acquire already steals a # dead owner's lock, so only a live concurrent harvest makes us wait, and its -# critical section is a grep plus an append. If the lock stays busy past the +# critical section is one ledger scan plus an append. If the lock stays busy past the # bound we give up best-effort (exit 1, which teardown warns on and continues) # rather than duplicate the row by appending unserialized. LEDGER_LOCK="$DATA/.usage-ledger.lock" @@ -498,7 +521,14 @@ until fm_lock_try_acquire "$LEDGER_LOCK"; do sleep 0.1 done LEDGER_LOCK_HELD=1 -if [ -f "$LEDGER" ] && grep -qF "\"task\":\"$ID\"" "$LEDGER" 2>/dev/null; then +# The identity test parses each ledger line and compares the task field's own +# value, so exactness is structural rather than resting on the punctuation +# that happens to surround the field today: it stays exact if the schema or +# the key order ever changes. A line this cannot parse simply does not match, +# which risks a duplicate row rather than a lost one. +if [ -f "$LEDGER" ] && jq -Rn --exit-status --arg id "$ID" \ + 'any(inputs | try (fromjson | objects) catch empty; .task == $id)' \ + "$LEDGER" >/dev/null 2>&1; then exit 0 fi # Test seam: widen the check-to-append window so a concurrency regression (a diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 159675eb901..0e8276ce10e 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -13,8 +13,10 @@ # Also covers the one token convention every parser normalizes onto, the # first-line cwd probe that rejects an unrelated sibling session before # parsing it in full, the report's per-model grouping and column sums, the -# documented harness-switch narrowing, and deterministic final-incarnation -# model attribution. +# documented harness-switch narrowing, deterministic final-incarnation model +# attribution, the log scan that reaches the harness's closing write without +# absorbing a later occupant of the same worktree path, and the harvest of a +# secondmate's children before a forced cleanup retires them. set -u # shellcheck source=tests/lib.sh @@ -925,6 +927,69 @@ teardown_status_case() { # --- teardown integration: harvest failure never blocks teardown ------------ +# A forced secondmate teardown retires that home's crewmate children and then +# removes the home itself. Those children ran on this filesystem, so their +# usage is harvestable, but only until their status log is retired with them. +# The row lands in the ledger of the home running the teardown, which is the +# one that outlives the child home. +teardown_child_case() { + local id=usageharvsm1 child=usageharvsmchild1 fb state data config smhome out row + local wt encoded logdir now + fb="$TMP_ROOT/sm-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/treehouse" + chmod +x "$fb/tmux" "$fb/treehouse" + state="$TMP_ROOT/sm-state"; config="$TMP_ROOT/sm-config"; data="$TMP_ROOT/sm-data" + smhome="$TMP_ROOT/sm-home" + mkdir -p "$state" "$config" "$data" "$smhome/state" "$smhome/data" "$smhome/config" + printf '%s\n' "$id" > "$smhome/.fm-secondmate-home" + mkdir -p "$TMP_ROOT/sm-proj" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$smhome" "project=$TMP_ROOT/sm-proj" \ + "home=$smhome" "kind=secondmate" "mode=no-mistakes" + printf 'working: routing\n' > "$state/$id.status" + + # The child crewmate task inside that secondmate home, with its own claude + # session log. Its worktree is already gone, as it is by teardown time. + wt="$TMP_ROOT/.no-mistakes/wt-$child" + fm_write_meta "$smhome/state/$child.meta" \ + "window=firstmate:fm-$child" "worktree=$wt" "project=$TMP_ROOT/sm-proj" "harness=claude" \ + "kind=ship" "mode=no-mistakes" "model=default" "effort=default" + { + printf 'working: started\n' + printf 'done: landed\n' + } > "$smhome/state/$child.status" + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$TMP_ROOT/sm-fake-claude/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgSM","model":"claude-child","usage":{"input_tokens":23,"output_tokens":4}}} +JSON + now=$(date +%s) + printf 'spawn_gen=s%s.77.1\n' "$((now - 300))" >> "$smhome/state/$child.meta" + touch -t "$(touch_stamp $((now - 30)))" "$smhome/state/$child.status" + touch -t "$(touch_stamp $((now - 20)))" "$logdir/session.jsonl" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/sm-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/sm-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/sm-fake-pi" \ + "$TEARDOWN" "$id" --force 2>&1) + expect_code 0 "$?" "forced secondmate teardown should succeed"$'\n'"$out" + [ ! -e "$smhome/state/$child.status" ] \ + || fail "the child's status log outlived the forced cleanup" + row=$(grep -F "\"task\":\"$child\"" "$data/usage-ledger.jsonl" 2>/dev/null || true) + [ -n "$row" ] || fail "the secondmate's child task left no ledger row"$'\n'"$out" + assert_contains "$row" '"source":"claude-projects"' \ + "the child row is harvested from the child's own session log" + assert_contains "$row" '"input_tokens":23' "the child row carries the child's usage" + assert_contains "$row" '"turns":1' \ + "the child row is read from the child home's own status log" + pass "teardown integration: a secondmate's children are harvested before they retire" +} + teardown_case() { local proj wt id fb state data config out id=usageharvtd1 @@ -1103,9 +1168,11 @@ JSON # A relaunch onto another model on the SAME harness leaves both incarnations' # logs in the window, and the row has one model field. It must be the final -# incarnation's, and it must not depend on the order the filesystem enumerates -# the logs in: the older log is created first here, so a first-log-wins rule -# reports the superseded model. +# incarnation's, chosen by WHEN the log was written rather than by its name: +# real claude logs are UUID-named, so path order says nothing about +# incarnation order. The newer log is deliberately named so it sorts EARLIER +# than the older one, so a path-ordered scan, or a first-log-wins rule, +# reports the superseded model and fails here. model_final_incarnation_case() { local id=usagemodelfinal wt="$TMP_ROOT/.no-mistakes/wt-usagemodelfinal" local data home state row out base encoded logdir @@ -1118,30 +1185,79 @@ model_final_incarnation_case() { encoded=${encoded//./-} logdir="$FM_USAGE_CLAUDE_DIR/$encoded" mkdir -p "$logdir" - cat > "$logdir/session-a-first.jsonl" <<'JSON' + cat > "$logdir/session-b-written-first.jsonl" <<'JSON' {"type":"assistant","message":{"id":"msgM1","model":"first-incarnation-model","usage":{"input_tokens":5,"output_tokens":1}}} JSON - cat > "$logdir/session-b-second.jsonl" <<'JSON' + cat > "$logdir/session-a-written-last.jsonl" <<'JSON' {"type":"assistant","message":{"id":"msgM2","model":"final-incarnation-model","usage":{"input_tokens":7,"output_tokens":2}}} JSON base=$(file_mtime_epoch "$state/$id.status") printf 'spawn_gen=s%s.4242.4\n' "$((base - 600))" >> "$state/$id.meta" touch -t "$(touch_stamp "$base")" "$state/$id.status" - touch -t "$(touch_stamp $((base - 400)))" "$logdir/session-a-first.jsonl" - touch -t "$(touch_stamp $((base - 100)))" "$logdir/session-b-second.jsonl" + touch -t "$(touch_stamp $((base - 400)))" "$logdir/session-b-written-first.jsonl" + touch -t "$(touch_stamp $((base - 100)))" "$logdir/session-a-written-last.jsonl" out=$("$HARVEST" "$id" 2>&1) expect_code 0 "$?" "model-attribution harvest should succeed"$'\n'"$out" row=$(cat "$data/usage-ledger.jsonl") assert_contains "$row" '"model":"final-incarnation-model"' \ - "the row reports the last incarnation's model, not the first log's" + "the row reports the chronologically last incarnation's model" assert_contains "$row" '"input_tokens":12' \ "both incarnations' usage is still summed on one harness (5+7)" assert_contains "$row" '"output_tokens":3' "both incarnations' output is summed (1+2)" pass "usage harvest: the model is the final incarnation's, whatever the scan order" } +# The crewmate appends its last status line from inside an agent turn, so the +# harness writes that turn's tool result and its closing assistant entry to the +# session log AFTER the append returns. Matching logs against the status mtime +# therefore rejected the whole file and reported a task whose usage was sitting +# on disk as unavailable. The scan reaches the harvest instant instead, which +# still excludes a log written after this task released its worktree - the case +# that matters, because pooled worktree paths are reused by later tasks. +closing_write_case() { + local id=usageclosingwrite wt="$TMP_ROOT/.no-mistakes/wt-usageclosingwrite" + local data home state row out now encoded logdir + data=$(harvest_case "$id" claude "$wt" default default) + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$FM_USAGE_CLAUDE_DIR/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session-closing.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgW","model":"claude-test","usage":{"input_tokens":41,"output_tokens":3}}} +JSON + # The same pooled worktree path, occupied by a LATER task whose logs are + # written after this harvest: they must never be absorbed into this row. + cat > "$logdir/session-next-occupant.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgNX","model":"claude-test","usage":{"input_tokens":999,"output_tokens":999}}} +JSON + + now=$(date +%s) + printf 'spawn_gen=s%s.4242.5\n' "$((now - 600))" >> "$state/$id.meta" + touch -t "$(touch_stamp $((now - 60)))" "$state/$id.status" + touch -t "$(touch_stamp $((now - 5)))" "$logdir/session-closing.jsonl" + touch -t "$(touch_stamp $((now + 3600)))" "$logdir/session-next-occupant.jsonl" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "closing-write harvest should succeed"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"source":"claude-projects"' \ + "a log flushed after the last status append is still matched" + assert_contains "$row" '"input_tokens":41' \ + "the closing write's usage is summed and the next occupant's is not" + assert_contains "$row" '"output_tokens":3' "no later task's output leaks into the row" + assert_contains "$row" "\"completed_at\":\"$(iso_utc $((now - 60)))\"" \ + "completed_at still rests on the last status append" + assert_contains "$row" '"wall_secs":540' \ + "wall seconds still measure spawn to last status append, not the harvest" + pass "usage harvest: the log scan covers the harness's closing write, not a later task" +} + # --- corrupt lines: one bad line costs that line, not the file -------------- # Pi's session logs are append-only, so a truncated tail line is a realistic @@ -1288,6 +1404,7 @@ relaunch_scope_case relaunch_birthless_case harness_switch_case model_final_incarnation_case +closing_write_case corrupt_line_case nonobject_line_case missing_model_case @@ -1301,4 +1418,5 @@ report_model_totals_case report_no_harness_case report_malformed_case teardown_status_case +teardown_child_case teardown_case From 5fa1abd3d8942c65064f23f3ddff9e78d80d5ac9 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 07:08:09 -0400 Subject: [PATCH 06/16] no-mistakes(review): harvest before worktree return, pin pool ordering --- bin/fm-teardown.sh | 39 +++++++---- bin/fm-usage-harvest.sh | 18 +++-- tests/fm-usage-harvest.test.sh | 121 +++++++++++++++++++++++++++++---- 3 files changed, 142 insertions(+), 36 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index a06d4f4d68d..005cf8926f1 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -2534,6 +2534,19 @@ cleanup_firstmate_home_children() { fm_backend_kill "$child_backend" "$child_t" "$(meta_value "$child_meta" zellij_tab_id)" "fm-$child_id" 2>/dev/null || true fi fi + # A local secondmate's children ran on this filesystem, so their session + # logs are here to harvest. The child's records are read from its own + # home, and the row is appended to the ledger of the home running this + # cleanup, which is the one that outlives the child home removed below. + # This runs BEFORE the worktree release below: while the child still holds + # its pooled worktree, no later task can have written a session log into + # that slot, which is what lets the scan run to the harvest instant. It + # also precedes the status retirement, which deletes the log carrying the + # task window and the turn count. Best effort, exactly as at the other + # sites: a failure warns and never changes this cleanup's own outcome. + FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ + "$FM_ROOT/bin/fm-usage-harvest.sh" "$child_id" >/dev/null \ + || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 if [ "$child_kind" = secondmate ]; then child_home=$(meta_value "$child_meta" home) [ -n "$child_home" ] || child_home=$child_wt @@ -2575,15 +2588,6 @@ cleanup_firstmate_home_children() { child_busy_gen=$(cat "$sub_state/$child_id.busy-gen" 2>/dev/null || true) fi retire_busy_state "$sub_state" "$child_id" "$child_busy_gen" || return 1 - # A local secondmate's children ran on this filesystem, so their session - # logs are here to harvest. The child's records are read from its own - # home, and the row is appended to the ledger of the home running this - # cleanup, which is the one that outlives the child home removed below. - # Best effort, exactly as at the other retirement sites: a failure warns - # and never changes this cleanup's own outcome. - FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ - "$FM_ROOT/bin/fm-usage-harvest.sh" "$child_id" >/dev/null \ - || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 status_retire_presentation_task "$sub_state" "$child_id" || return 1 fm_backlog_atomic_transition remove "$sub_state/$child_id.meta" "task record" "$sub_state" || return 1 rm -f "$sub_state/$child_id.turn-ended" \ @@ -2784,6 +2788,17 @@ fi # pruned code root. Best effort - a sweep failure never blocks this teardown. "$SCRIPT_DIR/fm-remote-job-reap-orphans.sh" >&2 || true +# Best-effort fleet usage harvest, placed here for two ordering reasons. It +# runs BEFORE the worktree release below, so the task still holds its pooled +# worktree and no later task can have written a session log into that slot, +# which is what lets the scan run to the harvest instant; and it runs before +# the status retirement further below, which deletes state/.status and +# with it the task window and the turn count. It also follows the worktree +# process reap above, so a runtime's closing write has already landed. A +# harvest failure must never block teardown or the worktree return. +"$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ + || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 + # Best-effort: drop the local task branch so the shared repo does not accumulate refs. if [ "$BACKEND" = orca ] && [ "$KIND" != secondmate ]; then if [ "$ORCA_PATH_MATCH_VERIFIED" != 1 ]; then @@ -2932,12 +2947,6 @@ fm_backend_clear_transition "$BACKEND" "$STATE" "$T" || true [ -n "$TASK_TMP" ] && rm -rf "$TASK_TMP" remove_pr_poll_artifacts "$STATE" "$ID" || exit 1 retire_busy_state "$STATE" "$ID" "$BUSY_GEN" || exit 1 -# Best-effort fleet usage harvest runs while the task's state files still -# exist. It must precede the status retirement below, which deletes -# state/.status: without that log the harvest has no task window and no -# turn count. A harvest failure must never block teardown. -"$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ - || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 status_retire_presentation_task "$STATE" "$ID" || exit 1 rm -f "$STATE/$ID.turn-ended" \ "$STATE/$ID.pi-ext.ts" "$STATE/$ID.grok-turnend-token" \ diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index 8886967e323..b3182c6dafd 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -82,9 +82,12 @@ # turn's tool result and its closing assistant entry into the session log # after the append returns, and matching at file granularity against # completed_at drops the whole log rather than its tail. The harvest instant -# bounds that extension without an arbitrary grace period: the harvest runs -# inside this task's own teardown, while the task still holds its worktree, so -# a later task cannot yet have written into the same pooled worktree slot. +# bounds that extension without an arbitrary grace period, and teardown is +# ordered so that bound is safe: bin/fm-teardown.sh runs the harvest BEFORE it +# returns the worktree to the treehouse pool, on the main path and on the +# local secondmate child path alike, so the task still holds its pooled +# worktree and no later occupant of that slot can have written a session log +# yet. Callers that harvest out of that order forfeit the guarantee. # wall_secs, spawned_at and completed_at are unaffected and still rest on the # status file. # Turn estimate: count of "^working:" lines in the status file. @@ -135,7 +138,8 @@ # is reported provider-qualified as "/" to match the # model spelling fm-spawn records in the meta, and bare when the record # carries no provider. -# harness=cursor, a task with a recorded remote_host (its worker ran on +# harness=opencode, harness=grok, harness=kimi, harness=cursor, +# harness=muse, a task with a recorded remote_host (its worker ran on # another machine, so its logs are not on this filesystem), an absent log # tree, or no in-window log that yields this task's assistant usage: token # fields are null with source "unavailable". Every harness applies that @@ -283,9 +287,9 @@ case "$TURNS" in ''|*[!0-9]*) TURNS=0 ;; esac # turn, so the harness writes that turn's tool result and closing assistant # entry into its own session log after the append returns, and a file-level # filter cut at END_EPOCH drops the whole log rather than just its tail. The -# harvest instant is bounded and owned by this task, because it runs inside -# this task's own teardown while the task still holds its worktree, so no -# later task can yet have written into the same pooled worktree slot. +# harvest instant is a safe bound because teardown runs this harvest before it +# returns the worktree to the pool, so the task still holds that slot and no +# later occupant can have written into it yet. SCAN_END_EPOCH=$(date +%s 2>/dev/null || printf '%s' "$END_EPOCH") case "$SCAN_END_EPOCH" in ''|*[!0-9]*) SCAN_END_EPOCH=$END_EPOCH ;; esac [ "$SCAN_END_EPOCH" -ge "$END_EPOCH" ] 2>/dev/null || SCAN_END_EPOCH=$END_EPOCH diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 0e8276ce10e..20dc1a99b9f 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -15,8 +15,9 @@ # parsing it in full, the report's per-model grouping and column sums, the # documented harness-switch narrowing, deterministic final-incarnation model # attribution, the log scan that reaches the harness's closing write without -# absorbing a later occupant of the same worktree path, and the harvest of a -# secondmate's children before a forced cleanup retires them. +# absorbing a later occupant of the same worktree path, the teardown ordering +# that keeps that scan bound safe, and the harvest of a secondmate's children +# before a forced cleanup retires them. set -u # shellcheck source=tests/lib.sh @@ -990,6 +991,102 @@ JSON pass "teardown integration: a secondmate's children are harvested before they retire" } +# The log scan reaches the harvest instant, and what keeps that bound safe is +# that teardown harvests while the task still holds its pooled worktree. A +# treehouse shim writes the NEXT occupant's session log into the same encoded +# project directory at the moment the worktree is returned to the pool, which +# is exactly the reachable window a harvest running after the return would +# absorb: those tokens must not appear in this task's row. The second run +# proves the harvest stays best effort in its new position, where a failure +# could otherwise abort teardown before the worktree is ever returned. +teardown_pool_order_case() { + local proj wt id fb state data config out row occupant thlog encoded logdir base + id=usageharvpool1 + proj="$TMP_ROOT/pool-proj"; wt="$TMP_ROOT/pool-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$TMP_ROOT/pool-fake-claude/$encoded" + mkdir -p "$logdir" + occupant="$logdir/session-next-occupant.jsonl" + thlog="$TMP_ROOT/pool-treehouse.log" + fb="$TMP_ROOT/pool-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + cat > "$fb/treehouse" <> "$thlog" +case "\$1" in + return) + # The pool hands this slot to another task, which starts writing its own + # session log under the same encoded project directory. + printf '%s\\n' '{"type":"assistant","message":{"id":"msgOC","model":"next-occupant-model","usage":{"input_tokens":999,"output_tokens":999}}}' \\ + > "$occupant" + ;; +esac +exit 0 +SH + chmod +x "$fb/tmux" "$fb/treehouse" + state="$TMP_ROOT/pool-state"; config="$TMP_ROOT/pool-config"; data="$TMP_ROOT/pool-data" + mkdir -p "$state" "$config" "$data/$id" + printf 'scout findings\n' > "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + { + printf 'working: scouting\n' + printf 'done: report written\n' + } > "$state/$id.status" + cat > "$logdir/session-own.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgOWN","model":"claude-own","usage":{"input_tokens":31,"output_tokens":6}}} +JSON + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.55.2\n' "$((base - 500))" >> "$state/$id.meta" + touch -t "$(touch_stamp $((base - 100)))" "$logdir/session-own.jsonl" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/pool-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/pool-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/pool-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "pool-order teardown should succeed"$'\n'"$out" + [ -f "$occupant" ] || fail "the treehouse shim never returned the worktree to the pool"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + assert_contains "$row" '"source":"claude-projects"' "the task's own log was harvested" + assert_contains "$row" '"input_tokens":31' \ + "the next occupant of the returned worktree is not summed into this row" + assert_contains "$row" '"model":"claude-own"' \ + "the next occupant's model does not become this task's model" + + # Same ordering, but the harvest cannot write: teardown must still return the + # worktree and still succeed. + id=usageharvpool2 + proj="$TMP_ROOT/pool2-proj"; wt="$TMP_ROOT/pool2-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + : > "$thlog" + data="$TMP_ROOT/pool2-data" + # The ledger path is a directory, so every append fails. + mkdir -p "$data/$id" "$data/usage-ledger.jsonl" + printf 'scout findings\n' > "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + printf 'working: scouting\n' > "$state/$id.status" + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/pool-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/pool-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/pool-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "teardown must survive a failing harvest in its new position"$'\n'"$out" + assert_contains "$out" "warning: usage harvest for $id failed" \ + "a failing harvest warns rather than aborting teardown" + grep -q '^return' "$thlog" \ + || fail "a failing harvest blocked the worktree return"$'\n'"$(cat "$thlog")" + pass "teardown integration: the harvest precedes the worktree return and never blocks it" +} + teardown_case() { local proj wt id fb state data config out id=usageharvtd1 @@ -1213,9 +1310,10 @@ JSON # harness writes that turn's tool result and its closing assistant entry to the # session log AFTER the append returns. Matching logs against the status mtime # therefore rejected the whole file and reported a task whose usage was sitting -# on disk as unavailable. The scan reaches the harvest instant instead, which -# still excludes a log written after this task released its worktree - the case -# that matters, because pooled worktree paths are reused by later tasks. +# on disk as unavailable. The scan reaches the harvest instant instead. What +# keeps that bound safe is teardown ordering rather than the harvester alone, +# so the next occupant of a reused worktree path is covered by +# teardown_pool_order_case rather than here. closing_write_case() { local id=usageclosingwrite wt="$TMP_ROOT/.no-mistakes/wt-usageclosingwrite" local data home state row out now encoded logdir @@ -1230,18 +1328,12 @@ closing_write_case() { mkdir -p "$logdir" cat > "$logdir/session-closing.jsonl" <<'JSON' {"type":"assistant","message":{"id":"msgW","model":"claude-test","usage":{"input_tokens":41,"output_tokens":3}}} -JSON - # The same pooled worktree path, occupied by a LATER task whose logs are - # written after this harvest: they must never be absorbed into this row. - cat > "$logdir/session-next-occupant.jsonl" <<'JSON' -{"type":"assistant","message":{"id":"msgNX","model":"claude-test","usage":{"input_tokens":999,"output_tokens":999}}} JSON now=$(date +%s) printf 'spawn_gen=s%s.4242.5\n' "$((now - 600))" >> "$state/$id.meta" touch -t "$(touch_stamp $((now - 60)))" "$state/$id.status" touch -t "$(touch_stamp $((now - 5)))" "$logdir/session-closing.jsonl" - touch -t "$(touch_stamp $((now + 3600)))" "$logdir/session-next-occupant.jsonl" out=$("$HARVEST" "$id" 2>&1) expect_code 0 "$?" "closing-write harvest should succeed"$'\n'"$out" @@ -1249,13 +1341,13 @@ JSON assert_contains "$row" '"source":"claude-projects"' \ "a log flushed after the last status append is still matched" assert_contains "$row" '"input_tokens":41' \ - "the closing write's usage is summed and the next occupant's is not" - assert_contains "$row" '"output_tokens":3' "no later task's output leaks into the row" + "the closing write's usage is summed" + assert_contains "$row" '"output_tokens":3' "the closing write's output is summed" assert_contains "$row" "\"completed_at\":\"$(iso_utc $((now - 60)))\"" \ "completed_at still rests on the last status append" assert_contains "$row" '"wall_secs":540' \ "wall seconds still measure spawn to last status append, not the harvest" - pass "usage harvest: the log scan covers the harness's closing write, not a later task" + pass "usage harvest: the log scan covers the harness's closing write" } # --- corrupt lines: one bad line costs that line, not the file -------------- @@ -1419,4 +1511,5 @@ report_no_harness_case report_malformed_case teardown_status_case teardown_child_case +teardown_pool_order_case teardown_case From 4fe521a8b3cddb6c745468f60b19fcd21bf8e83d Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 13:20:25 -0400 Subject: [PATCH 07/16] no-mistakes(review): correct teardown header and reap harvest-order prose --- bin/fm-teardown.sh | 38 ++++++++++++++++++++++++-------------- 1 file changed, 24 insertions(+), 14 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 005cf8926f1..cab233badeb 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -1,15 +1,22 @@ #!/usr/bin/env bash -# Tear down a finished task: return the treehouse worktree, release the Orca -# worktree, or retire a secondmate home; kill the recorded runtime endpoint, -# harvest the task's fleet usage-ledger row while its state files still exist -# (best effort: bin/fm-usage-harvest.sh owns that ledger, and a harvest failure -# only warns on stderr rather than blocking teardown; a forced secondmate -# teardown harvests each of that home's children the same way before their own -# records retire), -# clear volatile state, and transition this home's backlog item for ship and -# scout tasks before reporting success (a secondmate teardown transitions none, -# since secondmates are not backlog items), then refresh/prune the project's -# clone for PR-based ship tasks. +# Tear down a finished task: harvest the task's fleet usage-ledger row, then +# return the treehouse worktree, release the Orca worktree, or retire a +# secondmate home; kill the recorded runtime endpoint, clear volatile state, +# and transition this home's backlog item for ship and scout tasks before +# reporting success (a secondmate teardown transitions none, since secondmates +# are not backlog items), then refresh/prune the project's clone for PR-based +# ship tasks. +# The harvest runs FIRST of those steps deliberately, and that order is +# load-bearing rather than incidental: it precedes the worktree release so the +# task still holds its pooled slot and no later occupant of that slot can be +# scanned into its row, and it precedes the status retirement that deletes +# state/.status along with the task window and the turn count. +# bin/fm-usage-harvest.sh owns that ledger and states the same ordering +# contract from its own side. The harvest is best effort: a failure only warns +# on stderr and never blocks teardown or the worktree release. A forced +# secondmate teardown harvests each of that home's children the same way, +# before each child's own worktree release and record retirement, but a +# retired secondmate home's own ledger is not migrated into this home's. # Removing state/.meta and landing the backlog transition are one step, not # two: bin/fm-backlog-transition-lib.sh owns that invariant, and both halves run # under the task's own meta lock before this script reports success. Because the @@ -2793,9 +2800,12 @@ fi # worktree and no later task can have written a session log into that slot, # which is what lets the scan run to the harvest instant; and it runs before # the status retirement further below, which deletes state/.status and -# with it the task window and the turn count. It also follows the worktree -# process reap above, so a runtime's closing write has already landed. A -# harvest failure must never block teardown or the worktree return. +# with it the task window and the turn count. A runtime's closing write has +# landed by this point on both kinds reaching this line, for different +# reasons: a task teardown has already run the worktree process reap above, +# while a secondmate teardown skips that reap and relies on the secondmate +# having finished before teardown was invoked at all. A harvest failure must +# never block teardown or the worktree return. "$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 From 05c2245a88327d1644221b9bd8bd7c69996a8ab6 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 15:00:04 -0400 Subject: [PATCH 08/16] no-mistakes(review): split harvest into staged scan and post-refusal append --- bin/fm-teardown.sh | 127 ++++++++++++++++------- bin/fm-usage-harvest.sh | 183 +++++++++++++++++++++++---------- tests/fm-usage-harvest.test.sh | 84 ++++++++++++++- 3 files changed, 300 insertions(+), 94 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index cab233badeb..2271283c429 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -1,22 +1,32 @@ #!/usr/bin/env bash -# Tear down a finished task: harvest the task's fleet usage-ledger row, then -# return the treehouse worktree, release the Orca worktree, or retire a -# secondmate home; kill the recorded runtime endpoint, clear volatile state, -# and transition this home's backlog item for ship and scout tasks before -# reporting success (a secondmate teardown transitions none, since secondmates -# are not backlog items), then refresh/prune the project's clone for PR-based -# ship tasks. -# The harvest runs FIRST of those steps deliberately, and that order is -# load-bearing rather than incidental: it precedes the worktree release so the -# task still holds its pooled slot and no later occupant of that slot can be -# scanned into its row, and it precedes the status retirement that deletes -# state/.status along with the task window and the turn count. -# bin/fm-usage-harvest.sh owns that ledger and states the same ordering -# contract from its own side. The harvest is best effort: a failure only warns -# on stderr and never blocks teardown or the worktree release. A forced -# secondmate teardown harvests each of that home's children the same way, -# before each child's own worktree release and record retirement, but a -# retired secondmate home's own ledger is not migrated into this home's. +# Tear down a finished task: measure the task's fleet usage, return the +# treehouse worktree, release the Orca worktree, or retire a secondmate home; +# kill the recorded runtime endpoint, record the usage-ledger row, clear +# volatile state, and transition this home's backlog item for ship and scout +# tasks before reporting success (a secondmate teardown transitions none, since +# secondmates are not backlog items), then refresh/prune the project's clone +# for PR-based ship tasks. +# The usage harvest is best effort everywhere - a failure only warns on stderr +# and never blocks teardown, a worktree release or a cleanup - and +# bin/fm-usage-harvest.sh owns the ledger and the two-phase contract. This +# script has THREE harvest sites, and their ordering differs by path, so each +# is stated here rather than as one rule. +# On the local task path the harvest is SPLIT. Its scan runs before the +# worktree release, which is load-bearing: the task still holds its pooled +# slot there, so no later occupant of that slot can be scanned into its row. +# Its append runs after every fail-closed refusal below and immediately before +# the status retirement that deletes state/.status along with the task +# window and the turn count. The split is what keeps an aborted teardown from +# freezing a row a rerun could never correct, since each of those refusals +# exits while deliberately retaining the task's records. +# The forced secondmate child cleanup splits the same way and for the same two +# reasons, per child. +# The remote secondmate path harvests in ONE shot, LAST, after the remote home +# has already been retired on the far host and the registry route removed. That +# is sound rather than an oversight: no refusal remains between it and the +# status retirement it precedes, and a remote task's logs live on another +# machine, so its row is source=unavailable with no local worktree to scan. +# A retired secondmate home's own ledger is not migrated into this home's. # Removing state/.meta and landing the backlog transition are one step, not # two: bin/fm-backlog-transition-lib.sh owns that invariant, and both halves run # under the task's own meta lock before this script reports success. Because the @@ -246,6 +256,19 @@ DESCENDANT_TASK_STATES=() DESCENDANT_TASK_IDS=() DESCENDANT_TASK_KINDS=() DESCENDANT_TASK_HOMES=() +# Staging for the two-phase usage harvest (bin/fm-usage-harvest.sh owns that +# contract). The scan phase writes one task-scoped row file here and the append +# phase reads it back after this teardown's fail-closed refusals have passed. +# The directory is private to this run and the exit trap removes it on every +# path, including an aborted teardown, so a retry can never read a row measured +# by an earlier attempt. +USAGE_STAGE_DIR= +usage_stage_path() { # : print this run's staging path for that task + if [ -z "$USAGE_STAGE_DIR" ]; then + USAGE_STAGE_DIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-stage.XXXXXX") || return 1 + fi + printf '%s/%s.row\n' "$USAGE_STAGE_DIR" "$1" +} teardown_release_locks() { local status=$? i if declare -F teardown_release_herdr_locks >/dev/null 2>&1; then @@ -276,6 +299,8 @@ teardown_release_locks() { CONTROL_LOCK_HELD=0 fi fm_lease_guard_release || true + [ -z "$USAGE_STAGE_DIR" ] || rm -rf -- "$USAGE_STAGE_DIR" + USAGE_STAGE_DIR= return "$status" } trap teardown_release_locks EXIT @@ -725,7 +750,11 @@ remote_secondmate_teardown() { # Best-effort fleet usage harvest runs while the task's state files still # exist. It must precede the status retirement below, which deletes # state/.status: without that log the harvest has no task window and no - # turn count. A harvest failure must never block teardown. + # turn count. This path harvests in ONE shot rather than the scan-and-append + # split the other two sites use, because no refusal remains between here and + # that retirement, and a remote task has no local worktree to scan: its row + # is source=unavailable without any log scan at all. A harvest failure must + # never block teardown. "$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 status_retire_presentation_task "$STATE" "$ID" || return 1 @@ -2499,7 +2528,7 @@ preflight_firstmate_home_herdr_children() { # } cleanup_firstmate_home_children() { - local home=$1 sub_state child_meta child_id child_t child_wt child_proj child_kind child_home child_backend child_orca_worktree_id child_return_rc child_busy_gen + local home=$1 sub_state child_meta child_id child_t child_wt child_proj child_kind child_home child_backend child_orca_worktree_id child_return_rc child_busy_gen child_usage_stage sub_state="$home/state" [ -d "$sub_state" ] || return 0 for child_meta in "$sub_state"/*.meta; do @@ -2545,15 +2574,23 @@ cleanup_firstmate_home_children() { # logs are here to harvest. The child's records are read from its own # home, and the row is appended to the ledger of the home running this # cleanup, which is the one that outlives the child home removed below. - # This runs BEFORE the worktree release below: while the child still holds - # its pooled worktree, no later task can have written a session log into - # that slot, which is what lets the scan run to the harvest instant. It - # also precedes the status retirement, which deletes the log carrying the - # task window and the turn count. Best effort, exactly as at the other - # sites: a failure warns and never changes this cleanup's own outcome. - FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ - "$FM_ROOT/bin/fm-usage-harvest.sh" "$child_id" >/dev/null \ - || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 + # This SCAN runs BEFORE the worktree release below: while the child still + # holds its pooled worktree, no later task can have written a session log + # into that slot, which is what lets the scan run to the harvest instant. + # The row is only staged here because this loop still has refusals ahead of + # it that return 1 and leave the child's records for a rerun; it is + # appended further down, once they have passed and before the status + # retirement that deletes the log carrying the window and the turn count. + # Best effort, exactly as at the other sites: a failure warns and never + # changes this cleanup's own outcome. + child_usage_stage=$(usage_stage_path "$child_id" 2>/dev/null || true) + if [ -n "$child_usage_stage" ]; then + FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ + "$FM_ROOT/bin/fm-usage-harvest.sh" --scan-to "$child_usage_stage" "$child_id" >/dev/null \ + || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 + else + echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 + fi if [ "$child_kind" = secondmate ]; then child_home=$(meta_value "$child_meta" home) [ -n "$child_home" ] || child_home=$child_wt @@ -2595,6 +2632,11 @@ cleanup_firstmate_home_children() { child_busy_gen=$(cat "$sub_state/$child_id.busy-gen" 2>/dev/null || true) fi retire_busy_state "$sub_state" "$child_id" "$child_busy_gen" || return 1 + if [ -n "$child_usage_stage" ]; then + FM_DATA_OVERRIDE="$DATA" \ + "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$child_usage_stage" "$child_id" >/dev/null \ + || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 + fi status_retire_presentation_task "$sub_state" "$child_id" || return 1 fm_backlog_atomic_transition remove "$sub_state/$child_id.meta" "task record" "$sub_state" || return 1 rm -f "$sub_state/$child_id.turn-ended" \ @@ -2795,8 +2837,8 @@ fi # pruned code root. Best effort - a sweep failure never blocks this teardown. "$SCRIPT_DIR/fm-remote-job-reap-orphans.sh" >&2 || true -# Best-effort fleet usage harvest, placed here for two ordering reasons. It -# runs BEFORE the worktree release below, so the task still holds its pooled +# Best-effort fleet usage SCAN, placed here for two ordering reasons. It runs +# BEFORE the worktree release below, so the task still holds its pooled # worktree and no later task can have written a session log into that slot, # which is what lets the scan run to the harvest instant; and it runs before # the status retirement further below, which deletes state/.status and @@ -2804,10 +2846,18 @@ fi # landed by this point on both kinds reaching this line, for different # reasons: a task teardown has already run the worktree process reap above, # while a secondmate teardown skips that reap and relies on the secondmate -# having finished before teardown was invoked at all. A harvest failure must -# never block teardown or the worktree return. -"$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ - || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 +# having finished before teardown was invoked at all. The measured row is only +# STAGED here, because every fail-closed refusal below exits while retaining +# the task's records for a rerun, and a row appended before those refusals +# could never be corrected by that rerun. A scan failure must never block +# teardown or the worktree return. +USAGE_STAGE_MAIN=$(usage_stage_path "$ID" 2>/dev/null || true) +if [ -n "$USAGE_STAGE_MAIN" ]; then + "$FM_ROOT/bin/fm-usage-harvest.sh" --scan-to "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ + || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 +else + echo "warning: usage harvest for $ID failed; continuing teardown" >&2 +fi # Best-effort: drop the local task branch so the shared repo does not accumulate refs. if [ "$BACKEND" = orca ] && [ "$KIND" != secondmate ]; then @@ -2957,6 +3007,13 @@ fm_backend_clear_transition "$BACKEND" "$STATE" "$T" || true [ -n "$TASK_TMP" ] && rm -rf "$TASK_TMP" remove_pr_poll_artifacts "$STATE" "$ID" || exit 1 retire_busy_state "$STATE" "$ID" "$BUSY_GEN" || exit 1 +# Append phase of the harvest: every fail-closed refusal is behind us, so this +# teardown is committed and the staged row can become permanent. It still +# precedes the status retirement below, and it stays best effort. +if [ -n "${USAGE_STAGE_MAIN:-}" ]; then + "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ + || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 +fi status_retire_presentation_task "$STATE" "$ID" || exit 1 rm -f "$STATE/$ID.turn-ended" \ "$STATE/$ID.pi-ext.ts" "$STATE/$ID.grok-turnend-token" \ diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index b3182c6dafd..244f8d7949f 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -1,7 +1,13 @@ #!/usr/bin/env bash # fm-usage-harvest.sh - append one fleet usage-ledger row for a finished task. # -# Usage: fm-usage-harvest.sh +# Usage: fm-usage-harvest.sh [--scan-to |--append-from ] +# +# With no flag the command scans and appends in one shot. The two flags split +# that into phases for a caller whose own work can still fail after the scan: +# --scan-to measures the task and writes the finished row to without +# touching the ledger, and --append-from appends a row staged that way. See the +# two-phase contract below. # # Reads state/.meta (harness=, model=, effort=, worktree=; the # backend window= line is intentionally not consumed because the ledger has no @@ -83,11 +89,11 @@ # after the append returns, and matching at file granularity against # completed_at drops the whole log rather than its tail. The harvest instant # bounds that extension without an arbitrary grace period, and teardown is -# ordered so that bound is safe: bin/fm-teardown.sh runs the harvest BEFORE it -# returns the worktree to the treehouse pool, on the main path and on the +# ordered so that bound is safe: bin/fm-teardown.sh runs the SCAN phase BEFORE +# it returns the worktree to the treehouse pool, on the main path and on the # local secondmate child path alike, so the task still holds its pooled # worktree and no later occupant of that slot can have written a session log -# yet. Callers that harvest out of that order forfeit the guarantee. +# yet. Callers that scan out of that order forfeit the guarantee. # wall_secs, spawned_at and completed_at are unaffected and still rest on the # status file. # Turn estimate: count of "^working:" lines in the status file. @@ -165,6 +171,18 @@ # Idempotent: if the ledger already contains a line whose "task" is # , the command exits 0 without appending. # +# Two-phase contract: measuring and appending are separable because the ledger +# row is permanent while the caller's own work may still fail. --scan-to reads +# the meta, the status log and the session logs and writes the row it would +# have appended; --append-from reads nothing but that file and appends it under +# the same lock and the same idempotency guard. A caller that aborts between +# the phases therefore leaves NO row, so its retry measures the task again +# rather than inheriting the abandoned attempt's numbers. The staging file +# belongs to the caller, which owns creating it, keeping it private to one task +# and one run, and removing it on every exit path; --append-from refuses a file +# that is missing, unparseable, or names another task rather than appending +# something it cannot attribute. +# # Overrides (test seams and alternate homes): # FM_ROOT_OVERRIDE, FM_HOME, FM_STATE_OVERRIDE, FM_DATA_OVERRIDE as usual # FM_USAGE_CLAUDE_DIR default $HOME/.claude/projects @@ -174,9 +192,10 @@ # FM_USAGE_HARVEST_APPEND_DELAY test-only delay inside the ledger critical section # # Exit status: 0 on a successful or already-present harvest, 1 on a missing -# task record, missing jq, an unwritable ledger, or a ledger lock still held by -# a live concurrent harvest past FM_USAGE_LEDGER_LOCK_WAIT. Callers that must -# not block (teardown) own their own guard. +# task record, missing jq, an unwritable ledger, an unusable staging file, or a +# ledger lock still held by a live concurrent harvest past +# FM_USAGE_LEDGER_LOCK_WAIT. Callers that must not block (teardown) own their +# own guard. set -eu SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" @@ -198,8 +217,22 @@ PI_DIR="${FM_USAGE_PI_DIR:-${HOME:-}/.pi/agent/sessions}" err() { printf 'error: %s\n' "$1" >&2; } -if [ "$#" -ne 1 ] || [ -z "$1" ] || case "$1" in *[!A-Za-z0-9._-]*) true ;; *) false ;; esac; then - err "usage: fm-usage-harvest.sh " +STAGE_MODE= +STAGE_FILE= +while [ "$#" -gt 0 ]; do + case "$1" in + --scan-to|--append-from) + case "$1" in --scan-to) STAGE_MODE=scan ;; *) STAGE_MODE=append ;; esac + STAGE_FILE=${2:-} + shift + [ "$#" -eq 0 ] || shift + ;; + *) break ;; + esac +done +if [ "$#" -ne 1 ] || [ -z "$1" ] || case "$1" in *[!A-Za-z0-9._-]*) true ;; *) false ;; esac \ + || { [ -n "$STAGE_MODE" ] && [ -z "$STAGE_FILE" ]; }; then + err "usage: fm-usage-harvest.sh [--scan-to |--append-from ] " exit 1 fi command -v jq >/dev/null 2>&1 || { err "jq is required"; exit 1; } @@ -207,6 +240,77 @@ command -v jq >/dev/null 2>&1 || { err "jq is required"; exit 1; } ID=$1 META="$STATE/$ID.meta" STATUS="$STATE/$ID.status" +LEDGER="$DATA/usage-ledger.jsonl" + +REFDIR= +LEDGER_LOCK= +LEDGER_LOCK_HELD=0 +harvest_cleanup() { + local rc=$? + [ "$LEDGER_LOCK_HELD" != 1 ] || fm_lock_release "$LEDGER_LOCK" || true + [ -z "$REFDIR" ] || rm -rf -- "$REFDIR" + return "$rc" +} +trap harvest_cleanup EXIT + +# ledger_append_row : the whole critical section, shared by the +# one-shot harvest and by --append-from. +# +# Serialize the check-and-append as one critical section: acquire the ledger +# lock, then test for an existing row for this task and append only when +# absent. Two concurrent harvests of the same task cannot both pass the +# existence test and each append a duplicate row. +# +# The acquire is BOUNDED, not fm_lock_acquire_wait's unbounded spin, because +# this runs synchronously inside teardown: a wedged live holder must never +# block teardown from retiring the task. fm_lock_try_acquire already steals a +# dead owner's lock, so only a live concurrent harvest makes us wait, and its +# critical section is one ledger scan plus an append. If the lock stays busy +# past the bound we give up best-effort (exit 1, which teardown warns on and +# continues) rather than duplicate the row by appending unserialized. +ledger_append_row() { # + local row=$1 lock_deadline + mkdir -p -- "$DATA" + LEDGER_LOCK="$DATA/.usage-ledger.lock" + LEDGER_LOCK_WAIT=${FM_USAGE_LEDGER_LOCK_WAIT:-30} + lock_deadline=$(( $(date +%s) + LEDGER_LOCK_WAIT )) + until fm_lock_try_acquire "$LEDGER_LOCK"; do + if [ "$(date +%s)" -ge "$lock_deadline" ]; then + err "ledger lock busy after ${LEDGER_LOCK_WAIT}s; skipping harvest for $ID" + return 1 + fi + sleep 0.1 + done + LEDGER_LOCK_HELD=1 + # The identity test parses each ledger line and compares the task field's own + # value, so exactness is structural rather than resting on the punctuation + # that happens to surround the field today: it stays exact if the schema or + # the key order ever changes. A line this cannot parse simply does not match, + # which risks a duplicate row rather than a lost one. + if [ -f "$LEDGER" ] && jq -Rn --exit-status --arg id "$ID" \ + 'any(inputs | try (fromjson | objects) catch empty; .task == $id)' \ + "$LEDGER" >/dev/null 2>&1; then + return 0 + fi + # Test seam: widen the check-to-append window so a concurrency regression (a + # removed lock) is observable deterministically; unset in production. + [ -z "${FM_USAGE_HARVEST_APPEND_DELAY:-}" ] || sleep "$FM_USAGE_HARVEST_APPEND_DELAY" + printf '%s\n' "$row" >> "$LEDGER" +} + +# --append-from needs nothing but the staged row: no meta, no status log, no +# session-log scan. That is what lets teardown run it after its fail-closed +# refusals, long after the worktree it scanned has been returned. +if [ "$STAGE_MODE" = append ]; then + [ -f "$STAGE_FILE" ] || { err "no staged usage row for $ID at $STAGE_FILE"; exit 1; } + STAGED_ROW=$(head -n 1 -- "$STAGE_FILE" 2>/dev/null || true) + printf '%s' "$STAGED_ROW" | jq -e --arg id "$ID" \ + 'objects | select(.task == $id)' >/dev/null 2>&1 \ + || { err "staged usage row for $ID is unreadable or names another task"; exit 1; } + ledger_append_row "$STAGED_ROW" + exit 0 +fi + [ -f "$META" ] || { err "no task record: $META"; exit 1; } meta_get() { # @@ -297,15 +401,6 @@ case "$SCAN_END_EPOCH" in ''|*[!0-9]*) SCAN_END_EPOCH=$END_EPOCH ;; esac # Ref files pin find's mtime window portably (BSD and GNU find both compare # against -newer file mtimes, and touch -t exists on both). REFDIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-harvest.XXXXXX") -LEDGER_LOCK= -LEDGER_LOCK_HELD=0 -harvest_cleanup() { - local rc=$? - [ "$LEDGER_LOCK_HELD" != 1 ] || fm_lock_release "$LEDGER_LOCK" || true - rm -rf -- "$REFDIR" - return "$rc" -} -trap harvest_cleanup EXIT epoch_to_touch() { # # Both renderings are LOCAL time because that is what touch -t reads; a UTC # stamp would shift both window refs by the host's offset and drop real logs. @@ -501,44 +596,7 @@ EFFORT=$EFFORT_META SPAWNED=$(iso_from_epoch "$START_EPOCH" || true) COMPLETED=$(iso_from_epoch "$END_EPOCH" || true) -mkdir -p -- "$DATA" -# Serialize the check-and-append as one critical section: acquire the ledger -# lock, then test for an existing row for this task and append only when -# absent. Two concurrent harvests of the same task cannot both pass the -# existence test and each append a duplicate row. -# -# The acquire is BOUNDED, not fm_lock_acquire_wait's unbounded spin, because -# this runs synchronously inside teardown: a wedged live holder must never -# block teardown from retiring the task. fm_lock_try_acquire already steals a -# dead owner's lock, so only a live concurrent harvest makes us wait, and its -# critical section is one ledger scan plus an append. If the lock stays busy past the -# bound we give up best-effort (exit 1, which teardown warns on and continues) -# rather than duplicate the row by appending unserialized. -LEDGER_LOCK="$DATA/.usage-ledger.lock" -LEDGER_LOCK_WAIT=${FM_USAGE_LEDGER_LOCK_WAIT:-30} -lock_deadline=$(( $(date +%s) + LEDGER_LOCK_WAIT )) -until fm_lock_try_acquire "$LEDGER_LOCK"; do - if [ "$(date +%s)" -ge "$lock_deadline" ]; then - err "ledger lock busy after ${LEDGER_LOCK_WAIT}s; skipping harvest for $ID" - exit 1 - fi - sleep 0.1 -done -LEDGER_LOCK_HELD=1 -# The identity test parses each ledger line and compares the task field's own -# value, so exactness is structural rather than resting on the punctuation -# that happens to surround the field today: it stays exact if the schema or -# the key order ever changes. A line this cannot parse simply does not match, -# which risks a duplicate row rather than a lost one. -if [ -f "$LEDGER" ] && jq -Rn --exit-status --arg id "$ID" \ - 'any(inputs | try (fromjson | objects) catch empty; .task == $id)' \ - "$LEDGER" >/dev/null 2>&1; then - exit 0 -fi -# Test seam: widen the check-to-append window so a concurrency regression (a -# removed lock) is observable deterministically; unset in production. -[ -z "${FM_USAGE_HARVEST_APPEND_DELAY:-}" ] || sleep "$FM_USAGE_HARVEST_APPEND_DELAY" -jq -cn \ +ROW=$(jq -cn \ --arg task "$ID" --arg harness "$HARNESS" \ --arg model "$MODEL" --arg effort "$EFFORT" \ --arg spawned "$SPAWNED" --arg completed "$COMPLETED" \ @@ -552,4 +610,15 @@ jq -cn \ completed_at:(if $completed == "" then null else $completed end), wall_secs:$wall, turns:$turns, input_tokens:$it, cached_input_tokens:$ct, output_tokens:$ot, - reasoning_tokens:$rt, source:$source}' >> "$LEDGER" + reasoning_tokens:$rt, source:$source}') + +# --scan-to stops here: the row is staged for a later --append-from and the +# ledger is untouched, so a caller that aborts between the two phases leaves no +# row to freeze. The staging write is atomic within this run: a partial file +# fails --append-from's own parse rather than appending half a row. +if [ "$STAGE_MODE" = scan ]; then + printf '%s\n' "$ROW" > "$STAGE_FILE" + exit 0 +fi + +ledger_append_row "$ROW" diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 20dc1a99b9f..495e9ed2fbe 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -16,8 +16,9 @@ # documented harness-switch narrowing, deterministic final-incarnation model # attribution, the log scan that reaches the harness's closing write without # absorbing a later occupant of the same worktree path, the teardown ordering -# that keeps that scan bound safe, and the harvest of a secondmate's children -# before a forced cleanup retires them. +# that keeps that scan bound safe, the harvest of a secondmate's children +# before a forced cleanup retires them, and the scan-then-append split that +# keeps an aborted teardown from freezing a row its rerun could not correct. set -u # shellcheck source=tests/lib.sh @@ -1087,6 +1088,84 @@ JSON pass "teardown integration: the harvest precedes the worktree return and never blocks it" } +# Teardown's refusals exit while deliberately retaining the task's records so +# the operator can rerun, and the ledger's idempotency guard means a row +# written before those refusals could never be corrected by that rerun. So an +# aborted teardown must leave no row at all, and the rerun must MEASURE the +# task again rather than replay whatever the aborted attempt had computed. +teardown_refusal_case() { + local proj wt id fb state data config out status row encoded logdir base failflag + id=usageharvrefuse1 + proj="$TMP_ROOT/refuse-proj"; wt="$TMP_ROOT/refuse-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$TMP_ROOT/refuse-fake-claude/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgRF","model":"claude-refuse","usage":{"input_tokens":17,"output_tokens":2}}} +JSON + # The worktree return refuses while this flag exists, which is one of + # teardown's fail-closed exits. + failflag="$TMP_ROOT/refuse-treehouse-fails" + : > "$failflag" + fb="$TMP_ROOT/refuse-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + cat > "$fb/treehouse" <&2 + exit 1 +fi +exit 0 +SH + chmod +x "$fb/tmux" "$fb/treehouse" + state="$TMP_ROOT/refuse-state"; config="$TMP_ROOT/refuse-config"; data="$TMP_ROOT/refuse-data" + mkdir -p "$state" "$config" "$data/$id" + printf 'scout findings\n' > "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + printf 'working: scouting\n' > "$state/$id.status" + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.66.1\n' "$((base - 400))" >> "$state/$id.meta" + touch -t "$(touch_stamp $((base - 100)))" "$logdir/session.jsonl" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/refuse-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/refuse-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/refuse-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + status=$? + expect_code 1 "$status" "a refused worktree return must abort teardown"$'\n'"$out" + [ -f "$state/$id.status" ] \ + || fail "the refusal did not retain the task's status log for a rerun"$'\n'"$out" + [ ! -s "$data/usage-ledger.jsonl" ] \ + || fail "an aborted teardown left a ledger row: $(cat "$data/usage-ledger.jsonl")" + + # The task keeps working before the operator reruns teardown, so a rerun that + # replayed the aborted attempt's row would report the old turn count. + printf 'working: resumed\n' >> "$state/$id.status" + touch -t "$(touch_stamp "$base")" "$state/$id.status" + rm -f "$failflag" + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/refuse-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/refuse-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/refuse-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "the rerun should complete once the return succeeds"$'\n'"$out" + row=$(cat "$data/usage-ledger.jsonl") + [ "$(wc -l < "$data/usage-ledger.jsonl" | tr -d ' ')" = 1 ] \ + || fail "the rerun wrote more than one row"$'\n'"$row" + assert_contains "$row" '"turns":2' \ + "the rerun re-measured the task instead of replaying the aborted attempt" + assert_contains "$row" '"input_tokens":17' "the rerun's row carries the task's usage" + assert_contains "$row" '"source":"claude-projects"' "the rerun's row names its source" + pass "teardown integration: an aborted teardown writes no row and the rerun re-measures" +} + teardown_case() { local proj wt id fb state data config out id=usageharvtd1 @@ -1512,4 +1591,5 @@ report_malformed_case teardown_status_case teardown_child_case teardown_pool_order_case +teardown_refusal_case teardown_case From 38169ecb826d5080accbe5dce293cf822b001a4c Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 15:17:47 -0400 Subject: [PATCH 09/16] no-mistakes(review): fix staging cleanup leak, pin scan-phase failure --- bin/fm-teardown.sh | 42 ++++++++++++++------ bin/fm-usage-harvest.sh | 17 +++++--- tests/fm-usage-harvest.test.sh | 72 +++++++++++++++++++++++++++++----- 3 files changed, 103 insertions(+), 28 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 2271283c429..23d736cad60 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -259,14 +259,21 @@ DESCENDANT_TASK_HOMES=() # Staging for the two-phase usage harvest (bin/fm-usage-harvest.sh owns that # contract). The scan phase writes one task-scoped row file here and the append # phase reads it back after this teardown's fail-closed refusals have passed. -# The directory is private to this run and the exit trap removes it on every -# path, including an aborted teardown, so a retry can never read a row measured -# by an earlier attempt. +# The layout is one mktemp directory per teardown, $TMPDIR/fm-usage-stage.XXXXXX, +# holding one .row file per task this run harvests: the main task, or +# every child of a forced secondmate cleanup. The directory is private to this +# run and the exit trap removes it on every path, including an aborted +# teardown, so a retry can never read a row measured by an earlier attempt. +# usage_stage_dir creates it and must be called UNSUBSTITUTED, because an +# assignment made inside $(...) cannot reach this shell; usage_stage_path only +# formats a path, so it is safe to call in a substitution. USAGE_STAGE_DIR= +usage_stage_dir() { # create this run's staging directory once + [ -z "$USAGE_STAGE_DIR" ] || return 0 + USAGE_STAGE_DIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-stage.XXXXXX") || return 1 +} usage_stage_path() { # : print this run's staging path for that task - if [ -z "$USAGE_STAGE_DIR" ]; then - USAGE_STAGE_DIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-stage.XXXXXX") || return 1 - fi + [ -n "$USAGE_STAGE_DIR" ] || return 1 printf '%s/%s.row\n' "$USAGE_STAGE_DIR" "$1" } teardown_release_locks() { @@ -2583,7 +2590,10 @@ cleanup_firstmate_home_children() { # retirement that deletes the log carrying the window and the turn count. # Best effort, exactly as at the other sites: a failure warns and never # changes this cleanup's own outcome. - child_usage_stage=$(usage_stage_path "$child_id" 2>/dev/null || true) + child_usage_stage= + if usage_stage_dir; then + child_usage_stage=$(usage_stage_path "$child_id" 2>/dev/null || true) + fi if [ -n "$child_usage_stage" ]; then FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ "$FM_ROOT/bin/fm-usage-harvest.sh" --scan-to "$child_usage_stage" "$child_id" >/dev/null \ @@ -2842,16 +2852,22 @@ fi # worktree and no later task can have written a session log into that slot, # which is what lets the scan run to the harvest instant; and it runs before # the status retirement further below, which deletes state/.status and -# with it the task window and the turn count. A runtime's closing write has -# landed by this point on both kinds reaching this line, for different -# reasons: a task teardown has already run the worktree process reap above, -# while a secondmate teardown skips that reap and relies on the secondmate -# having finished before teardown was invoked at all. The measured row is only +# with it the task window and the turn count. Whether a runtime's closing +# write has landed by this line differs by kind. A task teardown has already +# run the worktree process reap above, so it has. A secondmate teardown skips +# that reap, and an ordinary one relies on the secondmate having finished +# before teardown was invoked; a forced discard does NOT, because --force +# exists to retire a secondmate that is still working, and its endpoint is not +# killed until further below, so such a row is narrowed to whatever its +# runtime had written by this point. The measured row is only # STAGED here, because every fail-closed refusal below exits while retaining # the task's records for a rerun, and a row appended before those refusals # could never be corrected by that rerun. A scan failure must never block # teardown or the worktree return. -USAGE_STAGE_MAIN=$(usage_stage_path "$ID" 2>/dev/null || true) +USAGE_STAGE_MAIN= +if usage_stage_dir; then + USAGE_STAGE_MAIN=$(usage_stage_path "$ID" 2>/dev/null || true) +fi if [ -n "$USAGE_STAGE_MAIN" ]; then "$FM_ROOT/bin/fm-usage-harvest.sh" --scan-to "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index 244f8d7949f..efe19561f06 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -179,9 +179,11 @@ # the phases therefore leaves NO row, so its retry measures the task again # rather than inheriting the abandoned attempt's numbers. The staging file # belongs to the caller, which owns creating it, keeping it private to one task -# and one run, and removing it on every exit path; --append-from refuses a file -# that is missing, unparseable, or names another task rather than appending -# something it cannot attribute. +# and one run, and removing it on every exit path; the scan renames it into +# place through a sibling temp file, so that cleanup has to cover the directory +# rather than just the row file. --append-from refuses a file that is missing, +# unparseable, or names another task rather than appending something it cannot +# attribute. # # Overrides (test seams and alternate homes): # FM_ROOT_OVERRIDE, FM_HOME, FM_STATE_OVERRIDE, FM_DATA_OVERRIDE as usual @@ -614,10 +616,13 @@ ROW=$(jq -cn \ # --scan-to stops here: the row is staged for a later --append-from and the # ledger is untouched, so a caller that aborts between the two phases leaves no -# row to freeze. The staging write is atomic within this run: a partial file -# fails --append-from's own parse rather than appending half a row. +# row to freeze. The staging file is written through a sibling temp file and +# renamed, so a scan killed mid-write leaves the previous content rather than a +# half row, and a torn file that reaches --append-from anyway fails its parse +# rather than appending half a row. if [ "$STAGE_MODE" = scan ]; then - printf '%s\n' "$ROW" > "$STAGE_FILE" + printf '%s\n' "$ROW" > "$STAGE_FILE.tmp.$$" + mv -f -- "$STAGE_FILE.tmp.$$" "$STAGE_FILE" exit 0 fi diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 495e9ed2fbe..538bc0ef5c8 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -32,6 +32,7 @@ TMP_ROOT=$(fm_test_tmproot fm-usage-harvest) command -v jq >/dev/null 2>&1 || { echo "skip: jq not found"; exit 0; } REAL_JQ=$(command -v jq) +REAL_MKTEMP=$(command -v mktemp) file_mtime_epoch() { # local t @@ -1060,8 +1061,9 @@ JSON assert_contains "$row" '"model":"claude-own"' \ "the next occupant's model does not become this task's model" - # Same ordering, but the harvest cannot write: teardown must still return the - # worktree and still succeed. + # Failure mode one, on the FAR side of the return: the append cannot write. + # It proves the append is best effort; it says nothing about the return, + # which has already happened by then. id=usageharvpool2 proj="$TMP_ROOT/pool2-proj"; wt="$TMP_ROOT/pool2-wt" fm_git_worktree "$proj" "$wt" "fm/$id" @@ -1080,12 +1082,56 @@ JSON FM_USAGE_CLAUDE_DIR="$TMP_ROOT/pool-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/pool-fake-codex" \ FM_USAGE_PI_DIR="$TMP_ROOT/pool-fake-pi" \ "$TEARDOWN" "$id" 2>&1) - expect_code 0 "$?" "teardown must survive a failing harvest in its new position"$'\n'"$out" + expect_code 0 "$?" "teardown must survive a failing append"$'\n'"$out" assert_contains "$out" "warning: usage harvest for $id failed" \ - "a failing harvest warns rather than aborting teardown" + "a failing append warns rather than aborting teardown" + + # Failure mode two, on the NEAR side of the return: the SCAN itself fails, + # because staging cannot be created. This is the half that can actually block + # the worktree return, so it is the half that has to be proven. + id=usageharvpool3 + proj="$TMP_ROOT/pool3-proj"; wt="$TMP_ROOT/pool3-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + thlog="$TMP_ROOT/pool3-treehouse.log" + : > "$thlog" + fb="$TMP_ROOT/pool3-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + cat > "$fb/treehouse" <> "$thlog" +exit 0 +SH + # Only the usage-staging directory fails to be created; every other mktemp + # caller in teardown is passed through untouched. + cat > "$fb/mktemp" < "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + printf 'working: scouting\n' > "$state/$id.status" + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/pool-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/pool-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/pool-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "teardown must survive a failing scan"$'\n'"$out" + assert_contains "$out" "warning: usage harvest for $id failed" \ + "a failing scan warns rather than aborting teardown" grep -q '^return' "$thlog" \ - || fail "a failing harvest blocked the worktree return"$'\n'"$(cat "$thlog")" - pass "teardown integration: the harvest precedes the worktree return and never blocks it" + || fail "a failing scan blocked the worktree return"$'\n'"$(cat "$thlog")" + [ ! -s "$data/usage-ledger.jsonl" ] || fail "a failing scan still produced a row" + pass "teardown integration: neither harvest phase can block the worktree return" } # Teardown's refusals exit while deliberately retaining the task's records so @@ -1094,7 +1140,7 @@ JSON # aborted teardown must leave no row at all, and the rerun must MEASURE the # task again rather than replay whatever the aborted attempt had computed. teardown_refusal_case() { - local proj wt id fb state data config out status row encoded logdir base failflag + local proj wt id fb state data config out status row encoded logdir base failflag tmp id=usageharvrefuse1 proj="$TMP_ROOT/refuse-proj"; wt="$TMP_ROOT/refuse-wt" fm_git_worktree "$proj" "$wt" "fm/$id" @@ -1133,7 +1179,11 @@ SH printf 'spawn_gen=s%s.66.1\n' "$((base - 400))" >> "$state/$id.meta" touch -t "$(touch_stamp $((base - 100)))" "$logdir/session.jsonl" - out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + # Teardown gets its own TMPDIR so the staging directory it creates for the + # scan phase is observable: it must not outlive the run, aborted or not. + tmp="$TMP_ROOT/refuse-tmp" + mkdir -p "$tmp" + out=$(PATH="$fb:$PATH" TMPDIR="$tmp" FM_ROOT_OVERRIDE="$ROOT" \ FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ FM_USAGE_CLAUDE_DIR="$TMP_ROOT/refuse-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/refuse-fake-codex" \ FM_USAGE_PI_DIR="$TMP_ROOT/refuse-fake-pi" \ @@ -1144,13 +1194,15 @@ SH || fail "the refusal did not retain the task's status log for a rerun"$'\n'"$out" [ ! -s "$data/usage-ledger.jsonl" ] \ || fail "an aborted teardown left a ledger row: $(cat "$data/usage-ledger.jsonl")" + [ -z "$(find "$tmp" -maxdepth 1 -name 'fm-usage-stage.*' -print -quit)" ] \ + || fail "an aborted teardown leaked its usage staging directory" # The task keeps working before the operator reruns teardown, so a rerun that # replayed the aborted attempt's row would report the old turn count. printf 'working: resumed\n' >> "$state/$id.status" touch -t "$(touch_stamp "$base")" "$state/$id.status" rm -f "$failflag" - out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + out=$(PATH="$fb:$PATH" TMPDIR="$tmp" FM_ROOT_OVERRIDE="$ROOT" \ FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ FM_USAGE_CLAUDE_DIR="$TMP_ROOT/refuse-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/refuse-fake-codex" \ FM_USAGE_PI_DIR="$TMP_ROOT/refuse-fake-pi" \ @@ -1163,6 +1215,8 @@ SH "the rerun re-measured the task instead of replaying the aborted attempt" assert_contains "$row" '"input_tokens":17' "the rerun's row carries the task's usage" assert_contains "$row" '"source":"claude-projects"' "the rerun's row names its source" + [ -z "$(find "$tmp" -maxdepth 1 -name 'fm-usage-stage.*' -print -quit)" ] \ + || fail "a completed teardown leaked its usage staging directory" pass "teardown integration: an aborted teardown writes no row and the rerun re-measures" } From c13369c6ebf1c61a949f364ef9210f03af85987c Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 15:49:03 -0400 Subject: [PATCH 10/16] no-mistakes(review): key ledger rows on task and spawn generation --- AGENTS.md | 2 +- bin/fm-teardown.sh | 8 +- bin/fm-usage-harvest.sh | 50 ++++++++--- tests/fm-usage-harvest.test.sh | 150 +++++++++++++++++++++++++++++++++ 4 files changed, 193 insertions(+), 17 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 7b6c87403d4..b9e457cb673 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -88,7 +88,7 @@ data/ personal fleet records; LOCAL, gitignored as a whole learnings.md fleet-local operational facts and gotchas; LOCAL, gitignored; dated, evidence-backed, curated, and updated with inspect-then-update - rewrite and prune rather than append forever, the same contract as captain.md; created lazily, absent until this home has a learning to store projects.md thin fleet navigation registry recording each project's standing delivery posture; firstmate-private, parsed for mechanical sync and seeding by fm-project-mode.sh (section 6) secondmates.md local and remote secondmate routing table; firstmate-private, maintained by the secondmate seed helpers (section 6) - usage-ledger.jsonl append-only fleet cost ledger, one JSON line per harvested task; written only by bin/fm-usage-harvest.sh, whose header owns the line schema, alongside its .usage-ledger.lock append lock, and read by bin/fm-usage-report.sh + usage-ledger.jsonl append-only fleet cost ledger, one JSON line per harvested task incarnation, so a reused task id appears once per spawn; written only by bin/fm-usage-harvest.sh, whose header owns the line schema, alongside its .usage-ledger.lock append lock, and read by bin/fm-usage-report.sh /brief.md per-task crewmate brief, or per-secondmate charter brief when kind=secondmate /report.md scout task deliverable, written by the crewmate; survives teardown projects/ cloned repos; gitignored; read-only except under hard rule 1's concrete captain-approved project operation exception diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 23d736cad60..6bf78fe6b33 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -2642,7 +2642,7 @@ cleanup_firstmate_home_children() { child_busy_gen=$(cat "$sub_state/$child_id.busy-gen" 2>/dev/null || true) fi retire_busy_state "$sub_state" "$child_id" "$child_busy_gen" || return 1 - if [ -n "$child_usage_stage" ]; then + if [ -n "$child_usage_stage" ] && [ -s "$child_usage_stage" ]; then FM_DATA_OVERRIDE="$DATA" \ "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$child_usage_stage" "$child_id" >/dev/null \ || echo "warning: usage harvest for $child_id failed; continuing cleanup" >&2 @@ -3025,8 +3025,10 @@ remove_pr_poll_artifacts "$STATE" "$ID" || exit 1 retire_busy_state "$STATE" "$ID" "$BUSY_GEN" || exit 1 # Append phase of the harvest: every fail-closed refusal is behind us, so this # teardown is committed and the staged row can become permanent. It still -# precedes the status retirement below, and it stays best effort. -if [ -n "${USAGE_STAGE_MAIN:-}" ]; then +# precedes the status retirement below, and it stays best effort. It runs only +# when the scan actually staged a row, so one failed scan warns once here +# rather than warning again for a staging file it already reported. +if [ -n "${USAGE_STAGE_MAIN:-}" ] && [ -s "$USAGE_STAGE_MAIN" ]; then "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 fi diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index efe19561f06..9830b83e06e 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -18,13 +18,31 @@ # # Ledger line schema (this file is the single owner of that schema; the # report script is a consumer): -# {"task":,"harness":,"model":,"effort":, +# {"task":,"spawn_gen":, +# "harness":,"model":,"effort":, # "spawned_at":,"completed_at":, # "wall_secs":,"turns":, # "input_tokens":,"cached_input_tokens":, # "output_tokens":,"reasoning_tokens":, # "source":} # +# Row identity is the PAIR task plus spawn_gen, not the task id alone, because +# a task id is reusable: teardown retires a task's records, and a later spawn +# may take the same id. Keying on the id alone silently dropped every such +# later run, since the append found the earlier row and skipped. spawn_gen is +# the meta's incarnation token, so a teardown rerun after a fail-closed refusal +# carries the same one and is still deduped, while a genuinely new spawn of a +# recycled id carries a different one and earns its own row. One consequence +# is a gain rather than a wart: a refused teardown followed by a relaunch and +# then a successful teardown records the relaunched incarnation instead of +# losing the work done after the refusal. +# ABSENCE has one reserved spelling, null: a task whose meta carries no +# spawn_gen writes "spawn_gen":null, and a row written before this field +# existed omits the key entirely. Both read as null, so a legacy row still +# blocks a re-harvest of that same legacy task while never matching, and never +# blocking, a row that does carry a token. A null generation is equal only to +# another null one. +# # Token invariant, identical for every source: input_tokens counts FRESH, # uncached input only, and cached_input_tokens counts every input token served # from or written to a prompt cache, so the two fields are disjoint and their @@ -168,8 +186,9 @@ # through to the full parse, and the full parse still admits a file only when # the cwd it reports equals the meta worktree. # -# Idempotent: if the ledger already contains a line whose "task" is -# , the command exits 0 without appending. +# Idempotent: if the ledger already contains a line whose "task" and +# "spawn_gen" both match this incarnation, the command exits 0 without +# appending. # # Two-phase contract: measuring and appending are separable because the ledger # row is permanent while the caller's own work may still fail. --scan-to reads @@ -271,7 +290,8 @@ trap harvest_cleanup EXIT # past the bound we give up best-effort (exit 1, which teardown warns on and # continues) rather than duplicate the row by appending unserialized. ledger_append_row() { # - local row=$1 lock_deadline + local row=$1 lock_deadline row_gen + row_gen=$(printf '%s' "$row" | jq -r '.spawn_gen // ""' 2>/dev/null || true) mkdir -p -- "$DATA" LEDGER_LOCK="$DATA/.usage-ledger.lock" LEDGER_LOCK_WAIT=${FM_USAGE_LEDGER_LOCK_WAIT:-30} @@ -284,13 +304,16 @@ ledger_append_row() { # sleep 0.1 done LEDGER_LOCK_HELD=1 - # The identity test parses each ledger line and compares the task field's own - # value, so exactness is structural rather than resting on the punctuation - # that happens to surround the field today: it stays exact if the schema or - # the key order ever changes. A line this cannot parse simply does not match, - # which risks a duplicate row rather than a lost one. - if [ -f "$LEDGER" ] && jq -Rn --exit-status --arg id "$ID" \ - 'any(inputs | try (fromjson | objects) catch empty; .task == $id)' \ + # The identity test parses each ledger line and compares the task and + # spawn_gen fields' own values, so exactness is structural rather than + # resting on the punctuation that happens to surround them today: it stays + # exact if the schema or the key order ever changes. An absent or null + # generation on either side reads as the empty string, so it matches only + # another absent one. A line this cannot parse simply does not match, which + # risks a duplicate row rather than a lost one. + if [ -f "$LEDGER" ] && jq -Rn --exit-status --arg id "$ID" --arg gen "$row_gen" \ + 'any(inputs | try (fromjson | objects) catch empty; + .task == $id and (.spawn_gen // "") == $gen)' \ "$LEDGER" >/dev/null 2>&1; then return 0 fi @@ -599,13 +622,14 @@ SPAWNED=$(iso_from_epoch "$START_EPOCH" || true) COMPLETED=$(iso_from_epoch "$END_EPOCH" || true) ROW=$(jq -cn \ - --arg task "$ID" --arg harness "$HARNESS" \ + --arg task "$ID" --arg gen "$SPAWN_GEN" --arg harness "$HARNESS" \ --arg model "$MODEL" --arg effort "$EFFORT" \ --arg spawned "$SPAWNED" --arg completed "$COMPLETED" \ --argjson wall "$WALL" --argjson turns "$TURNS" \ --argjson it "$IT" --argjson ct "$CT" --argjson ot "$OT" --argjson rt "$RT" \ --arg source "$SRC" \ - '{task:$task, harness:(if $harness == "" then null else $harness end), + '{task:$task, spawn_gen:(if $gen == "" then null else $gen end), + harness:(if $harness == "" then null else $harness end), model:(if ($model == "" or $model == "default") then null else $model end), effort:(if ($effort == "" or $effort == "default") then null else $effort end), spawned_at:(if $spawned == "" then null else $spawned end), diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 538bc0ef5c8..9ec28a8f236 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -715,6 +715,85 @@ JSON # --- concurrency: the ledger lock keeps the append idempotent --------------- +# A task id is reusable: teardown retires the task's records and a later spawn +# may take the same id. The ledger's identity is therefore the task plus its +# spawn_gen incarnation token, so a teardown rerun is still deduped while a +# genuinely new spawn earns its own row. Keyed on the id alone, the second +# incarnation's whole cost record was silently dropped. +reused_task_id_case() { + local id=usagereuse1 wt="$TMP_ROOT/wt-usagereuse1" + local data home state ledger out base rows + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + ledger="$data/usage-ledger.jsonl" + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.11.1\n' "$((base - 300))" >> "$state/$id.meta" + + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "first incarnation harvest should succeed"$'\n'"$out" + assert_contains "$(cat "$ledger")" "\"spawn_gen\":\"s$((base - 300)).11.1\"" \ + "the row records the incarnation it measured" + # Same incarnation again, as a teardown rerun does: still exactly one row. + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "a rerun of the same incarnation should succeed"$'\n'"$out" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] \ + || fail "a rerun of the same incarnation duplicated its row" + + # The id is spawned again later, which fm-spawn records as a new spawn_gen. + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "endpoint_task_id=$id" "worktree=$wt" \ + "project=$TMP_ROOT/proj-$id" "harness=cursor" "kind=ship" "mode=no-mistakes" \ + "model=cursor-x" "effort=" + printf 'spawn_gen=s%s.22.2\n' "$base" >> "$state/$id.meta" + printf 'working: second incarnation\n' > "$state/$id.status" + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "second incarnation harvest should succeed"$'\n'"$out" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 2 ] \ + || fail "a reused task id did not get its own row"$'\n'"$(cat "$ledger")" + rows=$(jq -r '.spawn_gen' "$ledger" | sort | tr '\n' ' ') + [ "$rows" = "s$((base - 300)).11.1 s$base.22.2 " ] \ + || fail "the two incarnations are not recorded separately: [$rows]" + [ "$(jq -r '.task' "$ledger" | sort -u)" = "$id" ] \ + || fail "the two rows do not share the reused task id" + pass "usage harvest: a reused task id records each incarnation once" +} + +# A row written before the ledger carried spawn_gen omits the key entirely, and +# a task whose meta has no spawn_gen writes null. Both read as an absent +# generation, which matches only another absent one. +legacy_ledger_row_case() { + local id=usagelegacy1 wt="$TMP_ROOT/wt-usagelegacy1" + local data home state ledger out base + data=$(harvest_case "$id" cursor "$wt" cursor-x "") + home=$(dirname "$data") + state="$home/state" + export_harvest_env "$home" + ledger="$data/usage-ledger.jsonl" + mkdir -p "$data" + printf '%s\n' \ + "{\"task\":\"$id\",\"harness\":\"cursor\",\"model\":\"cursor-x\",\"effort\":null,\"spawned_at\":null,\"completed_at\":null,\"wall_secs\":7,\"turns\":1,\"input_tokens\":null,\"cached_input_tokens\":null,\"output_tokens\":null,\"reasoning_tokens\":null,\"source\":\"unavailable\"}" \ + > "$ledger" + + # The same generation-less task: the legacy row still blocks a re-harvest. + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "harvest against a legacy row should succeed"$'\n'"$out" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 1 ] \ + || fail "a legacy row did not block a re-harvest of that same task"$'\n'"$(cat "$ledger")" + + # A later spawn of the same id does carry a token, so it is not blocked. + base=$(file_mtime_epoch "$state/$id.status") + printf 'spawn_gen=s%s.33.3\n' "$base" >> "$state/$id.meta" + out=$("$HARVEST" "$id" 2>&1) + expect_code 0 "$?" "harvest of a new incarnation should succeed"$'\n'"$out" + [ "$(wc -l < "$ledger" | tr -d ' ')" = 2 ] \ + || fail "a legacy row blocked a genuinely new incarnation"$'\n'"$(cat "$ledger")" + assert_contains "$(tail -1 "$ledger")" "\"spawn_gen\":\"s$base.33.3\"" \ + "the new incarnation's row carries its own token" + pass "usage harvest: an absent generation matches only another absent one" +} + race_case() { local id=usagerace1 wt="$TMP_ROOT/wt-usagerace1" local data home ledger p1 p2 @@ -840,11 +919,27 @@ JSON fields=$(printf '%s\n' "$out" | awk '$1 == "other-model" {print $2"|"$3"|"$4"|"$5"|"$6"|"$7}') [ "$fields" = "1|5|6|7|8|7" ] \ || fail "per-model totals for other-model are wrong: [$fields]" + # Both agg-model rows still appear per task, so the grouping folded them # rather than the report dropping one. assert_contains "$out" "agg1" "the per-task section still lists the first task" assert_contains "$out" "agg2" "the per-task section still lists the second task" assert_contains "$out" "agg4" "the per-task section still lists the unavailable task" + + # A reused task id is two incarnations, so it is two rows: the per-task + # section lists both and the per-model section sums both rather than + # collapsing them onto one id. + cat > "$ledger" <<'JSON' +{"task":"agg9","spawn_gen":"s1000000001.1.1","harness":"claude","model":"reuse-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":10,"turns":1,"input_tokens":3,"cached_input_tokens":4,"output_tokens":5,"reasoning_tokens":6,"source":"claude-projects"} +{"task":"agg9","spawn_gen":"s1000000999.2.2","harness":"claude","model":"reuse-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":20,"turns":2,"input_tokens":30,"cached_input_tokens":40,"output_tokens":50,"reasoning_tokens":60,"source":"claude-projects"} +JSON + out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) + expect_code 0 "$?" "report of a reused task id should succeed"$'\n'"$out" + fields=$(printf '%s\n' "$out" | awk '$1 == "reuse-model" {print $2"|"$3"|"$4"|"$5"|"$6"|"$7}') + [ "$fields" = "2|33|44|55|66|30" ] \ + || fail "per-model totals collapsed or mis-summed a reused id: [$fields]" + [ "$(printf '%s\n' "$out" | awk '$1 == "agg9"' | wc -l | tr -d ' ')" = 2 ] \ + || fail "the per-task section did not list both incarnations of a reused id"$'\n'"$out" pass "usage report: per-model rows group on the model and sum each column" } @@ -1220,6 +1315,58 @@ SH pass "teardown integration: an aborted teardown writes no row and the rerun re-measures" } +# A scan that fails after its staging directory exists must produce exactly one +# diagnostic: without a gate on the staged row the append phase runs against a +# file that was never written, printing its own error and a second warning for +# one underlying failure. +teardown_single_diagnostic_case() { + local proj wt id fb state data config out + id=usageharvonewarn1 + proj="$TMP_ROOT/onewarn-proj"; wt="$TMP_ROOT/onewarn-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + fb="$TMP_ROOT/onewarn-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/treehouse" + # The staging directory is created read-only, so it exists for the append + # gate to see while the scan's own write into it fails. + cat > "$fb/mktemp" < "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + printf 'working: scouting\n' > "$state/$id.status" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/onewarn-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/onewarn-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/onewarn-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + expect_code 0 "$?" "teardown must survive a scan that cannot stage"$'\n'"$out" + [ "$(printf '%s\n' "$out" | grep -c "warning: usage harvest for $id failed")" = 1 ] \ + || fail "one failed scan produced more than one warning"$'\n'"$out" + assert_not_contains "$out" "no staged usage row" \ + "the append ran against a staging file the scan never wrote" + pass "teardown integration: one failed scan yields exactly one diagnostic" +} + teardown_case() { local proj wt id fb state data config out id=usageharvtd1 @@ -1636,6 +1783,8 @@ missing_model_case no_usage_case cursor_case remote_case +reused_task_id_case +legacy_ledger_row_case race_case lock_bound_case report_case @@ -1646,4 +1795,5 @@ teardown_status_case teardown_child_case teardown_pool_order_case teardown_refusal_case +teardown_single_diagnostic_case teardown_case From 46ce6e884c81529590ab8258526cc86cdfdefa18 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 20:52:37 -0400 Subject: [PATCH 11/16] no-mistakes(review): show spawned_at per task, scope staging paths per home --- bin/fm-teardown.sh | 39 ++++++++++++++++++++++------------ bin/fm-usage-report.sh | 31 +++++++++++++++++---------- tests/fm-usage-harvest.test.sh | 17 +++++++++++---- 3 files changed, 59 insertions(+), 28 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 6bf78fe6b33..43f3135fce5 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -260,10 +260,15 @@ DESCENDANT_TASK_HOMES=() # contract). The scan phase writes one task-scoped row file here and the append # phase reads it back after this teardown's fail-closed refusals have passed. # The layout is one mktemp directory per teardown, $TMPDIR/fm-usage-stage.XXXXXX, -# holding one .row file per task this run harvests: the main task, or -# every child of a forced secondmate cleanup. The directory is private to this -# run and the exit trap removes it on every path, including an aborted -# teardown, so a retry can never read a row measured by an earlier attempt. +# holding one ..row file per task this run harvests: +# the main task, or every child of a forced secondmate cleanup. The digest is +# part of the name because a task id is unique only within its own home's state +# directory, while one staging directory serves every home a single teardown +# recurses through, so an id alone would let a nested home's grandchild +# overwrite an outer child's staged row between that child's scan and append. +# The directory is private to this run and the exit trap removes it on every +# path, including an aborted teardown, so a retry can never read a row measured +# by an earlier attempt. # usage_stage_dir creates it and must be called UNSUBSTITUTED, because an # assignment made inside $(...) cannot reach this shell; usage_stage_path only # formats a path, so it is safe to call in a substitution. @@ -272,9 +277,10 @@ usage_stage_dir() { # create this run's staging directory once [ -z "$USAGE_STAGE_DIR" ] || return 0 USAGE_STAGE_DIR=$(mktemp -d "${TMPDIR:-/tmp}/fm-usage-stage.XXXXXX") || return 1 } -usage_stage_path() { # : print this run's staging path for that task +usage_stage_path() { # : this run's staging path for it [ -n "$USAGE_STAGE_DIR" ] || return 1 - printf '%s/%s.row\n' "$USAGE_STAGE_DIR" "$1" + printf '%s/%s.%s.row\n' "$USAGE_STAGE_DIR" \ + "$(printf '%s' "$1" | cksum | cut -d' ' -f1)" "$2" } teardown_release_locks() { local status=$? i @@ -2592,7 +2598,7 @@ cleanup_firstmate_home_children() { # changes this cleanup's own outcome. child_usage_stage= if usage_stage_dir; then - child_usage_stage=$(usage_stage_path "$child_id" 2>/dev/null || true) + child_usage_stage=$(usage_stage_path "$sub_state" "$child_id" 2>/dev/null || true) fi if [ -n "$child_usage_stage" ]; then FM_STATE_OVERRIDE="$sub_state" FM_DATA_OVERRIDE="$DATA" \ @@ -2866,7 +2872,7 @@ fi # teardown or the worktree return. USAGE_STAGE_MAIN= if usage_stage_dir; then - USAGE_STAGE_MAIN=$(usage_stage_path "$ID" 2>/dev/null || true) + USAGE_STAGE_MAIN=$(usage_stage_path "$STATE" "$ID" 2>/dev/null || true) fi if [ -n "$USAGE_STAGE_MAIN" ]; then "$FM_ROOT/bin/fm-usage-harvest.sh" --scan-to "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ @@ -3023,11 +3029,18 @@ fm_backend_clear_transition "$BACKEND" "$STATE" "$T" || true [ -n "$TASK_TMP" ] && rm -rf "$TASK_TMP" remove_pr_poll_artifacts "$STATE" "$ID" || exit 1 retire_busy_state "$STATE" "$ID" "$BUSY_GEN" || exit 1 -# Append phase of the harvest: every fail-closed refusal is behind us, so this -# teardown is committed and the staged row can become permanent. It still -# precedes the status retirement below, and it stays best effort. It runs only -# when the scan actually staged a row, so one failed scan warns once here -# rather than warning again for a staging file it already reported. +# Append phase of the harvest: every refusal that would retain this task's +# worktree and its status log is behind us, so a row appended here can no +# longer freeze numbers a rerun would measure differently. Three fail-closed +# exits do still follow, and each is harmless for a different reason. The +# status retirement immediately below exits 1 without touching the status log, +# so a rerun re-measures the same file and the (task, spawn_gen) guard +# recognizes the identical row instead of duplicating it. The two backlog +# failures further down exit after that log is gone, where a rerun could only +# measure a degraded zero-turn row, so having appended already is what protects +# the real numbers. The append stays best effort, and it runs only when the +# scan actually staged a row, so one failed scan warns once here rather than +# warning again for a staging file it already reported. if [ -n "${USAGE_STAGE_MAIN:-}" ] && [ -s "$USAGE_STAGE_MAIN" ]; then "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 diff --git a/bin/fm-usage-report.sh b/bin/fm-usage-report.sh index 28636cb9659..7b3f3f761dc 100755 --- a/bin/fm-usage-report.sh +++ b/bin/fm-usage-report.sh @@ -3,10 +3,14 @@ # # Usage: fm-usage-report.sh [ledger-path] # -# Prints per-model totals and one row per task from the usage ledger written -# by fm-usage-harvest.sh (that file owns the line schema; this script only -# consumes it). With no argument the ledger resolves from the operational -# home exactly as the harvester does. +# Prints per-model totals and one row per harvested task incarnation from the +# usage ledger written by fm-usage-harvest.sh (that file owns the line schema; +# this script only consumes it). With no argument the ledger resolves from the +# operational home exactly as the harvester does. +# A reused task id therefore has one row per run: the per-task section carries +# spawned_at and sorts on task then spawned_at, so those runs are readable in +# the order they started. The per-model section aggregates rows, so it counts +# each incarnation as its own task. # # Output is aligned plain text; an absent or unavailable field renders as # "-". The ledger's @tsv rows are read over the unit separator rather than the @@ -46,8 +50,13 @@ if ! MODEL_ROWS=$(jq -rs ' printf 'error: %s: ledger is not readable as JSON lines\n' "$LEDGER" >&2 exit 1 fi -if ! TASK_ROWS=$(jq -r ' - [ (.task // "-"), (.harness // "-"), +# A task id is reusable, so the ledger carries one row per incarnation and the +# same id can appear more than once here. The rows are sorted by task and then +# by spawned_at, and spawned_at is rendered, so those runs are told apart by +# when they started and their order is defined rather than append order. +if ! TASK_ROWS=$(jq -rs ' + sort_by(.task // "", .spawned_at // "")[] + | [ (.task // "-"), (.spawned_at // "-"), (.harness // "-"), (.model // "-"), (.effort // "-"), (.input_tokens // "-"), (.cached_input_tokens // "-"), (.output_tokens // "-"), (.reasoning_tokens // "-"), @@ -70,12 +79,12 @@ if [ -n "$MODEL_ROWS" ]; then fi echo echo "per-task rows:" -printf '%-24s %-8s %-20s %-8s %12s %12s %12s %12s %10s %-16s\n' \ - task harness model effort input cached output reasoning wall_secs source +printf '%-24s %-20s %-8s %-20s %-8s %12s %12s %12s %12s %10s %-16s\n' \ + task spawned_at harness model effort input cached output reasoning wall_secs source if [ -n "$TASK_ROWS" ]; then printf '%s\n' "$TASK_ROWS" | tr '\t' '\037' | - while IFS=$'\037' read -r task harness model effort it ct ot rt wall source; do - printf '%-24s %-8s %-20s %-8s %12s %12s %12s %12s %10s %-16s\n' \ - "$task" "$harness" "$model" "$effort" "$it" "$ct" "$ot" "$rt" "$wall" "$source" + while IFS=$'\037' read -r task spawned harness model effort it ct ot rt wall source; do + printf '%-24s %-20s %-8s %-20s %-8s %12s %12s %12s %12s %10s %-16s\n' \ + "$task" "$spawned" "$harness" "$model" "$effort" "$it" "$ct" "$ot" "$rt" "$wall" "$source" done fi diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 9ec28a8f236..19026bec67f 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -862,8 +862,8 @@ report_no_harness_case() { out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) expect_code 0 "$?" "report of a harness-less row should succeed"$'\n'"$out" - fields=$(printf '%s\n' "$out" | awk -v t="$id" '$1 == t {print NF"|"$2"|"$3"|"$NF}') - [ "$fields" = "10|-|nohar-model|unavailable" ] \ + fields=$(printf '%s\n' "$out" | awk -v t="$id" '$1 == t {print NF"|"$3"|"$4"|"$NF}') + [ "$fields" = "11|-|nohar-model|unavailable" ] \ || fail "report shifted the harness-less row's columns: [$fields]" pass "usage report: an absent harness renders as a placeholder without shifting columns" } @@ -929,9 +929,11 @@ JSON # A reused task id is two incarnations, so it is two rows: the per-task # section lists both and the per-model section sums both rather than # collapsing them onto one id. + # The LATER incarnation is written first, so a report that merely echoed + # append order would list the runs backwards. cat > "$ledger" <<'JSON' -{"task":"agg9","spawn_gen":"s1000000001.1.1","harness":"claude","model":"reuse-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":10,"turns":1,"input_tokens":3,"cached_input_tokens":4,"output_tokens":5,"reasoning_tokens":6,"source":"claude-projects"} -{"task":"agg9","spawn_gen":"s1000000999.2.2","harness":"claude","model":"reuse-model","effort":null,"spawned_at":null,"completed_at":null,"wall_secs":20,"turns":2,"input_tokens":30,"cached_input_tokens":40,"output_tokens":50,"reasoning_tokens":60,"source":"claude-projects"} +{"task":"agg9","spawn_gen":"s1000000999.2.2","harness":"claude","model":"reuse-model","effort":null,"spawned_at":"2026-02-02T02:02:02Z","completed_at":null,"wall_secs":20,"turns":2,"input_tokens":30,"cached_input_tokens":40,"output_tokens":50,"reasoning_tokens":60,"source":"claude-projects"} +{"task":"agg9","spawn_gen":"s1000000001.1.1","harness":"claude","model":"reuse-model","effort":null,"spawned_at":"2026-01-01T01:01:01Z","completed_at":null,"wall_secs":10,"turns":1,"input_tokens":3,"cached_input_tokens":4,"output_tokens":5,"reasoning_tokens":6,"source":"claude-projects"} JSON out=$(FM_DATA_OVERRIDE="$home/data" "$REPORT" 2>&1) expect_code 0 "$?" "report of a reused task id should succeed"$'\n'"$out" @@ -940,6 +942,13 @@ JSON || fail "per-model totals collapsed or mis-summed a reused id: [$fields]" [ "$(printf '%s\n' "$out" | awk '$1 == "agg9"' | wc -l | tr -d ' ')" = 2 ] \ || fail "the per-task section did not list both incarnations of a reused id"$'\n'"$out" + # Each run is told apart by when it started, earliest first. + fields=$(printf '%s\n' "$out" | awk '$1 == "agg9" {print $2}' | tr '\n' ' ') + [ "$fields" = "2026-01-01T01:01:01Z 2026-02-02T02:02:02Z " ] \ + || fail "the reused id's runs are indistinguishable or out of order: [$fields]" + fields=$(printf '%s\n' "$out" | awk '$1 == "agg9" {print $6}' | tr '\n' ' ') + [ "$fields" = "3 30 " ] \ + || fail "the reused id's rows do not carry each run's own usage: [$fields]" pass "usage report: per-model rows group on the model and sum each column" } From 7774f3d5efb849aefc0a6889cc827f4469d830a8 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 21:09:05 -0400 Subject: [PATCH 12/16] no-mistakes(review): align harvest ordering prose, pin nested staging scope --- bin/fm-teardown.sh | 61 ++++++++++++++++--------- bin/fm-usage-harvest.sh | 5 +- tests/fm-usage-harvest.test.sh | 83 ++++++++++++++++++++++++++++++++++ 3 files changed, 125 insertions(+), 24 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 43f3135fce5..375b7eafa78 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -14,17 +14,24 @@ # On the local task path the harvest is SPLIT. Its scan runs before the # worktree release, which is load-bearing: the task still holds its pooled # slot there, so no later occupant of that slot can be scanned into its row. -# Its append runs after every fail-closed refusal below and immediately before -# the status retirement that deletes state/.status along with the task -# window and the turn count. The split is what keeps an aborted teardown from -# freezing a row a rerun could never correct, since each of those refusals -# exits while deliberately retaining the task's records. -# The forced secondmate child cleanup splits the same way and for the same two -# reasons, per child. +# Its append runs after every refusal that would RETAIN the task's worktree and +# its status log, and immediately before the status retirement that deletes +# state/.status along with the task window and the turn count. That is what +# keeps an aborted teardown from freezing a row a rerun could never correct, +# since each of those refusals exits while deliberately retaining the records a +# rerun would re-measure. Three fail-closed exits still follow the append: the +# status retirement itself, and the two backlog failures after it. They are +# harmless because the retirement leaves the status log untouched, so a rerun +# re-measures and the (task, spawn_gen) identity guard recognizes the identical +# row, while the backlog failures come after that log is gone, where a rerun +# could only measure a degraded zero-turn row. +# The forced secondmate child cleanup splits the same way and for the same +# reasons, per child, with its own two return-1 exits after the append: that +# child's status retirement and its record removal. # The remote secondmate path harvests in ONE shot, LAST, after the remote home # has already been retired on the far host and the registry route removed. That -# is sound rather than an oversight: no refusal remains between it and the -# status retirement it precedes, and a remote task's logs live on another +# is sound rather than an oversight: nothing between it and the status +# retirement it precedes can refuse, and a remote task's logs live on another # machine, so its row is source=unavailable with no local worktree to scan. # A retired secondmate home's own ledger is not migrated into this home's. # Removing state/.meta and landing the backlog transition are one step, not @@ -258,7 +265,8 @@ DESCENDANT_TASK_KINDS=() DESCENDANT_TASK_HOMES=() # Staging for the two-phase usage harvest (bin/fm-usage-harvest.sh owns that # contract). The scan phase writes one task-scoped row file here and the append -# phase reads it back after this teardown's fail-closed refusals have passed. +# phase reads it back once the refusals that would retain the task's worktree +# and status log have passed, as the header states per path. # The layout is one mktemp directory per teardown, $TMPDIR/fm-usage-stage.XXXXXX, # holding one ..row file per task this run harvests: # the main task, or every child of a forced secondmate cleanup. The digest is @@ -764,10 +772,12 @@ remote_secondmate_teardown() { # exist. It must precede the status retirement below, which deletes # state/.status: without that log the harvest has no task window and no # turn count. This path harvests in ONE shot rather than the scan-and-append - # split the other two sites use, because no refusal remains between here and - # that retirement, and a remote task has no local worktree to scan: its row - # is source=unavailable without any log scan at all. A harvest failure must - # never block teardown. + # split the other two sites use, because nothing between here and that + # retirement can refuse, and a remote task has no local worktree to scan: its + # row is source=unavailable without any log scan at all. The retirement below + # and the record removal after it can still return 1, which is harmless for + # the same reasons the main path states. A harvest failure must never block + # teardown. "$FM_ROOT/bin/fm-usage-harvest.sh" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 status_retire_presentation_task "$STATE" "$ID" || return 1 @@ -2592,10 +2602,14 @@ cleanup_firstmate_home_children() { # into that slot, which is what lets the scan run to the harvest instant. # The row is only staged here because this loop still has refusals ahead of # it that return 1 and leave the child's records for a rerun; it is - # appended further down, once they have passed and before the status + # appended further down, once those have passed and before the status # retirement that deletes the log carrying the window and the turn count. - # Best effort, exactly as at the other sites: a failure warns and never - # changes this cleanup's own outcome. + # Two return-1 exits still follow that append, and they are harmless for the + # same reasons as on the main path: the retirement leaves the status log + # for a rerun to re-measure under the same identity, and the record removal + # after it comes too late for a rerun to measure anything better. Best + # effort, exactly as at the other sites: a failure warns and never changes + # this cleanup's own outcome. child_usage_stage= if usage_stage_dir; then child_usage_stage=$(usage_stage_path "$sub_state" "$child_id" 2>/dev/null || true) @@ -2648,6 +2662,10 @@ cleanup_firstmate_home_children() { child_busy_gen=$(cat "$sub_state/$child_id.busy-gen" 2>/dev/null || true) fi retire_busy_state "$sub_state" "$child_id" "$child_busy_gen" || return 1 + # Append phase for this child: every refusal that would retain its worktree + # and status log is behind us, and the two return-1 exits that still follow + # are the ones named at the scan site above. It runs only when the scan + # actually staged a row, so one failed scan warns once rather than twice. if [ -n "$child_usage_stage" ] && [ -s "$child_usage_stage" ]; then FM_DATA_OVERRIDE="$DATA" \ "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$child_usage_stage" "$child_id" >/dev/null \ @@ -2865,11 +2883,10 @@ fi # before teardown was invoked; a forced discard does NOT, because --force # exists to retire a secondmate that is still working, and its endpoint is not # killed until further below, so such a row is narrowed to whatever its -# runtime had written by this point. The measured row is only -# STAGED here, because every fail-closed refusal below exits while retaining -# the task's records for a rerun, and a row appended before those refusals -# could never be corrected by that rerun. A scan failure must never block -# teardown or the worktree return. +# runtime had written by this point. The measured row is only STAGED here, +# because the refusals below that retain this task's worktree and status log +# for a rerun would otherwise freeze a row that rerun could never correct. A +# scan failure must never block teardown or the worktree return. USAGE_STAGE_MAIN= if usage_stage_dir; then USAGE_STAGE_MAIN=$(usage_stage_path "$STATE" "$ID" 2>/dev/null || true) diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index 9830b83e06e..c8dceec9f37 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -324,8 +324,9 @@ ledger_append_row() { # } # --append-from needs nothing but the staged row: no meta, no status log, no -# session-log scan. That is what lets teardown run it after its fail-closed -# refusals, long after the worktree it scanned has been returned. +# session-log scan. That is what lets teardown run it after the refusals that +# would retain the task's worktree and status log, long after the worktree it +# scanned has been returned. if [ "$STAGE_MODE" = append ]; then [ -f "$STAGE_FILE" ] || { err "no staged usage row for $ID at $STAGE_FILE"; exit 1; } STAGED_ROW=$(head -n 1 -- "$STAGE_FILE" 2>/dev/null || true) diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 19026bec67f..19691af22dc 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -1105,6 +1105,88 @@ JSON # absorb: those tokens must not appear in this task's row. The second run # proves the harvest stays best effort in its new position, where a failure # could otherwise abort teardown before the worktree is ever returned. +# One teardown harvests every task in every home it recurses through, and a +# task id is unique only within its own home's state directory. A secondmate +# child whose own home holds a grandchild with the SAME id therefore stages two +# different rows, and the recursion into that nested home runs between the +# outer child's scan and its append. Keyed on the id alone, the grandchild's +# row overwrites the outer child's staged file, the identity guard then finds +# the grandchild's row already present and skips, and the outer child's +# measured usage is lost while its records retire. +teardown_nested_child_case() { + local id=usageharvsm2 child=usageharvsmshared fb state data config smhome gchome out + local wt gwt encoded logdir now rows + fb="$TMP_ROOT/nest-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/treehouse" + chmod +x "$fb/tmux" "$fb/treehouse" + state="$TMP_ROOT/nest-state"; config="$TMP_ROOT/nest-config"; data="$TMP_ROOT/nest-data" + smhome="$TMP_ROOT/nest-home"; gchome="$TMP_ROOT/nest-home-inner" + mkdir -p "$state" "$config" "$data" "$smhome/state" "$smhome/data" "$smhome/config" \ + "$gchome/state" "$gchome/data" "$gchome/config" "$TMP_ROOT/nest-proj" + printf '%s\n' "$id" > "$smhome/.fm-secondmate-home" + printf '%s\n' "$child" > "$gchome/.fm-secondmate-home" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$smhome" "project=$TMP_ROOT/nest-proj" \ + "home=$smhome" "kind=secondmate" "mode=no-mistakes" + printf 'working: routing\n' > "$state/$id.status" + + now=$(date +%s) + # The outer child is itself a secondmate, so the cleanup recurses into its + # home between that child's scan and its append. + wt="$TMP_ROOT/.no-mistakes/wt-outer-$child" + fm_write_meta "$smhome/state/$child.meta" \ + "window=firstmate:fm-$child" "worktree=$wt" "project=$TMP_ROOT/nest-proj" \ + "harness=claude" "home=$gchome" "kind=secondmate" "mode=no-mistakes" \ + "model=default" "effort=default" + printf 'spawn_gen=s%s.81.1\n' "$((now - 400))" >> "$smhome/state/$child.meta" + printf 'working: outer child\n' > "$smhome/state/$child.status" + + # The grandchild shares the outer child's task id, which is legal because it + # lives in a different home's state directory. + gwt="$TMP_ROOT/.no-mistakes/wt-inner-$child" + fm_write_meta "$gchome/state/$child.meta" \ + "window=firstmate:fm-$child" "worktree=$gwt" "project=$TMP_ROOT/nest-proj" \ + "harness=claude" "kind=ship" "mode=no-mistakes" "model=default" "effort=default" + printf 'spawn_gen=s%s.82.2\n' "$((now - 300))" >> "$gchome/state/$child.meta" + printf 'working: grandchild\n' > "$gchome/state/$child.status" + + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$TMP_ROOT/nest-fake-claude/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgOUT","model":"claude-outer","usage":{"input_tokens":41,"output_tokens":5}}} +JSON + touch -t "$(touch_stamp $((now - 20)))" "$logdir/session.jsonl" + encoded=${gwt//\//-} + encoded=${encoded//./-} + logdir="$TMP_ROOT/nest-fake-claude/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgIN","model":"claude-inner","usage":{"input_tokens":77,"output_tokens":6}}} +JSON + touch -t "$(touch_stamp $((now - 20)))" "$logdir/session.jsonl" + touch -t "$(touch_stamp $((now - 30)))" "$smhome/state/$child.status" + touch -t "$(touch_stamp $((now - 30)))" "$gchome/state/$child.status" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/nest-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/nest-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/nest-fake-pi" \ + "$TEARDOWN" "$id" --force 2>&1) + expect_code 0 "$?" "nested forced secondmate teardown should succeed"$'\n'"$out" + rows=$(grep -cF "\"task\":\"$child\"" "$data/usage-ledger.jsonl" 2>/dev/null || true) + [ "$rows" = 2 ] \ + || fail "the two same-named tasks did not both reach the ledger: [$rows]"$'\n'"$(cat "$data/usage-ledger.jsonl" 2>/dev/null)"$'\n'"$out" + assert_contains "$(cat "$data/usage-ledger.jsonl")" '"input_tokens":41' \ + "the outer child's own usage survived the recursion into the nested home" + assert_contains "$(cat "$data/usage-ledger.jsonl")" '"input_tokens":77' \ + "the grandchild's own usage is recorded too" + pass "teardown integration: a nested home's same-named task cannot overwrite its parent's row" +} + teardown_pool_order_case() { local proj wt id fb state data config out row occupant thlog encoded logdir base id=usageharvpool1 @@ -1802,6 +1884,7 @@ report_no_harness_case report_malformed_case teardown_status_case teardown_child_case +teardown_nested_child_case teardown_pool_order_case teardown_refusal_case teardown_single_diagnostic_case From 8157bf4e4f60a79cb30d14783eb75442ab91adf1 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 21:29:26 -0400 Subject: [PATCH 13/16] no-mistakes(review): guard staging and ref cleanup in teardown traps --- bin/fm-teardown.sh | 2 +- bin/fm-usage-harvest.sh | 2 +- tests/fm-usage-harvest.test.sh | 101 +++++++++++++++++++++++++++++++++ 3 files changed, 103 insertions(+), 2 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 375b7eafa78..df2e8f9464f 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -320,7 +320,7 @@ teardown_release_locks() { CONTROL_LOCK_HELD=0 fi fm_lease_guard_release || true - [ -z "$USAGE_STAGE_DIR" ] || rm -rf -- "$USAGE_STAGE_DIR" + [ -z "$USAGE_STAGE_DIR" ] || rm -rf -- "$USAGE_STAGE_DIR" || true USAGE_STAGE_DIR= return "$status" } diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index c8dceec9f37..9c31b723867 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -269,7 +269,7 @@ LEDGER_LOCK_HELD=0 harvest_cleanup() { local rc=$? [ "$LEDGER_LOCK_HELD" != 1 ] || fm_lock_release "$LEDGER_LOCK" || true - [ -z "$REFDIR" ] || rm -rf -- "$REFDIR" + [ -z "$REFDIR" ] || rm -rf -- "$REFDIR" || true return "$rc" } trap harvest_cleanup EXIT diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index 19691af22dc..bc4c50e357e 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -1458,6 +1458,105 @@ SH pass "teardown integration: one failed scan yields exactly one diagnostic" } +# The staging directory is removed in teardown's exit trap, which runs under +# set -eu, so a removal that fails must not become the run's own exit status: +# teardown is fail-closed machinery whose callers read a non-zero exit as a +# refusal that retained the task's records. +teardown_stage_cleanup_failure_case() { + local proj wt id fb state data config out tmp holder status + id=usageharvstagerm1 + proj="$TMP_ROOT/stagerm-proj"; wt="$TMP_ROOT/stagerm-wt" + fm_git_worktree "$proj" "$wt" "fm/$id" + fb="$TMP_ROOT/stagerm-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/treehouse" + tmp="$TMP_ROOT/stagerm-tmp" + holder="$tmp/holder" + mkdir -p "$holder" + # The staging directory itself stays writable, so the scan stages its row and + # the append reads it back normally, but its PARENT is not, so removing the + # staging directory at exit fails. + cat > "$fb/mktemp" < "$data/$id/report.md" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$proj" "harness=claude" \ + "kind=scout" "mode=no-mistakes" "yolo=off" \ + "decisions_reviewed=1" "decision_keys=" + printf 'working: scouting\n' > "$state/$id.status" + + out=$(PATH="$fb:$PATH" TMPDIR="$tmp" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/stagerm-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/stagerm-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/stagerm-fake-pi" \ + "$TEARDOWN" "$id" 2>&1) + status=$? + chmod 700 "$holder" 2>/dev/null || true + expect_code 0 "$status" \ + "a staging cleanup failure must not fail an otherwise complete teardown"$'\n'"$out" + assert_contains "$out" "teardown $id complete" "teardown still reports completion" + [ -s "$data/usage-ledger.jsonl" ] \ + || fail "the completed run appended no row"$'\n'"$out" + pass "teardown integration: a failing staging cleanup cannot flip the exit status" +} + +# The harvester removes its own ref directory in its exit trap, under the same +# set -eu rules, so a removal that fails must not report a harvest that +# actually appended its row as a failure teardown would warn about. +harvest_refdir_cleanup_failure_case() { + local id=usageharvrefdir1 wt="$TMP_ROOT/.no-mistakes/wt-usageharvrefdir1" + local data home fb tmp holder out status + data=$(harvest_case "$id" claude "$wt" claude-meta-model default) + home=$(dirname "$data") + export_harvest_env "$home" + fb="$TMP_ROOT/refdir-fakebin" + tmp="$TMP_ROOT/refdir-tmp" + holder="$tmp/holder" + mkdir -p "$fb" "$holder" + # The ref directory is writable, so the window refs are stamped as usual, but + # its parent is not, so removing it at exit fails. + cat > "$fb/mktemp" <&1) + status=$? + chmod 700 "$holder" 2>/dev/null || true + expect_code 0 "$status" \ + "a ref-directory cleanup failure must not report a successful harvest as failed"$'\n'"$out" + assert_contains "$(cat "$data/usage-ledger.jsonl")" "\"task\":\"$id\"" \ + "the harvest that reported success appended its row" + pass "usage harvest: a failing ref-directory cleanup cannot flip the exit status" +} + teardown_case() { local proj wt id fb state data config out id=usageharvtd1 @@ -1888,4 +1987,6 @@ teardown_nested_child_case teardown_pool_order_case teardown_refusal_case teardown_single_diagnostic_case +teardown_stage_cleanup_failure_case +harvest_refdir_cleanup_failure_case teardown_case From 67637551fde074cd65caa37e29258c9d64e278f2 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 21:53:48 -0400 Subject: [PATCH 14/16] no-mistakes(document): note default-to-null ledger fields and report placeholders --- bin/fm-usage-harvest.sh | 3 +++ bin/fm-usage-report.sh | 6 ++++-- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/bin/fm-usage-harvest.sh b/bin/fm-usage-harvest.sh index 9c31b723867..cb9ef10e77e 100755 --- a/bin/fm-usage-harvest.sh +++ b/bin/fm-usage-harvest.sh @@ -25,6 +25,9 @@ # "input_tokens":,"cached_input_tokens":, # "output_tokens":,"reasoning_tokens":, # "source":} +# A meta model= or effort= holding the literal "default" names no concrete id, +# so the row records null for that field rather than the word itself, which is +# the same spelling an absent line gets. # # Row identity is the PAIR task plus spawn_gen, not the task id alone, because # a task id is reusable: teardown retires a task's records, and a later spawn diff --git a/bin/fm-usage-report.sh b/bin/fm-usage-report.sh index 7b3f3f761dc..3382e3e8cb9 100755 --- a/bin/fm-usage-report.sh +++ b/bin/fm-usage-report.sh @@ -12,8 +12,10 @@ # the order they started. The per-model section aggregates rows, so it counts # each incarnation as its own task. # -# Output is aligned plain text; an absent or unavailable field renders as -# "-". The ledger's @tsv rows are read over the unit separator rather than the +# Output is aligned plain text. In the per-task rows an absent or unavailable +# field renders as "-", while the per-model totals group rows carrying no model +# under "?" and count an absent token field as zero. +# The ledger's @tsv rows are read over the unit separator rather than the # tab, because tab is an IFS whitespace character and an empty field would # otherwise collapse and shift every later column left. # From ed86462f28b24df255eaa38d026946601f350d35 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Wed, 2 Sep 2026 22:54:30 -0400 Subject: [PATCH 15/16] no-mistakes: apply CI fixes --- bin/fm-teardown.sh | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index df2e8f9464f..35cc3902a6d 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -33,7 +33,10 @@ # is sound rather than an oversight: nothing between it and the status # retirement it precedes can refuse, and a remote task's logs live on another # machine, so its row is source=unavailable with no local worktree to scan. -# A retired secondmate home's own ledger is not migrated into this home's. +# The nested host-local teardown skips its append after removing that remote +# home, because its ledger lived inside the removed home and recreating it would +# undo the retirement. A retired secondmate home's own ledger is not migrated +# into this home's; the surviving parent writes the remote task's row instead. # Removing state/.meta and landing the backlog transition are one step, not # two: bin/fm-backlog-transition-lib.sh owns that invariant, and both halves run # under the task's own meta lock before this script reports success. Because the @@ -3055,10 +3058,15 @@ retire_busy_state "$STATE" "$ID" "$BUSY_GEN" || exit 1 # recognizes the identical row instead of duplicating it. The two backlog # failures further down exit after that log is gone, where a rerun could only # measure a degraded zero-turn row, so having appended already is what protects -# the real numbers. The append stays best effort, and it runs only when the -# scan actually staged a row, so one failed scan warns once here rather than -# warning again for a staging file it already reported. -if [ -n "${USAGE_STAGE_MAIN:-}" ] && [ -s "$USAGE_STAGE_MAIN" ]; then +# the real numbers. The append stays best effort, and it runs only when the scan +# actually staged a row, so one failed scan warns once here rather than warning +# again for a staging file it already reported. A nested remote secondmate +# teardown is the one deliberate skip: its STATE and DATA both live inside the +# home removed above, so appending now would recreate that retired home. The +# outer remote teardown records the task in its surviving parent ledger. +if [ "$KIND" = secondmate ] && [ ! -e "$STATE" ] && [ ! -L "$STATE" ]; then + : +elif [ -n "${USAGE_STAGE_MAIN:-}" ] && [ -s "$USAGE_STAGE_MAIN" ]; then "$FM_ROOT/bin/fm-usage-harvest.sh" --append-from "$USAGE_STAGE_MAIN" "$ID" >/dev/null \ || echo "warning: usage harvest for $ID failed; continuing teardown" >&2 fi From 6d5d71f8fe9fbbf50e6e42b96aafdc9f1fd759b6 Mon Sep 17 00:00:00 2001 From: Nicolas Payette Date: Thu, 3 Sep 2026 03:11:34 -0400 Subject: [PATCH 16/16] no-mistakes: apply CI fixes --- tests/fm-usage-harvest.test.sh | 53 ++++++++++++++++++++++++++++++++++ 1 file changed, 53 insertions(+) diff --git a/tests/fm-usage-harvest.test.sh b/tests/fm-usage-harvest.test.sh index bc4c50e357e..514b672474d 100755 --- a/tests/fm-usage-harvest.test.sh +++ b/tests/fm-usage-harvest.test.sh @@ -19,6 +19,8 @@ # that keeps that scan bound safe, the harvest of a secondmate's children # before a forced cleanup retires them, and the scan-then-append split that # keeps an aborted teardown from freezing a row its rerun could not correct. +# Also covers the nested remote secondmate teardown, whose append is skipped +# because the home it removed is the one holding its own ledger. set -u # shellcheck source=tests/lib.sh @@ -1187,6 +1189,56 @@ JSON pass "teardown integration: a nested home's same-named task cannot overwrite its parent's row" } +# The nested host-local teardown of a remote secondmate runs on the far host +# with its state and data overridden into that home's own parent-route +# directories (bin/fm-remote-secondmate-control.sh retire owns those paths), so +# the home it removes is the one holding its own ledger. The append phase must +# be skipped there: the harvester creates its data directory on append, so +# appending after the removal resurrects the home that was just retired. The +# surviving parent teardown is what records such a task. The scan still stages +# a row, so the skip shows only as the home staying gone. +teardown_remote_nested_home_case() { + local id=usageharvself1 fb home state data config wt out encoded logdir now + fb="$TMP_ROOT/self-fakebin" + mkdir -p "$fb" + printf '#!/usr/bin/env bash\nexit 0\n' > "$fb/tmux" + chmod +x "$fb/tmux" + home="$TMP_ROOT/self-home"; config="$TMP_ROOT/self-config" + state="$home/state/parent-route"; data="$home/data/.parent-route" + mkdir -p "$state" "$data" "$config" "$TMP_ROOT/self-proj" + printf '%s\n' "$id" > "$home/.fm-secondmate-home" + wt="$TMP_ROOT/.no-mistakes/wt-$id" + fm_write_meta "$state/$id.meta" \ + "window=firstmate:fm-$id" "worktree=$wt" "project=$TMP_ROOT/self-proj" \ + "harness=claude" "home=$home" "kind=secondmate" "mode=no-mistakes" \ + "model=default" "effort=default" + now=$(date +%s) + printf 'spawn_gen=s%s.91.1\n' "$((now - 400))" >> "$state/$id.meta" + printf 'working: nested remote secondmate\n' > "$state/$id.status" + touch -t "$(touch_stamp $((now - 30)))" "$state/$id.status" + + # A real log, so the scan stages a non-empty row and only the append is + # skipped. + encoded=${wt//\//-} + encoded=${encoded//./-} + logdir="$TMP_ROOT/self-fake-claude/$encoded" + mkdir -p "$logdir" + cat > "$logdir/session.jsonl" <<'JSON' +{"type":"assistant","message":{"id":"msgSELF","model":"claude-self","usage":{"input_tokens":31,"output_tokens":4}}} +JSON + touch -t "$(touch_stamp $((now - 20)))" "$logdir/session.jsonl" + + out=$(PATH="$fb:$PATH" FM_ROOT_OVERRIDE="$ROOT" \ + FM_STATE_OVERRIDE="$state" FM_DATA_OVERRIDE="$data" FM_CONFIG_OVERRIDE="$config" \ + FM_USAGE_CLAUDE_DIR="$TMP_ROOT/self-fake-claude" FM_USAGE_CODEX_DIR="$TMP_ROOT/self-fake-codex" \ + FM_USAGE_PI_DIR="$TMP_ROOT/self-fake-pi" \ + "$TEARDOWN" "$id" --force 2>&1) + expect_code 0 "$?" "nested remote secondmate teardown should succeed"$'\n'"$out" + [ ! -e "$home" ] \ + || fail "the append resurrected the retired secondmate home: [$(find "$home" | tr '\n' ' ')]"$'\n'"$out" + pass "teardown integration: the append never resurrects the home holding its own ledger" +} + teardown_pool_order_case() { local proj wt id fb state data config out row occupant thlog encoded logdir base id=usageharvpool1 @@ -1984,6 +2036,7 @@ report_malformed_case teardown_status_case teardown_child_case teardown_nested_child_case +teardown_remote_nested_home_case teardown_pool_order_case teardown_refusal_case teardown_single_diagnostic_case