Skip to content

Commit 6cd7fcf

Browse files
os-litantclaude
andauthored
test(cli): make the serve NODE_ENV e2e origin probe lifecycle-aware (#15654)
`probeOriginCheck` dropped the two artefacts that decide why a probe failed — the child's exit status and everything it printed — so the one recorded `UND_ERR_SOCKET / other side closed / bytesRead: 0` reached vitest as a bare `TypeError: fetch failed` and could not be attributed at all. Measured, three shapes side by side with this file's own request: nothing listening answers ECONNREFUSED with no socket object; a listener that accepts and then FINs, and a server torn down mid-request, both answer UND_ERR_SOCKET "other side closed" with bytesRead 0. Only the latter two match what was recorded, so the child was SERVING when the request arrived — this is a post-ready lifecycle event, not the readiness race the card assumed. On a transport failure the probe now asks the child whether it is still alive (waiting CHILD_EXIT_SETTLE_MS, because the FIN arrives before `exit` does) and then: a child that EXITED fails at once naming its exit code, signal and whole transcript, never retried; a non-UND_ERR_SOCKET failure is rethrown with the transcript, never retried; only UND_ERR_SOCKET against a still-running child is absorbed, at most PROBE_ATTEMPTS times, printing a labelled line each time so a recurring one is greppable rather than silent. Also adopts the banner TAIL (`Press Ctrl+C to stop`) as the ready marker, which is what every `runServe()` caller in this directory already waits on. Stated in the file as directory alignment, not as the repair: the HTTP listener is up before either banner line. No skip, no todo, no quarantine, no timeout bump. Claude-Session: https://claude.ai/code/session_01D47qPfEWVPmhguWgBZCi5N Co-authored-by: Claude <noreply@anthropic.com>
1 parent 54e2369 commit 6cd7fcf

1 file changed

Lines changed: 241 additions & 15 deletions

File tree

packages/cli/test/serve-node-env-production-default.e2e.test.ts

Lines changed: 241 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -292,6 +292,184 @@ interface OriginCheckResult {
292292
body: any;
293293
}
294294

295+
/**
296+
* The banner's LAST line — the marker the rest of this directory already waits
297+
* on (every `runServe()` caller here passes `/Press Ctrl\+C to stop/`), adopted
298+
* in place of this file's own `/Server is ready/`.
299+
*
300+
* `printServerReady` writes the head, the `API:` row and this line with
301+
* `console.error`, and writes to one stream are ordered, so a buffer holding
302+
* this line holds the whole banner. Keying on the HEAD leaves any later read of
303+
* the banner dependent on whether the rest of it landed in the same pipe chunk
304+
* — the reasoning `helpers/serve-process.ts` records for its own `BANNER_TAIL`,
305+
* which this file was the last spawner here not to follow.
306+
*
307+
* ⚠️ Stated so it is not oversold: this is directory alignment, ⛔ NOT the
308+
* repair for the failure described below, and it is not claimed to be. Measured
309+
* on this tree, the HTTP listener is up well before either line — `serve.ts`
310+
* awaits `runtime.start()` and only then prints the banner through
311+
* `publishBoundPort` — and a probe fired at a port nothing is listening on
312+
* answers `ECONNREFUSED` with no socket object at all, which is not the
313+
* signature that was recorded. Waiting for the whole banner could not have
314+
* prevented that failure.
315+
*/
316+
const READY_BANNER_TAIL = /Press Ctrl\+C to stop/;
317+
318+
/**
319+
* WHY THE PROBE BELOW IS LIFECYCLE-AWARE, and the reading that decided its
320+
* shape. The bound is this constant; the reason is this whole section.
321+
*
322+
* A merge-group run evicted a queue entry when the third call site below failed
323+
* with:
324+
*
325+
* TypeError: fetch failed
326+
* Caused by: SocketError: other side closed
327+
* { code: 'UND_ERR_SOCKET', socket: { bytesWritten: 349, bytesRead: +0 } }
328+
*
329+
* ## What that signature IS — measured, and it is ⛔ NOT "the server was not up"
330+
*
331+
* `bytesWritten: 349, bytesRead: 0` says the TCP connection was ESTABLISHED,
332+
* the whole request was delivered, and the peer then closed it without
333+
* answering. Three shapes measured side by side on this container, with the
334+
* same request this file sends:
335+
*
336+
* nothing listening on the port ECONNREFUSED, and NO socket object
337+
* (bytesWritten/bytesRead both undefined)
338+
* listener accepts, then FINs UND_ERR_SOCKET "other side closed",
339+
* bytesWritten 321, bytesRead 0
340+
* server torn down mid-request UND_ERR_SOCKET "other side closed",
341+
* bytesWritten 345, bytesRead 0
342+
*
343+
* Only the second and third match what was recorded, and the FIRST is what a
344+
* genuine readiness race looks like. So the child was serving when the request
345+
* arrived, and something ended the connection after it. The wait above was
346+
* already correct: ⛔ the repair is not a longer or better wait, and ⛔ not a
347+
* bigger timeout.
348+
*
349+
* ## What this harness could not say, and now says
350+
*
351+
* On the failing path this function used to discard the two artefacts that
352+
* decide between "the child died" and "a live child dropped a connection": the
353+
* child's exit status, and everything the child printed. The `child.on('exit')`
354+
* handler above feeds the READINESS promise only, so once that promise has
355+
* settled a later death is invisible here and the rejection reaches vitest as a
356+
* bare `TypeError: fetch failed` — no exit code, no stdout, no stderr. That is
357+
* why the one recorded occurrence could not be attributed at all, and it is the
358+
* defect this repair removes.
359+
*
360+
* It matters that a silent death is reachable. There is no
361+
* `process.on('uncaughtException')` and no `'unhandledRejection'` handler
362+
* anywhere in this repo's product source, so a late async throw inside the
363+
* child — or an OOM kill on a six-shard CI box — takes the process down with no
364+
* HTTP answer and exactly this client-side signature.
365+
*
366+
* ## The bound, and what it can and cannot hide
367+
*
368+
* ⛔ The retry is not the first move and cannot be reached before the child has
369+
* been asked whether it is alive. On a transport failure the probe waits up to
370+
* {@link CHILD_EXIT_SETTLE_MS} for the child's `exit` event — the FIN reaches
371+
* the client on the network's schedule and `exit` arrives on the event loop's,
372+
* so reading `exitCode` at the instant `fetch` rejects reports a dead child as
373+
* alive — and then:
374+
*
375+
* • child EXITED ⇒ ⛔ never retried. Fails at once, naming the exit code and
376+
* signal and quoting the child's whole stdout and stderr.
377+
* • failure is NOT `UND_ERR_SOCKET` ⇒ ⛔ never retried. Rethrown with the
378+
* child's output attached. ECONNREFUSED (nothing listening), a timeout, a
379+
* DNS or a TLS fault each still fail on their first occurrence.
380+
* • child ALIVE and `UND_ERR_SOCKET` ⇒ absorbed, up to this many attempts in
381+
* total.
382+
*
383+
* ⛔ CANNOT hide a wrong ANSWER. The loop absorbs transport failures only; a
384+
* `200` where the pin wants `403` is returned to the caller untouched, on the
385+
* first attempt, every time. Nor can it hide a boot that never reaches the
386+
* banner: that is the readiness rejection above, which this does not touch.
387+
*
388+
* ⚠️ CAN hide a LIVE `os serve` that occasionally destroys a connection without
389+
* answering it. That is a real product-defect class and this bound does not
390+
* remove it. What it does is make every occurrence print
391+
* `[serve-node-env-production-default] absorbed a transport failure` with the
392+
* full socket signature, so a recurring one is a `grep` away in a CI log
393+
* instead of a merge-queue eviction. ⛔ If that line starts appearing, the
394+
* finding is in `os serve` and belongs in a card against it — do not raise this
395+
* number to make it stop.
396+
*
397+
* ⛔ And the line this file may never cross, restated because the test is slow
398+
* (its shard ran 783 s) and its subject is unglamorous: no `.skip`, no `.todo`,
399+
* no quarantine list, no retry that swallows a failure into silence. A flake in
400+
* a required shard is a harness bug to diagnose, never a licence to stop
401+
* measuring.
402+
*/
403+
const PROBE_ATTEMPTS = 3;
404+
405+
/**
406+
* How long the probe gives the child's `exit` event before it will call the
407+
* child alive — see the section above for why that answer cannot be read
408+
* synchronously off `exitCode`.
409+
*
410+
* Two seconds because this is a LOCAL child whose exit has already happened by
411+
* the time its FIN reached us; the wait covers event-loop delivery, not process
412+
* teardown. It is paid ONLY on a failing attempt, so a green run never waits.
413+
*/
414+
const CHILD_EXIT_SETTLE_MS = 2_000;
415+
416+
/** The child's lifecycle state, as far as this process can observe it. */
417+
interface ChildFate {
418+
exited: boolean;
419+
code: number | null;
420+
signal: NodeJS.Signals | null;
421+
}
422+
423+
function fateOf(child: ProbeChild): ChildFate {
424+
return {
425+
exited: child.exitCode !== null || child.signalCode !== null,
426+
code: child.exitCode,
427+
signal: child.signalCode,
428+
};
429+
}
430+
431+
/** Ask the child whether it is still running, allowing `ms` for the answer. */
432+
function settleChildFate(child: ProbeChild, ms: number): Promise<ChildFate> {
433+
const already = fateOf(child);
434+
if (already.exited) return Promise.resolve(already);
435+
return new Promise<ChildFate>((settle) => {
436+
const onExit = () => {
437+
clearTimeout(timer);
438+
settle(fateOf(child));
439+
};
440+
const timer = setTimeout(() => {
441+
child.off('exit', onExit);
442+
settle(fateOf(child));
443+
}, ms);
444+
child.once('exit', onExit);
445+
});
446+
}
447+
448+
/** `cause.code` of a `fetch` rejection, when it carries one. */
449+
function transportCode(err: unknown): string | undefined {
450+
const cause = (err as { cause?: { code?: unknown } } | undefined)?.cause;
451+
return typeof cause?.code === 'string' ? cause.code : undefined;
452+
}
453+
454+
/**
455+
* One line naming what the transport did — the exact fields the recorded
456+
* failure had to be diagnosed from, kept together so the NEXT occurrence needs
457+
* no second run to be readable.
458+
*/
459+
function transportSignature(err: unknown): string {
460+
const cause = (err as {
461+
cause?: { code?: unknown; message?: unknown; socket?: Record<string, unknown> };
462+
} | undefined)?.cause;
463+
const socket = cause?.socket;
464+
const wire = socket
465+
? ` socket: bytesWritten=${String(socket.bytesWritten)} bytesRead=${String(socket.bytesRead)}`
466+
+ ` local=${String(socket.localAddress)}:${String(socket.localPort)}`
467+
+ ` remote=${String(socket.remoteAddress)}:${String(socket.remotePort)}`
468+
: ' socket: none — the connection was never established';
469+
return `${(err as Error)?.message ?? String(err)}`
470+
+ ` [cause ${String(cause?.code ?? 'none')}: ${String(cause?.message ?? 'none')}]${wire}`;
471+
}
472+
295473
/**
296474
* Boot `os serve` for real against the shipped entrypoint, wait for the ready
297475
* banner, POST a sign-in attempt carrying an untrusted-looking localhost
@@ -392,10 +570,13 @@ async function probeOriginCheck(env: Record<string, string | undefined>): Promis
392570

393571
await new Promise<void>((readyResolve, readyReject) => {
394572
const timer = setTimeout(() => {
395-
readyReject(new Error(`serve never reached "Server is ready"\n--- stdout ---\n${out}\n--- stderr ---\n${err}`));
573+
readyReject(new Error(
574+
'serve never printed its COMPLETE ready banner (last line: "Press Ctrl+C to stop")'
575+
+ `\n--- stdout ---\n${out}\n--- stderr ---\n${err}`,
576+
));
396577
}, 150_000);
397578
const onData = () => {
398-
if (/Server is ready/.test(out + err)) {
579+
if (READY_BANNER_TAIL.test(out + err)) {
399580
clearTimeout(timer);
400581
readyResolve();
401582
}
@@ -422,20 +603,65 @@ async function probeOriginCheck(env: Record<string, string | undefined>): Promis
422603
});
423604
});
424605

606+
// Everything the child said, for a failure message that can be attributed
607+
// without a second run. Read at THROW time, so it carries the crash the child
608+
// printed on its way down rather than the buffer as it stood at ready.
609+
const transcript = () => `\n--- child stdout ---\n${out}\n--- child stderr ---\n${err}`;
610+
425611
try {
426-
const res = await fetch(`http://localhost:${port}/api/v1/auth/sign-in/email`, {
427-
method: 'POST',
428-
headers: {
429-
'content-type': 'application/json',
430-
// No cookie header — this is the shape `validateFormCsrf` forces an
431-
// origin check for when neither Sec-Fetch-* nor a cookie is present.
432-
origin: `http://localhost:${untrustedOriginPort}`,
433-
},
434-
body: JSON.stringify({ email: 'nobody@example.com', password: 'definitely-wrong-password' }),
435-
});
436-
let body: any = null;
437-
try { body = await res.json(); } catch { /* non-JSON error body, fall through with null */ }
438-
return { status: res.status, body };
612+
const absorbed: string[] = [];
613+
for (let attempt = 1; attempt <= PROBE_ATTEMPTS; attempt++) {
614+
try {
615+
const res = await fetch(`http://localhost:${port}/api/v1/auth/sign-in/email`, {
616+
method: 'POST',
617+
headers: {
618+
'content-type': 'application/json',
619+
// No cookie header — this is the shape `validateFormCsrf` forces an
620+
// origin check for when neither Sec-Fetch-* nor a cookie is present.
621+
origin: `http://localhost:${untrustedOriginPort}`,
622+
},
623+
body: JSON.stringify({ email: 'nobody@example.com', password: 'definitely-wrong-password' }),
624+
});
625+
let body: any = null;
626+
try { body = await res.json(); } catch { /* non-JSON error body, fall through with null */ }
627+
return { status: res.status, body };
628+
} catch (probeErr) {
629+
const signature = transportSignature(probeErr);
630+
// ⛔ Ask the child FIRST, and wait for the answer. See PROBE_ATTEMPTS:
631+
// a dead child must never reach the absorb branch below.
632+
const fate = await settleChildFate(child, CHILD_EXIT_SETTLE_MS);
633+
if (fate.exited) {
634+
throw new Error(
635+
`os serve DIED while answering the origin probe on port ${port} — exit code `
636+
+ `${String(fate.code)}, signal ${String(fate.signal)}. This is the CHILD's failure, not a `
637+
+ 'dropped socket, so it is NOT retried; the transcript below is what it printed on its '
638+
+ `way down.\nattempt ${attempt}/${PROBE_ATTEMPTS}: ${signature}${transcript()}`,
639+
);
640+
}
641+
if (transportCode(probeErr) !== 'UND_ERR_SOCKET') {
642+
throw new Error(
643+
`the origin probe on port ${port} failed with a transport error this harness does not `
644+
+ 'absorb — only UND_ERR_SOCKET against a still-running child is absorbed, and only '
645+
+ `${PROBE_ATTEMPTS} times (see PROBE_ATTEMPTS).\nattempt ${attempt}/${PROBE_ATTEMPTS}: `
646+
+ `${signature}${transcript()}`,
647+
);
648+
}
649+
absorbed.push(`attempt ${attempt}/${PROBE_ATTEMPTS}: ${signature}`);
650+
// Loud on purpose. An absorbed failure that printed nothing would be the
651+
// "retry into silence" this card forbids; this line is what makes a
652+
// recurring one greppable in a CI log.
653+
console.error(
654+
'[serve-node-env-production-default] absorbed a transport failure from a STILL-RUNNING '
655+
+ `os serve on port ${port} (attempt ${attempt}/${PROBE_ATTEMPTS}) — ${signature}`,
656+
);
657+
}
658+
}
659+
throw new Error(
660+
`the origin probe never completed a request against os serve on port ${port} after `
661+
+ `${PROBE_ATTEMPTS} attempts. The child was still running ${CHILD_EXIT_SETTLE_MS} ms after `
662+
+ 'EVERY one of them, so this is a live server dropping connections, not a dead child — the '
663+
+ `finding is in os serve, not in this harness.\n${absorbed.join('\n')}${transcript()}`,
664+
);
439665
} finally {
440666
await stop(child);
441667
}

0 commit comments

Comments
 (0)