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.
This commit is contained in:
Marc-André Bombeck committed 2026-09-03 05:30:08 +02:00
1 parent 1e4b30c417
commit bdf3ffb5da
8 files changed
+359 -29

No files matched your search

@@ -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<void>((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<void>((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<void>((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);
}
});
});
+16 -9
View File
@@ -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<T = unknown> {
@@ -416,15 +417,21 @@ export class ServerCache<T> {
// 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" };
}
+87
View File
@@ -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<Promise<unknown>>();
/**
* 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<unknown>): 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<void> {
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;
}
+8 -2
View File
@@ -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 `<surface>.<noun>.<verb>` label (never user
@@ -34,7 +38,7 @@ export function fireAndForget(
promise: Promise<unknown>,
context: { action: string; meta?: Record<string, unknown> },
): 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);
}
+20 -14
View File
@@ -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(() => {
@@ -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);
}),
);
}
}
+20 -1
View File
@@ -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();
});
+21
View File
@@ -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();
});