From 2182f51d7ce7073b61a91ffc110e1ccb68a877cc Mon Sep 17 00:00:00 2001 From: teknium1 <127238744+teknium1@users.noreply.github.com> Date: Sat, 19 Sep 2026 23:36:26 -0700 Subject: [PATCH] fix: name the process holding the state.db write lock when a writer times out "database is locked (another Hermes process held the state.db write lock for over 60s)" identified the victim only. The open-descriptor scan cannot single out the writer because every Hermes process (gateway, CLI sessions, worktree agents, cron) has the DB open, so an operator hit repeatedly by session_persistence_failed:locked had nothing to act on. SQLite's unix VFS takes fcntl byte-range locks whose offset encodes the lock kind (state.db-shm byte 120 = WAL write, 121 = checkpoint; the pending-byte page on state.db = PENDING/RESERVED), and the kernel exports them with the owning pid in /proc/locks. hermes_state_lockowners reads that table at the moment the patience budget runs out and logs one WARNING per write-class holder with describe_holder_pid()'s argv summary, for both the transcript write path and open+init lock patience. The holder stays out of the exception text on purpose: classify_persistence_error() buckets by phrase and a holder argv such as a worktree named fix-corrupt-db would flip the bucket. Docs: the Write Contention section still described attempt-counted retries (_WRITE_MAX_RETRIES = 15); updated to the time budgets in force and the new log line. --- hermes_state.py | 7 +- hermes_state_lockowners.py | 119 ++++++++++++++++++ .../test_write_lock_owner_attribution.py | 69 ++++++++++ .../docs/developer-guide/session-storage.md | 21 +++- 4 files changed, 211 insertions(+), 5 deletions(-) create mode 100644 hermes_state_lockowners.py create mode 100644 tests/hermes_state/test_write_lock_owner_attribution.py diff --git a/hermes_state.py b/hermes_state.py index 71b91c19f7..4cecffde83 100644 --- a/hermes_state.py +++ b/hermes_state.py @@ -52,6 +52,7 @@ from hermes_state_profile_repair import SessionProfileRepairMixin from hermes_state_schema import SessionSchemaMixin import hermes_state_holders as _state_holders import hermes_state_lockguard as _lockguard +from hermes_state_lockowners import log_write_lock_holders from hermes_state_dbfile import ( _connect_tracked_db, _fd_is_truly_unlinked, _prepare_connection_retirement, _read_sqlite_application_id, _stat_sqlite_sidecar_identity, @@ -798,6 +799,7 @@ class SessionDB( self._close_connection_quietly(self._conn) now = time.monotonic() if now >= deadline: + log_write_lock_holders(self.db_path, self._WRITE_PATIENCE_S) raise jitter = random.uniform(self._WRITE_RETRY_SLOW_MIN_S, self._WRITE_RETRY_SLOW_MAX_S) time.sleep(min(jitter, max(deadline - now, 0.001))) @@ -1016,7 +1018,10 @@ class SessionDB( if "locked" in err_msg or "busy" in err_msg: if self._sleep_before_write_retry(deadline, patience_s): continue - # Say what actually happened, not disk/permission damage. + # Say what actually happened, not disk/permission damage. The holder goes to + # the log, not the message: classify_persistence_error() buckets by phrase and + # a holder's argv (a worktree named fix-corrupt-db) would flip the bucket. + log_write_lock_holders(self.db_path, patience_s) raise sqlite3.OperationalError( f"database is locked (another Hermes process held the " f"state.db write lock for over {patience_s:.0f}s — " diff --git a/hermes_state_lockowners.py b/hermes_state_lockowners.py new file mode 100644 index 0000000000..01594c669e --- /dev/null +++ b/hermes_state_lockowners.py @@ -0,0 +1,119 @@ +"""Who holds the SQLite write lock on state.db right now (Linux ``/proc/locks``). + +The "database is locked for over Ns" failure names the victim but not the holder, and the +open-descriptor scan (``hermes_state_holders``) cannot tell a reader from the one writer: every +Hermes process has the DB open. SQLite's unix VFS takes ``fcntl`` byte-range locks whose offsets +encode the lock kind, and the kernel exports them with the owning pid, so the holder can be named +at the moment the deadline passes. +""" + +from __future__ import annotations + +import logging +import os +import sys +from pathlib import Path +from typing import Dict, List, Tuple + +logger = logging.getLogger(__name__) + +# sqlite/src/os_unix.c: UNIX_SHM_BASE = (22 + SQLITE_SHM_NLOCK) * 4 = 120; WAL lock i sits at BASE + i. +_SHM_LOCK_NAMES = { + 120: "WAL write", + 121: "WAL checkpoint", + 122: "WAL recover", + 128: "shm dead-man switch", +} +# Rollback-journal / exclusive locks on the main file live in the pending-byte page (1 GiB). +_PENDING_BYTE = 0x40000000 +_MAIN_LOCK_NAMES = { + _PENDING_BYTE: "PENDING", + _PENDING_BYTE + 1: "RESERVED", +} + + +def _describe_range(sidecar: str, start: int, end: int) -> str: + if sidecar == "-shm": + if start in _SHM_LOCK_NAMES and end == start: + return _SHM_LOCK_NAMES[start] + if 123 <= start <= 127 and end == start: + return f"WAL read slot {start - 123}" + return f"shm bytes {start}-{end}" + if start == end and start in _MAIN_LOCK_NAMES: + return _MAIN_LOCK_NAMES[start] + if start == _PENDING_BYTE + 2: + return "SHARED range" + return f"db bytes {start}-{end}" + + +def parse_proc_locks(text: str, inodes: Dict[Tuple[int, int], str]) -> List[Tuple[int, str, str]]: + """``(pid, lock kind, sidecar)`` for every WRITE lock on one of ``inodes``. + + ``inodes`` maps ``(st_dev, st_ino)`` to ``""`` (main file), ``"-wal"`` or ``"-shm"``. Read locks + are dropped: they never block a writer in WAL mode. An OFD lock is reported with pid ``-1`` + (the kernel does not export its owner). + """ + found: List[Tuple[int, str, str]] = [] + for line in text.splitlines(): + fields = line.split() + # "N: POSIX ADVISORY WRITE MAJ:MIN:INO "; a blocked waiter is "N: -> POSIX ...". + if len(fields) < 8 or fields[1] == "->": + continue + _, _kind, _cls, access, pid_s, ident, start_s, end_s = fields[:8] + if access != "WRITE": + continue + try: + major_s, minor_s, ino_s = ident.split(":") + dev = os.makedev(int(major_s, 16), int(minor_s, 16)) + key = (dev, int(ino_s)) + pid = int(pid_s) + start = int(start_s) + end = start if end_s == "EOF" else int(end_s) + except ValueError: + continue + sidecar = inodes.get(key) + if sidecar is None: + continue + found.append((pid, _describe_range(sidecar, start, end), sidecar)) + return found + + +def state_db_write_lock_holders(db_path) -> List[str]: + """Operator-facing lines naming the processes that hold a write-class lock on ``db_path``. + + Empty when nothing is held or the platform has no ``/proc/locks``. + """ + if not sys.platform.startswith("linux"): + return [] + base = os.path.realpath(os.fspath(db_path)) + inodes: Dict[Tuple[int, int], str] = {} + for sidecar in ("", "-wal", "-shm"): + try: + st = os.stat(base + sidecar) + except OSError: + continue + inodes[(st.st_dev, st.st_ino)] = sidecar + try: + with open("/proc/locks", encoding="ascii", errors="replace") as handle: + text = handle.read() + except OSError: + return [] + from hermes_state_holders import describe_holder_pid + + lines = [] + for pid, kind, sidecar in parse_proc_locks(text, inodes): + who = describe_holder_pid(pid) if pid > 0 else "OFD lock, owner pid not exported by the kernel" + lines.append(f"{who} holds {kind} lock on {Path(base + sidecar).name}") + return lines + + +def log_write_lock_holders(db_path, patience_s: float) -> None: + """One WARNING naming the write-lock holders at the moment a writer gave up waiting.""" + holders = state_db_write_lock_holders(db_path) + if holders: + detail = " | ".join(holders) + else: + detail = "no write-class lock held at the deadline (the holder released just before it)" + logger.warning( + "state.db write lock unavailable for %.0fs (%s): %s", patience_s, Path(db_path).name, detail + ) diff --git a/tests/hermes_state/test_write_lock_owner_attribution.py b/tests/hermes_state/test_write_lock_owner_attribution.py new file mode 100644 index 0000000000..c652331e15 --- /dev/null +++ b/tests/hermes_state/test_write_lock_owner_attribution.py @@ -0,0 +1,69 @@ +"""Regression: a state.db write-lock timeout names the process holding the lock. + +Before, ``database is locked (another Hermes process held the state.db write lock for over 60s)`` +identified the victim only; every Hermes process has the DB open, so the descriptor scan could not +single out the writer. ``/proc/locks`` can. +""" + +import os +import sqlite3 +import subprocess +import sys +import textwrap +import time + +import pytest + +from hermes_state_lockowners import parse_proc_locks, state_db_write_lock_holders + + +def test_parse_proc_locks_keeps_only_write_locks_on_our_inodes_and_decodes_the_wal_write_byte(): + inodes = {(os.makedev(0x103, 0x02), 4194737): "-shm", (os.makedev(0x103, 0x02), 4228330): ""} + text = textwrap.dedent("""\ + 1: POSIX ADVISORY WRITE 594094 103:02:4194737 120 120 + 2: POSIX ADVISORY READ 594094 103:02:4194737 125 125 + 3: POSIX ADVISORY READ 99493 103:02:4194737 128 128 + 4: OFDLCK ADVISORY WRITE -1 103:02:4228330 1073741825 1073741825 + 5: POSIX ADVISORY WRITE 4242 103:02:99999 120 120 + 6: -> POSIX ADVISORY WRITE 777 103:02:4194737 120 120 + """) + assert parse_proc_locks(text, inodes) == [ + (594094, "WAL write", "-shm"), + (-1, "RESERVED", ""), + ] + + +@pytest.mark.linux_only +def test_live_writer_in_another_process_is_named_by_pid(tmp_path): + db = tmp_path / "state.db" + conn = sqlite3.connect(db) + conn.execute("PRAGMA journal_mode=wal") + conn.execute("CREATE TABLE t(x)") + conn.commit() + conn.close() + + holder = subprocess.Popen( + [sys.executable, "-c", textwrap.dedent(f""" + import sqlite3, sys, time + c = sqlite3.connect({str(db)!r}, isolation_level=None) + c.execute("BEGIN IMMEDIATE") + c.execute("INSERT INTO t VALUES (1)") + print("held", flush=True) + time.sleep(30) + """)], + stdout=subprocess.PIPE, text=True, + ) + try: + assert holder.stdout.readline().strip() == "held" + deadline = time.monotonic() + 5 + lines = [] + while time.monotonic() < deadline: + lines = state_db_write_lock_holders(db) + if lines: + break + time.sleep(0.05) + assert any(f"PID {holder.pid} " in line and "WAL write" in line for line in lines), lines + finally: + holder.kill() + holder.wait() + assert state_db_write_lock_holders(db) == [] diff --git a/website/docs/developer-guide/session-storage.md b/website/docs/developer-guide/session-storage.md index fdcb6187f8..e3c45ccd6d 100644 --- a/website/docs/developer-guide/session-storage.md +++ b/website/docs/developer-guide/session-storage.md @@ -300,7 +300,9 @@ Multiple hermes processes (gateway + CLI sessions + worktree agents) share one `state.db`. The `SessionDB` class handles write contention with: - **Short SQLite timeout** (1 second) instead of the default 30s -- **Application-level retry** with random jitter (20-150ms, up to 15 retries) +- **Time-budgeted application-level retry** with random jitter (20-150ms for the + first 2s, then 250ms-1s): 20s for routine writes, 60s for transcript writes + (their failure aborts the turn), 0.5s for observation-only activity writes - **BEGIN IMMEDIATE** transactions to surface lock contention at transaction start - **Periodic WAL checkpoints** every 50 successful writes (PASSIVE mode) @@ -308,12 +310,23 @@ This avoids the "convoy effect" where SQLite's deterministic internal backoff causes all competing writers to retry at the same intervals. ``` -_WRITE_MAX_RETRIES = 15 -_WRITE_RETRY_MIN_S = 0.020 # 20ms -_WRITE_RETRY_MAX_S = 0.150 # 150ms +_WRITE_PATIENCE_S, _TRANSCRIPT_WRITE_PATIENCE_S, _ACTIVITY_WRITE_PATIENCE_S = 20.0, 60.0, 0.5 +_WRITE_RETRY_MIN_S, _WRITE_RETRY_MAX_S = 0.020, 0.150 +_WRITE_RETRY_SLOW_MIN_S, _WRITE_RETRY_SLOW_MAX_S = 0.250, 1.000 _CHECKPOINT_EVERY_N_WRITES = 50 ``` +When a writer exhausts its budget the turn ends with +`session_persistence_failed:locked` and, on Linux, `hermes_state_lockowners` +logs a WARNING naming the process that held the lock at that moment +(`PID 594094 (hermes --worktree --yolo) holds WAL write lock on state.db-shm`), +read from `/proc/locks` — SQLite's byte-range `fcntl` locks encode the lock kind +in their offset (`state.db-shm` byte 120 = WAL write, 121 = checkpoint, +123-127 = read slots; the 1 GiB pending-byte page on `state.db` = rollback-journal +PENDING/RESERVED/SHARED). The open-descriptor scan cannot make this distinction +because every Hermes process has the DB open. Look for that line in +`~/.hermes/logs/errors.log` next to the `database is locked` failure. + ## Common Operations