fix(sessions): eager state.db schema migration at backend startup; stop swallowing locked ALTERs - #86671
Conversation
…up and stop swallowing locked ALTERs After `hermes update`, an existing state.db on an old schema made every GET /api/sessions poll fail with sqlite3.OperationalError "no such column: s.last_read_at" (or s.last_activity_at) until something unrelated forced a writable open — the desktop sidebar showed "No sessions yet" while every row sat intact on disk (#79531, #80037). Two remaining root causes (the stale hand-written read probe was already replaced by the SCHEMA_SQL-derived probe on main, prototyped in draft PR #80030 by @Tilly-YL): 1. Migrations ran lazily: _init_schema/_reconcile_columns only ran on a writable open, typically the user's first NEW session. The dashboard backend now schedules one writable open of its own state.db from the lifespan (daemon thread, never blocks the ready-probe socket, never raises), so the store is brought current before the first session- list poll on every `hermes serve` / `hermes dashboard` / Desktop headless entrypoint. 2. _reconcile_columns caught sqlite3.OperationalError around every ALTER TABLE ADD COLUMN and logged at DEBUG. Lock contention from orphaned sibling backends made the ALTER fail silently — startup "succeeded" with a half-reconciled schema, and the open-time lock patience (#74478) never saw the error because it was swallowed inside first. Now: "duplicate column" races stay at DEBUG, locked/busy re-raises so _connect_and_init_with_lock_patience retries the whole idempotent init with jittered backoff, and any other failure (e.g. un-ADDable NOT NULL) logs at WARNING. Regression tests: a store missing sessions.last_read_at is healed by the eager startup reconcile and serves list_sessions_rich; a locked ALTER propagates and is retried to success by the open lock patience; duplicate-column races stay quiet; other ALTER failures warn. Fixes #79531 Fixes #80037 Reported-by: @yenhunghuang (#79531) and @FLOW3R0111 (#80037) Root-cause analysis: @wangyi0177-eng (stale read probe) and @www654cc-pixel (_reconcile_columns DEBUG-swallow under lock contention); draft PR #80030 by @Tilly-YL prototyped the probe fix.
૮ >ﻌ< ა ci reviewrunning on db5e442 — fix(sessions): run state.db schema migration eagerly at back waiting for more jobs to start…
|
trevorgordon981
left a comment
There was a problem hiding this comment.
Direction is sound — making migration eager and lock errors loud is the right fix for #79531/#80037, and the tests are the strongest part of the PR. One blocking question before merge.
1. The read-probe heal path is not updated for the new re-raise (blocking)
This PR changes _reconcile_columns to re-raise database is locked out the shared helper. The PR text says the per-poll read-probe heal in _open_session_db_at_path "retries on every poll," but the diff doesn't modify that caller to catch the newly re-raised OperationalError("database is locked"). If that heal wraps _reconcile_columns in a try/except that swallows only certain errors (or doesn't catch at all), a locked DB at startup escalates from a quiet DEBUG to an unhandled error / 500 on every session-list poll.
The diff's only guarantee is on the eager thread itself (its own except Exception). The per-poll heal's tolerance of the re-raise is unverified and untested. Confirm the coupling, ideally with a regression test that the poll-time heal doesn't 500 when the store is locked.
2. Message-substring matching is brittle
"locked" in str(exc).lower() or "busy" in message re-classifies any future rewording as a schema error instead of triggering the retry. SQLite's OperationalError carries sqlite_errorcode/sqlite_errorname — a structured check (exc.sqlite_errorcode in (SQLITE_BUSY, SQLITE_LOCKED)) is more robust than substring matching on the message.
3. Persistent orphaned-writer case isn't solved, only surfaced louder
On a lock that persists through all 15 retries (orphaned sibling backend), _eager_reconcile_own_session_db logs WARNING and gives up, leaving the store behind SCHEMA_SQL. The PR acknowledges the per-poll heal can lose repeatedly to the orphan. That's acceptable scope, but it should be stated as "surfaced more loudly," not implied fixed.
4. Test-constant naming mismatch risk
test_locked_alter_is_retried_by_open_lock_patience monkeypatches _WRITE_RETRY_SLOW_MIN_S / _WRITE_RETRY_SLOW_MAX_S. The surrounding retry wrapper uses _WRITE_RETRY_MIN_S/_WRITE_RETRY_MAX_S (no SLOW variants) plus _WRITE_MAX_RETRIES. If the target main doesn't define the SLOW constants, monkeypatch.setattr raises AttributeError and the test errors rather than passes. The author says it passes locally, so they presumably exist on the base — but it's an undocumented coupling to possibly-renamed constants worth double-checking (and ideally deriving from the real ones).
Tests
Five new tests across two files, covering the exact regression modes including an end-to-end retry-heal and a never-raises guard. Main gap: no test that the per-poll read-probe heal tolerates the newly re-raised database is locked (finding #1), and the retry-test constant coupling (finding #4).
Summary
After
hermes update, an existingstate.dbon an old schema made everyGET /api/sessionspoll fail withsqlite3.OperationalError: no such column: s.last_read_at(ors.last_activity_at) until something unrelated forced a writable open. The desktop sidebar showed "No sessions yet" while every session row sat intact on disk.Fixes #79531
Fixes #80037
Root causes and fixes
The SCHEMA_SQL-derived read probe (root cause found by @wangyi0177-eng, prototyped in draft PR #80030 by @Tilly-YL) is already on main — any missing declared column now trips the read-only self-heal. This PR lands the two remaining pieces:
1. Migrations ran lazily, not at startup.
_init_schema→_reconcile_columnsonly ran on a writable open — typically the user's first NEW session. The backend lifespan now schedules one writable open of its ownstate.dbat startup (_eager_reconcile_own_session_db), so the store is brought current before the first session-list poll on every dashboard/hermes serve/Desktop-headless entrypoint. Runs in a daemon thread (never delays the ready-probe socket, GH-73083) and never raises — a store it can't fix still gets the per-poll read-probe heal.2.
_reconcile_columnsswallowed lock contention at DEBUG (root cause found by @www654cc-pixel). With orphanedhermes servebackends holding the DB, theALTER TABLE sessions ADD COLUMN last_read_athitdatabase is locked, was logged at DEBUG, and startup "succeeded" with a half-reconciled schema. The open-time lock patience (_connect_and_init_with_lock_patience, #74478) never saw the error because it was caught inside first. Now:duplicate column name(harmless race) → stays DEBUGdatabase is locked/busy→ re-raises, so the open-time lock patience retries the whole idempotent init with jittered backoffTests
TestReconcileColumnsErrorHandling(tests/test_hermes_state.py): locked ALTER propagates; end-to-end — a transiently locked ALTER is retried by the open lock patience and the store heals (last_read_atadded); duplicate-column races stay quiet; other ALTER failures warn.test_startup_eager_reconcile_heals_stale_store(tests/hermes_cli/test_web_server.py): a store missingsessions.last_read_atis healed by the startup reconcile and serveslist_sessions_rich.test_startup_eager_reconcile_never_raises: a locked store cannot break startup.All targeted suites pass locally (
tests/test_hermes_state.py,tests/hermes_cli/test_web_server.pyheal/stale/eager selection,tests/test_hermes_state_compression_busy_retry.py,tests/test_hermes_state_readonly_preflight.py,tests/test_web_server_sessiondb_eventloop.py). The one pre-existing failure on main (test_search_projection_skips_context_enrichment_queries) is unrelated and fails identically without this diff.Credit
_reconcile_columnsDEBUG-swallow failure mode under lock contentionInfographic omitted: FAL image hosting unavailable (account balance exhausted); generation itself succeeded but no fal.media URL could be produced.