sneak/webhooker
1
0
Fork 0
Code Issues 62 Pull Requests 2 Actions Packages Projects Releases Wiki Activity

A concurrent reader wedges the per-webhook database, stranding delivered webhooks at pending and re-delivering them on restart #256

New Issue
Closed
opened 2026-08-24 00:58:15 +02:00 by clawbot · 2 comments
clawbot commented 2026-08-24 00:58:15 +02:00
Collaborator
Copy Link

Reproduced end to end during the deployability audit. This is the defect that blocks 1.0.

Premises, confirmed on disk

Every SQLite handle opens as file:...?cache=shared&mode=rwc with no pool bound. pragma journal_mode returns delete (rollback journal, not WAL) and pragma busy_timeout returns 0, so a lock conflict returns immediately and nothing in the stack retries. The engine runs 10 delivery workers against the same file.

Load alone does NOT trigger it

Honest negative result first. Fresh source, 6 active targets, no concurrent reader:

  • 30 events, concurrency 1, 217/s — 180 deliveries, 0 write errors, 0 stranded
  • 50 events, concurrency 4, 149/s — 300 deliveries, 0 write errors, 0 stranded
  • 100 events, concurrency 8, 229/s — 600 deliveries, 0 write errors, 0 stranded
  • 200 events, concurrency 20, 407/s — 1200 deliveries, 0 write errors, 0 stranded

Also clean with RETENTION_SWEEP_INTERVAL=5s, and clean with a proper sqlite3 .backup running every 2 s at up to 25 events/s. Genuinely low volume with an operator polling select count(*) every 2 s is clean.

A concurrent long-held read DOES trigger it

Matched control, identical load, the only difference being an operator running sqlite3 <db> .dump — an export of their own data:

  • Control (no reader), 5 events/s x 6 targets: 0 inbound 500s, 0 engine write errors, 600 delivered, clean.
  • Test (.dump reader), same load: 60 of 60 inbound webhooks rejected with HTTP 500 (failed to commit transaction: database is locked (5) (SQLITE_BUSY)), 60 engine write errors, database wedged and unreadable.

Senders see 500. Those events never enter the system at all.

One lock conflict poisons a pooled connection permanently

Error census across the run: 593 x SQL logic error: cannot start a transaction within a transaction (1) against only 4 x database is locked (5). A single SQLITE_BUSY leaves the connection mid-transaction; database/sql keeps handing that connection out, and its open transaction holds the file lock.

The per-webhook DB became unreadable even in mode=ro, a hot -journal file remained, and the event log page hung past 180 s. Still locked 45 s after all load and readers stopped — it does not self-heal. Blast radius is one webhook; other sources kept returning 200. A restart clears it.

The stranding and the duplicates, measured

From the run that first wedged a database:

  • 1380 deliveries created (230 events x 6 targets); all 1380 reached the sinks, verified by payload.
  • Only 1176 delivery_results recorded. 206 deliveries left at pending, 204 of them with zero attempt rows.
  • After restart the sinks went from 230 each to 263-265 each: 206 duplicate deliveries, exactly matching the 206 stranded rows.
  • Single-payload proof: {"tag":"moderate","seq":167} arrived at the sink at 22:13:05 and again at 22:21:48, straddling the restart. The event log claims that delivery is delivered with 1 recorded attempt. The receiver got two POSTs. The audit trail is falsified.

It is self-sustaining

After the restart that was supposed to clear the wedge, with no external reader running at all, recovery re-enqueued the stranded pending rows across 10 workers and re-wedged the same file: 60 x failed to begin transaction: cannot start a transaction within a transaction. The restart that clears the wedge is itself a write burst that recreates it.

Mechanism

All in internal/delivery/engine.go:

  • recordResult (:913-940) and updateDeliveryStatus (:955-975) both log-and-swallow their errors, so a failed write leaves the row at its previous status.
  • Nothing sweeps pending — sweepWebhookRetries (:692-735) queries status = 'retrying' only.
  • recoverPendingDeliveries (:602-642) and sendRecoveredDeliveries (:1171-1213) re-enqueue every pending row unconditionally with attemptNum = 1, with no check for an existing successful DeliveryResult and no compare-and-set claim.

There is no state distinguishing "delivered but unrecorded" from "never attempted", so the engine cannot do better than re-send.

Definition of done

Two halves. Both are required; fixing only the first leaves the falsified audit trail, and fixing only the second leaves the wedge.

Durability layer, internal/database:

  • Open every SQLite handle with a busy timeout and WAL journaling, and drop cache=shared. cache=shared turns an in-process table conflict into SQLITE_LOCKED, which a busy timeout does not retry, so removing it is part of the fix rather than incidental.
  • Bound the connection pool per per-webhook handle so a poisoned connection cannot be handed out indefinitely.
  • Applies to the main DB, the per-webhook event DBs, and the archive DBs.

Delivery layer, internal/delivery/engine.go:

  • recordResult and updateDeliveryStatus must return their errors rather than swallowing them, and the caller must leave the delivery in a RETRYABLE state rather than a lying one.
  • Recovery must not re-send a delivery that already has a successful DeliveryResult.
  • Give the periodic sweep a pending-with-age-bound arm, so a stranded delivery is recovered without requiring a restart.

Verification

  • make check green.
  • The matched pair that produced this report: same load, one arm with a concurrent sqlite3 .dump reader and one without. Both arms must show 0 inbound HTTP 500s and 0 engine write errors.
  • A restart after the run must add zero new requests at the sinks.
  • A test proving recovery skips a pending delivery that already has a successful result row.
  • State in the PR body what the busy timeout and pool bound were set to and why.
Reproduced end to end during the deployability audit. This is the defect that blocks 1.0. ## Premises, confirmed on disk Every SQLite handle opens as `file:...?cache=shared&mode=rwc` with no pool bound. `pragma journal_mode` returns `delete` (rollback journal, not WAL) and `pragma busy_timeout` returns `0`, so a lock conflict returns immediately and nothing in the stack retries. The engine runs 10 delivery workers against the same file. ## Load alone does NOT trigger it Honest negative result first. Fresh source, 6 active targets, no concurrent reader: - 30 events, concurrency 1, 217/s — 180 deliveries, 0 write errors, 0 stranded - 50 events, concurrency 4, 149/s — 300 deliveries, 0 write errors, 0 stranded - 100 events, concurrency 8, 229/s — 600 deliveries, 0 write errors, 0 stranded - 200 events, concurrency 20, 407/s — 1200 deliveries, 0 write errors, 0 stranded Also clean with `RETENTION_SWEEP_INTERVAL=5s`, and clean with a proper `sqlite3 .backup` running every 2 s at up to 25 events/s. Genuinely low volume with an operator polling `select count(*)` every 2 s is clean. ## A concurrent long-held read DOES trigger it Matched control, identical load, the only difference being an operator running `sqlite3 <db> .dump` — an export of their own data: - Control (no reader), 5 events/s x 6 targets: 0 inbound 500s, 0 engine write errors, 600 delivered, clean. - Test (`.dump` reader), same load: **60 of 60 inbound webhooks rejected with HTTP 500** (`failed to commit transaction: database is locked (5) (SQLITE_BUSY)`), 60 engine write errors, database wedged and unreadable. Senders see 500. Those events never enter the system at all. ## One lock conflict poisons a pooled connection permanently Error census across the run: **593** x `SQL logic error: cannot start a transaction within a transaction (1)` against only **4** x `database is locked (5)`. A single `SQLITE_BUSY` leaves the connection mid-transaction; `database/sql` keeps handing that connection out, and its open transaction holds the file lock. The per-webhook DB became unreadable even in `mode=ro`, a hot `-journal` file remained, and the event log page hung past 180 s. Still locked 45 s after all load and readers stopped — it does not self-heal. Blast radius is one webhook; other sources kept returning 200. A restart clears it. ## The stranding and the duplicates, measured From the run that first wedged a database: - 1380 deliveries created (230 events x 6 targets); all 1380 reached the sinks, verified by payload. - Only 1176 `delivery_results` recorded. **206 deliveries left at `pending`**, 204 of them with zero attempt rows. - After restart the sinks went from 230 each to 263-265 each: **206 duplicate deliveries**, exactly matching the 206 stranded rows. - Single-payload proof: `{"tag":"moderate","seq":167}` arrived at the sink at 22:13:05 and again at 22:21:48, straddling the restart. The event log claims that delivery is `delivered` with **1 recorded attempt**. The receiver got two POSTs. The audit trail is falsified. ## It is self-sustaining After the restart that was supposed to clear the wedge, with no external reader running at all, recovery re-enqueued the stranded `pending` rows across 10 workers and re-wedged the same file: 60 x `failed to begin transaction: cannot start a transaction within a transaction`. The restart that clears the wedge is itself a write burst that recreates it. ## Mechanism All in `internal/delivery/engine.go`: - `recordResult` (:913-940) and `updateDeliveryStatus` (:955-975) both log-and-swallow their errors, so a failed write leaves the row at its previous status. - Nothing sweeps `pending` — `sweepWebhookRetries` (:692-735) queries `status = 'retrying'` only. - `recoverPendingDeliveries` (:602-642) and `sendRecoveredDeliveries` (:1171-1213) re-enqueue every `pending` row unconditionally with `attemptNum = 1`, with no check for an existing successful `DeliveryResult` and no compare-and-set claim. There is no state distinguishing "delivered but unrecorded" from "never attempted", so the engine cannot do better than re-send. ## Definition of done Two halves. Both are required; fixing only the first leaves the falsified audit trail, and fixing only the second leaves the wedge. **Durability layer, `internal/database`:** - Open every SQLite handle with a busy timeout and WAL journaling, and drop `cache=shared`. `cache=shared` turns an in-process table conflict into `SQLITE_LOCKED`, which a busy timeout does not retry, so removing it is part of the fix rather than incidental. - Bound the connection pool per per-webhook handle so a poisoned connection cannot be handed out indefinitely. - Applies to the main DB, the per-webhook event DBs, and the archive DBs. **Delivery layer, `internal/delivery/engine.go`:** - `recordResult` and `updateDeliveryStatus` must return their errors rather than swallowing them, and the caller must leave the delivery in a RETRYABLE state rather than a lying one. - Recovery must not re-send a delivery that already has a successful `DeliveryResult`. - Give the periodic sweep a `pending`-with-age-bound arm, so a stranded delivery is recovered without requiring a restart. ## Verification - `make check` green. - The matched pair that produced this report: same load, one arm with a concurrent `sqlite3 .dump` reader and one without. Both arms must show **0 inbound HTTP 500s and 0 engine write errors**. - A restart after the run must add **zero** new requests at the sinks. - A test proving recovery skips a `pending` delivery that already has a successful result row. - State in the PR body what the busy timeout and pool bound were set to and why.
clawbot added this to the 1.0.0 milestone 2026-08-24 00:58:19 +02:00
clawbot commented 2026-08-24 01:12:52 +02:00
Author
Collaborator
Copy Link

Reproduced on unmodified next before writing any code, with a harness matching the report: 6 active http targets, 60 events at 5/s, a concurrent sqlite3 <db> .dump loop started 4 s in.

  • 38 of 60 inbound webhooks rejected with HTTP 500, 260 engine write errors.
  • 132 requests at the sinks before restart, 244 after — 112 duplicate deliveries, confirmed by payload at the sink.
  • delivery_results holds 132 rows for 244 actual POSTs: the audit trail is falsified exactly as described.
  • pragma journal_mode = delete on the live file.

Plan.

Durability (internal/database). One DSN builder used by all three open sites (main DB, per-webhook event DBs, archive DBs): drop cache=shared, add _pragma=journal_mode(WAL), _pragma=busy_timeout(...), and _txlock=immediate. The last one matters as much as the busy timeout: a deferred transaction that upgrades to a write lock mid-transaction gets SQLITE_BUSY without the busy handler being consulted, and that is the failure that leaves a pooled connection mid-transaction and produces the 593 cannot start a transaction within a transaction. BEGIN IMMEDIATE takes the write lock up front, where the busy handler does apply. Plus explicit pool bounds (SetMaxOpenConns/SetMaxIdleConns/SetConnMaxLifetime/SetConnMaxIdleTime) so a connection that is poisoned anyway is retired rather than handed out forever.

WAL introduces -wal/-shm sidecars, so the backup/restore section of README.md gets corrected in the same commit — both documented procedures (sqlite3 .backup, stop-copy-start cp -a) are re-verified under WAL.

Delivery (internal/delivery/engine.go). recordResult and updateDeliveryStatus return their errors. On a bookkeeping write failure the caller does not advance the status, so the row stays in whichever non-terminal state it already held (pending or retrying) — the retryable states, per DeliveryStatus.Terminal(). This needs no write on the failure path, so it cannot itself fail.

Recovery and the sweep then reconcile before re-sending: any pending delivery that already has a successful DeliveryResult is marked delivered instead of re-enqueued. That distinguishes "delivered and recorded but status unwritten" from "never attempted", which is the state the issue notes does not exist today. Recovery also stops re-enqueueing at attemptNum = 1; it uses the real attempt count.

sweepWebhookRetries gains a pending-and-older-than-N arm running the same reconcile-then-dispatch path, so a stranded delivery is recovered without a restart.

Verification is the matched pair above plus a restart, with the sinks counted by payload, and a unit test that recovery skips a pending delivery holding a successful result row.

Reproduced on unmodified `next` before writing any code, with a harness matching the report: 6 active `http` targets, 60 events at 5/s, a concurrent `sqlite3 <db> .dump` loop started 4 s in. - 38 of 60 inbound webhooks rejected with HTTP 500, 260 engine write errors. - 132 requests at the sinks before restart, 244 after — **112 duplicate deliveries**, confirmed by payload at the sink. - `delivery_results` holds 132 rows for 244 actual POSTs: the audit trail is falsified exactly as described. - `pragma journal_mode` = `delete` on the live file. Plan. **Durability (`internal/database`).** One DSN builder used by all three open sites (main DB, per-webhook event DBs, archive DBs): drop `cache=shared`, add `_pragma=journal_mode(WAL)`, `_pragma=busy_timeout(...)`, and `_txlock=immediate`. The last one matters as much as the busy timeout: a deferred transaction that upgrades to a write lock mid-transaction gets `SQLITE_BUSY` *without* the busy handler being consulted, and that is the failure that leaves a pooled connection mid-transaction and produces the 593 `cannot start a transaction within a transaction`. `BEGIN IMMEDIATE` takes the write lock up front, where the busy handler does apply. Plus explicit pool bounds (`SetMaxOpenConns`/`SetMaxIdleConns`/`SetConnMaxLifetime`/`SetConnMaxIdleTime`) so a connection that is poisoned anyway is retired rather than handed out forever. WAL introduces `-wal`/`-shm` sidecars, so the backup/restore section of `README.md` gets corrected in the same commit — both documented procedures (`sqlite3 .backup`, stop-copy-start `cp -a`) are re-verified under WAL. **Delivery (`internal/delivery/engine.go`).** `recordResult` and `updateDeliveryStatus` return their errors. On a bookkeeping write failure the caller does **not** advance the status, so the row stays in whichever non-terminal state it already held (`pending` or `retrying`) — the retryable states, per `DeliveryStatus.Terminal()`. This needs no write on the failure path, so it cannot itself fail. Recovery and the sweep then reconcile before re-sending: any `pending` delivery that already has a successful `DeliveryResult` is marked `delivered` instead of re-enqueued. That distinguishes "delivered and recorded but status unwritten" from "never attempted", which is the state the issue notes does not exist today. Recovery also stops re-enqueueing at `attemptNum = 1`; it uses the real attempt count. `sweepWebhookRetries` gains a `pending`-and-older-than-N arm running the same reconcile-then-dispatch path, so a stranded delivery is recovered without a restart. Verification is the matched pair above plus a restart, with the sinks counted by payload, and a unit test that recovery skips a `pending` delivery holding a successful result row.
clawbot commented 2026-08-24 01:42:37 +02:00
Author
Collaborator
Copy Link

Built in #263 (branch issue-256-sqlite-durability, base next). Full rationale is in the PR body; the verification is here.

Matched pair, same load both arms (6 http targets, 60 events at 5/s, sinks holding each POST 1.5 s so deliveries are in flight), one arm with a concurrent sqlite3 <db> .dump loop:

before, reader before, no reader after, reader after, no reader
inbound HTTP 500s 38 / 60 0 0 0
engine write errors 260 0 0 0
new requests from restart 112 160 0 0
duplicate payloads at sinks 112 10 0 0
delivery_results rows 132 for 244 POSTs — 360 for 360 POSTs 360 for 360 POSTs

Sink counts are by payload at the receiver, not from the database. The before/no-reader arm's 160 is my harness not draining before the restart rather than the defect; both after arms drain and add nothing.

Pragmas confirmed by querying live handles, not the DSN: journal_mode = wal, busy_timeout = 10000 on both a running per-webhook database and the main database (TestPerWebhookDBAppliesPragmasOnALiveHandle, TestMainDBAppliesPragmasOnALiveHandle).

make check green with GOFLAGS=-count=1, lint in the digest-pinned container, re-run after rebasing onto current next.

Both documented backup procedures re-verified under WAL. .backup and stop-copy-start still work unchanged; the restore instructions were inverted and are corrected — after a crash the .db alone read 40 rows where .db plus -wal read 50, so a -wal in a salvaged copy must be carried, not dropped.

Two answers worth stating here. Send-succeeded-but-write-failed leaves the delivery in whichever non-terminal status it already holds and writes nothing, because the failure path must not depend on the database that just refused a write; the sweeps then recover it, and a delivery whose result row did land is settled to delivered rather than re-sent. And re-dispatch is claimed by compare-and-set, otherwise every 60-second sweep would send the same still-running delivery again.

One unrelated defect found while auditing the transaction paths, filed rather than fixed here: #262.

Built in https://git.eeqj.de/sneak/webhooker/pulls/263 (branch `issue-256-sqlite-durability`, base `next`). Full rationale is in the PR body; the verification is here. **Matched pair**, same load both arms (6 `http` targets, 60 events at 5/s, sinks holding each POST 1.5 s so deliveries are in flight), one arm with a concurrent `sqlite3 <db> .dump` loop: | | before, reader | before, no reader | after, reader | after, no reader | | --- | --- | --- | --- | --- | | inbound HTTP 500s | 38 / 60 | 0 | **0** | **0** | | engine write errors | 260 | 0 | **0** | **0** | | new requests from restart | 112 | 160 | **0** | **0** | | duplicate payloads at sinks | 112 | 10 | **0** | **0** | | `delivery_results` rows | 132 for 244 POSTs | — | 360 for 360 POSTs | 360 for 360 POSTs | Sink counts are by payload at the receiver, not from the database. The before/no-reader arm's 160 is my harness not draining before the restart rather than the defect; both after arms drain and add nothing. Pragmas confirmed by querying live handles, not the DSN: `journal_mode` = `wal`, `busy_timeout` = `10000` on both a running per-webhook database and the main database (`TestPerWebhookDBAppliesPragmasOnALiveHandle`, `TestMainDBAppliesPragmasOnALiveHandle`). `make check` green with `GOFLAGS=-count=1`, lint in the digest-pinned container, re-run after rebasing onto current `next`. Both documented backup procedures re-verified under WAL. `.backup` and stop-copy-start still work unchanged; the restore instructions were inverted and are corrected — after a crash the `.db` alone read 40 rows where `.db` plus `-wal` read 50, so a `-wal` in a salvaged copy must be carried, not dropped. Two answers worth stating here. Send-succeeded-but-write-failed leaves the delivery in whichever non-terminal status it already holds and writes nothing, because the failure path must not depend on the database that just refused a write; the sweeps then recover it, and a delivery whose result row *did* land is settled to `delivered` rather than re-sent. And re-dispatch is claimed by compare-and-set, otherwise every 60-second sweep would send the same still-running delivery again. One unrelated defect found while auditing the transaction paths, filed rather than fixed here: https://git.eeqj.de/sneak/webhooker/issues/262.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
merge-ready
needs-checks
needs-rebase
needs-review
needs-rework
No Label
Milestone
No items
No Milestone 1.0.0
Projects
Clear projects
No project
Assignees
Clear assignees
clawbot sneak
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#256
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?