root/fusion
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

fix(test): deterministic await for github-tracking dispatch race; record U7 triage findings

Browse Source 
- routes-planning-tracking: replace vi.waitFor polling (1s real-timer race vs fire-and-forget promise chain) with signalOnCall deferred resolution; assertions unchanged, mutate-to-prove verified
- top-time offenders documented keep-as-is: all are real-SQLite/real-git/spawned-process integration where the slowness IS the subject (FN-5048 keep class); demotion rejected (would churn inventory testIds)
This commit is contained in:
gsxdsm
2026-06-03 18:55:15 -07:00
parent 5bebc3cfe0
commit d2103b80df
2 changed files with 124 additions and 29 deletions
Download Patch File Download Diff File Expand all files Collapse all files

47
docs/test-speed-baseline-2026-06-03.md
View File

@@ -157,3 +157,50 @@ per-process count and the heavy-test tail that currently dominate.
| dashboard-app-quality-foundation-hooks-utils | `--no-isolate` | run1 crash; run2 33 fails (cross-file contamination) | revert |
Root cause: `packages/core/src/__test-utils__/vitest-setup.ts` mutates `fs`/`child_process`/cwd/HOME at module level per worker; non-isolated files share that state. Isolation is load-bearing for this repo — do not re-trial without restructuring the setup file. happy-dom and deps.optimizer trials dropped (lowest value; happy-dom not installed, optimizer not cleanly canary-able under `projects`). Deprecation audit: zero `poolMatchGlobs`/`environmentMatchGlobs`/workspace-file usages across all 28 configs — vitest 4 migration delta for these is already zero.
## U7 slow-test triage (2026-06-03): top offenders characterized
Characterization-first triage of the top-N offenders against `scripts/test-timings.json`.
The dominant finding: **every top-time offender is real-SQLite / real-git /
spawned-process integration that the FN-5048 "keep unconditionally" rule protects** —
the slowness *is* the test's subject, not incidental mechanics. The one actionable
defect was a flaky race (not a slow test), fixed deterministically. Honest result over
forced wins.
### Files changed
| File | Change | Before | After (3×) |
|---|---|---|---|
| `packages/dashboard/src/__tests__/routes-planning-tracking.test.ts` | Replaced `vi.waitFor` polling on background github-tracking dispatch with deterministic call-signaled awaits (`signalOnCall`) | flaky in-shard (failed once, passed isolated) | 6/6 pass, ~2.7–3.7s, 5× + 3× stable |
**Flaky fix mechanics.** The routes return 201 immediately, then dispatch
`GitHubClient.createIssue` / `logger.warn` on a fire-and-forget promise chain several
`await`s deep (`getSettings → maybeCreateTrackingIssue → createIssue`). The old test
polled with `vi.waitFor(() => expect(spy).toHaveBeenCalled())`, whose default 1000ms
real-timer timeout raced that microtask chain under shard CPU contention. Fix: the spied
function itself resolves a deferred on each invocation (`signalOnCall.calledTimes(n)` /
`.calledMatching(predicate)`), so the test awaits *exactly* until the background work
reaches the observable point — no timer, no timeout, no poll. **Assertions unchanged and
still bite**: mutate-to-prove disabled the dispatch (`if (false && hook …)`) and all 6
tests failed deterministically (8s test-level timeout) rather than passing vacuously;
restored after.
### Keep-as-is (integration-by-design; FN-5048 keep-unconditionally)
| File / suite | Σ time | Reason kept |
|---|---:|---|
| `core/agent-store.test.ts` | 11.6s | ~204 isolated tests, each building the full SQLite schema (≈30ms DDL, measured) + real CRUD/event assertions on a fresh in-memory DB. Schema build is irreducible per-DB (FTS5 is only ~2ms of it); mkdtemp+rm is ~43ms/204 total. Sharing one DB across tests breaks the documented per-test isolation (event-emission/count assertions from a clean slate). |
| `core/mission-store.test.ts` | 10.7s | ~248 isolated real-SQLite tests. A handful of 5–10ms `setTimeout` waits ensure distinct `createdAt` timestamps for ordering tests; ≈40ms total — fake timers would touch the very `new Date()` ordering under test for no meaningful gain. |
| `core/db.test.ts` | 10.1s | Spawns real child Node processes holding SQLite WAL write-locks (`BEGIN IMMEDIATE`, `busy_timeout`) to test cross-process lock contention. `holdMs:150` waits are intrinsic to the lock-timeout behavior and cannot be faked across process boundaries. Spawned-process + real-SQLite. |
| `engine/reliability-interactions/*` (shared-branch-group-lifecycle 13.9s, automerge-precedence 9.0s, merge-routing 8.4s, promotion-gate 8.4s, …) | ~50s | Real `git init`+commits+branches+squash-merges through the merge-coordinator + real in-memory TaskStore per test. Integration-by-design (task constraint). Demotion to `*.slow.test.ts` was evaluated and **rejected**: it reparents the file from project `engine-reliability` to `engine-slow`, and inventory testIds are project-qualified, so every test would show as remove+add and trip the U2 inventory superset guard. |
| `engine/merger-ai.test.ts` | 8.7s | 17 of 23 tests do real `git init` + real squash-merge per test (the merge IS the subject); 6 are fast pure-function/prompt tests already. Spawned-process integration. |
| `dashboard/routes-git.test.ts` | 9.4s | Already shares one git repo via `getSharedGitTestRepo` (beforeAll); per-test cost is real git subprocess calls exercising the git routes. Integration-by-design. |
| `dashboard/routes-agents.test.ts` | 11.2s | ~200 express route tests; store is mocked (`createMockStore`) in `beforeAll`. ~14 blocks use **disk-backed** `AgentStore` deliberately — they seed an agent with one store instance and read it back through the route's *own* store instance from the same `.fusion` dir, so disk persistence is load-bearing (in-memory would break the cross-instance handoff). |
### Timings snapshot
No `scripts/test-timings.json` refresh was needed for this unit: the only mechanics
change is to `routes-planning-tracking.test.ts`, which is not a top-time file (its slow
sibling `routes-planning.test.ts` is a different file) and whose post-fix duration is
unchanged. A later full refresh via `node scripts/ci-test-shard.mjs --write-timings`
remains the canonical mechanism.

106
packages/dashboard/src/__tests__/routes-planning-tracking.test.ts
View File

@@ -1,6 +1,6 @@
// @vitest-environment node
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
import { afterEach, beforeEach, describe, expect, it, vi, type MockInstance } from "vitest";
import express from "express";
import { setTaskCreatedHook, type Task, type TaskStore } from "@fusion/core";
import { registerPlanningSubtaskRoutes } from "../routes/register-planning-subtask-routes.js";
@@ -42,14 +42,58 @@ function deferred<T>() {
return { promise, resolve, reject };
}
/**
* Deterministic replacement for `vi.waitFor(() => expect(spy).toHaveBeenCalledTimes(n))`.
*
* The routes under test dispatch GitHub-issue creation on a fire-and-forget
* background promise chain (getSettings → maybeCreateTrackingIssue → createIssue
* / logger.warn), several `await`s deep. Polling for the call with `vi.waitFor`
* raced that chain under shard CPU contention (failed in-shard once, passed
* isolated). Instead we make the observable function itself signal: each
* invocation resolves the next pending deferred, so the test awaits exactly
* until the background work reaches the function — no timer, no timeout, no
* poll. The assertion (call count / argument shape) is unchanged and still bites.
*/
function signalOnCall<A extends unknown[], R>(impl: (...args: A) => R) {
let pending = deferred<void>();
const calls: A[] = [];
const wrapped = (...args: A): R => {
calls.push(args);
const toResolve = pending;
pending = deferred<void>();
toResolve.resolve();
return impl(...args);
};
// Resolves once the wrapped fn has been called at least `n` times.
const calledTimes = async (n: number): Promise<void> => {
while (calls.length < n) {
await pending.promise;
}
};
// Resolves once some invocation's args satisfy the predicate.
const calledMatching = async (predicate: (args: A) => boolean): Promise<void> => {
let seen = 0;
for (;;) {
while (seen < calls.length) {
if (predicate(calls[seen]!)) return;
seen += 1;
}
await pending.promise;
}
};
return { wrapped, calledTimes, calledMatching, get calls() { return calls; } };
}
describe("planning routes github tracking background dispatch", () => {
let app: express.Express;
let createIssueSpy: ReturnType<typeof vi.spyOn>;
let createIssueSpy: MockInstance<typeof GitHubClient.prototype.createIssue>;
let planningWarn: ReturnType<typeof vi.fn>;
let warnSignal: ReturnType<typeof signalOnCall<unknown[], void>>;
beforeEach(() => {
sessions.clear();
planningWarn = vi.fn();
warnSignal = signalOnCall<unknown[], void>(() => undefined);
planningWarn = vi.fn(warnSignal.wrapped);
let idCounter = 1;
const createdTasks = new Map<string, Record<string, unknown>>();
@@ -134,7 +178,8 @@ describe("planning routes github tracking background dispatch", () => {
it("POST /planning/create-task returns before createIssue resolves", async () => {
const issueDeferred = deferred<{ number: number; htmlUrl: string; createdAt: string }>();
createIssueSpy.mockReturnValue(issueDeferred.promise as never);
const createIssue = signalOnCall(() => issueDeferred.promise as never);
createIssueSpy.mockImplementation(createIssue.wrapped);
sessions.set("plan-1", {
summary: {
@@ -159,9 +204,8 @@ describe("planning routes github tracking background dispatch", () => {
const response = await responsePromise;
expect(response.status).toBe(201);
await vi.waitFor(() => {
expect(createIssueSpy).toHaveBeenCalledTimes(1);
});
await createIssue.calledTimes(1);
expect(createIssueSpy).toHaveBeenCalledTimes(1);
issueDeferred.resolve({
number: 1,
@@ -169,9 +213,9 @@ describe("planning routes github tracking background dispatch", () => {
createdAt: new Date().toISOString(),
});
await vi.waitFor(() => {
expect(createIssueSpy).toHaveBeenCalledTimes(1);
});
// No further dispatch should occur after the single createIssue resolves.
await Promise.resolve();
expect(createIssueSpy).toHaveBeenCalledTimes(1);
});
it("POST /planning/create-task still returns 201 when createIssue rejects", async () => {
@@ -199,9 +243,10 @@ describe("planning routes github tracking background dispatch", () => {
);
expect(response.status).toBe(201);
await vi.waitFor(() => {
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
await warnSignal.calledMatching(
(args) => typeof args[0] === "string" && args[0].includes("[github-tracking] Failed to create issue"),
);
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
it("POST /planning/create-task still returns 201 when createIssue throws synchronously", async () => {
@@ -231,14 +276,16 @@ describe("planning routes github tracking background dispatch", () => {
);
expect(response.status).toBe(201);
await vi.waitFor(() => {
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
await warnSignal.calledMatching(
(args) => typeof args[0] === "string" && args[0].includes("[github-tracking] Failed to create issue"),
);
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
it("POST /planning/create-tasks dispatches one createIssue per task without blocking", async () => {
const issueDeferred = deferred<{ number: number; htmlUrl: string; createdAt: string }>();
createIssueSpy.mockReturnValue(issueDeferred.promise as never);
const createIssue = signalOnCall(() => issueDeferred.promise as never);
createIssueSpy.mockImplementation(createIssue.wrapped);
sessions.set("plan-3", {
summary: {
@@ -268,9 +315,8 @@ describe("planning routes github tracking background dispatch", () => {
);
expect(response.status).toBe(201);
await vi.waitFor(() => {
expect(createIssueSpy).toHaveBeenCalledTimes(2);
});
await createIssue.calledTimes(2);
expect(createIssueSpy).toHaveBeenCalledTimes(2);
issueDeferred.resolve({
number: 2,
@@ -278,9 +324,9 @@ describe("planning routes github tracking background dispatch", () => {
createdAt: new Date().toISOString(),
});
await vi.waitFor(() => {
expect(createIssueSpy).toHaveBeenCalledTimes(2);
});
// No third dispatch after the two issues resolve.
await Promise.resolve();
expect(createIssueSpy).toHaveBeenCalledTimes(2);
});
it("POST /planning/create-tasks still returns 201 when createIssue rejects asynchronously", async () => {
@@ -314,9 +360,10 @@ describe("planning routes github tracking background dispatch", () => {
);
expect(response.status).toBe(201);
await vi.waitFor(() => {
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
await warnSignal.calledMatching(
(args) => typeof args[0] === "string" && args[0].includes("[github-tracking] Failed to create issue"),
);
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
it("POST /planning/create-tasks still returns 201 when createIssue throws synchronously", async () => {
@@ -352,8 +399,9 @@ describe("planning routes github tracking background dispatch", () => {
);
expect(response.status).toBe(201);
await vi.waitFor(() => {
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
await warnSignal.calledMatching(
(args) => typeof args[0] === "string" && args[0].includes("[github-tracking] Failed to create issue"),
);
expect(planningWarn).toHaveBeenCalledWith(expect.stringContaining("[github-tracking] Failed to create issue"));
});
});