diff --git a/CHANGELOG.md b/CHANGELOG.md index 9f87913..5188819 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,11 @@ This file records what changes **in the product** – process and session state ## [Unreleased] +### Fixed +- `/api/health` reports the AI service as `starting` instead of `failed` when it does not answer in time – + on the showcase usually the cold start of the scaled-to-zero container; after 30 s without an answer it + reads `failed` again, so a real outage is not hidden (#81). + ## [0.1.0] – 2026-09-27 First release: the pilot scope – intake of e-mail and PDF/Excel/Word, AI extraction with sources and diff --git a/docs/technical/api.md b/docs/technical/api.md index 60e53e5..ae22f6f 100644 --- a/docs/technical/api.md +++ b/docs/technical/api.md @@ -9,9 +9,10 @@ |---|---| | 200 | `{"status":"ok","checks":{"database":"ok","storage":"ok"},"dependencies":{"aiService":"ok"},"backlog":{"request-process":0,"request-export":0}}` | | 503 | `{"status":"degraded","checks":{"":"failed", …}}` – names only, never hosts, users or error text | +| 200 | `dependencies.aiService`: `ok`, `failed` (answered with an error / refused) or `starting` (no answer within the probe's 2 s – e.g. a cold start, #81; still no answer after 30 s → `failed`, #88); informational, never changes the status | | 503 | `{"status":"degraded","checks":{"config":"failed"}}` – invalid configuration (the server log names the variables) | -- Each check has a 3 s time limit; `cache-control: no-store`. +- Each check has a 3 s time limit (the AI service probe aborts itself after 2 s); `cache-control: no-store`. - Cost per call: one `select 1` and one S3 `HeadBucket`; the informational parts (AI-service ping, two backlog counts on `pgboss.job`) are cached for 10 s, so they run at most once per window. The backlog is summed over all companies (no tenant data, but it shows overall activity to an unauthenticated diff --git a/docs/technical/deployment-vercel.md b/docs/technical/deployment-vercel.md index e7483ce..a3f5821 100644 --- a/docs/technical/deployment-vercel.md +++ b/docs/technical/deployment-vercel.md @@ -141,7 +141,9 @@ step is idempotent: repeat it whenever visitors have decided the samples, and it ## 8. Smoke check -1. `GET /api/health` → 200, `database` and `storage` `ok`, `aiService` `ok`. +1. `GET /api/health` → 200, `database` and `storage` `ok`, `aiService` `ok`. Right after a pause the first + call may read `aiService` `starting` (the container's cold start, ~6 s) – repeat after 10 s. If it keeps + timing out for more than 30 s it reads `failed`: then check the AI project and `AI_SERVICE_URL` (#81, #88). 2. Drain route: without header → 401; with the secret → 200 JSON. 3. The banner „Demo – nur synthetische Daten" is visible on the login page. 4. Sign in as the seeded admin, upload a synthetic `.eml` (like the one in `tests/e2e/review-smoke.spec.ts`) diff --git a/docs/technical/operations.md b/docs/technical/operations.md index 5fcd1b5..1ca88a2 100644 --- a/docs/technical/operations.md +++ b/docs/technical/operations.md @@ -95,9 +95,12 @@ never its message) and `logger` for records of a library (docling, httpx, uvicor log line contains document content or personal data. - Correlation: the request id. The worker sends it to the AI service as `X-Request-Id`. Follow one request with `docker compose logs web worker ai | grep `. -- `/api/health` also reports `dependencies.aiService` (reachable or not) and `backlog` (waiting jobs per - queue). Both are informational and never turn the status into 503 – the AI service is an optional - compose profile. +- `/api/health` also reports `dependencies.aiService` and `backlog` (waiting jobs per queue). Both are + informational and never turn the status into 503 – the AI service is an optional compose profile. + `aiService` is `ok` (answered), `failed` (answered with an error, refused the connection, or no answer for + more than 30 s) or `starting` (no answer within the probe's 2 s – on the showcase usually the cold start of + the scaled-to-zero container, which the probe itself triggers; once it has started, the next call reads `ok`. + A failed or timed-out probe is not cached, #81/#88). ## Deploy step diff --git a/src/app/api/health/route.ts b/src/app/api/health/route.ts index 2f96920..1a36baa 100644 --- a/src/app/api/health/route.ts +++ b/src/app/api/health/route.ts @@ -3,13 +3,15 @@ import { pingDatabase } from "@/db"; import { countWaitingJobs } from "@/db/job-queue-client"; import { pingAiService } from "@/features/extraction"; import { QUEUES } from "@/features/jobs"; -import { cachedFor, logEvent, runHealthChecks } from "@/features/observability"; +import { cachedFor, logEvent, runHealthChecks, withStartupGrace } from "@/features/observability"; export const dynamic = "force-dynamic"; const CHECK_TIMEOUT_MS = 3_000; // Informational parts are cached (public endpoint): at most one AI ping and two counts per 10 s. const INFO_TTL_MS = 10_000; +// Longer than a cold start of the showcase AI container (~6 s): beyond it, no answer means failed (#88). +const AI_STARTUP_GRACE_MS = 30_000; let informational: | { aiService: () => Promise; process: () => Promise; exportQueue: () => Promise } | undefined; @@ -21,7 +23,7 @@ export async function GET(): Promise { try { const { config, database, storage } = getRuntime(); informational ??= { - aiService: cachedFor(INFO_TTL_MS, () => pingAiService(config.aiService.baseUrl)), + aiService: cachedFor(INFO_TTL_MS, withStartupGrace(() => pingAiService(config.aiService.baseUrl), AI_STARTUP_GRACE_MS)), process: cachedFor(INFO_TTL_MS, () => countWaitingJobs(database.pool, QUEUES.processRequest)), exportQueue: cachedFor(INFO_TTL_MS, () => countWaitingJobs(database.pool, QUEUES.exportRequest)), }; diff --git a/src/features/observability/health.test.ts b/src/features/observability/health.test.ts index e1b1579..6220465 100644 --- a/src/features/observability/health.test.ts +++ b/src/features/observability/health.test.ts @@ -1,5 +1,5 @@ import { describe, expect, it } from "vitest"; -import { cachedFor, runHealthChecks } from "./health"; +import { cachedFor, runHealthChecks, withStartupGrace } from "./health"; const ok = async () => {}; const failing = async () => { @@ -50,6 +50,66 @@ describe("runHealthChecks", () => { }); }); + // #81: a dependency that does not answer in time is usually a scaled-to-zero container waking up + // (the probe itself wakes it) – "starting", not "failed". An answered error stays "failed". + it("reports a dependency without an answer in time as starting, not failed", async () => { + const result = await runHealthChecks({ database: ok }, { timeoutMs: 20, dependencies: { aiService: hanging } }); + + expect(result.httpStatus).toBe(200); + expect(result.report.dependencies).toEqual({ aiService: "starting" }); + }); + + it("also counts the probe's own timeout (AbortSignal.timeout) as starting", async () => { + const aborted = async () => { + throw new DOMException("The operation was aborted due to timeout", "TimeoutError"); + }; + + const result = await runHealthChecks({ database: ok }, { timeoutMs: 100, dependencies: { aiService: aborted } }); + + expect(result.report.dependencies).toEqual({ aiService: "starting" }); + }); + + it("keeps a check (database, storage) that times out as failed with 503", async () => { + const result = await runHealthChecks({ database: hanging }, { timeoutMs: 20, dependencies: { aiService: hanging } }); + + expect(result.httpStatus).toBe(503); + expect(result.report).toMatchObject({ status: "degraded", checks: { database: "failed" }, dependencies: { aiService: "starting" } }); + }); + + // #88 review: a dependency that keeps timing out is not starting any more – a cold start takes ~6 s. + it("reports a dependency that keeps timing out beyond the grace period as failed, and starting again after an answer", async () => { + let clock = 0; + let answering = false; + const probe = withStartupGrace( + async () => { + if (!answering) throw new DOMException("The operation was aborted due to timeout", "TimeoutError"); + }, + 30_000, + () => clock, + ); + const state = async () => (await runHealthChecks({ database: ok }, { timeoutMs: 100, dependencies: { aiService: probe } })).report.dependencies?.aiService; + + expect(await state()).toBe("starting"); + clock = 29_999; + expect(await state()).toBe("starting"); + clock = 30_001; + expect(await state()).toBe("failed"); + + answering = true; + expect(await state()).toBe("ok"); + answering = false; + clock = 40_000; + expect(await state()).toBe("starting"); // a new cold start gets a new grace period + }); + + it("does not delay a real error: a refused connection is failed at once", async () => { + const probe = withStartupGrace(failing, 30_000, () => 0); + + const result = await runHealthChecks({ database: ok }, { timeoutMs: 100, dependencies: { aiService: probe } }); + + expect(result.report.dependencies).toEqual({ aiService: "failed" }); + }); + it("times out a hanging gauge as unknown (null) and never leaks error text", async () => { const result = await runHealthChecks({ database: ok }, { timeoutMs: 20, backlog: { "request-process": () => new Promise(() => {}) } }); diff --git a/src/features/observability/health.ts b/src/features/observability/health.ts index 3b8069e..510c62d 100644 --- a/src/features/observability/health.ts +++ b/src/features/observability/health.ts @@ -1,11 +1,16 @@ export type HealthCheck = () => Promise; export type CheckResult = "ok" | "failed"; +/** + * `starting` (#81): no answer within the time limit – for a scaled-to-zero container usually its cold + * start, which the probe itself triggers; the next probe normally reads `ok`. An answered error is `failed`. + */ +export type DependencyResult = CheckResult | "starting"; export interface HealthReport { status: "ok" | "degraded"; checks: Record; - /** Informational (#28): reachable or not – does not change the HTTP status (e.g. the optional AI profile). */ - dependencies?: Record; + /** Informational (#28, #81): ok, failed or starting – does not change the HTTP status (e.g. the optional AI profile). */ + dependencies?: Record; /** Informational (#28): jobs waiting per queue; null when unknown. */ backlog?: Record; } @@ -15,17 +20,24 @@ export interface HealthResult { report: HealthReport; } -// A check fails by throwing or by exceeding the time limit. Error details stay out of the -// report on purpose: /api/health is reachable without login and must not leak hosts or users. +// A required check fails by throwing or by exceeding the time limit; an informational dependency that +// does not answer in time is `starting` (#81). Error details stay out of the report on purpose: +// /api/health is reachable without login and must not leak hosts or users. export async function runHealthChecks( checks: Record, options: { timeoutMs: number; dependencies?: Record; backlog?: Record Promise> }, ): Promise { - const settleAll = (group: Record) => - Promise.all(Object.entries(group).map(async ([name, check]) => [name, await settle(check, options.timeoutMs)] as const)); + // A required check that does not answer in time has failed; an informational dependency is starting. + const settleAll = (group: Record, onTimeout: R) => + Promise.all( + Object.entries(group).map(async ([name, check]) => { + const outcome = await settle(check, options.timeoutMs); + return [name, outcome === "timeout" ? onTimeout : outcome] as const; + }), + ); const [entries, dependencies, backlog] = await Promise.all([ - settleAll(checks), - options.dependencies ? settleAll(options.dependencies) : undefined, + settleAll(checks, "failed" as const), + options.dependencies ? settleAll(options.dependencies, "starting" as const) : undefined, options.backlog ? Promise.all( Object.entries(options.backlog).map(async ([name, gauge]) => { @@ -45,16 +57,43 @@ export async function runHealthChecks( return { httpStatus: healthy ? 200 : 503, report }; } -async function settle(check: HealthCheck, timeoutMs: number): Promise { +const TIMED_OUT = Symbol("timed out"); + +/** + * A dependency that keeps timing out is not starting any more (#88 review): a cold start takes about + * 6 s, so timeouts for longer than `graceMs` read as failed – a wrong address, a dropped connection or a + * hanging service would otherwise show `starting` for ever. An answer (or a real error) ends the period. + */ +export function withStartupGrace(check: HealthCheck, graceMs: number, now: () => number = Date.now): HealthCheck { + let timingOutSince: number | undefined; + return async () => { + try { + await check(); + timingOutSince = undefined; + } catch (error) { + if (!isTimeout(error)) { + timingOutSince = undefined; + throw error; + } + timingOutSince ??= now(); + if (now() - timingOutSince > graceMs) throw new Error("no answer beyond the startup grace period"); + throw error; + } + }; +} +// Our own limit, or the probe's AbortSignal.timeout (a DOMException named TimeoutError). +const isTimeout = (error: unknown) => error === TIMED_OUT || (error instanceof Error && error.name === "TimeoutError"); + +async function settle(check: HealthCheck, timeoutMs: number): Promise { let timer: ReturnType | undefined; const timeout = new Promise((_, reject) => { - timer = setTimeout(() => reject(new Error("timeout")), timeoutMs); + timer = setTimeout(() => reject(TIMED_OUT), timeoutMs); }); try { await Promise.race([check(), timeout]); return "ok"; - } catch { - return "failed"; + } catch (error) { + return isTimeout(error) ? "timeout" : "failed"; } finally { clearTimeout(timer); } diff --git a/src/features/observability/index.ts b/src/features/observability/index.ts index 005825f..baa4874 100644 --- a/src/features/observability/index.ts +++ b/src/features/observability/index.ts @@ -1,3 +1,3 @@ // Public API of the `observability` module: health aggregation, structured log lines (IDs only). -export { cachedFor, runHealthChecks, type HealthCheck, type HealthReport, type HealthResult } from "./health"; +export { cachedFor, runHealthChecks, withStartupGrace, type CheckResult, type DependencyResult, type HealthCheck, type HealthReport, type HealthResult } from "./health"; export { captureLogs, logEvent, type LogDetail, type LogIds, type LogLevel } from "./log"; diff --git a/tests/integration/health.test.ts b/tests/integration/health.test.ts index a95f041..789a5b3 100644 --- a/tests/integration/health.test.ts +++ b/tests/integration/health.test.ts @@ -30,6 +30,24 @@ describe("GET /api/health", () => { }); }); + // #81/#88: the real undici abort of pingAiService (AbortSignal.timeout) reads as starting, not failed. + it("reports an AI service that does not answer in time as starting", async () => { + const server = createServer(() => { + // accepts the connection, never answers – like a container still starting + }); + await new Promise((resolve) => server.listen(0, "127.0.0.1", resolve)); + try { + vi.stubEnv("AI_SERVICE_URL", `http://127.0.0.1:${(server.address() as AddressInfo).port}`); + const { status, body } = await callHealth(); + + expect(status).toBe(200); + expect(body.dependencies).toEqual({ aiService: "starting" }); + } finally { + server.closeAllConnections(); + await new Promise((resolve) => server.close(resolve)); + } + }); + it("reports the AI service as reachable when its /healthz answers", async () => { const server = createServer((request, response) => void response.writeHead(request.url === "/healthz" ? 200 : 404).end('{"status":"ok"}')); await new Promise((resolve) => server.listen(0, "127.0.0.1", resolve));