diff --git a/docs/howto/diagnose-typed-ooda-database-locked.md b/docs/howto/diagnose-typed-ooda-database-locked.md new file mode 100644 index 000000000..fa7a66f69 --- /dev/null +++ b/docs/howto/diagnose-typed-ooda-database-locked.md @@ -0,0 +1,137 @@ +--- +title: Diagnose the typed-OODA "database is locked" crash-loop +description: Runbook for the systemic `typed outcome persistence failed: database is locked` signature (#4483) — confirm the WAL + writer-lock fix is live, read the journal-mode evidence, and interpret a residual lock warning. +last_updated: 2026-07-23 +review_schedule: as-needed +owner: simard +doc_type: howto +related: + - ../reference/typed-ooda-persistence-concurrency-api.md + - ../reference/ooda-capability-api.md + - ./unblock-stuck-ooda-goals.md + - ./run-ooda-daemon.md +--- + +# Diagnose the typed-OODA "database is locked" crash-loop + +Use this runbook when the OODA daemon logs a synchronized burst of: + +```text +typed goal-session cycle failed (ToolFailed): typed outcome persistence failed: database is locked +typed OODA outbox startup recovery incomplete: typed outcome persistence failed: database is locked +``` + +That signature is issue **#4483**: multiple per-goal cycle writers and the +startup outbox-recovery pass contend for one SQLite ledger that is not in WAL +mode, exhaust the busy timeout, and fail several goals' cycles at once. + +The fix ships in the [typed-OODA persistence concurrency API](../reference/typed-ooda-persistence-concurrency-api.md): +WAL + `synchronous=NORMAL` + `busy_timeout` applied on every connection, plus a +process-wide per-file writer lock. This runbook confirms the fix is live and +interprets anything that still looks like a lock. + +## 1. Confirm the burst signature + +Pull the recent daemon journal: + +```bash +journalctl --user -u simard-ooda --since "-6h" --no-pager \ + | grep -E "database is locked|outbox startup recovery incomplete" +``` + +The #4483 signature is a **synchronized burst** — the same +`database is locked` message across several distinct goals within the same +second — not one isolated slow write. If you see that shape on a build from +before the fix, upgrade the daemon (below). If you see it on a build that +includes the fix, jump to [Step 4](#4-interpret-a-residual-lock). + +## 2. Verify the running build includes the fix + +The fix is transparent — no new flag — so confirm it by the ledger's journal +mode rather than by config. First locate the ledger: + +```bash +ls -l "$SIMARD_STATE_ROOT/typed_ooda/" +# ledger.db <- the outcome ledger +# ledger.db-wal <- present only when WAL is active +# ledger.db-shm +``` + +The presence of `ledger.db-wal` alongside `ledger.db` is the at-a-glance +indicator that WAL is active on the live database. + +## 3. Read the journal-mode evidence + +Query the live ledger read-only: + +```bash +sqlite3 "$SIMARD_STATE_ROOT/typed_ooda/ledger.db" 'PRAGMA journal_mode;' +``` + +Expected output on a fixed daemon: + +```text +wal +``` + +- `journal_mode = wal` → readers and one writer proceed concurrently; no + whole-file exclusive write lock on the common path. This value is stored in + the database file, so an external `sqlite3` reading is authoritative. + +If you instead see `journal_mode = delete` (or `truncate`), the running daemon +predates the fix. Rebuild and redeploy from a source tree that includes issue +#4483, then re-run this step. The first write after upgrade promotes the +database to WAL in place; no migration or manual conversion is required. + +!!! note "Why not check `PRAGMA synchronous` here?" + `synchronous` is a **per-connection** setting, not stored in the database + file. The `sqlite3` CLI opens its own connection and always reports its own + default (`2`/FULL) — never the daemon's `NORMAL` — so it is useless as an + external "is the fix live?" signal. Use `journal_mode` (file-persistent) as + the sole external tell; `synchronous=NORMAL` is verified by the in-process + regression test instead. + +## 4. Interpret a residual lock + +After the fix, a `database is locked` line should not appear under normal +in-process contention. If one still does, distinguish the two remaining causes: + +| Observation | Meaning | Action | +| --- | --- | --- | +| `typed-ooda writer-lock path canonicalization failed; using raw path` (`tracing::warn!`) | The ledger path could not be canonicalized (e.g., removed mid-run); the writer fell back to the raw path, so two handles *might* not share one lock. | Confirm `$SIMARD_STATE_ROOT/typed_ooda/` is stable and not being deleted/relinked while the daemon runs. | +| `database is locked` with **two `simard-ooda` processes** on the same state root | Cross-process contention — out of scope for the in-process writer lock. | Ensure only one daemon owns a state root. See [Run the OODA Daemon](./run-ooda-daemon.md). | +| `PersistenceFailed` that is **not** `database is locked` | A real SQL/serialization fault, surfaced fail-visible (never swallowed). | Read the full `tracing` span; this is a genuine persistence error, not contention. | + +The daemon emits these diagnostics through structured `tracing` / +OpenTelemetry. Read them with: + +```bash +journalctl --user -u simard-ooda --since "-1h" --no-pager \ + | grep -E "typed-ooda|writer-lock|PersistenceFailed" +``` + +## 5. Clear goals stranded by the pre-fix burst + +Goals whose cycles failed during a pre-fix burst are not corrupted — the writes +simply did not commit. Once the daemon is on the fixed build, those goals +resume on their next cycle. If any goal was parked as blocked by a downstream +safeguard during the incident, clear it with the standard runbook: +[Unblock Stuck OODA Goals](./unblock-stuck-ooda-goals.md). + +## What you should *not* need to do + +- **Do not** raise a timeout or add a config flag — there is none to tune; WAL + plus the writer lock remove the contention a longer timeout would only mask. +- **Do not** delete or rebuild `ledger.db` — the fix is additive + (`SCHEMA_VERSION` unchanged) and the existing database is promoted to WAL in + place. +- **Do not** manually delete `ledger.db-wal` / `ledger.db-shm` while the daemon + runs — SQLite manages those sidecars. + +## Related + +- [Typed-OODA persistence concurrency API](../reference/typed-ooda-persistence-concurrency-api.md) + — the WAL + writer-lock contract this runbook verifies. +- [OODA capability API](../reference/ooda-capability-api.md) — the + `PersistenceFailed` error contract. +- [Run the OODA Daemon](./run-ooda-daemon.md) — single-owner state-root setup. diff --git a/docs/index.md b/docs/index.md index fbce969e7..00938f475 100644 --- a/docs/index.md +++ b/docs/index.md @@ -26,6 +26,7 @@ Terminal sessions and repo-grounded engineer runs now bridge through one explici - [Typed-capability OODA architecture](./architecture/typed-ooda-loop.md) - Semantic/typed boundary, actor-session authority, durable terminals, effect outbox, and the explicit remaining migration boundary. - [OODA capability API](./reference/ooda-capability-api.md) - Terminal schemas, authorization, replay, effect leases, current limitations, errors, and policy configuration. +- [Typed-OODA persistence concurrency API](./reference/typed-ooda-persistence-concurrency-api.md) — the writer-safety contract for the outcome ledger (#4483): WAL + `synchronous=NORMAL` + `busy_timeout` on every connection, plus a process-wide per-file writer lock, so concurrent per-goal cycles and startup outbox recovery can never surface `database is locked`. Paired with the [diagnose-the-crash-loop runbook](./howto/diagnose-typed-ooda-database-locked.md). - [Typed OODA goal-session deterministic rails](./reference/typed-ooda-goal-session-rails.md) — the two thin rail fixes that unblocked live OODA goals (#4076): propagating `AMPLIHACK_AGENT_BINARY` to the goal-session `recipe-runner-rs` subprocess (no silent `claude` fallback) and normalizing bare goal repo names to `rysweet/` at spawn admission, plus the additive Act-loop failure-detail log. - [Tutorial: Complete a typed OODA cycle](./tutorials/complete-a-typed-ooda-cycle.md) - Deterministic action, no-action, replay, and conflict examples. - [Tutorial: Run your first local session](./tutorials/run-your-first-local-session.md) - Exercise the local runtime through the primary CLI. diff --git a/docs/reference/typed-ooda-persistence-concurrency-api.md b/docs/reference/typed-ooda-persistence-concurrency-api.md new file mode 100644 index 000000000..d14f11f8e --- /dev/null +++ b/docs/reference/typed-ooda-persistence-concurrency-api.md @@ -0,0 +1,215 @@ +--- +title: Typed-OODA persistence concurrency API +description: How the typed-OODA outcome ledger stays writer-safe under concurrent per-goal cycles and startup outbox recovery — WAL journaling, per-connection pragmas, and a process-wide per-file writer lock that make "database is locked" unreachable. +last_updated: 2026-07-23 +review_schedule: as-needed +owner: simard +doc_type: reference +status: implemented +related: + - ./ooda-capability-api.md + - ../architecture/typed-ooda-loop.md + - ../howto/diagnose-typed-ooda-database-locked.md +--- + +# Typed-OODA persistence concurrency API + +The typed-OODA outcome ledger (`src/typed_ooda/ledger.rs`, `src/typed_ooda/schema.rs`) +is the single SQLite-backed store for terminal outcomes, progress records, +engineer claims, the idempotency registry, and the effect outbox. In live +operation the `simard-ooda` daemon runs **one thread per active goal** inside a +single process (`std::thread::scope`), and each thread opens its **own** +`CapabilityHandler` against the **same** ledger file. Startup also runs an +outbox recovery pass that writes to the same file. + +This page documents the concurrency contract that keeps those writers from +colliding. It is the reference for issue #4483, which eliminated the systemic +`typed outcome persistence failed: database is locked` crash-loop. + +## Guarantee + +> Concurrent per-goal cycle writes and startup outbox recovery against one +> ledger file never surface `SQLITE_BUSY` / `database is locked`. A single slow +> writer cannot fail another goal's cycle. + +The guarantee holds for all writers **inside one process**. Cross-process +contention (two `simard-ooda` processes on the same file) is out of scope; WAL +plus `busy_timeout` still let SQLite's own file locking degrade gracefully +rather than corrupt. + +## How it works + +Two independent, reinforcing layers deliver the guarantee. + +### Layer 1 — correct SQLite configuration on every open + +`schema::configure_connection` applies the durability and contention pragmas on +**every** connection handle, unconditionally, before schema initialization: + +| Pragma | Value | Why | +| --- | --- | --- | +| `busy_timeout` | `5000` ms | A writer waits up to 5 s for a competing writer instead of failing instantly. | +| `journal_mode` | `WAL` | Write-ahead logging lets readers and one writer proceed concurrently; no whole-file exclusive lock for the common path. | +| `synchronous` | `NORMAL` | Safe with WAL; avoids an `fsync` per commit while preserving crash consistency. | +| `foreign_keys` | `ON` | Referential integrity across outcome / effect / claim tables. | + +`configure_connection` is idempotent — re-asserting WAL on an already-WAL +database is a cheap no-op — so it is safe to run on the first open and on every +subsequent open. + +!!! note "Why every open, not just first-init" + Schema initialization early-returns once `user_version == SCHEMA_VERSION`, + and before #4483 the `journal_mode = WAL` pragma lived *inside* that gated + init path. `journal_mode=WAL` is a persistent, file-stored property, so a + database first created by current code stays WAL across every reopen — the + setting is not lost when the connection closes. The real gaps were narrower: + (a) a **legacy ledger created by a build that predated the WAL line** never + gets upgraded, because the version gate short-circuits before the pragma + runs; and (b) `synchronous` (a per-connection setting) was never applied at + all. Moving the pragmas into `configure_connection` — called + unconditionally, outside the version gate — makes WAL authoritative on + **every** handle regardless of when the file was created, and applies + `synchronous=NORMAL` to every connection. WAL is necessary but not + sufficient: it still permits only one writer at a time, so it does not by + itself prevent multi-connection `SQLITE_BUSY` — which is exactly why Layer 2 + exists. + +`journal_mode` is a persistent, file-stored property, so it is verifiable from +any connection — including an external `sqlite3` inspection: + +```sql +PRAGMA journal_mode; -- => wal +``` + +`synchronous`, by contrast, is a **per-connection** setting that is not stored +in the database file. An external `sqlite3` process opens its own connection and +reports its own default (`2`/FULL), *not* the daemon's `NORMAL`. It is therefore +observable only from within the daemon's own connection (see the regression test +below), never via external inspection. + +### Layer 2 — process-wide per-file writer lock + +WAL still permits only **one** writer at a time. Under a synchronized burst +(seven goals plus startup recovery), several handles can still contend and, +once `busy_timeout` is exhausted, one would fail. Layer 2 removes that race at +the source. + +A process-global registry maps each **canonicalized** ledger path to a shared +writer lock: + +```text +WRITER_LOCKS: OnceLock>>>> +``` + +Every `CapabilityHandler::open` resolves the canonical path and registers (or +reuses) the `Arc>` for that path. All handlers pointing at the same +file therefore share **one** writer lock, even though each has its own +`Connection`. Path canonicalization means a relative handle and an absolute +handle to the same file share the same lock. + +Every write acquires the writer lock **before** the per-connection mutex: + +```text +lock(): + 1. writer_lock.lock() # process-wide, per file (ordered first) + 2. connection.lock() # per handler + -> LedgerWriteGuard { _writer, connection } +``` + +Lock ordering is fixed at the single `lock()` site (writer → connection), so no +deadlock is possible. The guard is held for the entire write operation and +released when it drops. + +`LedgerWriteGuard` derefs to `Connection`, so all existing call sites +(`let mut connection = self.lock()?;`) are unchanged — serialization is fully +transparent to callers, including the startup outbox recovery path +(`drain_pending`). This is why one goal's slow write can no longer time out and +fail a different goal's cycle: the writes are serialized, not racing. + +## Failure visibility + +Persistence is fail-visible; nothing is swallowed. + +| Condition | Result | +| --- | --- | +| SQLite busy/locked | Retried within `busy_timeout`; serialized by the writer lock so it does not surface in normal operation. | +| Real SQL / serialization error | Returned as `CapabilityError::PersistenceFailed` (cycle path: `PersistenceFailed`), never a silent fallback. | +| Poisoned **connection** mutex | Surfaced as an `Err` — a poisoned connection is a real fault. | +| Poisoned **writer** `()` mutex | Recovered (`into_inner`) — the `()` guard protects no data, so one panic must not cascade into a crash loop across every goal. | +| `canonicalize` fails (path removed mid-run) | Falls back to the raw path and emits `tracing::warn!` — never panics, never silent. | + +All new diagnostics use structured `tracing` / OpenTelemetry only. No +`print!` / `println!` is introduced. See the +[OODA capability API errors table](./ooda-capability-api.md#errors) for the full +`PersistenceFailed` semantics. + +## Configuration + +There are **no new configuration knobs, environment variables, or CLI flags**. +The fix is additive and non-breaking: + +- `SCHEMA_VERSION` stays `1`; no schema-shape change and no migration. +- No public-API change; `CapabilityHandler::open`, `record_*`, and the read + API (`simard ooda outcomes ...`) keep their existing signatures. +- The busy timeout is a named constant (`schema::BUSY_TIMEOUT = 5000 ms`), + applied uniformly on every open. It is intentionally not operator-tunable — + WAL plus the writer lock remove the contention that a longer timeout would + otherwise paper over. + +Existing ledger paths need no action: the first write after upgrade runs +`configure_connection`, which promotes the database to WAL in place. WAL adds +`-wal` and `-shm` sidecar files next to the ledger; both are managed by SQLite +and require no operator handling. + +## Verifying the fix + +Inspect a live ledger (read-only) to confirm the persistent journal mode: + +```bash +sqlite3 "$SIMARD_STATE_ROOT/typed_ooda/ledger.db" 'PRAGMA journal_mode;' +# journal_mode -> wal +``` + +`journal_mode` is stored in the database file, so this external reading is +authoritative. Do **not** try to verify `synchronous` this way: it is a +per-connection setting, so the `sqlite3` CLI reports its own connection's default +(`2`/FULL), not the daemon's `NORMAL`. `synchronous=NORMAL` is asserted on the +daemon's own connection and is checked by the in-process regression test below. + +The presence of `ledger.db-wal` next to `ledger.db` is a further at-a-glance +confirmation that WAL is active. + +The concurrency contract is exercised by a regression test in +`src/typed_ooda/ledger.rs` (`#[cfg(test)]`): it opens multiple +`CapabilityHandler`s on one temp-dir ledger, drives burst writes plus a +startup-recovery-style writer from several threads, and asserts that + +1. no operation returns `PersistenceFailed` with `database is locked`, +2. `PRAGMA journal_mode == wal` and `PRAGMA synchronous == 1`, and +3. the final row count is consistent across handlers (serialization held). + +The test reads `PRAGMA synchronous` from a `CapabilityHandler`'s **own** +connection — the only place `NORMAL` is observable — not from an external +process. + +Without the fix the test flakes under `SQLITE_BUSY`; with WAL plus the writer +lock it passes deterministically. + +!!! warning "Maintainer note — keep this page in lockstep with the code" + This reference is the implementation spec for #4483 and names the artifacts + the fix must ship: `schema::configure_connection`, `schema::BUSY_TIMEOUT`, + the process-global `WRITER_LOCKS` registry, `LedgerWriteGuard`, and the + `writer_lock` field on the handler. After the fix lands, run a doc + verification pass: `grep` those symbol names under `src/typed_ooda/` and + confirm the regression test asserts `PRAGMA journal_mode == wal`. If any + symbol is renamed or the timeout stops being a named constant, update this + page so the contract stays accurate. + +## Related + +- [OODA capability API](./ooda-capability-api.md) — terminal schemas, the + effect outbox, and the `PersistenceFailed` error contract this layer upholds. +- [Typed-capability OODA architecture](../architecture/typed-ooda-loop.md) — + where the ledger sits in the goal-session path. +- [Diagnose the typed-OODA "database is locked" crash-loop](../howto/diagnose-typed-ooda-database-locked.md) + — operator runbook for the #4483 signature. diff --git a/mkdocs.yml b/mkdocs.yml index c15fdaf6e..297b19368 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -192,6 +192,7 @@ nav: - Diagnose a Deferred/Serialized Engineer Spawn (overlap): howto/diagnose-a-deferred-engineer-spawn.md - Configure Resource-Aware Engineer Admission: howto/configure-resource-aware-admission.md - Unblock Stuck OODA Goals: howto/unblock-stuck-ooda-goals.md + - Diagnose the Typed-OODA "database is locked" Crash-Loop: howto/diagnose-typed-ooda-database-locked.md - Diagnose a No-Progress Block and Read Its WHY: howto/diagnose-a-no-progress-block.md - Re-Investigate Bare-Blocked OODA Goals: howto/reinvestigate-bare-blocked-goals.md - Add a New Recipe-Brain Phase: howto/add-a-new-recipe-brain-phase.md @@ -290,6 +291,7 @@ nav: - Investigate-Before-Reap API: reference/investigate-stale-engineer-api.md - Tombstoned-Goal Engineer Reaper API: reference/tombstoned-goal-engineer-reaper-api.md - Typed OODA Goal-Session Deterministic Rails: reference/typed-ooda-goal-session-rails.md + - Typed-OODA Persistence Concurrency API: reference/typed-ooda-persistence-concurrency-api.md - Stable Goal-Session Identity API: reference/stable-goal-session-identity-api.md - Standing-Research Novelty-Directive API: reference/standing-research-goal-novelty-directive-api.md - Research-Goal Never-Idle Rail API: reference/research-goal-never-idle-rail-api.md diff --git a/src/typed_ooda/ledger.rs b/src/typed_ooda/ledger.rs index cf677f2f8..e47711e99 100644 --- a/src/typed_ooda/ledger.rs +++ b/src/typed_ooda/ledger.rs @@ -1,8 +1,9 @@ -use std::collections::BTreeSet; +use std::collections::{BTreeSet, HashMap}; use std::io::{self, Read, Write}; +use std::ops::{Deref, DerefMut}; use std::path::{Path, PathBuf}; use std::process::{Command, Stdio}; -use std::sync::{Mutex, MutexGuard}; +use std::sync::{Arc, Mutex, MutexGuard, OnceLock}; use std::time::{Duration, SystemTime, UNIX_EPOCH}; use rusqlite::{Connection, OptionalExtension, Transaction, TransactionBehavior, params}; @@ -145,10 +146,84 @@ pub trait EngineerLiveness: Send + Sync { pub struct CapabilityHandler { connection: Mutex, + /// Process-wide writer serialization for this ledger file. + /// + /// Every [`CapabilityHandler`] opened on the same canonical path shares this + /// `Arc>`, so writes from independent per-goal handlers (each with + /// its OWN [`Connection`], spawned one-per-goal in `concurrent.rs`) and from + /// the startup outbox-recovery path cannot collide. The in-process + /// `connection` mutex only serializes WITHIN a handler; this lock serializes + /// ACROSS handlers, which is what a single burst of `SQLITE_BUSY` failures + /// (issue #4483) required. Acquired in [`CapabilityHandler::lock`] before the + /// connection mutex, giving a single consistent lock order (no deadlock). + writer_lock: Arc>, policy: CapabilityPolicy, engineer_liveness: Option>, } +/// Process-wide registry of per-ledger-path writer locks. +/// +/// Keyed by the CANONICAL ledger path so two handlers opened via different but +/// equivalent path spellings (e.g. relative vs. absolute) still share one lock. +static LEDGER_WRITER_LOCKS: OnceLock>>>> = OnceLock::new(); + +/// Resolve (creating on first use) the process-wide writer lock for `path`. +/// +/// `path` must already exist on disk — callers open the SQLite connection (which +/// creates the file) before calling this, so canonicalization succeeds. +fn writer_lock_for(path: &Path) -> CapabilityResult>> { + let canonical = std::fs::canonicalize(path).map_err(|error| { + persistence_message(format!( + "typed outcome persistence failed: cannot canonicalize ledger path \ + {}: {error}", + path.display() + )) + })?; + let registry = LEDGER_WRITER_LOCKS.get_or_init(|| Mutex::new(HashMap::new())); + let mut guard = registry + .lock() + .map_err(|_| persistence_message("outcome ledger writer-lock registry is poisoned"))?; + match guard.get(&canonical) { + Some(existing) => Ok(Arc::clone(existing)), + None => { + let lock = Arc::new(Mutex::new(())); + tracing::debug!( + target: "typed_ooda::ledger", + ledger_path = %canonical.display(), + "registered process-wide writer lock for ledger path" + ); + guard.insert(canonical, Arc::clone(&lock)); + Ok(lock) + } + } +} + +/// A held write guard bundling BOTH the process-wide per-path writer lock and +/// the per-handler connection mutex. +/// +/// Derefs to [`Connection`] so every existing `self.lock()?` call site is +/// unchanged. The writer guard is dropped AFTER the connection guard (fields +/// drop in declaration order), releasing locks in reverse acquisition order. +struct WriteGuard<'a> { + connection: MutexGuard<'a, Connection>, + // Held for the lifetime of the guard; released last. Never read directly. + _writer: MutexGuard<'a, ()>, +} + +impl Deref for WriteGuard<'_> { + type Target = Connection; + + fn deref(&self) -> &Connection { + &self.connection + } +} + +impl DerefMut for WriteGuard<'_> { + fn deref_mut(&mut self) -> &mut Connection { + &mut self.connection + } +} + #[derive(Debug)] struct ActorBinding { cycle_id: String, @@ -253,13 +328,25 @@ impl std::fmt::Debug for CapabilityHandler { impl CapabilityHandler { pub fn open(path: impl AsRef, policy: CapabilityPolicy) -> CapabilityResult { - let mut connection = Connection::open(path.as_ref()).map_err(persistence)?; - connection - .busy_timeout(Duration::from_secs(5)) - .map_err(persistence)?; - super::schema::initialize(&mut connection, now_millis()).map_err(persistence)?; + let path = path.as_ref(); + let mut connection = Connection::open(path).map_err(persistence)?; + // Apply WAL + synchronous=NORMAL + busy_timeout + foreign_keys on EVERY + // open, before `initialize` (which early-returns on an already-created + // schema and would otherwise leave these unset). See + // `super::schema::configure_connection`. + super::schema::configure_connection(&connection).map_err(persistence)?; + let writer_lock = writer_lock_for(path)?; + { + // Serialize first-time schema creation (a real write transaction) + // against concurrent writers on the same file. + let _writer = writer_lock + .lock() + .map_err(|_| persistence_message("outcome ledger writer lock is poisoned"))?; + super::schema::initialize(&mut connection, now_millis()).map_err(persistence)?; + } Ok(Self { connection: Mutex::new(connection), + writer_lock, policy, engineer_liveness: None, }) @@ -1925,10 +2012,24 @@ impl CapabilityHandler { Ok(()) } - fn lock(&self) -> CapabilityResult> { - self.connection + fn lock(&self) -> CapabilityResult> { + // Acquire the process-wide per-path writer lock FIRST, then the + // per-handler connection mutex. This single, consistent order across all + // call sites serializes every ledger access (across independent + // handlers on the same file) so a burst of concurrent per-goal and + // startup-recovery writes cannot collide into `database is locked`. + let writer = self + .writer_lock .lock() - .map_err(|_| persistence_message("outcome ledger lock is poisoned")) + .map_err(|_| persistence_message("outcome ledger writer lock is poisoned"))?; + let connection = self + .connection + .lock() + .map_err(|_| persistence_message("outcome ledger lock is poisoned"))?; + Ok(WriteGuard { + connection, + _writer: writer, + }) } /// True iff the existing claim for `claim_key` corresponds to a live @@ -3519,3 +3620,285 @@ mod actor_session_scope_tests { } } } + +/// TDD regression suite for the systemic `database is locked` crash-loop +/// (issue #4483). +/// +/// ## Incident shape +/// +/// One `simard-ooda` process spawns one thread per goal (`std::thread::scope` +/// in `concurrent.rs`). Each thread opens its OWN [`CapabilityHandler`] on the +/// SAME ledger file, so N independent SQLite connections each sit behind their +/// own `Mutex`. The in-process mutex serializes writes only WITHIN +/// a handler, never ACROSS handlers. Combined with a rollback-journal DB (WAL +/// was never applied on an already-initialized ledger — see +/// `schema::configure_connection_tests`), the outbox startup-recovery writer +/// and the concurrent per-goal cycle writers took colliding whole-file +/// EXCLUSIVE locks and failed, in one synchronized burst, with: +/// +/// `typed outcome persistence failed: database is locked` +/// +/// firing across 7 distinct goals plus 6 startup-recovery paths. +/// +/// ## Fix under test (two reinforcing layers) +/// +/// 1. `journal_mode=WAL` applied on every open (readers + one writer proceed +/// concurrently) — asserted here via the file-persistent `journal_mode`. +/// 2. A process-wide, per-canonical-path writer lock acquired by BOTH the +/// startup-recovery path and every per-goal cycle write, so concurrent +/// connections to the same file cannot collide at all. +/// +/// These tests exercise the PUBLIC handler API under real thread contention. +/// Without the fix they fail (either the crate fails to compile because +/// `configure_connection` does not exist yet — the TDD "red" contract — or, +/// once the pragmas alone are added, the burst still flakes on `SQLITE_BUSY` +/// until the writer lock lands). +#[cfg(test)] +mod database_locked_regression_tests { + use super::*; + use std::sync::Barrier; + + const POLICY_REVISION: &str = "policy-v1"; + + fn open_shared_handler(path: &std::path::Path) -> CapabilityHandler { + CapabilityHandler::open(path, CapabilityPolicy::new(POLICY_REVISION)) + .expect("open capability handler on shared ledger path") + } + + /// A single terminal write through the exact `record_no_action` path the + /// crash signature came from. Every call uses a UNIQUE `(session, cycle, + /// request)` triple so it never trips `terminal_outcomes`' + /// `UNIQUE(session_id, cycle_id)` or the `request_id` PRIMARY KEY — any + /// failure is therefore a genuine persistence/locking failure, not a + /// data-model conflict. + fn record_one_no_action( + handler: &CapabilityHandler, + key: &str, + goal: &str, + ) -> CapabilityResult { + let session = format!("session-{key}"); + let cycle = format!("cycle-{key}"); + let request = format!("request-{key}"); + let actor = AuthenticatedToolContext::new( + "goal-session-actor", + &session, + [CapabilityGrant::RecordNoAction], + ) + .bound_to_cycle_goal(&cycle, goal); + handler.record_no_action( + &actor, + RecordNoActionRequest { + identity: TerminalRequestIdentity::new(&request, &session, &cycle, goal), + reason: OpaqueBytes::from(b"no action needed this cycle".to_vec()), + raw_semantic: OpaqueBytes::from(b"observed and decided".to_vec()), + evidence: Vec::new(), + }, + ) + } + + fn terminal_row_count(path: &std::path::Path) -> i64 { + let connection = Connection::open(path).expect("open ledger for row count"); + connection + .query_row("SELECT COUNT(*) FROM terminal_outcomes", [], |row| { + row.get(0) + }) + .expect("count terminal_outcomes") + } + + fn file_journal_mode(path: &std::path::Path) -> String { + let connection = Connection::open(path).expect("open ledger for journal_mode"); + connection + .query_row("PRAGMA journal_mode", [], |row| row.get::<_, String>(0)) + .expect("read journal_mode") + } + + /// The handler must leave the ledger FILE in WAL mode. WAL is a persistent + /// file property, so a fresh independent connection observes it — this is + /// the one lock-avoidance layer that IS externally verifiable (unlike the + /// per-connection `synchronous`/`busy_timeout`, checked in schema tests). + #[test] + fn opening_a_handler_puts_the_ledger_file_in_wal_mode() { + let dir = tempfile::tempdir().expect("tempdir"); + let path = dir.path().join("outcomes.sqlite3"); + + let _handler = open_shared_handler(&path); + + assert_eq!( + file_journal_mode(&path), + "wal", + "CapabilityHandler::open must configure the ledger into WAL journal mode" + ); + } + + /// CORE #4483 REGRESSION. + /// + /// Reproduce the incident: many goals, each with its OWN handler on the + /// SAME ledger file, all bursting terminal writes at once (released + /// together by a barrier). Assert that NOT ONE write fails with + /// `database is locked`, and that every write is durably persisted exactly + /// once. Before the fix, the synchronized burst across independent + /// connections fails a subset of writes with `SQLITE_BUSY`. + #[test] + fn concurrent_handlers_burst_writes_never_hit_database_locked() { + const GOALS: usize = 8; // >= the 7 goals from the live incident + const WRITES_PER_GOAL: usize = 25; + + let dir = tempfile::tempdir().expect("tempdir"); + let path = dir.path().join("outcomes.sqlite3"); + + // Warm up: create the schema once so per-thread opens all early-return + // in `initialize` — mirroring production, where the ledger file already + // exists from prior runs and the burst is on WRITES, not first-init. + drop(open_shared_handler(&path)); + + // One independent handler (= one SQLite connection) per goal thread, + // exactly like the per-goal `std::thread::scope` spawn in concurrent.rs. + let handlers: Vec = + (0..GOALS).map(|_| open_shared_handler(&path)).collect(); + let barrier = Barrier::new(GOALS); + + let lock_failures: Vec = std::thread::scope(|scope| { + let handles: Vec<_> = handlers + .iter() + .enumerate() + .map(|(goal_index, handler)| { + let barrier = &barrier; + scope.spawn(move || { + let goal = format!("goal-{goal_index}"); + let mut locked = Vec::new(); + barrier.wait(); // release all goals simultaneously + for write_index in 0..WRITES_PER_GOAL { + let key = format!("g{goal_index}-w{write_index}"); + if let Err(error) = record_one_no_action(handler, &key, &goal) { + let message = error.to_string(); + if message.contains("database is locked") { + locked.push(format!( + "goal {goal_index} write {write_index}: {message}" + )); + } else { + panic!( + "unexpected non-lock persistence error \ + (goal {goal_index} write {write_index}): {message}" + ); + } + } + } + locked + }) + }) + .collect(); + handles + .into_iter() + .flat_map(|handle| handle.join().expect("goal thread panicked")) + .collect() + }); + + assert!( + lock_failures.is_empty(), + "typed outcome writes must NEVER fail with `database is locked`; \ + got {} lock failures across concurrent goals:\n{:#?}", + lock_failures.len(), + lock_failures + ); + assert_eq!( + terminal_row_count(&path) as usize, + GOALS * WRITES_PER_GOAL, + "every concurrent write must be durably persisted exactly once" + ); + assert_eq!( + file_journal_mode(&path), + "wal", + "the ledger must remain in WAL mode throughout the concurrent burst" + ); + } + + /// Startup outbox recovery vs. live cycle writes. + /// + /// The 6 `typed OODA outbox startup recovery incomplete: ... database is + /// locked` failures came from the recovery path (which opens its OWN fresh + /// connection) colliding with per-goal cycle writers. Here a recovery-style + /// worker repeatedly opens a BRAND-NEW handler mid-burst while several goal + /// writers hammer the same file. The process-wide per-path writer lock must + /// serialize all of them so no recovery or cycle write hits + /// `database is locked`. + #[test] + fn startup_recovery_serializes_against_concurrent_cycle_writes() { + const WRITERS: usize = 6; + const WRITES_PER_WRITER: usize = 20; + const RECOVERY_PASSES: usize = 20; + + let dir = tempfile::tempdir().expect("tempdir"); + let path = dir.path().join("outcomes.sqlite3"); + drop(open_shared_handler(&path)); // pre-create schema (already-exists case) + + let writer_handlers: Vec = + (0..WRITERS).map(|_| open_shared_handler(&path)).collect(); + // +1 participant for the recovery worker. + let barrier = Barrier::new(WRITERS + 1); + + let lock_failures: Vec = std::thread::scope(|scope| { + let mut handles = Vec::new(); + + for (writer_index, handler) in writer_handlers.iter().enumerate() { + let barrier = &barrier; + handles.push(scope.spawn(move || { + let goal = format!("cycle-goal-{writer_index}"); + let mut locked = Vec::new(); + barrier.wait(); + for write_index in 0..WRITES_PER_WRITER { + let key = format!("cw{writer_index}-{write_index}"); + if let Err(error) = record_one_no_action(handler, &key, &goal) { + let message = error.to_string(); + if message.contains("database is locked") { + locked.push(format!("cycle writer {writer_index}: {message}")); + } else { + panic!("unexpected cycle-write error: {message}"); + } + } + } + locked + })); + } + + // Recovery worker: opens a fresh handler each pass (as startup + // outbox recovery does) and writes, racing the cycle writers. + let recovery_path = path.as_path(); + let barrier = &barrier; + handles.push(scope.spawn(move || { + let mut locked = Vec::new(); + barrier.wait(); + for pass in 0..RECOVERY_PASSES { + let handler = open_shared_handler(recovery_path); + let key = format!("recovery-{pass}"); + if let Err(error) = record_one_no_action(&handler, &key, "goal-recovery") { + let message = error.to_string(); + if message.contains("database is locked") { + locked.push(format!("startup recovery pass {pass}: {message}")); + } else { + panic!("unexpected recovery-write error: {message}"); + } + } + } + locked + })); + + handles + .into_iter() + .flat_map(|handle| handle.join().expect("worker thread panicked")) + .collect() + }); + + assert!( + lock_failures.is_empty(), + "startup recovery must be serialized against cycle writes so a single \ + lock cannot fail multiple goals; got {} lock failures:\n{:#?}", + lock_failures.len(), + lock_failures + ); + assert_eq!( + terminal_row_count(&path) as usize, + WRITERS * WRITES_PER_WRITER + RECOVERY_PASSES, + "every cycle and recovery write must be persisted exactly once" + ); + } +} diff --git a/src/typed_ooda/schema.rs b/src/typed_ooda/schema.rs index 188a2023d..ec130595a 100644 --- a/src/typed_ooda/schema.rs +++ b/src/typed_ooda/schema.rs @@ -1,7 +1,52 @@ +use std::time::Duration; + use rusqlite::{Connection, TransactionBehavior, params}; const SCHEMA_VERSION: i64 = 1; +/// Baseline SQLite `busy_timeout` applied to every ledger connection. +/// +/// 5s matches the value the live incident exhausted before the WAL + +/// process-wide writer-lock layers were added. Kept as a named constant so the +/// contract is grep-able and single-sourced; once WAL and the writer lock +/// remove the contention that produced `SQLITE_BUSY`, this is a defensive +/// backstop rather than the primary mechanism. +pub(super) const BUSY_TIMEOUT: Duration = Duration::from_millis(5000); + +/// Apply the connection-level configuration required to avoid the systemic +/// `database is locked` crash-loop (issue #4483). +/// +/// This MUST run on EVERY [`Connection`] open, unconditionally and BEFORE +/// [`initialize`]. [`initialize`] early-returns once +/// `PRAGMA user_version == SCHEMA_VERSION`, so any pragma set only inside it is +/// never re-applied to an already-initialized ledger — which is every ledger +/// after the first run. The live incident's ledgers were therefore left in the +/// default rollback-journal mode (whole-file EXCLUSIVE write locks) with no +/// `busy_timeout` and `synchronous=FULL`. +/// +/// The configuration: +/// - `busy_timeout` — wait instead of failing immediately on a momentarily held +/// lock. +/// - `journal_mode = WAL` — readers and a single writer proceed concurrently +/// instead of contending on a whole-file exclusive lock. WAL is a persistent +/// file property, so applying it here also upgrades legacy delete-mode +/// ledgers on open. +/// - `synchronous = NORMAL` — durable under WAL, far cheaper than FULL. +/// - `foreign_keys = ON` — preserve referential integrity (mirrors +/// [`initialize`], which also asserts it). +/// +/// Idempotent: re-asserting WAL on an already-WAL connection is a cheap no-op, +/// so calling this on every open is safe. +pub(super) fn configure_connection(connection: &Connection) -> rusqlite::Result<()> { + connection.busy_timeout(BUSY_TIMEOUT)?; + connection.execute_batch( + "PRAGMA journal_mode = WAL;\n\ + PRAGMA synchronous = NORMAL;\n\ + PRAGMA foreign_keys = ON;", + )?; + Ok(()) +} + pub(super) fn initialize(connection: &mut Connection, now_millis: i64) -> rusqlite::Result<()> { connection.execute_batch("PRAGMA foreign_keys = ON;")?; let version = schema_version(connection)?; @@ -223,3 +268,160 @@ fn ensure_column( } Ok(()) } + +// --------------------------------------------------------------------------- +// TDD regression suite for the systemic `database is locked` crash-loop +// (issue #4483). +// +// Root cause layer 1: SQLite pragmas were applied only inside `initialize`, +// which early-returns once `PRAGMA user_version == SCHEMA_VERSION`. On an +// already-initialized ledger (every run after the first) the connection was +// therefore left in the default rollback-journal mode (`delete`) with +// `synchronous=FULL` and NO `busy_timeout`. Rollback-journal mode takes a +// whole-file EXCLUSIVE write lock, so the outbox startup-recovery writer and +// the concurrent per-goal cycle writers collided and failed with +// `SQLITE_BUSY` -> "database is locked". +// +// The fix introduces `configure_connection`, applied UNCONDITIONALLY on every +// `Connection::open` (outside the version gate). These tests pin its contract +// and are written against the intended (not-yet-existing) API surface, so this +// module is compile-red until Step 8 lands `configure_connection` and +// `BUSY_TIMEOUT`. +// +// NOTE on external verifiability: `journal_mode = WAL` is a persistent file +// property and can be re-read from any fresh connection to the file. +// `synchronous` and `busy_timeout` are PER-CONNECTION and are NOT stored in +// the database file, so they can only be asserted on the very connection that +// `configure_connection` was applied to (as done here) — never via an external +// `sqlite3` CLI opening its own connection. +#[cfg(test)] +mod configure_connection_tests { + use super::*; + + fn open_file_connection() -> (tempfile::TempDir, Connection) { + let dir = tempfile::tempdir().expect("tempdir"); + // WAL requires a real on-disk database; an in-memory DB cannot be WAL. + let connection = Connection::open(dir.path().join("outcomes.sqlite3")) + .expect("open on-disk sqlite database"); + (dir, connection) + } + + fn journal_mode(connection: &Connection) -> String { + connection + .query_row("PRAGMA journal_mode", [], |row| row.get::<_, String>(0)) + .expect("read journal_mode") + } + + fn synchronous(connection: &Connection) -> i64 { + connection + .query_row("PRAGMA synchronous", [], |row| row.get::<_, i64>(0)) + .expect("read synchronous") + } + + fn busy_timeout_millis(connection: &Connection) -> i64 { + connection + .query_row("PRAGMA busy_timeout", [], |row| row.get::<_, i64>(0)) + .expect("read busy_timeout") + } + + /// The named baseline `busy_timeout` is 5s, matching the value the incident + /// exhausted before the WAL + writer-lock layers were added. Kept as a + /// named constant so the contract is grep-able and single-sourced. + #[test] + fn busy_timeout_constant_is_five_seconds() { + assert_eq!(BUSY_TIMEOUT, std::time::Duration::from_millis(5000)); + } + + /// Core contract: a single `configure_connection` call flips the connection + /// into WAL journal mode, sets `synchronous=NORMAL` (1), applies the + /// `busy_timeout`, and leaves `foreign_keys` enforced. Before the fix none + /// of these held on an already-initialized DB. + #[test] + fn configure_connection_sets_wal_normal_busy_timeout_and_foreign_keys() { + let (_dir, connection) = open_file_connection(); + + configure_connection(&connection).expect("configure_connection must succeed"); + + assert_eq!( + journal_mode(&connection), + "wal", + "journal_mode must be WAL so readers and one writer proceed concurrently" + ); + assert_eq!( + synchronous(&connection), + 1, + "synchronous must be NORMAL (1) — durable enough under WAL, far cheaper than FULL" + ); + assert_eq!( + busy_timeout_millis(&connection), + BUSY_TIMEOUT.as_millis() as i64, + "busy_timeout must be applied on every connection, not only in open()" + ); + let foreign_keys: i64 = connection + .query_row("PRAGMA foreign_keys", [], |row| row.get(0)) + .expect("read foreign_keys"); + assert_eq!(foreign_keys, 1, "foreign_keys must remain enforced"); + } + + /// `configure_connection` must be idempotent: re-asserting WAL on an + /// already-WAL connection is a cheap no-op, never an error. Every + /// `CapabilityHandler::open` calls it, so it runs many times per file. + #[test] + fn configure_connection_is_idempotent() { + let (_dir, connection) = open_file_connection(); + + configure_connection(&connection).expect("first configure"); + configure_connection(&connection).expect("second configure must be a no-op success"); + + assert_eq!(journal_mode(&connection), "wal"); + assert_eq!(synchronous(&connection), 1); + } + + /// The legacy-upgrade path: a ledger created by a PRE-WAL build persists + /// `journal_mode=delete` on disk and has `user_version == SCHEMA_VERSION`, + /// so `initialize` early-returns and never touches the journal mode. + /// `configure_connection`, applied on EVERY open, must still upgrade the + /// file to WAL. This is the exact shape of the already-initialized ledgers + /// in the live incident. + #[test] + fn already_initialized_delete_mode_ledger_is_upgraded_to_wal() { + let dir = tempfile::tempdir().expect("tempdir"); + let path = dir.path().join("outcomes.sqlite3"); + + // Simulate a pre-fix ledger: initialize, then force rollback-journal + // mode as a pre-WAL build would have left it. + { + let mut connection = Connection::open(&path).expect("open legacy ledger"); + initialize(&mut connection, 0).expect("initialize legacy ledger"); + connection + .pragma_update(None, "journal_mode", "DELETE") + .expect("force delete journal mode"); + assert_eq!( + journal_mode(&connection), + "delete", + "precondition: legacy ledger is in rollback-journal mode" + ); + } + + // Reopen exactly as CapabilityHandler::open will: configure BEFORE + // initialize. `initialize` will early-return (user_version already 1), + // so only `configure_connection` can perform the WAL upgrade. + let mut connection = Connection::open(&path).expect("reopen legacy ledger"); + configure_connection(&connection).expect("configure on reopen"); + initialize(&mut connection, 0).expect("initialize is a no-op on reopen"); + + assert_eq!( + journal_mode(&connection), + "wal", + "an already-initialized delete-mode ledger MUST be upgraded to WAL on open" + ); + + // And the upgrade is file-persistent: a brand-new connection sees WAL. + let fresh = Connection::open(&path).expect("fresh connection to upgraded ledger"); + assert_eq!( + journal_mode(&fresh), + "wal", + "WAL is a persistent file property visible to every subsequent connection" + ); + } +}