From 3c7ff030b2c0eb16a4ae34328e89e1ea24da52bc Mon Sep 17 00:00:00 2001 From: Garry Tan Date: Fri, 6 Nov 2026 00:47:50 -0800 Subject: [PATCH] ship budget: count a Capy /ship helper's calls from the call log (GST-1585) (#4059) * ship budget: count a Capy /ship helper calls from the call log the gstack-ship-* bins write (GST-1585) Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> * ship call log: Capy only, so test runs never write a real home; shorter Step 22 line keeps the capy skill budget (GST-1585) Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> * fix: pre-landing review fixes Review-Finding: p1/red-team#1 reader=red-team Review-Finding: p1/red-team#2 reader=red-team Review-Finding: p1/specialist-batched#2 reader=testing Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> * fix: granted fix-check fixes: poll-rerun overhead and early-settled passes Review-Finding: p3/outside-voice#2 reader=outside-voice Review-Finding: p3/adversarial-native#1 reader=adversarial-native Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> * changelog: GST-1585 fragment named for the branch, covers the review fixes Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> * docs: ship-budget call-log usage lists --since/--until; changelog fragment text Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> --------- Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> --- bin/gstack-review-dispatch | 3 + bin/gstack-ship-budget | 4 + bin/gstack-ship-parts | 3 + bin/gstack-ship-policy | 3 + bin/gstack-ship-preflight | 3 + bin/gstack-ship-queue | 3 + bin/gstack-ship-release | 3 + capy/skill/gstack/SKILL.md | 2 +- changelog.d/capy-gst-1585-helper-calls.md | 1 + docs/ship-budget.md | 17 +++ lib/ship-budget-cli.ts | 13 ++- lib/ship-call-log.ts | 112 +++++++++++++++++++ test/ship-call-log.test.ts | 126 ++++++++++++++++++++++ 13 files changed, 289 insertions(+), 4 deletions(-) create mode 100644 changelog.d/capy-gst-1585-helper-calls.md create mode 100644 lib/ship-call-log.ts create mode 100644 test/ship-call-log.test.ts diff --git a/bin/gstack-review-dispatch b/bin/gstack-review-dispatch index 82e0cdbc9..a9f9e91ee 100755 --- a/bin/gstack-review-dispatch +++ b/bin/gstack-review-dispatch @@ -36,6 +36,9 @@ import { auditVerdict, eventsDigest, loadReaders, readersLine, scanEvents, type import { effectiveReaders, READERS_POLICY_DEFAULT, type EffectiveReaders } from '../lib/ship-policy-readers'; import { defaultRoots, foundLines, inventory, quarantineStage, rerunBlocked, sweepResult, type Inventory } from '../lib/review-sweep'; import { REVIEW_DIFF_MAX_BYTES, ceilingContext, disclosureDigest, disclosureLine, parseTail, readSelection, tooLargeLine, unreadableLine, type PlanExclude, type ReaderDiff } from '../lib/review-exclude'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-review-dispatch'); const HELP = `gstack-review-dispatch — verbatim reviewer briefs and loss-free collection for /ship diff --git a/bin/gstack-ship-budget b/bin/gstack-ship-budget index 102bb839a..bcfb0ef06 100755 --- a/bin/gstack-ship-budget +++ b/bin/gstack-ship-budget @@ -24,6 +24,7 @@ * [--rebuild-from-record] * close --run|--record [--reading ] [--approved-by --words ] * calls --events [--since ] [--until ] (the host's transcript items: one CALLS: line, lib/ship-calls.ts) + * calls --run|--record [--log ] [--since ] [--until ] (the call log the gstack-ship-* bins write: lib/ship-call-log.ts) * * Exit: 0 continue/delegate · 3 stop (the next step does not start) · 2 usage * or validation (stderr). Logic: lib/ship-budget.ts, lib/ship-budget-cli.ts, @@ -32,6 +33,9 @@ import { BudgetError } from '../lib/ship-budget'; import { cmdCalls, cmdCheck, cmdClose, cmdNote, cmdResume, cmdSettle, cmdStart, type Outcome } from '../lib/ship-budget-cli'; import { cmdHandoff, cmdLaunch, cmdReconcile, cmdReturn, cmdVerifyHandoff } from '../lib/ship-handoff'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-ship-budget'); const [command, ...rest] = process.argv.slice(2); const ctx = { env: process.env, cwd: process.cwd() }; diff --git a/bin/gstack-ship-parts b/bin/gstack-ship-parts index 07ee7d572..e6c6d7f67 100755 --- a/bin/gstack-ship-parts +++ b/bin/gstack-ship-parts @@ -4,6 +4,9 @@ * returned once per run inside the phase program before it (GSTA-167 C5). Logic: lib/ship-parts.ts. */ import { shipParts } from '../lib/ship-parts'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-ship-parts'); const out = shipParts(process.argv.slice(2)); (out.exit === 2 ? process.stderr : process.stdout).write(out.text); diff --git a/bin/gstack-ship-policy b/bin/gstack-ship-policy index f01db4679..f9d0abdbf 100755 --- a/bin/gstack-ship-policy +++ b/bin/gstack-ship-policy @@ -21,6 +21,9 @@ import { BUMP_NEVER_KEY_VERSION, POLICY_KEYS, POLICY_KEY_INTRODUCED, SHIP_POLICY_PATH, examplePolicyJson, explainPolicy, isUnavailable, loadPolicyFromBase, loadPolicyFromHead, minimumReader, policyUnavailableLine, renderEffective, resolveBaseBranch, type LoadedPolicy, } from '../lib/ship-policy'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-ship-policy'); const HELP = `gstack-ship-policy — the repo ship policy (docs/ship-policy.md) diff --git a/bin/gstack-ship-preflight b/bin/gstack-ship-preflight index 3664d9353..25b4e6451 100755 --- a/bin/gstack-ship-preflight +++ b/bin/gstack-ship-preflight @@ -4,6 +4,9 @@ * STOP:/NEXT: lines wherever the agent must judge. Logic: lib/ship-preflight.ts. */ import { preflight } from '../lib/ship-preflight'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-ship-preflight'); const out = await preflight(process.argv.slice(2), process.cwd()); (out.exit === 2 ? process.stderr : process.stdout).write(out.text); diff --git a/bin/gstack-ship-queue b/bin/gstack-ship-queue index b500fd451..686138351 100755 --- a/bin/gstack-ship-queue +++ b/bin/gstack-ship-queue @@ -38,6 +38,9 @@ import { RESULT_CODES } from '../lib/result-codes'; import { resolveBaseBranch } from '../lib/ship-policy'; import { loadBasePolicy, ready, stamp, verify, type QueueContext, type StepOutput } from '../lib/ship-queue'; import { attemptFile, listAttempts, prepareGateAhead, recordGateAhead, type QueueFailure } from '../lib/ship-queue-gate'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-ship-queue'); const HELP = `gstack-ship-queue — the shared merge queue's protocol steps (docs/ship-policy.md#run-a-shared-merge-queue) diff --git a/bin/gstack-ship-release b/bin/gstack-ship-release index 48ccff618..5f580805e 100755 --- a/bin/gstack-ship-release +++ b/bin/gstack-ship-release @@ -4,6 +4,9 @@ * with STOP:/NEXT: lines wherever the agent must judge. Logic: lib/ship-release.ts. */ import { release } from '../lib/ship-release'; +import { logShipCall } from '../lib/ship-call-log'; + +logShipCall('gstack-ship-release'); const out = await release(process.argv.slice(2), process.cwd()); (out.exit === 2 ? process.stderr : process.stdout).write(out.text); diff --git a/capy/skill/gstack/SKILL.md b/capy/skill/gstack/SKILL.md index e4795cd88..f520c21d8 100644 --- a/capy/skill/gstack/SKILL.md +++ b/capy/skill/gstack/SKILL.md @@ -46,7 +46,7 @@ Capy checklist for `/autoplan`: drive `gstack-autoplan`, never a hand adaptation Token caps on /ship: pass a brief's cap as `--token-cap `. /ship reads `cost.tokens` and `cost.credits` from `tools.thread.get({ thread_id: "" })` (its own jam; a subagent reading root `"this"` starts `--subagent --reading-from this --meter-scope tree`) inside the same execute program as the `gstack-ship-budget` command that takes them as `--reading --credits `, never alone. `ship/DRIVER.md` starts `--mode observe`: each program ends with `note`, and only a note past the cap stops (`docs/ship-budget.md`). -/ship on Capy is about a dozen calls, each an execute program (`ship/DRIVER.md`). Each review pass and Step 11 is one call to the checked-in pass program (fill only `input`): `const t0 = await now(); const p = (await tools.capy.bash({ command: ". '' && gstack-review-dispatch program", description: "Pass" })).output.split("\n"); return p[0] + "\n" + (await new (Object.getPrototypeOf(async () => {}).constructor)("tools", "sleep", "now", "input", JSON.parse(p[1]))(tools, sleep, now, { startedAt: t0, launch: "", cwd: "", base: "", out: "/p", pass: "-p", laneModel: "", planFlags: [], logStart: ["review"], jam: "", record: "", step: "9.2" }));` It plans, logs `logStart` (`reservation` mode from `RESERVATION_ID:`), sends each brief on `machine: "shared"`, then polls: one `tools.subagent.list` per ~20 s tick, returning 200 s after the program's first line, where a reader is settled only at status `done` or `failed` or with a `summary` (a just-created `idle` reader has not run); it starts readers under `rejected` with `tools.subagent.start` as slots free and stops on one stuck 20 minutes. It ends on `NEXT:` (`poll`: rerun) or `STOP:`. `models` maps roles to models (`outside-voice`: another family, pinned in `voice-models.json`); Step 11 swaps `logStart` for `stage: "voices"`; a full repeat pass, `diffBase: ""`. Steps 7, 8 and 14.5 (`step: "14.5"`) use `extras`, JSON `{name, prompt_file, first, model}` (prompts verbatim from their sections, Step 7 `first`); they cannot block, so omit `model`: the pass prints `AUDIT_MODEL:`. Waits: never let 5 minutes pass between calls. While readers run, never end the turn on `wait`; rerun the loader. Else re-issue `wait` with `duration_seconds: 200` and operation ids. At Step 22 report the `CALLS:` line of `gstack-ship-budget calls --events ` on your transcript since /ship began. A small waiting child saves nothing. +/ship on Capy is about a dozen calls, each an execute program (`ship/DRIVER.md`). Each review pass and Step 11 is one call to the checked-in pass program (fill only `input`): `const t0 = await now(); const p = (await tools.capy.bash({ command: ". '' && gstack-review-dispatch program", description: "Pass" })).output.split("\n"); return p[0] + "\n" + (await new (Object.getPrototypeOf(async () => {}).constructor)("tools", "sleep", "now", "input", JSON.parse(p[1]))(tools, sleep, now, { startedAt: t0, launch: "", cwd: "", base: "", out: "/p", pass: "-p", laneModel: "", planFlags: [], logStart: ["review"], jam: "", record: "", step: "9.2" }));` It plans, logs `logStart` (`reservation` mode from `RESERVATION_ID:`), sends each brief on `machine: "shared"`, then polls: one `tools.subagent.list` per ~20 s tick, returning 200 s after the program's first line, where a reader is settled only at status `done` or `failed` or with a `summary` (a just-created `idle` reader has not run); it starts readers under `rejected` with `tools.subagent.start` as slots free and stops on one stuck 20 minutes. It ends on `NEXT:` (`poll`: rerun) or `STOP:`. `models` maps roles to models (`outside-voice`: another family, pinned in `voice-models.json`); Step 11 swaps `logStart` for `stage: "voices"`; a full repeat pass, `diffBase: ""`. Steps 7, 8 and 14.5 (`step: "14.5"`) use `extras`, JSON `{name, prompt_file, first, model}` (prompts verbatim from their sections, Step 7 `first`); they cannot block, so omit `model`: the pass prints `AUDIT_MODEL:`. Waits: never let 5 minutes pass between calls. While readers run, never end the turn on `wait`; rerun the loader. Else re-issue `wait` with `duration_seconds: 200` and operation ids. At Step 22 report the `CALLS:` line of `gstack-ship-budget calls --record `. A small waiting child saves nothing. ## Plan, approve, ship diff --git a/changelog.d/capy-gst-1585-helper-calls.md b/changelog.d/capy-gst-1585-helper-calls.md new file mode 100644 index 000000000..64a9ac939 --- /dev/null +++ b/changelog.d/capy-gst-1585-helper-calls.md @@ -0,0 +1 @@ +- **A /ship helper on Capy can count its own calls.** Every helper reported `CALLS: unavailable` because a subagent can't read its own transcript. On Capy, the gstack-ship-* commands and the review pass loader now add one row each to `/ship-calls.jsonl` when they exit, and `gstack-ship-budget calls --record ` turns those rows into a `CALLS: source=log` line: phase programs, review-pass polls, section reads, an estimate of the keep-alive waits between them, how far past 200 s each poll rerun starts, and gaps over the 300 s cache. Counting adds no call. A run window with no rows prints `CALLS: unavailable` instead of zeros, and a background lane or `finish` no longer hides the calls made while it runs. (GST-1585) diff --git a/docs/ship-budget.md b/docs/ship-budget.md index a60dbb7c7..84c873098 100644 --- a/docs/ship-budget.md +++ b/docs/ship-budget.md @@ -49,6 +49,23 @@ item is one parent call; a `wait`, or a program that only reads status (plus at note), is a keep-alive, and a gap over 300 s between calls outlives the prompt cache (`lib/ship-calls.ts`). +A Capy /ship helper cannot read its own transcript, so it counts from the call log instead: +`gstack-ship-budget calls --run |--record [--log ] [--since ] [--until ]`. On Capy (`GSTACK_CAPY=1`, set by the +launch file) every gstack-ship-* bin and `gstack-review-dispatch` append one row to `/ship-calls.jsonl` when they exit (a bin another +one spawned writes none), so counting adds no call. The window is the run's start to its close, and the +line is `CALLS: source=log calls= phase= pass= section= other= keepalive_est= total_est= pass_overhead_s= +gaps_over_300s= max_gap_s= first= last=`, or `CALLS: unavailable source=log reason=no rows in the run window log=` +when the window holds no row (the rotated `ship-calls.jsonl.1` is read too). Rows that run back to back are one call, and +a row longer than a program (a background lane or `finish`) ends where it starts; a pass loader +(`gstack-review-dispatch program`) opens a call that lasts its 200 s poll; a program's closing `note` +joins it. A call with the loader is a pass poll, one with a note a phase program, one with only +`gstack-ship-parts` a section read. Calls that run no gstack command (a `wait`, an edit) leave no row, +so `keepalive_est` fills the time between calls, outside a pass, at one keep-alive per 200 s plus the +median pass overhead: how far past 200 s a pass rerun starts, measured from 200 s poll reruns only (a pass call +that did not note, then a loader 200 s or more later) and never below 0 +(`lib/ship-call-log.ts`). `total_est` is `calls + keepalive_est`; quick decision calls between logged ones +are not in it. + **Credits.** Every command that takes `--reading` also takes `--credits ` from the same `thread.get`. Tokens count a cached read the same as a fresh one; credits are what the run costs, including the full-context re-bill after a gap over five minutes (about 40x a cached call, diff --git a/lib/ship-budget-cli.ts b/lib/ship-budget-cli.ts index d1ce7201b..e5b3f5189 100644 --- a/lib/ship-budget-cli.ts +++ b/lib/ship-budget-cli.ts @@ -19,6 +19,7 @@ import { runDirFor, settleIn, stepProjection, tally, unitConstants, unreservedDispatches, usageError, writeLedger, type Ledger, type MeterKind, type Next, type Note, } from './ship-budget'; +import { callLogFile, countLoggedCalls, loggedCallsLine, readCallLog } from './ship-call-log'; import { callsLine, countCalls } from './ship-calls'; import { claudeConfigDir, loadMeterState, newMeterState, nonceSessions, readClaudeUsage, saveMeterState, sessionJournals } from './claude-usage'; @@ -411,11 +412,17 @@ export function cmdNote(argv: string[], ctx: Ctx): Outcome { }); } -/** calls: count parent calls from the host's transcript items (lib/ship-calls.ts). */ +/** calls: count parent calls from the host's transcript items (lib/ship-calls.ts), or a run's from the call log (lib/ship-call-log.ts). */ export function cmdCalls(argv: string[], ctx: Ctx): Outcome { - const o = parseArgs(argv, ['events', 'since', 'until']); + const o = parseArgs(argv, ['events', 'since', 'until', 'run', 'record', 'log']); const raw = str(o, 'events'); - if (!raw) throw usageError('calls needs --events '); + if (!raw) { + if (!str(o, 'run') && !str(o, 'record') && !str(o, 'log')) throw usageError('calls needs --events , or --run |--record to read the call log'); + const l = str(o, 'run') || str(o, 'record') ? readLedger(ledgerFileFor({ run: str(o, 'run'), record: str(o, 'record') }, ctx.env)) : undefined; + const log = str(o, 'log') ?? callLogFile(ctx.env); + const c = countLoggedCalls(readCallLog(log), { since: str(o, 'since') ?? l?.created_at, until: str(o, 'until') ?? l?.closed_at }); + return { stdout: [c.calls ? loggedCallsLine(c) : `CALLS: unavailable source=log reason=no rows in the run window log=${log}`], exit: 0 }; + } const file = raw === '~' || raw.startsWith('~/') ? path.join(ctx.env.HOME || os.homedir(), raw.slice(1)) : raw; let doc: unknown; try { doc = JSON.parse(fs.readFileSync(file, 'utf8')); } catch (e: any) { throw usageError(`calls --events ${file}: ${e.message}`); } diff --git a/lib/ship-call-log.ts b/lib/ship-call-log.ts new file mode 100644 index 000000000..d8cbdb34d --- /dev/null +++ b/lib/ship-call-log.ts @@ -0,0 +1,112 @@ +/** + * ship-call-log — the /ship helper's calls, counted from the commands it already runs (GST-1585, + * GSTA-330 H1). A Capy helper cannot read its own transcript, so on Capy (GSTACK_CAPY=1) every gstack-ship-* + * bin and the pass loader (`gstack-review-dispatch`) append one row to /ship-calls.jsonl when they exit, and + * `gstack-ship-budget calls --run|--record` rebuilds the helper's calls from those rows: no added call. + * + * Rows join one call while they run back to back (each starts within 5 s of the last one's end); a row longer + * than a program (a background lane or finish) ends where it starts, so it never absorbs the calls made while it runs. A pass + * loader (`gstack-review-dispatch program`) opens a call that polls up to 200 s after its first line, so + * review rows and notes join it until it notes; a program's closing `note` joins it up to 230 s after its + * first row. A call with a loader is a pass poll, one with a note a phase program, one with only + * gstack-ship-parts a section read, anything else other. Calls that run no gstack command (a `wait`, an + * edit) leave no row: the time between calls, outside a pass, is filled at one keep-alive per 200 s plus + * the median pass overhead (the time a 200 s poll rerun adds past its 200 s, never below 0; a pass that noted, or a + * loader that starts under 200 s after the last one, is no rerun). + */ +import * as fs from 'node:fs'; +import * as path from 'node:path'; +import { resolveStateRoot } from './state-root'; + +export interface CallRow { v: 1; bin: string; sub: string; step?: string; reading?: number; credits?: number; start: string; ms: number; exit: number } +export interface LoggedCalls { + calls: number; phase: number; pass: number; section: number; other: number; keepaliveEst: number; + passOverhead: number[]; idleGaps: number; maxGapS: number; first: string | null; last: string | null; +} + +const NESTED = 'GSTACK_SHIP_CALL_NESTED'; +const ROTATE_BYTES = 8 * 1024 * 1024; +const JOIN_MS = 5_000; +const POLL_S = 200; +const PROGRAM_MS = 230_000; +const DEFAULT_OVERHEAD_S = 15; +const CACHE_TTL_S = 300; + +export const callLogFile = (env: NodeJS.ProcessEnv) => path.join(resolveStateRoot(env), 'ship-calls.jsonl'); + +/** Register this bin's row, written at exit, on Capy only (GSTACK_CAPY=1 from the launch file); a bin another gstack-ship-* bin spawned writes none. A failed write never changes the command. */ +export function logShipCall(bin: string, argv: string[] = process.argv.slice(2)): void { + if (process.env.GSTACK_CAPY !== '1' || process.env[NESTED] === '1') return; + process.env[NESTED] = '1'; + const started = Date.now(); + const flag = (name: string) => { const i = argv.indexOf(`--${name}`); return i >= 0 ? argv[i + 1] : undefined; }; + const num = (name: string) => { const v = Number(flag(name)); return flag(name) !== undefined && Number.isFinite(v) ? v : undefined; }; + process.on('exit', code => { + try { + const row: CallRow = { v: 1, bin, sub: argv[0] && !argv[0].startsWith('-') ? argv[0] : '', start: new Date(started).toISOString(), ms: Date.now() - started, exit: code }; + const step = flag('step'), reading = num('reading'), credits = num('credits'); + if (step !== undefined) row.step = step; + if (reading !== undefined) row.reading = reading; + if (credits !== undefined) row.credits = credits; + const file = callLogFile(process.env); + fs.mkdirSync(path.dirname(file), { recursive: true }); + if ((fs.statSync(file, { throwIfNoEntry: false })?.size ?? 0) > ROTATE_BYTES) fs.renameSync(file, `${file}.1`); + fs.appendFileSync(file, JSON.stringify(row) + '\n'); + } catch { /* counting must never break the command */ } + }); +} + +export function readCallLog(file: string): CallRow[] { + return [`${file}.1`, file].filter(f => fs.existsSync(f)).flatMap(f => fs.readFileSync(f, 'utf8').split('\n')).flatMap(line => { + try { const r = JSON.parse(line); return r?.v === 1 && typeof r.start === 'string' && !Number.isNaN(Date.parse(r.start)) ? [r as CallRow] : []; } catch { return []; } + }); +} + +interface Call { start: number; end: number; loader: boolean; note: boolean; partsOnly: boolean } +const isLoader = (r: CallRow) => r.bin === 'gstack-review-dispatch' && r.sub === 'program'; +const isNote = (r: CallRow) => r.bin === 'gstack-ship-budget' && r.sub === 'note'; + +export function countLoggedCalls(rows: readonly CallRow[], window: { since?: string; until?: string } = {}): LoggedCalls { + const since = window.since ? Date.parse(window.since) : -Infinity, until = window.until ? Date.parse(window.until) : Infinity; + const inWindow = rows.map(r => ({ r, s: Date.parse(r.start), ms: Math.max(0, r.ms) })) + .filter(x => x.s <= until && x.s + x.ms >= since).sort((a, b) => a.s - b.s); + const calls: Call[] = []; + for (const { r, s, ms } of inWindow) { + const e = ms > PROGRAM_MS ? s : s + ms; + const cur = calls[calls.length - 1]; + const joins = cur && !isLoader(r) && (s <= cur.end + JOIN_MS + || (cur.loader && !cur.note && s <= cur.start + PROGRAM_MS) + || (isNote(r) && !cur.note && !cur.partsOnly && s <= cur.start + PROGRAM_MS)); + if (!joins) { calls.push({ start: s, end: e, loader: isLoader(r), note: isNote(r), partsOnly: r.bin === 'gstack-ship-parts' }); continue; } + cur.end = Math.max(cur.end, e); + cur.loader ||= isLoader(r); + cur.note ||= isNote(r); + cur.partsOnly &&= r.bin === 'gstack-ship-parts'; + } + const kind = (c: Call) => c.loader ? 'pass' : c.note ? 'phase' : c.partsOnly ? 'section' : 'other'; + const passOverhead: number[] = []; + let idleGaps = 0, maxGapS = 0; + for (let k = 1; k < calls.length; k++) { + const gap = Math.round((calls[k]!.start - calls[k - 1]!.start) / 1000); + if (gap > CACHE_TTL_S) idleGaps++; + maxGapS = Math.max(maxGapS, gap); + if (calls[k]!.loader && calls[k - 1]!.loader && !calls[k - 1]!.note && gap >= POLL_S - JOIN_MS / 1000) passOverhead.push(Math.max(0, gap - POLL_S)); + } + const sorted = [...passOverhead].sort((a, b) => a - b); + const cycle = POLL_S + Math.max(0, sorted.length ? sorted[Math.ceil(sorted.length / 2) - 1]! : DEFAULT_OVERHEAD_S); + let keepaliveEst = 0; + for (let k = 1; k < calls.length; k++) { + if (calls[k]!.loader && calls[k - 1]!.loader) continue; + keepaliveEst += Math.round(Math.max(0, calls[k]!.start - calls[k - 1]!.end) / 1000 / cycle); + } + const count = (k: string) => calls.filter(c => kind(c) === k).length; + const iso = (ms: number | undefined) => ms === undefined ? null : new Date(ms).toISOString(); + return { calls: calls.length, phase: count('phase'), pass: count('pass'), section: count('section'), other: count('other'), keepaliveEst, + passOverhead, idleGaps, maxGapS, first: iso(calls[0]?.start), last: iso(calls[calls.length - 1]?.start) }; +} + +export function loggedCallsLine(c: LoggedCalls): string { + const sorted = [...c.passOverhead].sort((a, b) => a - b); + const overhead = sorted.length ? `p50:${sorted[Math.ceil(sorted.length / 2) - 1]},max:${sorted[sorted.length - 1]}` : 'none'; + return `CALLS: source=log calls=${c.calls} phase=${c.phase} pass=${c.pass} section=${c.section} other=${c.other} keepalive_est=${c.keepaliveEst} total_est=${c.calls + c.keepaliveEst} pass_overhead_s=${overhead} gaps_over_300s=${c.idleGaps} max_gap_s=${c.maxGapS} first=${c.first ?? 'none'} last=${c.last ?? 'none'}`; +} diff --git a/test/ship-call-log.test.ts b/test/ship-call-log.test.ts new file mode 100644 index 000000000..e36d639b4 --- /dev/null +++ b/test/ship-call-log.test.ts @@ -0,0 +1,126 @@ +/** + * gstack-ship-budget calls --run|--record (GST-1585, GSTA-330 H1): a Capy /ship helper cannot read its own + * transcript, so every helper reported CALLS: unavailable. The gstack-ship-* bins and the review pass loader + * now append one row each to the state root's call log, and calls rebuilds the helper's calls from those rows + * (no added call): phase programs, pass polls, section reads, and the keep-alives that fill the time between. + */ +import { afterAll, describe, expect, test } from 'bun:test'; +import { spawnSync } from 'node:child_process'; +import * as fs from 'node:fs'; +import * as os from 'node:os'; +import * as path from 'node:path'; +import { countLoggedCalls, type CallRow } from '../lib/ship-call-log'; + +const BIN_DIR = path.resolve(import.meta.dir, '..', 'bin'); +const tmp = fs.mkdtempSync(path.join(os.tmpdir(), 'ship-call-log-')); +afterAll(() => fs.rmSync(tmp, { recursive: true, force: true })); +const run = (bin: string, args: string[], state: string) => + spawnSync(path.join(BIN_DIR, bin), args, { encoding: 'utf8', timeout: 60_000, env: { ...process.env, GSTACK_STATE_ROOT: state, GSTACK_CAPY: '1', GSTACK_SHIP_CALL_NESTED: '' } }); +const rows = (state: string): CallRow[] => fs.readFileSync(path.join(state, 'ship-calls.jsonl'), 'utf8').trim().split('\n').map(l => JSON.parse(l)); +const at = (s: string) => `2026-11-06T${s}Z`; +const row = (t: string, bin: string, sub: string, ms = 200, extra: Partial = {}): CallRow => ({ v: 1, bin, sub, start: at(t), ms, exit: 0, ...extra }); +// A helper's day, shortened: a phase program, waits, a phase program, a four-call review pass, a section read, a phase program, a queue command. +const DAY: CallRow[] = [ + row('10:00:00.000', 'gstack-ship-budget', 'start', 300), + row('10:00:01.000', 'gstack-ship-preflight', '', 2000), + row('10:00:05.000', 'gstack-ship-budget', 'note', 200, { step: '2', reading: 400000, credits: 100 }), + row('10:00:05.500', 'gstack-ship-parts', 'next', 300), + row('10:12:00.000', 'gstack-ship-preflight', '', 3000), + row('10:12:04.000', 'gstack-ship-budget', 'note', 200, { step: '6' }), + row('10:12:30.000', 'gstack-review-dispatch', 'program', 100), + row('10:12:31.000', 'gstack-review-dispatch', 'pass', 1500), + row('10:12:40.000', 'gstack-review-dispatch', 'sent', 100), + row('10:16:05.000', 'gstack-review-dispatch', 'program', 100), + row('10:19:45.000', 'gstack-review-dispatch', 'program', 100), + row('10:23:45.000', 'gstack-review-dispatch', 'program', 100), + row('10:24:30.000', 'gstack-ship-budget', 'note', 200, { step: '9' }), + row('10:24:31.000', 'gstack-review-dispatch', 'collect', 500), + row('10:25:00.000', 'gstack-ship-parts', 'next', 300), + row('10:25:30.000', 'gstack-ship-budget', 'note', 200, { step: '12' }), + row('10:40:00.000', 'gstack-ship-queue', 'ready', 4000), +]; +const DAY_LINE = `CALLS: source=log calls=9 phase=3 pass=4 section=1 other=1 keepalive_est=7 total_est=16 pass_overhead_s=p50:20,max:40 gaps_over_300s=2 max_gap_s=870 first=${at('10:00:00.000')} last=${at('10:40:00.000')}`; + +describe('the call log', () => { + // Value: protects=a helper's calls are counted from the commands it already runs, so each gstack-ship-* bin and the pass loader must leave one row with its subcommand, step, readings, exit and duration, and a bin a gstack-ship-* bin spawns must not add a second row; fails_when=a bin writes no row on Capy, writes one off Capy (a test's real home), drops --step/--reading/--credits, logs a nested child, or a log write failure changes the command's output or exit; + // why_new=every helper reported CALLS: unavailable (GSTA-326 step0.tsv); seam=none; no_claim=which calls a helper makes without running a gstack command (the keep-alive estimate covers those) + test('each bin appends one row; a failed log write changes nothing', () => { + const state = fs.mkdtempSync(path.join(tmp, 'state-')); + const parts = run('gstack-ship-parts', [], state); + const note = run('gstack-ship-budget', ['note', '--run', 'nope', '--step', '7', '--reading', '5', '--credits', '1.5'], state); + const loader = run('gstack-review-dispatch', ['program'], state); + expect(loader.status, loader.stderr).toBe(0); + const got = rows(state); + expect(got.map(r => [r.bin, r.sub, r.exit])).toEqual([['gstack-ship-parts', '', Number(parts.status)], ['gstack-ship-budget', 'note', Number(note.status)], ['gstack-review-dispatch', 'program', 0]]); + expect(got[1]).toMatchObject({ v: 1, step: '7', reading: 5, credits: 1.5 }); + for (const r of got) { expect(Number.isNaN(Date.parse(r.start))).toBe(false); expect(r.ms).toBeGreaterThanOrEqual(0); } + const blocked = path.join(tmp, 'a-file'); + fs.writeFileSync(blocked, ''); + const again = run('gstack-ship-parts', [], blocked); + expect([again.status, again.stdout, again.stderr]).toEqual([parts.status, parts.stdout, parts.stderr]); + const nested = spawnSync(path.join(BIN_DIR, 'gstack-ship-parts'), [], { encoding: 'utf8', timeout: 60_000, env: { ...process.env, GSTACK_STATE_ROOT: state, GSTACK_CAPY: '1', GSTACK_SHIP_CALL_NESTED: '1' } }); + expect(nested.status).toBe(parts.status); + const offCapy = spawnSync(path.join(BIN_DIR, 'gstack-ship-parts'), [], { encoding: 'utf8', timeout: 60_000, env: { ...process.env, GSTACK_STATE_ROOT: state, GSTACK_CAPY: '', GSTACK_SHIP_CALL_NESTED: '' } }); + expect(offCapy.status).toBe(parts.status); + expect(rows(state)).toHaveLength(3); + }); +}); + +describe('countLoggedCalls', () => { + // Value: protects=the helper's call split: rows join one call while they run back to back, a pass loader opens a call that lasts its 200 s poll, a note closes the program it ends, a lone gstack-ship-parts is a section read, the time between calls is filled at one keep-alive per 200 s plus the measured pass overhead, and gaps over the 300 s cache are flagged; fails_when=a pass's later rows or a program's closing note count as new calls, pass reruns count as keep-alives, or the overhead or gap figures drift; + // why_new=the split decides whether a 240 s keep-alive or merged phase calls are worth building (GSTA-330 H1); seam=none; no_claim=the host's billing of a gap + test('splits phase, pass, section and other calls and estimates the keep-alives between them', () => { + expect(countLoggedCalls(DAY)).toMatchObject({ calls: 9, phase: 3, pass: 4, section: 1, other: 1, keepaliveEst: 7, passOverhead: [15, 20, 40], idleGaps: 2, maxGapS: 870 }); + }); + + test('a program whose note comes more than 5 s after its last command is still one call', () => { + const c = countLoggedCalls([row('11:00:00.000', 'gstack-ship-preflight', '', 1000), row('11:02:30.000', 'gstack-ship-budget', 'note', 200, { step: '5' })]); + expect(c).toMatchObject({ calls: 1, phase: 1, other: 0 }); + }); + + test('a background row longer than a program does not absorb the calls made while it runs', () => { + const c = countLoggedCalls([row('10:00:00.000', 'gstack-ship-preflight', '', 1_200_000), row('10:00:02.000', 'gstack-ship-budget', 'note', 300), row('10:04:00.000', 'gstack-ship-parts', 'next', 300), row('10:08:00.000', 'gstack-ship-budget', 'note', 300)]); + expect(c).toMatchObject({ calls: 3, phase: 2, section: 1, keepaliveEst: 2 }); + }); + + test('loaders that are not 200 s poll reruns never set the pass overhead, so the keep-alive estimate stays finite', () => { + const c = countLoggedCalls([row('10:00:00.000', 'gstack-review-dispatch', 'program', 100), row('10:00:00.300', 'gstack-review-dispatch', 'program', 100), row('10:10:00.000', 'gstack-ship-parts', 'next', 300)]); + expect(c).toMatchObject({ calls: 3, pass: 2, section: 1, passOverhead: [], keepaliveEst: 3 }); + }); + + test('a pass that settles early and notes does not swallow the next phase call', () => { + const c = countLoggedCalls([row('10:00:00.000', 'gstack-review-dispatch', 'program', 100), row('10:01:00.000', 'gstack-ship-budget', 'note', 200, { step: '9.2' }), row('10:01:40.000', 'gstack-review-dispatch', 'judge', 300), row('10:01:41.000', 'gstack-ship-budget', 'note', 200, { step: '9.4' })]); + expect(c).toMatchObject({ calls: 2, pass: 1, phase: 1 }); + }); +}); + +describe('gstack-ship-budget calls --record', () => { + // Value: protects=a helper gets its CALLS line from its own record: the window is the run's start to close, rows outside it are not counted, and --log reads another file; fails_when=calls still demands --events, counts rows outside the run's window, drops the rotated log's rows, prints zero counts for an empty window, or prints a line in another shape; + // why_new=Step 22 asked for a CALLS line no Capy helper could produce; seam=none; no_claim=a run whose commands write to another state root + test('counts the run window from the call log', () => { + const state = fs.mkdtempSync(path.join(tmp, 'state-')); + const rec = path.join(state, 'record.md'); + fs.writeFileSync(rec, '# record\n'); + fs.writeFileSync(path.join(state, 'ship-calls.jsonl'), JSON.stringify(row('09:00:00.000', 'gstack-ship-budget', 'note', 200, { step: '1' })) + '\n'); + const start = run('gstack-ship-budget', ['start', '--record', rec, '--mode', 'observe', '--reading', '100', '--credits', '1'], state); + expect(start.status, start.stderr + start.stdout).toBe(0); + const note = run('gstack-ship-budget', ['note', '--record', rec, '--step', '2', '--reading', '200', '--credits', '2'], state); + expect(note.status, note.stderr + note.stdout).toBe(0); + const close = run('gstack-ship-budget', ['close', '--record', rec, '--reading', '300', '--credits', '3'], state); + expect(close.status, close.stderr + close.stdout).toBe(0); + const c = run('gstack-ship-budget', ['calls', '--record', rec], state); + expect(c.status, c.stderr).toBe(0); + expect(c.stdout.trim()).toMatch(/^CALLS: source=log calls=1 phase=1 pass=0 section=0 other=0 keepalive_est=0 total_est=1 pass_overhead_s=none gaps_over_300s=0 max_gap_s=0 first=\S+ last=\S+$/); + const day = path.join(tmp, 'day.jsonl'); + fs.writeFileSync(day, DAY.map(r => JSON.stringify(r)).join('\n') + '\n'); + const d = run('gstack-ship-budget', ['calls', '--log', day, '--since', at('09:00:00.000'), '--until', at('11:00:00.000')], state); + expect(d.stdout.trim(), d.stderr).toBe(DAY_LINE); + const rotated = path.join(tmp, 'rotated.jsonl'); + fs.writeFileSync(`${rotated}.1`, DAY.slice(0, 8).map(r => JSON.stringify(r)).join('\n') + '\n'); + fs.writeFileSync(rotated, DAY.slice(8).map(r => JSON.stringify(r)).join('\n') + '\n'); + expect(run('gstack-ship-budget', ['calls', '--log', rotated, '--since', at('09:00:00.000'), '--until', at('11:00:00.000')], state).stdout.trim()).toBe(DAY_LINE); + const none = path.join(tmp, 'none.jsonl'); + expect(run('gstack-ship-budget', ['calls', '--record', rec, '--log', none], state).stdout.trim()).toBe(`CALLS: unavailable source=log reason=no rows in the run window log=${none}`); + expect(run('gstack-ship-budget', ['calls'], state).status).toBe(2); + }); +});