From ffa48ba5382102ea65feef05fcbe22078db06088 Mon Sep 17 00:00:00 2001 From: Jack Zhuang <50353452+hotlong@users.noreply.github.com> Date: Tue, 29 Sep 2026 07:05:42 +0800 Subject: [PATCH] test(create-objectstack): boot the scaffold-e2e probe blocks on a HELD port, and show what a block said when it fails The boot-and-probe suite rewrote each block's port to one an advisory probe had just found free (`pickFreePort(38700)` / `(38900)`), let go of it, and the `os start` stub then waited out its 1.2s boot delay before binding. That port sits inside `ip_local_port_range`, where the kernel also hands out source ports for outbound connections, so under a loaded shard the stub's bind could lose the number and the block exited 1 on its liveness check about two seconds in. The assertion printed nothing the block had said, so its exit path could only be inferred. The port now comes from the kernel (`listen(0)`) in a holder child that keeps it bound with SO_REUSEPORT. The `os start` and container stubs bind the same port with the same flag and end the holder once their own listener is up, so the port is bound at every instant from the kernel's answer to our server's bind: no outbound connect() or other listen(0) can be given it, and any other binder is refused. The holder resets connections, so the block's pre-flight still reads it as nothing serving, and it proves the port is joinable before it announces it, so a flag the platform ignored fails there, by name. Every assertion on a block's exit status or duration now carries the block's own output as its failure message. Pins: the two `os start` blocks run on the handed-over port (the stub names the port it bound), and a deliberate occupier aimed at that port is refused. Claude-Session: https://claude.ai/code/session_local_1d2a197c-c20e-4e90-9be8-413d4d432289 Co-authored-by: Claude --- .../src/scaffold-e2e-boot-probe.test.ts | 289 +++++++++++++----- 1 file changed, 220 insertions(+), 69 deletions(-) diff --git a/packages/create-objectstack/src/scaffold-e2e-boot-probe.test.ts b/packages/create-objectstack/src/scaffold-e2e-boot-probe.test.ts index 9129d5f471c..bc214f5497c 100644 --- a/packages/create-objectstack/src/scaffold-e2e-boot-probe.test.ts +++ b/packages/create-objectstack/src/scaffold-e2e-boot-probe.test.ts @@ -68,12 +68,22 @@ // listening and nothing was checked. // // One substitution is NOT a stub: the port literal is rewritten to a per-run -// free port before the script runs, so this test cannot collide with a -// concurrent agent in the same container — which would be a poor look in this -// file of all files. The literal is deliberately not the contract (see the -// workflow comment: every `runs-on:` in this repo is `ubuntu-latest`, one VM per -// job, so the fixed ports stay); the contract is what the loop accepts and -// refuses, and that is port-independent. +// port before the script runs, so this test cannot collide with a concurrent +// agent in the same container — which would be a poor look in this file of all +// files. The literal is deliberately not the contract (see the workflow +// comment: every `runs-on:` in this repo is `ubuntu-latest`, one VM per job, so +// the fixed ports stay); the contract is what the loop accepts and refuses, and +// that is port-independent. +// +// ⛔ That per-run port is HELD, never merely probed. The kernel assigns it +// (`listen(0)`) to a holder process that keeps it bound until the server the +// block boots has bound it too — `portHolder()` below. The advisory probe it +// replaced tested a port free and let go of it, and the stub then waited out +// its boot delay before binding: over a second, on a port inside +// `ip_local_port_range`, which is also where the kernel draws source ports for +// OUTBOUND connections. A lost race there reads exactly like the stub's own +// refusal — the block exits 1 on its liveness check about two seconds in — so +// every assertion on a block's exit status also carries what the block said. // // Deliberately NOT asserted: that `docker run` refuses a duplicate `--name` and // a taken `-p` host port. That claim is docker's documented behaviour and it is @@ -86,7 +96,6 @@ import { describe, it, expect } from 'vitest'; import { execFileSync, spawn } from 'node:child_process'; import fs from 'node:fs'; -import net from 'node:net'; import os from 'node:os'; import path from 'node:path'; import { fileURLToPath } from 'node:url'; @@ -143,30 +152,22 @@ function stepScript(stepName: string): string { return `${body.join('\n')}\n`; } -/** A TCP port free right now, searching upward from `base`. Advisory only. */ -async function pickFreePort(base: number): Promise { - const isFree = (port: number) => - new Promise((resolve) => { - const probe = net.createServer(); - probe.once('error', () => resolve(false)); - probe.once('listening', () => probe.close(() => resolve(true))); - probe.listen(port); - }); - for (let port = base; port < base + 400; port += 1) { - if (await isFree(port)) return port; - } - throw new Error(`no free TCP port in [${base}, ${base + 400})`); -} - /** * Stands in for `os start --port N` with the semantics MEASURED above: a busy * port is REFUSED (never shifted), and the refusal arrives after a boot delay, * because that delay is what let the pre-fix loop accept a neighbour while our * own process was still alive and undecided. + * + * Handed a port holder (`STUB_PORT_HOLDER_PID`, see `portHolder()`), it binds + * with `reusePort` — joining the holder's binding instead of racing it — and + * ends the holder once its own listener is up. That is the whole hand-over; + * a port held by anything else is still refused, exactly as `os start` refuses + * it. Its answers name the port it bound, so a run can prove where it served. */ const OS_START_STUB = ` const http = require('node:http'); const port = Number(process.argv[2]); +const holder = Number(process.env.STUB_PORT_HOLDER_PID || '0'); setTimeout(() => { if (process.env.OS_STUB_DIE_ON_BOOT === '1') { console.log(' boot failed: artifact could not be read'); @@ -174,7 +175,7 @@ setTimeout(() => { } const server = http.createServer((req, res) => { res.writeHead(200, { 'content-type': 'application/json' }); - res.end(JSON.stringify({ iam: 'OURS', url: req.url })); + res.end(JSON.stringify({ iam: 'OURS', port: server.address().port, url: req.url })); }); server.once('error', (err) => { if (err.code === 'EADDRINUSE') { @@ -184,7 +185,10 @@ setTimeout(() => { } throw err; }); - server.listen(port); + server.listen({ port, reusePort: holder > 0 }, () => { + if (holder > 0) process.kill(holder, 'SIGKILL'); + console.log(' listening on ' + port + (holder > 0 ? ', taken over from its holder' : '')); + }); }, Number(process.env.OS_STUB_BOOT_MS || '1200')); `; @@ -213,10 +217,14 @@ exec "$STUB_NODE" "$STUB_DIR/os-start.js" "$PORT" * simply never became healthy. That ordering is the point: a container that * dies after already answering is not a case the loop can get wrong, because * the loop has already broken out of it. + * + * Takes a held host port over the way `OS_START_STUB` does: bind with + * `reusePort`, then end the holder. */ const CONTAINER_STUB = ` const http = require('node:http'); const dieMs = Number(process.env.STUB_CONTAINER_DIE_MS || '0'); +const holder = Number(process.env.STUB_PORT_HOLDER_PID || '0'); if (dieMs > 0) { setTimeout(() => { console.log('container crashed on purpose'); process.exit(1); }, dieMs); } else { @@ -225,7 +233,9 @@ if (dieMs > 0) { res.writeHead(200, { 'content-type': 'application/json' }); res.end(JSON.stringify({ iam: 'OUR-CONTAINER', url: req.url })); }) - .listen(Number(process.argv[2])); + .listen({ port: Number(process.argv[2]), reusePort: holder > 0 }, () => { + if (holder > 0) process.kill(holder, 'SIGKILL'); + }); } `; @@ -268,7 +278,9 @@ if (cmd === 'run') { process.stdout.write(String(child.pid) + '\\n'); process.exit(0); })); - probe.listen(Number(hostPort)); + // A host port handed over by the harness's holder is joined, not refused; + // one held by anything else still fails the run, as docker's -p does. + probe.listen({ port: Number(hostPort), reusePort: Number(process.env.STUB_PORT_HOLDER_PID || '0') > 0 }); } else if (cmd === 'inspect') { let st; try { st = JSON.parse(fs.readFileSync(at(argv[argv.length - 1]), 'utf8')); } catch { process.exit(1); } @@ -356,6 +368,21 @@ function runBlock(h: Harness, script: string): Ran { } } +/** + * What a block said, as the failure message of an assertion on its run. + * + * A bare `expected 1 to be +0` names no exit path: the pre-flight refusal, the + * liveness exit and the timeout all end in `exit 1`, and the block's own + * `::error::` line and the server log it dumps are what tell them apart. So they + * travel with the verdict instead of being left for a later `toContain` to show. + */ +function said(r: Ran): string { + return ( + `the block exited ${r.status} after ${r.seconds}s — its own output:\n` + + `--- block output ---\n${r.out.trim() || '(nothing: the block wrote neither stdout nor stderr)'}` + ); +} + /** * A neighbouring run's healthy server, answering everything with 200. * @@ -382,12 +409,13 @@ function runBlock(h: Harness, script: string): Ran { * and each one is a reason raising the budget could not have repaired it: * * * The failure reproduces with a perfectly healthy child on a port - * `pickFreePort` had just approved. `node` refused the bind with + * `pickFreePort` — the advisory probe this file then carried — had just + * approved. `node` refused the bind with * `listen EADDRINUSE 0.0.0.0:39510` while `ss -ltn` showed NO listener on * 39510 — the port was the local ephemeral port of an unrelated outbound * ESTABLISHED connection belonging to another process in the container. - * `pickFreePort` proves a port is bindable at the instant it asks; its own - * docblock says "advisory only", and this is what that costs. Reproduced + * `pickFreePort` proved a port bindable at the instant it asked; its own + * docblock said "advisory only", and this is what that costs. Reproduced * 3/3 against the pre-fix helper: 20761ms, 20930ms, 20886ms, every one of * them reporting `the neighbour never came up on port 39510` and nothing * else. @@ -407,13 +435,15 @@ function runBlock(h: Harness, script: string): Ran { * decides the others — which is why this file still names no budget. * * The child also asks the KERNEL for the port (`listen(0)`) and reports back - * what it was given, so the window `pickFreePort` leaves open is not merely + * what it was given, so the window an advisory probe leaves open is not merely * reported on, it is closed: the neighbour holds the binding continuously from - * before its caller learns the number. `port` is for the controls, which need - * to aim a second neighbour at a port that is genuinely taken. + * before its caller learns the number. `port` is for the controls and the + * occupier pins, which need to aim a second child at a port that is genuinely + * taken. `portHolder()` is this same instrument with a child that serves + * nothing. */ interface NeighbourOptions { - /** Bind this port instead of asking the kernel. Controls only. */ + /** Bind this port instead of asking the kernel. Controls and occupiers only. */ port?: number; /** Replace the child's program text — the controls hand in broken ones. */ stub?: string; @@ -421,11 +451,20 @@ interface NeighbourOptions { exec?: string; /** The backstop, ⛔ not a budget: every other failure mode reports at once. */ timeoutMs?: number; + /** + * Whether "up" means ANSWERED (a 200 at the probe URL) or only ANNOUNCED. + * `false` is for the port holder, which answers nothing by design. + */ + answers?: boolean; + /** Who a diagnosis names. */ + role?: string; } interface Neighbour { /** The port the child really bound, read back from the child. */ port: number; + /** The child's pid — what the stubs are handed to end a port holder. */ + pid: number; stop: () => void; } @@ -435,6 +474,8 @@ async function neighbour(options: NeighbourOptions = {}): Promise { stub = NEIGHBOUR_STUB, exec = process.execPath, timeoutMs = 30_000, + answers = true, + role = 'the neighbour', } = options; const started = Date.now(); const child = spawn(exec, ['-e', stub], { @@ -462,8 +503,8 @@ async function neighbour(options: NeighbourOptions = {}): Promise { const where = requested === 0 ? 'on a kernel-assigned port' : `on port ${requested}`; const diagnosis = (headline: string) => new Error( - `the neighbour never came up ${where} after ${Date.now() - started}ms: ${headline}\n` + - `--- neighbour output ---\n${ + `${role} never came up ${where} after ${Date.now() - started}ms: ${headline}\n` + + `--- its own output ---\n${ state.output.trim() || '(nothing: the child wrote neither stdout nor stderr)' }`, ); @@ -505,6 +546,13 @@ async function neighbour(options: NeighbourOptions = {}): Promise { } finally { clearTimeout(backstop); } + // A child that announced was spawned, so it has a pid; say so if it does not. + const pid = child.pid; + if (pid === undefined) { + stop(); + throw diagnosis(`it announced a listener on port ${bound} and has no pid`); + } + if (!answers) return { port: bound, pid, stop }; // Announced is not answered. This is the one window the backstop really // guards, and the only one where waiting longer is not obviously wrong. @@ -521,7 +569,7 @@ async function neighbour(options: NeighbourOptions = {}): Promise { try { const res = await fetch(url, { signal: AbortSignal.timeout(1_000) }); await res.arrayBuffer(); - if (res.ok) return { port: bound, stop }; + if (res.ok) return { port: bound, pid, stop }; last = `HTTP ${res.status}`; } catch (err) { last = err instanceof Error ? `${err.name}: ${err.message}` : String(err); @@ -558,6 +606,57 @@ server.listen(Number(process.env.NEIGHBOUR_PORT || '0'), () => { }); `; +/** + * The port holder's program. It speaks the neighbour's announce protocol, so + * `neighbour()` spawns it, reads its port back and diagnoses it unchanged. + * + * It resets every connection rather than leaving it unanswered: the block's + * pre-flight `curl -fsS` must fail at once, exactly as against a closed port, + * and that curl carries no `--max-time`, so a holder that accepted and never + * answered would hang the block. And before announcing, it binds a second + * `reusePort` socket to its own port and lets go of it: a hand-over the stubs + * could not complete fails HERE, naming the flag, and not later in the block as + * `Port N is already in use` — the one line a lost port race also prints. + */ +const PORT_HOLDER_STUB = ` +const net = require('node:net'); +const say = (line, then) => process.stdout.write(line + '\\n', then); +const fail = (why) => say('NEIGHBOUR-LISTEN-ERROR ' + why, () => process.exit(1)); +const holder = net.createServer((socket) => socket.resetAndDestroy()); +holder.once('error', (err) => fail((err && err.code) || String(err))); +holder.listen({ port: 0, reusePort: true }, () => { + const port = holder.address().port; + const joiner = net.createServer(); + joiner.once('error', (err) => fail('reusePort-not-in-effect:' + ((err && err.code) || String(err)))); + joiner.listen({ port, reusePort: true }, () => joiner.close(() => say('NEIGHBOUR-LISTENING ' + port))); +}); +`; + +/** + * A port for a block to boot on, HELD from the kernel's answer until the + * server that block starts has bound it — never "free right now" and let go. + * + * The holder asks the kernel for a port (`listen(0)`) with `SO_REUSEPORT` set + * and keeps that listener open. Handed its pid (`STUB_PORT_HOLDER_PID`), the + * stubs standing in for `os start` and for the container bind the same port + * with the same flag — joining the holder's binding rather than racing for the + * number — and end the holder once their own listener is up. The port is bound + * at every instant between the two, so for the whole of the stub's boot delay: + * + * * no outbound connection can be given it as a source port — the kernel's + * connect() skips a port something has explicitly bound, which is what an + * advisory probe inside `ip_local_port_range` could never rule out; + * * no other `listen(0)` can be assigned it; + * * any other binder — anything without `SO_REUSEPORT`, i.e. anything that + * is not this harness — is refused with EADDRINUSE instead of taking it. + * + * Linux-only, like the suite it serves (`RUNNABLE`): libuv answers ENOTSUP to + * `reusePort` on macOS. Stopping it after a stub has ended it is harmless. + */ +function portHolder(): Promise { + return neighbour({ stub: PORT_HOLDER_STUB, answers: false, role: 'the port holder' }); +} + function curlBody(url: string): string { try { return execFileSync('curl', ['-fsS', url], { encoding: 'utf8' }).trim(); @@ -586,40 +685,64 @@ describe.skipIf(!RUNNABLE)('[#9779] scaffold-e2e.yml boot-and-probe blocks asser // spelling the loop probes, or "refused" below proves nothing. expect(curlBody(`http://localhost:${port}/api/v1/health`)).toContain('NEIGHBOUR'); const r = runBlock(harness(), script); - expect(r.status).not.toBe(0); + expect(r.status, said(r)).not.toBe(0); expect(r.out).toContain('already serving'); // The whole card: it must NOT have gone on to assert /api/v1/ready // against the neighbour, which is what the pre-fix block did (and // printed, since `curl -fsS .../ready` echoes the body). expect(r.out).not.toContain('"iam":"NEIGHBOUR"'); // And it says so at once — the answer never depended on waiting. - expect(r.seconds).toBeLessThan(20); + expect(r.seconds, said(r)).toBeLessThan(20); } finally { n.stop(); } }, 120_000); it('accepts the server it booted itself, and probes THAT one', async () => { - const port = await pickFreePort(38700); - const script = stepScript(step).replaceAll('8080', String(port)); - const r = runBlock(harness(), script); - expect(r.status).toBe(0); - // `curl -fsS .../api/v1/ready` echoes the body, so the run says out loud - // whose app it asserted on. This is the guard that keeps the case above - // from passing for the trivial reason that the block always fails. - expect(r.out).toContain('"iam":"OURS"'); + const held = await portHolder(); + try { + const port = held.port; + // The holder serves nothing, so the pre-flight reads it as a closed + // port — or "accepted" below could mean the pre-flight never ran. + expect(curlBody(`http://localhost:${port}/api/v1/health`)).toBe('NONE'); + // And it really HOLDS the port: a deliberate occupier aimed at it is + // refused. An advisory probe let go of the number it approved, so an + // occupier arriving before the stub's bind took it, and the block + // then died on its liveness check with `Port N is already in use`. + const occupier = await failedNeighbour({ port, role: 'the occupier' }); + expect(occupier.message).toContain('its listener refused to bind: EADDRINUSE'); + + const script = stepScript(step).replaceAll('8080', String(port)); + const r = runBlock(harness({ STUB_PORT_HOLDER_PID: String(held.pid) }), script); + expect(r.status, said(r)).toBe(0); + // `curl -fsS .../api/v1/ready` echoes the body, so the run says out loud + // whose app it asserted on. This is the guard that keeps the case above + // from passing for the trivial reason that the block always fails. + expect(r.out).toContain('"iam":"OURS"'); + // ...and where: the stub names the port it bound, the handed-over one. + expect(r.out).toContain(`"port":${port},`); + } finally { + held.stop(); + } }, 120_000); it('fails fast, and says why, when the server it started exits', async () => { - const port = await pickFreePort(38700); - const script = stepScript(step).replaceAll('8080', String(port)); - const r = runBlock(harness({ OS_STUB_DIE_ON_BOOT: '1' }), script); - expect(r.status).not.toBe(0); - expect(r.out).toContain('exited before becoming healthy'); - // The server log is dumped, so the reason is in the run's own output. - expect(r.out).toContain('artifact could not be read'); - // The pre-fix loop reached its 60s ceiling before saying anything. - expect(r.seconds).toBeLessThan(30); + const held = await portHolder(); + try { + const script = stepScript(step).replaceAll('8080', String(held.port)); + const r = runBlock( + harness({ OS_STUB_DIE_ON_BOOT: '1', STUB_PORT_HOLDER_PID: String(held.pid) }), + script, + ); + expect(r.status, said(r)).not.toBe(0); + expect(r.out).toContain('exited before becoming healthy'); + // The server log is dumped, so the reason is in the run's own output. + expect(r.out).toContain('artifact could not be read'); + // The pre-fix loop reached its 60s ceiling before saying anything. + expect(r.seconds, said(r)).toBeLessThan(30); + } finally { + held.stop(); + } }, 120_000); }); } @@ -628,22 +751,33 @@ describe.skipIf(!RUNNABLE)('[#9779] scaffold-e2e.yml boot-and-probe blocks asser const step = 'Docker build and run (scaffolded Dockerfile)'; it('stops polling once its own container has exited, instead of waiting out the timeout', async () => { - const port = await pickFreePort(38900); - const script = stepScript(step).replaceAll('18080', String(port)); - const r = runBlock(harness({ STUB_CONTAINER_DIE_MS: '1500' }), script); - expect(r.status).not.toBe(0); - expect(r.out).toContain('no longer running'); - // Vacuity guard: the container really did start and then die, rather than - // never having run at all — `docker logs` carries its own last words. - expect(r.out).toContain('container crashed on purpose'); - expect(r.seconds).toBeLessThan(30); + const held = await portHolder(); + try { + const script = stepScript(step).replaceAll('18080', String(held.port)); + const r = runBlock( + harness({ STUB_CONTAINER_DIE_MS: '1500', STUB_PORT_HOLDER_PID: String(held.pid) }), + script, + ); + expect(r.status, said(r)).not.toBe(0); + expect(r.out).toContain('no longer running'); + // Vacuity guard: the container really did start and then die, rather than + // never having run at all — `docker logs` carries its own last words. + expect(r.out).toContain('container crashed on purpose'); + expect(r.seconds, said(r)).toBeLessThan(30); + } finally { + held.stop(); + } }, 120_000); it('passes while its container stays up', async () => { - const port = await pickFreePort(38900); - const script = stepScript(step).replaceAll('18080', String(port)); - const r = runBlock(harness(), script); - expect(r.status).toBe(0); + const held = await portHolder(); + try { + const script = stepScript(step).replaceAll('18080', String(held.port)); + const r = runBlock(harness({ STUB_PORT_HOLDER_PID: String(held.pid) }), script); + expect(r.status, said(r)).toBe(0); + } finally { + held.stop(); + } }, 120_000); }); }); @@ -669,7 +803,7 @@ async function failedNeighbour( if (came) { came.stop(); throw new Error( - `this control is vacuous: the neighbour was supposed to fail and it came up on port ${came.port}`, + `this control is vacuous: ${options.role ?? 'the neighbour'} was supposed to fail and it came up on port ${came.port}`, ); } return { @@ -756,4 +890,21 @@ describe.skipIf(!RUNNABLE)('[#19424] the neighbour harness says WHY it did not c expect(message).toContain('ENOENT'); expect(seconds).toBeLessThan(10); }, 60_000); + + it('names reusePort when the port holder hands out a port nothing else can join', async () => { + // The holder with its own flag taken away: the stubs could not take such a + // port over, and the holder must say so before anyone is handed it. + const unjoinable = PORT_HOLDER_STUB.replace('{ port: 0, reusePort: true }', '{ port: 0 }'); + // Guard the mutation itself: an anchor that matched nothing would run the + // real holder, and the case would then fail for a reason it never names. + expect(unjoinable).not.toBe(PORT_HOLDER_STUB); + const { message, seconds } = await failedNeighbour({ + stub: unjoinable, + answers: false, + role: 'the port holder', + }); + expect(message).toContain('the port holder never came up'); + expect(message).toContain('its listener refused to bind: reusePort-not-in-effect:EADDRINUSE'); + expect(seconds).toBeLessThan(10); + }, 60_000); });