From f8cbd52c51ab9f99e2482a3bf7a6baf904ce83e7 Mon Sep 17 00:00:00 2001 From: Dimitri Kennedy Date: Mon, 19 Oct 2026 13:23:36 -0400 Subject: [PATCH] test: make process-timing tests tolerate host load Replace wall-clock guesses in three tests that failed intermittently on loaded hosts (HACK-1280): - The hanging-probe test now proves the kill only after the fake Docker publishes its pid through an atomic marker handshake. A probe timeout that fires before the handshake is inconclusive and escalates through named rungs (500 ms, 2 s, 8 s); every rung still requires the timeout refusal, and the reap check polls to a named deadline instead of a fixed 50 ms sleep. - The native compose ownership file sets a named 60 s default test budget: its scenarios launch many cold fake-Docker processes, and an expired test kept writing into the next test's shared root. - The initial forwarding trace test uses named bounds for each forwarded command (30 s) and for the test (150 s) instead of 3 s and 5 s. No product timeout or assertion changes. Refs HACK-1280 Co-Authored-By: Claude Opus 5.5 --- tests/native-compose-ownership.test.ts | 97 ++++++-- ...ative-process-policy-initial-trace.test.ts | 227 ++++++++++-------- 2 files changed, 201 insertions(+), 123 deletions(-) diff --git a/tests/native-compose-ownership.test.ts b/tests/native-compose-ownership.test.ts index 3e278349a..207d778f9 100644 --- a/tests/native-compose-ownership.test.ts +++ b/tests/native-compose-ownership.test.ts @@ -1,4 +1,11 @@ -import { afterEach, beforeEach, expect, spyOn, test } from "bun:test"; +import { + afterEach, + beforeEach, + expect, + setDefaultTimeout, + spyOn, + test, +} from "bun:test"; import { chmod, mkdtemp, readFile, rm } from "node:fs/promises"; import { tmpdir } from "node:os"; import { join } from "node:path"; @@ -26,6 +33,15 @@ const VOLUME = "hack-21-hack-fixture-instance-4-data"; const CREATED = "2026-10-08T00:00:00.123456789Z"; const REBORN = "2026-10-08T00:00:01.123456789Z"; const CANARY = "synthetic-private-env-image-canary"; +/** + * Every fake Docker query here is a cold Bun process, and one scenario can launch + * dozens. Bun's 5 s default then budgets host process start-up rather than the + * product, and an expired test keeps running against the next test's shared + * root. The probe keeps its own default (or test-chosen) timeout in every query. + */ +const FAKE_DOCKER_TEST_TIMEOUT_MS = 60_000; +setDefaultTimeout(FAKE_DOCKER_TEST_TIMEOUT_MS); + const options: NativeComposeOwnershipOptions = { composeProject: PROJECT, runtimeIdentity: PROJECT, @@ -50,7 +66,7 @@ beforeEach(async () => { await Bun.write( join(root, "docker"), `#!${process.execPath} -import {appendFileSync, existsSync, readFileSync, writeFileSync} from "node:fs"; +import {appendFileSync, existsSync, readFileSync, renameSync, writeFileSync} from "node:fs"; const root = ${JSON.stringify(root)}; const args = process.argv.slice(2); appendFileSync(root + "/commands", JSON.stringify(args) + "\\n"); @@ -59,10 +75,12 @@ const [kind, action] = args; if (!["container","volume","network"].includes(kind) || !["ls","inspect"].includes(action) || !args.includes("--format")) { writeFileSync(root + "/mutated", "unexpected engine mutation"); process.exit(99); } -if (fixture.mode === "hang") { writeFileSync(root + "/started", String(process.pid)); await Bun.sleep(60_000); } +// Handshake markers appear atomically: a reader never observes a partial pid. +const signal = (name, pid) => { writeFileSync(root + "/" + name + ".tmp", String(pid)); renameSync(root + "/" + name + ".tmp", root + "/" + name); }; +if (fixture.mode === "hang") { signal("started", process.pid); await Bun.sleep(60_000); } if (fixture.mode === "descendant") { const child = Bun.spawn([process.execPath, "-e", 'await Bun.sleep(60_000)'], {stdout: "inherit", stderr: "inherit"}); - writeFileSync(root + "/descendant", String(child.pid)); process.exit(0); + signal("descendant", child.pid); process.exit(0); } if (fixture.mode === "fail") { console.error(${JSON.stringify(CANARY)}); process.exit(23); } if (fixture.mode === "stderr-overflow") { await Bun.write(Bun.stderr, "x".repeat(17 * 1024)); process.exit(0); } @@ -1057,21 +1075,66 @@ test("inspect argv batching does not cap the number of owned resources", async ( ).toBeLessThanOrEqual(16 * 1024); } }); +/** + * Probe timeouts tried in order for one hanging fake Docker. The kill proof needs + * the fake Docker to publish its pid before the probe fires; on a loaded host a + * cold Bun start can exceed the fast rung. An attempt without that handshake is + * inconclusive (its process died before it could be observed) and escalates; it + * never counts as a pass. Every attempt still has to refuse with the timeout code. + * Both modes at every rung plus reaping stay within FAKE_DOCKER_TEST_TIMEOUT_MS. + */ +const HANG_PROBE_TIMEOUTS_MS = [500, 2000, 8000] as const; +/** Bound for the kernel to reap a SIGKILLed orphan after the probe refuses. */ +const HANG_REAP_DEADLINE_MS = 10_000; + +async function hangHandshakePid(marker: string): Promise { + if (!(await Bun.file(marker).exists())) { + return; + } + const pid = Number(await readFile(marker, "utf8")); + if (!(Number.isSafeInteger(pid) && pid > 1)) { + throw new Error(`Malformed ${marker} handshake`); + } + return pid; +} + +async function exitedWithin(pid: number, deadlineMs: number): Promise { + const deadline = Date.now() + deadlineMs; + while (true) { + try { + process.kill(pid, 0); + } catch { + return true; + } + if (Date.now() >= deadline) { + return false; + } + await Bun.sleep(10); + } +} + test("a real hanging process times out and its inherited-pipe descendant is killed", async () => { for (const mode of ["hang", "descendant"]) { - await prepare({ mode }); - await expectRefusal( - { ...options, timeoutMs: 500 }, - "E_NATIVE_COMPOSE_PROBE_TIMEOUT" - ); - const pid = Number( - await readFile( - join(root, mode === "hang" ? "started" : "descendant"), - "utf8" - ) - ); - await Bun.sleep(50); - expect(() => process.kill(pid, 0)).toThrow(); + const marker = join(root, mode === "hang" ? "started" : "descendant"); + let pid: number | undefined; + for (const timeoutMs of HANG_PROBE_TIMEOUTS_MS) { + await rm(marker, { force: true }); + await prepare({ mode }); + await expectRefusal( + { ...options, timeoutMs }, + "E_NATIVE_COMPOSE_PROBE_TIMEOUT" + ); + pid = await hangHandshakePid(marker); + if (pid !== undefined) { + break; + } + } + if (pid === undefined) { + throw new Error( + `Fake Docker never published its ${mode} pid before the longest probe timeout` + ); + } + expect(await exitedWithin(pid, HANG_REAP_DEADLINE_MS)).toBe(true); } }); test("abort before spawn and during a real read-only query refuses and reaps the child", async () => { diff --git a/tests/native-process-policy-initial-trace.test.ts b/tests/native-process-policy-initial-trace.test.ts index c9690bd5d..46685832f 100644 --- a/tests/native-process-policy-initial-trace.test.ts +++ b/tests/native-process-policy-initial-trace.test.ts @@ -105,121 +105,136 @@ test("initial trace accepts only exact ownership read protocols", () => { } }); -test("initial forwarding preserves bytes/exits but records no unknown output, args or stderr", async () => { - const root = await mkdtemp(join(tmpdir(), "process-initial-forwarding-")); - const previous = process.env.PATH; - const binary = join(root, "docker"); - const traceRoot = join(root, "trace"); - try { - await Bun.write( - binary, - `#!${process.execPath} --no-env-file +/** + * Each forwarded command cold-starts two Bun processes (the trace forwarder and + * the fake Docker). These bounds only stop a wedged child from hanging the run; + * exits, bytes and trace order are still asserted exactly. + */ +const FORWARDED_DOCKER_EXEC_TIMEOUT_MS = 30_000; +/** Four forwarded commands at their exec bound, plus trace reads and rewrites. */ +const INITIAL_FORWARDING_TEST_TIMEOUT_MS = 150_000; + +test( + "initial forwarding preserves bytes/exits but records no unknown output, args or stderr", + async () => { + const root = await mkdtemp(join(tmpdir(), "process-initial-forwarding-")); + const previous = process.env.PATH; + const binary = join(root, "docker"); + const traceRoot = join(root, "trace"); + try { + await Bun.write( + binary, + `#!${process.execPath} --no-env-file const args=process.argv.slice(2); await Bun.sleep(20); if(args[0]==="compose"){await Bun.write(Bun.stdout,"original compose bytes\\n");await Bun.write(Bun.stderr,${JSON.stringify(CANARY)});process.exit(17);} if(args[1]==="ls"){await Bun.write(Bun.stdout,"original list bytes\\n");process.exit(0);} await Bun.write(Bun.stdout,${JSON.stringify(CANARY)});await Bun.write(Bun.stderr,${JSON.stringify(CANARY)});process.exit(23); ` - ); - await chmod(binary, 0o700); - process.env.PATH = root; - const prepared = await prepareProcessPolicyInitialTrace({ - directory: traceRoot, - }); - const run = async (args: readonly string[]) => - await exec([join(traceRoot, "docker"), ...args], { - env: { PATH: prepared.path }, - stdin: "ignore", - timeoutMs: 3000, + ); + await chmod(binary, 0o700); + process.env.PATH = root; + const prepared = await prepareProcessPolicyInitialTrace({ + directory: traceRoot, + }); + const run = async (args: readonly string[]) => + await exec([join(traceRoot, "docker"), ...args], { + env: { PATH: prepared.path }, + stdin: "ignore", + timeoutMs: FORWARDED_DOCKER_EXEC_TIMEOUT_MS, + }); + expect(await run(list("container"))).toEqual({ + exitCode: 0, + stdout: "original list bytes\n", + stderr: "", }); - expect(await run(list("container"))).toEqual({ - exitCode: 0, - stdout: "original list bytes\n", - stderr: "", - }); - expect( - await run(["compose", "-p", project, "-f", CANARY, "up", "-d"]) - ).toEqual({ - exitCode: 17, - stdout: "original compose bytes\n", - stderr: CANARY, - }); - expect( - await run(["inspect", id, "--format", "{{json .Config.Env}}"]) - ).toEqual({ exitCode: 23, stdout: CANARY, stderr: CANARY }); - expect(await run(list("network"))).toEqual({ - exitCode: 0, - stdout: "original list bytes\n", - stderr: "", - }); - const trace = await readProcessPolicyInitialTrace(prepared.directory); - expect(trace.queries.map((row) => row.args)).toEqual([ - list("container"), - list("network"), - ]); - expect((trace.queries[0]?.startOrder ?? -1) < trace.upStartOrder).toBe( - true - ); - expect((trace.queries[1]?.startOrder ?? -1) > trace.upReapOrder).toBe(true); - for (const name of await readdir(prepared.directory)) { expect( - await Bun.file(join(prepared.directory, name)).text() - ).not.toContain(CANARY); - } - const journal = join(prepared.directory, "events.jsonl"); - const originalJournal = await Bun.file(journal).text(); - const second = trace.queries[1]; - const first = trace.queries[0]; - if (!(first && second)) { - throw new Error("Missing synthetic query pair"); - } - // Complete but overlapping original reads cannot be grouped into a faithful - // single-owner replay, even if every capsule and reply is still present. - const effect = originalJournal - .trimEnd() - .split("\n") - .filter( - (line) => !(line.includes(first.token) || line.includes(second.token)) + await run(["compose", "-p", project, "-f", CANARY, "up", "-d"]) + ).toEqual({ + exitCode: 17, + stdout: "original compose bytes\n", + stderr: CANARY, + }); + expect( + await run(["inspect", id, "--format", "{{json .Config.Env}}"]) + ).toEqual({ exitCode: 23, stdout: CANARY, stderr: CANARY }); + expect(await run(list("network"))).toEqual({ + exitCode: 0, + stdout: "original list bytes\n", + stderr: "", + }); + const trace = await readProcessPolicyInitialTrace(prepared.directory); + expect(trace.queries.map((row) => row.args)).toEqual([ + list("container"), + list("network"), + ]); + expect((trace.queries[0]?.startOrder ?? -1) < trace.upStartOrder).toBe( + true ); - const overlapping = [ - { token: first.token, event: "start" }, - { token: second.token, event: "start" }, - { token: first.token, event: "reap" }, - { token: second.token, event: "reap" }, - ].map((event) => JSON.stringify(event)); - await Bun.write(journal, `${[...overlapping, ...effect].join("\n")}\n`); - await expect( - readProcessPolicyInitialTrace(prepared.directory) - ).rejects.toThrow("trace unavailable"); - await Bun.write(journal, originalJournal.slice(0, -1)); - await expect( - readProcessPolicyInitialTrace(prepared.directory) - ).rejects.toThrow("trace unavailable"); - await Bun.write(journal, originalJournal); - expect( - (await readProcessPolicyInitialTrace(prepared.directory)).queries.map( - (row) => row.args - ) - ).toEqual([list("container"), list("network")]); - const row = trace.queries[0]; - if (!row) { - throw new Error("Missing synthetic trace"); + expect((trace.queries[1]?.startOrder ?? -1) > trace.upReapOrder).toBe( + true + ); + for (const name of await readdir(prepared.directory)) { + expect( + await Bun.file(join(prepared.directory, name)).text() + ).not.toContain(CANARY); + } + const journal = join(prepared.directory, "events.jsonl"); + const originalJournal = await Bun.file(journal).text(); + const second = trace.queries[1]; + const first = trace.queries[0]; + if (!(first && second)) { + throw new Error("Missing synthetic query pair"); + } + // Complete but overlapping original reads cannot be grouped into a faithful + // single-owner replay, even if every capsule and reply is still present. + const effect = originalJournal + .trimEnd() + .split("\n") + .filter( + (line) => !(line.includes(first.token) || line.includes(second.token)) + ); + const overlapping = [ + { token: first.token, event: "start" }, + { token: second.token, event: "start" }, + { token: first.token, event: "reap" }, + { token: second.token, event: "reap" }, + ].map((event) => JSON.stringify(event)); + await Bun.write(journal, `${[...overlapping, ...effect].join("\n")}\n`); + await expect( + readProcessPolicyInitialTrace(prepared.directory) + ).rejects.toThrow("trace unavailable"); + await Bun.write(journal, originalJournal.slice(0, -1)); + await expect( + readProcessPolicyInitialTrace(prepared.directory) + ).rejects.toThrow("trace unavailable"); + await Bun.write(journal, originalJournal); + expect( + (await readProcessPolicyInitialTrace(prepared.directory)).queries.map( + (row) => row.args + ) + ).toEqual([list("container"), list("network")]); + const row = trace.queries[0]; + if (!row) { + throw new Error("Missing synthetic trace"); + } + const reap = join(prepared.directory, `${row.token}.json.reap`); + const originalReap = await Bun.file(reap).text(); + await unlink(reap); + await expect( + readProcessPolicyInitialTrace(prepared.directory) + ).rejects.toThrow(); + await Bun.write(reap, originalReap); + await unlink(join(prepared.directory, `${row.token}.json.start`)); + await expect( + readProcessPolicyInitialTrace(prepared.directory) + ).rejects.toThrow(); + } finally { + restoreEnv("PATH", previous); + await rm(root, { recursive: true, force: true }); } - const reap = join(prepared.directory, `${row.token}.json.reap`); - const originalReap = await Bun.file(reap).text(); - await unlink(reap); - await expect( - readProcessPolicyInitialTrace(prepared.directory) - ).rejects.toThrow(); - await Bun.write(reap, originalReap); - await unlink(join(prepared.directory, `${row.token}.json.start`)); - await expect( - readProcessPolicyInitialTrace(prepared.directory) - ).rejects.toThrow(); - } finally { - restoreEnv("PATH", previous); - await rm(root, { recursive: true, force: true }); - } -}); + }, + INITIAL_FORWARDING_TEST_TIMEOUT_MS +); test("initial forwarding preserves a multicall Docker entry and refuses its replacement", async () => { const root = await mkdtemp(join(tmpdir(), "process-initial-entry-"));