diff --git a/CHANGELOG.md b/CHANGELOG.md index d570d9eace..8486f2b196 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ _Living section — bullets land here as PRs merge into `release/v3.8.47` (paral - **fix(providers):** stop Antigravity connections from falsely reporting **all-accounts quota-exhausted** ([#6295](https://github.com/diegosouzapw/OmniRoute/issues/6295)) — `genericQuotaFetcher.ts::percentUsedForQuota()` ignored the `fractionReported` flag and defaulted an unreported model's `remainingPercentage` to 0, which computed as 100% used; since `convertUsageToQuotaInfo()` takes the worst-case window across a connection, a single model with no reported fraction dragged the whole account into `limitReached` and `quotaPreflight` skipped it. `percentUsedForQuota()` now returns `null` (unknown, window ignored) whenever `fractionReported === false`, before falling back to `remainingPercentage`. Regression guard: `tests/unit/generic-quota-fetcher.test.ts`. - **fix(providers):** grok-cli (Grok Build) now strips `reasoning_effort`/`reasoning` before forwarding the request ([#6288](https://github.com/diegosouzapw/OmniRoute/issues/6288)) — Claude Code sends `reasoning_effort` on every request (routing the Opus slot), which Grok Build's upstream chat-proxy endpoint rejects with a 400; `transformRequest()`'s existing `UNSUPPORTED` sampling-param strip list (#5273) never covered it. Regression guard: `tests/unit/grok-cli-reasoning-strip-6288.test.ts`. +- **fix(cli):** `omniroute serve` no longer hangs silently on a readiness timeout ([#6321](https://github.com/diegosouzapw/OmniRoute/issues/6321)) — the child server's stdout was piped to `"ignore"` whenever `--log`/`OMNIROUTE_SHOW_LOG` wasn't set (the default), discarding any debug output, and `runWithSupervisor`'s `waitForServer(...).then((up) => { if (up) {...} })` had no `else` branch, so a boot that never became ready produced zero further output after "⏳ Starting server...". Stdout is now buffered alongside stderr (`ServerSupervisor.getRecentLog()`), and a timeout prints a clear diagnostic plus the buffered output instead of staying silent. Does not by itself explain why boot never completes on a given machine — see the issue for further reproduction. Regression guard: `tests/unit/cli-serve-readiness-timeout-6321.test.ts`. ### 📝 Maintenance diff --git a/bin/cli/commands/serve.mjs b/bin/cli/commands/serve.mjs index ab9d793ca3..b7abd7beeb 100644 --- a/bin/cli/commands/serve.mjs +++ b/bin/cli/commands/serve.mjs @@ -351,11 +351,35 @@ async function runWithSupervisor( if (up) { if (useTray) await maybeStartTray(dashboardPort, apiPort, supervisor); onReady(dashboardPort, apiPort, noOpen, startedAt); + } else { + reportReadinessTimeout(dashboardPort, supervisor); } }); } } +// #6321: waitForServer resolving `false` used to fall through silently — the CLI +// printed the banner + "⏳ Starting server..." and then produced ZERO further +// output forever, even though the child process may well have crashed or be +// stuck (issue reports show the server sometimes actually comes up later, or is +// reachable directly while the CLI still looks hung). Surface a clear diagnostic +// plus whatever stdout/stderr the child buffered instead of going silent. +export function reportReadinessTimeout(dashboardPort, supervisor) { + console.error( + `\n\x1b[33m⚠ Server did not respond within 60s.\x1b[0m It may still be starting, or may` + + ` have failed silently.` + ); + console.error(` Try: curl -I http://localhost:${dashboardPort}/api/monitoring/health`); + console.error(` Or: rerun with \x1b[36m--log\x1b[0m to see live server output.\n`); + + const recentLog = supervisor?.getRecentLog?.() ?? []; + if (recentLog.length) { + console.error("--- Recent server output ---"); + recentLog.forEach((l) => console.error(l)); + console.error("--- End recent output ---\n"); + } +} + let _killTray = null; function killTrayIfActive() { if (_killTray) { diff --git a/bin/cli/runtime/processSupervisor.mjs b/bin/cli/runtime/processSupervisor.mjs index 63f2a9912f..1af7c9313c 100644 --- a/bin/cli/runtime/processSupervisor.mjs +++ b/bin/cli/runtime/processSupervisor.mjs @@ -35,22 +35,32 @@ export class ServerSupervisor { // heap via NODE_OPTIONS (a CLI arg would shadow/override their value). The // calibrated heap is already carried by env.NODE_OPTIONS either way. const heapArgs = buildNodeHeapArgs(process.env, this.memoryLimit); + // #6321: stdout used to be discarded (`"ignore"`) whenever `--log`/OMNIROUTE_SHOW_LOG + // wasn't set (the default) — any debug/pino output written to stdout vanished + // silently, so a boot that never becomes ready looked like a dead hang with zero + // output even at APP_LOG_LEVEL=debug. Pipe stdout too and buffer it alongside + // stderr so a readiness timeout can surface what the child actually printed. this.child = spawn("node", [...heapArgs, this.serverPath], { cwd: dirname(this.serverPath), env: this.env, - stdio: showLog ? "inherit" : ["ignore", "ignore", "pipe"], + stdio: showLog ? "inherit" : ["ignore", "pipe", "pipe"], }); writePidFile("server", this.child.pid); + const bufferOutput = (data) => { + const lines = data.toString().split("\n").filter(Boolean); + this.crashLog.push(...lines); + if (this.crashLog.length > CRASH_LOG_LINES) { + this.crashLog = this.crashLog.slice(-CRASH_LOG_LINES); + } + }; + + if (this.child.stdout) { + this.child.stdout.on("data", bufferOutput); + } if (this.child.stderr) { - this.child.stderr.on("data", (data) => { - const lines = data.toString().split("\n").filter(Boolean); - this.crashLog.push(...lines); - if (this.crashLog.length > CRASH_LOG_LINES) { - this.crashLog = this.crashLog.slice(-CRASH_LOG_LINES); - } - }); + this.child.stderr.on("data", bufferOutput); } this.child.on("error", (err) => this.handleExit(-1, err)); @@ -107,6 +117,12 @@ export class ServerSupervisor { }, delay); } + // #6321: exposes the buffered stdout+stderr lines so a caller (e.g. a readiness + // timeout) can print what the child actually said instead of silence. + getRecentLog() { + return [...this.crashLog]; + } + dumpCrashLog() { console.error("\n--- Server crash log ---"); this.crashLog.forEach((l) => console.error(l)); diff --git a/tests/unit/cli-serve-readiness-timeout-6321.test.ts b/tests/unit/cli-serve-readiness-timeout-6321.test.ts new file mode 100644 index 0000000000..5ccf73587c --- /dev/null +++ b/tests/unit/cli-serve-readiness-timeout-6321.test.ts @@ -0,0 +1,64 @@ +import test from "node:test"; +import assert from "node:assert/strict"; + +// #6321: `omniroute serve` printed the banner + "⏳ Starting server..." then hung +// forever with ZERO further output whenever waitForServer() timed out (resolved +// `false`) — `runWithSupervisor`'s `.then((up) => { if (up) {...} })` had no `else` +// branch, so a boot that never became ready was indistinguishable from a genuine +// infinite hang, even at APP_LOG_LEVEL=debug (stdout was also being discarded — +// see the companion assertion on ServerSupervisor.getRecentLog()). + +test("reportReadinessTimeout prints a diagnostic instead of staying silent (#6321)", async () => { + const logs: string[] = []; + const origErr = console.error.bind(console); + console.error = (...args: unknown[]) => logs.push(args.join(" ")); + + try { + const { reportReadinessTimeout } = await import("../../bin/cli/commands/serve.mjs"); + assert.equal( + typeof reportReadinessTimeout, + "function", + "serve.mjs must export a readiness-timeout diagnostic handler" + ); + + const fakeSupervisor = { + getRecentLog: () => ["[server] booting...", "[server] waiting on migrations"], + }; + reportReadinessTimeout(20128, fakeSupervisor); + + const combined = logs.join("\n"); + assert.notEqual(combined.trim(), "", "must not silently produce zero output on a timeout"); + assert.ok( + combined.includes("did not respond") || combined.toLowerCase().includes("60s"), + `expected a clear readiness-timeout message, got:\n${combined}` + ); + assert.ok( + combined.includes("booting") && combined.includes("migrations"), + "must surface the buffered server output instead of discarding it" + ); + } finally { + console.error = origErr; + } +}); + +test("ServerSupervisor.getRecentLog() exposes buffered output for readiness diagnostics (#6321)", async () => { + const { ServerSupervisor } = await import("../../bin/cli/runtime/processSupervisor.mjs"); + + const supervisor = new ServerSupervisor({ + serverPath: "/fake/server.js", + env: {}, + maxRestarts: 0, + }); + + assert.equal( + typeof supervisor.getRecentLog, + "function", + "ServerSupervisor must expose getRecentLog() so callers can surface buffered output" + ); + + // Simulate lines that arrived on the child's stdout/stderr before a readiness + // timeout — previously stdout was piped to "ignore" and never reached crashLog. + supervisor.crashLog = ["stdout: server starting", "stderr: waiting for db"]; + const recent = supervisor.getRecentLog(); + assert.deepEqual(recent, ["stdout: server starting", "stderr: waiting for db"]); +});