fix(sse): de-flake timing-sensitive combo cooldown/breaker tests (#6803) (#6897)

* fix(sse): de-flake timing-sensitive combo cooldown/breaker tests (#6803)

Extracts 3 wall-clock-sensitive assertions (combo-quota-share cooldown
ceiling x2, circuit-breaker HALF_OPEN race) into tests/unit/serial/
(--test-concurrency=1, the repo's established remedy for this class of
test) and widens their margins, since a starved CI-runner event loop can
blow even a serialized test's timing window. Also adds an explicit 30s
vitest timeout to the MCP audit shutdown test, which had no override and
inherited vitest's 5000ms default.

Regression proof: reproduced RED locally under real devbox CPU
contention (2644ms/1796ms elapsed vs the old 1500ms ceiling, exactly the
reported failure mode); confirmed GREEN after the fix under the same
contention.

* fix(quality): register new serial timing tests + prune stale any-suppression count

- stryker.conf.json: add tests/unit/serial/combo-quota-share-cooldown-wait-timing.test.ts
  and tests/unit/serial/combo-strategy-fallbacks-half-open-timing.test.ts to
  tap.testFiles so their mutant kills count for accountFallback.ts and
  circuitBreaker.ts (PR #6897 added these files but didn't register them).
- eslint-suppressions.json: combo-strategy-fallbacks.test.ts's no-explicit-any
  suppression count was stale (35) after this PR trimmed 2 any-usages out of
  the file when extracting the half-open timing test; corrected to 33.

Co-authored-by: Diego Rodrigues de Sa e Souza <souzamiriamrodrigues790@gmail.com>

---------

Co-authored-by: Diego Rodrigues de Sa e Souza <souzamiriamrodrigues790@gmail.com>
This commit is contained in:
Diego Rodrigues de Sa e Souza
2026-07-12 01:59:57 -03:00
committed by GitHub
parent a6dfd1068e
commit 0f3c68fa69
8 changed files with 366 additions and 133 deletions

View File

@@ -0,0 +1 @@
- fix(sse): de-flake timing-sensitive combo cooldown/breaker tests + add explicit MCP audit shutdown timeout (#6803)

View File

@@ -1059,7 +1059,7 @@
},
"tests/unit/combo-strategy-fallbacks.test.ts": {
"@typescript-eslint/no-explicit-any": {
"count": 35
"count": 33
}
},
"tests/unit/combo-stream-readiness-fallback.test.ts": {

View File

@@ -37,31 +37,39 @@ describe("MCP audit shutdown", () => {
vi.restoreAllMocks();
});
it("checkpoints and closes the audit database during shutdown", async () => {
const mockDb: MockAuditDb = {
prepare: vi.fn(() => createStatementMock()),
pragma: vi.fn(),
close: vi.fn(),
open: true,
};
const MockDatabase = vi.fn(function MockDatabase() {
return mockDb;
});
it(
"checkpoints and closes the audit database during shutdown",
async () => {
const mockDb: MockAuditDb = {
prepare: vi.fn(() => createStatementMock()),
pragma: vi.fn(),
close: vi.fn(),
open: true,
};
const MockDatabase = vi.fn(function MockDatabase() {
return mockDb;
});
vi.doMock("better-sqlite3", () => ({
default: MockDatabase,
}));
vi.doMock("better-sqlite3", () => ({
default: MockDatabase,
}));
const audit = await import("../audit.ts");
const audit = await import("../audit.ts");
await audit.logToolCall("omniroute_get_health", { ok: true }, { ok: true }, 12, true);
expect(mockDb.prepare).toHaveBeenCalledTimes(1);
await audit.logToolCall("omniroute_get_health", { ok: true }, { ok: true }, 12, true);
expect(mockDb.prepare).toHaveBeenCalledTimes(1);
expect(audit.closeAuditDb()).toBe(true);
expect(mockDb.pragma).toHaveBeenCalledWith("wal_checkpoint(TRUNCATE)");
expect(mockDb.close).toHaveBeenCalledTimes(1);
expect(audit.closeAuditDb()).toBe(false);
});
expect(audit.closeAuditDb()).toBe(true);
expect(mockDb.pragma).toHaveBeenCalledWith("wal_checkpoint(TRUNCATE)");
expect(mockDb.close).toHaveBeenCalledTimes(1);
expect(audit.closeAuditDb()).toBe(false);
},
// Explicit generous timeout (vitest default is 5000ms): under contended
// CI-runner load, vi.resetModules() + a fresh dynamic import + mocked DB
// calls can exceed the default budget though the behavior is correct
// (issue #6803).
30000
);
it("still closes the audit database when checkpoint fails", async () => {
const mockDb: MockAuditDb = {

View File

@@ -230,6 +230,8 @@
"tests/unit/router-strategies.test.ts",
"tests/unit/rule12-error-sanitization-sweep.test.ts",
"tests/unit/serial/combo-health-autopilot.test.ts",
"tests/unit/serial/combo-quota-share-cooldown-wait-timing.test.ts",
"tests/unit/serial/combo-strategy-fallbacks-half-open-timing.test.ts",
"tests/unit/serial/provider-health-autopilot.test.ts",
"tests/unit/service-combo-metrics.test.ts",
"tests/unit/services-branch-hardening.test.ts",

View File

@@ -15,6 +15,10 @@
*
* The waits use a real (short) cooldown so the real setTimeout in
* waitForCooldownAwareRetry elapses fast and the model lock expires naturally.
*
* Scenarios 2 and 4 assert a wall-clock ceiling and were extracted to
* tests/unit/serial/combo-quota-share-cooldown-wait-timing.test.ts (#6803) —
* see that file's header for why.
*/
import test from "node:test";
import assert from "node:assert/strict";
@@ -131,33 +135,12 @@ test("quota-share: short 429 cooldown → waits and re-dispatches (2nd pass 200)
);
});
test("quota-share: 403 quota_exhausted → NO wait, error propagated immediately", async () => {
let calls = 0;
const handleSingleModel = async () => {
calls += 1;
return rateLimitResponse(403);
};
const startedAt = Date.now();
const res = await handleComboChat({
body: { model: "openai/gpt-4" },
combo: comboOf("quota-share"),
handleSingleModel,
isModelAvailable: async () => true,
log: createLog() as never,
settings: shortModelLockoutSettings(),
allCombos: null,
});
const elapsed = Date.now() - startedAt;
assert.notEqual(res.status, 200, "quota_exhausted must not be retried into a success");
// The real signal that the cooldown wait did NOT fire: a single upstream
// dispatch (no redispatch). The 403 lock cooldown is multi-second, so the
// wait — had it fired — would dominate the elapsed time; assert we stayed far
// below that (loose bound; the first combo dispatch pays DB/import overhead).
assert.equal(calls, 1, "quota_exhausted must NOT trigger a wait+redispatch");
assert.ok(elapsed < 1500, `quota_exhausted must not wait out a cooldown, but ${elapsed}ms elapsed`);
});
// NOTE: "quota-share: 403 quota_exhausted → NO wait" and "non quota-share
// (priority): 429 propagated immediately, NO wait" were extracted to
// tests/unit/serial/combo-quota-share-cooldown-wait-timing.test.ts (#6803) —
// both assert a wall-clock ceiling that flaked under CI-runner load; the
// serial dir (--test-concurrency=1) removes the intra-suite contention that
// caused it.
test("quota-share: client abort during the wait → 499", async () => {
const controller = new AbortController();
@@ -185,30 +168,6 @@ test("quota-share: client abort during the wait → 499", async () => {
assert.equal(res.status, 499, "abort during the cooldown wait must return 499");
});
test("non quota-share (priority): 429 propagated immediately, NO wait", async () => {
let calls = 0;
const handleSingleModel = async () => {
calls += 1;
return rateLimitResponse(429);
};
const startedAt = Date.now();
const res = await handleComboChat({
body: { model: "openai/gpt-4" },
combo: { ...comboOf("priority"), name: "priority-combo" },
handleSingleModel,
isModelAvailable: async () => true,
log: createLog() as never,
settings: shortModelLockoutSettings(),
allCombos: null,
});
const elapsed = Date.now() - startedAt;
assert.equal(res.status, 429, "priority combo must propagate the 429 unchanged");
assert.equal(calls, 1, "priority combo must NOT wait+redispatch");
assert.ok(elapsed < 1500, `priority combo must not wait out a cooldown, but ${elapsed}ms elapsed`);
});
test("quota-share with comboCooldownWait disabled → 429 propagated, NO wait", async () => {
let calls = 0;
const handleSingleModel = async () => {

View File

@@ -782,66 +782,12 @@ test("unknown strategy value normalizes to priority order", async () => {
assert.deepEqual(calls, ["openai/gpt-4o-mini"], "typo falls back to priority (first model)");
});
test("combo skips a provider while its breaker is OPEN and attempts it again after the reset timeout (HALF_OPEN)", async () => {
const breaker = getCircuitBreaker("openai", { failureThreshold: 1, resetTimeout: 40 });
try {
await breaker.execute(async () => {
throw new Error("simulated provider failure");
});
} catch {
// expected — trips the breaker OPEN
}
assert.equal(breaker.getStatus().state, "OPEN");
const comboDef = {
name: "half-open-recovery",
strategy: "priority",
models: ["openai/gpt-4o-mini", "claude/sonnet"],
config: { maxRetries: 0, retryDelayMs: 0, fallbackDelayMs: 0 },
};
// While OPEN: the openai target must be skipped, claude serves.
const callsWhileOpen: string[] = [];
const blocked = await handleComboChat({
body: {},
combo: comboDef,
handleSingleModel: async (_body: any, modelStr: string) => {
callsWhileOpen.push(modelStr);
return okResponse();
},
isModelAvailable: async () => true,
log: createLog(),
settings: null,
allCombos: null,
});
assert.equal(blocked.ok, true);
assert.deepEqual(callsWhileOpen, ["claude/sonnet"], "OPEN breaker target must be skipped");
// After the reset timeout the breaker reads HALF_OPEN — the combo must probe
// the provider again instead of excluding it forever (lazy recovery contract).
await new Promise((resolve) => setTimeout(resolve, 80));
assert.equal(breaker.getStatus().state, "HALF_OPEN");
const callsAfterExpiry: string[] = [];
const probed = await handleComboChat({
body: {},
combo: comboDef,
handleSingleModel: async (_body: any, modelStr: string) => {
callsAfterExpiry.push(modelStr);
return okResponse();
},
isModelAvailable: async () => true,
log: createLog(),
settings: null,
allCombos: null,
});
assert.equal(probed.ok, true);
assert.deepEqual(
callsAfterExpiry,
["openai/gpt-4o-mini"],
"HALF_OPEN provider must be probed again"
);
});
// NOTE: "combo skips a provider while its breaker is OPEN and attempts it
// again after the reset timeout (HALF_OPEN)" was extracted to
// tests/unit/serial/combo-strategy-fallbacks-half-open-timing.test.ts (#6803)
// — it races an 80ms real setTimeout against a 40ms breaker resetTimeout,
// which flaked under CI-runner load; the serial dir (--test-concurrency=1)
// removes the intra-suite contention that caused it.
test("preScreenTargets marks an expired-OPEN (HALF_OPEN) target as available", async () => {
const breaker = getCircuitBreaker("openai", { failureThreshold: 1, resetTimeout: 30 });

View File

@@ -0,0 +1,153 @@
/**
* tests/unit/serial/combo-quota-share-cooldown-wait-timing.test.ts
*
* Extracted from tests/unit/combo-quota-share-cooldown-wait.test.ts (#6803).
*
* These two scenarios assert a wall-clock ceiling (`elapsed < 1500`) around a
* handleComboChat() call that also performs real SQLite I/O (test.beforeEach
* does fs.rmSync+fs.mkdirSync + core.resetDbInstance()). Under CI-runner
* CPU/IO contention (multiple concurrent sibling shard jobs) this ceiling can
* be exceeded even though the functional behavior (no wait, single dispatch)
* is correct — this is a "did NOT wait out a cooldown" ceiling, not a
* behavior-under-test assertion, so it is timing-sensitive by nature.
*
* Running these in tests/unit/serial/ (--test-concurrency=1, see
* package.json's test:unit:serial) removes the intra-suite parallelism that
* was the dominant source of contention, matching the repo's established
* remedy pattern for this class of test.
*/
import test from "node:test";
import assert from "node:assert/strict";
import fs from "node:fs";
import os from "node:os";
import path from "node:path";
const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omr-combo-cooldown-wait-timing-"));
process.env.DATA_DIR = TEST_DATA_DIR;
process.env.API_KEY_SECRET = "test-combo-cooldown-wait-timing-secret";
const core = await import("../../../src/lib/db/core.ts");
const { handleComboChat } = await import("../../../open-sse/services/combo.ts");
const { clearAllModelLockouts } = await import("../../../open-sse/services/accountFallback.ts");
function createLog() {
return { info: () => {}, warn: () => {}, error: () => {}, debug: () => {} };
}
const BASE_COOLDOWN_MS = 150;
const RETRY_AFTER_MS = 250;
function shortModelLockoutSettings() {
return {
modelLockout: {
enabled: true,
errorCodes: [403, 429],
baseCooldownMs: BASE_COOLDOWN_MS,
maxCooldownMs: 5000,
maxBackoffSteps: 0,
useExponentialBackoff: false,
},
};
}
function jsonResponse(status: number, body: Record<string, unknown>) {
return new Response(JSON.stringify(body), {
status,
headers: { "content-type": "application/json" },
});
}
function rateLimitResponse(status: number) {
return jsonResponse(status, {
error: { message: `rate limited (${status})` },
retryAfter: new Date(Date.now() + RETRY_AFTER_MS).toISOString(),
});
}
function comboOf(strategy: string) {
return {
name: `qtSd/${strategy}-${Math.random().toString(16).slice(2, 8)}`,
strategy,
models: ["openai/gpt-4"],
config: { maxRetries: 0, retryDelayMs: 0, fallbackDelayMs: 0, maxSetRetries: 0 },
};
}
async function resetStorage() {
core.resetDbInstance();
fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true });
fs.mkdirSync(TEST_DATA_DIR, { recursive: true });
}
test.beforeEach(async () => {
clearAllModelLockouts();
await resetStorage();
});
test.after(async () => {
clearAllModelLockouts();
try {
core.resetDbInstance();
fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true });
} catch {
/* best effort */
}
});
test("quota-share: 403 quota_exhausted → NO wait, error propagated immediately", async () => {
let calls = 0;
const handleSingleModel = async () => {
calls += 1;
return rateLimitResponse(403);
};
const startedAt = Date.now();
const res = await handleComboChat({
body: { model: "openai/gpt-4" },
combo: comboOf("quota-share"),
handleSingleModel,
isModelAvailable: async () => true,
log: createLog() as never,
settings: shortModelLockoutSettings(),
allCombos: null,
});
const elapsed = Date.now() - startedAt;
assert.notEqual(res.status, 200, "quota_exhausted must not be retried into a success");
// The real signal that the cooldown wait did NOT fire: a single upstream
// dispatch (no redispatch). The 403 lock cooldown is multi-second, so the
// wait — had it fired — would dominate the elapsed time; assert we stayed far
// below that (loose bound; the first combo dispatch pays DB/import overhead).
assert.equal(calls, 1, "quota_exhausted must NOT trigger a wait+redispatch");
// Widened from 1500ms (#6803): the primary signal is calls===1 above (no
// redispatch happened at all); this ceiling is a secondary sanity check
// that we didn't accidentally wait out a real (multi-second-to-hours)
// quota_exhausted lock, so a generous bound still catches a real
// regression while tolerating CI-runner DB/import contention.
assert.ok(elapsed < 10000, `quota_exhausted must not wait out a cooldown, but ${elapsed}ms elapsed`);
});
test("non quota-share (priority): 429 propagated immediately, NO wait", async () => {
let calls = 0;
const handleSingleModel = async () => {
calls += 1;
return rateLimitResponse(429);
};
const startedAt = Date.now();
const res = await handleComboChat({
body: { model: "openai/gpt-4" },
combo: { ...comboOf("priority"), name: "priority-combo" },
handleSingleModel,
isModelAvailable: async () => true,
log: createLog() as never,
settings: shortModelLockoutSettings(),
allCombos: null,
});
const elapsed = Date.now() - startedAt;
assert.equal(res.status, 429, "priority combo must propagate the 429 unchanged");
assert.equal(calls, 1, "priority combo must NOT wait+redispatch");
// Widened from 1500ms (#6803) — see the sibling test above for rationale.
assert.ok(elapsed < 10000, `priority combo must not wait out a cooldown, but ${elapsed}ms elapsed`);
});

View File

@@ -0,0 +1,164 @@
/**
* tests/unit/serial/combo-strategy-fallbacks-half-open-timing.test.ts
*
* Extracted from tests/unit/combo-strategy-fallbacks.test.ts (#6803).
*
* This scenario races a real 80ms setTimeout against a 40ms circuit-breaker
* resetTimeout before asserting breaker.getStatus().state === 'HALF_OPEN'.
* Under a starved event loop (CI-runner CPU contention from concurrent
* sibling shard jobs) this timing margin can be missed even though the
* lazy-recovery contract (OPEN → HALF_OPEN once the reset timeout elapses) is
* implemented correctly.
*
* Running this in tests/unit/serial/ (--test-concurrency=1, see package.json's
* test:unit:serial) removes the intra-suite parallelism that was the dominant
* source of contention, matching the repo's established remedy pattern for
* this class of test.
*/
import test from "node:test";
import assert from "node:assert/strict";
import fs from "node:fs";
import os from "node:os";
import path from "node:path";
const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-combo-fallbacks-half-open-"));
const ORIGINAL_DATA_DIR = process.env.DATA_DIR;
process.env.DATA_DIR = TEST_DATA_DIR;
const { handleComboChat } = await import("../../../open-sse/services/combo.ts");
const core = await import("../../../src/lib/db/core.ts");
const settingsDb = await import("../../../src/lib/db/settings.ts");
const { resetAllComboMetrics } = await import("../../../open-sse/services/comboMetrics.ts");
const { resetAllCircuitBreakers, getCircuitBreaker } =
await import("../../../src/shared/utils/circuitBreaker.ts");
const { resetAll: resetAllSemaphores } =
await import("../../../open-sse/services/rateLimitSemaphore.ts");
const { _resetAllDecks } = await import("../../../src/shared/utils/shuffleDeck.ts");
const { clearSessions } = await import("../../../open-sse/services/sessionManager.ts");
type LogEntry = { level: string; tag: unknown; msg: unknown };
function createLog() {
const entries: LogEntry[] = [];
return {
info: (tag: unknown, msg: unknown) => entries.push({ level: "info", tag, msg }),
warn: (tag: unknown, msg: unknown) => entries.push({ level: "warn", tag, msg }),
error: (tag: unknown, msg: unknown) => entries.push({ level: "error", tag, msg }),
debug: (tag: unknown, msg: unknown) => entries.push({ level: "debug", tag, msg }),
entries,
};
}
function okResponse(body: unknown = { choices: [{ message: { content: "ok" } }] }) {
return new Response(JSON.stringify(body), {
status: 200,
headers: { "content-type": "application/json" },
});
}
async function cleanupTestDataDir() {
let lastError: unknown;
for (let attempt = 0; attempt < 5; attempt += 1) {
try {
core.resetDbInstance();
fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true });
return;
} catch (error: unknown) {
lastError = error;
await new Promise((resolve) => setTimeout(resolve, 25));
}
}
if (lastError) throw lastError;
}
test.beforeEach(async () => {
resetAllComboMetrics();
resetAllCircuitBreakers();
resetAllSemaphores();
_resetAllDecks();
clearSessions();
await cleanupTestDataDir();
fs.mkdirSync(TEST_DATA_DIR, { recursive: true });
await settingsDb.resetAllPricing();
settingsDb.clearAllLKGP();
});
test.after(async () => {
resetAllComboMetrics();
resetAllCircuitBreakers();
resetAllSemaphores();
_resetAllDecks();
settingsDb.clearAllLKGP();
if (ORIGINAL_DATA_DIR === undefined) {
delete process.env.DATA_DIR;
} else {
process.env.DATA_DIR = ORIGINAL_DATA_DIR;
}
await cleanupTestDataDir();
});
test("combo skips a provider while its breaker is OPEN and attempts it again after the reset timeout (HALF_OPEN)", async () => {
// Widened from the original 40ms/80ms margin (#6803): under contended
// CI-runner load even --test-concurrency=1 doesn't guarantee the "while
// OPEN" dispatch completes before a 40ms window elapses. A larger absolute
// margin (same ~2x wait:resetTimeout ratio) tolerates real scheduling
// jitter while still proving the lazy-recovery contract.
const breaker = getCircuitBreaker("openai", { failureThreshold: 1, resetTimeout: 300 });
try {
await breaker.execute(async () => {
throw new Error("simulated provider failure");
});
} catch {
// expected — trips the breaker OPEN
}
assert.equal(breaker.getStatus().state, "OPEN");
const comboDef = {
name: "half-open-recovery",
strategy: "priority",
models: ["openai/gpt-4o-mini", "claude/sonnet"],
config: { maxRetries: 0, retryDelayMs: 0, fallbackDelayMs: 0 },
};
// While OPEN: the openai target must be skipped, claude serves.
const callsWhileOpen: string[] = [];
const blocked = await handleComboChat({
body: {},
combo: comboDef,
handleSingleModel: async (_body: unknown, modelStr: string) => {
callsWhileOpen.push(modelStr);
return okResponse();
},
isModelAvailable: async () => true,
log: createLog(),
settings: null,
allCombos: null,
});
assert.equal(blocked.ok, true);
assert.deepEqual(callsWhileOpen, ["claude/sonnet"], "OPEN breaker target must be skipped");
// After the reset timeout the breaker reads HALF_OPEN — the combo must probe
// the provider again instead of excluding it forever (lazy recovery contract).
await new Promise((resolve) => setTimeout(resolve, 600));
assert.equal(breaker.getStatus().state, "HALF_OPEN");
const callsAfterExpiry: string[] = [];
const probed = await handleComboChat({
body: {},
combo: comboDef,
handleSingleModel: async (_body: unknown, modelStr: string) => {
callsAfterExpiry.push(modelStr);
return okResponse();
},
isModelAvailable: async () => true,
log: createLog(),
settings: null,
allCombos: null,
});
assert.equal(probed.ok, true);
assert.deepEqual(
callsAfterExpiry,
["openai/gpt-4o-mini"],
"HALF_OPEN provider must be probed again"
);
});