Skip to content

Plugin tests share one context.db, and PRAGMA busy_timeout equals bun's default test timeout — lock contention surfaces as an unattributable 5000ms timeout #312

Description

@iceteaSA

What happens

Check (plugin) intermittently fails with tests that report this test timed out after 5000ms and nothing else. No assertion failure, no error message, no stack — just a wall-clock kill. The set of tests that fail changes between runs, and they pass on a re-run and in isolation.

Recent example on a PR branch: 3929 pass / 7 fail, all 7 timeouts, spread across four unrelated files (system-prompt-hash, inject-compartments, compaction-off-transition, storage-embedding-measurements). All four pass locally.

I originally read this as a slow runner, and want to show why that's wrong, because it's the reason the real cause is easy to miss:

test local CI
keeps project docs, user profile, and key files out… 52 ms >5000 ms
does NOT update systemPromptHash… 47 ms >5000 ms
injects the MINIMAL block for a subagent… 45 ms >5000 ms
invalidates cached marker reads after background writes… 242 ms >5000 ms
bounds a session's corpus rows… 133 ms >5000 ms

The CI runner is about 6.5× slower on this suite overall (668s vs 102s wall for the same 3926 tests). 6.5× on a 52 ms test is ~340 ms. These are 20–100× blowups. Nothing is slow; something is waiting.

Cause

Three things upstream combine, and each is individually reasonable:

  1. packages/plugin/test-preload.ts:30 points every test at one database. It sets MAGIC_CONTEXT_TEST_DATA_DIR to a single temp dir, and resolveDatabasePath() (storage-db.ts:162-172) resolves a bare openDatabase() inside it. So every openDatabase() with no explicit path opens the same context.db. There are 491 such call sites across 54 test files.

  2. storage-db.ts:711 sets PRAGMA busy_timeout=5000. Correct for production — the comment explains it guards a cold-open race between OpenCode/Pi startup and the subprocess lease tests.

  3. bun test's default per-test timeout is also 5000ms, and packages/plugin/package.json's test script is a bare bun test with no --timeout.

All test files execute in one process (verified: two files report the same process.pid), so these connections are genuinely concurrent against one file.

When one connection holds a write lock and another wants it, SQLite blocks the second for the full busy_timeout. That's 5000ms — expiring at the same moment bun kills the test. The lock wait is never observed: bun's timeout fires first and reports a bare timeout instead of SQLITE_BUSY: database is locked.

The two 5000s are unrelated constants that happen to be equal, which is what makes the failure unattributable.

Reproduction (clean upstream/master, no fork code)

packages/plugin/src/zz-repro.test.ts:

import { test, expect } from "bun:test";
import { Database } from "bun:sqlite";
import { openDatabase, resolveDatabasePath } from "./features/magic-context/storage-db";

test("shared-DB lock contention surfaces as an undiagnosable test timeout", () => {
    const seed = openDatabase();   // creates the shared context.db the preload points at
    seed?.close();
    const { dbPath } = resolveDatabasePath();
    console.log(`REPRO shared_db=${dbPath}`);

    const a = new Database(dbPath);
    a.exec("PRAGMA busy_timeout=5000");
    a.exec("PRAGMA journal_mode=WAL");
    a.exec("CREATE TABLE IF NOT EXISTS zz(x)");
    a.exec("BEGIN EXCLUSIVE");           // hold the write lock

    const b = new Database(dbPath);
    b.exec("PRAGMA busy_timeout=5000");  // what initializeDatabase sets
    const t0 = Date.now();
    try { b.exec("INSERT INTO zz VALUES (1)"); }
    catch (e) { console.log(`REPRO blocked_ms=${Date.now() - t0} err=${(e as Error).message}`); }
    expect(1).toBe(1);
});
REPRO shared_db=/tmp/mc-plugin-test-xdg-fcEEXR/cortexkit/magic-context/context.db
REPRO blocked_ms=5004 err=database is locked
(fail) shared-DB lock contention surfaces as an undiagnosable test timeout [5050.17ms]
  ^ this test timed out after 5000ms.

Both lines print: the lock wait and the timeout, at the same 5004/5050ms. In a real run only the second is visible.

Why CI and not local

Contention is a race. A faster machine narrows the window where two tests want the write lock simultaneously; a slower, more contended runner widens it. That explains the CI-only, non-deterministic, moves-around-between-runs signature — without requiring any test to actually be slow.

Suggested fixes

Not mutually exclusive; (1) alone converts every future instance from unattributable to self-explaining.

  1. Decouple the two constants. Run the plugin suite with --timeout set to something clearly above busy_timeout (the E2E job already does this — ci.yml:317 uses --timeout 600000). A lock wait then surfaces as SQLITE_BUSY: database is locked with a real stack, instead of a bare wall-clock kill. Cheapest change, biggest diagnostic win.

  2. Give each test file its own database. A per-file temp dir (or :memory: where the test doesn't need a real path) removes the contention rather than making it legible. Bigger change — 491 call sites — but it's the actual fix, and inject-compartments.test.ts already uses :memory: in one place as precedent.

  3. Lower busy_timeout under test only, so a lock wait fails fast and loudly well inside the test budget. Least invasive to production semantics, but only helps if paired with (1) for the message to be readable.

Happy to send a PR for (1) — one line in packages/plugin/package.json — if you want to start there. (2) is worth its own change with a decision on the isolation mechanism first.

Environment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions