diff --git a/.changeset/22410-dev-banner-order.md b/.changeset/22410-dev-banner-order.md new file mode 100644 index 00000000000..1ac7cb20356 --- /dev/null +++ b/.changeset/22410-dev-banner-order.md @@ -0,0 +1,11 @@ +--- +'@objectstack/cli': patch +--- + +fix(cli): `os dev` prints the server's ready banner whole, then the MCP connect block whole, instead of interleaving the two (#22410) + +Clause-β‘‘: no + +- **What a terminal showed.** `os dev` is two processes writing one terminal. The parent prints the MCP connect block (`πŸ€– MCP server β€” connect a coding agent:` with its Endpoint, Skill, Connect and Disable rows) when the `serve` child sends `objectstack:listening`, and the child sent that message before it printed its ready banner. Measured under a pty on the Build-with-Claude-Code tutorial project, 6 of 7 boots printed the block above or inside the banner. In 2 of them, banner lines landed between the block's rows, in one case the `➜ Console:` and `➜ MCP:` rows. A setup boot before those seven printed the `πŸ”‘ Dev admin` credential lines and the whole plugin section between `Skill` and `Connect`. +- **What changed.** The child now sends `objectstack:listening` after its ready banner and boot diagnostics have printed. The parent prints the block on that message, so it always comes last, under the banner's `Press Ctrl+C to stop` row. The order follows from the sequence itself, with no timer: the banner is written to the terminal before the message is sent. After the change, every measured boot printed the banner whole and then the block whole. +- **What did not change.** The message is still `{ type: 'objectstack:listening', port, url }`, carrying the port actually bound. The runtime state file is still written before either announcement, and `objectstack:seed-settled` still follows `objectstack:listening`. A program that spawns `os serve` with an IPC channel receives `objectstack:listening` slightly later than before: after the banner has printed instead of before. diff --git a/packages/cli/src/commands/serve.ts b/packages/cli/src/commands/serve.ts index d5e3bd6de32..ab5982d524a 100644 --- a/packages/cli/src/commands/serve.ts +++ b/packages/cli/src/commands/serve.ts @@ -718,10 +718,15 @@ export interface BoundPortChannels { * either announcement below: it is the file both of them send a consumer to. */ writeRuntimeState: (published: { port: number; url: string }) => void; - /** Sends {@link ListeningMessage}, when an IPC channel is open. */ - announceListening: (message: ListeningMessage) => void; - /** Prints the ready banner, whose `API:` row names the same address. */ + /** + * Prints the ready banner, whose `API:` row names the same address, and the + * boot diagnostics under it. β›” Must COMPLETE before the IPC message below: + * the `os dev` parent prints its MCP connect block on that message, into the + * same terminal (#22410). + */ printBanner: () => void; + /** Sends {@link ListeningMessage}, when an IPC channel is open. LAST β€” see above. */ + announceListening: (message: ListeningMessage) => void; } /** @@ -757,6 +762,25 @@ export interface BoundPortChannels { * into every consumer forever and hides it from the one place that can fix it. * The producer owns the ordering: **write the file, THEN announce it.** * + * ## The second race: two processes, one terminal (#22410) + * + * The IPC message is not only a fact for a program. The `os dev` parent prints + * its MCP connect block (`πŸ€– MCP server β€” connect a coding agent:` and its + * Endpoint / Skill / Connect / Disable rows) the moment the message arrives, + * into the terminal this process writes its banner to. Sent BEFORE the banner, + * the two processes wrote that terminal at once: measured under a pty on the + * Build-with-Claude-Code tutorial project, 6 of 7 boots printed the block + * above or inside the banner, 2 of them with banner lines inside the block, and + * one probe boot printed the whole credential and plugin section between + * `Skill` and `Connect`. + * + * So the banner comes SECOND and the message LAST. That makes the order + * causal, not timed: the banner is written synchronously (a terminal is + * synchronous stdio on POSIX, and `keepStderrNonBlocking` leaves a TTY + * alone), so every banner byte is in the terminal before the message is sent, + * and the parent prints only on receipt. β›” No sleep or timer orders anything + * here. The message's shape is unchanged; it arrives a banner's print later. + * * ## Why the channels are injected rather than called inline * * The ORDER is the contract here, and an order is only pinned by a test that @@ -783,11 +807,12 @@ export function publishBoundPort( const url = `${boundProtocol}://localhost:${boundPort}`; // 1 ─ THE FILE FIRST. Both announcements below send a consumer to it. channels.writeRuntimeState({ port: boundPort, url }); - // 2 ─ IPC: the `os dev` parent learns the real port without polling. - channels.announceListening({ type: 'objectstack:listening', port: boundPort, url }); - // 3 ─ The banner: a human, or a supervisor tailing stdout, reads the same + // 2 ─ The banner: a human, or a supervisor tailing stdout, reads the same // address β€” and by now the state file it names is on disk. channels.printBanner(); + // 3 ─ IPC LAST: the `os dev` parent learns the real port without polling, + // and prints its MCP connect block under a banner that has finished (#22410). + channels.announceListening({ type: 'objectstack:listening', port: boundPort, url }); } /** @@ -5312,14 +5337,16 @@ export default class Serve extends Command { // one so supervisors and the `os dev` parent never have to guess: // β€’ runtime.json: a small state file under OS_HOME for external // supervisors / health checks (pid + port + url). + // β€’ the ready banner, whose `API:` row names the same address. // β€’ IPC: when spawned with an 'ipc' channel (as `os dev` does), the // parent learns the real port without polling. - // β€’ the ready banner, whose `API:` row names the same address. // // ⭐ That list is in ORDER, and the order is the whole point (commit faff497fd): // the file is written BEFORE either channel announces the address that - // sends a consumer to it. {@link publishBoundPort} carries the race the - // old order lost, and the reason the repair is not reader-side polling. + // sends a consumer to it, and the banner is printed whole BEFORE the + // message that makes the `os dev` parent print into the same terminal + // (#22410). {@link publishBoundPort} carries both races the old orders + // lost, and the reason neither repair is a reader-side poll or a timer. publishBoundPort(boundPort, runtimeBoundPortChannels(printBanner), boundProtocol); // ── …and one beat later, whether the APP is ready too (#17329) ── diff --git a/packages/cli/test/dev-boot-output-order.integration.test.ts b/packages/cli/test/dev-boot-output-order.integration.test.ts new file mode 100644 index 00000000000..60d9817beeb --- /dev/null +++ b/packages/cli/test/dev-boot-output-order.integration.test.ts @@ -0,0 +1,293 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #22410 β€” the first screen of `os dev` prints in ONE fixed order, each block + * whole: the `serve` child's ready banner (credentials and boot diagnostics + * included), and only then the parent's MCP connect block. + * + * ## The defect, measured at the public door before the fix + * + * `os dev` is two processes writing one terminal. The parent prints the MCP + * connect block (`πŸ€– MCP server β€” connect a coding agent:` and its Endpoint / + * Skill / Connect / Disable rows) to its stdout when the child's + * `objectstack:listening` IPC message arrives, and the child used to send that + * message BEFORE it printed its ready banner to stderr. So both printed at + * once: under a pty, on the tutorial project, the block's rows came out + * interleaved line by line with the banner's β€” the `➜ API / Console / MCP` + * rows, `Tenancy`, `Plugins: 41 loaded`, and on some boots the + * `πŸ”‘ Dev admin: … / admin123` credential line, landing between `Connect` and + * `Disable`. The PR that closes this card carries the measured before/after + * tables. + * + * ## Why the order is now causal, and what this file pins + * + * `publishBoundPort` drives the banner BEFORE the IPC message. The banner is + * written synchronously β€” a terminal is a synchronous stdio on POSIX, and + * `keepStderrNonBlocking` deliberately leaves a TTY alone β€” so every banner + * byte is in the terminal before `objectstack:listening` is even sent, and the + * parent prints only on receipt. No timer orders anything. + * + * The SEQUENCE is pinned deterministically, in-process, by + * `serve-bound-port-publish-order.test.ts`. This file pins what a person sees: + * the real `os dev`, under a real pty (`script(1)` β€” the same tool + * `login-json-ndjson.e2e.test.ts` drives a TTY with, and it fails rather than + * skips without it), across several boots, because against the old order the + * damage was a race that a single boot can miss. For every boot: + * + * - the block's five rows are contiguous β€” nothing printed between them; + * - the `πŸ”‘ Dev admin` credential line is outside the block; + * - the block starts after the banner's last row (`Press Ctrl+C to stop`), so + * no parent row sits inside the banner either. + * + * ## Spawn shape + * + * `bin/run.js` with `NODE_ENV` unset β€” the shipped entry, resolving commands + * from `dist/` (`requireBuiltCli`). `--no-watch` keeps the watcher's own lines + * out of the reading; each boot gets a fresh database file so the dev admin is + * seeded, and its credential line printed, on every boot. A boot ends with a + * real Ctrl+C typed into the pty. Every boot runs in `beforeAll` and every `it` + * reads what it recorded. + */ + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { execFileSync, spawn, type ChildProcess } from 'node:child_process'; +import { mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join, resolve } from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { + childEnv, + E2E_SECRET_KEY, + randomPort, + requireBuiltCli, + RUN_JS_RESOLVES_FROM_DIST, +} from './helpers/serve-process.js'; +import { writeDefineStackConfig } from './helpers/define-stack-fixture.js'; + +const HERE = resolve(fileURLToPath(import.meta.url), '..'); +/** `bin/run.js` β€” the SHIPPED entrypoint. */ +const CLI = resolve(HERE, '../bin/run.js'); + +/** How many boots. Against the old order the damage was a race, so one boot proves little. */ +const BOOTS = 5; +const BOOT_TIMEOUT_MS = 180_000; +/** After the banner, how long the parent's block may take to arrive. */ +const BLOCK_GRACE_MS = 30_000; +/** After both have printed, how long to keep reading β€” late lines would land here. */ +const LINGER_MS = 2_000; +const ALL_BOOTS_TIMEOUT_MS = BOOTS * (BOOT_TIMEOUT_MS + BLOCK_GRACE_MS + 30_000); + +const SCAFFOLD = { + manifest: { id: 'com.example.order', namespace: 'order', version: '1.0.0', type: 'app', name: 'order' }, + objects: [{ + name: 'order_item', + label: 'Item', + sharingModel: 'private', + fields: { title: { type: 'text', label: 'Title' } }, + }], +}; + +const ESC = String.fromCharCode(27); +/** SGR colour codes and other CSI sequences a terminal session carries. */ +const CSI = new RegExp(`${ESC}\\[[0-9;?]*[A-Za-z]`, 'g'); +/** The ETX byte a terminal sends for Ctrl+C. */ +const CTRL_C = String.fromCharCode(3); + +const BLOCK_HEADER = 'MCP server β€” connect a coding agent:'; +/** The four rows under the header, in the order `printMcpConnectHint` prints them. */ +const BLOCK_ROWS = [/^\s+Endpoint\s/, /^\s+Skill\s/, /^\s+Connect\s/, /^\s+Disable\s+OS_MCP_SERVER_ENABLED=false/]; +const BANNER_TAIL = 'Press Ctrl+C to stop'; +const CREDENTIAL = 'Dev admin:'; + +interface BootReading { + boot: number; + /** The pty transcript, CSI sequences removed, split on line ends. */ + lines: string[]; +} + +const readings: Array = []; +const groups: ChildProcess[] = []; +let dir: string; + +function screenLines(raw: string): string[] { + return raw.replace(CSI, '').split(/\r?\n/).map((line) => line.replace(/\r/g, '')); +} + +/** Boot `os dev` under a pty until the banner and the block have both printed, then Ctrl+C it. */ +function bootUnderPty(boot: number): Promise { + const port = randomPort(); + const command = [ + `exec '${process.execPath}' '${CLI}' dev --no-watch`, + `-d 'file:boot${boot}.db' -p ${port}`, + ].join(' '); + return new Promise((resolveBoot, rejectBoot) => { + const child = spawn('script', ['-qfec', command, '/dev/null'], { + cwd: dir, + // `childEnv`, never a bare `...process.env` β€” see its header. `NODE_ENV` + // unset, so the built entry resolves its commands from `dist/`. Every + // variable that moves the block's origin is unset, so the block prints. + env: childEnv({ + OS_HOME: join(dir, 'home'), + OS_CLOUD_URL: 'off', + OS_DISABLE_CONSOLE: '1', + OS_SECRET_KEY: E2E_SECRET_KEY, + OS_DATABASE_URL: undefined, + OS_ARTIFACT_URL: undefined, + OS_ARTIFACT_PATH: undefined, + OS_MCP_SERVER_ENABLED: undefined, + OS_AUTH_URL: undefined, + BETTER_AUTH_URL: undefined, + OS_BASE_URL: undefined, + OS_MODE: undefined, + NODE_ENV: undefined, + NO_COLOR: undefined, + FORCE_COLOR: undefined, + }), + stdio: ['pipe', 'pipe', 'pipe'], + // Own process group: `script` owns the pty, whose session holds `dev` and its `serve` child. + detached: true, + }); + groups.push(child); + let raw = ''; + let bannerSeen = false; + let stopping = false; + let failure: Error | null = null; + const timers: Array> = []; + const stop = (err: Error | null) => { + if (stopping) return; + stopping = true; + failure = err; + // Keep reading for a moment: a line that would land late lands here. + timers.push(setTimeout(() => { try { child.stdin?.write(CTRL_C); } catch { /* pty gone */ } }, LINGER_MS)); + timers.push(setTimeout(() => { try { process.kill(-child.pid!, 'SIGKILL'); } catch { /* gone */ } }, LINGER_MS + 15_000)); + }; + timers.push(setTimeout( + () => stop(new Error(`boot ${boot}: os dev never printed its banner\n--- output ---\n${raw.slice(-4000)}`)), + BOOT_TIMEOUT_MS, + )); + const onData = (d: Buffer) => { + raw += d.toString('utf8'); + const text = raw.replace(CSI, ''); + if (!bannerSeen && text.includes(BANNER_TAIL)) { + bannerSeen = true; + timers.push(setTimeout( + () => stop(new Error(`boot ${boot}: the MCP block never printed\n--- output ---\n${raw.slice(-4000)}`)), + BLOCK_GRACE_MS, + )); + } + if (bannerSeen && screenLines(raw).some((l) => BLOCK_ROWS[3].test(l))) stop(null); + }; + child.stdout?.on('data', onData); + child.stderr?.on('data', onData); + child.on('exit', () => { + for (const t of timers) clearTimeout(t); + if (failure) rejectBoot(failure); + else if (!stopping) rejectBoot(new Error(`boot ${boot}: os dev exited before its banner\n--- output ---\n${raw.slice(-4000)}`)); + else resolveBoot(raw); + }); + }); +} + +beforeAll(async () => { + requireBuiltCli(RUN_JS_RESOLVES_FROM_DIST); + try { + execFileSync('script', ['--version'], { stdio: 'ignore', env: childEnv() }); + } catch { + throw new Error('script(1) from util-linux is required to put `os dev` on a real terminal β€” this file fails instead of skipping without one.'); + } + dir = mkdtempSync(join(tmpdir(), 'os-22410-dev-order-')); + writeDefineStackConfig(dir, SCAFFOLD); + // Sequential: each boot owns a port and a database, and two at once would race each other. + for (let boot = 1; boot <= BOOTS; boot++) { + try { + readings.push({ boot, lines: screenLines(await bootUnderPty(boot)) }); + } catch (error) { + readings.push(error instanceof Error ? error : new Error(String(error))); + } + } +}, ALL_BOOTS_TIMEOUT_MS); + +afterAll(() => { + for (const child of groups) { + if (child.exitCode === null && child.signalCode === null) { + try { process.kill(-child.pid!, 'SIGKILL'); } catch { /* group already gone */ } + } + } + try { rmSync(dir, { recursive: true, force: true }); } catch { /* ignore */ } +}); + +function recorded(): BootReading[] { + expect(readings, 'not every boot was run').toHaveLength(BOOTS); + for (const r of readings) if (r instanceof Error) throw r; + return readings as BootReading[]; +} + +/** One boot's reading of the screen: where the block starts and ends, and what printed inside it. */ +interface ScreenReading { + boot: number; + /** The block header's line, or -1. */ + header: number; + /** The block's last row (`Disable`), or -1. */ + disable: number; + /** Lines between the header and the last row that are not the block's own rows. */ + foreign: string[]; + /** The `πŸ”‘ Dev admin` line, or -1. */ + credential: number; + /** The banner's last row (`Press Ctrl+C to stop`), or -1. */ + tail: number; +} + +function readScreen(r: BootReading): ScreenReading { + const header = r.lines.findIndex((l) => l.includes(BLOCK_HEADER)); + const disable = header < 0 ? -1 : r.lines.findIndex((l, i) => i > header && BLOCK_ROWS[3].test(l)); + const foreign = header < 0 || disable < 0 + ? [] + : r.lines.slice(header + 1, disable).filter((l) => !BLOCK_ROWS.some((row) => row.test(l))).map((l) => l.trim()); + return { + boot: r.boot, + header, + disable, + foreign, + credential: r.lines.findIndex((l) => l.includes(CREDENTIAL)), + tail: r.lines.findIndex((l) => l.includes(BANNER_TAIL)), + }; +} + +/** + * Every boot's reading, after the control: each boot printed the whole block, + * its banner tail and its credential line, so every verdict below is a reading + * of something that is there rather than of an absence. + */ +function screens(): ScreenReading[] { + const all = recorded().map(readScreen); + const absent = all.flatMap((s) => [ + ...(s.header < 0 || s.disable < 0 ? [`boot ${s.boot}: no whole MCP connect block on the screen`] : []), + ...(s.tail < 0 ? [`boot ${s.boot}: no banner tail`] : []), + ...(s.credential < 0 ? [`boot ${s.boot}: no credential line β€” the boot did not seed its dev admin`] : []), + ]); + expect(absent, 'the control: every boot prints the block, the banner and the credential line').toEqual([]); + return all; +} + +describe('#22410 β€” `os dev` prints the banner, then the MCP block, each block whole', () => { + it('the MCP block\'s rows are contiguous on every boot', () => { + const split = screens() + .filter((s) => s.disable - s.header !== BLOCK_ROWS.length || s.foreign.length > 0) + .map((s) => `boot ${s.boot}: ${s.foreign.length} foreign line(s) inside the block: ${JSON.stringify(s.foreign)}`); + expect(split, `${split.length} of ${BOOTS} boots split the block`).toEqual([]); + }); + + it('the dev admin credential line sits outside the block on every boot', () => { + const inside = screens() + .filter((s) => s.credential > s.header && s.credential < s.disable) + .map((s) => `boot ${s.boot}: the credential line printed inside the MCP block`); + expect(inside, `${inside.length} of ${BOOTS} boots printed the credential inside the block`).toEqual([]); + }); + + it('the block comes after the whole banner on every boot β€” one fixed order', () => { + const early = screens() + .filter((s) => s.header < s.tail) + .map((s) => `boot ${s.boot}: the MCP block started before the banner finished`); + expect(early, `${early.length} of ${BOOTS} boots printed the block inside or above the banner`).toEqual([]); + }); +}); diff --git a/packages/cli/test/serve-bound-port-publish-order.test.ts b/packages/cli/test/serve-bound-port-publish-order.test.ts index 0a68fa6f892..6dbffe7bbb7 100644 --- a/packages/cli/test/serve-bound-port-publish-order.test.ts +++ b/packages/cli/test/serve-bound-port-publish-order.test.ts @@ -39,6 +39,16 @@ * The e2e keeps its own job β€” proving the three channels agree with the socket * (#13062). This file proves they cannot be announced before they are true. * + * ## The second constraint on the same sequence (#22410) + * + * The banner comes BEFORE the IPC message. The `os dev` parent prints its MCP + * connect block when `objectstack:listening` arrives, into the terminal the + * child prints its banner to; sent first, the message let the two processes + * write that terminal at once, and the block's rows came out interleaved with + * the banner's. The full order is therefore state-file β†’ banner β†’ IPC, and + * what a person sees under a pty is pinned by + * `dev-boot-output-order.integration.test.ts`. + * * ## β›” Why the real IPC leg is never CALLED here * * `runtimeBoundPortChannels().announceListening` is `process.send`, and under @@ -112,7 +122,7 @@ function withHome(home: string, fn: () => T): T { } describe('#13193 β€” `os serve` writes the state file BEFORE it announces the port', () => { - it('drives the three channels in the order state-file β†’ IPC β†’ banner', () => { + it('drives the three channels in the order state-file β†’ banner β†’ IPC', () => { const order: string[] = []; publishBoundPort(45671, { @@ -125,7 +135,7 @@ describe('#13193 β€” `os serve` writes the state file BEFORE it announces the po // announcing would satisfy that, and losing a channel is the defect in the // opposite direction β€” the one #13062 was filed for. expect(order, 'all three channels must fire, in this exact order').toEqual([ - 'state-file', 'ipc', 'banner', + 'state-file', 'banner', 'ipc', ]); }); @@ -223,7 +233,7 @@ describe('#13193 β€” `os serve` writes the state file BEFORE it announces the po }); expect(order, 'a failed write must not swallow the announcements').toEqual([ - 'state-file', 'ipc', 'banner', + 'state-file', 'banner', 'ipc', ]); expect(existsSync(join(home, RUNTIME_FILE)), 'the write really did fail').toBe(false); });