test: remove real-time waits from the slowest test files (FN-5048) (#1784)
Removes real wall-clock waits and per-test rebuilds from the slowest test files, replacing them with deterministic seams. **No assertions weakened, no timeouts widened, no retries added** — this is anti-pattern removal per FN-5048, verified by re-running each file. ## Changes | File | What | Result | |---|---|---| | `dashboard/.../insights-routes.test.ts` | Boot server+store **once** in `beforeAll` (was `createServer` + `TaskStore.init` per test ×24); reset insight tables per test for isolation; drive sweeper via fake timers | test-exec **~3.7s → ~0.8s** | | `core/.../db.test.ts` | Fixed 150ms write-lock hold → manual stdin signal-release (keeps the real OS-lock contention under test); fixed a real EPIPE on redundant release | 152 pass, non-flaky / 8 runs; −300ms dead wait | | `core/.../mission-store.test.ts` | 4 real `setTimeout` sleeps (only there to force distinct timestamps) → `vi.setSystemTime` controlled clock | anti-pattern removed | | `core/.../agent-store.test.ts` | 1 real ordering-sleep → injected `renewedAt` clock; **assertions strengthened** to pin exact timestamp values | anti-pattern removed | | `engine/.../in-process-runtime.test.ts` | Fake the one real 25ms sleep; drop its inflated 30s per-test timeout | anti-pattern removed | ## Honest accounting - The **real wins** are `insights-routes` (per-test server boot eliminated, ~75% execution-time cut) and `db` (dead lock-hold removed). - The **timestamp-sleep removals** (mission-store, agent-store, in-process-runtime) are small absolute wins — the headline per-file durations (16–25s) were **full-suite shard contention, not in-file dead time** (each runs in 3–10s isolated). But they eliminate the FN-5048 real-wait anti-pattern, so a hub edit no longer drags real sleeps into every `--changed` selection. - **`workflow-routes.test.ts` was evaluated for splitting and deliberately NOT split.** A measured A/B showed the 4-way split *regressed* wall-clock (6s → 11s): the file is import/transform-bound (per-file esbuild + `@fusion/core`/express import ≈ 5s > the ~4.3s test runtime), and per-test store migration was already amortized by `installInMemoryDbSnapshot`. Splitting only multiplies the dominant fixed cost. Left intact. ## Verification - `core` 612/612, `dashboard` 24/24, `engine` 78/78 (file-scoped). - `tsc --noEmit` clean on all 3 packages; eslint clean. Follow-up (not in this PR): `scripts/test-timings.json` is stale (its former #1 file no longer exists) — refresh via `pnpm test:velocity -- --measure --write-report` so the watchdog budgets and velocity report reflect reality. 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- stage-review-badge-begin --> --- <a href="https://stagereview.app/Runfusion/Fusion/pull/1784"> <picture> <source media="(prefers-color-scheme: dark)" srcset="https://stagereview.app/assets/gh-open-in-stage-dark.svg"> <img src="https://stagereview.app/assets/gh-open-in-stage-light.svg" alt="Open in Stage"> </picture> </a> <!-- stage-review-badge-end --> <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit * **Tests** * Made several test suites more deterministic by replacing real-time delays with controlled timers and fixed timestamps. * Improved lock and task checkout tests to use manual release signals, reducing timing-related flakiness. * Streamlined route test setup/teardown for faster, more reliable runs. * Added safer cleanup around timer-based tests to avoid intermittent failures. <!-- end of auto-generated comment: release notes by coderabbit.ai -->
This commit is contained in:
gsxdsm
@@ -1897,12 +1897,27 @@ describe("AgentStore", () => {
|
||||
});
|
||||
|
||||
it("checkoutTask is idempotent for same agent/node/epoch and renews lease timestamp", async () => {
|
||||
const first = await store.checkoutTask(holderId, taskId, { nodeId: "node-a", runId: "run-1", leaseEpoch: 0 });
|
||||
await new Promise((resolve) => setTimeout(resolve, 5));
|
||||
/*
|
||||
FNXC:CheckoutLeasing 2026-06-25-21:49:
|
||||
Lease-renewal ordering is asserted via the store's injectable `renewedAt` clock seam
|
||||
(CheckoutClaimContext.renewedAt → AgentStore.checkoutTask), not a real setTimeout sleep.
|
||||
Previously a real 5ms wait forced a distinct heartbeat timestamp between the two checkouts;
|
||||
that wasted wall-clock time and added flake surface (FN-5048: do not add slow tests).
|
||||
Two explicit, ordered ISO timestamps make the renewal assertion deterministic with zero waiting.
|
||||
*/
|
||||
const firstRenewedAt = "2026-01-01T00:00:00.000Z";
|
||||
const secondRenewedAt = "2026-01-01T00:00:00.005Z";
|
||||
const first = await store.checkoutTask(holderId, taskId, {
|
||||
nodeId: "node-a",
|
||||
runId: "run-1",
|
||||
leaseEpoch: 0,
|
||||
renewedAt: firstRenewedAt,
|
||||
});
|
||||
const second = await store.checkoutTask(holderId, taskId, {
|
||||
nodeId: "node-a",
|
||||
runId: "run-2",
|
||||
leaseEpoch: first.checkoutLeaseEpoch ?? 0,
|
||||
renewedAt: secondRenewedAt,
|
||||
});
|
||||
|
||||
expect(second.checkedOutBy).toBe(holderId);
|
||||
@@ -1910,6 +1925,8 @@ describe("AgentStore", () => {
|
||||
expect(second.checkoutNodeId).toBe("node-a");
|
||||
expect(second.checkoutRunId).toBe("run-2");
|
||||
expect(second.checkoutLeaseEpoch).toBe(first.checkoutLeaseEpoch);
|
||||
expect(first.checkoutLeaseRenewedAt).toBe(firstRenewedAt);
|
||||
expect(second.checkoutLeaseRenewedAt).toBe(secondRenewedAt);
|
||||
expect(second.checkoutLeaseRenewedAt).not.toBe(first.checkoutLeaseRenewedAt);
|
||||
});
|
||||
|
||||
|
||||
@@ -120,15 +120,39 @@ afterAll(() => {
|
||||
cleanupTmpDirsSync();
|
||||
});
|
||||
|
||||
/*
|
||||
FNXC:CoreDB-LockTest 2026-06-25-21:55:
|
||||
The write-lock contention helper spawns a real child process that takes a real
|
||||
SQLite EXCLUSIVE/RESERVED lock — that real OS lock IS the thing under test, so it
|
||||
must NOT be mocked. The child releases the lock ONLY on an explicit `RELEASE`
|
||||
stdin message (signal release); there is no fixed wall-clock hold.
|
||||
|
||||
History: a `releaseMode: "timer"` variant fired `setTimeout(release, holdMs)` in
|
||||
the child to drop the lock after a FIXED real duration (150ms per test). Two
|
||||
recovery tests used it to release the lock mid-retry, paying ~150ms of dead
|
||||
wall-clock wait each. That timer was removed: the recovery path retries via
|
||||
synchronous `sleepSync` (Atomics.wait) on the main thread, so the test cannot
|
||||
release the lock from its own event loop while blocked. Instead the test sends
|
||||
`signalRelease()` (a bare stdin write, no await) in the SAME synchronous tick
|
||||
immediately before `transactionImmediate(...)`. The parent reaches its first
|
||||
`BEGIN IMMEDIATE` before the child can schedule + read the pipe + COMMIT (a
|
||||
cross-process IPC+WAL round trip), so attempt 0 deterministically contends with
|
||||
the still-held lock; the child then commits during the parent's first
|
||||
`sleepSync` window and the retry recovers. Lock held only as long as needed,
|
||||
released deterministically, zero fixed sleeps.
|
||||
*/
|
||||
async function holdWriteLock(
|
||||
dbPath: string,
|
||||
options?: { holdMs?: number; releaseMode?: "manual" | "timer" },
|
||||
options?: { releaseMode?: "manual" },
|
||||
): Promise<{
|
||||
child: ChildProcessWithoutNullStreams;
|
||||
// Fire-and-forget: tell the child to drop the lock WITHOUT awaiting its exit.
|
||||
// Used to release mid-`transactionImmediate` retry, where the main thread is
|
||||
// synchronously blocked in `sleepSync` and cannot await the child's exit.
|
||||
signalRelease: () => void;
|
||||
release: () => Promise<void>;
|
||||
}> {
|
||||
const releaseMode = options?.releaseMode ?? "manual";
|
||||
const holdMs = options?.holdMs ?? 0;
|
||||
void options;
|
||||
const script = `
|
||||
const { DatabaseSync } = require("node:sqlite");
|
||||
const db = new DatabaseSync(${JSON.stringify(dbPath)});
|
||||
@@ -141,14 +165,10 @@ async function holdWriteLock(
|
||||
try { db.close(); } catch {}
|
||||
process.exit(0);
|
||||
};
|
||||
if (${JSON.stringify(releaseMode)} === "timer") {
|
||||
setTimeout(release, ${holdMs});
|
||||
} else {
|
||||
process.stdin.setEncoding("utf8");
|
||||
process.stdin.on("data", (chunk) => {
|
||||
if (chunk.includes("RELEASE")) release();
|
||||
});
|
||||
}
|
||||
process.stdin.setEncoding("utf8");
|
||||
process.stdin.on("data", (chunk) => {
|
||||
if (chunk.includes("RELEASE")) release();
|
||||
});
|
||||
`;
|
||||
|
||||
const child = spawn(process.execPath, ["-e", script], {
|
||||
@@ -158,6 +178,14 @@ async function holdWriteLock(
|
||||
child.once("exit", () => {
|
||||
activeLockChildren.delete(child);
|
||||
});
|
||||
// FNXC:CoreDB-LockTest 2026-06-25-21:55: A RELEASE write inherently races the
|
||||
// child's exit — once the child reads RELEASE it COMMITs and exits, closing its
|
||||
// stdin, so a write that lands just after exit hits a closed pipe (EPIPE).
|
||||
// That EPIPE is benign: it only means the lock was already released, which is
|
||||
// the success condition. Swallow it so it never surfaces as an uncaught
|
||||
// exception. This does NOT weaken the lock test — assertions run before any
|
||||
// release and are untouched.
|
||||
child.stdin.on("error", () => {});
|
||||
|
||||
const ready = new Promise<void>((resolve, reject) => {
|
||||
let stderr = "";
|
||||
@@ -179,17 +207,28 @@ async function holdWriteLock(
|
||||
|
||||
await ready;
|
||||
|
||||
// Track whether RELEASE was already sent so `release()` (the cleanup path)
|
||||
// does not redundantly re-write to a child that `signalRelease()` already told
|
||||
// to exit — the redundant write is the EPIPE source removed above.
|
||||
let released = false;
|
||||
|
||||
return {
|
||||
child,
|
||||
signalRelease: () => {
|
||||
if (released || child.exitCode !== null || child.killed) {
|
||||
return;
|
||||
}
|
||||
released = true;
|
||||
child.stdin.write("RELEASE\n");
|
||||
},
|
||||
release: async () => {
|
||||
if (child.exitCode !== null || child.killed) {
|
||||
return;
|
||||
}
|
||||
if (releaseMode === "timer") {
|
||||
await once(child, "exit");
|
||||
return;
|
||||
if (!released) {
|
||||
released = true;
|
||||
child.stdin.write("RELEASE\n");
|
||||
}
|
||||
child.stdin.write("RELEASE\n");
|
||||
await once(child, "exit");
|
||||
},
|
||||
};
|
||||
@@ -1012,10 +1051,14 @@ describe("Database", () => {
|
||||
it("recovers outermost immediate transactions after a transient writer lock", async () => {
|
||||
const dbPath = db.getPath();
|
||||
db.exec("PRAGMA busy_timeout = 0");
|
||||
const lock = await holdWriteLock(dbPath, { releaseMode: "timer", holdMs: 150 });
|
||||
const lock = await holdWriteLock(dbPath, { releaseMode: "manual" });
|
||||
let callbackCalls = 0;
|
||||
|
||||
try {
|
||||
// FNXC:CoreDB-LockTest 2026-06-25-21:55: signal release in the SAME tick as
|
||||
// transactionImmediate so attempt 0 contends with the still-held lock and the
|
||||
// child commits during the first sleepSync retry window (no fixed wall-clock hold).
|
||||
lock.signalRelease();
|
||||
db.transactionImmediate(() => {
|
||||
callbackCalls += 1;
|
||||
db.prepare(
|
||||
@@ -1036,10 +1079,14 @@ describe("Database", () => {
|
||||
it("preserves nested savepoint rollback semantics after recovering the outer immediate writer lock", async () => {
|
||||
const dbPath = db.getPath();
|
||||
db.exec("PRAGMA busy_timeout = 0");
|
||||
const lock = await holdWriteLock(dbPath, { releaseMode: "timer", holdMs: 150 });
|
||||
const lock = await holdWriteLock(dbPath, { releaseMode: "manual" });
|
||||
let callbackCalls = 0;
|
||||
|
||||
try {
|
||||
// FNXC:CoreDB-LockTest 2026-06-25-21:55: same signal-release-then-recover pattern as
|
||||
// the recovery test above; verifies nested savepoint rollback survives the outer
|
||||
// immediate-lock recovery without paying a fixed 150ms hold.
|
||||
lock.signalRelease();
|
||||
db.transactionImmediate(() => {
|
||||
callbackCalls += 1;
|
||||
db.prepare(
|
||||
|
||||
@@ -1,4 +1,4 @@
|
||||
import { describe, it, expect, beforeEach, afterEach, beforeAll, afterAll } from "vitest";
|
||||
import { describe, it, expect, beforeEach, afterEach, beforeAll, afterAll, vi } from "vitest";
|
||||
import { MissionStore, deriveMilestoneAcceptanceCriteriaFromFeatures } from "../mission-store.js";
|
||||
import { installInMemoryDbSnapshot, clearInMemoryDbSnapshot } from "./store-test-helpers.js";
|
||||
import { GoalStore } from "../goal-store.js";
|
||||
@@ -134,19 +134,33 @@ describe("MissionStore", () => {
|
||||
expect(result).toBeUndefined();
|
||||
});
|
||||
|
||||
it("lists missions ordered by createdAt desc", async () => {
|
||||
const m1 = store.createMission({ title: "Mission 1" });
|
||||
await new Promise((r) => setTimeout(r, 10)); // Ensure different timestamps
|
||||
const m2 = store.createMission({ title: "Mission 2" });
|
||||
await new Promise((r) => setTimeout(r, 10));
|
||||
const m3 = store.createMission({ title: "Mission 3" });
|
||||
// FNXC:CoreTests 2026-06-25-21:50: MissionStore stamps createdAt/updatedAt
|
||||
// via new Date().toISOString() with no injectable clock seam, and ordering
|
||||
// queries (ORDER BY createdAt DESC) have no tiebreak. Tests previously slept
|
||||
// real wall-clock (setTimeout 5-10ms) just to force distinct timestamps —
|
||||
// pure dead time (FN-5048). Drive the system clock with fake timers +
|
||||
// setSystemTime instead: zero real waiting, deterministic ordering. Scoped
|
||||
// per-test (useRealTimers in finally) so the file's real-async paths and the
|
||||
// async afterEach db.close() keep real timers.
|
||||
it("lists missions ordered by createdAt desc", () => {
|
||||
vi.useFakeTimers();
|
||||
try {
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.000Z"));
|
||||
const m1 = store.createMission({ title: "Mission 1" });
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.010Z"));
|
||||
const m2 = store.createMission({ title: "Mission 2" });
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.020Z"));
|
||||
const m3 = store.createMission({ title: "Mission 3" });
|
||||
|
||||
const list = store.listMissions();
|
||||
const list = store.listMissions();
|
||||
|
||||
expect(list).toHaveLength(3);
|
||||
expect(list[0].id).toBe(m3.id); // Newest first
|
||||
expect(list[1].id).toBe(m2.id);
|
||||
expect(list[2].id).toBe(m1.id);
|
||||
expect(list).toHaveLength(3);
|
||||
expect(list[0].id).toBe(m3.id); // Newest first
|
||||
expect(list[1].id).toBe(m2.id);
|
||||
expect(list[2].id).toBe(m1.id);
|
||||
} finally {
|
||||
vi.useRealTimers();
|
||||
}
|
||||
});
|
||||
|
||||
it("round-trips mission branchStrategy on create", () => {
|
||||
@@ -178,21 +192,29 @@ describe("MissionStore", () => {
|
||||
expect(store.getMission(mission.id)?.branchStrategy).toBeUndefined();
|
||||
});
|
||||
|
||||
it("updates a mission", async () => {
|
||||
const mission = store.createMission({ title: "Original" });
|
||||
await new Promise((r) => setTimeout(r, 5)); // Ensure timestamp difference
|
||||
const updated = store.updateMission(mission.id, {
|
||||
title: "Updated",
|
||||
status: "active",
|
||||
});
|
||||
// FNXC:CoreTests 2026-06-25-21:50: real-sleep removed (FN-5048); advance the
|
||||
// fake clock between create and update so updatedAt > createdAt deterministically.
|
||||
it("updates a mission", () => {
|
||||
vi.useFakeTimers();
|
||||
try {
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.000Z"));
|
||||
const mission = store.createMission({ title: "Original" });
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.005Z"));
|
||||
const updated = store.updateMission(mission.id, {
|
||||
title: "Updated",
|
||||
status: "active",
|
||||
});
|
||||
|
||||
expect(updated.title).toBe("Updated");
|
||||
expect(updated.status).toBe("active");
|
||||
expect(updated.id).toBe(mission.id);
|
||||
expect(updated.createdAt).toBe(mission.createdAt);
|
||||
expect(new Date(updated.updatedAt).getTime()).toBeGreaterThan(
|
||||
new Date(mission.updatedAt).getTime()
|
||||
);
|
||||
expect(updated.title).toBe("Updated");
|
||||
expect(updated.status).toBe("active");
|
||||
expect(updated.id).toBe(mission.id);
|
||||
expect(updated.createdAt).toBe(mission.createdAt);
|
||||
expect(new Date(updated.updatedAt).getTime()).toBeGreaterThan(
|
||||
new Date(mission.updatedAt).getTime()
|
||||
);
|
||||
} finally {
|
||||
vi.useRealTimers();
|
||||
}
|
||||
});
|
||||
|
||||
it("throws when updating non-existent mission", () => {
|
||||
@@ -540,7 +562,12 @@ describe("MissionStore", () => {
|
||||
});
|
||||
});
|
||||
|
||||
it("computes correct health for multiple missions with varying states", async () => {
|
||||
// FNXC:CoreTests 2026-06-25-21:50: real-sleep removed (FN-5048); fake clock
|
||||
// advanced between the two missions to keep their createdAt distinct/ordered.
|
||||
it("computes correct health for multiple missions with varying states", () => {
|
||||
vi.useFakeTimers();
|
||||
try {
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.000Z"));
|
||||
// Mission 1: 1 milestone (active), 1 slice (active), 4 features (1 done, 2 in-flight, 1 failed)
|
||||
const m1 = store.createMission({ title: "Mission 1" });
|
||||
store.updateMission(m1.id, { status: "active" });
|
||||
@@ -562,7 +589,7 @@ describe("MissionStore", () => {
|
||||
const f1Failed = store.addFeature(sl1.id, { title: "F1-failed" });
|
||||
store.linkFeatureToTask(f1Failed.id, "FN-FAILED-1");
|
||||
|
||||
await new Promise((r) => setTimeout(r, 10));
|
||||
vi.setSystemTime(new Date("2026-06-25T00:00:00.010Z"));
|
||||
|
||||
// Mission 2: 2 milestones (1 complete, 1 active), 0 features
|
||||
const m2 = store.createMission({ title: "Mission 2" });
|
||||
@@ -617,6 +644,9 @@ describe("MissionStore", () => {
|
||||
autopilotEnabled: false,
|
||||
lastActivityAt: undefined,
|
||||
});
|
||||
} finally {
|
||||
vi.useRealTimers();
|
||||
}
|
||||
});
|
||||
|
||||
it("counts failed tasks across missions correctly", () => {
|
||||
@@ -4520,6 +4550,3 @@ describe("MissionStore", () => {
|
||||
});
|
||||
});
|
||||
});
|
||||
|
||||
// vi import for vitest mocking
|
||||
import { vi } from "vitest";
|
||||
|
||||
Reference in New Issue
Block a user