From cd7932a42b816802a68c743076662d02af4134a5 Mon Sep 17 00:00:00 2001 From: Alain Schlesser Date: Fri, 16 Oct 2026 18:46:47 +0200 Subject: [PATCH 1/2] test(ui-server): control primary boot probe deadlines --- docs/process/test-waits.md | 23 +- .../tests/boot-probe-deadline.test.ts | 312 +++++++++++++++++- 2 files changed, 312 insertions(+), 23 deletions(-) diff --git a/docs/process/test-waits.md b/docs/process/test-waits.md index c694f893f..6b3a4a395 100644 --- a/docs/process/test-waits.md +++ b/docs/process/test-waits.md @@ -396,13 +396,22 @@ failed cases, repeated controls and unexecuted paths remain distinguishable. The observations separate several temporal contracts: -- The native boot-probe suite keeps thirteen real process-deadline cases. Its - existing lower oracle is 4950 ms for a 5000 ms deadline, with a 1500 ms - settlement margin for loaded scheduling. The eight-second fixture holds do - not run to completion. These bounds explain the present 66.73 second command; - they do not prove that five seconds of wall time is necessary to test every - deadline branch. A clock replacement still needs actual registered callbacks, - real process termination, ineffective-killer behavior and cleanup witnesses. +- The boot-probe suite preserves thirteen subprocess scenarios. The unwrapped + target and both hung-helper cases retain native 4950–6500 ms elapsed proof. + Ten other cases capture the actual source-owned 5000 ms primary callback; + after real version output, subsequent pending stdout/stderr reads and native + target readiness, 4999 ms cannot deliver it and 5000 ms delivers it once. + Their elapsed operand explicitly combines logical primary time and native + settlement, retaining the 1500 ms settlement allowance. Cleanup (250 ms), + helper cleanup (200 ms), signals, pipes and subprocess exits remain native. + Inherited-pipe readiness compares the live descendant's actual endpoints + with the exited parent's endpoints. Successful exit/EOF proves cancellation; + assertion and actual disappearance-failure witnesses prove pending-work + settlement and complete descriptor restoration. Eight-second fixture holds + end in owned cleanup. Historical 66.73-second measurements describe the + original native file; delivery measurements and fault receipts belong to + [#1939](https://github.com/schlessera/brain-kit/issues/1939). They do not + resolve the independent historical helper-PID investigation in #1310. - Seven stale-write watchdogs requested 20000 ms; none fired, and all seven were cleared after roughly 329–357 ms. A supplemental HTTP observation recorded four 3000 ms watchdogs, also cleared without firing. These registration-to-clear diff --git a/packages/ui-server/tests/boot-probe-deadline.test.ts b/packages/ui-server/tests/boot-probe-deadline.test.ts index e1c0c18f8..c75c005c0 100644 --- a/packages/ui-server/tests/boot-probe-deadline.test.ts +++ b/packages/ui-server/tests/boot-probe-deadline.test.ts @@ -3,6 +3,7 @@ import { afterEach, describe, expect, test } from "bun:test"; import { chmodSync, existsSync, mkdirSync, mkdtempSync, readFileSync, readlinkSync, rmSync, writeFileSync } from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; +import { probeVersionCommand } from "../../ui-sdk/src/server/version-probe"; import { probeClaudeRuntime } from "../../ui-backend-claude/src/runtime-probe"; import { probeBrainCliVersion } from "../src/brain/client"; import { createHostBoundary } from "../src/brain/host-boundary"; @@ -10,7 +11,7 @@ import { createRecordingObservability } from "../src/observability"; const dirs: string[] = []; const inheritedDirs = new Set(); -afterEach(async () => { +async function cleanupFixtures(): Promise { const errors: unknown[] = []; for (const dir of dirs.splice(0)) { try { @@ -27,6 +28,12 @@ afterEach(async () => { rmSync(dir, { recursive: true, force: true }); } if (errors.length) throw new AggregateError(errors, "Inherited-pipe fixture cleanup failed"); +} +afterEach(async () => { + const active = controller; + controller = undefined; + try { if (active) await active.dispose(cleanupFixtures); else await cleanupFixtures(); } + finally { active?.assertRestored(); } }); function descendantPid(dir: string): number { @@ -43,13 +50,13 @@ function inheritedEndpoints(dir: string, pid: number): void { expect(readlinkSync(`/proc/${pid}/fd/${fd}`)).toBe(original); } } -async function cleanupDescendant(dir: string): Promise { +async function cleanupDescendant(dir: string, terminate: (pid: number) => void = pid => { process.kill(pid, "SIGKILL"); }): Promise { const pid = descendantPid(dir); const entry = `/proc/${pid}`; if (existsSync(entry)) { // Identify the actual inherited endpoints before signalling a non-child PID. inheritedEndpoints(dir, pid); - process.kill(pid, "SIGKILL"); + terminate(pid); } const until = Date.now() + 1_000; while (existsSync(entry) && Date.now() < until) await Bun.sleep(10); @@ -69,19 +76,232 @@ function fixture(output: string, body: string | ((dir: string) => string) = 'exe mkdirSync(bin, { recursive: true }); const path = executable(join(bin, "brain"), `echo $$ > '${dir}/probe.pid'\nprintf '%s\\n' \"$@\" > '${dir}/argv.log'\ntrap '' TERM\necho '${output}'\n${typeof body === "function" ? body(dir) : body}`); const wrapper = executable(join(dir, "wrapper"), 'exec "$@"'); - return { dir, path, wrapper } as { dir: string; path: string; wrapper?: string }; + return { dir, path, wrapper, output } as { dir: string; path: string; wrapper?: string; output: string }; +} +/** File-local pass-through observations; native controls never replace timers. */ +class PrimaryDeadline { + private restores: (() => void)[] = []; + private snapshots: [object, PropertyKey, PropertyDescriptor | undefined][] = []; + private processes: Bun.Subprocess[] = []; + private primary?: { callback: () => void; handle: ReturnType; cleared: boolean; fired: number }; + private timers: { owner: string; delay: number; fired: number; cleared: boolean; handle?: ReturnType }[] = []; + private nativeReads: Promise[] = []; + private pending = [0, 0]; + private reads = [0, 0]; + private eof = [false, false]; + private stdout = ""; + private target?: Bun.Subprocess; + private exited = false; + settled = false; + polls = 0; + work?: Promise; + private nativeSet = globalThis.setTimeout; + private nativeClear = globalThis.clearTimeout; + + constructor(private f: ReturnType, readonly controlled: boolean) { + try { + if (controlled) { + // Explicit owner/callback binding; a new owner fails closed. Duration + // alone cannot select this timer. Re-derive its line after harmless moves. + const lines = readFileSync(new URL("../../ui-sdk/src/server/version-probe.ts", import.meta.url), "utf8").split("\n"); + const site = lines.findIndex(line => line.includes("timer = setTimeout(() => resolve({ timedOut: true }), VERSION_PROBE_TIMEOUT_MS)")); + expect(site, "source-owned primary registration exists").toBeGreaterThan(0); + expect(lines.filter(line => line.includes("timer = setTimeout(")).length, "exactly one primary owner").toBe(1); + expect(lines[site - 1]).toContain("const deadline = new Promise"); + const owner = `version-probe.ts:${site + 1}:`; + this.replace(globalThis, "setTimeout", ((callback: (...args: unknown[]) => void, delay: number, ...args: unknown[]) => { + const stack = new Error().stack ?? ""; + const caller = stack.match(/\/ui-sdk\/src\/server\/((?:version-probe|exec-wrapper)\.ts:\d+:)/)?.[1]; + const fromPrimary = caller === owner; + const fromProbe = caller?.startsWith("version-probe.ts:") ?? false; + const fromHelper = caller?.startsWith("exec-wrapper.ts:") ?? false; + if (!fromPrimary && !fromProbe && !fromHelper) return this.nativeSet(callback, delay, ...args); + const record = { owner: fromPrimary ? "primary" : fromProbe ? "cleanup" : "helper", delay, fired: 0, cleared: false, handle: undefined as ReturnType | undefined }; + this.timers.push(record); + if (fromPrimary) { + expect(this.primary, "no extra primary registration").toBeUndefined(); + const handle = {} as ReturnType; + record.handle = handle; + this.primary = { callback: () => { record.fired++; callback(...args); }, handle, cleared: false, fired: 0 }; + return handle; + } + record.handle = this.nativeSet(() => { record.fired++; callback(...args); }, delay); + return record.handle; + }) as typeof setTimeout); + this.replace(globalThis, "clearTimeout", ((handle: ReturnType) => { + const record = this.timers.find(timer => timer.handle === handle); + if (record) record.cleared = true; + if (this.primary?.handle === handle) { this.primary.cleared = true; return; } + this.nativeClear(handle); + }) as typeof clearTimeout); + } + const spawn = Bun.spawn; + this.replace(Bun, "spawn", ((...args: Parameters) => { + const proc = Reflect.apply(spawn, Bun, args) as Bun.Subprocess; + this.processes.push(proc); + const argv = args[0]; + if (argv?.includes(f.path)) { + expect(this.target, "one actual version subprocess").toBeUndefined(); + this.target = proc; + void proc.exited.then(() => { this.exited = true; }); + if (controlled) for (const [index, stream] of [proc.stdout, proc.stderr].entries()) { + if (!stream || typeof stream === "number") throw new Error("native pipe required"); + const getReader = stream.getReader; + this.replace(stream, "getReader", (...readerArgs: unknown[]) => { + const reader = Reflect.apply(getReader, stream, readerArgs) as ReadableStreamDefaultReader; + const read = reader.read; + this.replace(reader, "read", () => { + this.reads[index]!++; + this.pending[index]!++; + const promise = read.call(reader); + this.nativeReads.push(promise); + void promise.then(chunk => { + this.pending[index]!--; + if (chunk.done) this.eof[index] = true; + else if (index === 0) this.stdout += new TextDecoder().decode(chunk.value); + }, () => { this.pending[index]!--; }); + return promise; // Actual native promise/result, never a replacement. + }); + return reader; + }); + } + } + return proc; + }) as typeof Bun.spawn); + } catch (error) { + for (const restore of this.restores.reverse()) restore(); + throw error; + } + } + + private replace(object: object, key: PropertyKey, value: unknown): void { + const descriptor = Object.getOwnPropertyDescriptor(object, key); + this.snapshots.push([object, key, descriptor]); + Object.defineProperty(object, key, { configurable: descriptor?.configurable ?? true, writable: true, enumerable: descriptor?.enumerable ?? false, value }); + this.restores.push(() => descriptor ? Object.defineProperty(object, key, descriptor) : Reflect.deleteProperty(object, key)); + } + track(work: Promise): Promise { + this.work = work; + void work.then(() => { this.settled = true; }, () => { this.settled = true; }); + return work; + } + async ready(): Promise { + const until = Date.now() + 2_000; + while (Date.now() < until) { + const pipeReady = this.stdout.includes(this.f.output) && this.reads[0]! >= 2 && this.pending.every(n => n === 1) && this.eof.every(done => !done); + let nativeReady = false; + if (this.target && pipeReady) { + if (inheritedDirs.has(this.f.dir)) { + if (this.exited && existsSync(join(this.f.dir, "descendant.owner.pid"))) { + const pid = descendantPid(this.f.dir); + inheritedEndpoints(this.f.dir, pid); + nativeReady = existsSync(`/proc/${pid}`); + } + } else { + try { nativeReady = readlinkSync(`/proc/${this.target.pid}/exe`).endsWith("/sleep"); } catch { /* Await native exec. */ } + } + } + if (pipeReady && nativeReady || this.settled) break; + this.polls++; + await Bun.sleep(1); + } + expect(this.settled, "native pending work cannot complete before deadline").toBe(false); + expect(this.stdout, "actual version bytes delivered").toContain(this.f.output); + expect(this.reads[0], "stdout entered its subsequent read").toBeGreaterThanOrEqual(2); + expect(this.pending, "both actual native reads remain pending").toEqual([1, 1]); + expect(this.eof, "neither native stream has reached EOF").toEqual([false, false]); + expect(this.target, "actual target was observed").toBeDefined(); + if (inheritedDirs.has(this.f.dir)) { + expect(this.exited, "inherited-pipe parent exited before advancement").toBe(true); + inheritedEndpoints(this.f.dir, descendantPid(this.f.dir)); + } else expect(readlinkSync(`/proc/${this.target!.pid}/exe`), "target completed trap/output and exec").toMatch(/\/sleep$/); + this.checkTimers(); + expect(this.primary, "actual primary registration captured").toBeDefined(); + } + advance(milliseconds: number): void { + const primary = this.primary; + expect(primary, "actual primary registration captured").toBeDefined(); + if (milliseconds >= 5_000 && !primary!.cleared && primary!.fired === 0) { + primary!.fired++; + primary!.callback(); + } + } + async deadline(): Promise { + await this.ready(); + this.advance(4_999); + await Promise.resolve(); + expect(this.primary!.fired, "no primary delivery at 4999").toBe(0); + expect(this.settled, "no probe completion at 4999").toBe(false); + const started = Date.now(); + this.advance(5_000); + this.advance(5_001); + expect(this.primary!.fired, "one primary delivery at 5000").toBe(1); + return started; + } + checkTimers(): void { + for (const timer of this.timers) expect(timer.delay, `${timer.owner} default milliseconds`).toBe(timer.owner === "primary" ? 5_000 : timer.owner === "cleanup" ? 250 : 200); + expect(this.timers.filter(timer => timer.owner === "primary").length, "one primary registration").toBe(1); + } + assertCancelled(): void { + expect(this.primary?.cleared, "successful completion clears primary").toBe(true); + this.advance(5_001); + expect(this.primary!.fired, "cancelled primary cannot deliver").toBe(0); + } + async dispose(cleanup: () => Promise): Promise { + // Cleanup failures cannot bypass joining native work or descriptor restoration. + try { await cleanup(); } + finally { + try { + for (const proc of this.processes) if (proc.exitCode === null) { + try { process.kill(-proc.pid, "SIGKILL"); } catch { /* Not a group leader. */ } + try { proc.kill("SIGKILL"); } catch { /* Already exited. */ } + } + await Promise.all(this.processes.map(proc => proc.exited)); + await this.work?.catch(() => {}); + await Promise.allSettled(this.nativeReads); + expect(this.pending, "all observed native read promises settled").toEqual([0, 0]); + for (const proc of this.processes) expect(existsSync(`/proc/${proc.pid}`), "owned direct child disappears after awaited exit").toBe(false); + if (this.controlled) { + this.checkTimers(); + for (const timer of this.timers) expect(timer.cleared || timer.fired === 1, `${timer.owner} settles natively or clears`).toBe(true); + } + } finally { + try { + for (const timer of this.timers) if (timer.owner !== "primary") this.nativeClear(timer.handle); + this.primary = undefined; + this.timers.length = 0; + } finally { for (const restore of this.restores.reverse()) restore(); } + } + } + } + assertRestored(): void { + expect(this.primary, "captured callback discarded").toBeUndefined(); + expect(this.timers, "owned timer handles discarded").toEqual([]); + for (const [object, key, descriptor] of this.snapshots) expect(Object.getOwnPropertyDescriptor(object, key), `restored ${String(key)} descriptor`).toEqual(descriptor); + expect(this.work === undefined || this.settled, "pending probe settled before restoration").toBe(true); + } } -async function probe(kind: "brain" | "claude", f: ReturnType, killer?: string) { +let controller: PrimaryDeadline | undefined; + +async function probe(kind: "brain" | "claude", f: ReturnType, killer?: string, controlled = true) { + const clock = new PrimaryDeadline(f, controlled); + controller = clock; const observability = createRecordingObservability(); let error: unknown; const started = Date.now(); - try { - // The host path of the probe, which a server takes where no governed turn can run (#1648). - if (kind === "brain") await probeBrainCliVersion(f.dir, observability.logger("brain"), { exec: { wrapper: f.wrapper, killer }, - boundary: createHostBoundary({ brainPath: f.dir, exec: { wrapper: f.wrapper, killer }, workerHost: () => ({ ok: false, requirement: "host-path fixture" }) }) }); - else await probeClaudeRuntime({ claudeCodePath: f.path, brainPath: f.dir, env: { PATH: process.env.PATH }, exec: { wrapper: f.wrapper, killer } }); - } catch (caught) { error = caught; } - return { elapsed: Date.now() - started, error, logs: observability.logs.find({ severity: "WARN" }) }; + const work = clock.track((async () => { + try { + // The host path of the probe, which a server takes where no governed turn can run (#1648). + if (kind === "brain") await probeBrainCliVersion(f.dir, observability.logger("brain"), { exec: { wrapper: f.wrapper, killer }, + boundary: createHostBoundary({ brainPath: f.dir, exec: { wrapper: f.wrapper, killer }, workerHost: () => ({ ok: false, requirement: "host-path fixture" }) }) }); + else await probeClaudeRuntime({ claudeCodePath: f.path, brainPath: f.dir, env: { PATH: process.env.PATH }, exec: { wrapper: f.wrapper, killer } }); + } catch (caught) { error = caught; } + })()); + const settlementStarted = controlled ? await clock.deadline() : started; + await work; + // Controlled elapsed is explicit logical primary time plus native settlement. + // The three native controls continue to measure the whole wall-clock interval. + return { elapsed: (controlled ? 5_000 : 0) + Date.now() - settlementStarted, error, logs: observability.logs.find({ severity: "WARN" }) }; } // 1.5 s permits loaded CI scheduling, not the fixture's eight-second lifetime. @@ -91,10 +311,10 @@ describe("boot probe deadline", () => { const f = fixture("0.42.0"); // Also exercise the ordinary, unwrapped CLI launch. delete f.wrapper; - const result = await probe("brain", f); + const result = await probe("brain", f, undefined, false); expect(result.logs.map(log => String(log.body)).join("\n")).toContain("within 5 s"); expect(result.elapsed).toBeGreaterThanOrEqual(4_950); - expect(result.elapsed).toBeLessThan(5_000 + SETTLEMENT_MARGIN_MS); + expect(result.elapsed).toBeLessThan(5_000 + SETTLEMENT_MARGIN_MS); }); for (const kind of ["brain", "claude"] as const) { for (const mode of ["missing", "failing", "hung", "noop"] as const) { @@ -102,7 +322,7 @@ describe("boot probe deadline", () => { const f = fixture(kind === "brain" ? "0.42.0" : "2.0.0 (Claude Code)"); const killer = mode === "missing" ? join(f.dir, "absent") : executable(join(f.dir, "killer"), mode === "failing" ? "exit 3" : mode === "noop" ? "exit 0" : `echo $$ > '${f.dir}/helper.pid'\nexec sleep 8`); - const result = await probe(kind, f, killer); + const result = await probe(kind, f, killer, mode !== "hung"); expect(result.elapsed).toBeGreaterThanOrEqual(4_950); expect(result.elapsed).toBeLessThan(5_000 + SETTLEMENT_MARGIN_MS); const text = kind === "brain" ? result.logs.map(log => String(log.body)).join("\n") : String(result.error); @@ -154,10 +374,70 @@ describe("boot probe deadline", () => { expect(existsSync(record)).toBe(true); expect(readFileSync(record, "utf8").trim()).toBe(`${pid} KILL alive`); expect(result.elapsed).toBeGreaterThanOrEqual(4_950); - expect(result.elapsed).toBeLessThan(5_000 + SETTLEMENT_MARGIN_MS); + expect(result.elapsed).toBeLessThan(5_000 + SETTLEMENT_MARGIN_MS); expect(readFileSync(join(f.dir, "argv.log"), "utf8").trim().split("\n")).toEqual(["--version"]); if (kind === "claude") expect(String(result.error)).toContain("within 5 s"); else expect(result.logs.map(log => String(log.body)).join("\n")).toContain("within 5 s"); }); } }); + + +describe("primary deadline ownership and restoration", () => { + test("successful native exit and EOF cancel the captured primary", async () => { + const f = fixture("0.42.0", "exit 0"); + delete f.wrapper; + const clock = new PrimaryDeadline(f, true); + controller = clock; + const result = await clock.track(probeVersionCommand([f.path, "--version"], { cwd: f.dir, env: { PATH: process.env.PATH }, exec: {} })); + expect(result.stdout.trim()).toBe("0.42.0"); + expect(result.exitCode).toBe(0); + expect(result.timedOut).toBe(false); + clock.checkTimers(); + clock.assertCancelled(); + }); + + test("cleanup disappearance failure still settles native work and restores descriptors", async () => { + const f = fixture("0.42.0", dir => + `stdout_endpoint=$(readlink /proc/$$/fd/1)\nstderr_endpoint=$(readlink /proc/$$/fd/2)\nprintf '%s\\n' "$stdout_endpoint" > '${dir}/1.endpoint'\nprintf '%s\\n' "$stderr_endpoint" > '${dir}/2.endpoint'\nsleep 8 &\necho $! > '${dir}/descendant.owner.pid'\necho $! > '${dir}/descendant.pid'\nexit 0`); + inheritedDirs.add(f.dir); + delete f.wrapper; + const clock = new PrimaryDeadline(f, true); + controller = clock; + clock.track(probeVersionCommand([f.path, "--version"], { cwd: f.dir, env: { PATH: process.env.PATH }, exec: {} })); + await clock.ready(); + expect(clock.settled, "failure witness starts with pending native work").toBe(false); + controller = undefined; + try { + // Leave the positively identified native descendant alive so the real + // disappearance assertion fails, rather than throwing a synthetic error. + await expect(clock.dispose(async () => { + try { await cleanupDescendant(f.dir, () => {}); } + finally { await cleanupDescendant(f.dir); } + })).rejects.toThrow("owned inherited-pipe descendant disappears after teardown"); + clock.assertRestored(); + expect(existsSync(`/proc/${descendantPid(f.dir)}`), "failure witness descendant finally disappeared").toBe(false); + } finally { await cleanupDescendant(f.dir); } + }); +}); + + +test("assertion failure joins pending native work before restoring the clock", async () => { + const f = fixture("0.42.0"); + delete f.wrapper; + const clock = new PrimaryDeadline(f, true); + controller = clock; + clock.track(probeVersionCommand([f.path, "--version"], { cwd: f.dir, env: { PATH: process.env.PATH }, exec: {} })); + let failure: unknown; + try { + await clock.ready(); + expect(clock.settled).toBe(false); + expect("deliberate assertion failure").toBe("passing control"); + } catch (error) { failure = error; } + finally { + controller = undefined; + try { await clock.dispose(cleanupFixtures); } + finally { clock.assertRestored(); } + } + expect(String(failure)).toContain("passing control"); +}); From a9a37261397e6d72760167e1c4e302ad24945f95 Mon Sep 17 00:00:00 2001 From: Alain Schlesser Date: Fri, 16 Oct 2026 19:12:48 +0200 Subject: [PATCH 2/2] test(ui-server): pin primary callback function ownership --- packages/ui-server/tests/boot-probe-deadline.test.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/ui-server/tests/boot-probe-deadline.test.ts b/packages/ui-server/tests/boot-probe-deadline.test.ts index c75c005c0..a6a132c1f 100644 --- a/packages/ui-server/tests/boot-probe-deadline.test.ts +++ b/packages/ui-server/tests/boot-probe-deadline.test.ts @@ -108,6 +108,8 @@ class PrimaryDeadline { expect(site, "source-owned primary registration exists").toBeGreaterThan(0); expect(lines.filter(line => line.includes("timer = setTimeout(")).length, "exactly one primary owner").toBe(1); expect(lines[site - 1]).toContain("const deadline = new Promise"); + const declarations = [...lines.slice(0, site).join("\n").matchAll(/\b(?:async )?function (\w+)\(/g)]; + expect(declarations.at(-1)?.[1], "actual primary callback owner").toBe("probeVersionCommand"); const owner = `version-probe.ts:${site + 1}:`; this.replace(globalThis, "setTimeout", ((callback: (...args: unknown[]) => void, delay: number, ...args: unknown[]) => { const stack = new Error().stack ?? "";