diff --git a/docs/operator-runbook.md b/docs/operator-runbook.md index 6f1ac0a..0bc1413 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 a27be44..5952100 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 0000000..4179de9 --- /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)