fix(cli): escalate the readiness probe timeout so a slow health response is not a phantom boot failure (#12484)

* fix(cli): escalate the readiness probe timeout so a slow health response is not a phantom boot failure

`omniroute serve` reported "Server did not respond within 60s" over servers that
were up and serving traffic. Every probe of /api/monitoring/health was aborted at
a fixed 2s, and a timed-out probe is classified "hanging", which never counts
toward readiness (#6800). So whenever the first health response takes longer than
2s the poll can never succeed: each abort discards the in-flight request before
the route finishes (its own 1s payload cache is never populated either), and
500ms later the next probe restarts the same work into the same ceiling, for the
whole 60s budget. Reproduced by the new test: against a health route that answers
200 in 3.2s, the old poller ran 12 probes over 30s and reported ready=false every
time.

The per-probe timeout now escalates after each hang (2s, 4s, 8s, 15s), clamped to
the time left in the budget so the caller's total timeout still holds. Only a hang
escalates, so #6800's guarantee is unchanged: a socket that accepts TCP and never
answers still resolves false. waitForServer also reports each probe outcome to an
optional onOutcome callback, and the readiness-timeout diagnostic uses it to say
whether the port was accepting connections, which separates "up and still warming"
from "never bound the port".

Same failure family as #10508, which fixed it by taking a DNS lookup out of the 2s
budget rather than by widening it. The heavy /api/monitoring/health route is what
makes that budget tight in the first place (its own docstring points high-frequency
pollers at /api/health/ping, which is what the Electron readiness poller uses);
switching the CLI probe route is a larger change, left as a follow-up.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CJf2dxEpiwZqyZujWk57T2

* chore(changelog): link the readiness-probe fix to PR 12484

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CJf2dxEpiwZqyZujWk57T2

---------

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>

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.`
   );

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

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

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/);
+});