diff --git a/.agents/docs/error-experience/entries/2026-07-17-sqlite-log-lock-retry-storm.md b/.agents/docs/error-experience/entries/2026-07-17-sqlite-log-lock-retry-storm.md new file mode 100644 index 00000000..04f21f46 --- /dev/null +++ b/.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. diff --git a/.agents/evidence/pr/sqlite-log-backoff/codex-resume-trace-viewer.png b/.agents/evidence/pr/sqlite-log-backoff/codex-resume-trace-viewer.png new file mode 100644 index 00000000..e7b51321 Binary files /dev/null and b/.agents/evidence/pr/sqlite-log-backoff/codex-resume-trace-viewer.png differ diff --git a/claude_tap/trace_log_handler.py b/claude_tap/trace_log_handler.py index 2b1b4346..0aaba2a6 100644 --- a/claude_tap/trace_log_handler.py +++ b/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) diff --git a/tests/test_trace_store_locking.py b/tests/test_trace_store_locking.py index a5a96f7a..4868a1b0 100644 --- a/tests/test_trace_store_locking.py +++ b/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"