From e3ae535e88538ae30f4cc53b77d07ee05ac99b73 Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 20 Aug 2026 18:40:57 -0400 Subject: [PATCH] fix(db): WAL, because watching a fetch was killing it Found by running the thing rather than testing it. A first market-data fetch, started from the browser and watched on the page that says it will show the progress, DIED at 45 seconds with `OperationalError: disk I/O error` after writing 31,709 candles. Not disk space (362 GiB free) and not corruption (`PRAGMA integrity_check` -> ok). The setup page auto-refreshes every 5 seconds and opens the database to render the checklist; the background job was writing to it. In SQLite's default rollback journal a writer takes an EXCLUSIVE lock and readers take SHARED ones, so the two cannot coexist. Measured, same fetch, same machine, against the real venue: page polling every 5s, rollback -> FAILED at 45s, 31,709 candles nobody polling, rollback -> ran 150s, 108,202 candles polling every 0.2s, WAL -> ran 150s, 108,501 candles, 694 clean reads The middle row is what makes this worth taking seriously: the fetch was fine, and OBSERVING it was the bug. Worse, observing it is the encouraged behaviour -- the action's own message says "this page will show its progress". In WAL, readers never block the writer and the writer never blocks readers. The hazard was never specific to the job runner either: an agent writing a cycle while a dashboard refreshes is the same shape, and the web UI is what made it reachable. A busy timeout comes with it. SQLite's default is ZERO -- it raises immediately -- which is the wrong default for a process that now reads and writes one file at the same time. Journal mode is a property of the FILE, not the connection, so an existing deployment converts on its next connection and needs nothing from an operator. `:memory:` is excluded: there is no file to journal, SQLite refuses WAL there, and a shared in-memory database is single-connection anyway. TWO THINGS CHECKED RATHER THAN ASSUMED. `keel update`'s backups are unaffected -- it uses SQLite's own online-backup API, precisely because "a plain file copy of a database with a live rollback journal is not a snapshot", and that API reads committed WAL content too. And the `-wal`/`-shm` sidecars must not be mistaken for databases: both the backup set and `is_deployment_root` glob `keel*.db`, which does not match them, and that is now pinned. Also checked: a read-only URI open (`file:...?mode=ro`, how `keel setup` inspects a deployment) still works against a WAL database with no writer present. Verified end to end after the fix: the identical scenario, polled once per SECOND -- five times harder than the page does -- ran past 102 seconds and 74,714 candles without an error. 4092 passed, 3 skipped (5 new). ruff clean repo-wide; mypy clean over keel + packages. Refs #437, #435, #18. Co-Authored-By: Claude Opus 5 (1M context) --- docs/operator-runbook.md | 11 +++ keel/data/db.py | 43 ++++++++-- tests/data/test_db_concurrency.py | 130 ++++++++++++++++++++++++++++++ 3 files changed, 179 insertions(+), 5 deletions(-) create mode 100644 tests/data/test_db_concurrency.py diff --git a/docs/operator-runbook.md b/docs/operator-runbook.md index 6f1ac0a1..0bc1413d 100644 --- a/docs/operator-runbook.md +++ b/docs/operator-runbook.md @@ -282,6 +282,17 @@ and has already produced one. Establish which account a number came from before | cadence | daily (day-stamp) | daily, UTC (UTC day-stamp) | **hourly**, UTC (UTC hour-stamp) | daily, in the US session (UTC day-stamp) | | rules traded | daily turtle, `paper` | daily turtle + DCA, `live` | **hourly** turtle, `paper` | daily turtle on equities, `paper` | +**Why there are three files per database.** Since keel serves a web UI, one process reads the +database while another writes it — a page refreshing while a fetch or an agent cycle runs. SQLite's +default journal cannot do that (a writer takes an exclusive lock), and it did not: a first fetch +watched from the setup page died at 45 seconds with `disk I/O error`. The databases are now in +**WAL** mode, so readers never block the writer and the writer never blocks readers. + +That means `keel.db-wal` and `keel.db-shm` sit beside each `keel*.db`. They are part of the +database — do not delete them while keel is running, and prefer `keel update`'s backups (which use +SQLite's own online-backup API) over copying the `.db` file by hand. Conversion happens on the +next connection and needs nothing from you. + **Which one am I looking at.** On any dashboard (`keel status`, `keel insights`, `keel tui`, `keel serve`) the `equity_state_mode` line names the account the equity, high-water mark and drawdown figures diff --git a/keel/data/db.py b/keel/data/db.py index a27be44b..59521005 100644 --- a/keel/data/db.py +++ b/keel/data/db.py @@ -310,9 +310,7 @@ def _migrate_v2_broker_subscriptions(conn: sqlite3.Connection) -> None: if already_migrated is not None: return - row = conn.execute( - "SELECT value FROM agent_state WHERE key = 'subscription'" - ).fetchone() + row = conn.execute("SELECT value FROM agent_state WHERE key = 'subscription'").fetchone() if row is None: return @@ -464,15 +462,50 @@ def _migrate_v10_instrument_attestations(conn: sqlite3.Connection) -> None: } +#: How long a connection waits for a lock before giving up. SQLite's default is ZERO -- it raises +#: immediately -- which is the wrong default for a process that now reads and writes this file at +#: the same time. Five seconds is far longer than any contention here lasts and far shorter than +#: a person's patience. +BUSY_TIMEOUT_MS = 5_000 + + def connect(path: str | Path = "keel.db") -> sqlite3.Connection: """Open a `sqlite3.Connection` to `path` (or an in-memory DB for `":memory:"`). - Configures dict-like `Row` access and turns on foreign-key enforcement, which SQLite - otherwise leaves off per-connection by default. + Configures dict-like `Row` access, foreign-key enforcement (which SQLite otherwise leaves off + per-connection), a busy timeout, and WAL. + + **WAL, and why it is not a tuning preference.** In the default rollback journal a writer takes + an EXCLUSIVE lock and readers take SHARED ones, so a reader and a writer cannot coexist. That + was survivable while one process used this file at a time. It stopped being survivable when + `keel serve` began polling the database every few seconds to render a page while a background + fetch wrote to it (#437): the fetch DIED, and it died on the path most likely to be taken, + because the page invites the operator to watch it. Measured, on the same fetch: + + page polling every 5s, rollback -> FAILED at 45s, 31,709 candles ("disk I/O error") + nobody polling, rollback -> ran 150s, 108,202 candles + polling every 0.2s, WAL -> ran 150s, 108,501 candles, 694 clean reads + + In WAL, readers never block the writer and the writer never blocks readers. The agent writing + a cycle while a dashboard refreshes is the same shape and was the same hazard. + + Journal mode is a property OF THE FILE, not of the connection: the first connection converts + it and every later one inherits it, so this is a no-op on an already-converted database. + + Two consequences worth knowing. WAL adds `-wal` and `-shm` sidecar files beside the database + -- a deployment folder now has three files where it had one. And `keel update`'s backups are + unaffected: it uses SQLite's own online-backup API, precisely because "a plain file copy of a + database with a live rollback journal is not a snapshot", and that API reads committed WAL + content too. """ conn = sqlite3.connect(str(path)) conn.row_factory = sqlite3.Row conn.execute("PRAGMA foreign_keys = ON") + conn.execute(f"PRAGMA busy_timeout = {BUSY_TIMEOUT_MS}") + # `:memory:` has no file to journal, and asking for WAL there is refused; a shared in-memory + # database is also single-connection by nature, so there is nothing to protect. + if str(path) != ":memory:": + conn.execute("PRAGMA journal_mode = WAL") return conn diff --git a/tests/data/test_db_concurrency.py b/tests/data/test_db_concurrency.py new file mode 100644 index 00000000..4179de93 --- /dev/null +++ b/tests/data/test_db_concurrency.py @@ -0,0 +1,130 @@ +"""Reading this database while something writes it must not break the write (#437). + +`keel serve` polls the database every few seconds to render a page, and a background fetch writes +to it for minutes. In SQLite's default rollback journal those two cannot coexist: a writer takes +an EXCLUSIVE lock, readers take SHARED ones. Measured against a real Coinbase fetch: + + page polling every 5s, rollback -> FAILED at 45s, 31,709 candles ("disk I/O error") + nobody polling, rollback -> ran 150s, 108,202 candles + polling every 0.2s, WAL -> ran 150s, 108,501 candles, 694 clean reads + +The failure took the path most likely to be taken: the page tells the operator it will show the +fetch's progress, so watching it is the encouraged behaviour, and watching it is what killed it. +""" + +from __future__ import annotations + +import sqlite3 +import threading +from pathlib import Path + +from keel.data.db import BUSY_TIMEOUT_MS, connect, migrate + + +def test_a_file_database_is_opened_in_wal(tmp_path: Path) -> None: + """Journal mode is a property of the FILE: the first connection converts it and every later + one inherits it, so this is what makes an existing deployment safe on next start.""" + db = tmp_path / "keel.db" + conn = connect(str(db)) + try: + assert conn.execute("PRAGMA journal_mode").fetchone()[0] == "wal" + finally: + conn.close() + + +def test_a_busy_timeout_is_set(tmp_path: Path) -> None: + """SQLite's default is ZERO -- it raises immediately -- which is the wrong default for a + process that now reads and writes this file at the same time.""" + conn = connect(str(tmp_path / "keel.db")) + try: + assert conn.execute("PRAGMA busy_timeout").fetchone()[0] == BUSY_TIMEOUT_MS + finally: + conn.close() + + +def test_an_in_memory_database_is_not_asked_for_wal() -> None: + """There is no file to journal, SQLite refuses WAL there, and a shared in-memory database is + single-connection by nature -- there is nothing to protect.""" + conn = connect(":memory:") + try: + assert conn.execute("PRAGMA journal_mode").fetchone()[0] == "memory" + finally: + conn.close() + + +def test_a_reader_polling_hard_does_not_break_a_writer(tmp_path: Path) -> None: + """The regression itself, in miniature: one connection writing in a loop while another opens, + reads and closes as fast as it can. Under a rollback journal this is the shape that produced + `disk I/O error` against the real venue.""" + db = tmp_path / "keel.db" + setup = connect(str(db)) + migrate(setup) + setup.close() + + errors: list[str] = [] + stop = threading.Event() + reads = {"n": 0} + + def _read() -> None: + while not stop.is_set(): + try: + # Read-only, exactly as `keel.commands.setup.inspect` opens it. + ro = sqlite3.connect(f"file:{db}?mode=ro", uri=True) + try: + ro.execute("SELECT COUNT(*) FROM rules").fetchone() + reads["n"] += 1 + finally: + ro.close() + except Exception as exc: # noqa: BLE001 - the failure being tested is any of them + errors.append(f"reader: {type(exc).__name__}: {exc}") + return + + reader = threading.Thread(target=_read, daemon=True) + reader.start() + try: + writer = connect(str(db)) + try: + for index in range(400): + writer.execute( + "INSERT INTO rules (kind, params, status, created_at) VALUES (?,?,?,?)", + ("turtle_breakout", "{}", "candidate", index), + ) + writer.commit() + except Exception as exc: # noqa: BLE001 + errors.append(f"writer: {type(exc).__name__}: {exc}") + finally: + writer.close() + finally: + stop.set() + reader.join(5) + + assert not errors, errors + assert reads["n"] > 0, "the reader never ran, so this proves nothing" + + check = connect(str(db)) + try: + assert check.execute("SELECT COUNT(*) FROM rules").fetchone()[0] == 400 + finally: + check.close() + + +def test_the_sidecar_files_are_not_mistaken_for_databases(tmp_path: Path) -> None: + """WAL adds `keel.db-wal` and `keel.db-shm`. Both the updater's backup set and the + deployment-root detector glob `keel*.db`, which must not match them -- a `-wal` treated as a + database would be backed up as one and, worse, counted as one.""" + from keel_core import paths + + db = tmp_path / "keel.db" + conn = connect(str(db)) + migrate(conn) + conn.execute( + "INSERT INTO rules (kind, params, status, created_at) VALUES ('k','{}','candidate',1)" + ) + conn.commit() + conn.close() + + names = {path.name for path in tmp_path.iterdir()} + assert "keel.db" in names + matched = {path.name for path in tmp_path.glob("keel*.db")} + assert matched == {"keel.db"}, matched + assert paths.is_deployment_root(tmp_path)