fix(cli): os dev prints the ready banner whole, then the MCP connect block (#22410)

.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.

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) ──

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<BootReading | Error> = [];
+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<string> {
+  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<ReturnType<typeof setTimeout>> = [];
+    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([]);
+  });
+});