From bdf3ffb5daf049ece91c2f6b0940dc8b8201cab3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Thu, 3 Sep 2026 05:30:00 +0200 Subject: [PATCH] test: settle detached background work before a test file tears down The unit suite reported all 1937 files green and then failed the job with `EnvironmentTeardownError: Closing rpc while "onUserConsoleLog" was pending`, naming a different scoring test each time. Vitest replaces globalThis.console with a sink that forwards every write to the main thread as an onUserConsoleLog RPC call. When a worker finishes a test file it awaits the calls in flight and then rejects whatever was started after that point, so a console write from work that outlived its test lands in the gap and fails the run. The blame goes to the file being torn down rather than to the test that started the work, which is why the named file never logged anything itself. Three paths detach a promise and log on the handle: fireAndForget, the stale-while-revalidate cache refresh, and the offline query persister. They now register the handled handle in a set that both suite setups drain in afterEach, so no test leaves work in flight. The registry is inert outside test: nothing there awaits it, and holding a reference to an unsettled promise would retain it for the life of a worker. No production behaviour changes, so there is no changelog entry. Evidence. A focused harness that starts failing background tasks and returns hit the teardown error 10 runs out of 10 before the change and 0 out of 10 after. Instrumenting the real suite showed two detached console writes per run escaping their test, both from the rollup tail; after the change, none, and thirteen writes per run now complete inside the test that started them. The guard asserts the behaviour, not a count: a registered task must keep settleBackgroundTasks from resolving ahead of it, and the set must drain back to empty. It goes red on unregistered work, on a disabled registry, on an unwrapped call site, on a sweep that matches nothing, and on a setup that drops the hook. --- .../background-task-settle-guard.test.ts | 178 ++++++++++++++++++ src/lib/cache/server-cache.ts | 25 ++- src/lib/logging/background-tasks.ts | 87 +++++++++ src/lib/logging/fire-and-forget.ts | 10 +- src/lib/pwa/query-persister.ts | 34 ++-- src/lib/rollups/after-measurement-mutation.ts | 12 +- tests/integration/environment-setup.ts | 21 ++- vitest.setup.ts | 21 +++ 8 files changed, 359 insertions(+), 29 deletions(-) create mode 100644 src/__tests__/background-task-settle-guard.test.ts create mode 100644 src/lib/logging/background-tasks.ts 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(); +});