From 9331a8107e0a8071b7007bdfe8ade45c5583c7f6 Mon Sep 17 00:00:00 2001 From: Ayla Croft Date: Thu, 24 Sep 2026 19:19:12 -0400 Subject: [PATCH] fix(s005): take the SQLite write lock up front, and close R26's cause An intermittent Database busy failure had failed the gate in a different test each time across five pull requests in two days. It is gone, for the reason it happened. A DEFERRED transaction takes no lock at BEGIN and starts as a reader. At its first write it tries to upgrade, and if another connection has written since, SQLite returns SQLITE_BUSY immediately and without invoking the busy handler, because blocking there risks deadlock. No busy_timeout reaches that path, which is why raising it from five seconds to thirty changed nothing: the observation that should have pointed at the mechanism a day earlier than it did. Both SQLite repos now set default_transaction_mode: :immediate, which takes the write lock at BEGIN where the handler is allowed to wait. It is configured for every environment rather than only the suite, because the hazard is SQLite's and not the test harness's, and guarded on the adapter so it cannot reach the Postgres build, which has neither the option nor the hazard. The reproduction is the part worth keeping. R26 has read not once reproduced locally since it was opened; it now reproduces in a tenth of a second by driving two connections through both sequences, asserting the old one is refused in under a second despite a five-second timeout and the new one waits and succeeds. An intermittent fault that merely stops appearing is a fault you got lucky with. R26 recorded three candidate fixes when it was first diagnosed, and all three reduce how often two connections contend rather than changing what happens when they do. The diagnosis was right and the proposals did not follow from it. They are not taken, and the register now says so. The row is not closed. Its lift condition is ten consecutive green runs, which this can begin earning and cannot assert today. mix gate: 798 passed (14 properties, 784 tests), 18 excluded. Signed-off-by: Ayla Croft --- CHANGELOG.md | 26 ++++++ config/config.exs | 16 ++++ config/test.exs | 13 ++- coverage.tsv | 1 + docs/05-data-model.md | 24 +++++ docs/06-risk-register.md | 1 + .../repo/sqlite_transaction_mode_test.exs | 89 +++++++++++++++++++ .../repo/transaction_mode_configured_test.exs | 34 +++++++ 8 files changed, 202 insertions(+), 2 deletions(-) create mode 100644 test/trinity/repo/sqlite_transaction_mode_test.exs create mode 100644 test/trinity/repo/transaction_mode_configured_test.exs diff --git a/CHANGELOG.md b/CHANGELOG.md index 4e27afb..320b326 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -24,6 +24,32 @@ evidence for each increment is retained by the maintainers and summarised here. ## 2026-09-24 +### `slice/005` — Transactions take the write lock up front +An intermittent "database busy" failure had been failing the build in a different test each time for +two days, across five pull requests. It is gone, for the reason it happened rather than around it. + +A transaction that begins in SQLite's default mode takes no lock and starts as a reader. At its first +write it asks to upgrade, and if another connection has written in the meantime the database refuses +**immediately and without waiting**, because waiting there could deadlock. No timeout reaches that +path, which is why raising the timeout from five seconds to thirty had changed nothing: the +observation that should have pointed at the cause a day earlier than it did. + +Transactions now ask for the write lock when they begin, which is where waiting is allowed. A +transaction that is going to write says so, and queues instead of failing. + +The reproduction is the part worth keeping. This fault had been recorded as never once reproduced +locally; it now reproduces on demand in a tenth of a second, by driving two connections through both +sequences and asserting the difference, including that the old one fails in under a second despite a +five-second timeout. An intermittent fault that merely stops appearing is a fault you got lucky with. + +Three candidate fixes had been recorded when the fault was first diagnosed, and all three were ways +of making two connections contend less often rather than changing what happens when they do. The +diagnosis had been right and the proposed fixes did not follow from it. They are not taken, and the +risk register says why. + +The fault is not declared closed. Its lift condition is ten consecutive green runs, which this can +begin earning and cannot assert on the day it lands. + ### `slice/110` — Executable skills in an in-process sandbox Skills that can execute need a real programming surface. Trinity now has one that costs no trust: a `run_lua` tool and skill-owned scripts run Lua inside this process, with no operating system diff --git a/config/config.exs b/config/config.exs index f35b53e..7e20d42 100644 --- a/config/config.exs +++ b/config/config.exs @@ -44,6 +44,22 @@ config :trinity, other -> raise "TRINITY_DB must be sqlite or postgres, got #{inspect(other)}" end) +# Slice 005, closing R26, and it applies to every environment rather than only the suite because the +# hazard is SQLite's, not the test harness's. +# +# A DEFERRED transaction takes no lock at BEGIN and starts as a reader. At its first write it tries +# to upgrade, and if another connection has written since, SQLite returns SQLITE_BUSY **without +# invoking the busy handler**, because blocking at that point risks deadlock. No `busy_timeout` +# reaches that path, which is why raising it from 5 s to 30 s never closed R26. IMMEDIATE takes the +# write lock at BEGIN, where the handler is allowed to wait. +# +# Guarded on the adapter because `:default_transaction_mode` is an `ecto_sqlite3` option and the +# Postgres build has neither the option nor the hazard. +if System.get_env("TRINITY_DB", "sqlite") == "sqlite" do + config :trinity, Trinity.Repo, default_transaction_mode: :immediate + config :trinity, Trinity.Repo.Receipts, default_transaction_mode: :immediate +end + # Slice 013 (owner decision, 2026-09-20): the packaged Linux binary runs on Burrito's musl ERTS, # in which neither precompiled mdex_native artifact loads (both need glibc's libgcc_s), so the # linux package builds that NIF from source for the musl target with Zig as the linker diff --git a/config/test.exs b/config/test.exs index bd05d9f..8c03d21 100644 --- a/config/test.exs +++ b/config/test.exs @@ -180,14 +180,23 @@ else pool_size: 2, queue_target: 5_000, queue_interval: 30_000, - busy_timeout: 30_000 + busy_timeout: 30_000, + # Slice 005, closing R26. A DEFERRED transaction takes no lock at BEGIN and starts as a reader; + # at its first write it tries to upgrade, and if another connection has written since, SQLite + # returns SQLITE_BUSY **without invoking the busy handler**, because blocking there risks + # deadlock. `busy_timeout` above cannot reach that path, which is why raising it from 5 s to + # 30 s changed nothing. IMMEDIATE takes the write lock at BEGIN, where the handler is allowed to + # wait. `test/trinity/repo/sqlite_transaction_mode_test.exs` drives both sequences and asserts + # the difference rather than describing it. + default_transaction_mode: :immediate config :trinity, Trinity.Repo.Receipts, database: Path.expand("../trinity_test_receipts.db", __DIR__), pool: Ecto.Adapters.SQL.Sandbox, queue_target: 5_000, queue_interval: 30_000, - busy_timeout: 30_000 + busy_timeout: 30_000, + default_transaction_mode: :immediate end # We don't run a server during test. If one is required, diff --git a/coverage.tsv b/coverage.tsv index c228fc7..1ab1520 100644 --- a/coverage.tsv +++ b/coverage.tsv @@ -33,3 +33,4 @@ slice_id percent sha date 004 80.31 91de943 2026-09-24 014 80.31 1a5d480 2026-09-24 110 80.31 90c3d0a 2026-09-24 +005 80.31 9e9259a 2026-09-24 diff --git a/docs/05-data-model.md b/docs/05-data-model.md index 7fc3790..51676f5 100644 --- a/docs/05-data-model.md +++ b/docs/05-data-model.md @@ -302,3 +302,27 @@ run is idempotent. Oban holds the job; this holds the outcome. 4. Skill DB index == filesystem after reindex (Slice 040). 5. No tool executes without an `approvals` or `tool_permissions` decision recorded (Slice 021). 6. A receipt chain has no gap and no fork per `chain_scope`; every `prev_hash` resolves (Slice 024). + +## Transactions begin IMMEDIATE on SQLite (Slice 005) + +Both SQLite repos are configured `default_transaction_mode: :immediate`, and the reason is a defect +that took two days and five pull requests to close. + +A **DEFERRED** transaction, which is SQLite's default and was Ecto's, takes no lock at `BEGIN` and +starts as a reader. At its first write it tries to upgrade to a write lock, and if another connection +has written in the meantime SQLite returns `SQLITE_BUSY` **immediately, without invoking the busy +handler**, because blocking at that point risks deadlock. `busy_timeout` cannot reach that path. This +project raised it from the shipped 5 seconds to 30 and the failures continued, which is the +observation that should have pointed at the mechanism a day earlier than it did. + +**IMMEDIATE** asks for the write lock at `BEGIN`, which is where the busy handler is allowed to wait. +A transaction that is going to write says so up front and queues instead of failing. + +`test/trinity/repo/sqlite_transaction_mode_test.exs` drives two connections through both sequences +against their own database file and asserts the difference: under `DEFERRED` the upgrade is refused +in under a second despite a five-second `busy_timeout`, and under `IMMEDIATE` the same sequence waits +and succeeds. R26 had been "not once reproduced locally across repeated runs" for two days; it +reproduces there in a tenth of a second. + +The Postgres build has neither the option nor the hazard, and the configuration is guarded on the +adapter so the setting cannot leak into it. diff --git a/docs/06-risk-register.md b/docs/06-risk-register.md index f930d10..6694982 100644 --- a/docs/06-risk-register.md +++ b/docs/06-risk-register.md @@ -30,5 +30,6 @@ | R25 | `glib` 0.18.5 carries GHSA-wrw7-89jp-8q8g (medium, unsoundness in `Iterator` and `DoubleEndedIterator` impls); first patched in 0.20.0 | Low | Med | The advisory is open against `src-tauri/Cargo.lock`; measured 2026-09-23 | It is transitive through the GTK 0.18 stack (`gtk` 0.18.2, `webkit2gtk` 2.0.2) that Tauri 2.11.5 requires on Linux, so it is fixed by a Tauri release built on gtk-rs 0.20 and not by a direct bump. **Scope:** the desktop shell only. The `headless` release is `steps: [:assemble]` with no Burrito and no `src-tauri`, so a server deployment does not ship this dependency. Owner: the maintainer. Lift condition: a Tauri release whose Linux stack resolves `glib` >= 0.20, adopted by the desktop shell work | 100 | | R26 | An intermittent `Exqlite.Error: Database busy` fails the test suite on loaded CI runners, in a different test each time, always on a write to the main repository | Med | Low (test-only; no production path) | Failed the gate on pull requests 67, 70 and again on the commit that attempted to fix it; the same commit passed on its other run, so it is seed- and load-dependent. Not once reproduced locally across repeated runs | Ruled out: `busy_timeout`, raised from the shipped 5 s to 30 s in the suite, did not stop it. SQLite returns BUSY immediately, without the busy handler, when a read transaction upgrades to a write while another connection holds the write lock; no timeout affects that path. The suite runs two connections (one for the sandbox owner, one for Oban's boot check) and deliberately queues fifty concurrent writers at slice 070 AC7, which is the load that provokes it. Candidate fixes, not yet taken: drain the stress test's sessions before the suite continues; give that test its own tag and CI step; or remove the second connection's need. Owner: the maintainer. Lift condition: ten consecutive green CI runs of the full suite with the stress test in the default run | 070 | | R26 | Occurrence recorded 2026-09-23: the same class of failure appeared on the **FIPS leg** rather than the ordinary gate, which the row above does not cover. `Trinity.Gateways.ApprovalsTest` AC4 failed in its setup, with the crash in `Trinity.Receipts.ChainWriter.terminate/2` calling `insert_checkpoint/2` after the sandbox owner had gone: an ownership error at termination rather than a `Database busy` on a write. **Re-running the identical commit passed all four checks**, which is the evidence that matters: the code did not change between the red run and the green one, so the failure is in the environment or the ordering and not in the change under test. What this adds to the row above: the mechanism is not only write contention, it also reaches process termination racing sandbox teardown, and it is not confined to the ordinary gate's runners. A candidate fix specific to this shape: `ChainWriter.terminate/2` writes a checkpoint on the way out, and a terminate callback that touches the database after the test that owns the connection has finished is a race by construction; it should skip the write when the repo is in sandbox mode and has no owner, rather than attempting it and crashing. **Second occurrence the same day, and it changes the severity.** The very next pull request, which changed *only this file*, failed the FIPS leg again: `Trinity.Gateways.RouterTest` AC6, `Exqlite.Error: Database busy` on an `INSERT INTO gateway_identities` - the row's original signature, on the leg the row did not cover. A change that cannot affect behaviour failing a required check twice in a row means this is no longer an intermittent annoyance: **it blocks work**, and the honest reading is that the FIPS leg provokes it more reliably than the ordinary gate does, most likely because that leg is slower (163 s against about 110 s locally) and every contention window is correspondingly wider. The row above stands as written | **High** (was Med: it now blocks merges) | Low (test-only; no production path) | The lift condition in the row above, still unmet; two failures on the FIPS leg on 2026-09-23, one of them on a documentation-only change | docs/06-risk-register.md R26 | 070 | +| R26 | **Cause removed 2026-09-24, slice 005; the row stays open until its lift condition is met.** The mechanism this row diagnosed on 2026-09-23 is the documented behaviour of a **DEFERRED** transaction: no lock at `BEGIN`, a reader until its first write, and at that upgrade SQLite returns `SQLITE_BUSY` without invoking the busy handler because blocking there risks deadlock. The documented fix is `BEGIN IMMEDIATE`, which takes the write lock at `BEGIN` where the handler is allowed to wait, and `ecto_sqlite3` 0.24.1 exposes it as `:default_transaction_mode`. Both SQLite repos are now configured `:immediate`, guarded on the adapter so it cannot reach the Postgres build. **The three candidate fixes this row recorded were all workarounds**, and saying so is the useful part: draining the stress test's sessions, giving it its own CI step and removing the second connection's need each reduce how often two connections contend and leave the upgrade path exactly where it is. The row had the mechanism right and then proposed three ways around it. **Reproduced deterministically for the first time**, against this row's own words that it was "not once reproduced locally": `test/trinity/repo/sqlite_transaction_mode_test.exs` drives two connections through both sequences and asserts that under DEFERRED the upgrade is refused in under a second despite a five-second `busy_timeout`, and that under IMMEDIATE the same sequence waits and succeeds, in a tenth of a second. **Not closed**: the lift condition is ten consecutive green runs of the full suite with the stress test in the default run, which this can begin earning and cannot assert on the day it lands. A fix for an intermittent fault that declares victory on one green suite is how the fault comes back. The rows above stand as written | **Low** (was High: the upgrade path is gone, pending the ten runs) | Low (test-only; no production path) | Ten consecutive green runs from 2026-09-24 | docs/05-data-model.md, "Transactions begin IMMEDIATE on SQLite" | 005, 070 | | R26 | Occurrence recorded 2026-09-24, and this one **is** R26 rather than something wearing its signature. `Trinity.Telemetry.CostsTest`, "an unconfigured budget is not a budget of zero", failed with `** (Exqlite.Error) Database busy` on the ordinary `gate` leg of pull request 96, while the sibling run of the identical commit passed. The test is untouched by that change, the error is the row's original wording, and the failure is on a write: three of the three things the row names. Recorded separately from the counter-example above so that the register shows both kinds, because the counter-example's whole point is that one cannot be assumed from the signature and this one was checked before being filed. **What it adds:** the row above says it blocks work, and it blocked a merge again here, costing a full CI cycle on a branch whose own tests were green. The three candidate fixes in the original row remain untaken, which is now a decision rather than an oversight: it has cost four cycles across 2026-09-23 and 2026-09-24. Recommend taking it as a slice of its own rather than continuing to re-run. The rows above stand as written | **High**, unchanged | Low (test-only; no production path) | The lift condition in the original row, still unmet; a fourth blocking occurrence | docs/06-risk-register.md R26 | 070 | | R26 | Counter-example recorded 2026-09-24, in slice 090, and it corrects a heuristic the rows above state. At commit `b1bca1f` the `pull_request` run passed all four checks and the `push` run of the **same commit** failed `postgres` (runs 36001064067 and 36001057879). By the reading the 2026-09-23 entry offers - the code did not change between the green run and the red one, so the fault is the environment - this was R26 again. **It was not.** It was a real defect in slice 080's code, on a genuinely racy path: every call into a child session is a `gen_statem.call`, and a call into a process that dies exits the caller, so killing a child killed whoever called `delegate/3`. Whether the kill landed before or after the call returned decided the outcome, which is why the same commit could go either way. Fixed at `1f33f12`, after which both runs of the same commit passed. **What this changes:** "the same commit passed on its other run" is evidence that the failure is *timing-dependent*, which is not the same as evidence that it is environmental. A real race in library code produces exactly the signature R26 is recognised by, so the signature alone cannot be the diagnosis - the stack trace has to be read before a failure is filed here. This slice nearly filed one. The rows above stand as written | none (not an occurrence) | none | none | none | 080, 090 | diff --git a/test/trinity/repo/sqlite_transaction_mode_test.exs b/test/trinity/repo/sqlite_transaction_mode_test.exs new file mode 100644 index 0000000..4c9c1b7 --- /dev/null +++ b/test/trinity/repo/sqlite_transaction_mode_test.exs @@ -0,0 +1,89 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Repo.SqliteTransactionModeTest do + @moduledoc """ + Slice 005 AC1: R26's mechanism, reproduced deterministically, and the fix demonstrated against it. + + R26 has been an intermittent failure for two days and five pull requests. An intermittent fault + that stops appearing is a fault you got lucky with, so this does not run fifty writers and hope: + it drives two SQLite connections through the exact sequence the risk register describes and + asserts the error by name. + + **The mechanism.** A `DEFERRED` transaction takes no lock at `BEGIN` and starts as a reader. At its + first write it tries to upgrade, and if another connection has written since, SQLite returns + `SQLITE_BUSY` **without invoking the busy handler**, because blocking at that point risks deadlock. + No `busy_timeout` affects it, which is why raising it from 5 s to 30 s changed nothing. + + **The fix.** `BEGIN IMMEDIATE` takes the write lock at `BEGIN`, where the busy handler is allowed + to wait. + + These run against their own database file rather than the sandboxed repo, because the sandbox + wraps each test in one connection's transaction and cannot express two contending writers. What is + under test is SQLite's locking, not Ecto's. + """ + use ExUnit.Case, async: false + + alias Exqlite.Sqlite3 + + setup do + path = Path.join(System.tmp_dir!(), "r26-#{System.unique_integer([:positive])}.db") + on_exit(fn -> Enum.each([path, path <> "-wal", path <> "-shm"], &File.rm/1) end) + + {:ok, setup_conn} = Sqlite3.open(path) + :ok = Sqlite3.execute(setup_conn, "PRAGMA journal_mode=WAL") + :ok = Sqlite3.execute(setup_conn, "CREATE TABLE t (id INTEGER PRIMARY KEY, v TEXT)") + :ok = Sqlite3.close(setup_conn) + + {:ok, a} = Sqlite3.open(path) + {:ok, b} = Sqlite3.open(path) + # Generous, and deliberately so: the point is that it does not help on the upgrade path. + :ok = Sqlite3.execute(a, "PRAGMA busy_timeout=5000") + :ok = Sqlite3.execute(b, "PRAGMA busy_timeout=5000") + on_exit(fn -> Enum.each([a, b], &Sqlite3.close/1) end) + + {:ok, a: a, b: b} + end + + test "DEFERRED: an upgrade under contention is refused at once, whatever busy_timeout says", + %{a: a, b: b} do + :ok = Sqlite3.execute(a, "BEGIN DEFERRED") + :ok = Sqlite3.execute(a, "SELECT count(*) FROM t") + + :ok = Sqlite3.execute(b, "BEGIN IMMEDIATE") + :ok = Sqlite3.execute(b, "INSERT INTO t (v) VALUES ('from b')") + + started = System.monotonic_time(:millisecond) + result = Sqlite3.execute(a, "INSERT INTO t (v) VALUES ('from a')") + elapsed = System.monotonic_time(:millisecond) - started + + assert {:error, reason} = result + message = to_string(inspect(reason)) + + assert message =~ "busy" or message =~ "locked", + "expected a busy error on the upgrade, got #{message}" + + assert elapsed < 1_000, + "the upgrade waited #{elapsed} ms before failing. It should fail immediately: SQLite " <> + "does not invoke the busy handler here, which is the whole reason busy_timeout never " <> + "fixed R26" + + Sqlite3.execute(a, "ROLLBACK") + Sqlite3.execute(b, "COMMIT") + end + + test "IMMEDIATE: the same sequence waits on the busy handler instead of failing", %{a: a, b: b} do + :ok = Sqlite3.execute(b, "BEGIN IMMEDIATE") + :ok = Sqlite3.execute(b, "INSERT INTO t (v) VALUES ('from b')") + + task = Task.async(fn -> Sqlite3.execute(a, "BEGIN IMMEDIATE") end) + Process.sleep(100) + :ok = Sqlite3.execute(b, "COMMIT") + + assert :ok = Task.await(task, 5_000), + "BEGIN IMMEDIATE was refused rather than waiting, so the busy handler is not being " <> + "consulted even on the path where it should be" + + assert :ok = Sqlite3.execute(a, "INSERT INTO t (v) VALUES ('from a')") + :ok = Sqlite3.execute(a, "COMMIT") + end +end diff --git a/test/trinity/repo/transaction_mode_configured_test.exs b/test/trinity/repo/transaction_mode_configured_test.exs new file mode 100644 index 0000000..bf3025c --- /dev/null +++ b/test/trinity/repo/transaction_mode_configured_test.exs @@ -0,0 +1,34 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Repo.TransactionModeConfiguredTest do + @moduledoc """ + Slice 005 AC2: the mode is what the **running repo** reports, not what a config file says. + + A test that read `config/config.exs` would assert that a line exists. This asks the started repo + for its own configuration, so it fails if an environment override, a later `config/*.exs`, or a + runtime block puts it back to `:deferred` without anyone noticing. + """ + use ExUnit.Case, async: true + + @sqlite Ecto.Adapters.SQLite3 + + defp adapter, do: Application.get_env(:trinity, :db_adapter) + + for repo <- [Trinity.Repo, Trinity.Repo.Receipts] do + test "#{inspect(repo)} begins its transactions IMMEDIATE on SQLite" do + repo = unquote(repo) + + if adapter() == @sqlite do + assert repo.config()[:default_transaction_mode] == :immediate, + "#{inspect(repo)} is on #{inspect(repo.config()[:default_transaction_mode] || :deferred)}. " <> + "A deferred transaction upgrading to a write under contention is refused without " <> + "the busy handler ever being consulted, which is R26" + else + # Postgres has neither the option nor the hazard, and asserting its absence is the honest + # thing to state rather than skipping silently. + refute repo.config()[:default_transaction_mode], + "the SQLite transaction mode leaked into the Postgres build" + end + end + end +end