fix: back off SQLite log writes after lock errors

.agents/docs/error-experience/entries/2026-07-17-sqlite-log-lock-retry-storm.md

@@ -0,0 +1,23 @@
+# SQLite log lock retry storm
+
+Date: 2026-07-17
+
+## What broke
+
+A long-running Talon Codex proxy eventually returned `request timed out` for every turn. The proxy log contained a sustained stream of `sqlite3.OperationalError: database is locked` errors from `SQLiteLogHandler` while the shared trace database was under write contention.
+
+The process had loaded claude-tap 0.1.107 before a newer executable was installed. Updating the executable on disk did not replace the already imported code in that process, so the failures continued until Talon restarted the proxy.
+
+## Investigation
+
+Broad journal searches produced too much notification traffic to identify the transition. Grouping terminal turn states and error notifications by UTC hour showed a clean boundary: successful turns fell to zero while `request timed out` failures became continuous. The claude-tap log then tied that boundary to repeated SQLite lock exceptions in the request logging path.
+
+Comparing 0.1.107 with current `main` confirmed that the main branch already bounded SQLite lock waits and prevented storage errors from aborting proxy requests. A focused regression test exposed one remaining problem: the synchronous logging handler retried every log record immediately after a failure. Concurrent requests could therefore serialize repeated one-second waits on the event loop even though each individual failure was caught.
+
+## Fix
+
+After a SQLite logging failure, the handler skips auxiliary log persistence for one second before retrying. Trace record persistence keeps its existing behavior, and successful logging resumes automatically after the cooldown.
+
+## Lesson
+
+Catching an ancillary storage exception is not sufficient when the failed operation has a bounded but non-trivial wait. Hot synchronous paths also need retry pacing so concurrent failures cannot recreate an outage through accumulated latency.

claude_tap/trace_log_handler.py

@@ -4,10 +4,13 @@
 
 import logging
 import sqlite3
+import time
 from datetime import datetime, timezone
 
 from claude_tap.trace_store import TraceStore, get_trace_store
 
+_STORAGE_RETRY_SECONDS = 1.0
+
 
 class SQLiteLogHandler(logging.Handler):
     """Write log records to the active trace session."""
@@ -16,8 +19,11 @@ def __init__(self, session_id: str, store: TraceStore | None = None):
         super().__init__()
         self.session_id = session_id
         self._store = store or get_trace_store()
+        self._retry_after = 0.0
 
     def emit(self, record: logging.LogRecord) -> None:
+        if time.monotonic() < self._retry_after:
+            return
         try:
             message = record.getMessage()
             formatter = self.formatter or logging.Formatter()
@@ -32,6 +38,7 @@ def emit(self, record: logging.LogRecord) -> None:
                 logged_at=datetime.fromtimestamp(record.created, tz=timezone.utc).strftime("%H:%M:%S"),
             )
         except sqlite3.Error:
+            self._retry_after = time.monotonic() + _STORAGE_RETRY_SECONDS
             return
         except Exception:
             self.handleError(record)

tests/test_trace_store_locking.py

@@ -3,6 +3,7 @@
 from __future__ import annotations
 
 import json
+import logging
 import multiprocessing
 import os
 import sqlite3
@@ -18,6 +19,7 @@
 from claude_tap.cli import _create_trace_writer
 from claude_tap.codex_app_transcript import CodexAppTranscriptSessionRegistry
 from claude_tap.trace import TraceWriter
+from claude_tap.trace_log_handler import SQLiteLogHandler
 from claude_tap.trace_store import TraceStore
 from tests.conftest import e2e_env, trace_db_path
 from tests.test_e2e import PROJECT_ROOT, run_fake_upstream_in_thread
@@ -167,6 +169,28 @@ def test_failed_write_rolls_back_quickly(tmp_path: Path) -> None:
     assert store.load_records(session_id) == [_record(2)]
 
 
+def test_sqlite_log_handler_backs_off_after_storage_error(monkeypatch: pytest.MonkeyPatch) -> None:
+    attempts = 0
+    now = 100.0
+
+    class LockedStore:
+        def append_log(self, *_args, **_kwargs) -> None:
+            nonlocal attempts
+            attempts += 1
+            raise sqlite3.OperationalError("database is locked")
+
+    monkeypatch.setattr(time, "monotonic", lambda: now)
+    handler = SQLiteLogHandler("locked-session", store=LockedStore())
+    record = logging.LogRecord("test", logging.INFO, __file__, 1, "proxy request", (), None)
+
+    handler.emit(record)
+    handler.emit(record)
+    now += 1.0
+    handler.emit(record)
+
+    assert attempts == 2
+
+
 @pytest.mark.asyncio
 async def test_trace_writer_drops_locked_record_without_interrupting_capture(tmp_path: Path, capsys) -> None:
     db_path = tmp_path / "writer.sqlite3"