Keep the telemetry emitter service alive through spool lock contention

[MaxGhenis]

Problem

Every concurrent build on a host shares one SQLite spool for local telemetry (~/.cache/microcosm/telemetry/events.sqlite3, busy timeout 5 s). Before the emitter service binds its socket, main() opens the spool (Alembic upgrade head, then prune) and EmitterService.run() registers the producer, which is a write.

Measured on origin/main 7f23594 (CPython 3.14.7 free-threaded, SQLite 3.53.1), with a second connection holding BEGIN IMMEDIATE, as another build's service does while it writes:

Step	Result
register (new or existing producer), append	OperationalError: database is locked (SQLITE_BUSY) after 5.2 s
EventSpool(...) on a spool with rows older than 7 days (its prune deletes)	same error after 5.2 s
EventSpool(...) on a new spool (migration DDL)	same error after 5.2 s
pending_runs, has_deliverable, a prune with nothing to delete	succeed: a RESERVED lock does not block readers

main() did not catch the error, so the service exited, the build ran with no hosted telemetry, and a SQLAlchemy traceback, including the SQL and its parameters, landed on the build's stderr.

Concurrent first opens raced. Eight services opening a new spool at the same instant failed about half the time:

• 23 of 48 here. The design review measured 57 of 80 (3.14) and 52 of 80 (CPython 3.13.9 with the GIL).
• The errors were "table alembic_version/telemetry_runs/telemetry_events already exists", or an IntegrityError on alembic_version.
• Cause: Python's sqlite3 module never opens a transaction before DDL, so engine.begin() plus alembic upgrade was neither atomic nor serialized. A statement trace shows the four CREATEs autocommitted.
• The same race recurs whenever a new migration ships to a host running several builds.

The delivery worker died on any exception. Heartbeat appends, prune-on-append and flush_once (for example int(None) from a collector expires_in: null) were unguarded. The thread died with a traceback on the build's stderr. Only the worker notices a dead build, so a build later SIGKILLed left a service serving forever, in its own session (start_new_session=True).

Change

1. Startup waits out lock contention, inside the build's budget.
   • The client passes --ready-deadline: the Unix time at which start() gives up (datetime.now(UTC), the module's existing wall clock).
   • main.open_registered_spool opens the spool and registers the producer in one retry loop (contention.py). The service waits for another process's lock until 0.5 s before the build stops waiting.
     • Each SQLite wait ends by that startup deadline and lasts at most the normal 5 s. A PRAGMA busy_timeout applied at connection checkout enforces it.
     • An attempt that fails on the lock is retried with jittered backoff (0.05 s doubling to 0.25 s) while one can still start before the deadline. The first attempt always runs, and a backoff sleep that overruns the deadline ends the retries.
     • The total is capped at 60 s, whatever the deadline or the wall clock says. Afterwards the spool returns to the normal 5 s wait.
   • Never worse than before. Without --ready-deadline, startup makes one attempt with the normal 5 s wait, exactly the old behaviour. With one, it waits at least as long as the old single 5 s wait could have before the build gave up, minus the 0.5 s margin. For example, with the 3 s budget on main today, a lock held for 1.5 s is waited out, and a test pins this.
   • The socket is bound only after registration, so "ready" still means "can queue events".
   • Still locked at the deadline: one line ("could not register this build in its spool …: another process kept the spool locked for N s (database is locked).") and exit 75 (EX_TEMPFAIL). Any other startup failure: one line, exit 1.
2. Opening a spool at head takes no write lock.
   • Retention moved from spool open and from every append to the delivery worker: EventSpool.prune_if_due, once per 60 s, with a failed attempt counting toward the interval.
   • prune deletes in batches of 500 rows, each its own short transaction, and pauses 25 ms between batches outside the process lock.
     • Without the pause, other processes were still locked out for the whole prune: SQLite's busy handler polls rather than queueing, so it rarely lands in the gap between batches. With a 100k-row backlog, another service's appends waited up to 5.2 s and sometimes failed.
     • With the pause, their worst wait was 0.16–0.92 s.
   • A prune works at most 1 s per worker tick and resumes on the next tick, so the worker's heartbeat and parent check keep running while a backlog drains.
   • A prune with nothing to remove checks read-only first and takes no write lock.
   • Expired runs are deleted in the same batches as events.
   • The size check first reads the file's page counts. A file that uses no more than the 100 MiB cap cannot hold more than the cap, so the usual prune no longer sums every payload.
   • A service that closes within the worker's first one-second tick still runs one bounded prune step, so a host of short builds cannot skip retention.
3. Migrations run one process at a time, atomically.
   • A read-only check returns early when the spool is at head, the common case, which takes no write lock.
   • Otherwise the whole upgrade runs in one BEGIN IMMEDIATE transaction (SQLAlchemy's documented pysqlite recipe for transactional DDL), on a short-lived engine. A second migrator waits, then finds the spool at head, and Alembic does nothing.
   • A spool stamped with a revision missing from this checkout's history (for example a later migration from another checkout sharing the spool) is refused from the read-only check, without taking the lock.
4. The worker keeps running.
   • Each step is guarded and skipped for one tick on failure: sample, heartbeat, prune_if_due, flush_once, and the drain.
   • Lock contention is silent and retried. Any other error prints one line per error type.
   • A failed heartbeat stays due. The parent check runs every tick. The unexpected-exit record retries lock errors for the drain window.
   • CollectorDelivery.flush_once backs off like a collector failure after an unexpected error, so a bug cannot become one request per second. A locked spool is retried on the next tick.
   • _serve stops if the worker thread ever dies.
   • A check of the build that raises is reported and treated as a dead build.
   • Pre-existing bug fixed: a build that sent close and then exited while a worker step was still running (a slow collector POST or a locked append) was recorded as an unexpected exit after its completion. The parent check now runs only while the build has not closed.
5. No raw tracebacks on the build's stderr. Invalid arguments give one line and exit 2, not argparse's usage block. The client passes --ready-deadline=<value> as one token, so a past deadline parses. SIGINT ends the service at once, as SIGTERM does. Every service warning goes through diagnostics.write_warning, which never raises. A closed stderr pipe — a build run through tee and interrupted — no longer kills the worker. describe_error prints the driver's one-line message, not SQLAlchemy's statement and parameters.

Evaluated and not done

• Degrade to local-only instead of exiting. local_only is a per-run row state in the same spool that is locked, so it cannot be recorded. The client already continues the build with a disabled handle when the service exits.

• Becoming ready before the spool is usable (bind first, buffer events in memory, or register lazily on the first append). This would remove SQLite from readiness entirely. But a persistent lock would then stall the build's event sends: _handle appends synchronously in the accept thread, waiting up to 5 s per event, while the client times out after 0.2 s per send. Exiting cleanly costs the build the startup budget once instead. Doing this properly means decoupling the event path from spool writes; that is a separate change (follow-up below).

• An index on created_at to speed the prune's scans. It needs a new migration, and an older checkout sharing the spool would then refuse it (follow-up below).

Invariants (each has a test in test_telemetry_spool_contention.py)

• Retry contract (Hypothesis, fake clock, any script of ok/locked/fatal attempts, any deadline including −∞, any jitter).
  • The first attempt always runs, and every later attempt starts before the deadline, even when a sleep overruns (modelled). No wait is asked to reach it.
  • The result is the last attempt's. Only SQLITE_BUSY/SQLITE_LOCKED are retried; any other error propagates on its first occurrence.
  • Each lock error draws one wait in [d/2, d], with d = min(0.25, 0.05·2^k). A lock error escapes only when its retry could not start in time.
• Classification (exhaustive). Every primary result code 0–255, each with extensions 0, 1, 2, 3 and 255, raw and SQLAlchemy-wrapped: transient iff the primary code is 5 or 6 (SQLITE_BUSY or SQLITE_LOCKED, as literals). Checked differentially against errors SQLite itself raises: a lock timeout is transient; "table … already exists" and an IntegrityError are not.
• Deadline (Hypothesis, behavioural). Startup stops at least 0.5 s before the build's deadline, and within the 60 s limit. It uses all of that time, so nothing is given up early. No flag means no deadline. NaN is refused; ∞ is capped.
• Never worse than the old single wait. With a 3 s build budget, a 1.5 s hold is waited out. Without a deadline, one attempt runs with the normal 5 s wait. Startup waits end by the deadline and never exceed 5 s.
• Readiness implies registration.
  • In process, for a new spool, a spool at head, and one with expired rows: while the lock is held there is no socket and at least two lock failures. Registration completes, and the ping is answered, only after release.
  • End to end, the real client starts the real service with the lock held past one full 5 s SQLite wait. It becomes available only after release, then queues ordered events from "started" to "completed", with no traceback.
• Gives up first, in one line. In process, the service exits 75 with exactly one stderr line before the build's deadline. The real process with a held lock also writes exactly one line.
• Opening at head takes no write lock. Even with expired rows, EventSpool opens in well under one busy wait while the lock is held.
• Migrations.
  • A migration interrupted after its first DDL leaves no tables.
  • An opener that arrives during another's migration waits, then changes nothing; the schema passes alembic check.
  • Six processes opening a new spool at once all succeed and all register.
  • An unknown revision is refused without the lock.
• Retention.
  • Differential (Hypothesis): the batched prune keeps exactly the events and runs that the single-pass rule keeps, for random ages, sizes, caps and batch sizes 1–4. That holds whether it runs in one call or one batch per call, and no transaction deletes more than one batch.
  • Schedule (Hypothesis): prune_if_due prunes on the first call, at once after an unfinished prune, and otherwise iff 60 s have passed since the previous attempt, failed or not.
  • A prune with nothing to remove succeeds in under 1 s while another process holds the write lock.
  • Pauses happen between batches with the process lock free.
  • A zero budget stops after each batch and resumes.
  • Expired runs go in batches with pauses.
  • A spool under the cap is pruned without a sum( query; one over it is summed and trimmed.
  • A service closed within its first tick still prunes an expired event.
  • Appends never prune.
• Worker liveness (Hypothesis over scripted per-step outcomes, tick counts, parent death and heartbeat intervals).
  • The worker never raises, including when the parent check itself raises. The parent is checked every tick until the build is found dead or has closed.
  • A build that died without closing is recorded once, on that tick, which stops the loop. A build whose close arrived mid-tick is never recorded.
  • Heartbeat attempts match a reference schedule: due one interval after the start or after the last success, with a failure staying due.
  • Lock errors print nothing; every other error type prints exactly one line.
  • The shutdown drain (its own property, over any failure sequence) never raises and never runs past its deadline.
• One line. Invalid arguments give exactly one stderr line, and SIGINT on the real process gives exit −2 with empty stderr.
• Other.
  • Serving stops when the worker dies, and warnings never raise on a broken pipe or closed stderr.
  • An unexpected delivery error backs off while a locked spool does not. The unexpected-exit record waits out contention.

Mutation check. Hand-written mutants, each removing one guarantee above, applied in a separate worktree and run against their targeted tests. A kill counts only when a test fails on an assertion or the expected exception; each failing test id and its E line are recorded.

• At the pushed head fd8d230, all 54 applicable mutants are killed on 2 of 2 runs, each from a fresh Hypothesis database (108 of 108). The unmutated tree passed the same tests first.
• Getting there took fixes to the tests, not just the code: the first harness run's "kills" were a setup error, and four properties had strategies that rarely reached the distinguishing cases.
• Harness and logs: ~/reviews/microcosm-telemetry-spool-lock-2026-10-09/mutants/ (SUMMARY.md, run_mutants_v7.py, results_v7.json).

Known limits

• A spool over the 100 MiB cap is still summed and sorted in one read per prune, as before this PR. A reviewer measured about 2.8 s of that read with 100k events over the cap, and other writers cannot commit while it runs. Shortening it needs an index on created_at, which needs a migration (see "Evaluated and not done").
• Mixed versions. A checkout without this change does not take the migration lock, so old and new code opening a new spool at the same instant can still race. In the reviewers' runs the old-code processes failed and the new ones succeeded.
• Wall-clock steps. The deadline crosses processes as Unix time. A clock step between the build's spawn and the service's start shifts the service's deadline by the step. The 60 s cap and the build's own monotonic deadline bound the effect.
• Blocking calls in the drain (a collector POST of up to 5 s, a locked statement of up to 5 s) can run past the drain budget, as before.
• The prune differential uses distinct timestamps and payloads written by the current serialiser. On exact (created_at, sequence) ties the order is arbitrary in both versions. For payloads whose stored length differs from their re-serialised length, this version counts the stored length, which is what the cap total sums.
• CPython 3.13. I ran the tests on 3.14.7 free-threaded. CI runs them on 3.13 and 3.14, and the design check ran the transactional-DDL recipe and error classification on 3.13.9.

Reviews

• Design check, before the code settled: a red-team, an executed library verification on 3.13 and 3.14, and an independent design. Findings are in check/ in the evidence folder.
• In-session review of bf2ec8e: three lenses with executed checks; two of the three lenses' findings were re-checked by skeptics. All findings are addressed in the commits after bf2ec8e. The largest was that the first startup design, with a 2 s margin and 0.25 s waits, lost telemetry on a 1.5 s hold under main's 3 s budget, where the old code survived.
• GPT-6.1 Sol hard review of bf2ec8e: REQUEST_CHANGES, six findings (review-hard-r1.md). Each is addressed:
  1. Prune blocking appends: batched runs, page-count size check, pauses and a per-tick budget. The over-cap read remains (first known limit).
  2. Short sessions skipping retention: the shutdown prune step.
  3. Close during a tick recorded as a crash: fixed in fe73677.
  4. Retries after an overrun sleep: rechecked after waking.
  5. stderr paths (argparse, SIGINT, parent check): fixed in fe73677.
  6. Timing-dependent tests: they now wait on observed attempts and thread state.
• A delta review of the commits since bf2ec8e follows.

Merge order with #1166 and #1165

This branch is merged with origin/main as of a224dc1. One conflict in collector.py, with main's settled-rejection warning, is resolved to go through write_warning. With #1166 merged as well, the client waits up to 30 s instead of 3 s, so startup can wait out locks of up to about 29 s; with main's 3 s budget alone, up to about 2.5 s.

• The diffs merge without conflicts in either order.
• I merged Keep the telemetry emitter service off the modelling stack #1166 and Stop telemetry test servers when a test body fails #1165 into this branch locally and ran this PR's tests plus test_telemetry_emitter.py, test_telemetry_emitter_startup.py and test_telemetry_emitter_service_imports.py: all passed. That includes test_subprocess_exchanges_ambient_token_and_delivers_events, which times out on origin/main under load. Keep the telemetry emitter service off the modelling stack #1166 fixes that.
• The client builds the deadline with datetime.now(UTC) because Keep the telemetry emitter service off the modelling stack #1166's startup tests replace the module's time with a fake that has no time().

Trade-off to know: with #1166's 30 s budget, a spool that stays locked costs the build up to about 29.5 s at start before it continues without telemetry. With main's current 3 s budget, it costs about 3 s today (the build kills the service at its deadline) and about 2.5 s with this PR, where the service stops 0.5 s early to say why.

Tests run (touched files only, -p no:cacheprovider --basetemp=<scratch>)

test_telemetry_spool_contention.py (new) and test_telemetry_emitter.py: all passed on this branch. I deselected only test_subprocess_exchanges_ambient_token_and_delivers_events; it failed here exactly as on origin/main, from the 3 s budget at load average 90–130, and passes with #1166 merged (above).

Follow-ups (not in this PR)

• Isolate telemetry delivery failures per run #1176 (stacked on this branch): isolate delivery failures per run, with per-run backoff, including the 401 paths that still retry every tick here.
• Let checkouts at different versions share the telemetry spool #1175: let checkouts at different versions share the spool, which also unblocks an index on created_at.
• Keep one build's telemetry login from deciding other builds' runs #1177: keep one build's missing Hugging Face login from marking other builds' runs local-only.
• Decouple the event path from spool writes (an ordered, bounded in-memory queue and a writer thread), so contention never stalls or drops a build's events after startup. A separate session has started this.

axiom: n/a: telemetry infrastructure, no policy encoding

🤖 Generated with Claude Code