From 59108e09fac4c24a7326e503bb19d83f3cd9a0ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Wed, 9 Sep 2026 22:39:39 +0200 Subject: [PATCH] fix(test): stop the score suites from talking to a real database MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The three score engines' unit tests hand `persist*Score` a fake Prisma, but `upsertScoreRow` routes the written row through `afterMeasurementMutation`, which reads the `@/lib/db` singleton instead of the injected client. Both legs of that tail therefore opened a socket to a Postgres the unit job does not run: on CI the attempt failed with ECONNREFUSED a few hundred milliseconds later and logged on the way out, after the test that started it had ended. A console write that lands while the worker is closing its RPC channel fails the whole run with `EnvironmentTeardownError: Closing rpc while "onUserConsoleLog" was pending` — four of nine unit-suite failures in thirty days, every one of them with all tests green, blamed on whichever score file the worker happened to be tearing down. Run 31961548185 carries the full stack: recomputeBucketsForMeasurement <- afterMeasurementMutation <- upsertScoreRow <- persistStressScore <- stress-score.test.ts:105. It stayed invisible on a maintainer's machine because a local Postgres answers on 5432: the same call succeeded quietly, and the suite was writing rollup rows for its fixture users into a real database. The four files that drive `upsertScoreRow` stub the tail. That removes the doomed I/O rather than the log line, and the call they were making by accident is now asserted in score-row.test.ts instead: the v1.37.19 wiring is pinned by an expectation rather than by a stack trace. Verified by mutation — dropping the `afterMeasurementMutation` call from score-row.ts fails the new assertion. The settle guard's sweep is widened while here. Its eight-line handler window and five-line registration preamble were both measured against the sites that existed when it was written and both cut through real code: the console write in mood-rollups.ts sits nine lines into its handler, so the one genuinely unregistered detached promise in the tree was never seen, and the registration in fire-and-forget.ts sits below its handler, so a correct site read as a violation. Registration is now looked for wherever it wraps the statement, by paren depth rather than by line count, and mood-rollups.ts registers its WEEK/MONTH/YEAR enqueue. Verified by mutation: unwrapping that call fails the guard. Gate: the four files, twenty consecutive runs, 20/20 green (53 tests each). Test time across the three engine files falls from 708 ms to 20 ms — the round-trips that are no longer made. --- .../background-task-settle-guard.test.ts | 62 +++++++++++++++++-- .../insights/__tests__/recovery-score.test.ts | 12 ++++ src/lib/insights/__tests__/score-row.test.ts | 46 ++++++++++++++ .../insights/__tests__/strain-score.test.ts | 12 ++++ .../insights/__tests__/stress-score.test.ts | 12 ++++ src/lib/rollups/mood-rollups.ts | 42 +++++++------ 6 files changed, 162 insertions(+), 24 deletions(-) diff --git a/src/__tests__/background-task-settle-guard.test.ts b/src/__tests__/background-task-settle-guard.test.ts index 9ce3fa914..322c7dd6f 100644 --- a/src/__tests__/background-task-settle-guard.test.ts +++ b/src/__tests__/background-task-settle-guard.test.ts @@ -19,6 +19,18 @@ * `.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. + * + * It was narrower than that until the window below was widened. An + * eight-line handler window and a five-line registration preamble were both + * measured against the sites that existed when the guard was written, and + * both cut through real code: the console write in `mood-rollups.ts` sits + * nine lines into its handler, so the sweep never saw the one detached + * `Promise.all` in the tree that was genuinely unregistered, and the + * registration in `fire-and-forget.ts` sits BELOW its handler rather than + * above it, so a site that is correct read as a violation. The window now + * spans a plausible handler body and registration counts wherever it wraps + * the statement — above the handle or on the line that files the settled + * result. */ import { describe, it, expect } from "vitest"; import { readFileSync } from "node:fs"; @@ -57,6 +69,37 @@ function sourceFiles(): string[] { .filter((rel) => !rel.endsWith(".test.ts") && !rel.endsWith(".test.tsx")); } +/** + * How far past the `.catch(` / `.then(` line a handler's console write still + * counts as this handler's. Twenty lines covers every handler body in the + * tree with room to spare; eight did not. + */ +const HANDLER_WINDOW = 20; + +const registers = (text: string) => /trackBackgroundTask\(/.test(text); + +/** + * The source lines that open a call still unclosed at the start of `line` — + * the chain of enclosing calls the handler sits inside, innermost last. + * + * Paren counting is a coarse reading of TypeScript: a `(` inside a string or a + * comment counts like any other. That costs nothing here, because the question + * asked of the result is only whether one of those lines names + * `trackBackgroundTask`, and a stray paren can at worst widen the chain by a + * line that does not. + */ +function enclosingOpenCallLines(source: string, line: number): string[] { + const lines = source.split("\n"); + const open: number[] = []; + for (let i = 0; i < line - 1; i += 1) { + for (const ch of lines[i]) { + if (ch === "(") open.push(i); + else if (ch === ")") open.pop(); + } + } + return open.map((i) => lines[i]); +} + /** Lines starting a `.catch()` / `.then()` whose handler writes to the console. */ function consoleWritingHandlers(): { file: string; line: number }[] { const found: { file: string; line: number }[] = []; @@ -64,7 +107,7 @@ function consoleWritingHandlers(): { file: string; line: number }[] { 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"); + const handler = lines.slice(index, index + HANDLER_WINDOW).join("\n"); if (!/console\.(log|warn|error|info|debug|trace)\(/.test(handler)) return; found.push({ file: rel, line: index + 1 }); }); @@ -149,11 +192,18 @@ describe("background-task settle contract", () => { 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); + const source = readFileSync(join(SRC, file), "utf8"); + // Registered either by wrapping the handle — `trackBackgroundTask(` is + // then one of the calls still open where the handler starts, however + // many lines above that is — or by filing the settled handle just after + // the handler closes. Both shapes are in the tree; a fixed window above + // the match saw neither reliably. + if (enclosingOpenCallLines(source, line).some(registers)) return false; + const lines = source.split("\n"); + const trailer = lines + .slice(line, line + HANDLER_WINDOW + 5) + .filter((l) => registers(l)); + return trailer.length === 0; }); expect( diff --git a/src/lib/insights/__tests__/recovery-score.test.ts b/src/lib/insights/__tests__/recovery-score.test.ts index 375edd22d..12237c9aa 100644 --- a/src/lib/insights/__tests__/recovery-score.test.ts +++ b/src/lib/insights/__tests__/recovery-score.test.ts @@ -12,6 +12,18 @@ import { describe, it, expect, vi, beforeEach } from "vitest"; import type { Derived } from "@/lib/insights/derived/types"; import type { ReadinessValue } from "@/lib/insights/derived/readiness"; +/** + * The post-mutation tail reads the real `@/lib/db` client, not the fake this + * file injects, so a stored score opened a socket to a Postgres the unit job + * does not run. The attempt failed a few hundred milliseconds later and logged + * on the way out — after the test that started it had ended — which is how a + * green file tore its worker's RPC channel down mid-write. Stubbed here; + * `score-row.test.ts` asserts the wiring this stands for. + */ +vi.mock("@/lib/rollups/after-measurement-mutation", () => ({ + afterMeasurementMutation: vi.fn(async () => {}), +})); + const computeReadinessMock = vi.fn<(...args: unknown[]) => Promise>>(); diff --git a/src/lib/insights/__tests__/score-row.test.ts b/src/lib/insights/__tests__/score-row.test.ts index 63c4fb4f6..b21f2b2c9 100644 --- a/src/lib/insights/__tests__/score-row.test.ts +++ b/src/lib/insights/__tests__/score-row.test.ts @@ -14,6 +14,27 @@ vi.mock("@/lib/logging/context", () => ({ annotate: (...args: unknown[]) => annotateMock(...args), })); +/** + * The post-mutation tail talks to the real database, and this file does not. + * + * `upsertScoreRow` routes every stored score through + * `afterMeasurementMutation`, which reads the `@/lib/db` singleton rather than + * the client the caller injected. A unit test that hands in a fake Prisma + * therefore still opened a socket to a Postgres the unit job does not run: the + * attempt failed with ECONNREFUSED a few hundred milliseconds later and both + * legs logged on the way out, after the test that started them had ended. A + * console write that lands while the worker is closing its RPC channel fails + * the whole run with `EnvironmentTeardownError: Closing rpc while + * "onUserConsoleLog" was pending` — four of nine unit-suite failures in thirty + * days, every one of them with all tests green. Stubbing the tail removes the + * doomed I/O rather than the log line, and the call it made by accident is + * asserted below instead. + */ +vi.mock("@/lib/rollups/after-measurement-mutation", () => ({ + afterMeasurementMutation: vi.fn(async () => {}), +})); + +import { afterMeasurementMutation } from "@/lib/rollups/after-measurement-mutation"; import { scoreDayKey, scoreMeasuredAt, @@ -92,6 +113,31 @@ describe("upsertScoreRow", () => { measuredAt: arg.create.measuredAt, }); }); + + it("routes the written row through the shared post-mutation tail", async () => { + // v1.37.19 wiring: a score row is a Measurement like any other, so the + // (type, day) rollup bucket and the cached status assessment converge on + // the tick that wrote it. Pinned here rather than left to a live database + // call that no unit job can serve. + const prisma = { + measurement: { upsert: vi.fn().mockResolvedValue({}) }, + } as unknown as Parameters[0]; + + await upsertScoreRow(prisma, { + userId: "u1", + type: "STRAIN_SCORE", + externalIdPrefix: "strain:", + score: 42, + now: new Date("2026-06-02T03:00:00Z"), + }); + + expect(afterMeasurementMutation).toHaveBeenCalledWith("u1", [ + { + type: "STRAIN_SCORE", + measuredAt: new Date("2026-06-01T12:00:00.000Z"), + }, + ]); + }); }); describe("runScoreBatch", () => { diff --git a/src/lib/insights/__tests__/strain-score.test.ts b/src/lib/insights/__tests__/strain-score.test.ts index 1e47ca9f2..6ac225af0 100644 --- a/src/lib/insights/__tests__/strain-score.test.ts +++ b/src/lib/insights/__tests__/strain-score.test.ts @@ -10,6 +10,18 @@ */ import { describe, it, expect, vi, beforeEach } from "vitest"; +/** + * The post-mutation tail reads the real `@/lib/db` client, not the fake this + * file injects, so a stored score opened a socket to a Postgres the unit job + * does not run. The attempt failed a few hundred milliseconds later and logged + * on the way out — after the test that started it had ended — which is how a + * green file tore its worker's RPC channel down mid-write. Stubbed here; + * `score-row.test.ts` asserts the wiring this stands for. + */ +vi.mock("@/lib/rollups/after-measurement-mutation", () => ({ + afterMeasurementMutation: vi.fn(async () => {}), +})); + import { strainDayKey, strainExternalId, diff --git a/src/lib/insights/__tests__/stress-score.test.ts b/src/lib/insights/__tests__/stress-score.test.ts index 1427c4723..b5f5f5391 100644 --- a/src/lib/insights/__tests__/stress-score.test.ts +++ b/src/lib/insights/__tests__/stress-score.test.ts @@ -10,6 +10,18 @@ */ import { describe, it, expect, vi, beforeEach } from "vitest"; +/** + * The post-mutation tail reads the real `@/lib/db` client, not the fake this + * file injects, so a stored score opened a socket to a Postgres the unit job + * does not run. The attempt failed a few hundred milliseconds later and logged + * on the way out — after the test that started it had ended — which is how a + * green file tore its worker's RPC channel down mid-write. Stubbed here; + * `score-row.test.ts` asserts the wiring this stands for. + */ +vi.mock("@/lib/rollups/after-measurement-mutation", () => ({ + afterMeasurementMutation: vi.fn(async () => {}), +})); + const computeVitalsBaselineMock = vi.fn(); vi.mock("@/lib/insights/derived/baseline", () => ({ computeVitalsBaseline: (...args: unknown[]) => diff --git a/src/lib/rollups/mood-rollups.ts b/src/lib/rollups/mood-rollups.ts index 78596eea9..9f9986bd0 100644 --- a/src/lib/rollups/mood-rollups.ts +++ b/src/lib/rollups/mood-rollups.ts @@ -48,6 +48,7 @@ import { prisma } from "@/lib/db"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { annotate } from "@/lib/logging/context"; +import { trackBackgroundTask } from "@/lib/logging/background-tasks"; import { startOfUtcDay } from "@/lib/tz/start-of-utc-day"; import type { Prisma, @@ -307,25 +308,30 @@ export async function recomputeMoodBucketsForEntry( // off the pg-boss critical path. Errors stay caught inside // `enqueueMoodRollupRecompute` so the unhandled-rejection logger // captures any pg-boss failure. - void Promise.all( - ASYNC_GRANULARITIES.map((granularity) => { - const { from, to } = bucketSpan(dateLabel, granularity); - return enqueueMoodRollupRecompute({ - userId, - granularity, - from, - to, - }).catch((err: unknown) => { - const message = err instanceof Error ? err.message : String(err); - annotate({ - meta: { - mood_rollup_enqueue_failed: true, - mood_rollup_enqueue_error: message, - }, + // 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( + Promise.all( + ASYNC_GRANULARITIES.map((granularity) => { + const { from, to } = bucketSpan(dateLabel, granularity); + return enqueueMoodRollupRecompute({ + userId, + granularity, + from, + to, + }).catch((err: unknown) => { + const message = err instanceof Error ? err.message : String(err); + annotate({ + meta: { + mood_rollup_enqueue_failed: true, + mood_rollup_enqueue_error: message, + }, + }); + console.error("[mood-rollups] async enqueue failed:", message); }); - console.error("[mood-rollups] async enqueue failed:", message); - }); - }), + }), + ), ); }