Skip to content

fix(db): one wedged handler could freeze the whole database — three bounds - #368

Merged
vjvarada merged 2 commits into
mainfrom
fix/stalled-session-db-freeze
Aug 6, 2026
Merged

fix(db): one wedged handler could freeze the whole database — three bounds#368
vjvarada merged 2 commits into
mainfrom
fix/stalled-session-db-freeze

Conversation

@vjvarada

@vjvarada vjvarada commented Aug 6, 2026

Copy link
Copy Markdown
Contributor

The incident

Sending mail stopped working on 2026-08-06. It was reported as "I can't send emails — is it the multi-user work?" It was not an auth or scoping regression: the send path's ownership and feature gates were intact. It was a database freeze, and email was simply the first surface anyone noticed.

Verified live on the box with pg_blocking_pids:

pid 1208980  idle in transaction, 14h44m
             SELECT org_domains FROM email_assistant_settings WHERE account_id = $1
                 ↓ holds ACCESS SHARE
pid 1210326  ALTER TABLE email_assistant_settings ADD COLUMN IF NOT EXISTS ...   (waiting)
                 ↓ ACCESS EXCLUSIVE parks at the head of a FIFO queue
pid 1209232, 1209228, 1216158, ...  every later reader of that table, indefinitely

The chain:

  1. An LLM completion hung — acompletion was awaited with no wall-clock bound.
  2. The caller held a SQLAlchemy AsyncSession across that await. A session opens a transaction on first execute() and holds it until commit/rollback/close, so the hung call parked a Postgres transaction idle in transaction for 14h44m.
  3. The migration runner asked for ACCESS EXCLUSIVE on that table and waited. Postgres's lock queue is FIFO, so every later reader queued behind the waiting ALTER — including SELECT signature FROM email_assistant_settings, which the send path makes on its way to the provider.
  4. Each blocked reader pinned a pooled connection until the email engine's 10+20 pool drained, and unrelated endpoints started answering QueuePool limit of size 10 overflow 20 reached.

The BFF aborts the send POST at 30s, so the user-visible symptom was a failed send with zero POST /email/send lines in three days of gateway logs — the request never completed, so uvicorn never logged it. Absence of the access line was the symptom.

Terminating the stale backend cleared it: the blocked query went from indefinite to 1.5ms. A new session took the same lock six minutes later and the freeze reproduced identically. That is what makes this a code fix rather than an operational one.

The fix — three independent bounds

Any one of them breaks the chain. All three are here because there was no bound at all, and the cheapest way for this to come back is for someone to restore one link while the other two still look fine.

Link Bound Where
Unbounded await asyncio.wait_for at 90s per attempt (LLM_REQUEST_TIMEOUT_SECS) acb_llm/client.py
Unbounded held transaction idle_in_transaction_session_timeout=600s via asyncpg server_settings gateway/db.py + 7 engines, email_ingestion
Migration waits for a lock SET lock_timeout=5s + 5 bounded retries the migration runner

Three details worth reviewing rather than skimming:

  • except TimeoutError sits ABOVE the generic handler. asyncio.wait_for's TimeoutError stringifies to '', so the existing any(token in str(exc).lower() ...) transient check reads it as non-transient and re-raises. Getting the order wrong would convert one slow provider response into a hard failure on attempt 1 — the fix becoming a new, quieter outage. A test pins it.
  • 600s, not 300s. A rules run legitimately awaits a completion with a session open, and complete retries 3×90s + 6s backoff ≈ 276s. If the DB ceiling dropped under that, Postgres would start killing healthy transactions mid-retry, which reads as random unattributable failures under load. test_idle_ceiling_clears_the_llm_worst_case fails if someone raises one number without the other.
  • The idle ceiling is scoped to the app's own connections, not set via ALTER ROLE. pg_dump and the migration runner connect as the same role and must not inherit an app-tuned deadline.

test_every_gateway_engine_carries_the_bounds is a structural guard: per-site opt-in is exactly how the email engine ended up as the one that drained.

Verification

uv run pytest tests/unit/test_stalled_session_cannot_freeze_the_db.py -q   -> 10 passed
uv run pytest tests/unit -q -k email                                       -> 973 passed, 1 skipped
uv run pytest tests/unit -q -k "llm or db or engine or connect or migration"
    -> 410 passed, 1 failed (test_workflows_engine::test_module_node_runs_generated_code,
       PRE-EXISTING — red on a clean stashed tree too)
uv run ruff check . --select F821,F601,F602,F502,F7,B006                   -> All checks passed!
uv run xenon --max-absolute F --max-modules F --max-average B apps packages -> exit 0

Not just green — confirmed red without the fix. With the asyncio.wait_for removed, both LLM tests fail (in bounded time; each carries an outer CI guard so a broken build fails rather than hangs). The retry loop was exercised against a fake psql:

case result
clean apply exit 0, 1 attempt
lock busy 2x then succeeds exit 0, 3 attempts, retries logged
lock busy forever exit 1 after exactly 3, prints the pg_stat_activity query that finds the holder
real SQL error exit 1 after exactly 1 — no retry, real error surfaced

Where multi-user came in

As the amplifier, not the bug. A second mailbox (Ishaanpilar@fracktal.in) was connected 2026-08-05 08:56 UTC, doubling every per-account background loop against pools sized when there was one mailbox. The sweep for the new account ran seconds after the lock was taken. Suggestive, not proven — pg_stat_activity does not expose the bound account_id.

Not in this PR

  • The email automation package holds DB sessions across provider and LLM calls throughout. That is now bounded, not removed. Restructuring those transaction boundaries is its own change.
  • acb-pull.service was exiting 128 (git fetch -q origin release) on repeated ticks around 06:42–06:58 UTC. It has since recovered on its own — last successful pull 07:20:49Z, box at 8d83ca10. Worth a look at why it flapped, but it is not blocking this deploy.
  • The unit file acb-pull.service lives only on the box, not in the repo, so the concurrent-tick hazard in it (a fixed /tmp/acb-pull-run.sh that a later tick can overwrite while an earlier one is still executing it) cannot be fixed here. Two overlapping apply_migrations.sh runs were observed during the incident, so the flock in vps_pull.sh is not covering everything it looks like it covers.
  • The leak is still live on the deployed code. Re-checked after opening this PR: the same resolve_org_domains session was 20 minutes idle in transaction with a migration and two readers queued behind it. Cleared again by hand. Until this merges, the box stays one long LLM hang away from a repeat.

No migration. No .env change required — both new knobs have working defaults.

🤖 Generated with Claude Code

vjvarada and others added 2 commits August 6, 2026 12:57
Two defects, one green run (spec Defect 4): publish-release's depth-1
checkout could never prove the fast-forward, so 'release' sat at #360
for three merges; and ssh_deploy's 900s timeout is shorter than the
pre-migration backup alone, so the session died mid-apply and verify()
blessed the still-running OLD deployment. fetch-depth: 0 and timeout
1800 (matched to the pull unit's TimeoutStartSec).

Defect 3 recorded alongside: the pull poller's HEAD==release skip
cannot see an incomplete apply, because git reset moves HEAD before
migrations run.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…ounds

Sending mail stopped working on 2026-08-06. The send path's auth was fine; the
cause was infrastructural, and the same chain would have taken down any app
surface that reads a table a migration happens to touch.

What happened, verified on the box:

1. An LLM completion hung. `acompletion` was awaited with no wall-clock bound.
2. The caller held a SQLAlchemy AsyncSession across that await. A session opens a
   transaction on first execute() and holds it until commit/rollback/close, so
   the hung call parked a Postgres transaction `idle in transaction` — holding
   ACCESS SHARE on email_assistant_settings — for 14h44m.
3. The migration runner asked for ACCESS EXCLUSIVE on that table to replay
   39_email_learned_writing_style.sql, and WAITED. Postgres's lock queue is
   FIFO, so every later reader queued behind the waiting ALTER — including
   `SELECT signature FROM email_assistant_settings`, which the send path makes
   on its way to the provider. The BFF aborts that POST at 30s, so the symptom
   was a failed send with no /email/send line in the gateway log at all.
4. Each blocked reader held its pooled connection, so the email engine's
   10+20 pool drained and endpoints with nothing to do with email began
   answering `QueuePool limit of size 10 overflow 20 reached`.

Terminating the stale backend cleared it. A NEW session took the same lock six
minutes later and the freeze reproduced identically, which is what makes this a
code fix rather than an operational one.

Three independent bounds; any one breaks the chain. All three are here because
there was no bound at all, and the cheapest way for this to come back is for
someone to restore one link while the other two still look fine.

- acb_llm/client.py: every completion runs under asyncio.wait_for at 90s
  (LLM_REQUEST_TIMEOUT_SECS). The wall-clock bound is the guarantee, not
  litellm's `timeout` — a provider-side timeout is only honoured to the extent
  the provider's transport honours it, and the one that hung did not.
  TimeoutError is caught ABOVE the generic handler: asyncio's TimeoutError
  stringifies to '', so the existing `any(token in str(exc).lower() ...)`
  transient test reads it as non-transient and re-raises, which would have
  turned one slow response into a hard failure on attempt 1.
- gateway/db.py: engine_connect_args() adds
  idle_in_transaction_session_timeout=600s via asyncpg server_settings, and all
  seven gateway engines now share it (tasks already used the seam). Scoped to
  the app's connections deliberately — pg_dump and the migration runner connect
  as the same role and must not inherit an app-tuned deadline. 600s and not
  300s because a rules run legitimately awaits a completion with a session open
  and `complete` retries 3x90s + 6s backoff; a test pins that coupling so
  raising one number without the other fails rather than silently killing
  healthy transactions. email_ingestion gets the same via its own
  _connect_args (separate package, cannot share the constant).
- The migration runner: SET lock_timeout (5s) prepended to each migration's
  psql session, with 5 bounded retries. A stale reader can now delay a
  migration but can no longer freeze a table, because the ALTER never enters
  the lock queue. Only a lock timeout retries — any other psql error still
  fails at once. On exhaustion it prints the pg_stat_activity query that finds
  the holder.

Not fixed here, and named rather than left to be rediscovered: the email
automation package holds DB sessions across provider and LLM calls throughout.
That is now bounded rather than removed. Restructuring those transaction
boundaries is its own change.

Verify:
  uv run pytest tests/unit/test_stalled_session_cannot_freeze_the_db.py -q
      -> 10 passed
  uv run pytest tests/unit -q -k email        -> 973 passed, 1 skipped
  uv run pytest tests/unit -q -k "llm or db or engine or connect or migration"
      -> 410 passed, 1 pre-existing failure (test_workflows_engine, red on a
         clean tree too)
  uv run ruff check . --select F821,F601,F602,F502,F7,B006  -> All checks passed!
  uv run xenon --max-absolute F --max-modules F --max-average B apps packages
      -> exit 0

  The two LLM tests were confirmed RED with the ceiling removed, and the retry
  loop was exercised against a fake psql: clean apply 1 attempt; lock-busy-twice
  3 attempts then success; lock-busy-forever fails after exactly 3 with the
  diagnostic; a real SQL error fails after 1 with no retry.

No migration. No .env change required — both new knobs have working defaults.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@vjvarada
vjvarada merged commit c038252 into main Aug 6, 2026
7 checks passed
vjvarada added a commit that referenced this pull request Aug 6, 2026
…ry deploy

#368 shipped `SET lock_timeout = 5s;` — unquoted. Postgres answers "trailing
junk after numeric literal", and under ON_ERROR_STOP=1 that failed the FIRST
migration in the ladder. So a guard whose entire purpose was to stop a stalled
session from blocking deploys blocked every deploy itself. Caught on its first
real run; no DDL executed, because the prelude is the first statement in the
session and the ladder stops there.

Two things were wrong, and the second is the one worth keeping.

1. Quote the value. '5s' and '5000' are both accepted by Postgres; a bare 5s is
   a syntax error. Verified against the live server, not inferred.

2. A safety feature must not be able to brick the thing it protects. The prelude
   is now PROBED once, before the ladder runs. If the server rejects it — a
   typo'd MIGRATION_LOCK_TIMEOUT, a server that spells it differently — the
   runner says so loudly and applies migrations WITHOUT it. Degrading to the
   previous behaviour is survivable; an undeployable box is not. With the probe
   in place, the original unquoted bug would have produced a warning and a
   successful deploy instead of an outage in the deploy path.

Why the tests missed it, and what changed so they cannot again:

- `test_migrations_set_a_lock_timeout` asserted the string was PRESENT, not that
  it was valid SQL. Presence is not validity. `test_the_lock_timeout_value_is_
  QUOTED` now parses the emitted statement and requires a quoted value. It scans
  only non-comment lines — the runner quotes the broken form in its own
  explanation of this bug, and a test that cannot tell an example from an
  instruction would fail on the documentation that prevents the next occurrence.
- The shell harness's fake psql drained stdin without looking at it, so any SQL
  passed. It now mimics Postgres's actual rule and rejects a bare unit. Re-run
  with the original bug reintroduced, it reproduces "trailing junk" exactly —
  and the deploy still succeeds, via the new fallback.
- `test_a_bad_prelude_degrades_instead_of_bricking_the_deploy` pins the fallback
  path itself, so a future edit cannot quietly make the guard fail closed again.

Verify:
  uv run pytest tests/unit/test_stalled_session_cannot_freeze_the_db.py -q
      -> 12 passed
  uv run ruff check . --select F821,F601,F602,F502,F7,B006  -> All checks passed!
  bash -n on the runner                                     -> OK

  Red-first confirmed: with the unquoted form reintroduced,
  test_the_lock_timeout_value_is_QUOTED fails and the fixed form passes.

  Behavioural, against a SQL-validating fake psql:
    valid prelude, clean apply         -> exit 0, 1 attempt
    lock busy 2x then succeeds         -> exit 0, 3 attempts
    lock busy past the retry budget    -> exit 1, exactly 3 attempts
    MIGRATION_LOCK_TIMEOUT=nonsense    -> exit 0, warns, applies without the
                                          timeout (the new fallback)

No migration. No .env change.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant