diff --git a/changelog.d/features/10303-healthz-event-loop-lag.md b/changelog.d/features/10303-healthz-event-loop-lag.md new file mode 100644 index 0000000000..991c123021 --- /dev/null +++ b/changelog.d/features/10303-healthz-event-loop-lag.md @@ -0,0 +1 @@ +- **feat(resilience):** warn when `/healthz` is served under event-loop lag ≥200ms so a slow 200 is visible as sick, not healthy ([#10303](https://github.com/diegosouzapw/OmniRoute/issues/10303)) diff --git a/docs/ops/MONITORING_GUIDE.md b/docs/ops/MONITORING_GUIDE.md index 82a66eeb49..a25add9242 100644 --- a/docs/ops/MONITORING_GUIDE.md +++ b/docs/ops/MONITORING_GUIDE.md @@ -162,7 +162,7 @@ OmniRoute is a **single Node process** (one event loop). Stock Docker `HEALTHCHE | Probe | Recommended target | Notes | | --- | --- | --- | | **Startup** | HTTP `GET /healthz` with a long `failureThreshold` (or large `startPeriod`) | Cold start + SQLite migration can exceed a few seconds | -| **Readiness** | HTTP `GET /healthz` | Remove endpoints while starting/stopping; still flaps if the loop is CPU-blocked | +| **Readiness** | HTTP `GET /healthz` | Remove endpoints while starting/stopping; still flaps if the loop is CPU-blocked. A **200 in multiple seconds is not healthy** (#10303) — it means the event loop was starved before the 3-byte handler ran | | **Liveness** | **TCP** on the main service port (`PORT`, default `20128`), **or** HTTP `/healthz` with soft thresholds | Do **not** kill the pod on short event-loop stalls; busy ≠ dead | | **Deep health** | `GET /api/monitoring/health` from an external checker | Not for kubelet `livenessProbe` / tight `readinessProbe` | diff --git a/src/app/healthz/route.ts b/src/app/healthz/route.ts index 4ee01c32d2..5ac54700fd 100644 --- a/src/app/healthz/route.ts +++ b/src/app/healthz/route.ts @@ -1,4 +1,5 @@ import { getServerLifecyclePhase } from "@/lib/serverLifecycle"; +import { observeHealthzEventLoopLag } from "@/lib/healthzLag"; export const dynamic = "force-dynamic"; @@ -23,6 +24,7 @@ function createHealthResponse(method: "GET" | "HEAD"): Response { } export function GET(): Response { + observeHealthzEventLoopLag(); return createHealthResponse("GET"); } diff --git a/src/lib/healthzLag.ts b/src/lib/healthzLag.ts new file mode 100644 index 0000000000..fb4f17567e --- /dev/null +++ b/src/lib/healthzLag.ts @@ -0,0 +1,40 @@ +import { monitorEventLoopDelay } from "node:perf_hooks"; + +/** `/healthz` returning 200 after this much event-loop lag is already sick (#10303). */ +export const HEALTHZ_SLOW_LAG_MS = 200; +const WARN_EVERY_MS = 10_000; + +let lastWarnAt = 0; +let histogram: ReturnType | null = null; + +export function resetHealthzLagWarnStateForTests(): void { + lastWarnAt = 0; +} + +export function shouldWarnHealthzLag(lagMs: number, now = Date.now()): boolean { + if (!Number.isFinite(lagMs) || lagMs < HEALTHZ_SLOW_LAG_MS) return false; + if (now - lastWarnAt < WARN_EVERY_MS) return false; + lastWarnAt = now; + return true; +} + +export function formatHealthzLagWarning(lagMs: number): string { + return `GET /healthz event-loop lag ${Math.round(lagMs)}ms (HTTP 200 is not healthy; busy != ready)`; +} + +export function getEventLoopLagMs(): number { + if (!histogram) { + histogram = monitorEventLoopDelay({ resolution: 20 }); + histogram.enable(); + } + return histogram.mean / 1e6; +} + +export function observeHealthzEventLoopLag( + log: (msg: string) => void = console.warn, + lagMs = getEventLoopLagMs() +): boolean { + if (!shouldWarnHealthzLag(lagMs)) return false; + log(`[HEALTHZ] ${formatHealthzLagWarning(lagMs)}`); + return true; +} diff --git a/tests/unit/10303-healthz-lag.test.ts b/tests/unit/10303-healthz-lag.test.ts new file mode 100644 index 0000000000..afaab6e77f --- /dev/null +++ b/tests/unit/10303-healthz-lag.test.ts @@ -0,0 +1,35 @@ +import test from "node:test"; +import assert from "node:assert/strict"; + +import { + HEALTHZ_SLOW_LAG_MS, + formatHealthzLagWarning, + observeHealthzEventLoopLag, + resetHealthzLagWarnStateForTests, + shouldWarnHealthzLag, +} from "../../src/lib/healthzLag.ts"; + +test("shouldWarnHealthzLag ignores sub-threshold lag", () => { + resetHealthzLagWarnStateForTests(); + assert.equal(shouldWarnHealthzLag(0), false); + assert.equal(shouldWarnHealthzLag(HEALTHZ_SLOW_LAG_MS - 1), false); +}); + +test("shouldWarnHealthzLag fires once then debounce", () => { + resetHealthzLagWarnStateForTests(); + const t0 = 1_700_000_000_000; + assert.equal(shouldWarnHealthzLag(3748, t0), true); + assert.equal(shouldWarnHealthzLag(3748, t0 + 1000), false); + assert.equal(shouldWarnHealthzLag(3748, t0 + 10_000), true); +}); + +test("observeHealthzEventLoopLag logs when injected lag is high", () => { + resetHealthzLagWarnStateForTests(); + const messages: string[] = []; + assert.equal(observeHealthzEventLoopLag((m) => messages.push(m), 12), false); + assert.equal(messages.length, 0); + assert.equal(observeHealthzEventLoopLag((m) => messages.push(m), 3748), true); + assert.equal(messages[0], `[HEALTHZ] ${formatHealthzLagWarning(3748)}`); + assert.match(messages[0], /3748ms/); + assert.match(messages[0], /not healthy/); +});