Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/fixes/6803-6803-flaky-timing-tests.md
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
- fix(sse): de-flake timing-sensitive combo cooldown/breaker tests + add explicit MCP audit shutdown timeout (#6803)
2 changes: 1 addition & 1 deletion config/quality/eslint-suppressions.json
Original file line number Diff line number Diff line change
Expand Up @@ -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": {
Expand Down
58 changes: 33 additions & 25 deletions open-sse/mcp-server/__tests__/audit.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
});

vi.doMock("better-sqlite3", () => ({
default: MockDatabase,
}));

const audit = await import("../audit.ts");

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

const audit = await import("../audit.ts");

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);
},
// 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
);
Comment on lines +67 to +72

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

While adding a 30000ms timeout to this test prevents flakes, the other two tests in this file (still closes the audit database when checkpoint fails and falls back to node:sqlite when better-sqlite3 binding is missing) also perform vi.resetModules() and dynamic imports, making them equally susceptible to timing out under CI contention. Consider setting a suite-level timeout on the describe block (e.g., describe("MCP audit shutdown", () => { ... }, 30000)) to cover all tests in this file uniformly.


it("still closes the audit database when checkpoint fails", async () => {
const mockDb: MockAuditDb = {
Expand Down
2 changes: 2 additions & 0 deletions stryker.conf.json
Original file line number Diff line number Diff line change
Expand Up @@ -224,6 +224,8 @@
"tests/unit/route-guard-provider-login-local-only.test.ts",
"tests/unit/router-strategies.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",
Expand Down
61 changes: 10 additions & 51 deletions tests/unit/combo-quota-share-cooldown-wait.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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 () => {
Expand Down
66 changes: 6 additions & 60 deletions tests/unit/combo-strategy-fallbacks.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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 });
Expand Down
153 changes: 153 additions & 0 deletions tests/unit/serial/combo-quota-share-cooldown-wait-timing.test.ts
Original file line number Diff line number Diff line change
@@ -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";
Comment on lines +25 to +27

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

The environment variables process.env.DATA_DIR and process.env.API_KEY_SECRET are modified globally but never restored in test.after. This can pollute the environment and cause side effects or failures in other tests if they run in the same process or share state. Saving and restoring the original values is a safer practice.

const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omr-combo-cooldown-wait-timing-"));
const ORIGINAL_DATA_DIR = process.env.DATA_DIR;
const ORIGINAL_API_KEY_SECRET = process.env.API_KEY_SECRET;
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 });
}
Comment on lines +76 to +80

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

The resetStorage function does not have any retry logic when calling fs.rmSync. SQLite file locks on Windows or CI environments can cause fs.rmSync to fail intermittently. Adding a retry loop (similar to cleanupTestDataDir in the other timing test file) makes this test much more robust against Windows file locking flakes.

async function resetStorage() {
  let lastError: unknown;
  for (let attempt = 0; attempt < 5; attempt += 1) {
    try {
      core.resetDbInstance();
      fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true });
      fs.mkdirSync(TEST_DATA_DIR, { recursive: true });
      return;
    } catch (error: unknown) {
      lastError = error;
      await new Promise((resolve) => setTimeout(resolve, 25));
    }
  }
  if (lastError) throw lastError;
}


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 */
}
});
Comment on lines +87 to +95

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

Restore the original environment variables in test.after to prevent global environment pollution and ensure test isolation.

test.after(async () => {
  clearAllModelLockouts();
  if (ORIGINAL_DATA_DIR === undefined) {
    delete process.env.DATA_DIR;
  } else {
    process.env.DATA_DIR = ORIGINAL_DATA_DIR;
  }
  if (ORIGINAL_API_KEY_SECRET === undefined) {
    delete process.env.API_KEY_SECRET;
  } else {
    process.env.API_KEY_SECRET = ORIGINAL_API_KEY_SECRET;
  }
  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`);
});
Loading
Loading