diff --git a/src/__tests__/background-task-settle-guard.test.ts b/src/__tests__/background-task-settle-guard.test.ts new file mode 100644 index 000000000..9ce3fa914 --- /dev/null +++ b/src/__tests__/background-task-settle-guard.test.ts @@ -0,0 +1,178 @@ +/** + * Background work started inside a test must not outlive it. + * + * Several paths in this codebase start a promise, return without awaiting it, + * and log on the detached handle so the failure is not swallowed. Vitest + * replaces `globalThis.console` with a sink that forwards every write to the + * main thread as an `onUserConsoleLog` RPC call, awaits the calls in flight + * when it tears a test file down, and then REJECTS whatever was started after + * that point. A detached write that lands in that window fails the whole run + * with `EnvironmentTeardownError: Closing rpc while "onUserConsoleLog" was + * pending` — blamed on the file the worker was tearing down, which is not the + * test that started the work and need not contain a console call of its own. + * + * Both suite setups therefore await `settleBackgroundTasks()` after every + * test, and that only works while the detached paths keep registering what + * they start. + * + * These are tripwires, not proofs. The sweep below matches a detached + * `.catch()` / `.then()` whose handler writes to the console — the shape that + * actually produced the failure. A background path that logs some other way, + * or that logs from a callee rather than from the handler, is invisible to it. + */ +import { describe, it, expect } from "vitest"; +import { readFileSync } from "node:fs"; +import { join } from "node:path"; + +import { walkSourceFiles } from "./helpers/source-files"; +import { fireAndForget } from "@/lib/logging/fire-and-forget"; +import { + pendingBackgroundTaskCount, + settleBackgroundTasks, + trackBackgroundTask, +} from "@/lib/logging/background-tasks"; + +const ROOT = process.cwd(); +const SRC = join(ROOT, "src"); + +/** + * Detached console writers that deliberately stay unregistered. + * + * `cli/mcp-stdio.ts` is a process entrypoint: its `main().catch(...)` is the + * top-level failure handler and there is no test that runs it, so there is + * nothing for a registry to hold. `jobs/boss-instance.ts` awaits its handle — + * the matcher sees the `console` call in the following lines, not a detached + * promise. + */ +const UNREGISTERED_BY_DESIGN = new Set([ + "cli/mcp-stdio.ts", + "lib/jobs/boss-instance.ts", +]); + +/** Every non-test source file under `src/`, minus the generated Prisma client. */ +function sourceFiles(): string[] { + return walkSourceFiles(SRC, { floor: 3000 }) + .filter((rel) => !rel.startsWith("generated/")) + .filter((rel) => !rel.includes("__tests__")) + .filter((rel) => !rel.endsWith(".test.ts") && !rel.endsWith(".test.tsx")); +} + +/** Lines starting a `.catch()` / `.then()` whose handler writes to the console. */ +function consoleWritingHandlers(): { file: string; line: number }[] { + const found: { file: string; line: number }[] = []; + for (const rel of sourceFiles()) { + const lines = readFileSync(join(SRC, rel), "utf8").split("\n"); + lines.forEach((line, index) => { + if (!/\.(catch|then)\(/.test(line)) return; + const handler = lines.slice(index, index + 8).join("\n"); + if (!/console\.(log|warn|error|info|debug|trace)\(/.test(handler)) return; + found.push({ file: rel, line: index + 1 }); + }); + } + return found; +} + +describe("background-task settle contract", () => { + it("registers an in-flight task and drains it on settle", async () => { + let release: () => void = () => {}; + const task = new Promise((resolve) => { + release = resolve; + }); + + trackBackgroundTask(task); + expect(pendingBackgroundTaskCount()).toBe(1); + + let settled = false; + const settling = settleBackgroundTasks().then(() => { + settled = true; + }); + + // Settle must not resolve ahead of the task it is waiting on — that is the + // whole reason the registry exists. + await new Promise((resolve) => setTimeout(resolve, 20)); + expect(settled).toBe(false); + + release(); + await settling; + expect(settled).toBe(true); + // And nothing is retained once the task is done. + expect(pendingBackgroundTaskCount()).toBe(0); + }); + + it("registers what fireAndForget starts", async () => { + let release: () => void = () => {}; + fireAndForget( + new Promise((resolve) => { + release = resolve; + }), + { action: "guard.background.registered" }, + ); + expect(pendingBackgroundTaskCount()).toBe(1); + + release(); + await settleBackgroundTasks(); + expect(pendingBackgroundTaskCount()).toBe(0); + }); + + it("also awaits work a settling task starts itself", async () => { + let innerDone = false; + + fireAndForget( + Promise.resolve().then(() => { + fireAndForget( + new Promise((resolve) => + setTimeout(() => { + innerDone = true; + resolve(); + }, 10), + ), + { action: "guard.background.cascade.inner" }, + ); + }), + { action: "guard.background.cascade.outer" }, + ); + + await settleBackgroundTasks(); + expect(innerDone).toBe(true); + expect(pendingBackgroundTaskCount()).toBe(0); + }); + + it("keeps every detached console writer registered", () => { + const sites = consoleWritingHandlers(); + + // An empty sweep must not read as a pass: if the matcher stops finding the + // shape it is the matcher that broke, not the tree that got clean. Pinned + // below the five sites that exist today, so removing one legitimately does + // not trip a guard that is about the sweep being alive, not about freezing + // a count. + expect(sites.length).toBeGreaterThanOrEqual(3); + + const unregistered = sites.filter(({ file, line }) => { + if (UNREGISTERED_BY_DESIGN.has(file)) return false; + const lines = readFileSync(join(SRC, file), "utf8").split("\n"); + // The registration wraps the handle, so it opens on one of the few lines + // above the `.catch(` / `.then(` the sweep matched. + const preamble = lines.slice(Math.max(0, line - 5), line).join("\n"); + return !/trackBackgroundTask\(/.test(preamble); + }); + + expect( + unregistered.map(({ file, line }) => `src/${file}:${line}`), + "a detached promise logs to the console without registering — wrap the " + + "handled handle in trackBackgroundTask() so the suite can await it", + ).toEqual([]); + }); + + it("keeps the settle hook wired into both suite setups", () => { + for (const setup of [ + "vitest.setup.ts", + join("tests", "integration", "environment-setup.ts"), + ]) { + const source = readFileSync(join(ROOT, setup), "utf8"); + expect( + source.includes("settleBackgroundTasks"), + `${setup} no longer awaits background tasks after each test`, + ).toBe(true); + } + }); +}); diff --git a/src/lib/cache/server-cache.ts b/src/lib/cache/server-cache.ts index 8e4cead77..64447d7dc 100644 --- a/src/lib/cache/server-cache.ts +++ b/src/lib/cache/server-cache.ts @@ -35,6 +35,7 @@ * reaching into the private `Map`. */ +import { trackBackgroundTask } from "@/lib/logging/background-tasks"; import type { WorkoutsProjection } from "@/lib/workouts/list-read"; export interface ServerCacheOptions { @@ -416,15 +417,21 @@ export class ServerCache { // console.error stands in for the wide-event annotation; the // key is logged as its djb2 hash, matching the cache-outcome // meta convention, so the userId segment never reaches stdout. - refresh.catch((err) => { - console.error( - `cache.${this.opts.name ?? "unnamed"}.refresh_failed`, - JSON.stringify({ - key_hash: hashCacheKey(key), - error: err instanceof Error ? err.message : String(err), - }), - ); - }); + // Registered so the test suite can await it: the error below is a + // console write on a detached handle, and one that lands while a + // vitest worker is closing its RPC channel fails the whole run. + // No-op outside test. + trackBackgroundTask( + refresh.catch((err) => { + console.error( + `cache.${this.opts.name ?? "unnamed"}.refresh_failed`, + JSON.stringify({ + key_hash: hashCacheKey(key), + error: err instanceof Error ? err.message : String(err), + }), + ); + }), + ); } return { value: cachedEntry.value, outcome: "stale" }; } diff --git a/src/lib/logging/background-tasks.ts b/src/lib/logging/background-tasks.ts new file mode 100644 index 000000000..5516ef44e --- /dev/null +++ b/src/lib/logging/background-tasks.ts @@ -0,0 +1,87 @@ +/** + * The registry of detached background work, so a test can await what a + * request-path shortcut deliberately does not. + * + * ## The failure this exists for + * + * Several code paths start a promise and return without awaiting it, then log + * on the detached handle so the failure is not swallowed — `fireAndForget`, + * the stale-while-revalidate cache refresh, the offline query persister. That + * is right for production and hostile to a test runner: vitest replaces + * `globalThis.console` with a sink that forwards every write to the main + * thread as an `onUserConsoleLog` RPC call, and when a worker finishes a test + * file it awaits the calls in flight and then REJECTS whatever was started + * after that point. A detached write that lands in the window between those + * two steps fails the entire run with + * + * EnvironmentTeardownError: [vitest-worker]: Closing rpc while + * "onUserConsoleLog" was pending + * + * blamed on the file the worker was tearing down — which need not contain a + * single console call of its own, and never points at the test that started + * the work. Muting the console in tests would hide the log line the detached + * path exists to produce and leave the race in place; awaiting the work + * removes the precondition. + * + * ## Why the registry is test-only + * + * Production never awaits it, so tracking there would buy nothing and cost + * something real: a strong reference to every background promise for as long + * as it stays unsettled. One wedged task on a long-lived pg-boss worker would + * then be retained for the life of the process, which turns an observability + * affordance into a slow leak. Under test the worker is short-lived and the + * set is drained after every test, so neither concern applies. Outside test + * every call site keeps exactly the behaviour and cost it had before — start + * the promise, discard the handle, one boolean check. + * + * The module deliberately imports nothing: it is reachable from client code + * (`lib/pwa/query-persister.ts`) as well as from the server tree, and must not + * drag `node:async_hooks` into the browser bundle the way `./context` would. + */ +const TRACK_IN_FLIGHT = + typeof process !== "undefined" && + (process.env?.VITEST === "true" || process.env?.NODE_ENV === "test"); + +const inFlight = new Set>(); + +/** + * Register a detached promise so `settleBackgroundTasks()` can await it. + * + * Pass a handle that CANNOT reject — the `.catch(...)` result, not the raw + * work. A rejecting handle would surface as an unhandled rejection through the + * bookkeeping below, which is a louder signal than this helper should invent. + * + * A no-op outside test. + */ +export function trackBackgroundTask(settled: Promise): void { + if (!TRACK_IN_FLIGHT) return; + + inFlight.add(settled); + void settled.finally(() => { + inFlight.delete(settled); + }); +} + +/** + * Await every registered task still in flight, including work that a settling + * task starts itself. + * + * Both suite setups call this from `afterEach`, so no test can leave + * background work running past its own end. A no-op outside test, where + * nothing registers. + */ +export async function settleBackgroundTasks(): Promise { + while (inFlight.size > 0) { + await Promise.allSettled([...inFlight]); + } +} + +/** + * How many tasks are registered right now. Test-only introspection for the + * registration guard, which asserts both that a task registers and that the + * set drains back to empty — a retained reference would otherwise pass + * unnoticed. + */ +export function pendingBackgroundTaskCount(): number { + return inFlight.size; +} diff --git a/src/lib/logging/fire-and-forget.ts b/src/lib/logging/fire-and-forget.ts index 93fdc0fb7..a6f06895c 100644 --- a/src/lib/logging/fire-and-forget.ts +++ b/src/lib/logging/fire-and-forget.ts @@ -1,4 +1,5 @@ import { annotate } from "./context"; +import { trackBackgroundTask } from "./background-tasks"; /** * Run a best-effort background promise and leave an observable breadcrumb @@ -22,7 +23,10 @@ import { annotate } from "./context"; * the raw console sink, keeping it redaction-safe by construction. * * The promise stays fire-and-forget: the caller does not await it and its - * resolution is discarded exactly as before. + * resolution is discarded exactly as before. Under test the settled handle is + * registered with `trackBackgroundTask` so the suite setup can await it — see + * `./background-tasks` for why a late `console.warn` is otherwise a teardown + * hazard. * * @param promise The background work. May already be running. * @param context.action A stable `..` label (never user @@ -34,7 +38,7 @@ export function fireAndForget( promise: Promise, context: { action: string; meta?: Record }, ): void { - void Promise.resolve(promise).catch((error: unknown) => { + const settled = Promise.resolve(promise).catch((error: unknown) => { const message = error instanceof Error ? error.message : String(error); annotate({ meta: { @@ -48,4 +52,6 @@ export function fireAndForget( // above, so nothing sensitive reaches the raw console sink. console.warn(`[fire-and-forget] background task failed: ${context.action}`); }); + + trackBackgroundTask(settled); } diff --git a/src/lib/pwa/query-persister.ts b/src/lib/pwa/query-persister.ts index cb976125d..6c996f5b3 100644 --- a/src/lib/pwa/query-persister.ts +++ b/src/lib/pwa/query-persister.ts @@ -32,6 +32,7 @@ import { type QueryClient, } from "@tanstack/react-query"; +import { trackBackgroundTask } from "@/lib/logging/background-tasks"; import { queryKeys } from "@/lib/query-keys"; import { isReadingSharedRecord } from "@/lib/query-keys/record-scope"; @@ -283,20 +284,25 @@ export function startPersistingQueryCache( return; } - void idbSet(payload).catch((err) => { - // Don't silently swallow a full-disk failure: a quota error means the - // offline cache stopped updating, and a clear signal beats a stale - // snapshot the user can't explain. Drop the persisted blob so the next - // flush has room rather than failing again against a full store. - if (isQuotaError(err)) { - console.warn( - "[query-persister] IndexedDB quota exceeded; dropping persisted cache", - ); - void clearPersistedQueryCache(); - return; - } - console.warn("[query-persister] persist failed", err); - }); + // Registered so the test suite can await it: the warns below are console + // writes on a detached handle, and one that lands while a vitest worker is + // closing its RPC channel fails the whole run. No-op outside test. + trackBackgroundTask( + idbSet(payload).catch((err) => { + // Don't silently swallow a full-disk failure: a quota error means the + // offline cache stopped updating, and a clear signal beats a stale + // snapshot the user can't explain. Drop the persisted blob so the next + // flush has room rather than failing again against a full store. + if (isQuotaError(err)) { + console.warn( + "[query-persister] IndexedDB quota exceeded; dropping persisted cache", + ); + void clearPersistedQueryCache(); + return; + } + console.warn("[query-persister] persist failed", err); + }), + ); }; const unsubscribe = queryClient.getQueryCache().subscribe(() => { diff --git a/src/lib/rollups/after-measurement-mutation.ts b/src/lib/rollups/after-measurement-mutation.ts index 9d121f47a..d4ff65816 100644 --- a/src/lib/rollups/after-measurement-mutation.ts +++ b/src/lib/rollups/after-measurement-mutation.ts @@ -23,6 +23,7 @@ import { recomputeBucketsForMeasurement, } from "@/lib/rollups/measurement-rollups"; import { invalidateStatusInsightsForTypes } from "@/lib/insights/status-invalidation"; +import { trackBackgroundTask } from "@/lib/logging/background-tasks"; import type { MeasurementType } from "@/generated/prisma/client"; export async function afterMeasurementMutation( @@ -48,8 +49,13 @@ export async function afterMeasurementMutation( // the rollup leg above failed, so the two legs never gate each other. const types = Array.from(new Set(keys.map((k) => k.type))); if (types.length > 0) { - invalidateStatusInsightsForTypes(userId, types).catch((err) => { - console.warn(`[${label}] status-insight invalidate failed`, err); - }); + // Registered so the test suite can await it: the warn below is a console + // write on a detached handle, and one that lands while a vitest worker is + // closing its RPC channel fails the whole run. No-op outside test. + trackBackgroundTask( + invalidateStatusInsightsForTypes(userId, types).catch((err) => { + console.warn(`[${label}] status-insight invalidate failed`, err); + }), + ); } } diff --git a/tests/integration/environment-setup.ts b/tests/integration/environment-setup.ts index 82c6e8864..a3c7c4da6 100644 --- a/tests/integration/environment-setup.ts +++ b/tests/integration/environment-setup.ts @@ -1,4 +1,4 @@ -import { inject } from "vitest"; +import { afterEach, inject } from "vitest"; declare module "vitest" { export interface ProvidedContext { @@ -13,3 +13,22 @@ delete process.env.ENCRYPTION_KEYS; delete process.env.ENCRYPTION_ACTIVE_KEY_ID; process.env.API_TOKEN_HMAC_KEY = "integration-test-hmac-key-32-bytes-minimum"; process.env.SESSION_SECRET = "integration-test-session-secret-32-bytes"; + +/** + * Leave no background work in flight when an integration test ends — the same + * contract the unit setup keeps, for the same reason: detached background work + * logs on its own handle, and a console write that reaches vitest after the + * worker has begun closing its RPC channel fails the run with + * `EnvironmentTeardownError: Closing rpc while "onUserConsoleLog" was pending`. + * This suite has its own config and its own setup file, so the unit hook does + * not cover it. + * + * The import is deferred: this file's whole job is to bridge DATABASE_URL into + * the worker BEFORE any application module reads it at import time, and a + * static import here would pull part of the application tree in first. + */ +afterEach(async () => { + const { settleBackgroundTasks } = + await import("@/lib/logging/background-tasks"); + await settleBackgroundTasks(); +}); diff --git a/vitest.setup.ts b/vitest.setup.ts index dae4ec9c8..ce0e1a8aa 100644 --- a/vitest.setup.ts +++ b/vitest.setup.ts @@ -10,6 +10,8 @@ * primed up front and `t()` resolves every locale on the first render, * exactly like the server-handoff path does in the app. */ +import { afterEach } from "vitest"; +import { settleBackgroundTasks } from "@/lib/logging/background-tasks"; import { primeMessages } from "@/lib/i18n/load-locale"; import deMessages from "./messages/de.json"; import enMessages from "./messages/en.json"; @@ -26,3 +28,22 @@ primeMessages("fr", frMessages); primeMessages("it", itMessages); primeMessages("pl", plMessages); primeMessages("ko", koMessages); + +/** + * Leave no background work in flight when a test ends. + * + * Several paths start a promise, return without awaiting it, and log on the + * detached handle so the failure is not swallowed. Vitest forwards every + * console write to the main thread as an `onUserConsoleLog` RPC call and + * rejects whatever is still pending on that channel while it tears a test file + * down, so a write that lands in that window fails the whole run with + * `EnvironmentTeardownError: Closing rpc while "onUserConsoleLog" was pending` + * — blamed on the file the worker was tearing down, which is not the test that + * started the work and need not log anything of its own. Awaiting the + * registered tasks here removes the precondition instead of muting the + * console, which would have thrown away a real signal and left the + * non-determinism in place. See `src/lib/logging/background-tasks.ts`. + */ +afterEach(async () => { + await settleBackgroundTasks(); +});