fix: back off SQLite log writes after lock errors#391
Conversation
Co-authored-by: Talon <talon@users.noreply.github.com>
7a34b19 to
9acaa4a
Compare
YoungCan-Wang
left a comment
There was a problem hiding this comment.
[P1] The one-second cooldown still permits repeated event-loop stalls under sustained lock contention.
A failed append_log() can already block for the full one-second SQLite/write-lock timeout. Because _retry_after is then set to only one second after that failure completes, continuous log traffic can still trigger another synchronous one-second write attempt roughly every two seconds.
I reproduced the timing with a store that consumes the busy timeout before raising: over 5.11 seconds, the handler made three blocking attempts, spending about 60% of the interval blocked. Since proxy request paths call log.info() synchronously, these retries can continue pausing the proxy event loop and may preserve the timeout behavior this PR is intended to fix.
The added regression test raises OperationalError immediately, so it verifies attempt counting but does not model the blocking duration. Please use a materially longer or exponential circuit breaker, temporarily disable auxiliary persistence, or move these writes off the request/event-loop path, and add a test where the failed write consumes the busy timeout before raising.
The rest of the change looks sound; this sustained-contention behavior is the blocking concern.
Summary
Problem
A long-running Talon proxy entered a sustained timeout loop while the shared 23 GB trace database was under write contention. Current
mainalready bounds SQLite waits and prevents trace storage errors from aborting requests, butSQLiteLogHandlerstill retried every log record immediately. Each retry could block synchronously for up to one second, so concurrent requests recreated prolonged request latency.Before the fix, the focused regression test reproduced the retry storm and failed with
assert 3 == 2. The handler now skips auxiliary log persistence during a one-second cooldown and retries afterward.Validation
uv lock --checkuv run ruff check .uv run ruff format --check .uv run pytest tests/ -x --timeout=60(989 passed, 25 skipped)gpt-5.4via the ChatGPT OAuth targetEvidence
Real E2E trace viewer source: the screenshot was captured from the viewer HTML exported by
uv run claude-tap export bb2b323f-f40e-4a08-aa18-e21bdfdcd5fa --format htmlafter a resumed Codex 0.144.4 session through the local branch, using the isolated/tmp/claude-tap-log-backoff-e2e/traces.sqlite3database.