Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
226 changes: 224 additions & 2 deletions engine/src/cli.attached.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,16 @@ let authHeaders: Array<string | null> = [];
/** What an `attach` answers with, when a test needs it to differ from `drainResponse` — a
* send mints its credential through attach, so those tests need both to be distinct. */
let attachResponse: { status: number; body: unknown } | undefined;
/** Milliseconds a `/messages` request is left hanging before answering. The failure mode this
* models is NOT a refused connection — it is one the engine ACCEPTS and never answers, which
* `fetch` will wait on forever unless something bounds it. */
let messagesHangMs = 0;
/** Same, for the drain — it carries its own tighter bound, so it needs its own hang. */
let drainHangMs = 0;
/** What the CLI under test uses as its default backstop. */
let engineTimeoutMs = '30000';
/** Hang the land route, to drive a MUTATING call through a real timeout. */
let landHangMs = 0;
/** What `GET /messages` answers with. `kild watch` reads the log, never the inbox, so its
* tests drive this rather than `drainResponse`. */
let messagesResponse: { status: number; body: unknown } | undefined;
Expand All @@ -58,6 +68,15 @@ beforeAll(async () => {
if (url.pathname.endsWith('/agents/attach') && attachResponse) {
return Response.json(attachResponse.body, { status: attachResponse.status });
}
if (url.pathname.endsWith('/land') && landHangMs > 0) {
await new Promise((resolve) => setTimeout(resolve, landHangMs));
}
if (url.pathname.endsWith('/inbox/drain') && drainHangMs > 0) {
await new Promise((resolve) => setTimeout(resolve, drainHangMs));
}
if (url.pathname.endsWith('/messages') && messagesHangMs > 0) {
await new Promise((resolve) => setTimeout(resolve, messagesHangMs));
}
if (url.pathname.endsWith('/messages') && messagesResponse) {
return Response.json(messagesResponse.body, { status: messagesResponse.status });
}
Expand Down Expand Up @@ -98,6 +117,9 @@ async function runCli(
...process.env,
KILD_ENGINE: engineOverride ?? engineUrl,
KILD_HOME: kildHome,
// Keep the backstop testable. Without an override the only way to exercise the DEFAULT is
// a 30s test, so nothing covered it and removing it entirely left the suite green.
KILD_ENGINE_TIMEOUT_MS: engineTimeoutMs,
};
for (const key of IDENTITY_ENV) delete env[key];
Object.assign(env, identity);
Expand Down Expand Up @@ -619,8 +641,11 @@ test('the BOOTSTRAP path respects the window too, not just the poll loop', async
'http://127.0.0.1:1',
);
const elapsed = Date.now() - started;
expect(overrun.exitCode).toBe(2); // quiet — the window closed, the engine was not declared dead
// A 1s window must not become a 6s one because the first fetch happened to fail.
// Exit 3, not 2. This assertion USED to expect quiet, and that expectation was wrong: the
// engine never answered once, so "nothing new" would assert a response that never came.
// What this test is actually for is the elapsed time — a 1s window must not become a 6s one
// because the first fetch happened to fail — and that is unchanged.
expect(overrun.exitCode).toBe(3);
expect(elapsed).toBeLessThan(3_000);
}, 15_000);

Expand All @@ -645,3 +670,200 @@ test('the quiet message reports the time that actually elapsed', async () => {
expect(quiet.stderr).toMatch(/nothing new in \d+s/);
messagesResponse = undefined;
});

test('a hung engine is unreachable, not patient', async () => {
// The gap that survived the watch review: `fetch` has no timeout, so a connection the engine
// ACCEPTS and never answers hangs inside a single poll regardless of any deadline built on
// top of it. A watcher would sit past its whole window reporting neither mail nor a dead
// engine — defeating the exit-3 distinction it exists to draw.
messagesHangMs = 30_000;
const started = Date.now();
const hung = await runCli([
'watch',
'kild-9',
'--as',
'kild',
'--since',
'1',
'--timeout',
'60',
'--interval',
'0.1',
]);
const elapsed = Date.now() - started;
expect(hung.exitCode).toBe(3);
expect(hung.stderr).toContain('unreachable');
expect(hung.stderr).toContain('timed out'); // the cause rides the report, not just "aborted"

// Three attempts, each bounded by the 1s request floor — not the 60s window, and certainly
// not the 30s hang.
expect(elapsed).toBeLessThan(15_000);
messagesHangMs = 0;
}, 30_000);

test('a drain against a hung engine times out, and says so', async () => {
// The drain carries its own 1.5s bound because it runs inside a turn-end hook. This proves
// the bound is actually applied and that the message names the cause — an opaque "aborted"
// tells a caller nothing about whether to retry.
messagesHangMs = 0;
drainHangMs = 10_000;
const loud = await runCli(['inbox', 'kild-9', '--as', 'kild']);
expect(loud.exitCode).toBe(1);
expect(loud.stderr).toContain('timed out');

// ...and the same failure inside the hook is silence, because a hook may never block a turn.
const hook = await runCli(['inbox', 'kild-9', '--as', 'kild', '--format', 'claude-stop']);
expect(hook.stdout).toBe('');
expect(hook.exitCode).toBe(0);
drainHangMs = 0;
}, 30_000);

test('a hung engine is UNREACHABLE even when the interval outlasts the window', async () => {
// Confirmed regression: with --interval >= --timeout the first poll blocked for its own
// bound (10s against a 3s window), the deadline was then already gone, and it reported
// QUIET — asserting the engine answered and had nothing, after every request had failed.
// Two answers to one question: the request bound used the interval, the loop used the
// deadline. The bound now takes what remains, and "quiet" is refused unless the engine
// actually answered at least once.
messagesHangMs = 30_000;
const started = Date.now();
const hung = await runCli([
'watch',
'kild-9',
'--as',
'kild',
'--since',
'1',
'--timeout',
'3',
'--interval',
'10',
]);
const elapsed = Date.now() - started;
expect(hung.exitCode).toBe(3);
expect(hung.stderr).not.toContain('nothing new'); // never claim quiet on an unanswered engine
expect(elapsed).toBeLessThan(9_000); // and never blow through the window by 3x
messagesHangMs = 0;
}, 30_000);

test('the default backstop is applied when no caller supplies a signal', async () => {
// Removing the default left every test passing, because the two hang tests are protected by
// their own explicit signals and bypass it entirely. This one goes through `kild log`, which
// supplies none.
engineTimeoutMs = '600';
messagesHangMs = 5_000;
const hung = await runCli(['log', 'kild-9', '--since', '1']);
expect(hung.exitCode).toBe(1);
expect(hung.stderr).toContain('timed out');
messagesHangMs = 0;
engineTimeoutMs = '30000';
});

test('`kild show` reports an unreachable engine instead of an empty log', async () => {
// It swallowed every failure into `[]`. Invisible while a hung engine simply hung; a
// confident wrong answer the moment a timeout made the call return.
engineTimeoutMs = '600';
messagesHangMs = 5_000;
const shown = await runCli(['show', 'kild-9']);
expect(shown.exitCode).toBe(1);
expect(shown.stderr).toContain('timed out');
messagesHangMs = 0;
engineTimeoutMs = '30000';
}, 20_000);

test.each([
['abc', 'non-numeric'],
['', 'empty'],
['0', 'zero'],
['-5', 'negative'],
['30s', 'a unit suffix'],
])('KILD_ENGINE_TIMEOUT_MS=%s is refused (%s)', async (value) => {
// An unusable override must not degrade into a timeout of zero, which aborts every request
// the instant it is made and looks exactly like an engine refusing to talk. Nor into a
// cryptic RangeError from AbortSignal, which names neither the variable nor the fix.
engineTimeoutMs = value;
const bad = await runCli(['log', 'kild-9']);
expect(bad.exitCode).toBe(1);
expect(bad.stderr).toContain('KILD_ENGINE_TIMEOUT_MS');
// ...and as a FORMATTED CLI error, not a raw crash. Validating at module load threw before
// dispatch()'s handler existed, so every command died with a Bun stack trace naming a source
// line instead of the fix. Both exited 1 with the variable's name in the text, so asserting
// only that could not tell them apart — which is how this fix had no coverage at all.
expect(bad.stderr).not.toContain('Bun v');
expect(bad.stderr).not.toContain('function engineTimeoutMs');
engineTimeoutMs = '30000';
});

test('an engine failure whose text contains "timed out" is NOT reported as maybe-completed', async () => {
// `land`/`rm` report an unknown outcome on a real timeout, because a client abort does not
// stop server-side work. Deciding that by searching the message for "timed out" would
// misread a relayed git error as "your merge may have gone through" — and send an operator
// looking for a merge that never happened.
drainResponse = {
status: 409,
body: { error: 'git merge failed: operation timed out talking to the object store' },
};
const landed = await runCli(['land', 'kild-9', '--execute']);
expect(landed.exitCode).toBe(1);
expect(landed.stderr).toContain('timed out talking to the object store');
expect(landed.stderr).not.toContain('may still be completing');
withNoMail();
});

test('a timed-out land reports an UNKNOWN outcome, not a failure', async () => {
// A client abort does not reach the engine — no signal is passed server-side and no git
// command it runs is cancellable — so a timed-out merge may well have happened. Reporting
// it as a plain failure sends the operator to retry a merge that already landed. Reverting
// `mayHaveHappened` left the whole suite green, so this is the test that pins it.
engineTimeoutMs = '600';
landHangMs = 5_000;
const landed = await runCli(['land', 'kild-9', '--execute']);
expect(landed.exitCode).toBe(1);
expect(landed.stderr).toContain('may still be completing');
expect(landed.stderr).toContain('kild ls');
landHangMs = 0;
engineTimeoutMs = '30000';
}, 20_000);

test("a caller's own deadline is still a timeout, and says whose", async () => {
// The drain supplies its own 1.5s signal. Deciding "is this a timeout" by whether OUR signal
// fired reported the drain's deadline as a bare "The operation timed out." — naming neither
// the path nor the cause. The branch reads the signal's REASON instead, so both deadlines
// are timeouts and each says which one it was.
drainHangMs = 10_000;
const drained = await runCli(['inbox', 'kild-9', '--as', 'kild']);
expect(drained.exitCode).toBe(1);
expect(drained.stderr).toContain('timed out');
expect(drained.stderr).toContain("caller's own deadline");
expect(drained.stderr).toContain('/inbox/drain'); // the path, not an opaque abort
drainHangMs = 0;
}, 20_000);

test('`kild show` still works on an ORPHAN, whose log legitimately 404s', async () => {
// `GET /:id` answers for an orphan tree; `GET /:id/messages` 404s, because the registry's
// log map holds live and archived kilds only. Removing the blanket catch turned that
// disagreement into a crash with no output at all — against a case this command has an
// explicit display branch for.
drainRequests = [];
drainResponse = {
status: 200,
body: { id: 'live-demo', name: 'live-demo', orphan: true, agents: [] },
};
messagesResponse = { status: 404, body: { error: 'no such kild: live-demo' } };
const shown = await runCli(['show', 'live-demo']);
expect(shown.exitCode).toBe(0);
expect(shown.stdout).toContain('orphan tree');
messagesResponse = undefined;
withNoMail();
});

test('...but `kild show` still reports a non-404 log failure', async () => {
// Only "nothing was ever said here" is tolerated. An unreachable engine is not that.
drainResponse = { status: 200, body: { id: 'kild-9', name: 'k', agents: [] } };
messagesResponse = { status: 500, body: { error: 'registry exploded' } };
const shown = await runCli(['show', 'kild-9']);
expect(shown.exitCode).toBe(1);
expect(shown.stderr).toContain('registry exploded');
messagesResponse = undefined;
withNoMail();
});
72 changes: 67 additions & 5 deletions engine/src/cli.ts
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,8 @@ import {
attachAgent,
disposeKild,
drainInbox,
EngineHttpError,
EngineTimeout,
getKild,
kildMessages,
kildsStatus,
Expand All @@ -40,6 +42,7 @@ import {
WATCH_EXIT,
WATCH_POLL_MS,
WATCH_TOLERATED_FAILURES,
watchRequestTimeout,
watchSummary,
} from './kild/watch.ts';

Expand Down Expand Up @@ -392,6 +395,11 @@ async function kildWatch(idArg: string | undefined): Promise<never> {
return new Promise((resolve) => setTimeout(resolve, interval));
}
let failures = 0;
/** Whether the engine has answered even once. "Quiet" is a claim ABOUT the engine — that it
* responded and had nothing — so it cannot be reported by a watcher that never heard from
* it. Without this, a window that closed after nothing but failures exited 2, asserting the
* opposite of what was observed. */
let answered = false;

/**
* Ask once. Returns the batch, or null when the failure was tolerated and the caller should
Expand All @@ -407,8 +415,14 @@ async function kildWatch(idArg: string | undefined): Promise<never> {
since: number | undefined,
): Promise<Awaited<ReturnType<typeof kildMessages>> | null> {
try {
const batch = await kildMessages(kildId, since);
// The bound and the deadline are one question, asked once: never wait past the window.
const batch = await kildMessages(
kildId,
since,
watchRequestTimeout(interval, deadline - Date.now()),
);
failures = 0;
answered = true;
return batch;
} catch (err) {
if (++failures < WATCH_TOLERATED_FAILURES) return null;
Expand Down Expand Up @@ -436,7 +450,14 @@ async function kildWatch(idArg: string | undefined): Promise<never> {
function expire(): never {
// Report the window that actually elapsed. Printing the requested `--timeout` made the
// message a lie in exactly the case worth reporting — the one where waiting overran it.
console.error(`kild: nothing new in ${Math.round((Date.now() - started) / 1000)}s`);
const elapsed = Math.round((Date.now() - started) / 1000);
if (!answered) {
// Never heard from it. Saying "nothing new" would assert the engine responded and had
// nothing, which is the dead-looks-quiet conflation these codes exist to prevent.
console.error(`kild: engine did not answer within ${elapsed}s`);
process.exit(WATCH_EXIT.unreachable);
}
console.error(`kild: nothing new in ${elapsed}s`);
process.exit(WATCH_EXIT.quiet);
}

Expand Down Expand Up @@ -536,6 +557,34 @@ async function kildInbox(idArg: string | undefined): Promise<void> {
if (drained.messages.length === 0) console.error(drained.capped ? 'wake cap reached' : 'no mail');
}

/**
* Run a MUTATING call, and if it times out, say the outcome is unknown rather than failed.
*
* A client-side abort does not reach the engine: nothing here passes a signal into the
* server, and no git command it runs is cancellable, so a timed-out `land` may still merge
* and a timed-out `rm` may still remove the tree. Reporting that as a plain failure would be
* the worst kind of wrong — the operator retries a merge that already happened, or treats a
* deleted worktree as surviving.
*
* This is the same rule the disposal path already follows for its discard list: an
* unanswerable question is not an empty list, and it is not a `no` either.
*/
async function mayHaveHappened<T>(verb: string, call: () => Promise<T>): Promise<T> {
try {
return await call();
} catch (err) {
// Typed, not string-matched. An engine-side failure whose message merely CONTAINS "timed
// out" — a relayed git error, a 409 body — must never be reported as "this may have
// completed", because that sends an operator to check for a merge that never happened.
if (!(err instanceof EngineTimeout)) throw err;
throw new Error(
`${verb} timed out — the engine does NOT cancel work when the client gives up, so this ` +
`may still be completing or already done. Check with \`kild ls\` and git before ` +
`retrying. (${errText(err)})`,
);
}
}

/** `--since <seq>` as a message cursor. A non-number is a usage error, never "from the
* start" — a silently-ignored cursor replays the whole log as if it were new. */
function parseSince(): number | undefined {
Expand All @@ -562,7 +611,18 @@ async function kildShow(id: string): Promise<void> {
// The detail route is what decides whether this kild exists; a missing LOG does not mean a
// missing kild — an orphan tree is a kild with nothing ever said in it.
const kild = await getKild(id);
const messages = await kildMessages(id).catch(() => []);
// A missing LOG does not mean a missing kild. An ORPHAN is a tree git reports with no kild
// record, so `GET /:id` answers for it (resolveKild falls back to an orphan identity) while
// `GET /:id/messages` 404s — the registry's log map holds live and archived kilds only. Two
// routes, two answers to "does this exist", and this is the seam between them.
//
// So a 404 is tolerated and nothing else is. The blanket `.catch(() => [])` this replaced
// reported an empty log for EVERY failure, which hid an unreachable engine behind a kild
// that looked simply quiet.
const messages = await kildMessages(id).catch((err) => {
if (err instanceof EngineHttpError && err.status === 404) return [];
throw err;
});
const compact = compactLiveKilds([kild])[0];
if (!compact) throw new Error(`no such kild: ${id}`);

Expand Down Expand Up @@ -684,7 +744,7 @@ async function kildSpawn(id: string, handle: string): Promise<void> {
* `kild/<name>` branch always survives, which is why `--force` costs no commits.
*/
async function kildRm(id: string): Promise<void> {
const res = await disposeKild(id, values.force);
const res = await mayHaveHappened('rm', () => disposeKild(id, values.force));
if (json) return void console.log(JSON.stringify(res, null, 2));
console.log(res.message);
// An unanswerable question is not an empty list, and this is the one moment the operator
Expand All @@ -706,7 +766,9 @@ function formatLand(res: LandResponse): string {
* that touches nothing; with it, the branch is merged into its base in the project's main
* checkout and the merge sha is reported (and recorded on the kild for the ledger). */
async function kildLand(id: string): Promise<void> {
const res = values.execute ? await landKild(id) : await landPreview(id);
const res = values.execute
? await mayHaveHappened('land', () => landKild(id))
: await landPreview(id);
if (json) return void console.log(JSON.stringify(res, null, 2));
console.log(formatLand(res));
if (res.collides.length > 0) console.error(`collides: ${res.collides.join(', ')}`);
Expand Down
Loading
Loading