diff --git a/changelog.d/9416-stdin-only-loop-liveness.md b/changelog.d/9416-stdin-only-loop-liveness.md new file mode 100644 index 0000000000..34e834102a --- /dev/null +++ b/changelog.d/9416-stdin-only-loop-liveness.md @@ -0,0 +1,12 @@ +### Fixed + +- A program whose only pending work is a `process.stdin` read no longer exits + before the bytes arrive (#9416). `process.stdin` reached as an object — an + alias, a parameter, or a field — files its listener in perry-runtime's own + stdin registries; #9399 taught perry-stdlib's `js_stdlib_has_active_handles` + about those lists, but such a program links runtime-only, where the symbol the + generated event loop calls is perry-runtime's trampoline and the stdlib arm is + unreachable. The trampoline now consults `stdin_listeners_keep_loop_alive()` + itself, so stdin-driven filters, REPLs and stdio transports stay alive exactly + as long as Node keeps them (and no longer: `pause()`/`unref()`/`destroy()` and + EOF-plus-`'end'` still release the loop). diff --git a/changelog.d/9421-async-output-flush.md b/changelog.d/9421-async-output-flush.md new file mode 100644 index 0000000000..3eb6259cc4 --- /dev/null +++ b/changelog.d/9421-async-output-flush.md @@ -0,0 +1,15 @@ +### Tests + +- `test_gap_9421_async_output_flush` pins the async queue-and-flush write + path that #9421 blames for the truncated claude-code transcript. It drives + multi-line output from async callbacks, a `process.stdout.write` loop, + interleaved `console.log`/`console.error`, output followed by an explicit + `process.exit()`, output past one pipe buffer, and a transliteration of + claude-code's own `SessionWriter` (`scheduleDrain` → `setTimeout(100)` → + `await drainWriteQueue()` → `await appendFile`, next to the one + `appendFileSync` record the report says is the only survivor). Perry matches + Node byte for byte in every one, including on unfixed `main` — so the + async-flush attribution is wrong. The `writer-exit-early` role reproduces the + reported 1-vs-5 signature exactly, **under both engines**, by leaving before + the 100 ms drain timer: the symptom identifies a run that ended too early, + not a flush that failed. diff --git a/crates/perry-runtime/src/lib.rs b/crates/perry-runtime/src/lib.rs index 1e78b80deb..a0c7d966ab 100644 --- a/crates/perry-runtime/src/lib.rs +++ b/crates/perry-runtime/src/lib.rs @@ -558,6 +558,29 @@ pub(crate) mod stdlib_pump { if crate::dgram_reactor::has_active() { return 1; } + // #9416: a `process.stdin` listener registered on the stdin OBJECT — + // an alias (`const s = process.stdin`), a parameter, or a field — + // files its callback in perry-runtime's OWN stdin registries and + // starts perry-runtime's own fd-0 reader. #9399 taught *perry-stdlib's* + // `js_stdlib_has_active_handles` about those lists, but a program whose + // only stdlib-flavoured work IS that listener links RUNTIME-ONLY, and + // then the symbol the generated event loop calls is THIS trampoline — + // whose `STDLIB_HAS_ACTIVE_FN` is null, so the stdlib arm is never + // reached. `stdin_listeners_keep_loop_alive()` answered "keep running" + // on every check and nothing asked it: the loop found no work and + // `main` returned with the pipe still open and the bytes unread, which + // kills every stdin-driven CLI filter, REPL and stdio transport that + // does not also hold a timer. The registry, the reader and the + // predicate are all perry-runtime's, so the check belongs here; the + // stdlib copy stays for the stdlib-linked path and is simply redundant. + // + // Not a pin: the predicate is false when nobody is listening, false + // once stdin is detached (`pause`/`unref`/`destroy`), and false again + // after EOF has been seen and the terminal `'end'`/`'close'` dispatch + // has run. + if crate::os::stdin_listeners_keep_loop_alive() { + return 1; + } if crate::process::js_process_ipc_has_active() != 0 { return 1; } @@ -592,6 +615,38 @@ pub(crate) mod stdlib_pump { 0 } + /// #9416: the symbol the generated event loop calls must itself + /// consult the runtime-local stdin registries. + /// + /// A `process.stdin` listener registered on the stdin OBJECT lands in + /// perry-runtime's own lists, and a program whose only work is that + /// listener links RUNTIME-ONLY — `STDLIB_HAS_ACTIVE_FN` is null, so the + /// perry-stdlib arm that #9399 taught about those lists is unreachable. + /// Before the fix this returned 0 with a live listener and the loop + /// exited with the pipe still open. + #[test] + fn stdin_object_listener_keeps_the_loop_alive_without_stdlib() { + crate::os::test_set_stdin_data_listener(None); + assert_eq!( + js_stdlib_has_active_handles(), + 0, + "no stdin listener and no other source: the loop must be free to exit" + ); + crate::os::test_set_stdin_data_listener(Some(0x1234)); + assert_eq!( + js_stdlib_has_active_handles(), + 1, + "a live runtime-local stdin listener must keep the event loop alive \ + even when perry-stdlib is not linked (#9416)" + ); + crate::os::test_set_stdin_data_listener(None); + assert_eq!( + js_stdlib_has_active_handles(), + 0, + "removing the listener must release the loop again" + ); + } + #[test] fn aux_pump_registration_is_idempotent() { // Registering the same fn pointer repeatedly stores it once, diff --git a/crates/perry-runtime/src/os.rs b/crates/perry-runtime/src/os.rs index 3008655342..581b920b04 100644 --- a/crates/perry-runtime/src/os.rs +++ b/crates/perry-runtime/src/os.rs @@ -845,6 +845,8 @@ pub use process_streams::{ stdin_chunk_jsvalue, stdin_has_encoding, stdin_is_detached, stdin_listeners_keep_loop_alive, stdin_push_bytes, }; +#[cfg(test)] +pub(crate) use process_streams::test_set_stdin_data_listener; /// Get the operating system name /// Returns: "Darwin", "Linux", "Windows_NT", etc. diff --git a/crates/perry-runtime/src/os_process_streams.rs b/crates/perry-runtime/src/os_process_streams.rs index efc14ce9ba..5a4cb0b06f 100644 --- a/crates/perry-runtime/src/os_process_streams.rs +++ b/crates/perry-runtime/src/os_process_streams.rs @@ -517,6 +517,25 @@ extern "C" fn process_stdin_listeners( /// delivered, then — once `'end'`/`'close'` have fired, or when nobody is /// listening for them — lets it exit. `pause()`/`unref()`/`destroy()` release /// the hold immediately, via the same `stdin_is_detached` latch readline uses. +/// Test-only: seed or clear the runtime-local `'data'` listener registry. +/// +/// #9416's unit test drives `js_stdlib_has_active_handles` — the symbol the +/// generated event loop calls — through the same registry a real +/// `const s = process.stdin; s.on("data", …)` fills, without spawning an fd-0 +/// reader that would fight the test harness for the terminal. +#[cfg(test)] +pub(crate) fn test_set_stdin_data_listener(cb: Option) { + use std::sync::atomic::Ordering; + if let Ok(mut l) = STDIN_DATA_LISTENERS.lock() { + l.clear(); + if let Some(cb) = cb { + l.push(cb); + } + } + STDIN_EOF_SEEN.store(false, Ordering::Release); + STDIN_END_FIRED.store(false, Ordering::Release); +} + pub fn stdin_listeners_keep_loop_alive() -> bool { if stdin_is_detached() { return false; diff --git a/test-files/test_gap_9416_stdin_only_loop_liveness.ts b/test-files/test_gap_9416_stdin_only_loop_liveness.ts new file mode 100644 index 0000000000..58d455707f --- /dev/null +++ b/test-files/test_gap_9416_stdin_only_loop_liveness.ts @@ -0,0 +1,164 @@ +// #9416: a program whose only pending work is a `process.stdin` read must keep +// the event loop turning, exactly as Node keeps a process alive for a ref'd +// stdin handle. +// +// The shape that failed is `process.stdin` reached as an OBJECT — an alias +// (`const s = process.stdin`), a parameter, or a field — rather than the +// literal `process.stdin.on(...)` spelling codegen lowers to perry-stdlib's +// readline extern. The object form files its listener in perry-runtime's own +// stdin registries and starts perry-runtime's own fd-0 reader, and #9407 taught +// *perry-stdlib's* `js_stdlib_has_active_handles` about those lists. But a +// program whose only stdlib-flavoured work IS that listener links RUNTIME-ONLY, +// and then the symbol the generated event loop calls is perry-runtime's +// `js_stdlib_has_active_handles` trampoline, whose registered stdlib pointer is +// null. `stdin_listeners_keep_loop_alive()` answered "keep running" on every +// single check and nothing ever asked it: the loop found no work and `main` +// returned with the pipe still open and the bytes unread. +// +// The parity runner gives a fixture no stdin of its own, so this test re-spawns +// itself with a pipe on the child's stdin and drives each shape in a child role. +// The payload is written after a delay so that "the loop stayed alive" is what +// is actually measured — the unfixed engine exits in ~20-50 ms, long before it +// arrives, which is why the pre-fix failure is deterministic here even though +// the bug reads as flaky when input is already buffered. +// +// The last two roles are negative controls: they must still exit PROMPTLY while +// the parent holds the pipe open forever. A fix that simply pins the loop open +// whenever stdin exists would hang them, and the watchdog would report it. +import { spawn } from "node:child_process"; + +const ROLE_ENV = "PERRY_9416_STDIN_ROLE"; +const PAYLOAD = "alpha\nbeta\n"; +const WRITE_DELAY_MS = 120; +// Generous on purpose: this machine runs many concurrent compiles, and the +// watchdog exists only so a REGRESSION that hangs reports as a readable diff +// instead of a harness timeout. A healthy role finishes in well under 1.2 s. +const WATCHDOG_MS = 3000; +const role = process.env[ROLE_ENV] ?? ""; + +// The roles that have their answer leave explicitly, so the fixture stays well +// inside the parity runner's per-test timeout. Perry's event loop sleeps for up +// to a second in `js_wait_for_event` before it re-checks liveness, so a role +// that drains naturally costs ~1 s of pure idle wait where Node costs ~20 ms; +// that lag is a separate matter from this issue and the two negative controls +// below still exercise the natural-drain path. +function finish(line: string): void { + console.log(line); + process.exit(0); +} + +function reportText(label: string, text: string): void { + finish(label + ' text: ' + JSON.stringify(text)); +} + +if (role === "aliased-data") { + // The reported shape: an aliased receiver, data + end, nothing else pending. + const stream: any = process.stdin; + let acc = ""; + stream.on("data", (chunk: any) => { + acc += String(chunk); + }); + stream.on("end", () => reportText("aliased-data", acc)); +} else if (role === "param-data") { + // Same registry, reached through a parameter (claude-code's stdio transport + // shape: `helper(process.stdin)` then `stream.on("data", ...)` inside). + const read = (stream: any, done: (text: string) => void) => { + let acc = ""; + stream.on("data", (chunk: any) => { + acc += String(chunk); + }); + stream.once("end", () => done(acc)); + }; + read(process.stdin, (text) => reportText("param-data", text)); +} else if (role === "end-only") { + // No data listener at all — only the terminal event. Node holds the process + // open for it; the parent closes the pipe with nothing written. + const stream: any = process.stdin; + stream.once("end", () => finish("end-only fired: true")); + stream.resume(); +} else if (role === "in-timeout") { + // The read is registered a turn later, so the very first liveness check sees + // no stdin work at all and a timer must carry the loop to the registration. + setTimeout(() => { + const stream: any = process.stdin; + let acc = ""; + stream.on("data", (chunk: any) => { + acc += String(chunk); + }); + stream.on("end", () => reportText("in-timeout", acc)); + }, 30); +} else if (role === "with-timer") { + // stdin plus one short timer: the timer expires long before the payload + // arrives, so the read still has to hold the loop by itself afterwards. + const stream: any = process.stdin; + let acc = ""; + stream.on("data", (chunk: any) => { + acc += String(chunk); + }); + stream.on("end", () => reportText("with-timer", acc)); + setTimeout(() => {}, 1); +} else if (role === "no-listener") { + // NEGATIVE CONTROL: no stdin listener. The parent never writes and never + // closes the pipe, so this must exit on its own. + console.log("no-listener done: true"); +} else if (role === "paused") { + // NEGATIVE CONTROL: a listener that releases stdin again. `pause()` unrefs + // the handle in Node, so the process exits even with the pipe held open. + const stream: any = process.stdin; + stream.on("data", () => {}); + setTimeout(() => { + stream.pause(); + console.log("paused done: true"); + }, 30); +} else { + const childArgs = [...process.execArgv, ...process.argv.slice(1)]; + // `feed` says what the parent does with the child's stdin: + // "delayed" — write the payload after WRITE_DELAY_MS, then close + // "close" — close immediately with nothing written + // "hold" — never write, never close (the negative controls) + const runRole = (name: string, feed: "delayed" | "close" | "hold") => + new Promise((resolve) => { + const child = spawn(process.execPath, childArgs, { + env: { ...process.env, [ROLE_ENV]: name }, + stdio: ["pipe", "inherit", "inherit"], + }); + let settled = false; + const watchdog = setTimeout(() => { + if (settled) return; + settled = true; + console.log(name + " exit: WATCHDOG"); + child.kill("SIGKILL"); + resolve(); + }, WATCHDOG_MS); + child.on("exit", (code) => { + if (settled) return; + settled = true; + clearTimeout(watchdog); + console.log(name + " exit:", code); + resolve(); + }); + if (feed === "delayed") { + setTimeout(() => { + try { + child.stdin!.write(PAYLOAD); + child.stdin!.end(); + } catch { + /* child already gone */ + } + }, WRITE_DELAY_MS); + } else if (feed === "close") { + child.stdin!.end(); + } + }); + + (async () => { + await runRole("aliased-data", "delayed"); + await runRole("param-data", "delayed"); + await runRole("end-only", "close"); + await runRole("in-timeout", "delayed"); + await runRole("with-timer", "delayed"); + await runRole("no-listener", "hold"); + await runRole("paused", "hold"); + console.log("done"); + })(); +} diff --git a/test-files/test_gap_9421_async_output_flush.ts b/test-files/test_gap_9421_async_output_flush.ts new file mode 100644 index 0000000000..eed67780bc --- /dev/null +++ b/test-files/test_gap_9421_async_output_flush.ts @@ -0,0 +1,180 @@ +// #9421 — the async queue-and-flush write path, pinned. +// +// NOT a gap test: every shape below already passes on unfixed `main`, and that +// is the point. #9421 reports that a claude-code session transcript comes out +// 1 line where Node writes 5, and attributes it to the session writer's async +// `insertQueueOperation` → `flush` path losing records ("work enqueued +// asynchronously and flushed before exit is lost; sync writes land"). This +// fixture is that attribution's test: it drives the shapes the report names, +// including a faithful transliteration of claude-code's own `SessionWriter` +// (`scheduleDrain` → `setTimeout(FLUSH_INTERVAL_MS = 100)` → `await +// drainWriteQueue()` → `await appendFile`, alongside the one `appendFileSync` +// record the report says is the only survivor). Perry matches Node in all of +// them, so the async-flush attribution is wrong and the divergence is upstream +// of the writer. +// +// The 1-vs-5 signature does have an exact cause, and this fixture pins it too: +// `writer-exit-early` exits before the 100 ms drain timer fires and lands +// exactly ONE record — the synchronous one — under BOTH engines. So the +// symptom identifies a run that ended too early, not a flush that failed. +import { spawn } from "node:child_process"; +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; + +const ROLE_ENV = "PERRY_9421_ROLE"; +const role = process.env[ROLE_ENV] ?? ""; +const BIG_LINE = "y".repeat(1023) + "\n"; +const BIG_LINES = 200; // 204800 bytes — comfortably past one pipe buffer + +function transcript(): string { + return path.join(os.tmpdir(), "perry_9421_" + process.pid + ".jsonl"); +} + +// claude-code's session writer, transliterated from the bundle. +class SessionWriter { + queues = new Map void }[]>(); + flushTimer: ReturnType | null = null; + activeDrain: Promise | null = null; + FLUSH_INTERVAL_MS = 100; + + enqueueWrite(file: string, entry: unknown): Promise { + return new Promise((resolve) => { + let q = this.queues.get(file); + if (!q) { + q = []; + this.queues.set(file, q); + } + q.push({ entry, resolve }); + this.scheduleDrain(); + }); + } + + scheduleDrain(): void { + if (this.flushTimer) return; + this.flushTimer = setTimeout(async () => { + this.flushTimer = null; + this.activeDrain = this.drainWriteQueue(); + await this.activeDrain; + this.activeDrain = null; + if (this.queues.size > 0) this.scheduleDrain(); + }, this.FLUSH_INTERVAL_MS); + } + + async drainWriteQueue(): Promise { + for (const [file, q] of this.queues) { + if (q.length === 0) continue; + const batch = q.splice(0); + let chunk = ""; + for (const item of batch) chunk += JSON.stringify(item.entry) + "\n"; + await fs.promises.appendFile(file, chunk, { mode: 0o600 }); + for (const item of batch) item.resolve(); + } + for (const [file, q] of this.queues) if (q.length === 0) this.queues.delete(file); + } +} + +function driveWriter(exitAfterMs: number | null): void { + const file = transcript(); + const writer = new SessionWriter(); + for (let i = 0; i < 4; i++) void writer.enqueueWrite(file, { type: "queued", i: i }); + // The one record the report says survives: a direct synchronous append. + fs.appendFileSync(file, JSON.stringify({ type: "last-prompt" }) + "\n"); + const report = () => { + let lines: string[] = []; + try { + lines = fs.readFileSync(file, "utf8").split("\n").filter((l) => l.length > 0); + } catch { + /* nothing written */ + } + try { + fs.unlinkSync(file); + } catch { + /* already gone */ + } + console.log("records:", lines.length); + for (const line of lines) console.log(" " + line); + }; + if (exitAfterMs === null) { + // Natural drain: read the file back one turn after the drain must have run. + setTimeout(report, 400); + } else { + setTimeout(() => { + report(); + process.exit(0); + }, exitAfterMs); + } +} + +if (role === "async-callbacks") { + // Multi-line output produced from async callbacks. + for (let i = 0; i < 5; i++) Promise.resolve().then(() => console.log("promise " + i)); + process.nextTick(() => console.log("tick")); + setTimeout(() => console.log("timer"), 1); +} else if (role === "write-loop") { + for (let i = 0; i < 5; i++) process.stdout.write("write " + i + "\n"); +} else if (role === "interleaved") { + console.log("out 1"); + console.error("err 1"); + console.log("out 2"); + console.error("err 2"); + console.log("out 3"); +} else if (role === "write-then-exit") { + for (let i = 0; i < 5; i++) process.stdout.write("exit-write " + i + "\n"); + console.log("exit-write done"); + process.exit(0); +} else if (role === "big") { + for (let i = 0; i < BIG_LINES; i++) process.stdout.write(BIG_LINE); +} else if (role === "writer-natural") { + driveWriter(null); +} else if (role === "writer-exit-late") { + driveWriter(300); +} else if (role === "writer-exit-early") { + // Exits before the 100 ms drain timer: ONE record, the synchronous one. + driveWriter(40); +} else { + const childArgs = [...process.execArgv, ...process.argv.slice(1)]; + const runRole = (name: string) => + new Promise((resolve) => { + // `interleaved` inherits both streams so the two writes keep their real + // relative order in the fixture's own merged output; separate pipes + // would only prove per-stream ordering. + const stdio: ("ignore" | "pipe" | "inherit")[] = + name === "interleaved" ? ["ignore", "inherit", "inherit"] : ["ignore", "pipe", "pipe"]; + const child = spawn(process.execPath, childArgs, { + env: { ...process.env, [ROLE_ENV]: name }, + stdio: stdio, + }); + let out = ""; + let err = ""; + child.stdout?.on("data", (chunk: Buffer | string) => { + out += String(chunk); + }); + child.stderr?.on("data", (chunk: Buffer | string) => { + err += String(chunk); + }); + child.on("close", (code) => { + console.log("== " + name + " exit: " + code); + // `big` is compared by size so the fixture's own output stays small. + if (name === "big") { + console.log("stdout bytes: " + out.length); + } else { + for (const line of out.split("\n")) if (line.length > 0) console.log("out| " + line); + } + for (const line of err.split("\n")) if (line.length > 0) console.log("err| " + line); + resolve(); + }); + }); + + (async () => { + await runRole("async-callbacks"); + await runRole("write-loop"); + await runRole("interleaved"); + await runRole("write-then-exit"); + await runRole("big"); + await runRole("writer-natural"); + await runRole("writer-exit-late"); + await runRole("writer-exit-early"); + console.log("done"); + })(); +}