Skip to content

Commit c27e160

Browse files
fix(create-objectstack): the boot-probe neighbour reports WHY it did not come up (#19429)
Fixes #19424 Clause-②: no ## The reading this starts from The boot-probe harness spawned its neighbour with `stdio: 'ignore'` and waited on 80 blind `curl` probes 0.25s apart — exactly 20s — through `execFileSync('bash', …, { stdio: 'ignore' })`, then threw naming only the port. Both ends discarded the evidence by construction, so the card's two same-run readings (`20999ms` red and `299ms` green, same titled assertion, same runner, seconds apart) were indistinguishable to a reader. A budget chosen against an unreadable failure is a guess, so this PR chooses none. ⛔ **What this PR does not claim.** Not that the CI child died, not that the runner was loaded, not that 20s is too short. No frequency was measured and none is inherited; the job behind the card could not be re-run. ## What WAS measured (this repo, this container, `576d5df660`) 1. **The pre-fix helper answers three different causes with one sentence.** Driven against a healthy child, a child that exits at once with code 3, and a child that stays alive and never listens: **20761ms / 20751ms / 20778ms**, every one of them `the neighbour never came up on port N` and nothing else. Second run, same three: 20930ms / 20771ms / 20976ms. 2. **The healthy child failed too, and the cause was invisible to every check the harness could run.** `node` refused the bind — `listen EADDRINUSE: address already in use 0.0.0.0:39510` — on a port `pickFreePort` had just approved and on which `ss -ltn` showed **no listener at all**. `lsof` found it: `TCP 192.0.2.2:39510 -> 160.79.104.10:443 (ESTABLISHED)`. The port was an unrelated process's local **ephemeral source port**. `pickFreePort` proves a port is bindable at the instant it asks; its own docblock already says "advisory only". 3. **`process.kill(pid, 0)` is NOT a liveness check in this harness**, so the obvious repair is a trap. With the worker's event loop blocked inside `execFileSync` the exited child is an unreaped **zombie**, and `kill(pid, 0)` on a zombie succeeds: it answered "alive" about a child that had died 20 seconds earlier. ⚠️ Reading 2 is a mechanism reproduced **here**, ⛔ not a diagnosis of CI run 35529522740. What it establishes is narrower and enough: a port can be refused *after* passing `pickFreePort`, and the old instrument reports that case in exactly the words it uses for a slow runner. ## What changed `packages/create-objectstack/src/scaffold-e2e-boot-probe.test.ts` only. ⛔ Nothing the suite pins (#9779) is weakened, skipped or quarantined — the eight existing assertions are untouched and still green. - **The child announces its own listener.** `NEIGHBOUR-LISTENING port` from the `listen` callback, or `NEIGHBOUR-LISTEN-ERROR errno` from an `error` handler — written with `process.stdout.write(…, cb)` and exiting from the callback, because stdout is a pipe here and `process.exit()` on the next line truncates an async pipe write. - **The parent awaits that line**, with the `exit` event, the `spawn` error and the child's captured stdout/stderr wired to the same promise. Five outcomes now report themselves the moment they happen and name themselves: never spawned · exited before announcing (code, signal, and the child's own last words) · refused the bind (with the errno) · alive and never announced · announced and then went mute. - **The child asks the KERNEL for the port** (`listen(0)`) and reports back what it got, so the window `pickFreePort` leaves open is closed rather than merely reported on: the neighbour holds the binding continuously from before its caller learns the number. - ⛔ **No budget was raised.** The remaining ceiling is a backstop for the one outcome none of the others covers — announced, alive, still not answering — never the thing that decides the other four. That is what makes this a different instrument rather than a bigger number. ## The control that can FAIL ⛔ A green suite is no evidence that a diagnostic works. Five new cases break the neighbour four different ways and pin that the harness names THAT way, beside the healthy path: | deliberately broken child | verdict pinned | observed | |---|---|---| | a second child aimed at a port the first one holds | `its listener refused to bind: EADDRINUSE` | 108ms | | a child that exits at once | `it exited before announcing a listener (code 3` plus its own stderr | 40ms | | a child that stays alive and never listens | `it stayed alive and never announced a listener`, and ⛔ NOT the exit wording | 2006ms (its own 2s backstop) | | an executable that does not exist | `it never spawned` plus `ENOENT` | 3ms | | **the healthy path** | reports a port that answers at the exact spelling the block probes | 69ms | The same three broken children against the pre-fix helper: 20761ms / 20751ms / 20778ms, one undifferentiated sentence. **Ablation — one-time, restored, not left in the tree.** Collapsing the headline out of the diagnosis (anchor `: ${headline}\n`, replaced by an inert marker) turned **exactly** the four broken-child controls red and left the healthy control and all eight pre-existing assertions green: `Tests 4 failed | 9 passed (13)`. Driven through `scripts/ablation-replace.mjs`, which proved the mutation reached disk (`anchor 1 -> 0`, blob `9129d5f471c2 -> e0cd4e4d17af`) and proved the restore (`blob after restore 9129d5f` = `blob at HEAD`, `git diff HEAD` empty). The merge commit that follows does not touch the ablated file. ## Readings, all on `0dd94da744` (the final commit) - `pnpm --filter create-objectstack test` — **16 files, 208 tests, all pass** (13 in this file). - `pnpm --filter create-objectstack typecheck` — **exit 0**, and the test file is genuinely in that program: `tsc --noEmit --listFiles` names it (1 hit), so the green is not an `exclude` speaking. - `pnpm lint` (`eslint . --no-inline-config`, the whole repo — a full run, ⛔ not a narrowing) — **exit 0**. - Derived gate families (`node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack`) — **51 derived · 48 exit 0 · 3 exit 3**. The three are `check:dual-build-cjs-loads`, `check:lean-entry-closure` and `check:type-check-debt`, each printing `PREREQUISITE NOT MET` because it reads a full closure build this worktree does not carry. ⛔ Those three are **NOT MEASURED** here — neither pass nor finding; CI builds the closure and owns them. `--ran` reconciliation, exit codes recorded: `51 derived, 48 run, 3 NOT-MEASURED, 0 UNRUN`. - `pnpm check:cross-package-test-inputs` — **exit 0**. The diff adds no new escaping read, so `scripts/cross-package-test-inputs.mjs` and `turbo.json` were left alone: the gate was asked, ⛔ not pre-empted. ## Changeset `skip-changeset`, measured rather than assumed. After `pnpm --filter create-objectstack build`, the identifiers this PR adds (`scaffold-e2e-boot-probe`, `NEIGHBOUR-LISTENING`, `NeighbourOptions`) occur **0** times across every artefact `files[]` ships — `dist/index.js`, `dist/created-summary.js`, `dist/chunk-ZIUW7UEA.js`, `dist/created-summary.d.ts` — while the positive control `summarizeTree`/`formatBytes` occurs **14** times across those same four. ⇒ nothing published moves. ⚠️ The label itself was **not written**: the dispatch order forbids label writes it does not name, and it names none. It still needs applying by the owning seat. ## Acceptance notes - `pickFreePort` is still used by the other four cases in this file and the same staleness applies to them in principle. **Noted, not filed:** there the port is bound by the `os start` stub *inside* the block, which already prints `Port N is already in use.` and exits 1, so that path fails legibly today. Carrier: this PR's reviewer; no other PR is queued on this file. - The card's retracted note about a fixed port 38700 bind conflict **stays retracted** — `:147 pickFreePort(base)` scans 400 candidates and 38700/38900 are bases. The EADDRINUSE above is a different mechanism (a port that passed the scan and was refused afterwards), ⛔ not that claim revived. - The neighbour wait was the only clock touched. The workflow scripts under test, their `curl` spellings and their own timeouts are unchanged. --- _Generated by [Claude Code](https://claude.ai/code/session_01QCdUBjM47SxioST9z5Zwdf)_ Co-authored-by: Claude <noreply@anthropic.com>
1 parent bed7188 commit c27e160

1 file changed

Lines changed: 287 additions & 23 deletions

File tree

‎packages/create-objectstack/src/scaffold-e2e-boot-probe.test.ts‎

Lines changed: 287 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -366,45 +366,196 @@ function runBlock(h: Harness, script: string): Ran {
366366
* the block's `curl` — which carries no `--max-time`, exactly as the workflow
367367
* spells it — would hang until the harness timeout. Measured while writing this
368368
* file: every case sat at its 240s ceiling.
369+
*
370+
* ## Why this waits on the child's own word instead of on a clock (#19424)
371+
*
372+
* The wait this replaces was 80 `curl` probes 0.25s apart — exactly 20s — run
373+
* through `execFileSync('bash', …, { stdio: 'ignore' })` against a child
374+
* spawned with `stdio: 'ignore'`, and it threw naming only the port. Every
375+
* piece of evidence about WHY was discarded by construction: the child's exit
376+
* code, its stderr, whether it ever spawned at all. A CI failure at 20,999ms
377+
* and a healthy 299ms pass of the SAME assertion in the same run were therefore
378+
* indistinguishable to the reader, and the only remedy such a reading can
379+
* suggest is a bigger number.
380+
*
381+
* Two things were measured here while rewriting it (this repo, `576d5df660`),
382+
* and each one is a reason raising the budget could not have repaired it:
383+
*
384+
* * The failure reproduces with a perfectly healthy child on a port
385+
* `pickFreePort` had just approved. `node` refused the bind with
386+
* `listen EADDRINUSE 0.0.0.0:39510` while `ss -ltn` showed NO listener on
387+
* 39510 — the port was the local ephemeral port of an unrelated outbound
388+
* ESTABLISHED connection belonging to another process in the container.
389+
* `pickFreePort` proves a port is bindable at the instant it asks; its own
390+
* docblock says "advisory only", and this is what that costs. Reproduced
391+
* 3/3 against the pre-fix helper: 20761ms, 20930ms, 20886ms, every one of
392+
* them reporting `the neighbour never came up on port 39510` and nothing
393+
* else.
394+
* * `process.kill(pid, 0)` is NOT a liveness check in this harness, so the
395+
* obvious repair is a trap. With the event loop blocked inside
396+
* `execFileSync` the exited child is an unreaped ZOMBIE, and `kill(pid, 0)`
397+
* on a zombie SUCCEEDS — measured: it answered "alive" about a child that
398+
* had died 20 seconds earlier.
399+
*
400+
* So the child announces its own listener on stdout and the parent AWAITS that
401+
* line, with the `exit` event, the `spawn` error and the child's captured
402+
* output wired to the same promise. Each way this can fail now reports itself
403+
* the moment it happens and names itself: never spawned · exited before
404+
* announcing (with code, signal and its own last words) · refused the bind
405+
* (with the errno) · alive but never announced · announced and then went mute.
406+
* `timeoutMs` is a backstop for the last of those, ⛔ never the thing that
407+
* decides the others — which is why this file still names no budget.
408+
*
409+
* The child also asks the KERNEL for the port (`listen(0)`) and reports back
410+
* what it was given, so the window `pickFreePort` leaves open is not merely
411+
* reported on, it is closed: the neighbour holds the binding continuously from
412+
* before its caller learns the number. `port` is for the controls, which need
413+
* to aim a second neighbour at a port that is genuinely taken.
369414
*/
370-
function neighbour(port: number): { stop: () => void } {
371-
const child = spawn(process.execPath, ['-e', NEIGHBOUR_STUB], {
372-
env: { ...process.env, NEIGHBOUR_PORT: String(port) },
415+
interface NeighbourOptions {
416+
/** Bind this port instead of asking the kernel. Controls only. */
417+
port?: number;
418+
/** Replace the child's program text — the controls hand in broken ones. */
419+
stub?: string;
420+
/** Replace the executable — the "it never spawned" control. */
421+
exec?: string;
422+
/** The backstop, ⛔ not a budget: every other failure mode reports at once. */
423+
timeoutMs?: number;
424+
}
425+
426+
interface Neighbour {
427+
/** The port the child really bound, read back from the child. */
428+
port: number;
429+
stop: () => void;
430+
}
431+
432+
async function neighbour(options: NeighbourOptions = {}): Promise<Neighbour> {
433+
const {
434+
port: requested = 0,
435+
stub = NEIGHBOUR_STUB,
436+
exec = process.execPath,
437+
timeoutMs = 30_000,
438+
} = options;
439+
const started = Date.now();
440+
const child = spawn(exec, ['-e', stub], {
441+
env: { ...process.env, NEIGHBOUR_PORT: String(requested) },
373442
detached: true,
374-
stdio: 'ignore',
443+
stdio: ['ignore', 'pipe', 'pipe'],
375444
});
376445
child.unref();
446+
447+
// `state` rather than plain `let`s: these are written from callbacks, and a
448+
// narrowed `null` read back in the polling loop below would silently make
449+
// the "and then exited" branch unreachable.
450+
const state = { output: '', exited: null as { code: number | null; signal: string | null } | null };
451+
377452
const stop = () => {
378453
try {
379454
if (child.pid) process.kill(child.pid, 'SIGKILL');
380455
} catch {
381456
/* already gone */
382457
}
458+
child.stdout?.destroy();
459+
child.stderr?.destroy();
383460
};
384-
try {
385-
execFileSync(
386-
'bash',
387-
[
388-
'-c',
389-
`for _ in $(seq 1 80); do curl -fsS "http://localhost:${port}/api/v1/health" > /dev/null 2>&1 && exit 0; sleep 0.25; done; exit 1`,
390-
],
391-
{ stdio: 'ignore' },
461+
462+
const where = requested === 0 ? 'on a kernel-assigned port' : `on port ${requested}`;
463+
const diagnosis = (headline: string) =>
464+
new Error(
465+
`the neighbour never came up ${where} after ${Date.now() - started}ms: ${headline}\n` +
466+
`--- neighbour output ---\n${
467+
state.output.trim() || '(nothing: the child wrote neither stdout nor stderr)'
468+
}`,
392469
);
393-
} catch {
470+
471+
let announce: (port: number) => void = () => {};
472+
let giveUp: (err: Error) => void = () => {};
473+
const announced = new Promise<number>((resolve, reject) => {
474+
announce = resolve;
475+
giveUp = reject;
476+
});
477+
478+
const read = (chunk: string) => {
479+
state.output += chunk;
480+
const up = /NEIGHBOUR-LISTENING (\d+)/.exec(state.output);
481+
if (up) announce(Number(up[1]));
482+
const refused = /NEIGHBOUR-LISTEN-ERROR (\S+)/.exec(state.output);
483+
if (refused) giveUp(diagnosis(`its listener refused to bind: ${refused[1]}`));
484+
};
485+
child.stdout?.setEncoding('utf8');
486+
child.stderr?.setEncoding('utf8');
487+
child.stdout?.on('data', read);
488+
child.stderr?.on('data', read);
489+
child.on('error', (err) => giveUp(diagnosis(`it never spawned: ${err.message}`)));
490+
child.on('exit', (code, signal) => {
491+
state.exited = { code, signal };
492+
giveUp(diagnosis(`it exited before announcing a listener (code ${code}, signal ${signal})`));
493+
});
494+
const backstop = setTimeout(
495+
() => giveUp(diagnosis('it stayed alive and never announced a listener')),
496+
timeoutMs,
497+
);
498+
499+
let bound: number;
500+
try {
501+
bound = await announced;
502+
} catch (err) {
394503
stop();
395-
throw new Error(`the neighbour never came up on port ${port}`);
504+
throw err;
505+
} finally {
506+
clearTimeout(backstop);
507+
}
508+
509+
// Announced is not answered. This is the one window the backstop really
510+
// guards, and the only one where waiting longer is not obviously wrong.
511+
const url = `http://localhost:${bound}/api/v1/health`;
512+
let last = 'no probe completed';
513+
for (;;) {
514+
if (state.exited) {
515+
const { code, signal } = state.exited;
516+
stop();
517+
throw diagnosis(
518+
`it announced a listener on port ${bound} and then exited (code ${code}, signal ${signal})`,
519+
);
520+
}
521+
try {
522+
const res = await fetch(url, { signal: AbortSignal.timeout(1_000) });
523+
await res.arrayBuffer();
524+
if (res.ok) return { port: bound, stop };
525+
last = `HTTP ${res.status}`;
526+
} catch (err) {
527+
last = err instanceof Error ? `${err.name}: ${err.message}` : String(err);
528+
}
529+
if (Date.now() - started > timeoutMs) {
530+
stop();
531+
throw diagnosis(
532+
`it announced a listener on port ${bound} but never answered ${url} (last probe: ${last})`,
533+
);
534+
}
535+
await new Promise((resolve) => setTimeout(resolve, 50));
396536
}
397-
return { stop };
398537
}
399538

539+
/**
540+
* `process.stdout.write(…, cb)` and not `console.log`: stdout is a PIPE here,
541+
* writes to a pipe are asynchronous, and `process.exit()` on the next line
542+
* truncates them. Exiting from the write callback is what makes the errno
543+
* survive the exit that reports it.
544+
*/
400545
const NEIGHBOUR_STUB = `
401546
const http = require('node:http');
402-
http
403-
.createServer((_req, res) => {
404-
res.writeHead(200, { 'content-type': 'application/json' });
405-
res.end(JSON.stringify({ iam: 'NEIGHBOUR' }));
406-
})
407-
.listen(Number(process.env.NEIGHBOUR_PORT));
547+
const server = http.createServer((_req, res) => {
548+
res.writeHead(200, { 'content-type': 'application/json' });
549+
res.end(JSON.stringify({ iam: 'NEIGHBOUR' }));
550+
});
551+
server.once('error', (err) => {
552+
process.stdout.write('NEIGHBOUR-LISTEN-ERROR ' + ((err && err.code) || err) + '\\n', () => {
553+
process.exit(1);
554+
});
555+
});
556+
server.listen(Number(process.env.NEIGHBOUR_PORT || '0'), () => {
557+
process.stdout.write('NEIGHBOUR-LISTENING ' + server.address().port + '\\n');
558+
});
408559
`;
409560

410561
function curlBody(url: string): string {
@@ -424,9 +575,12 @@ describe.skipIf(!RUNNABLE)('[#9779] scaffold-e2e.yml boot-and-probe blocks asser
424575
for (const [job, step] of OS_START_STEPS) {
425576
describe(`${job} / ${step}`, () => {
426577
it('refuses a neighbour already answering the URL its loop accepts as proof', async () => {
427-
const port = await pickFreePort(38700);
578+
// The neighbour goes up FIRST and reports the port the kernel gave it,
579+
// so the script is rewritten around a port that is already held rather
580+
// than around one that merely tested free a moment ago (#19424).
581+
const n = await neighbour();
582+
const port = n.port;
428583
const script = stepScript(step).replaceAll('8080', String(port));
429-
const n = neighbour(port);
430584
try {
431585
// Vacuity guard: the neighbour must really be reachable at the exact
432586
// spelling the loop probes, or "refused" below proves nothing.
@@ -493,3 +647,113 @@ describe.skipIf(!RUNNABLE)('[#9779] scaffold-e2e.yml boot-and-probe blocks asser
493647
}, 120_000);
494648
});
495649
});
650+
651+
/**
652+
* Runs `neighbour()` expecting it NOT to come up, and hands back what it said.
653+
*
654+
* The "it came up after all" branch throws its own message rather than falling
655+
* into the catch: a control that reports the harness's success as if it were
656+
* the harness's diagnosis is a control that can never fail.
657+
*/
658+
async function failedNeighbour(
659+
options: NeighbourOptions,
660+
): Promise<{ message: string; seconds: number }> {
661+
const started = Date.now();
662+
let came: Neighbour | null = null;
663+
let error: unknown = null;
664+
try {
665+
came = await neighbour(options);
666+
} catch (err) {
667+
error = err;
668+
}
669+
if (came) {
670+
came.stop();
671+
throw new Error(
672+
`this control is vacuous: the neighbour was supposed to fail and it came up on port ${came.port}`,
673+
);
674+
}
675+
return {
676+
message: error instanceof Error ? error.message : String(error),
677+
seconds: (Date.now() - started) / 1000,
678+
};
679+
}
680+
681+
/**
682+
* The controls for the instrument above (#19424).
683+
*
684+
* ⛔ A green suite is not evidence that a diagnostic works — only a
685+
* deliberately broken child is. Each case here breaks the neighbour a
686+
* DIFFERENT way and pins that the harness names THAT way and not another, so a
687+
* diagnosis that collapses back into one undifferentiated "never came up"
688+
* cannot pass. The healthy path is pinned in the same block, because a
689+
* diagnosis that fires on a working neighbour is its own defect.
690+
*
691+
* Gated on `RUNNABLE` with the suite above rather than on its own terms: the
692+
* harness these pin is reached only where that suite runs, so pinning it
693+
* elsewhere would pin an instrument nothing uses.
694+
*/
695+
describe.skipIf(!RUNNABLE)('[#19424] the neighbour harness says WHY it did not come up', () => {
696+
it('reports the port it really bound, and answers there', async () => {
697+
const n = await neighbour();
698+
try {
699+
expect(n.port).toBeGreaterThan(0);
700+
// Read back through the same spelling the block's loop uses, so "the
701+
// port it reports" and "the port that answers" are pinned as one fact.
702+
expect(curlBody(`http://localhost:${n.port}/api/v1/health`)).toContain('NEIGHBOUR');
703+
} finally {
704+
n.stop();
705+
}
706+
}, 60_000);
707+
708+
it('names the errno when the child cannot bind the port it was given', async () => {
709+
// The measured failure this card was filed against: a port that tested
710+
// free and was refused anyway. Here it is made deterministic by aiming the
711+
// second child at a port the first one is holding.
712+
const held = await neighbour();
713+
try {
714+
const { message, seconds } = await failedNeighbour({ port: held.port });
715+
expect(message).toContain('the neighbour never came up');
716+
expect(message).toContain(`on port ${held.port}`);
717+
expect(message).toContain('its listener refused to bind: EADDRINUSE');
718+
// The point of the whole change: this arrives at once instead of after a
719+
// budget nobody can defend.
720+
expect(seconds).toBeLessThan(10);
721+
} finally {
722+
held.stop();
723+
}
724+
}, 60_000);
725+
726+
it('names the exit code and the child last words when the child dies at once', async () => {
727+
const { message, seconds } = await failedNeighbour({
728+
stub: `process.stderr.write('boot log: the artifact could not be read\\n');\nprocess.exit(3);`,
729+
});
730+
expect(message).toContain('it exited before announcing a listener (code 3');
731+
// The child's own output is carried out with the verdict — the half the
732+
// pre-fix harness discarded by spawning with `stdio: 'ignore'`.
733+
expect(message).toContain('boot log: the artifact could not be read');
734+
expect(seconds).toBeLessThan(10);
735+
}, 60_000);
736+
737+
it('says the child stayed alive when it never announces a listener', async () => {
738+
const { message, seconds } = await failedNeighbour({
739+
stub: 'setTimeout(() => {}, 60_000);',
740+
timeoutMs: 2_000,
741+
});
742+
expect(message).toContain('it stayed alive and never announced a listener');
743+
// ⛔ Not collapsed into the death case: alive-and-mute and dead are the two
744+
// the old instrument could not tell apart, so they must not read alike.
745+
expect(message).not.toContain('it exited before announcing');
746+
expect(message).toContain('(nothing: the child wrote neither stdout nor stderr)');
747+
expect(seconds).toBeLessThan(20);
748+
}, 60_000);
749+
750+
it('says it never spawned when the child cannot be executed at all', async () => {
751+
const { message, seconds } = await failedNeighbour({
752+
exec: path.join(os.tmpdir(), 'objectstack-no-such-node-19424'),
753+
timeoutMs: 5_000,
754+
});
755+
expect(message).toContain('it never spawned');
756+
expect(message).toContain('ENOENT');
757+
expect(seconds).toBeLessThan(10);
758+
}, 60_000);
759+
});

0 commit comments

Comments
 (0)