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.
This commit is contained in:
@@ -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 — "
|
||||
|
||||
119
hermes_state_lockowners.py
Normal file
119
hermes_state_lockowners.py
Normal file
@@ -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 <pid> MAJ:MIN:INO <start> <end|EOF>"; 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
|
||||
)
|
||||
69
tests/hermes_state/test_write_lock_owner_attribution.py
Normal file
69
tests/hermes_state/test_write_lock_owner_attribution.py
Normal file
@@ -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) == []
|
||||
@@ -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
|
||||
|
||||
|
||||
Reference in New Issue
Block a user