mirror of
https://github.com/garrytan/gstack.git
synced 2026-11-07 17:28:23 +01:00
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>
This commit is contained in:
1 parent
01572dec6d
commit
3c7ff030b2
13 files changed
+289
-4
No files matched your search
@@ -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
|
||||
|
||||
|
||||
@@ -24,6 +24,7 @@
|
||||
* [--rebuild-from-record]
|
||||
* close --run|--record [--reading <n>] [--approved-by <who> --words <text>]
|
||||
* calls --events <file> [--since <iso>] [--until <iso>] (the host's transcript items: one CALLS: line, lib/ship-calls.ts)
|
||||
* calls --run|--record [--log <file>] [--since <iso>] [--until <iso>] (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() };
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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)
|
||||
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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)
|
||||
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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 <n>`. /ship reads `cost.tokens` and `cost.credits` from `tools.thread.get({ thread_id: "<your own jam 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 <n> --credits <c>`, 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: ". '<launch file>' && 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: "<launch file>", cwd: "<repo>", base: "<base>", out: "<run dir>/p<n>", pass: "<run>-p<n>", laneModel: "<your model id>", planFlags: [], logStart: ["review"], jam: "<jam id>", record: "<rec>", 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: "<RANGE_BASE>"`. 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 <file>` 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: ". '<launch file>' && 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: "<launch file>", cwd: "<repo>", base: "<base>", out: "<run dir>/p<n>", pass: "<run>-p<n>", laneModel: "<your model id>", planFlags: [], logStart: ["review"], jam: "<jam id>", record: "<rec>", 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: "<RANGE_BASE>"`. 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 <rec>`. A small waiting child saves nothing.
|
||||
|
||||
## Plan, approve, ship
|
||||
|
||||
|
||||
@@ -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 `<state root>/ship-calls.jsonl` when they exit, and `gstack-ship-budget calls --record <rec>` 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)
|
||||
@@ -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 <id>|--record <path> [--log <file>] [--since <iso>] [--until <iso>]`. On Capy (`GSTACK_CAPY=1`, set by the
|
||||
launch file) every gstack-ship-* bin and `gstack-review-dispatch` append one row to `<state root>/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=<file>`
|
||||
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 <cost.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,
|
||||
|
||||
+10
-3
@@ -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 <file of the host\'s transcript items>');
|
||||
if (!raw) {
|
||||
if (!str(o, 'run') && !str(o, 'record') && !str(o, 'log')) throw usageError('calls needs --events <file of the host\'s transcript items>, or --run <id>|--record <path> 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}`); }
|
||||
|
||||
@@ -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 <state root>/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'}`;
|
||||
}
|
||||
@@ -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> = {}): 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);
|
||||
});
|
||||
});
|
||||
Reference in new issue
Block a user