Merge pull request #917 from MBombeck/test/settle-background-tasks

test: settle detached background work before a test file tears down

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<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);
+    }
+  });
+});

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<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" };
     }

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<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;
+}

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 `<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);
 }

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(() => {

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);
+      }),
+    );
   }
 }

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();
+});

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();
+});