diff --git a/bin/cli/commands/serve.mjs b/bin/cli/commands/serve.mjs index ff7edb7b98..ce674be340 100644 --- a/bin/cli/commands/serve.mjs +++ b/bin/cli/commands/serve.mjs @@ -4,7 +4,12 @@ import { join, dirname } from "node:path"; import { fileURLToPath, pathToFileURL } from "node:url"; import { platform, totalmem } from "node:os"; import { t } from "../i18n.mjs"; -import { writePidFile, cleanupPidFile, waitForServer, resolveReadyTimeoutMs } from "../utils/pid.mjs"; +import { + writePidFile, + cleanupPidFile, + waitForServer, + resolveReadyTimeoutMs, +} from "../utils/pid.mjs"; import { ServerSupervisor, detectMitmCrash, @@ -305,7 +310,11 @@ export async function runServe(opts = {}) { opts.maxRestarts ?? 2, startedAt, useTray, - { trayReadyPort: opts.trayReadyPort, trayReadyToken: opts.trayReadyToken } + { + trayReadyPort: opts.trayReadyPort, + trayReadyToken: opts.trayReadyToken, + readyTimeoutMs: resolveReadyTimeoutMs({ timeoutMs: opts.readyTimeout }), + } ); } @@ -419,7 +428,7 @@ async function runWithSupervisor( maxRestarts, startedAt, useTray = false, - { trayReadyPort, trayReadyToken } = {} + { trayReadyPort, trayReadyToken, readyTimeoutMs = resolveReadyTimeoutMs() } = {} ) { if (showLog) process.env.OMNIROUTE_SHOW_LOG = "1"; writePidFile("supervisor", process.pid); @@ -458,8 +467,12 @@ async function runWithSupervisor( }); if (!showLog) { - const readyTimeoutMs = resolveReadyTimeoutMs({ timeoutMs: opts.readyTimeout }); - waitForServer(dashboardPort, readyTimeoutMs).then(async (up) => { + let lastProbeOutcome = null; + waitForServer(dashboardPort, readyTimeoutMs, { + onOutcome: (outcome) => { + lastProbeOutcome = outcome; + }, + }).then(async (up) => { if (up) { if (useTray) { const trayReady = await maybeStartTray(dashboardPort, apiPort, supervisor); @@ -483,7 +496,7 @@ async function runWithSupervisor( } onReady(dashboardPort, apiPort, noOpen, startedAt); } else { - reportReadinessTimeout(dashboardPort, supervisor); + reportReadinessTimeout(dashboardPort, supervisor, lastProbeOutcome); } }); } @@ -495,13 +508,28 @@ async function runWithSupervisor( // 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) { +export function reportReadinessTimeout(dashboardPort, supervisor, lastProbeOutcome = null) { const readyTimeoutMs = resolveReadyTimeoutMs(); const seconds = Math.round(readyTimeoutMs / 1000); console.error( `\n\x1b[33m⚠ Server did not respond within ${seconds}s.\x1b[0m It may still be starting, or may` + ` have failed silently.` ); + // The last probe classification separates a real boot failure (nothing ever + // bound the port, so the buffered output below is the reason) from a server + // that IS listening and merely did not answer the health route in time: + // very likely usable already, with only the readiness signal timed out. + if (lastProbeOutcome === "hanging" || lastProbeOutcome === "fast-reject") { + console.error( + ` Port ${dashboardPort} IS accepting connections, so the server is probably up and` + + ` still warming up. Check the dashboard before restarting it.` + ); + } else if (lastProbeOutcome === "not-listening") { + console.error( + ` Nothing is listening on port ${dashboardPort}, so the server never bound it and the` + + ` output below is the reason.` + ); + } console.error( ` Tip: set OMNIROUTE_READY_TIMEOUT_MS=${readyTimeoutMs * 2} or --ready-timeout ${readyTimeoutMs * 2} for slower cold starts.` ); diff --git a/bin/cli/utils/pid.mjs b/bin/cli/utils/pid.mjs index 4a3721bfdc..e12f2ada30 100644 --- a/bin/cli/utils/pid.mjs +++ b/bin/cli/utils/pid.mjs @@ -63,6 +63,24 @@ export function sleep(ms) { return new Promise((resolve) => setTimeout(resolve, ms)); } +// A probe that times out is classified "hanging" and never counts toward +// readiness (#6800), so a FIXED per-probe timeout puts a hard ceiling on how +// slow a healthy first response is allowed to be. On a cold Windows boot the +// health route resolves ~10 dynamic imports and reads the DB before it can +// answer; when that first response lands past the ceiling the poll can never +// succeed, because each abort discards the in-flight request before the route +// finishes (its own 1s payload cache is never populated either) and the next +// probe restarts the same work into the same ceiling — for the whole budget. +// The CLI then printed "⚠ Server did not respond within 60s" over a server +// that went on to serve traffic normally. Escalating the timeout keeps #6800's +// guarantee (a socket that never answers still yields "hanging" forever) while +// letting a slow-but-real response actually be observed. +const INITIAL_PROBE_TIMEOUT_MS = 2000; +const MAX_PROBE_TIMEOUT_MS = 15000; +// Floor for the last probe of a budget that is nearly spent — long enough for a +// loopback round-trip, short enough not to overrun the caller's timeout. +const MIN_PROBE_TIMEOUT_MS = 250; + // #2460: Default raised from 15s to 60s so Windows users (slower Next.js // cold start due to filesystem watchers, antivirus, etc.) get a working // "server ready" signal instead of a phantom timeout while the server is @@ -83,18 +101,24 @@ export function resolveReadyTimeoutMs(overrides = {}) { if (typeof overrides.timeoutMs === "number" && overrides.timeoutMs > 0) { return overrides.timeoutMs; } - const envValue = Number.parseInt( - process.env.OMNIROUTE_READY_TIMEOUT_MS || "", - 10 - ); + const envValue = Number.parseInt(process.env.OMNIROUTE_READY_TIMEOUT_MS || "", 10); return Number.isFinite(envValue) && envValue > 0 ? envValue : DEFAULT_READY_TIMEOUT_MS; } -export async function waitForServer(port, timeout = 60000) { +// `onOutcome` receives every probe classification so a caller can tell a +// "nothing ever bound the port" timeout apart from a "port is up, the health +// route is just still warming" one when it reports the failure. +export async function waitForServer(port, timeout = 60000, { onOutcome } = {}) { const start = Date.now(); let tcpListeningSince = null; + let probeTimeout = INITIAL_PROBE_TIMEOUT_MS; while (Date.now() - start < timeout) { - const outcome = await pollHealthOnce(port); + const remaining = timeout - (Date.now() - start); + const outcome = await pollHealthOnce( + port, + Math.max(MIN_PROBE_TIMEOUT_MS, Math.min(probeTimeout, remaining)) + ); + onOutcome?.(outcome); if (outcome === "ready") return true; if (outcome === "fast-reject") { if (tcpListeningSince === null) tcpListeningSince = Date.now(); @@ -103,6 +127,11 @@ export async function waitForServer(port, timeout = 60000) { // "hanging" (request timed out with no response at all) or // "not-listening" — neither counts toward the grace window. tcpListeningSince = null; + // Only a hang says "this server may simply need longer to answer"; + // widen the next probe instead of aborting into the same ceiling again. + if (outcome === "hanging") { + probeTimeout = Math.min(probeTimeout * 2, MAX_PROBE_TIMEOUT_MS); + } } await sleep(500); } @@ -115,11 +144,13 @@ export async function waitForServer(port, timeout = 60000) { // actively refused/reset (not a timeout) — the HTTP server is alive and // answering quickly, just not routing this endpoint yet (#2460). // - "hanging": the request timed out waiting for any response — the -// process accepted the TCP connection but never answered (#6800). +// process accepted the TCP connection but never answered (#6800). The +// caller widens `probeTimeoutMs` after a hang so a merely slow (rather +// than dead) server is not aborted into the same ceiling on every probe. // - "not-listening": nothing is accepting connections on the port at all. // #11766: probe both IPv4 and IPv6 loopback to handle servers listening on // either family (or both). -async function pollHealthOnce(port) { +async function pollHealthOnce(port, probeTimeoutMs = INITIAL_PROBE_TIMEOUT_MS) { const hosts = ["127.0.0.1", "::1"]; const outcomes = []; @@ -128,7 +159,7 @@ async function pollHealthOnce(port) { hosts.map(async (host) => { try { const res = await fetch(`http://${host}:${port}/api/monitoring/health`, { - signal: AbortSignal.timeout(2000), + signal: AbortSignal.timeout(probeTimeoutMs), }); return { host, outcome: res.ok ? "ready" : "fast-reject" }; } catch (err) { diff --git a/changelog.d/fixes/12484-cli-readiness-probe-timeout.md b/changelog.d/fixes/12484-cli-readiness-probe-timeout.md new file mode 100644 index 0000000000..b53a7013b6 --- /dev/null +++ b/changelog.d/fixes/12484-cli-readiness-probe-timeout.md @@ -0,0 +1 @@ +- **fix(cli):** `omniroute serve` no longer reports "Server did not respond within 60s" for a server that is actually up: the readiness probe's per-attempt timeout now escalates (2s, 4s, 8s, 15s, clamped to the time left in the budget) instead of aborting every attempt at a fixed 2s, so a health route that needs more than 2s for its first response is observed rather than repeatedly torn down. The timeout diagnostic now also states whether the port was accepting connections. ([#12484](https://github.com/diegosouzapw/OmniRoute/pull/12484)) diff --git a/tests/unit/waitForServer-slow-first-response.test.mjs b/tests/unit/waitForServer-slow-first-response.test.mjs new file mode 100644 index 0000000000..4bdbfe17fc --- /dev/null +++ b/tests/unit/waitForServer-slow-first-response.test.mjs @@ -0,0 +1,130 @@ +// Regression test for the "⚠ Server did not respond within 60s" false alarm on a +// server that is actually healthy: `omniroute serve` printed the readiness-timeout +// diagnostic while the process went on to serve traffic normally. +// +// Cause: every probe of /api/monitoring/health was aborted after a FIXED 2s +// (`AbortSignal.timeout(2000)`), and a probe that times out is classified +// "hanging", which waitForServer refuses to count toward readiness (#6800). +// So whenever the first health response takes longer than 2s — a cold Windows +// boot where that route resolves ~10 dynamic imports and reads the DB — the poll +// can never succeed: each abort discards the in-flight request before the route +// finishes (so the route's own 1s payload cache is never populated either), and +// 500ms later a fresh probe restarts the same work into the same 2s ceiling, for +// the whole 60s budget. Same failure family as #10508, which fixed it by taking a +// DNS lookup out of that 2s budget rather than by widening the budget. +// +// Fix: escalate the per-probe timeout (2s → 4s → 8s → 15s) so a slow-but-real +// response is observed instead of aborted forever, clamped to the remaining +// budget so the total wait still honours the caller's timeout. + +import { test } from "node:test"; +import assert from "node:assert/strict"; +import http from "node:http"; +import net from "node:net"; +import { waitForServer } from "../../bin/cli/utils/pid.mjs"; + +const SLOW_RESPONSE_MS = 3200; // > the initial 2s probe timeout + +test("waitForServer reports ready when the health response outlasts a probe timeout", async () => { + let served = 0; + const server = http.createServer((req, res) => { + served += 1; + // Answer only after a delay that exceeds the initial probe timeout. An + // aborted probe tears the socket down before this fires — exactly how the + // real health route loses all of its work on every abort. + const timer = setTimeout(() => { + if (res.writableEnded || res.destroyed) return; + res.writeHead(200, { "content-type": "application/json" }); + res.end('{"status":"healthy"}'); + }, SLOW_RESPONSE_MS); + res.on("close", () => clearTimeout(timer)); + res.on("error", () => {}); + }); + + await new Promise((resolve, reject) => { + server.once("error", reject); + server.listen(0, "127.0.0.1", resolve); + }); + const port = server.address().port; + + try { + const start = Date.now(); + const ready = await waitForServer(port, 30000); + const elapsedMs = Date.now() - start; + + assert.equal( + ready, + true, + `waitForServer() reported ready=false after ${elapsedMs}ms (${served} probe(s)) even ` + + `though /api/monitoring/health answered 200 in ${SLOW_RESPONSE_MS}ms — a healthy ` + + `server that is merely slower than one probe timeout must not be declared timed out.` + ); + assert.ok( + elapsedMs < 30000, + `expected readiness well before the 30s budget, took ${elapsedMs}ms` + ); + } finally { + server.close(); + } +}); + +test("escalating probe timeouts stay clamped to the caller's remaining budget", async () => { + // A socket that accepts TCP and never answers must still resolve false at + // (roughly) the caller's timeout — an escalating per-probe timeout must never + // let a single in-flight probe overrun the overall budget (#6800 guard). + const server = net.createServer(() => {}); + await new Promise((resolve, reject) => { + server.once("error", reject); + server.listen(0, "127.0.0.1", resolve); + }); + const port = server.address().port; + + try { + const start = Date.now(); + const ready = await waitForServer(port, 8000); + const elapsedMs = Date.now() - start; + + assert.equal(ready, false, "a never-answering socket must not be reported ready"); + assert.ok( + elapsedMs < 12000, + `waitForServer overran its 8s budget by more than 4s (took ${elapsedMs}ms) — a probe ` + + `timeout must be clamped to the time left in the budget` + ); + } finally { + server.close(); + } +}); + +test("readiness-timeout diagnostic distinguishes a listening port from a dead one", async () => { + const { reportReadinessTimeout } = await import("../../bin/cli/commands/serve.mjs"); + const supervisor = { getRecentLog: () => [] }; + + const capture = async (lastProbeOutcome) => { + const lines = []; + const origErr = console.error.bind(console); + console.error = (...args) => lines.push(args.join(" ")); + try { + reportReadinessTimeout(20128, supervisor, lastProbeOutcome); + } finally { + console.error = origErr; + } + return lines.join("\n"); + }; + + const hanging = await capture("hanging"); + assert.match( + hanging, + /IS accepting connections/, + "a timeout against a listening port must say the server is probably up, not just that it " + + "failed — that is the difference between a scary false alarm and an accurate hint" + ); + + const dead = await capture("not-listening"); + assert.match(dead, /Nothing is listening/, "a port that never bound must be reported as such"); + assert.doesNotMatch(dead, /IS accepting connections/); + + // Callers that pass no classification (and the #6321 test) keep the old output. + const unknown = await capture(undefined); + assert.doesNotMatch(unknown, /IS accepting connections|Nothing is listening/); + assert.match(unknown, /did not respond/); +});