3 Commits

Author SHA1 Message Date
clawbot
9a70afb8b7 Make SQLite durable under concurrent readers and stop re-delivering stranded webhooks (closes #256)
All checks were successful
check / check (push) Successful in 3m3s
An operator running `sqlite3 <db> .dump` against their own per-webhook
database wedged it: inbound webhooks rejected with HTTP 500, delivered
webhooks stranded at `pending`, and every one of them POSTed a second
time on the next restart while the event log recorded a single attempt.

Durability. Every SQLite file — main, per-webhook, and archive — now
opens through one path, `internal/database/sqlite_open.go`, in WAL
journal mode with a 10-second busy timeout, `BEGIN IMMEDIATE`
transactions, and a bounded connection pool. WAL is what stops a reader
blocking writers at all. `_txlock=immediate` is what stops a `COMMIT`
failing while its transaction stays open on a pooled connection, which
is how four `database is locked` errors became 593 `cannot start a
transaction within a transaction`. `cache=shared` is gone, because
under it an in-process conflict is SQLITE_LOCKED, which the busy
handler does not retry. The busy timeout is applied before
journal_mode: the driver runs DSN pragmas in order on every new
connection, and `PRAGMA journal_mode` takes a lock, so the reverse
order leaves the one pragma that can block uncovered by the handler
meant to cover it.

Eligibility. `internal/delivery/inflight.go` holds the set of
deliveries the engine owns — taken when a task is queued, when a
target schedules a retry, and by every recovery path before it
re-dispatches; dropped when the worker that ran the task returns.
Recovery and both sweep arms re-dispatch only what the set does not
hold. Nothing decides that from a row's age: a delivery waiting in a
10000-deep channel is arbitrarily old and perfectly healthy, and
reasoning from age re-sends it. `takeForRedispatch` is the single gate
every re-dispatch goes through — ownership first, then a conditional
update confirming the row is still in the status the batch read.

Bookkeeping. `recordResult` and `updateDeliveryStatus` return their
errors instead of logging and dropping them, and a caller whose
bookkeeping write failed writes nothing at all: the delivery keeps
whichever non-terminal status it already held, and the sweeps recover
it. Every recovery path — pending and retrying alike — first settles
any delivery that already holds a successful `DeliveryResult` rather
than sending it again. Recovery continues each delivery's own attempt
numbering instead of restarting at 1. The sweep gains a
`pending`-with-age-bound arm, so a stranded delivery no longer waits
for a restart.

Docs. WAL produces `-wal`/`-shm` sidecars, so the backup and restore
procedures in README.md are corrected against measurement: both
documented procedures were re-run against a live instance, a `-wal`
left by a crash carries data the `.db` alone does not, and an archive
file normally holds its rows in a `-wal` rather than in the `.db`.
2026-08-24 01:02:01 +00:00
032f265d69 Derive cookie Secure and CSRF strictness from the request transport (closes #269)
All checks were successful
check / check (push) Successful in 2m56s
2026-08-24 03:01:37 +02:00
65ace2d856 Roll back a failed webhook deletion instead of committing it (closes #262)
Some checks failed
check / check (push) Superseded by a newer commit; never tested
2026-08-24 03:01:33 +02:00
32 changed files with 3202 additions and 279 deletions

175
README.md
View File

@@ -74,27 +74,41 @@ you can place variables in a `.env` file in the project root (loaded
automatically via `godotenv/autoload`). automatically via `godotenv/autoload`).
The environment is selected by setting `WEBHOOKER_ENVIRONMENT` to `dev` The environment is selected by setting `WEBHOOKER_ENVIRONMENT` to `dev`
or `prod` (default: `dev`). The setting controls several behaviors: or `prod` (default: `dev`). The setting controls exactly one behavior:
| Behavior | `dev` | `prod` | | Behavior | `dev` | `prod` |
| --------------------- | -------------------------------- | ------------------------------- | | -------- | ----------------------- | ---------------- |
| CORS | Allows any origin (`*`) | Disabled (no-op) | | CORS | Allows any origin (`*`) | Disabled (no-op) |
| Session cookie Secure | `false` (works over plain HTTP) | `true` (requires HTTPS) |
The CSRF cookie's `Secure` flag and Origin/Referer validation mode are The environment setting does **not** control cookie security. Both the
determined per-request based on the actual transport protocol, not the session cookie and the CSRF cookie get their `Secure` flag, and the
environment setting. The middleware checks `r.TLS` (direct TLS) and the CSRF middleware its Origin/Referer validation mode, from the transport
`X-Forwarded-Proto` header (TLS-terminating reverse proxy) to decide: of each individual request, decided by one predicate —
`internal/reqtls.IsTLS`. It reports TLS for a direct TLS connection
(`r.TLS`) or for a TLS-terminating reverse proxy that reports one in
`X-Forwarded-Proto`:
- **Direct TLS or `X-Forwarded-Proto: https`**: Secure cookies, strict - **Direct TLS or `X-Forwarded-Proto: https`**: Secure cookies, strict
Origin/Referer validation. Origin/Referer validation.
- **Plaintext HTTP**: Non-Secure cookies, relaxed Origin/Referer - **Plaintext HTTP**: Non-Secure cookies, relaxed Origin/Referer
checks (token validation still enforced). checks (token validation still enforced).
This means CSRF protection works correctly in all deployment scenarios: The `X-Forwarded-Proto` value is matched case-insensitively on its
behind a TLS-terminating reverse proxy, with direct TLS, or over plain first comma-separated element, trimmed, so `HTTPS` and the appended
HTTP during development. When running behind a reverse proxy, ensure it chains a proxy behind another proxy emits (`https, http`) are all read
sets the `X-Forwarded-Proto: https` header. as TLS.
This means both cookie security and CSRF protection work correctly in
all deployment scenarios: behind a TLS-terminating reverse proxy, with
direct TLS, or over plain HTTP during development — a plain-HTTP local
run gets non-`Secure` cookies and remains usable, and a proxied
deployment gets `Secure` ones without the operator setting anything.
When running behind a reverse proxy, ensure it sets the
`X-Forwarded-Proto: https` header. Unlike `X-Forwarded-For`, this
header is read from any peer and is **not** gated by
`TRUSTED_PROXIES`; a correctly configured proxy overwrites whatever a
client sent. On a listener exposed directly to clients, any client can
assert it, so do not run one without a proxy in front.
All other differences (log format, security headers, etc.) are All other differences (log format, security headers, etc.) are
independent of the environment setting — log format is determined by independent of the environment setting — log format is determined by
@@ -566,9 +580,25 @@ is both the simplest and the only complete rule:
`events-3f2a1c9e-....db`. The only other file is `webhooker.lock`, the `events-3f2a1c9e-....db`. The only other file is `webhooker.lock`, the
always-empty [single-instance lock](#single-instance-lock); it holds no always-empty [single-instance lock](#single-instance-lock); it holds no
state and is not part of the backup set — a copied one is stale and state and is not part of the backup set — a copied one is stale and
blocks nothing. No `-wal` or `-shm` files are produced (see below); a blocks nothing.
transient `{name}.db-journal` may exist beside a database while a write
is in flight and is not part of the backup set either. **`-wal` and `-shm` sidecars.** Every database runs in WAL journal mode,
so while the service is running each `{name}.db` has a `{name}.db-wal`
and a `{name}.db-shm` beside it. **`-wal` is part of the database, not a
scratch file**: it holds committed transactions that are not yet in the
`.db`, so a copy of the `.db` without its `-wal` is missing data and may
have no readable schema at all. `-shm` is regenerable, but there is no
reason to separate the two — copy the directory and you have them.
A clean shutdown closes `webhooker.db` and every `events-*.db`, which
checkpoints and removes their sidecars; a killed or crashed instance
leaves them, and they must be carried with the `.db`. **Archive
databases are different**: their handle is not closed at shutdown, so
`archive-*.db-wal` and `-shm` normally survive a clean stop and the
`-wal` can hold every row the archive has. Measured on a stopped
instance: `archive-….db` 4096 bytes with no table, its `-wal` 157 KB
holding all 8 archived events. Copying `DATA_DIR` in full is what makes
this a non-issue; copying `.db` files out of it by name is not.
Configuration is **not** in `DATA_DIR` — it comes from the environment Configuration is **not** in `DATA_DIR` — it comes from the environment
and from a `.env` file read out of the process working directory. Back and from a `.env` file read out of the process working directory. Back
@@ -576,17 +606,19 @@ that up with your deployment config, separately.
### A hot copy is not safe ### A hot copy is not safe
No `journal_mode` pragma is ever issued on any database webhooker opens, Every database webhooker opens runs in WAL journal mode. The main and
so all of them run on SQLite's default rollback journal. There is no event databases are also held open for the entire process lifetime —
WAL. The main and event databases are also held open for the entire `WebhookDBManager` caches event database handles and closes them only on
process lifetime — `WebhookDBManager` caches event database handles and webhook deletion or shutdown — so "it looked idle" is not a guarantee
closes them only on webhook deletion or shutdown — so "it looked idle" that nothing was mid-transaction.
is not a guarantee that nothing was mid-transaction.
That means `cp`, `rsync`, `tar` or a filesystem snapshot taken against a That means `cp`, `rsync`, `tar` or a filesystem snapshot taken against a
running instance can capture a database mid-transaction and yield a file running instance can capture a database and its `-wal` at two different
that is corrupt or missing state the journal would have rolled back. Use instants and yield a file that is corrupt or missing state. Copying a
one of the two procedures below instead. `.db` on its own is worse and fails loudly: recently written pages,
including the schema itself on a young database, live in the `-wal`, so
the copy reads back as an empty or table-less database. Use one of the
two procedures below instead.
**Stop, copy, start.** The simplest, needs no extra tooling, and the **Stop, copy, start.** The simplest, needs no extra tooling, and the
only one that gives a single point in time across every file: only one that gives a single point in time across every file:
@@ -605,8 +637,9 @@ for db in /path/to/data/*.db; do
done done
``` ```
`.backup` takes the proper locks and writes a consistent file. Two `.backup` reads through the WAL and writes a single consistent file with
caveats. First, the runtime image is `alpine:3.21` with only no sidecars of its own, so the destination is complete as it stands.
Two caveats. First, the runtime image is `alpine:3.21` with only
`ca-certificates` added — the `sqlite3` CLI is **not** in it, so run `ca-certificates` added — the `sqlite3` CLI is **not** in it, so run
this on the host against the volume path, or from a throwaway container this on the host against the volume path, or from a throwaway container
that mounts the volume. Second, each file is captured at its own that mounts the volume. Second, each file is captured at its own
@@ -614,15 +647,37 @@ instant, so a webhook created or an event delivered between two files
being copied lands in one and not the other. If you need the whole set being copied lands in one and not the other. If you need the whole set
coherent as of a single moment, stop the service. coherent as of a single moment, stop the service.
Note that `sqlite3 <db> .dump` is **not** one of these procedures: it is
an export, it holds a read transaction open for as long as it runs, and
it pins the WAL against checkpointing for that whole time. It is safe to
run — it does not block ingestion — but back up with `.backup` or a
stopped copy.
Archive databases are the one exception the service is built for: the Archive databases are the one exception the service is built for: the
archive writer closes its handle after each write (debounced to at most archive writer closes and reopens its handle around writes (debounced
one reopen per second), so an operator can move `archive-{uuid}.db` to at most one reopen per second), so an operator can move
away for offline retention while the service runs, and it is recreated `archive-{uuid}.db` away for offline retention while the service runs,
on the next write (see and it is recreated on the next write. See
[Database Architecture](#database-architecture)). That is a [Database Architecture](#database-architecture). That is a
move-the-file-away workflow, not a substitute for the backup procedures move-the-file-away workflow, not a substitute for the backup procedures
above. above.
**Move the sidecars with it.** Under WAL that workflow is no longer a
single file, and the common case is the dangerous one. The reopen
happens on the *next* write after the debounce window elapses, so after
the last write of a burst nothing checkpoints: measured, 20 s after ten
events the `archive-….db` was 4096 bytes — a header, no table — with
all ten rows sitting in a 189 KB `-wal`. Copying the `.db` alone at that
moment yields a file that opens with `no such table: archived_events`.
The file becomes self-contained again when the handle closes, which
happens on the next write past the debounce window, when the connection
pool retires the idle connection (about a minute after the last write),
or at the idle archive sweep — measured, the same file was a complete
20 KB `.db` with no sidecars about a minute after its last write.
Shutdown is **not** on that list: the archive handle is not closed when
the service stops. So either move `archive-{uuid}.db` together with any
`-wal`/`-shm` beside it, or wait until there are none.
### Restore ### Restore
1. Stop the service. 1. Stop the service.
@@ -636,14 +691,22 @@ above.
restored without `webhooker.db` are simply orphaned; nothing restored without `webhooker.db` are simply orphaned; nothing
references their UUIDs. references their UUIDs.
3. Do not carry `*.db-journal` files into the restore. Backups taken by 3. Carry any `*.db-wal` and `*.db-shm` files that are in the backup.
either procedure above are self-consistent and do not need one. They are part of the database, and dropping a `-wal` silently
discards every transaction it still holds. An `.backup` set will not
contain any: it writes a single consolidated file per database. A
stop-and-copy set has none for `webhooker.db` or the `events-*.db`,
because a clean stop closes those and checkpoints their sidecars
away — but it will normally have them for `archive-*.db`, whose
handle stays open across shutdown, and those carry the archive's
rows. A copy salvaged from a crashed instance has them for
everything, and needs all of them.
4. **Fix ownership.** The container runs as the non-root `webhooker` 4. **Fix ownership.** The container runs as the non-root `webhooker`
user, UID 1000 / GID 1000. Restored files must be owned by (or user, UID 1000 / GID 1000. Restored files must be owned by (or
writable by) that UID, and so must the directory itself — SQLite writable by) that UID, and so must the directory itself — SQLite
creates the rollback journal beside the database, so a writable file creates the `-wal` and `-shm` sidecars beside the database, so a
inside a directory it cannot write is not enough: writable file inside a directory it cannot write is not enough:
```bash ```bash
chown -R 1000:1000 /path/to/data chown -R 1000:1000 /path/to/data
@@ -1391,10 +1454,12 @@ This separation provides:
only, or disables cleanup entirely when set to `0` (retain forever). only, or disables cleanup entirely when set to `0` (retain forever).
- **Performance** — each webhook's database has its own page cache and - **Performance** — each webhook's database has its own page cache and
its own lock, so concurrent event ingestion across webhooks won't its own lock, so concurrent event ingestion across webhooks won't
contend. No write-ahead log is involved: both DSNs are contend. Every database — main, per-webhook, and archive — is opened
`file:{path}?cache=shared&mode=rwc` and no `journal_mode` pragma is through one code path (`internal/database/sqlite_open.go`) in WAL
ever issued, so every database runs on SQLite's default rollback journal mode, with a 10-second busy timeout, `BEGIN IMMEDIATE`
journal. transactions, and a bounded connection pool. Under WAL a reader never
blocks a writer, so an operator reading a database does not stall
event ingestion into it.
The **database target type** builds on this architecture to provide The **database target type** builds on this architecture to provide
long-term archiving, separate from the per-webhook event database (which long-term archiving, separate from the per-webhook event database (which
@@ -1853,13 +1918,16 @@ the rest. Nothing dropped is needed for the likeliest use, debugging a
CSRF rejection. Its three inputs are the TLS decision, `Origin` and CSRF rejection. Its three inputs are the TLS decision, `Origin` and
`Referer`; the latter two are kept, and the first is the scheme of the `Referer`; the latter two are kept, and the first is the scheme of the
retained URL, because the SDK derives that scheme from retained URL, because the SDK derives that scheme from
`r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` — byte `r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"`. That
for byte the predicate `internal/middleware/csrf.go` uses to choose predicate is the SDK's own and is stricter than `internal/reqtls.IsTLS`,
between the `csrf.Secure(true)` and `csrf.Secure(false)` handlers. which this service now uses everywhere it decides transport: the SDK
That is what the rewrite above preserves it for, and it is why reports `http` for the `HTTPS` and `https, http` spellings `reqtls`
dropping `X-Forwarded-Proto` costs nothing. The dropped provider accepts. Only a reported scheme is affected, no decision is, so it is
headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are real left to the SDK rather than reimplemented. That is what the rewrite
signal but are recorded locally on the event, and above preserves it for, and it is why dropping `X-Forwarded-Proto`
costs nothing. The dropped provider headers (`X-GitHub-Event`,
`X-Gitlab-Event` and the like) are real signal but are recorded
locally on the event, and
`Sentry-Trace`/`Baggage` are already reflected in the event's trace `Sentry-Trace`/`Baggage` are already reflected in the event's trace
context. context.
@@ -2515,8 +2583,9 @@ check, see [The login endpoint](#the-login-endpoint).
- **Web UI:** Cookie-based sessions using gorilla/sessions with - **Web UI:** Cookie-based sessions using gorilla/sessions with
encrypted cookies. Sessions are configured with HttpOnly, SameSite encrypted cookies. Sessions are configured with HttpOnly, SameSite
Lax, and Secure (in production). Absolute session lifetime is 7 days, Lax, and Secure whenever the request is on TLS — the flag follows the
with a sliding idle timeout on top of it (see request's transport, not the environment. Absolute session lifetime
is 7 days, with a sliding idle timeout on top of it (see
[Sessions](#sessions)). [Sessions](#sessions)).
- **API (planned):** API key authentication via `Authorization: Bearer` - **API (planned):** API key authentication via `Authorization: Bearer`
header. API keys are stored per-user with usage tracking header. API keys are stored per-user with usage tracking
@@ -2529,7 +2598,10 @@ check, see [The login endpoint](#the-login-endpoint).
### Security ### Security
- Passwords hashed with Argon2id (64 MB memory cost) - Passwords hashed with Argon2id (64 MB memory cost)
- Session cookies are HttpOnly, SameSite Lax, Secure (prod only) - Session cookies are HttpOnly, SameSite Lax, and Secure on any request
that arrived over TLS (directly or through a reverse proxy reporting
it), decided per-request by `internal/reqtls.IsTLS` rather than by the
configured environment
- Session regeneration on login to prevent session fixation attacks - Session regeneration on login to prevent session fixation attacks
- Session key is a 32-byte value auto-generated on first startup and - Session key is a 32-byte value auto-generated on first startup and
stored in the database stored in the database
@@ -2542,9 +2614,10 @@ check, see [The login endpoint](#the-login-endpoint).
on all state-changing forms (cookie-based double-submit tokens with on all state-changing forms (cookie-based double-submit tokens with
HMAC authentication). Applied to `/pages`, `/sources`, `/source`, and HMAC authentication). Applied to `/pages`, `/sources`, `/source`, and
`/user` routes. Excluded from `/webhook` (inbound webhook POSTs) and `/user` routes. Excluded from `/webhook` (inbound webhook POSTs) and
`/api` (stateless API). The middleware auto-detects TLS status `/api` (stateless API). The middleware detects TLS per-request through
per-request (via `r.TLS` and `X-Forwarded-Proto`) to set appropriate `internal/reqtls.IsTLS` — the same predicate the session cookie uses —
cookie security flags and Origin/Referer validation mode to set appropriate cookie security flags and Origin/Referer validation
mode
- **Optional inbound signature verification** per entrypoint (GitHub - **Optional inbound signature verification** per entrypoint (GitHub
`X-Hub-Signature-256`, GitLab `X-Gitlab-Token`). Off by default and `X-Hub-Signature-256`, GitLab `X-Gitlab-Token`). Off by default and
off after an upgrade, so behaviour is unchanged until an operator off after an upgrade, so behaviour is unchanged until an operator

View File

@@ -4,7 +4,6 @@ package database
import ( import (
"context" "context"
"crypto/rand" "crypto/rand"
"database/sql"
"encoding/base64" "encoding/base64"
"errors" "errors"
"fmt" "fmt"
@@ -16,7 +15,6 @@ import (
"go.uber.org/fx" "go.uber.org/fx"
"gorm.io/driver/sqlite" "gorm.io/driver/sqlite"
"gorm.io/gorm" "gorm.io/gorm"
_ "modernc.org/sqlite" // Pure Go SQLite driver
"sneak.berlin/go/webhooker/internal/banner" "sneak.berlin/go/webhooker/internal/banner"
"sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/gormlog" "sneak.berlin/go/webhooker/internal/gormlog"
@@ -198,13 +196,11 @@ func (d *Database) connectTo(dataDir string) error {
// Construct the main application database path inside DATA_DIR. // Construct the main application database path inside DATA_DIR.
dbPath := filepath.Join(dataDir, MainDBFileName) dbPath := filepath.Join(dataDir, MainDBFileName)
dbURL := fmt.Sprintf(
"file:%s?cache=shared&mode=rwc",
dbPath,
)
// Open the database with the pure Go SQLite driver // Opened through OpenSQLite so this handle carries the same WAL
sqlDB, err := sql.Open("sqlite", dbURL) // journaling, busy timeout, immediate-transaction locking, and pool
// bounds as every other database file. See sqlite_open.go.
sqlDB, err := OpenSQLite(dbPath, SQLiteModeCreate)
if err != nil { if err != nil {
d.log.Error( d.log.Error(
"failed to open database", "failed to open database",

View File

@@ -0,0 +1,157 @@
package database
import (
"database/sql"
"fmt"
"net/url"
"time"
_ "modernc.org/sqlite" // Pure Go SQLite driver
)
// Every SQLite file this service opens — the main database, the
// per-webhook event databases, and the archive databases — is opened
// through OpenSQLite, so the durability settings below are properties
// of the service rather than of one call site.
//
// modernc.org/sqlite installs no busy handler and issues no pragmas of
// its own: it executes only the pragmas named in explicit `_pragma=`
// DSN parameters, and gorm.io/driver/sqlite adds none when it is
// handed an existing *sql.DB. Every setting therefore has to be
// spelled out here or it is simply not in effect.
// SQLite URI open modes.
const (
// SQLiteModeCreate creates the database file when it is missing.
SQLiteModeCreate = "rwc"
// SQLiteModeExisting requires the file to exist already.
SQLiteModeExisting = "rw"
)
const (
// SQLiteBusyTimeout is how long SQLite retries a lock conflict
// before returning SQLITE_BUSY.
//
// Under WAL a reader never blocks a writer, so the only conflict
// left is writer against writer: this process's delivery workers
// against each other, or against another process holding the write
// lock. Those clear in milliseconds. Ten seconds is far above that
// and still well inside the receiver's request budget, so an
// inbound webhook waits rather than being rejected with a 500.
SQLiteBusyTimeout = 10 * time.Second
// sqliteMaxOpenConns bounds the connection pool for one database
// file.
//
// The pool needs a bound at all because database/sql cannot detect
// a connection left mid-transaction: modernc.org/sqlite implements
// neither driver.Validator nor driver.SessionResetter, so a
// connection whose COMMIT failed is returned to the pool with its
// transaction still open and handed out again indefinitely. That is
// what turned four `database is locked` errors into 593
// `cannot start a transaction within a transaction` in
// https://git.eeqj.de/sneak/webhooker/issues/256.
//
// Four is above the one writer SQLite allows at a time, so reads
// still proceed while a write is in flight, and low enough that
// contention is resolved by the busy handler rather than by piling
// up connections against a lock only one of them can hold.
sqliteMaxOpenConns = 4
// sqliteMaxIdleConns keeps the pool warm without holding every
// connection open through an idle period.
sqliteMaxIdleConns = 2
// sqliteConnMaxLifetime and sqliteConnMaxIdleTime retire pooled
// connections on a schedule. With _txlock=immediate a failed
// COMMIT should no longer be reachable, but these bound the damage
// if one happens anyway: a poisoned connection is closed and
// replaced within the lifetime instead of wedging the file until
// the process restarts.
sqliteConnMaxLifetime = 5 * time.Minute
sqliteConnMaxIdleTime = time.Minute
)
// SQLiteDSN builds the connection string for one database file.
//
// mode is the SQLite URI open mode: "rwc" to create the file when it
// is missing, "rw" to require that it already exists.
//
// Three settings carry the fix for
// https://git.eeqj.de/sneak/webhooker/issues/256 and none of them is
// optional:
//
// - journal_mode=WAL, so a reader — an operator running
// `sqlite3 <db> .dump` over their own data — takes a snapshot
// instead of blocking every writer behind it.
//
// - busy_timeout, so a writer that does meet a lock waits for it.
// Without one SQLite gives up immediately; nothing above it
// retries.
//
// - _txlock=immediate, so every transaction takes the write lock at
// BEGIN. A deferred transaction acquires it lazily on its first
// write, and that upgrade returns SQLITE_BUSY *without* consulting
// the busy handler, because SQLite cannot block a transaction that
// may already hold a read snapshot. Such a COMMIT then fails while
// the transaction stays open on the connection. A busy timeout
// alone does not prevent this; BEGIN IMMEDIATE does, by putting
// the wait somewhere the handler applies.
//
// Note what is absent: `cache=shared`. Under a shared cache an
// in-process conflict is reported as SQLITE_LOCKED rather than
// SQLITE_BUSY, and the busy handler does not retry SQLITE_LOCKED — so
// leaving it in would have defeated the busy timeout for exactly the
// contention this service generates. Dropping it is part of the fix,
// not housekeeping.
//
// synchronous is deliberately left at SQLite's default of FULL: this
// is a webhook receiver whose one promise is that an event it answered
// 200 for is durable.
// The order of the _pragma parameters is load-bearing.
// modernc.org/sqlite executes them in the order they appear, on every
// new connection, before the connection is handed to the pool. Setting
// journal_mode first means that pragma itself runs with no busy
// handler installed: the pool opens connections lazily, so the moment
// a new one is created is a moment the database is under load, and
// PRAGMA journal_mode takes a lock. It would fail immediately with
// SQLITE_BUSY and fail the query that caused the connection to be
// opened. busy_timeout is therefore set first, so every pragma after
// it — and the whole life of the connection — is covered.
func SQLiteDSN(path, mode string) string {
q := url.Values{}
q.Set("mode", mode)
q.Set("_txlock", "immediate")
q.Add(
"_pragma",
fmt.Sprintf(
"busy_timeout(%d)",
SQLiteBusyTimeout.Milliseconds(),
),
)
q.Add("_pragma", "journal_mode(WAL)")
return "file:" + path + "?" + q.Encode()
}
// OpenSQLite opens the SQLite file at path with the service's
// durability settings and pool bounds applied. mode is the SQLite URI
// open mode ("rwc" or "rw").
//
// The handle is returned rather than a *gorm.DB because the callers
// wrap it in gorm themselves with their own logger.
func OpenSQLite(path, mode string) (*sql.DB, error) {
sqlDB, err := sql.Open("sqlite", SQLiteDSN(path, mode))
if err != nil {
return nil, fmt.Errorf(
"opening sqlite database %s: %w", path, err,
)
}
sqlDB.SetMaxOpenConns(sqliteMaxOpenConns)
sqlDB.SetMaxIdleConns(sqliteMaxIdleConns)
sqlDB.SetConnMaxLifetime(sqliteConnMaxLifetime)
sqlDB.SetConnMaxIdleTime(sqliteConnMaxIdleTime)
return sqlDB, nil
}

View File

@@ -0,0 +1,178 @@
package database_test
import (
"context"
"path/filepath"
"strings"
"testing"
"github.com/google/uuid"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/database"
)
// livePragma reads a pragma off a live handle. Reading the DSN back
// would prove only that the string was built; these tests assert that
// SQLite actually applied it.
func livePragma(t *testing.T, db *gorm.DB, name string) string {
t.Helper()
var v string
row := db.Raw("pragma " + name).Row()
require.NoError(t, row.Scan(&v))
return v
}
func TestSQLiteDSNCarriesTheDurabilitySettings(t *testing.T) {
t.Parallel()
dsn := database.SQLiteDSN(
"/var/lib/webhooker/webhooker.db",
database.SQLiteModeCreate,
)
assert.Contains(t, dsn, "journal_mode%28WAL%29")
assert.Contains(t, dsn, "busy_timeout%2810000%29")
assert.Contains(t, dsn, "_txlock=immediate")
assert.Contains(t, dsn, "mode=rwc")
// busy_timeout must come first. The driver runs these in order on
// every new connection, and PRAGMA journal_mode takes a lock — a
// connection opened while the database is busy would fail on that
// pragma, with no busy handler yet installed to wait it out.
assert.Less(
t,
strings.Index(dsn, "busy_timeout"),
strings.Index(dsn, "journal_mode"),
"busy_timeout must be applied before journal_mode",
)
// cache=shared turns an in-process conflict into SQLITE_LOCKED,
// which the busy handler does not retry. It must never come back.
// See https://git.eeqj.de/sneak/webhooker/issues/256.
assert.NotContains(t, strings.ToLower(dsn), "cache=shared")
}
// TestPerWebhookDBAppliesPragmasOnALiveHandle is the check the issue
// asks for by name: the settings are confirmed by querying the running
// database, not by inspecting the connection string.
func TestPerWebhookDBAppliesPragmasOnALiveHandle(t *testing.T) {
t.Parallel()
mgr, lc := setupTestWebhookDBManager(t)
ctx := context.Background()
require.NoError(t, lc.Start(ctx))
defer func() { require.NoError(t, lc.Stop(ctx)) }()
webhookID := uuid.New().String()
db, err := mgr.GetDB(webhookID)
require.NoError(t, err)
assert.Equal(
t, "wal",
strings.ToLower(livePragma(t, db, "journal_mode")),
)
assert.Equal(
t, "10000", livePragma(t, db, "busy_timeout"),
)
}
func TestMainDBAppliesPragmasOnALiveHandle(t *testing.T) {
t.Parallel()
ctx := context.Background()
dir := t.TempDir()
sqlDB, err := database.OpenSQLite(
filepath.Join(dir, database.MainDBFileName),
database.SQLiteModeCreate,
)
require.NoError(t, err)
defer func() { require.NoError(t, sqlDB.Close()) }()
var journal string
require.NoError(t, sqlDB.
QueryRowContext(ctx, "pragma journal_mode").
Scan(&journal))
assert.Equal(t, "wal", strings.ToLower(journal))
var busy string
require.NoError(t, sqlDB.
QueryRowContext(ctx, "pragma busy_timeout").
Scan(&busy))
assert.Equal(t, "10000", busy)
}
// TestConcurrentReaderDoesNotBlockWrites is the unit-scale form of the
// reproduction in
// https://git.eeqj.de/sneak/webhooker/issues/256: an operator's
// long-held read of their own data used to make every concurrent write
// fail. Under WAL the reader takes a snapshot and the writes proceed.
func TestConcurrentReaderDoesNotBlockWrites(t *testing.T) {
t.Parallel()
mgr, lc := setupTestWebhookDBManager(t)
ctx := context.Background()
require.NoError(t, lc.Start(ctx))
defer func() { require.NoError(t, lc.Stop(ctx)) }()
webhookID := uuid.New().String()
db, err := mgr.GetDB(webhookID)
require.NoError(t, err)
// A second handle on the same file, holding a read transaction
// open across every write below — what `sqlite3 <db> .dump` is.
readerSQL, err := database.OpenSQLite(
mgr.DBPath(webhookID), database.SQLiteModeExisting,
)
require.NoError(t, err)
defer func() { require.NoError(t, readerSQL.Close()) }()
readerConn, err := readerSQL.Conn(ctx)
require.NoError(t, err)
defer func() { require.NoError(t, readerConn.Close()) }()
_, err = readerConn.ExecContext(ctx, "begin deferred")
require.NoError(t, err)
_, err = readerConn.ExecContext(
ctx, "select count(*) from events",
)
require.NoError(t, err)
for range 25 {
err = db.Transaction(func(tx *gorm.DB) error {
return tx.Create(&database.Event{
WebhookID: webhookID,
EntrypointID: uuid.New().String(),
Method: "POST",
Body: "{}",
}).Error
})
require.NoError(t, err)
}
_, err = readerConn.ExecContext(ctx, "commit")
require.NoError(t, err)
var count int64
require.NoError(
t,
db.Model(&database.Event{}).Count(&count).Error,
)
assert.Equal(t, int64(25), count)
}

View File

@@ -2,7 +2,6 @@ package database
import ( import (
"context" "context"
"database/sql"
"errors" "errors"
"fmt" "fmt"
"log/slog" "log/slog"
@@ -234,12 +233,11 @@ func (m *WebhookDBManager) openDB(
webhookID string, webhookID string,
) (*gorm.DB, error) { ) (*gorm.DB, error) {
path := m.dbPath(webhookID) path := m.dbPath(webhookID)
dbURL := fmt.Sprintf(
"file:%s?cache=shared&mode=rwc",
path,
)
sqlDB, err := sql.Open("sqlite", dbURL) // See sqlite_open.go: WAL, a busy timeout, immediate-transaction
// locking, and a bounded pool, all of which this file needs most —
// it is the one every delivery worker writes to concurrently.
sqlDB, err := OpenSQLite(path, SQLiteModeCreate)
if err != nil { if err != nil {
return nil, fmt.Errorf( return nil, fmt.Errorf(
"opening webhook database %s: %w", "opening webhook database %s: %w",

View File

@@ -41,6 +41,31 @@ const (
// sweep runs. // sweep runs.
retrySweepInterval = 60 * time.Second retrySweepInterval = 60 * time.Second
// pendingSweepMinAge is how long a delivery must have sat
// untouched at pending before the sweep will look at it.
//
// It is not what keeps the sweep off live work — inflightSet is,
// and it is exact. This bound sets the re-dispatch cadence for a
// delivery that really is stranded: without it, a delivery the
// database will not let the engine settle would be re-sent on
// every 60-second tick.
//
// It is nonetheless set clear of the longest legitimate attempt,
// so that the two guards do not both have to be right. That
// length is MaxTargetTimeoutSeconds (300s), the per-target
// timeout the target form accepts — not httpClientTimeout, which
// is merely the default. Fifteen minutes leaves a margin of
// three times the ceiling rather than the zero margin the two
// equal values would have given.
pendingSweepMinAge = 15 * time.Minute
// pendingSweepBatch bounds how many stranded pending deliveries
// one sweep of one webhook re-dispatches. The sweep runs every
// retrySweepInterval, so a larger backlog drains across
// successive sweeps instead of arriving as one burst against a
// database that was already struggling to accept writes.
pendingSweepBatch = 500
// MaxInlineBodySize is the maximum event body size that // MaxInlineBodySize is the maximum event body size that
// will be carried inline in a Task through the channel. // will be carried inline in a Task through the channel.
// Bodies at or above this size are left nil and fetched // Bodies at or above this size are left nil and fetched
@@ -157,6 +182,12 @@ type Engine struct {
// dbTarget is retained so the engine can reach the archive // dbTarget is retained so the engine can reach the archive
// writer registry for webhook eviction and the idle sweep. // writer registry for webhook eviction and the idle sweep.
dbTarget *databaseTarget dbTarget *databaseTarget
// inflight is the set of deliveries this engine currently owns.
// Recovery and the sweeps re-dispatch only what it does not
// hold. Held by value: its zero value works, so no constructor
// can leave it out. See inflight.go.
inflight inflightSet
} }
// New creates and registers the delivery engine with the // New creates and registers the delivery engine with the
@@ -189,12 +220,27 @@ func New(
// are ready. // are ready.
func (e *Engine) Notify(tasks []Task) { func (e *Engine) Notify(tasks []Task) {
for i := range tasks { for i := range tasks {
// Owned before it is queued, and until the worker that runs
// it returns. A task can sit in a 10000-deep channel for a
// long time on a healthy system, and nothing may re-send it
// while it waits. See inflight.go.
if !e.inflight.retainIdle(tasks[i].DeliveryID) {
e.log.Warn(
"delivery already in flight, not queued again",
"delivery_id", tasks[i].DeliveryID,
"event_id", tasks[i].EventID,
)
continue
}
select { select {
case e.deliveryCh <- tasks[i]: case e.deliveryCh <- tasks[i]:
default: default:
e.inflight.release(tasks[i].DeliveryID)
e.log.Warn( e.log.Warn(
"delivery channel full, "+ "delivery channel full, "+
"task will be recovered on restart", "task will be recovered by the sweep",
"delivery_id", tasks[i].DeliveryID, "delivery_id", tasks[i].DeliveryID,
"event_id", tasks[i].EventID, "event_id", tasks[i].EventID,
) )
@@ -229,10 +275,20 @@ func (e *Engine) ScheduleRetry(
"next_attempt", task.AttemptNum, "next_attempt", task.AttemptNum,
) )
// The reference is taken here rather than when the timer fires,
// so the delivery stays owned across the whole backoff window.
// Its caller is a target inside Deliver, so the engine already
// owns it; this second reference is what keeps that ownership
// alive after the worker returns and the row sits at retrying
// with nothing running. Without it the sweep finds the row
// orphaned and sends it again.
e.inflight.retain(task.DeliveryID)
time.AfterFunc(delay, func() { time.AfterFunc(delay, func() {
select { select {
case e.retryCh <- task: case e.retryCh <- task:
default: default:
e.inflight.release(task.DeliveryID)
e.log.Warn( e.log.Warn(
"retry channel full, delivery "+ "retry channel full, delivery "+
"will be recovered by periodic sweep", "will be recovered by periodic sweep",
@@ -332,13 +388,35 @@ func (e *Engine) worker(ctx context.Context) {
case <-ctx.Done(): case <-ctx.Done():
return return
case task := <-e.deliveryCh: case task := <-e.deliveryCh:
e.processNewTask(ctx, &task) e.runTask(ctx, &task, e.processNewTask)
case task := <-e.retryCh: case task := <-e.retryCh:
e.processRetryTask(ctx, &task) e.runTask(ctx, &task, e.processRetryTask)
} }
} }
} }
// runTask runs one task and then drops the reference the queueing
// side took on its delivery.
//
// The release is deferred rather than written after the call because
// every early return inside the processing paths must drop it too: a
// delivery whose database could not be opened is one the engine has
// stopped working on, and leaving it owned would hide it from the
// sweep forever.
//
// Ownership does not necessarily end here. A target that scheduled a
// retry took its own reference before this one is dropped, so the
// delivery stays owned through the backoff window.
func (e *Engine) runTask(
ctx context.Context,
task *Task,
run func(context.Context, *Task),
) {
defer e.inflight.release(task.DeliveryID)
run(ctx, task)
}
func (e *Engine) recoverPending(ctx context.Context) { func (e *Engine) recoverPending(ctx context.Context) {
defer e.wg.Done() defer e.wg.Done()
@@ -526,7 +604,16 @@ func (e *Engine) recoverRetryingDeliveries(
return return
} }
settled := e.reconcileDelivered(
webhookDB, webhookID, retrying,
e.loadTargetMap(retrying),
)
for i := range retrying { for i := range retrying {
if _, ok := settled[retrying[i].ID]; ok {
continue
}
e.recoverSingleRetry( e.recoverSingleRetry(
webhookDB, webhookID, &retrying[i], webhookDB, webhookID, &retrying[i],
) )
@@ -588,6 +675,10 @@ func (e *Engine) recoverSingleRetry(
d, webhookID, &event, &target, attemptNum+1, d, webhookID, &event, &target, attemptNum+1,
) )
if !e.rescheduleRecovered(webhookDB, task, remaining) {
return
}
e.log.Info( e.log.Info(
"recovering retrying delivery", "recovering retrying delivery",
"webhook_id", webhookID, "webhook_id", webhookID,
@@ -595,8 +686,6 @@ func (e *Engine) recoverSingleRetry(
"attempt", attemptNum, "attempt", attemptNum,
"remaining_backoff", remaining, "remaining_backoff", remaining,
) )
e.ScheduleRetry(task, remaining)
} }
func (e *Engine) recoverPendingDeliveries( func (e *Engine) recoverPendingDeliveries(
@@ -606,12 +695,14 @@ func (e *Engine) recoverPendingDeliveries(
) { ) {
var deliveries []database.Delivery var deliveries []database.Delivery
// No Preload: event bodies are read one at a time in
// sendRecoveredDeliveries, and only for the deliveries actually
// being sent.
result := webhookDB. result := webhookDB.
Where( Where(
"status = ?", "status = ?",
database.DeliveryStatusPending, database.DeliveryStatusPending,
). ).
Preload("Event").
Find(&deliveries) Find(&deliveries)
if result.Error != nil { if result.Error != nil {
@@ -634,11 +725,137 @@ func (e *Engine) recoverPendingDeliveries(
"count", len(deliveries), "count", len(deliveries),
) )
e.recoverPendingBatch(
ctx, webhookDB, webhookID, deliveries,
)
}
// recoverPendingBatch settles every delivery in the batch that was
// already delivered, and re-dispatches only the rest. Both the
// restart-time recovery and the periodic sweep go through it, so a
// pending delivery is treated the same however it was found.
func (e *Engine) recoverPendingBatch(
ctx context.Context,
webhookDB *gorm.DB,
webhookID string,
deliveries []database.Delivery,
) {
targetMap := e.loadTargetMap(deliveries) targetMap := e.loadTargetMap(deliveries)
e.sendRecoveredDeliveries( settled := e.reconcileDelivered(
ctx, deliveries, webhookID, targetMap, webhookDB, webhookID, deliveries, targetMap,
) )
e.sendRecoveredDeliveries(
ctx, webhookDB, deliveries, webhookID,
targetMap, settled,
)
}
// reconcileDelivered finds the deliveries in a recovered batch that
// already have a successful DeliveryResult, marks them delivered, and
// returns their ids so the caller does not send them a second time.
//
// This is the state the engine previously had no way to represent. A
// delivery is left in a non-terminal state by a failed bookkeeping
// write, and that covers two different histories: nothing was ever
// sent, or the send reached the receiver and only the status write
// failed. Re-sending was the sole option, so every stranded row
// produced a duplicate at the receiver and an event log that recorded
// one attempt for two POSTs. A successful result row distinguishes
// them: it is written before the status, so its presence means the
// wire I/O happened and was recorded, and all that is missing is the
// status.
//
// Every recovery path runs this, not only the pending one. A delivery
// abandoned at retrying can hold a successful result just as a pending
// one can — a second attempt that reached the receiver and whose status
// write then failed sits at retrying with success recorded — and
// re-sending it is the same duplicate.
//
// Deliveries whose result row itself never landed are not in the
// returned set and are re-sent, recorded as the further attempt they
// are. That is honest at-least-once delivery rather than a silent
// duplicate.
func (e *Engine) reconcileDelivered(
webhookDB *gorm.DB,
webhookID string,
deliveries []database.Delivery,
targetMap map[string]database.Target,
) map[string]struct{} {
settled := make(map[string]struct{})
if len(deliveries) == 0 {
return settled
}
ids := make([]string, 0, len(deliveries))
for i := range deliveries {
ids = append(ids, deliveries[i].ID)
}
var deliveredIDs []string
err := webhookDB.
Model(&database.DeliveryResult{}).
Where(
"delivery_id IN ? AND success = ?", ids, true,
).
Distinct().
Pluck("delivery_id", &deliveredIDs).Error
if err != nil {
// Every delivery stays out of the settled set, so the batch
// is re-sent exactly as it was before this check existed.
// That is the safe direction: a duplicate delivery beats
// declaring a delivery successful on a query that failed.
e.log.Error(
"failed to query successful delivery results; "+
"pending deliveries will be re-sent",
"webhook_id", webhookID,
"error", err,
)
return settled
}
for _, id := range deliveredIDs {
settled[id] = struct{}{}
}
if len(settled) == 0 {
return settled
}
e.log.Info(
"settling recovered deliveries that already succeeded",
"webhook_id", webhookID,
"count", len(settled),
)
for i := range deliveries {
if _, ok := settled[deliveries[i].ID]; !ok {
continue
}
// A delivery the engine is working on right now settles
// itself; writing over it from here would race that worker.
if !e.inflight.retainIdle(deliveries[i].ID) {
delete(settled, deliveries[i].ID)
continue
}
e.settleStatus(
webhookDB,
&deliveries[i],
targetMap[deliveries[i].TargetID].Type,
database.DeliveryStatusDelivered,
)
e.inflight.release(deliveries[i].ID)
}
return settled
} }
func (e *Engine) retrySweep(ctx context.Context) { func (e *Engine) retrySweep(ctx context.Context) {
@@ -722,6 +939,11 @@ func (e *Engine) sweepWebhookRetries(
return return
} }
settled := e.reconcileDelivered(
webhookDB, webhookID, retrying,
e.loadTargetMap(retrying),
)
for i := range retrying { for i := range retrying {
select { select {
case <-ctx.Done(): case <-ctx.Done():
@@ -729,10 +951,70 @@ func (e *Engine) sweepWebhookRetries(
default: default:
} }
if _, ok := settled[retrying[i].ID]; ok {
continue
}
e.sweepSingleRetry( e.sweepSingleRetry(
webhookDB, webhookID, &retrying[i], webhookDB, webhookID, &retrying[i],
) )
} }
e.sweepWebhookPending(ctx, webhookDB, webhookID)
}
// sweepWebhookPending recovers deliveries stranded at pending.
//
// A delivery is created pending and leaves that state only when its
// outcome is written, so a pending row the engine does not own is one
// whose bookkeeping write failed — the state that used to sit there
// until a restart, and then produce a duplicate at the receiver. The
// sweep gives it the same reconcile-then-dispatch treatment restart
// recovery gets, so it costs a minute rather than an operator
// noticing.
//
// What keeps the sweep off live work is ownership, checked per
// delivery in takeForRedispatch, not the age bound in this query.
// A delivery waiting in deliveryCh is pending and arbitrarily old —
// the channel holds 10000 tasks and 10 workers drain it — so
// reasoning from the row's age alone re-sends it. See inflight.go.
func (e *Engine) sweepWebhookPending(
ctx context.Context,
webhookDB *gorm.DB,
webhookID string,
) {
var pending []database.Delivery
err := webhookDB.
Where(
"status = ? AND updated_at < ?",
database.DeliveryStatusPending,
time.Now().Add(-pendingSweepMinAge),
).
Limit(pendingSweepBatch).
Find(&pending).Error
if err != nil {
e.log.Error(
"retry sweep: "+
"failed to query pending deliveries",
"webhook_id", webhookID,
"error", err,
)
return
}
if len(pending) == 0 {
return
}
e.log.Info(
"retry sweep: recovering stranded pending deliveries",
"webhook_id", webhookID,
"count", len(pending),
)
e.recoverPendingBatch(ctx, webhookDB, webhookID, pending)
} }
// sweepSingleRetry re-enqueues an orphaned retrying delivery // sweepSingleRetry re-enqueues an orphaned retrying delivery
@@ -789,8 +1071,13 @@ func (e *Engine) sweepSingleRetry(
d, webhookID, &event, &target, attemptNum+1, d, webhookID, &event, &target, attemptNum+1,
) )
select { if !e.redispatch(
case e.retryCh <- task: e.retryCh, webhookDB, task,
database.DeliveryStatusRetrying,
) {
return
}
e.log.Info( e.log.Info(
"retry sweep: "+ "retry sweep: "+
"recovered orphaned retrying delivery", "recovered orphaned retrying delivery",
@@ -798,8 +1085,6 @@ func (e *Engine) sweepSingleRetry(
"webhook_id", webhookID, "webhook_id", webhookID,
"attempt", attemptNum+1, "attempt", attemptNum+1,
) )
default:
}
} }
// failUnretryableRetry terminally fails an orphaned retrying // failUnretryableRetry terminally fails an orphaned retrying
@@ -822,6 +1107,16 @@ func (e *Engine) failUnretryableRetry(
d *database.Delivery, d *database.Delivery,
target *database.Target, target *database.Target,
) { ) {
// Terminal, and reached from the recovery paths, so it takes
// ownership like every other write they make: a delivery the
// engine is still attempting must not be failed underneath the
// worker running it.
if !e.inflight.retainIdle(d.ID) {
return
}
defer e.inflight.release(d.ID)
e.log.Warn( e.log.Warn(
"failing orphaned retrying delivery: target "+ "failing orphaned retrying delivery: target "+
"type no longer supports retries", "type no longer supports retries",
@@ -839,7 +1134,7 @@ func (e *Engine) failUnretryableRetry(
target.Type, target.Type,
) )
e.recordResult( err := e.recordResult(
webhookDB, webhookDB,
d, d,
e.countAttempts(webhookDB, d.ID)+1, e.countAttempts(webhookDB, d.ID)+1,
@@ -849,6 +1144,11 @@ func (e *Engine) failUnretryableRetry(
reason, reason,
0, 0,
) )
if err != nil {
e.bookkeepingFailed(d, err)
return
}
// The type is passed rather than assigned onto d: the delivery // The type is passed rather than assigned onto d: the delivery
// is loaded here without its target relation, and populating // is loaded here without its target relation, and populating
@@ -856,7 +1156,7 @@ func (e *Engine) failUnretryableRetry(
// whole target row — plaintext config, which for a slack target // whole target row — plaintext config, which for a slack target
// is the credential — into the per-webhook event database. See // is the credential — into the per-webhook event database. See
// https://git.eeqj.de/sneak/webhooker/issues/206. // https://git.eeqj.de/sneak/webhooker/issues/206.
e.updateDeliveryStatus( e.settleStatus(
webhookDB, d, target.Type, webhookDB, d, target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )
@@ -878,7 +1178,7 @@ func (e *Engine) processDelivery(
"type", d.Target.Type, "type", d.Target.Type,
) )
e.updateDeliveryStatus( e.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )
@@ -910,6 +1210,14 @@ func (e *Engine) observeAttempt(
// recordResult persists a DeliveryResult row describing a // recordResult persists a DeliveryResult row describing a
// single attempt. It is a cross-target helper the targets // single attempt. It is a cross-target helper the targets
// call. // call.
//
// It returns its error rather than swallowing it. A DeliveryResult
// row is the only record that an attempt happened at all, so a
// caller that ignored a failed write would go on to mark the
// delivery delivered — leaving the event log claiming one attempt
// for a receiver that got two. Every caller must instead stop
// advancing the delivery's status and let it stay in the
// non-terminal state it already holds; see bookkeepingFailed.
func (e *Engine) recordResult( func (e *Engine) recordResult(
webhookDB *gorm.DB, webhookDB *gorm.DB,
d *database.Delivery, d *database.Delivery,
@@ -918,7 +1226,7 @@ func (e *Engine) recordResult(
statusCode int, statusCode int,
respBody, errMsg string, respBody, errMsg string,
durationMs int64, durationMs int64,
) { ) error {
result := &database.DeliveryResult{ result := &database.DeliveryResult{
DeliveryID: d.ID, DeliveryID: d.ID,
AttemptNum: attemptNum, AttemptNum: attemptNum,
@@ -931,12 +1239,44 @@ func (e *Engine) recordResult(
err := webhookDB.Create(result).Error err := webhookDB.Create(result).Error
if err != nil { if err != nil {
e.log.Error( return fmt.Errorf(
"failed to record delivery result", "recording delivery result for %s: %w", d.ID, err,
"delivery_id", d.ID,
"error", err,
) )
} }
return nil
}
// bookkeepingFailed reports that a delivery's own record of what
// happened could not be written, and deliberately writes nothing in
// response.
//
// Leaving the row alone is the whole point. A delivery is created
// pending and only ever leaves that state through
// updateDeliveryStatus, so a delivery whose bookkeeping write failed
// is still pending or retrying — the two non-terminal states, per
// DeliveryStatus.Terminal — and both are swept and recovered. Writing
// anything here would need the very database that just refused a
// write, and would be one more thing to fail; not writing cannot.
//
// The cost is honest at-least-once behaviour: a send that reached the
// receiver but whose result row did not land is attempted again, and
// recorded as the further attempt it is. What no longer happens is the
// silent duplicate — a second POST the event log denies ever
// occurred. Where the result row *did* land and only the status write
// failed, reconcileDelivered settles the row without re-sending.
func (e *Engine) bookkeepingFailed(
d *database.Delivery, err error,
) {
e.log.Error(
"delivery bookkeeping write failed; leaving delivery "+
"in a recoverable state",
"delivery_id", d.ID,
"event_id", d.EventID,
"target_id", d.TargetID,
"status", d.Status,
"error", err,
)
} }
// updateDeliveryStatus persists a new status for a delivery. // updateDeliveryStatus persists a new status for a delivery.
@@ -952,26 +1292,51 @@ func (e *Engine) recordResult(
// //
// The counter moves only after the row is written, so a transition // The counter moves only after the row is written, so a transition
// the database rejected is not claimed as an outcome that happened. // the database rejected is not claimed as an outcome that happened.
// For the same reason the error is returned rather than logged and
// dropped: a delivery whose status write failed has not reached that
// status, and its caller must not act as though it had.
func (e *Engine) updateDeliveryStatus( func (e *Engine) updateDeliveryStatus(
webhookDB *gorm.DB, webhookDB *gorm.DB,
d *database.Delivery, d *database.Delivery,
targetType database.TargetType, targetType database.TargetType,
status database.DeliveryStatus, status database.DeliveryStatus,
) { ) error {
err := webhookDB.Model(d). err := webhookDB.Model(d).
Update("status", status).Error Update("status", status).Error
if err != nil { if err != nil {
e.log.Error( return fmt.Errorf(
"failed to update delivery status", "updating delivery %s to status %s: %w",
"delivery_id", d.ID, d.ID, status, err,
"status", status,
"error", err,
) )
return
} }
// An empty type means the target row is gone — a delivery being
// settled long after its target was deleted. The row still has to
// be settled, but the counter is left alone rather than given a
// series labelled with the empty string.
if targetType != "" {
e.mtr.DeliveryStatusChanged(targetType, status) e.mtr.DeliveryStatusChanged(targetType, status)
}
return nil
}
// settleStatus moves a delivery to its outcome status and reports a
// failed write through bookkeepingFailed, which leaves the row
// recoverable. It exists so the target call sites read as one
// statement rather than four lines of identical error handling.
func (e *Engine) settleStatus(
webhookDB *gorm.DB,
d *database.Delivery,
targetType database.TargetType,
status database.DeliveryStatus,
) {
err := e.updateDeliveryStatus(
webhookDB, d, targetType, status,
)
if err != nil {
e.bookkeepingFailed(d, err)
}
} }
func truncate(s string, maxLen int) string { func truncate(s string, maxLen int) string {
@@ -1065,6 +1430,184 @@ func (e *Engine) countAttempts(
return int(resultCount) return int(resultCount)
} }
// takeForRedispatch decides whether a recovered delivery may be sent
// again, and takes it if so. It is the single gate every re-dispatch
// path goes through, and it asks two separate questions in order.
//
// First, does the engine already own this delivery? Ownership is
// exact and mutually exclusive, so a delivery queued, being attempted,
// or waiting out a retry backoff is refused here, and two dispatchers
// racing for the same delivery cannot both win. See inflight.go.
//
// Second, is the row still in the status that made it eligible? The
// batch was read some time ago and a worker may have settled a row
// since. The check is a conditional update rather than a read so the
// answer cannot go stale between asking and acting.
//
// Stamping updated_at is the same statement, and it is a cadence
// control rather than a claim: the pending sweep selects on that
// column, so a delivery handed out now is not selected again on the
// next tick a minute later but after pendingSweepMinAge. A delivery
// the database refuses to settle is therefore retried on that
// interval instead of every tick.
//
// A failed write is a refusal. It means the database is not accepting
// writes, which is the condition that stranded the delivery in the
// first place; an attempt that cannot be recorded is exactly the
// unlogged duplicate this is all here to prevent.
//
// The caller must release ownership if it then fails to queue the
// task.
func (e *Engine) takeForRedispatch(
webhookDB *gorm.DB,
deliveryID string,
eligible database.DeliveryStatus,
) bool {
if !e.inflight.retainIdle(deliveryID) {
return false
}
res := webhookDB.
Model(&database.Delivery{}).
Where(
"id = ? AND status = ?", deliveryID, eligible,
).
UpdateColumn("updated_at", time.Now())
if res.Error != nil {
e.log.Error(
"failed to mark delivery for re-dispatch; "+
"leaving it for a later sweep",
"delivery_id", deliveryID,
"error", res.Error,
)
e.inflight.release(deliveryID)
return false
}
if res.RowsAffected != 1 {
// Settled underneath us between the query and here.
e.inflight.release(deliveryID)
return false
}
return true
}
// queueRecovered puts an owned delivery's task on a worker channel,
// dropping the ownership the gate took if it does not fit.
func (e *Engine) queueRecovered(
ch chan<- Task, task Task,
) bool {
select {
case ch <- task:
return true
default:
e.inflight.release(task.DeliveryID)
e.log.Warn(
"worker channel full during recovery; "+
"delivery will be recovered by a later sweep",
"delivery_id", task.DeliveryID,
"webhook_id", task.WebhookID,
)
return false
}
}
// redispatch hands a recovered delivery to a worker channel through
// takeForRedispatch, and reports whether the task was queued.
func (e *Engine) redispatch(
ch chan<- Task,
webhookDB *gorm.DB,
task Task,
eligible database.DeliveryStatus,
) bool {
if !e.takeForRedispatch(
webhookDB, task.DeliveryID, eligible,
) {
return false
}
return e.queueRecovered(ch, task)
}
// rescheduleRecovered hands an orphaned retrying delivery back to the
// retry timer, through the same gate. It reports whether the delivery
// was rescheduled.
//
// The reference taken by the gate is dropped as soon as ScheduleRetry
// has taken its own, which it does before returning: what keeps the
// delivery owned through the backoff window is ScheduleRetry's
// reference, not this one.
func (e *Engine) rescheduleRecovered(
webhookDB *gorm.DB, task Task, delay time.Duration,
) bool {
if !e.takeForRedispatch(
webhookDB, task.DeliveryID,
database.DeliveryStatusRetrying,
) {
return false
}
defer e.inflight.release(task.DeliveryID)
e.ScheduleRetry(task, delay)
return true
}
// countAttemptsBatch counts the recorded attempts of every delivery
// in a batch with one grouped query, keyed by delivery id. Deliveries
// with no attempts are simply absent from the result, which reads back
// as the zero this caller wants.
//
// One query rather than one per delivery: this runs on the recovery
// path, which is a burst of writes against a database that has just
// been under enough contention to strand these rows in the first
// place. See https://git.eeqj.de/sneak/webhooker/issues/256.
func (e *Engine) countAttemptsBatch(
webhookDB *gorm.DB, deliveries []database.Delivery,
) map[string]int {
counts := make(map[string]int, len(deliveries))
if len(deliveries) == 0 {
return counts
}
ids := make([]string, 0, len(deliveries))
for i := range deliveries {
ids = append(ids, deliveries[i].ID)
}
// One delivery id per recorded attempt, tallied here rather than
// grouped in SQL: internal/gormlog forbids (*gorm.DB).Scan, which
// a GROUP BY into a struct would need, and an attempt row per
// delivery is bounded by the target's MaxRetries.
var attemptIDs []string
err := webhookDB.
Model(&database.DeliveryResult{}).
Where("delivery_id IN ?", ids).
Pluck("delivery_id", &attemptIDs).Error
if err != nil {
e.log.Error(
"failed to count delivery attempts for recovery",
"error", err,
)
return counts
}
for _, id := range attemptIDs {
counts[id]++
}
return counts
}
func (e *Engine) loadEvent( func (e *Engine) loadEvent(
webhookDB *gorm.DB, eventID string, webhookDB *gorm.DB, eventID string,
) (database.Event, error) { ) (database.Event, error) {
@@ -1132,6 +1675,10 @@ func buildRecoveryTask(
func (e *Engine) loadTargetMap( func (e *Engine) loadTargetMap(
deliveries []database.Delivery, deliveries []database.Delivery,
) map[string]database.Target { ) map[string]database.Target {
if len(deliveries) == 0 {
return nil
}
seen := make(map[string]bool) seen := make(map[string]bool)
targetIDs := make([]string, 0, len(deliveries)) targetIDs := make([]string, 0, len(deliveries))
@@ -1168,12 +1715,33 @@ func (e *Engine) loadTargetMap(
return targetMap return targetMap
} }
// sendRecoveredDeliveries re-dispatches pending deliveries, skipping
// the ids in settled — those already reached their receiver and have
// been marked delivered by reconcileDelivered.
//
// The skip and takeForRedispatch's status check answer different
// questions and neither replaces the other. This one is "did this
// delivery already succeed", which is what settles the row to
// delivered instead of sending it, and which is the only thing that
// keeps the retrying paths from terminally failing a delivery that
// reconcile just settled. The status check is "is the row still what
// the batch query said it was", which catches a worker settling it to
// anything at all in between.
func (e *Engine) sendRecoveredDeliveries( func (e *Engine) sendRecoveredDeliveries(
ctx context.Context, ctx context.Context,
webhookDB *gorm.DB,
deliveries []database.Delivery, deliveries []database.Delivery,
webhookID string, webhookID string,
targetMap map[string]database.Target, targetMap map[string]database.Target,
settled map[string]struct{},
) { ) {
// The attempt number continues each delivery's own history
// rather than restarting at 1. A recovered delivery may already
// have recorded attempts, and numbering the next one 1 again
// both collides in the event log and hands the retry path a
// backoff computed from the wrong attempt.
attempts := e.countAttemptsBatch(webhookDB, deliveries)
for i := range deliveries { for i := range deliveries {
select { select {
case <-ctx.Done(): case <-ctx.Done():
@@ -1181,6 +1749,10 @@ func (e *Engine) sendRecoveredDeliveries(
default: default:
} }
if _, ok := settled[deliveries[i].ID]; ok {
continue
}
target, ok := targetMap[deliveries[i].TargetID] target, ok := targetMap[deliveries[i].TargetID]
if !ok { if !ok {
e.log.Error( e.log.Error(
@@ -1192,22 +1764,40 @@ func (e *Engine) sendRecoveredDeliveries(
continue continue
} }
task := buildRecoveryTask( if !e.takeForRedispatch(
&deliveries[i], webhookID, webhookDB, deliveries[i].ID,
&deliveries[i].Event, &target, 1, database.DeliveryStatusPending,
) ) {
continue
select {
case e.deliveryCh <- task:
default:
e.log.Warn(
"delivery channel full during "+
"recovery, remaining deliveries "+
"will be recovered on next restart",
"delivery_id", deliveries[i].ID,
)
return
} }
// The body is read here, one delivery at a time and only for
// deliveries that are actually being sent, rather than
// preloaded across the whole batch. A batch is up to
// pendingSweepBatch rows at up to the 1 MB ingest cap, and
// most of a sweep's batch is refused by the gate above — so
// preloading would hold hundreds of megabytes per webhook per
// tick to build tasks it then discards.
event, err := e.loadEvent(
webhookDB, deliveries[i].EventID,
)
if err != nil {
e.log.Error(
"failed to load event for recovered delivery",
"delivery_id", deliveries[i].ID,
"event_id", deliveries[i].EventID,
"error", err,
)
e.inflight.release(deliveries[i].ID)
continue
}
task := buildRecoveryTask(
&deliveries[i], webhookID, &event, &target,
attempts[deliveries[i].ID]+1,
)
e.queueRecovered(e.deliveryCh, task)
} }
} }

View File

@@ -2,7 +2,6 @@ package delivery_test
import ( import (
"context" "context"
"database/sql"
"encoding/json" "encoding/json"
"fmt" "fmt"
"io" "io"
@@ -70,11 +69,12 @@ func iMainDB(t *testing.T) *gorm.DB {
t.TempDir(), "main-test.db", t.TempDir(), "main-test.db",
) )
dsn := fmt.Sprintf( // Opened the way the service opens the main database, so these
"file:%s?cache=shared&mode=rwc", dbPath, // tests cannot pass against journal and locking settings
// production does not use.
sqlDB, err := database.OpenSQLite(
dbPath, database.SQLiteModeCreate,
) )
sqlDB, err := sql.Open("sqlite", dsn)
require.NoError(t, err) require.NoError(t, err)
t.Cleanup(func() { _ = sqlDB.Close() }) t.Cleanup(func() { _ = sqlDB.Close() })

View File

@@ -3,7 +3,6 @@ package delivery_test
import ( import (
"bytes" "bytes"
"context" "context"
"database/sql"
"encoding/json" "encoding/json"
"fmt" "fmt"
"log/slog" "log/slog"
@@ -37,11 +36,12 @@ func testWebhookDB(t *testing.T) *gorm.DB {
t.TempDir(), "events-test.db", t.TempDir(), "events-test.db",
) )
dsn := fmt.Sprintf( // Opened the way the service opens a per-webhook database, so
"file:%s?cache=shared&mode=rwc", dbPath, // these tests cannot pass against journal and locking settings
// production does not use.
sqlDB, err := database.OpenSQLite(
dbPath, database.SQLiteModeCreate,
) )
sqlDB, err := sql.Open("sqlite", dsn)
require.NoError(t, err) require.NoError(t, err)
t.Cleanup(func() { _ = sqlDB.Close() }) t.Cleanup(func() { _ = sqlDB.Close() })

View File

@@ -33,6 +33,11 @@ const (
// response is written against this number, so a test has to // response is written against this number, so a test has to
// be able to name it. // be able to name it.
ExportMaxBodyLog = maxBodyLog ExportMaxBodyLog = maxBodyLog
// ExportPendingSweepMinAge is how long a delivery must sit at
// pending before the sweep treats it as stranded. A test has to
// name it to age a row past the bound.
ExportPendingSweepMinAge = pendingSweepMinAge
) )
// ExportIsBlockedIP exposes isBlockedIP for testing. // ExportIsBlockedIP exposes isBlockedIP for testing.
@@ -286,6 +291,26 @@ func (e *Engine) ExportWedgeWorker(release <-chan struct{}) {
}) })
} }
// ExportInflightHeld reports how many deliveries the engine currently
// owns, so a test can prove ownership is released rather than leaked.
func (e *Engine) ExportInflightHeld() int {
return e.inflight.held()
}
// ExportRetainDelivery takes the first reference on a delivery, as the
// queueing side does. It lets a test put a delivery into the state a
// worker or a full channel would, without running the pool.
func (e *Engine) ExportRetainDelivery(deliveryID string) bool {
return e.inflight.retainIdle(deliveryID)
}
// ExportRecoverRetryingDeliveries exposes recoverRetryingDeliveries.
func (e *Engine) ExportRecoverRetryingDeliveries(
webhookDB *gorm.DB, webhookID string,
) {
e.recoverRetryingDeliveries(webhookDB, webhookID)
}
// ExportDeliveryCh returns the delivery channel. // ExportDeliveryCh returns the delivery channel.
func (e *Engine) ExportDeliveryCh() chan Task { func (e *Engine) ExportDeliveryCh() chan Task {
return e.deliveryCh return e.deliveryCh

View File

@@ -0,0 +1,110 @@
package delivery
import "sync"
// inflightSet records which deliveries the engine currently owns.
//
// A delivery is owned from the moment a task for it is handed to a
// channel or to a retry timer until the engine has no further plan for
// it in memory. Restart recovery and both arms of the periodic sweep
// re-dispatch only deliveries the set does not hold, which is what
// makes them exact rather than a guess about how long a row has sat at
// pending.
//
// This replaces reasoning from timestamps. A delivery's row says
// pending from creation until its outcome is written, which covers
// four different situations — never dispatched, waiting in a channel,
// being attempted right now, and genuinely stranded — and no column
// distinguishes them. Only the engine knows which, and it knows
// exactly. `deliveryChannelSize` is 10000 against 10 workers, so a
// perfectly healthy delivery can wait far longer than any age bound
// worth setting before its attempt even begins; an age bound alone
// re-sends it. See
// https://git.eeqj.de/sneak/webhooker/issues/256.
//
// In-memory state is sufficient because a data directory admits one
// process: internal/datadir takes an flock on it at startup and a
// second instance refuses to run. Deliveries owned by a process that
// died are not in any successor's set, and restart recovery is what
// picks those up.
//
// References are counted rather than held as a plain set because
// ownership outlives the worker that took it. A target that schedules
// a retry from inside Deliver adds a reference while the worker still
// holds one, so the delivery stays owned across the gap between the
// worker returning and the timer firing — the window in which a sweep
// would otherwise find the row at retrying and send it again.
//
// The zero value is ready to use, and the Engine holds one by value.
// That is deliberate: an engine built by a constructor that forgot to
// initialise this would not refuse to re-dispatch anything, and the
// symptom would be duplicate deliveries rather than a failure anybody
// notices.
type inflightSet struct {
mu sync.Mutex
ids map[string]int
}
// retain adds a reference to a delivery the caller already knows the
// engine owns, so that ownership survives the current holder letting
// go. It cannot fail.
func (s *inflightSet) retain(deliveryID string) {
s.mu.Lock()
defer s.mu.Unlock()
if s.ids == nil {
s.ids = make(map[string]int)
}
s.ids[deliveryID]++
}
// retainIdle takes the first reference on a delivery, and reports
// whether it got it. It fails when the engine already owns the
// delivery, which is what makes two claimants — restart recovery and
// the sweep run concurrently, or two sweep arms — mutually exclusive
// rather than merely atomic.
func (s *inflightSet) retainIdle(deliveryID string) bool {
s.mu.Lock()
defer s.mu.Unlock()
if s.ids[deliveryID] > 0 {
return false
}
if s.ids == nil {
s.ids = make(map[string]int)
}
s.ids[deliveryID] = 1
return true
}
// release drops one reference. The delivery becomes eligible for
// re-dispatch again once the last one goes.
func (s *inflightSet) release(deliveryID string) {
s.mu.Lock()
defer s.mu.Unlock()
n := s.ids[deliveryID] - 1
if n <= 0 {
delete(s.ids, deliveryID)
return
}
s.ids[deliveryID] = n
}
// held reports how many deliveries the engine currently owns. It
// exists so a test can assert that ownership is released rather than
// leaked: a reference that is never dropped hides its delivery from
// every sweep for the life of the process, which is the one way this
// mechanism can fail silently.
func (s *inflightSet) held() int {
s.mu.Lock()
defer s.mu.Unlock()
return len(s.ids)
}

View File

@@ -0,0 +1,428 @@
package delivery_test
import (
"context"
"path/filepath"
"strings"
"sync"
"testing"
"time"
"github.com/google/uuid"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/delivery"
)
// These tests pin the rule that decides whether a delivery may be
// handed back to a worker: the engine re-dispatches only what it does
// not already own. Age alone is not that rule — a healthy delivery
// waiting in a 10000-deep channel is old and must not be re-sent. See
// https://git.eeqj.de/sneak/webhooker/issues/256.
// fSweepSetup seeds the main database with the webhook row the sweep
// enumerates, and returns the setup.
func fSweepSetup(
t *testing.T, targetID, name string,
) iSetup {
t.Helper()
s := newISetup(t)
iCreateTarget(t, s.MainDB, targetID,
s.WebhookID, name,
database.TargetTypeLog, "", 0,
)
require.NoError(t, s.MainDB.Create(&database.Webhook{
BaseModel: database.BaseModel{ID: s.WebhookID},
UserID: uuid.New().String(),
Name: name,
}).Error)
return s
}
// fDrain collects every task the engine has queued.
//
// Every caller drives the dispatch paths synchronously and has already
// waited for them to return, so anything they queued is in the channel
// by now. The short grace covers nothing but scheduler jitter, and is
// kept small because one of these tests runs the drain forty times.
func fDrain(e *delivery.Engine) []delivery.Task {
var out []delivery.Task
for {
select {
case task := <-e.ExportDeliveryCh():
out = append(out, task)
case task := <-e.ExportRetryCh():
out = append(out, task)
case <-time.After(25 * time.Millisecond):
return out
}
}
}
// TestArchiveHandleIsWAL closes the last gap in the durability
// evidence: the main and per-webhook tiers each assert their journal
// mode on a live handle, and the archive tier gets its settings from
// the same code path but nothing checked the running file.
func TestArchiveHandleIsWAL(t *testing.T) {
t.Parallel()
w := delivery.NewExportArchiveWriter(
filepath.Join(t.TempDir(), "archive-wal.db"),
archiveTestLogger(), 0,
)
require.NoError(t, w.Open(0))
var mode string
row := w.DB().Raw("pragma journal_mode").Row()
require.NoError(t, row.Scan(&mode))
assert.Equal(t, "wal", strings.ToLower(mode))
var busy string
row = w.DB().Raw("pragma busy_timeout").Row()
require.NoError(t, row.Scan(&busy))
assert.Equal(t, "10000", busy)
}
// TestSweepLeavesAQueuedDeliveryAlone is the case the age bound cannot
// see. The delivery is queued and untouched, so its row is arbitrarily
// old and still perfectly healthy; only ownership distinguishes it
// from a stranded one.
func TestSweepLeavesAQueuedDeliveryAlone(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "queued")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"queued":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rAgePending(t, s.WebhookDB, d.ID)
// Queued exactly as the receiver queues it, and never dequeued:
// no workers are running in this engine.
s.Engine.Notify([]delivery.Task{{
DeliveryID: d.ID,
EventID: event.ID,
WebhookID: s.WebhookID,
TargetID: targetID,
}})
require.Equal(t, 1, s.Engine.ExportInflightHeld())
s.Engine.ExportSweepWebhookRetries(
context.Background(), s.WebhookID,
)
tasks := fDrain(s.Engine)
assert.Len(
t, tasks, 1,
"the sweep must not queue a delivery that is "+
"already waiting for a worker",
)
}
// TestRecoveryAndSweepDoNotDoubleDispatch drives the two entry points
// the engine starts concurrently against one aged pending row. Before
// ownership they both dispatched it.
func TestRecoveryAndSweepDoNotDoubleDispatch(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "racing")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"racing":true}`,
)
ctx := context.Background()
for range 40 {
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rAgePending(t, s.WebhookDB, d.ID)
var wg sync.WaitGroup
wg.Go(func() {
s.Engine.ExportRecoverPendingDeliveries(
ctx, s.WebhookDB, s.WebhookID,
)
})
wg.Go(func() {
s.Engine.ExportSweepWebhookRetries(
ctx, s.WebhookID,
)
})
wg.Wait()
tasks := fDrain(s.Engine)
require.Len(
t, tasks, 1,
"delivery %s dispatched %d times",
d.ID, len(tasks),
)
// No worker runs in this engine, so the reference the winner
// took is never released and earlier iterations' deliveries
// stay owned — which is itself the property under test, since
// both paths see them on every subsequent pass.
}
}
// TestConcurrentClaimsOfOneDeliveryYieldOneOwner exercises the
// exclusion directly, rather than arguing it from a SQL predicate.
func TestConcurrentClaimsOfOneDeliveryYieldOneOwner(
t *testing.T,
) {
t.Parallel()
eng := newISetup(t).Engine
deliveryID := uuid.New().String()
var (
wg sync.WaitGroup
mu sync.Mutex
won int
)
for range 64 {
wg.Go(func() {
if eng.ExportRetainDelivery(deliveryID) {
mu.Lock()
won++
mu.Unlock()
}
})
}
wg.Wait()
assert.Equal(t, 1, won)
assert.Equal(t, 1, eng.ExportInflightHeld())
}
// TestOwnershipIsReleasedAfterDelivery guards the other direction: a
// leaked reference hides a delivery from every sweep for the life of
// the process.
func TestOwnershipIsReleasedAfterDelivery(t *testing.T) {
t.Parallel()
s := newISetup(t)
targetID := uuid.New().String()
iCreateTarget(t, s.MainDB, targetID,
s.WebhookID, "released",
database.TargetTypeLog, "", 0,
)
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"released":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
s.Engine.ExportStart()
defer func() {
require.NoError(
t, s.Engine.ExportStop(context.Background()),
)
}()
body := `{"released":true}`
s.Engine.Notify([]delivery.Task{{
DeliveryID: d.ID,
EventID: event.ID,
WebhookID: s.WebhookID,
TargetID: targetID,
TargetName: "released",
TargetType: database.TargetTypeLog,
Body: &body,
EntrypointID: event.EntrypointID,
}})
iWaitForDelivered(t, s.WebhookDB, d.ID)
assert.Eventually(
t,
func() bool {
return s.Engine.ExportInflightHeld() == 0
},
2*time.Second, 20*time.Millisecond,
"the delivery stayed owned after it was delivered",
)
}
// TestRetryingRecoverySkipsASuccessfulResult is the retrying-side twin
// of the pending reconcile. A second attempt that reached the receiver
// and whose status write then failed sits at retrying holding a
// successful result, and re-sending it is the same duplicate.
func TestRetryingRecoverySkipsASuccessfulResult(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "retry-settled")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"retry":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusRetrying,
)
rSeedResult(t, s.WebhookDB, d.ID, 1, false)
rSeedResult(t, s.WebhookDB, d.ID, 2, true)
s.Engine.ExportRecoverRetryingDeliveries(
s.WebhookDB, s.WebhookID,
)
assert.Empty(
t, fDrain(s.Engine),
"a retrying delivery holding a successful result "+
"must not be sent again",
)
iAssertStatus(
t, s.WebhookDB, d.ID,
database.DeliveryStatusDelivered,
)
}
// TestRetryingSweepSkipsASuccessfulResult is the same rule on the
// periodic sweep's retrying arm.
func TestRetryingSweepSkipsASuccessfulResult(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "retry-swept")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"swept":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusRetrying,
)
rSeedResult(t, s.WebhookDB, d.ID, 1, false)
rSeedResult(t, s.WebhookDB, d.ID, 2, true)
s.Engine.ExportSweepWebhookRetries(
context.Background(), s.WebhookID,
)
assert.Empty(t, fDrain(s.Engine))
iAssertStatus(
t, s.WebhookDB, d.ID,
database.DeliveryStatusDelivered,
)
var attempts int64
require.NoError(t, s.WebhookDB.
Model(&database.DeliveryResult{}).
Where("delivery_id = ?", d.ID).
Count(&attempts).Error)
assert.Equal(
t, int64(2), attempts,
"settling must not invent an attempt",
)
}
// TestScheduledRetryIsNotSweptDuringBackoff closes the window between
// a target scheduling a retry and the timer firing. The row says
// retrying and nothing is running, which is exactly what an orphaned
// retry looks like from the database.
func TestScheduledRetryIsNotSweptDuringBackoff(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "backoff")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"backoff":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusRetrying,
)
s.Engine.ExportScheduleRetry(delivery.Task{
DeliveryID: d.ID,
EventID: event.ID,
WebhookID: s.WebhookID,
TargetID: targetID,
AttemptNum: 2,
}, time.Hour)
require.Equal(t, 1, s.Engine.ExportInflightHeld())
s.Engine.ExportSweepWebhookRetries(
context.Background(), s.WebhookID,
)
assert.Empty(
t, fDrain(s.Engine),
"the sweep must not duplicate a retry that is "+
"already scheduled",
)
}
// TestRedispatchStampsTheRow pins the cadence control: a stranded
// delivery that has just been handed out is not selected again by the
// next tick a minute later.
func TestRedispatchStampsTheRow(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "stamped")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"stamped":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rAgePending(t, s.WebhookDB, d.ID)
ctx := context.Background()
s.Engine.ExportSweepWebhookRetries(ctx, s.WebhookID)
require.Len(t, fDrain(s.Engine), 1)
var row database.Delivery
require.NoError(t, s.WebhookDB.
First(&row, "id = ?", d.ID).Error)
assert.WithinDuration(
t, time.Now(), row.UpdatedAt, time.Minute,
"a re-dispatched delivery must be stamped so the "+
"next tick does not select it again",
)
}

View File

@@ -3,8 +3,6 @@ package delivery_test
import ( import (
"bytes" "bytes"
"context" "context"
"database/sql"
"fmt"
"log/slog" "log/slog"
"net/http" "net/http"
"path/filepath" "path/filepath"
@@ -54,12 +52,10 @@ func (q *qdSyncBuf) String() string {
func qdMainDB(t *testing.T, log *slog.Logger) *gorm.DB { func qdMainDB(t *testing.T, log *slog.Logger) *gorm.DB {
t.Helper() t.Helper()
dsn := fmt.Sprintf( sqlDB, err := database.OpenSQLite(
"file:%s?cache=shared&mode=rwc",
filepath.Join(t.TempDir(), "main-gormlog.db"), filepath.Join(t.TempDir(), "main-gormlog.db"),
database.SQLiteModeCreate,
) )
sqlDB, err := sql.Open("sqlite", dsn)
require.NoError(t, err) require.NoError(t, err)
t.Cleanup(func() { _ = sqlDB.Close() }) t.Cleanup(func() { _ = sqlDB.Close() })

View File

@@ -0,0 +1,378 @@
package delivery_test
import (
"context"
"net/http"
"net/http/httptest"
"sync/atomic"
"testing"
"time"
"github.com/google/uuid"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/delivery"
)
// These tests cover the delivery half of
// https://git.eeqj.de/sneak/webhooker/issues/256: a delivery that
// reached its receiver but whose bookkeeping write failed used to be
// left at pending and re-sent on the next restart, giving the receiver
// a second copy while the event log recorded one attempt.
// rSeedResult records a DeliveryResult against a delivery, standing in
// for the attempt row the send path writes before the status.
func rSeedResult(
t *testing.T,
db *gorm.DB,
deliveryID string,
attemptNum int,
success bool,
) {
t.Helper()
require.NoError(t, db.Create(&database.DeliveryResult{
DeliveryID: deliveryID,
AttemptNum: attemptNum,
Success: success,
}).Error)
}
// rAgePending backdates a delivery past the sweep's age bound, which is
// what separates a stranded delivery from one a worker still holds.
func rAgePending(
t *testing.T, db *gorm.DB, deliveryID string,
) {
t.Helper()
old := time.Now().Add(
-2 * delivery.ExportPendingSweepMinAge,
)
require.NoError(t, db.Model(&database.Delivery{}).
Where("id = ?", deliveryID).
UpdateColumn("updated_at", old).Error)
}
func TestRecoverySkipsPendingWithSuccessfulResult(
t *testing.T,
) {
t.Parallel()
s := newISetup(t)
targetID := uuid.New().String()
iCreateTarget(t, s.MainDB, targetID,
s.WebhookID, "already-delivered",
database.TargetTypeLog, "", 0,
)
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"delivered":true}`,
)
// The delivery whose send succeeded and whose result row landed:
// only the status write failed, so it sits at pending.
done := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rSeedResult(t, s.WebhookDB, done.ID, 1, true)
// A delivery that was genuinely never attempted.
fresh := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
s.Engine.ExportRecoverPendingDeliveries(
context.Background(), s.WebhookDB, s.WebhookID,
)
select {
case task := <-s.Engine.ExportDeliveryCh():
assert.Equal(
t, fresh.ID, task.DeliveryID,
"only the unattempted delivery may be re-sent",
)
case <-time.After(2 * time.Second):
t.Fatal("expected the unattempted delivery")
}
select {
case task := <-s.Engine.ExportDeliveryCh():
t.Fatalf(
"re-sent an already delivered delivery: %s",
task.DeliveryID,
)
case <-time.After(200 * time.Millisecond):
}
// It is settled rather than merely skipped: leaving it pending
// would strand it again on the next sweep.
iAssertStatus(
t, s.WebhookDB, done.ID,
database.DeliveryStatusDelivered,
)
}
// TestRecoveryContinuesTheAttemptNumbering pins the audit trail: a
// recovered delivery that already recorded two attempts is re-sent as
// attempt three, not as attempt one again.
func TestRecoveryContinuesTheAttemptNumbering(t *testing.T) {
t.Parallel()
s := newISetup(t)
targetID := uuid.New().String()
iCreateTarget(t, s.MainDB, targetID,
s.WebhookID, "numbering",
database.TargetTypeLog, "", 0,
)
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"numbering":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rSeedResult(t, s.WebhookDB, d.ID, 1, false)
rSeedResult(t, s.WebhookDB, d.ID, 2, false)
s.Engine.ExportRecoverPendingDeliveries(
context.Background(), s.WebhookDB, s.WebhookID,
)
select {
case task := <-s.Engine.ExportDeliveryCh():
assert.Equal(t, d.ID, task.DeliveryID)
assert.Equal(t, 3, task.AttemptNum)
case <-time.After(2 * time.Second):
t.Fatal("expected the delivery to be recovered")
}
}
// TestSweepRecoversStrandedPending is the half that removes the
// restart requirement: a delivery left at pending is picked up by the
// periodic sweep.
func TestSweepRecoversStrandedPending(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "stranded")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"stranded":true}`,
)
stranded := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rAgePending(t, s.WebhookDB, stranded.ID)
// A delivery a worker may still be holding: young, and therefore
// none of the sweep's business.
inFlight := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
s.Engine.ExportSweepWebhookRetries(
context.Background(), s.WebhookID,
)
select {
case task := <-s.Engine.ExportDeliveryCh():
assert.Equal(t, stranded.ID, task.DeliveryID)
case <-time.After(2 * time.Second):
t.Fatal("expected the stranded delivery")
}
select {
case task := <-s.Engine.ExportDeliveryCh():
t.Fatalf(
"swept an in-flight delivery: %s",
task.DeliveryID,
)
case <-time.After(200 * time.Millisecond):
}
iAssertStatus(
t, s.WebhookDB, inFlight.ID,
database.DeliveryStatusPending,
)
}
// TestSweepClaimsAStrandedDeliveryOnlyOnce guards the repeat the sweep
// would otherwise be: the row stays pending for as long as the attempt
// runs, and a sweep a minute later must not send it a second time.
func TestSweepClaimsAStrandedDeliveryOnlyOnce(t *testing.T) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "claimed")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"claimed":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rAgePending(t, s.WebhookDB, d.ID)
ctx := context.Background()
s.Engine.ExportSweepWebhookRetries(ctx, s.WebhookID)
select {
case task := <-s.Engine.ExportDeliveryCh():
assert.Equal(t, d.ID, task.DeliveryID)
case <-time.After(2 * time.Second):
t.Fatal("expected the stranded delivery")
}
// The delivery is still pending — nothing has run it yet — but
// the claim must keep the next sweep off it.
iAssertStatus(
t, s.WebhookDB, d.ID,
database.DeliveryStatusPending,
)
s.Engine.ExportSweepWebhookRetries(ctx, s.WebhookID)
select {
case task := <-s.Engine.ExportDeliveryCh():
t.Fatalf(
"sent a claimed delivery again: %s",
task.DeliveryID,
)
case <-time.After(200 * time.Millisecond):
}
}
// TestSweepSettlesStrandedPendingWithoutResending is the sweep's own
// version of the reconcile: a stranded delivery holding a successful
// result is settled where it stands, and the receiver hears nothing.
func TestSweepSettlesStrandedPendingWithoutResending(
t *testing.T,
) {
t.Parallel()
targetID := uuid.New().String()
s := fSweepSetup(t, targetID, "settled")
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"settled":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
rSeedResult(t, s.WebhookDB, d.ID, 1, true)
rAgePending(t, s.WebhookDB, d.ID)
s.Engine.ExportSweepWebhookRetries(
context.Background(), s.WebhookID,
)
select {
case task := <-s.Engine.ExportDeliveryCh():
t.Fatalf(
"re-sent a delivery that already succeeded: %s",
task.DeliveryID,
)
case <-time.After(200 * time.Millisecond):
}
iAssertStatus(
t, s.WebhookDB, d.ID,
database.DeliveryStatusDelivered,
)
var attempts int64
require.NoError(t, s.WebhookDB.
Model(&database.DeliveryResult{}).
Where("delivery_id = ?", d.ID).
Count(&attempts).Error)
assert.Equal(
t, int64(1), attempts,
"settling must not invent an attempt",
)
}
// TestFailedResultWriteLeavesDeliveryRecoverable is the rule the
// targets now follow: a bookkeeping write that fails must not advance
// the status, because pending and retrying are the states the sweeps
// recover and delivered is a claim the database refused to record.
func TestFailedResultWriteLeavesDeliveryRecoverable(
t *testing.T,
) {
t.Parallel()
s := newISetup(t)
targetID := uuid.New().String()
var hits atomic.Int64
ts := httptest.NewServer(http.HandlerFunc(
func(w http.ResponseWriter, _ *http.Request) {
hits.Add(1)
w.WriteHeader(http.StatusOK)
},
))
defer ts.Close()
event := iSeedEvent(
t, s.WebhookDB, s.WebhookID, `{"unwritable":true}`,
)
d := iSeedDelivery(
t, s.WebhookDB, event.ID, targetID,
database.DeliveryStatusPending,
)
// Drop the table the attempt row goes in, so the send succeeds
// and only the bookkeeping write fails.
require.NoError(
t,
s.WebhookDB.Exec("drop table delivery_results").Error,
)
full := &database.Delivery{
EventID: event.ID,
TargetID: targetID,
Status: database.DeliveryStatusPending,
Event: event,
Target: database.Target{
Name: "unwritable",
Type: database.TargetTypeHTTP,
Config: iHTTPConfig(ts.URL),
},
}
full.ID = d.ID
s.Engine.ExportDeliverHTTP(
context.Background(), s.WebhookDB, full,
&delivery.Task{DeliveryID: d.ID, AttemptNum: 1},
)
assert.Equal(
t, int64(1), hits.Load(),
"the send itself must still happen",
)
iAssertStatus(
t, s.WebhookDB, d.ID,
database.DeliveryStatusPending,
)
}

View File

@@ -58,12 +58,17 @@ func (t *databaseTarget) Deliver(
"error", err, "error", err,
) )
t.eng.recordResult( recErr := t.eng.recordResult(
webhookDB, d, 1, false, 0, "", webhookDB, d, 1, false, 0, "",
err.Error(), elapsed.Milliseconds(), err.Error(), elapsed.Milliseconds(),
) )
if recErr != nil {
t.eng.bookkeepingFailed(d, recErr)
t.eng.updateDeliveryStatus( return
}
t.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )
@@ -71,12 +76,17 @@ func (t *databaseTarget) Deliver(
return return
} }
t.eng.recordResult( recErr := t.eng.recordResult(
webhookDB, d, 1, true, 0, "", "", webhookDB, d, 1, true, 0, "", "",
elapsed.Milliseconds(), elapsed.Milliseconds(),
) )
if recErr != nil {
t.eng.bookkeepingFailed(d, recErr)
t.eng.updateDeliveryStatus( return
}
t.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusDelivered, database.DeliveryStatusDelivered,
) )

View File

@@ -1,7 +1,6 @@
package delivery package delivery
import ( import (
"database/sql"
"encoding/json" "encoding/json"
"errors" "errors"
"fmt" "fmt"
@@ -12,6 +11,7 @@ import (
"gorm.io/driver/sqlite" "gorm.io/driver/sqlite"
"gorm.io/gorm" "gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/gormlog" "sneak.berlin/go/webhooker/internal/gormlog"
) )
@@ -30,13 +30,13 @@ const (
// path: open the archive file, creating it if missing, so a // path: open the archive file, creating it if missing, so a
// first write (or a write after the operator moved the file // first write (or a write after the operator moved the file
// away) recreates it. // away) recreates it.
archiveModeCreate = "rwc" archiveModeCreate = database.SQLiteModeCreate
// archiveModeExisting is the SQLite URI mode used by the idle // archiveModeExisting is the SQLite URI mode used by the idle
// sweep: open read-write but never create. A sweep must never // sweep: open read-write but never create. A sweep must never
// conjure an empty archive file for a webhook that has a // conjure an empty archive file for a webhook that has a
// database target but has never received an event. // database target but has never received an event.
archiveModeExisting = "rw" archiveModeExisting = database.SQLiteModeExisting
) )
var ( var (
@@ -273,9 +273,11 @@ func (w *archiveWriter) open(expiry time.Duration) error {
func (w *archiveWriter) openMode( func (w *archiveWriter) openMode(
mode string, expiry time.Duration, mode string, expiry time.Duration,
) error { ) error {
dbURL := fmt.Sprintf("file:%s?mode=%s", w.path, mode) // Opened through database.OpenSQLite so an archive file carries
// the same WAL journaling, busy timeout, immediate-transaction
sqlDB, err := sql.Open("sqlite", dbURL) // locking, and pool bounds as every other database file. See
// internal/database/sqlite_open.go.
sqlDB, err := database.OpenSQLite(w.path, mode)
if err != nil { if err != nil {
return fmt.Errorf( return fmt.Errorf(
"opening archive database %s: %w", w.path, err, "opening archive database %s: %w", w.path, err,

View File

@@ -77,14 +77,19 @@ func (c *httpCore) fireAndForget(
) { ) {
c.eng.observeAttempt(d.Target.Type, res.elapsed()) c.eng.observeAttempt(d.Target.Type, res.elapsed())
c.eng.recordResult( err := c.eng.recordResult(
webhookDB, d, 1, res.success, webhookDB, d, 1, res.success,
res.statusCode, res.respBody, res.errMsg, res.statusCode, res.respBody, res.errMsg,
res.duration, res.duration,
) )
if err != nil {
c.eng.bookkeepingFailed(d, err)
return
}
if res.success { if res.success {
c.eng.updateDeliveryStatus( c.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusDelivered, database.DeliveryStatusDelivered,
) )
@@ -92,7 +97,7 @@ func (c *httpCore) fireAndForget(
return return
} }
c.eng.updateDeliveryStatus( c.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )
@@ -122,16 +127,25 @@ func (c *httpCore) withRetry(
c.eng.observeAttempt(d.Target.Type, res.elapsed()) c.eng.observeAttempt(d.Target.Type, res.elapsed())
c.eng.recordResult( err := c.eng.recordResult(
webhookDB, d, attemptNum, res.success, webhookDB, d, attemptNum, res.success,
res.statusCode, res.respBody, res.errMsg, res.statusCode, res.respBody, res.errMsg,
res.duration, res.duration,
) )
if err != nil {
// The breaker still learns the outcome: it describes the
// target's health, which is unaffected by this database's.
c.recordCircuitOutcome(cb, res.success)
c.eng.bookkeepingFailed(d, err)
return
}
if res.success { if res.success {
cb.RecordSuccess() cb.RecordSuccess()
c.eng.updateDeliveryStatus( c.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusDelivered, database.DeliveryStatusDelivered,
) )
@@ -146,6 +160,20 @@ func (c *httpCore) withRetry(
) )
} }
// recordCircuitOutcome feeds one attempt's outcome to the target's
// circuit breaker.
func (c *httpCore) recordCircuitOutcome(
cb *CircuitBreaker, success bool,
) {
if success {
cb.RecordSuccess()
return
}
cb.RecordFailure()
}
func (c *httpCore) circuitBreakerBlock( func (c *httpCore) circuitBreakerBlock(
webhookDB *gorm.DB, webhookDB *gorm.DB,
d *database.Delivery, d *database.Delivery,
@@ -169,7 +197,7 @@ func (c *httpCore) circuitBreakerBlock(
"cooldown_remaining", remaining, "cooldown_remaining", remaining,
) )
c.eng.updateDeliveryStatus( c.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusRetrying, database.DeliveryStatusRetrying,
) )
@@ -189,7 +217,7 @@ func (c *httpCore) handleRetry(
attemptNum int, attemptNum int,
) { ) {
if attemptNum >= maxRetries { if attemptNum >= maxRetries {
c.eng.updateDeliveryStatus( c.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )
@@ -197,7 +225,7 @@ func (c *httpCore) handleRetry(
return return
} }
c.eng.updateDeliveryStatus( c.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusRetrying, database.DeliveryStatusRetrying,
) )
@@ -332,12 +360,17 @@ func (t *httpTarget) Deliver(
"error", err, "error", err,
) )
t.eng.recordResult( recErr := t.eng.recordResult(
webhookDB, d, task.AttemptNum, webhookDB, d, task.AttemptNum,
false, 0, "", err.Error(), 0, false, 0, "", err.Error(), 0,
) )
if recErr != nil {
t.eng.bookkeepingFailed(d, recErr)
t.eng.updateDeliveryStatus( return
}
t.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )

View File

@@ -55,12 +55,17 @@ func (t *logTarget) Deliver(
t.eng.observeAttempt(d.Target.Type, elapsed) t.eng.observeAttempt(d.Target.Type, elapsed)
t.eng.recordResult( err := t.eng.recordResult(
webhookDB, d, 1, true, 0, "", "", webhookDB, d, 1, true, 0, "", "",
elapsed.Milliseconds(), elapsed.Milliseconds(),
) )
if err != nil {
t.eng.bookkeepingFailed(d, err)
t.eng.updateDeliveryStatus( return
}
t.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusDelivered, database.DeliveryStatusDelivered,
) )

View File

@@ -95,12 +95,17 @@ func (t *slackTarget) failConfig(
d *database.Delivery, d *database.Delivery,
err error, err error,
) { ) {
t.eng.recordResult( recErr := t.eng.recordResult(
webhookDB, d, 1, webhookDB, d, 1,
false, 0, "", err.Error(), 0, false, 0, "", err.Error(), 0,
) )
if recErr != nil {
t.eng.bookkeepingFailed(d, recErr)
t.eng.updateDeliveryStatus( return
}
t.eng.settleStatus(
webhookDB, d, d.Target.Type, webhookDB, d, d.Target.Type,
database.DeliveryStatusFailed, database.DeliveryStatusFailed,
) )

View File

@@ -92,11 +92,10 @@ func (h *Handlers) HandleEventBodyDownload() http.HandlerFunc {
// once per range. // once per range.
// //
// One consequence is worth keeping in view: the read finishes // One consequence is worth keeping in view: the read finishes
// before the client is written to, so no read lock is held for // before the client is written to, so nothing is held open for
// the length of a slow download. These per-webhook databases // the length of a slow download. Under WAL a read no longer
// run in SQLite's default journal mode rather than WAL, so a // blocks the receiver, but it does pin the WAL against
// lock held that long would block the receiver from recording // checkpointing, and a download can last minutes.
// new events.
func (h *Handlers) serveEventBody( func (h *Handlers) serveEventBody(
w http.ResponseWriter, w http.ResponseWriter,
r *http.Request, r *http.Request,

View File

@@ -143,10 +143,10 @@ func (h *Handlers) resubmitEvent(
} }
// Read before the write transaction is opened. The body can be up // Read before the write transaction is opened. The body can be up
// to the 1 MB ingest cap, and holding a read of it inside the // to the 1 MB ingest cap, and every transaction on these files
// transaction would extend how long the per-webhook database is // takes the write lock at BEGIN (_txlock=immediate, see
// locked against the receiver, which runs these files in // internal/database/sqlite_open.go), so reading inside it would
// SQLite's default journal mode rather than WAL. // hold that lock against the receiver for the length of the read.
src, found, err := loadResubmitSource( src, found, err := loadResubmitSource(
webhookDB, webhook.ID, eventID.String(), webhookDB, webhook.ID, eventID.String(),
) )

View File

@@ -2,6 +2,7 @@ package handlers_test
import ( import (
"context" "context"
"errors"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"os" "os"
@@ -11,6 +12,7 @@ import (
"github.com/go-chi/chi" "github.com/go-chi/chi"
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"gorm.io/gorm"
"gorm.io/gorm/clause" "gorm.io/gorm/clause"
"sneak.berlin/go/webhooker/internal/database" "sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/handlers" "sneak.berlin/go/webhooker/internal/handlers"
@@ -73,6 +75,77 @@ func seedTarget(
return tgt return tgt
} }
// errInjectedDelete is the failure failDeleteOnTable reports
// from a delete statement.
var errInjectedDelete = errors.New("injected delete failure")
// seedEntrypoint inserts an entrypoint for a webhook.
func seedEntrypoint(
t *testing.T,
db *database.Database,
webhookID string,
) {
t.Helper()
ep := &database.Entrypoint{
WebhookID: webhookID,
Path: "ep-" + webhookID,
Active: true,
}
require.NoError(
t,
db.DB().Omit(clause.Associations).Create(ep).Error,
)
}
// countRows counts the live (not soft-deleted) rows of a model
// matching column = value.
func countRows(
t *testing.T,
db *database.Database,
model any,
column, value string,
) int64 {
t.Helper()
var n int64
require.NoError(
t,
db.DB().Model(model).
Where(column+" = ?", value).
Count(&n).Error,
)
return n
}
// failDeleteOnTable makes every delete against the named table
// fail the way a database-level error does: the statement
// reports an error but leaves the surrounding transaction
// usable, so a caller that does not check it can go on to
// commit the statements that did succeed.
func failDeleteOnTable(
t *testing.T,
db *database.Database,
table string,
) {
t.Helper()
require.NoError(t, db.DB().Callback().Delete().
Before("gorm:delete").
Register(
"test:fail_delete_"+table,
func(tx *gorm.DB) {
if tx.Statement.Table == table {
_ = tx.AddError(errInjectedDelete)
}
},
),
)
}
// archivePathFor returns the archive database path the // archivePathFor returns the archive database path the
// delivery engine would use for a webhook: beside the webhook's // delivery engine would use for a webhook: beside the webhook's
// event database in the data directory. // event database in the data directory.
@@ -209,6 +282,159 @@ func TestHandleSourceDelete_KeepsArchiveFile(t *testing.T) {
) )
} }
// TestHandleSourceDelete_FailedDeleteKeepsEverything proves
// that a failing delete statement loses nothing: the
// configuration is rolled back whole, the event database
// survives, and the operator is told the deletion failed
// instead of being redirected as though it worked.
func TestHandleSourceDelete_FailedDeleteKeepsEverything(
t *testing.T,
) {
t.Parallel()
var (
h *handlers.Handlers
sess *session.Session
db *database.Database
mgr *database.WebhookDBManager
)
app := newTestApp(t, &h, &sess, &db, &mgr)
app.RequireStart()
t.Cleanup(app.RequireStop)
wh := seedWebhook(t, db)
seedEntrypoint(t, db, wh.ID)
seedTarget(t, db, wh.ID, database.TargetTypeDatabase)
require.NoError(t, mgr.CreateDB(wh.ID))
eventDBPath := mgr.DBPath(wh.ID)
require.FileExists(t, eventDBPath)
// The entrypoint delete runs first and succeeds; the target
// delete then fails, which is what the whole transaction has
// to be rolled back over.
failDeleteOnTable(t, db, "targets")
cookies := authenticatedCookies(
t, sess, deleteTestUserID, deleteTestUsername,
)
req := postRequest(
"/source/"+wh.ID+"/delete",
cookies,
map[string]string{paramSourceID: wh.ID},
)
w := httptest.NewRecorder()
h.HandleSourceDelete().ServeHTTP(w, req)
assert.Equal(
t, http.StatusInternalServerError, w.Code,
"a failed deletion must be reported, not redirected",
)
assert.Empty(
t, w.Header().Get("Location"),
"a failed deletion must not redirect to /sources",
)
assert.Equal(
t, int64(1),
countRows(t, db, &database.Webhook{}, "id", wh.ID),
"the webhook must survive a failed deletion",
)
assert.Equal(
t, int64(1),
countRows(
t, db, &database.Entrypoint{}, "webhook_id", wh.ID,
),
"the entrypoint delete must be rolled back",
)
assert.Equal(
t, int64(1),
countRows(
t, db, &database.Target{}, "webhook_id", wh.ID,
),
"the target must survive a failed deletion",
)
assert.FileExists(
t, eventDBPath,
"event history must not be destroyed when the "+
"configuration delete did not commit",
)
}
// TestHandleSourceDelete_RemovesConfigAndEventDatabase is the
// positive control for the rollback above: an ordinary deletion
// still removes the webhook, its children and its event
// database.
func TestHandleSourceDelete_RemovesConfigAndEventDatabase(
t *testing.T,
) {
t.Parallel()
var (
h *handlers.Handlers
sess *session.Session
db *database.Database
mgr *database.WebhookDBManager
)
app := newTestApp(t, &h, &sess, &db, &mgr)
app.RequireStart()
t.Cleanup(app.RequireStop)
wh := seedWebhook(t, db)
seedEntrypoint(t, db, wh.ID)
seedTarget(t, db, wh.ID, database.TargetTypeDatabase)
require.NoError(t, mgr.CreateDB(wh.ID))
eventDBPath := mgr.DBPath(wh.ID)
require.FileExists(t, eventDBPath)
cookies := authenticatedCookies(
t, sess, deleteTestUserID, deleteTestUsername,
)
req := postRequest(
"/source/"+wh.ID+"/delete",
cookies,
map[string]string{paramSourceID: wh.ID},
)
w := httptest.NewRecorder()
h.HandleSourceDelete().ServeHTTP(w, req)
require.Equal(t, http.StatusSeeOther, w.Code)
assert.Equal(t, "/sources", w.Header().Get("Location"))
assert.Equal(
t, int64(0),
countRows(t, db, &database.Webhook{}, "id", wh.ID),
)
assert.Equal(
t, int64(0),
countRows(
t, db, &database.Entrypoint{}, "webhook_id", wh.ID,
),
)
assert.Equal(
t, int64(0),
countRows(
t, db, &database.Target{}, "webhook_id", wh.ID,
),
)
assert.NoFileExists(
t, eventDBPath,
"a successful deletion removes the event database",
)
}
// TestHandleTargetDelete_EvictsWhenLastDatabaseTargetGone // TestHandleTargetDelete_EvictsWhenLastDatabaseTargetGone
// proves that removing the last database target releases the // proves that removing the last database target releases the
// archive writer. // archive writer.

View File

@@ -625,43 +625,27 @@ func (h *Handlers) deleteWebhookResources(
webhook database.Webhook, webhook database.Webhook,
userID string, userID string,
) { ) {
tx := h.db.DB().Begin() // The configuration delete commits before the event database
if tx.Error != nil { // is touched. No transaction spans the main database and the
h.log.Error( // filesystem, so one side has to go first: committing the
"failed to begin transaction", // configuration first means a later failure leaves an unused
"error", tx.Error, // event database file on disk, while removing the event
) // database first would mean a failed commit destroys the
http.Error( // history of a webhook that still exists. A leftover file can
w, "Internal server error", // be removed by hand; deleted history cannot be recovered.
http.StatusInternalServerError, err := h.commitWebhookDeletion(&webhook)
)
return
}
tx.Where(
"webhook_id = ?", webhook.ID,
).Delete(&database.Entrypoint{})
tx.Where(
"webhook_id = ?", webhook.ID,
).Delete(&database.Target{})
tx.Delete(&webhook)
err := tx.Commit().Error
if err != nil { if err != nil {
h.log.Error( h.serverError(w, "failed to delete webhook", err)
"failed to commit deletion", "error", err,
)
http.Error(
w, "Internal server error",
http.StatusInternalServerError,
)
return return
} }
h.log.Info(
"webhook deleted",
"webhook_id", webhook.ID,
"user_id", userID,
)
// Release the delivery engine's per-webhook archiving state // Release the delivery engine's per-webhook archiving state
// so a deleted webhook's archive writer (and any handle open // so a deleted webhook's archive writer (and any handle open
// within its debounce window) does not linger for the // within its debounce window) does not linger for the
@@ -671,22 +655,63 @@ func (h *Handlers) deleteWebhookResources(
err = h.dbMgr.DeleteDB(webhook.ID) err = h.dbMgr.DeleteDB(webhook.ID)
if err != nil { if err != nil {
h.log.Error( // The configuration is committed, so the webhook is gone,
"failed to delete webhook event database", // but its event database file is still on disk with
"webhook_id", webhook.ID, // nothing referencing it. Report the failure rather than
"error", err, // redirecting as though everything succeeded: the file
// needs removing by hand, and the logged error names it.
h.serverError(
w, "failed to delete webhook event database", err,
) )
return
} }
h.log.Info(
"webhook deleted",
"webhook_id", webhook.ID,
"user_id", userID,
)
http.Redirect(w, r, "/sources", http.StatusSeeOther) http.Redirect(w, r, "/sources", http.StatusSeeOther)
} }
// commitWebhookDeletion soft-deletes a webhook's entrypoints,
// targets and the webhook row in one transaction. Every
// statement is checked and any failure rolls the whole
// transaction back, so a caller that gets an error knows the
// configuration is untouched and the event database must be
// left alone.
func (h *Handlers) commitWebhookDeletion(
webhook *database.Webhook,
) error {
tx := h.db.DB().Begin()
if tx.Error != nil {
return tx.Error
}
err := tx.Where(
"webhook_id = ?", webhook.ID,
).Delete(&database.Entrypoint{}).Error
if err != nil {
tx.Rollback()
return err
}
err = tx.Where(
"webhook_id = ?", webhook.ID,
).Delete(&database.Target{}).Error
if err != nil {
tx.Rollback()
return err
}
err = tx.Delete(webhook).Error
if err != nil {
tx.Rollback()
return err
}
return tx.Commit().Error
}
// evictArchiveWriter asks the delivery engine to drop its // evictArchiveWriter asks the delivery engine to drop its
// cached archive writer for a webhook, closing the archive file // cached archive writer for a webhook, closing the archive file
// handle. // handle.

View File

@@ -5,6 +5,7 @@ import (
"github.com/gorilla/csrf" "github.com/gorilla/csrf"
"sneak.berlin/go/webhooker/internal/logfield" "sneak.berlin/go/webhooker/internal/logfield"
"sneak.berlin/go/webhooker/internal/reqtls"
) )
// CSRFToken retrieves the CSRF token from the request context. // CSRFToken retrieves the CSRF token from the request context.
@@ -13,13 +14,6 @@ func CSRFToken(r *http.Request) string {
return csrf.Token(r) return csrf.Token(r)
} }
// isClientTLS reports whether the client-facing connection uses TLS.
// It checks for a direct TLS connection (r.TLS) or a TLS-terminating
// reverse proxy that sets the standard X-Forwarded-Proto header.
func isClientTLS(r *http.Request) bool {
return r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"
}
// CSRF returns middleware that provides CSRF protection using the // CSRF returns middleware that provides CSRF protection using the
// gorilla/csrf library. The middleware uses the session authentication // gorilla/csrf library. The middleware uses the session authentication
// key to sign a CSRF cookie and validates a masked token submitted via // key to sign a CSRF cookie and validates a masked token submitted via
@@ -27,9 +21,10 @@ func isClientTLS(r *http.Request) bool {
// POST/PUT/PATCH/DELETE requests. Requests with an invalid or missing // POST/PUT/PATCH/DELETE requests. Requests with an invalid or missing
// token receive a 403 Forbidden response. // token receive a 403 Forbidden response.
// //
// The middleware detects the client-facing transport protocol per-request // The middleware detects the client-facing transport protocol
// using r.TLS and the X-Forwarded-Proto header. This allows correct // per-request via reqtls.IsTLS, the single TLS predicate the session
// behavior in all deployment scenarios: // cookie also uses. This allows correct behavior in all deployment
// scenarios:
// //
// - Direct HTTPS: strict Referer/Origin checks, Secure cookies. // - Direct HTTPS: strict Referer/Origin checks, Secure cookies.
// - Behind a TLS-terminating reverse proxy: strict checks (the // - Behind a TLS-terminating reverse proxy: strict checks (the
@@ -83,7 +78,7 @@ func (m *Middleware) CSRF() func(http.Handler) http.Handler {
httpCSRF := httpProtect(next) httpCSRF := httpProtect(next)
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if isClientTLS(r) { if reqtls.IsTLS(r) {
// Client is on TLS (directly or via reverse proxy). // Client is on TLS (directly or via reverse proxy).
// Use Secure cookies and strict Origin/Referer checks. // Use Secure cookies and strict Origin/Referer checks.
tlsCSRF.ServeHTTP(w, r) tlsCSRF.ServeHTTP(w, r)

View File

@@ -297,55 +297,176 @@ func TestCSRFToken_NoMiddleware(t *testing.T) {
} }
// --- TLS Detection Tests --- // --- TLS Detection Tests ---
//
// The predicate itself is tested in internal/reqtls. What is tested
// here is the consequence that actually matters: which of the two
// gorilla/csrf instances a request is routed to.
//
// The two are told apart behaviourally rather than by inspection. On
// the STRICT (TLS) instance, a state-changing request carrying no
// Origin header must supply a Referer -- gorilla/csrf rejects it with
// ErrNoReferer before it ever looks at the token, to defend a
// TLS site against an HTTP machine-in-the-middle injecting a form. On
// the RELAXED (plaintext) instance that check is skipped and a valid
// token is enough. So: valid token, no Origin, no Referer, and the
// outcome names the instance.
//
// Landing on the relaxed instance for a genuinely-HTTPS deployment is
// the defect: an exact == "https" comparison did exactly that for the
// uppercase and comma-appended spellings below.
func TestIsClientTLS_DirectTLS(t *testing.T) { // csrfTookStrictPath reports whether the CSRF middleware routed a
t.Parallel() // request with the given transport to the strict instance. It also
// asserts the CSRF cookie's Secure attribute agrees, since the two are
// set by the same choice and must never disagree.
func csrfTookStrictPath(
t *testing.T,
env string,
directTLS bool,
fwdProto string,
) bool {
t.Helper()
m, _ := testMiddleware(t, env)
csrfMW := m.CSRF()
newReq := func(method string) *http.Request {
r := httptest.NewRequestWithContext( r := httptest.NewRequestWithContext(
context.Background(), http.MethodGet, "/", nil) context.Background(), method,
"http://example.com/form", nil,
)
if directTLS {
r.TLS = &tls.ConnectionState{} r.TLS = &tls.ConnectionState{}
}
if fwdProto != "" {
r.Header.Set("X-Forwarded-Proto", fwdProto)
}
return r
}
token, cookies := csrfGetToken(t, csrfMW, newReq(http.MethodGet))
// Deliberately no Origin and no Referer: that is what makes the
// two instances distinguishable.
called, code := csrfPostWithToken(
t, csrfMW, newReq(http.MethodPost), token, cookies,
)
strict := !called
if strict {
assert.Equal(
t, http.StatusForbidden, code,
"the strict instance rejects a Referer-less POST",
)
}
for _, c := range cookies {
if c.Name == csrfCookieName {
assert.Equal(
t, strict, c.Secure,
"the CSRF cookie's Secure attribute and the "+
"chosen instance come from one decision "+
"and must agree",
)
}
}
return strict
}
// TestCSRF_ForwardedProtoSpellingsTakeStrictPath runs the header
// spellings a real proxy emits through the middleware. The environment
// is dev -- the DEFAULT when WEBHOOKER_ENVIRONMENT is unset -- to pin
// that the routing is a per-request transport decision and owes
// nothing to configuration.
func TestCSRF_ForwardedProtoSpellingsTakeStrictPath(t *testing.T) {
t.Parallel()
cases := []struct {
name string
header string
strict bool
why string
}{
{
name: "lowercase",
header: "https",
strict: true,
why: "the ordinary spelling",
},
{
name: "uppercase",
header: "HTTPS",
strict: true,
why: "the header value is a case-insensitive token",
},
{
name: "chain with plaintext inner hop",
header: "https, http",
strict: true,
why: "a chained proxy appends its hop; the leftmost " +
"element is the browser's connection",
},
{
name: "chain of two TLS hops",
header: "https,https",
strict: true,
why: "appended chain with no space after the comma",
},
{
name: "trailing space",
header: "https ",
strict: true,
why: "whitespace is not part of the token",
},
{
name: "plaintext",
header: "http",
strict: false,
why: "the negative control: the proxy reports a " +
"plaintext client connection",
},
}
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
assert.Equal(
t, tc.strict,
csrfTookStrictPath(
t, config.EnvironmentDev, false, tc.header,
),
"X-Forwarded-Proto %q: %s", tc.header, tc.why,
)
})
}
}
// TestCSRF_DirectTLSTakesStrictPath covers the no-proxy TLS
// deployment, and TestCSRF_PlaintextTakesRelaxedPath the no-proxy
// plaintext one -- the local development case that must keep working.
func TestCSRF_DirectTLSTakesStrictPath(t *testing.T) {
t.Parallel()
assert.True( assert.True(
t, middleware.IsClientTLS(r), t,
"should detect direct TLS connection", csrfTookStrictPath(t, config.EnvironmentDev, true, ""),
"a request that arrived over TLS takes the strict path",
) )
} }
func TestIsClientTLS_XForwardedProto(t *testing.T) { func TestCSRF_PlaintextTakesRelaxedPath(t *testing.T) {
t.Parallel() t.Parallel()
r := httptest.NewRequestWithContext(
context.Background(), http.MethodGet, "/", nil)
r.Header.Set("X-Forwarded-Proto", "https")
assert.True(
t, middleware.IsClientTLS(r),
"should detect TLS via X-Forwarded-Proto",
)
}
func TestIsClientTLS_PlaintextHTTP(t *testing.T) {
t.Parallel()
r := httptest.NewRequestWithContext(
context.Background(), http.MethodGet, "/", nil)
assert.False( assert.False(
t, middleware.IsClientTLS(r), t,
"should detect plaintext HTTP", csrfTookStrictPath(t, config.EnvironmentProd, false, ""),
) "no TLS and no proxy header is plaintext, in any environment",
}
func TestIsClientTLS_XForwardedProtoHTTP(t *testing.T) {
t.Parallel()
r := httptest.NewRequestWithContext(
context.Background(), http.MethodGet, "/", nil)
r.Header.Set("X-Forwarded-Proto", "http")
assert.False(
t, middleware.IsClientTLS(r),
"should detect plaintext when X-Forwarded-Proto is http",
) )
} }

View File

@@ -56,11 +56,6 @@ func ClientKeyForTest(m *Middleware, r *http.Request) string {
return m.clientKey(r) return m.clientKey(r)
} }
// IsClientTLS exposes isClientTLS for testing.
func IsClientTLS(r *http.Request) bool {
return isClientTLS(r)
}
// LoginRateLimitConst exposes the loginRateLimit constant: the // LoginRateLimitConst exposes the loginRateLimit constant: the
// number of FAILED login attempts one client may make against one // number of FAILED login attempts one client may make against one
// submitted username per interval. // submitted username per interval.

59
internal/reqtls/reqtls.go Normal file
View File

@@ -0,0 +1,59 @@
// Package reqtls answers one question, in one place, for the whole
// application: did this request reach the service over TLS?
//
// It exists because that question used to be answered independently in
// several packages, by hand, and the answers disagreed. The session
// cookie's Secure attribute was decided at startup from the configured
// environment while the CSRF cookie's was decided per-request, so a
// deployment behind a TLS proxy in the default environment emitted one
// Secure cookie and one non-Secure cookie on the same response.
// Everything kept working, which is exactly why nobody noticed.
//
// Any code that needs a scheme or a Secure flag must call IsTLS rather
// than reading the request itself.
package reqtls
import (
"net/http"
"strings"
)
// forwardedProtoHeader is the de-facto standard header by which a
// TLS-terminating reverse proxy reports the protocol the CLIENT used.
const forwardedProtoHeader = "X-Forwarded-Proto"
// IsTLS reports whether the client-facing connection uses TLS: either
// the request arrived over TLS directly, or a reverse proxy terminated
// TLS and said so in X-Forwarded-Proto.
//
// The header is only as trustworthy as whatever sits in front of the
// listener. A proxy that overwrites it -- which is what the deployment
// documentation requires -- makes it authoritative; a listener exposed
// directly to clients lets any client assert it. That is the same
// exposure every X-Forwarded-* consumer carries.
func IsTLS(r *http.Request) bool {
return r.TLS != nil || forwardedProto(r) == "https"
}
// forwardedProto reduces X-Forwarded-Proto to a bare, comparable
// protocol token, or "" when the header is absent or blank.
//
// Two shapes that real infrastructure emits do not survive an exact
// comparison against "https", and both name a TLS client connection:
//
// - "HTTPS", because the header value is a case-insensitive token and
// nothing obliges a proxy to emit it lowercased.
// - "https, http", because a proxy chained behind another proxy
// APPENDS its own hop instead of replacing the value. As with
// X-Forwarded-For, the leftmost element is the one nearest the
// client, so it is the element that describes the browser's
// connection -- the only hop a cookie's Secure attribute is about.
//
// Landing on the plaintext path for either of those spellings is not a
// cosmetic error: it stops gorilla/csrf enforcing the strict Referer
// check on a site that genuinely is HTTPS.
func forwardedProto(r *http.Request) string {
first, _, _ := strings.Cut(r.Header.Get(forwardedProtoHeader), ",")
return strings.ToLower(strings.TrimSpace(first))
}

View File

@@ -0,0 +1,209 @@
package reqtls_test
import (
"context"
"crypto/tls"
"net/http"
"net/http/httptest"
"testing"
"github.com/stretchr/testify/assert"
"sneak.berlin/go/webhooker/internal/reqtls"
)
// newReq builds a plaintext request with no forwarding headers.
func newReq(t *testing.T) *http.Request {
t.Helper()
return httptest.NewRequestWithContext(
context.Background(), http.MethodGet, "/", nil,
)
}
func TestIsTLS_DirectTLS(t *testing.T) {
t.Parallel()
r := newReq(t)
r.TLS = &tls.ConnectionState{}
assert.True(
t, reqtls.IsTLS(r),
"a request that arrived over TLS is TLS",
)
}
func TestIsTLS_PlaintextNoHeader(t *testing.T) {
t.Parallel()
assert.False(
t, reqtls.IsTLS(newReq(t)),
"no TLS connection and no header means plaintext",
)
}
// protoCase is one X-Forwarded-Proto spelling and the answer IsTLS
// owes it.
type protoCase struct {
name string
header string
want bool
why string
}
// protoCases enumerates the header values real infrastructure emits.
func protoCases() []protoCase {
return append(protoTLSCases(), protoPlaintextCases()...)
}
// protoTLSCases are the spellings that name a TLS client connection.
// Every one but the first is a spelling an exact == "https"
// comparison used to miss, silently downgrading a genuinely-HTTPS
// deployment to the plaintext path.
func protoTLSCases() []protoCase {
return []protoCase{
{
name: "lowercase",
header: "https",
want: true,
why: "the ordinary spelling",
},
{
name: "uppercase",
header: "HTTPS",
want: true,
why: "the value is a case-insensitive token; " +
"nothing obliges a proxy to lowercase it",
},
{
name: "mixed case",
header: "HttpS",
want: true,
why: "case folding must be total, not just the two extremes",
},
{
name: "chain with plaintext inner hop",
header: "https, http",
want: true,
why: "a chained proxy appends its hop; the leftmost " +
"element is the client-facing one",
},
{
name: "chain of two TLS hops",
header: "https,https",
want: true,
why: "appended chain with no space after the comma",
},
{
name: "trailing space",
header: "https ",
want: true,
why: "surrounding whitespace is not part of the token",
},
{
name: "leading space",
header: " https",
want: true,
why: "surrounding whitespace is not part of the token",
},
{
name: "uppercase chain",
header: "HTTPS, HTTP",
want: true,
why: "case folding and chain splitting must compose",
},
}
}
// protoPlaintextCases are the values that must NOT be read as TLS.
func protoPlaintextCases() []protoCase {
return []protoCase{
{
name: "plaintext",
header: "http",
want: false,
why: "the negative control: the proxy reports plaintext",
},
{
name: "plaintext chain with TLS inner hop",
header: "http, https",
want: false,
why: "the client-facing hop is plaintext even though " +
"an inner hop used TLS",
},
{
name: "empty",
header: "",
want: false,
why: "an empty header asserts nothing",
},
{
name: "whitespace only",
header: " ",
want: false,
why: "a blank header asserts nothing",
},
{
name: "unrelated token",
header: "ftp",
want: false,
why: "only https means TLS",
},
{
name: "https as a substring",
header: "nothttps",
want: false,
why: "matching must be on the whole token, not a substring",
},
}
}
func TestIsTLS_ForwardedProtoSpellings(t *testing.T) {
t.Parallel()
for _, tc := range protoCases() {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
r := newReq(t)
r.Header.Set("X-Forwarded-Proto", tc.header)
assert.Equal(
t, tc.want, reqtls.IsTLS(r),
"X-Forwarded-Proto %q: %s", tc.header, tc.why,
)
})
}
}
// TestIsTLS_DirectTLSBeatsPlaintextHeader pins the precedence: a
// connection this process itself terminated with TLS is a fact, and a
// header claiming otherwise does not override it.
func TestIsTLS_DirectTLSBeatsPlaintextHeader(t *testing.T) {
t.Parallel()
r := newReq(t)
r.TLS = &tls.ConnectionState{}
r.Header.Set("X-Forwarded-Proto", "http")
assert.True(
t, reqtls.IsTLS(r),
"an actual TLS connection outranks a header claiming plaintext",
)
}
// TestIsTLS_FirstHeaderValueWins covers a proxy that adds a second
// header line rather than appending to the existing one. net/http
// keeps them as separate values; the first is the client-facing hop,
// matching how the comma-separated form is read.
func TestIsTLS_FirstHeaderValueWins(t *testing.T) {
t.Parallel()
r := newReq(t)
r.Header.Add("X-Forwarded-Proto", "https")
r.Header.Add("X-Forwarded-Proto", "http")
assert.True(
t, reqtls.IsTLS(r),
"the first header line is the client-facing hop",
)
}

View File

@@ -147,10 +147,13 @@ func sentryRoutePattern(hint *sentry.EventHint) string {
// //
// The scheme is load-bearing and is kept: the SDK derives it from // The scheme is load-bearing and is kept: the SDK derives it from
// r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https" // r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"
// (interfaces.go:180), byte for byte the predicate // (interfaces.go:180), which is the reason dropping X-Forwarded-Proto
// internal/middleware/csrf.go uses, so it is the CSRF TLS decision and // from the header allowlist costs nothing. That predicate is the SDK's
// the reason dropping X-Forwarded-Proto from the header allowlist // own and is stricter than reqtls.IsTLS, which this service now uses
// costs nothing. The host is parsed.Host of the SDK's // everywhere it decides transport: the SDK reports "http" for the
// "HTTPS" and "https, http" spellings reqtls accepts. Only a reported
// scheme is affected, no decision is, so it is left to the SDK rather
// than reimplemented. The host is parsed.Host of the SDK's
// scheme://r.Host/path, so it is whatever the client's Host header // scheme://r.Host/path, so it is whatever the client's Host header
// carried: this service validates no hostname. It is kept because that // carried: this service validates no hostname. It is kept because that
// same header is on the allowlist, so scrubbing it here would withhold // same header is on the allowlist, so scrubbing it here would withhold

View File

@@ -5,6 +5,6 @@ import "github.com/gorilla/sessions"
// NewStore exposes the production cookie-store constructor so tests // NewStore exposes the production cookie-store constructor so tests
// exercise the store the application actually runs with, rather than a // exercise the store the application actually runs with, rather than a
// lookalike assembled in the test. // lookalike assembled in the test.
func NewStore(key []byte, secure bool) *sessions.CookieStore { func NewStore(key []byte) *sessions.CookieStore {
return newStore(key, secure) return newStore(key)
} }

View File

@@ -17,6 +17,7 @@ import (
"sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/database" "sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/logger" "sneak.berlin/go/webhooker/internal/logger"
"sneak.berlin/go/webhooker/internal/reqtls"
) )
const ( const (
@@ -87,7 +88,6 @@ type Session struct {
store *sessions.CookieStore store *sessions.CookieStore
key []byte // raw 32-byte auth key, also used for CSRF cookie signing key []byte // raw 32-byte auth key, also used for CSRF cookie signing
log *slog.Logger log *slog.Logger
config *config.Config
// idleTimeout is the sliding inactivity window. A session that // idleTimeout is the sliding inactivity window. A session that
// sees no authenticated request within this window expires, // sees no authenticated request within this window expires,
@@ -104,6 +104,10 @@ type Session struct {
// cookie. MaxAge is deliberately left at its zero value: for a store // cookie. MaxAge is deliberately left at its zero value: for a store
// it is set through CookieStore.MaxAge (see newStore), and for a // it is set through CookieStore.MaxAge (see newStore), and for a
// single session it is copied from the store's options. // single session it is copied from the store's options.
//
// Secure is a parameter rather than a constant because it is the one
// attribute here that is not a policy -- it is a fact about the
// connection carrying this particular response. See applyTransport.
func cookieOptions(secure bool) *sessions.Options { func cookieOptions(secure bool) *sessions.Options {
return &sessions.Options{ return &sessions.Options{
Path: "/", Path: "/",
@@ -121,14 +125,52 @@ func cookieOptions(secure bool) *sessions.Options {
// Options never touches Codecs -- so a store configured that way still // Options never touches Codecs -- so a store configured that way still
// decodes a 30-day-old cookie, leaving the cookie attribute and the // decodes a 30-day-old cookie, leaving the cookie attribute and the
// codec disagreeing about the same policy. store.MaxAge sets both. // codec disagreeing about the same policy. store.MaxAge sets both.
func newStore(key []byte, secure bool) *sessions.CookieStore { //
// The store's Secure is fixed at true, and is only a template: every
// write path overwrites it for the request in hand (applyTransport).
// It is true rather than false so that a write path added later which
// forgets to call applyTransport fails loudly -- the browser drops the
// cookie over plaintext HTTP and the developer sees it immediately --
// instead of silently shipping the authentication credential without
// Secure, which is the exact failure this store already had once.
func newStore(key []byte) *sessions.CookieStore {
store := sessions.NewCookieStore(key) store := sessions.NewCookieStore(key)
store.Options = cookieOptions(secure) store.Options = cookieOptions(true)
store.MaxAge(secondsPerDay * sessionMaxAgeDays) store.MaxAge(secondsPerDay * sessionMaxAgeDays)
return store return store
} }
// applyTransport sets the session cookie's Secure attribute from the
// transport of the request being answered.
//
// This is decided per-request, not once at startup. Deciding it at
// startup from the configured environment is what this replaces, and
// it got the DEFAULT posture wrong: "dev" is the environment when
// WEBHOOKER_ENVIRONMENT is unset, so a deployment terminating TLS at a
// proxy without also setting the environment emitted the
// authentication cookie with no Secure attribute -- silently, and on
// the same response as a CSRF cookie that did have one.
//
// gorilla/sessions makes this cheap and local: CookieStore.New gives
// every session its own copy of the store's Options, and
// CookieStore.Save renders the cookie from that copy rather than from
// the store. So the flag is set on the one session being saved,
// without a second store and without reaching across concurrent
// requests.
//
// The flag tracks the transport in BOTH directions rather than being
// latched on once seen. Secure on a plaintext response is worse than
// useless: the browser discards such a cookie without any error, so a
// latched flag would make a plain-HTTP local run impossible to log
// into. It is also why every write path must call this, including the
// deletion cookies in Destroy and Regenerate -- a Secure deletion
// cookie sent over plaintext is dropped too, leaving the session the
// caller believed it had just revoked.
func applyTransport(r *http.Request, sess *sessions.Session) {
sess.Options.Secure = reqtls.IsTLS(r)
}
// New creates a new session manager. The cookie store is // New creates a new session manager. The cookie store is
// initialized during the fx OnStart phase after the database is // initialized during the fx OnStart phase after the database is
// connected, using a session key that is auto-generated and stored // connected, using a session key that is auto-generated and stored
@@ -139,7 +181,6 @@ func New(
) (*Session, error) { ) (*Session, error) {
s := &Session{ s := &Session{
log: params.Logger.Get(), log: params.Logger.Get(),
config: params.Config,
idleTimeout: params.Config.SessionIdleTimeout, idleTimeout: params.Config.SessionIdleTimeout,
now: time.Now, now: time.Now,
} }
@@ -172,7 +213,7 @@ func New(
} }
s.key = keyBytes s.key = keyBytes
s.store = newStore(keyBytes, !params.Config.IsDev()) s.store = newStore(keyBytes)
s.log.Info("session manager initialized") s.log.Info("session manager initialized")
return nil return nil
@@ -196,12 +237,16 @@ func (s *Session) GetKey() []byte {
return s.key return s.key
} }
// Save saves the session. // Save saves the session. Every session-cookie write in the
// application goes through here or through Regenerate, which is what
// makes applyTransport a complete answer rather than a best effort.
func (s *Session) Save( func (s *Session) Save(
r *http.Request, r *http.Request,
w http.ResponseWriter, w http.ResponseWriter,
sess *sessions.Session, sess *sessions.Session,
) error { ) error {
applyTransport(r, sess)
return sess.Save(r, w) return sess.Save(r, w)
} }
@@ -340,6 +385,7 @@ func (s *Session) Regenerate(
// Destroy the old session // Destroy the old session
oldSess.Options.MaxAge = -1 oldSess.Options.MaxAge = -1
s.ClearUser(oldSess) s.ClearUser(oldSess)
applyTransport(r, oldSess)
err := oldSess.Save(r, w) err := oldSess.Save(r, w)
if err != nil { if err != nil {
@@ -368,7 +414,7 @@ func (s *Session) Regenerate(
// Apply the standard session options (the destroyed old // Apply the standard session options (the destroyed old
// session had MaxAge = -1, which store.New might inherit // session had MaxAge = -1, which store.New might inherit
// from the cookie). // from the cookie).
newSess.Options = cookieOptions(!s.config.IsDev()) newSess.Options = cookieOptions(reqtls.IsTLS(r))
newSess.Options.MaxAge = secondsPerDay * sessionMaxAgeDays newSess.Options.MaxAge = secondsPerDay * sessionMaxAgeDays
return newSess, nil return newSess, nil

View File

@@ -2,6 +2,7 @@ package session_test
import ( import (
"context" "context"
"crypto/tls"
"log/slog" "log/slog"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
@@ -73,7 +74,7 @@ func testSessionWithClock(
t.Helper() t.Helper()
key := testKey() key := testKey()
store := session.NewStore(key, false) store := session.NewStore(key)
cfg := &config.Config{ cfg := &config.Config{
Environment: config.EnvironmentDev, Environment: config.EnvironmentDev,
@@ -880,3 +881,264 @@ func TestDestroy_ThenSave_DeletesCookie(t *testing.T) {
"destroyed session cookie should have negative MaxAge", "destroyed session cookie should have negative MaxAge",
) )
} }
// --- Secure Attribute / Transport Tests ---
// transportCase describes one client-facing transport and the Secure
// attribute the session cookie must carry for it.
type transportCase struct {
name string
tls bool
header string
want bool
why string
}
// transportCases enumerates the transports the session cookie has to
// get right. Every https spelling here is one a real proxy emits.
func transportCases() []transportCase {
return []transportCase{
{
name: "direct TLS",
tls: true,
want: true,
why: "this process terminated TLS itself",
},
{
name: "proxy reports https",
header: "https",
want: true,
why: "the ordinary reverse-proxy deployment",
},
{
name: "proxy reports HTTPS",
header: "HTTPS",
want: true,
why: "the header value is a case-insensitive token",
},
{
name: "appended chain https, http",
header: "https, http",
want: true,
why: "the leftmost hop is the browser's connection",
},
{
name: "appended chain https,https",
header: "https,https",
want: true,
why: "two TLS hops, no space after the comma",
},
{
name: "trailing space",
header: "https ",
want: true,
why: "whitespace is not part of the token",
},
{
name: "proxy reports http",
header: "http",
want: false,
why: "the negative control: Secure over plaintext is " +
"dropped by the browser without a word",
},
{
name: "plaintext, no proxy",
want: false,
why: "a plain local run must stay loggable-in",
},
}
}
// transportRequest builds a request carrying the case's transport.
func (tc transportCase) request(t *testing.T) *http.Request {
t.Helper()
r := httptest.NewRequestWithContext(
context.Background(), http.MethodGet,
"http://example.com/", nil,
)
if tc.tls {
r.TLS = &tls.ConnectionState{}
}
if tc.header != "" {
r.Header.Set("X-Forwarded-Proto", tc.header)
}
return r
}
// sessionCookieFrom returns the session cookie from a response, or
// fails the test if there is none.
func sessionCookieFrom(
t *testing.T,
w *httptest.ResponseRecorder,
) *http.Cookie {
t.Helper()
for _, c := range w.Result().Cookies() {
if c.Name == session.SessionName {
return c
}
}
require.FailNow(t, "no session cookie in response")
return nil
}
// TestSave_SecureFollowsRequestTransport is the regression test for
// the defect this replaces: Secure was fixed at startup from the
// configured environment, and "dev" is the environment when
// WEBHOOKER_ENVIRONMENT is unset. A deployment behind a TLS proxy in
// that DEFAULT posture shipped the authentication cookie with no
// Secure attribute and said nothing about it.
//
// testSession builds its config with EnvironmentDev precisely so that
// the https cases below fail against the old startup-fixed behaviour.
func TestSave_SecureFollowsRequestTransport(t *testing.T) {
t.Parallel()
for _, tc := range transportCases() {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
s := testSession(t)
r := tc.request(t)
w := httptest.NewRecorder()
sess, err := s.Get(r)
require.NoError(t, err)
s.SetUser(sess, "user-1", "alice")
require.NoError(t, s.Save(r, w, sess))
assert.Equal(
t, tc.want, sessionCookieFrom(t, w).Secure,
"session cookie Secure for %q: %s",
tc.name, tc.why,
)
})
}
}
// TestSave_SecureTracksTransportBothWays pins that the flag is not
// latched. One store serves every request, so a Secure cookie set for
// a proxied request must not leak into a later plaintext response --
// the browser would silently discard that one, and a local run would
// become impossible to log into.
func TestSave_SecureTracksTransportBothWays(t *testing.T) {
t.Parallel()
s := testSession(t)
secureReq := httptest.NewRequestWithContext(
context.Background(), http.MethodGet,
"http://example.com/", nil,
)
secureReq.Header.Set("X-Forwarded-Proto", "https")
secureW := httptest.NewRecorder()
secureSess, err := s.Get(secureReq)
require.NoError(t, err)
require.NoError(t, s.Save(secureReq, secureW, secureSess))
require.True(
t, sessionCookieFrom(t, secureW).Secure,
"proxied request should produce a Secure cookie",
)
plainReq := httptest.NewRequestWithContext(
context.Background(), http.MethodGet,
"http://example.com/", nil,
)
plainW := httptest.NewRecorder()
plainSess, err := s.Get(plainReq)
require.NoError(t, err)
require.NoError(t, s.Save(plainReq, plainW, plainSess))
assert.False(
t, sessionCookieFrom(t, plainW).Secure,
"a later plaintext request must not inherit Secure from "+
"the earlier proxied one",
)
}
// TestDestroy_DeletionCookieFollowsTransport covers the trap in the
// deletion path. The store's template Secure is true, so a logout over
// plaintext that failed to track the transport would emit a Secure
// deletion cookie -- which the browser drops, leaving the session the
// user just tried to end still sitting in the jar.
func TestDestroy_DeletionCookieFollowsTransport(t *testing.T) {
t.Parallel()
s := testSession(t)
r := httptest.NewRequestWithContext(
context.Background(), http.MethodGet,
"http://example.com/", nil,
)
w := httptest.NewRecorder()
sess, err := s.Get(r)
require.NoError(t, err)
s.Destroy(sess)
require.NoError(t, s.Save(r, w, sess))
cookie := sessionCookieFrom(t, w)
require.Negative(
t, cookie.MaxAge,
"Destroy then Save should emit a deletion cookie",
)
assert.False(
t, cookie.Secure,
"a deletion cookie sent over plaintext must not be Secure, "+
"or the browser discards it and the session survives",
)
}
// TestRegenerate_BothCookiesFollowTransport covers the login path.
// Regenerate writes two cookies -- a deletion for the pre-login
// session and the new authenticated one -- and both have to match the
// transport or one of them is silently dropped.
func TestRegenerate_BothCookiesFollowTransport(t *testing.T) {
t.Parallel()
for _, tc := range transportCases() {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
s := testSession(t)
r := tc.request(t)
w := httptest.NewRecorder()
oldSess, err := s.Get(r)
require.NoError(t, err)
newSess, err := s.Regenerate(r, w, oldSess)
require.NoError(t, err)
s.SetUser(newSess, "user-1", "alice")
require.NoError(t, s.Save(r, w, newSess))
cookies := w.Result().Cookies()
require.Len(
t, cookies, 2,
"Regenerate then Save writes a deletion cookie "+
"and a replacement",
)
for _, c := range cookies {
assert.Equal(
t, tc.want, c.Secure,
"cookie %d Secure for %q: %s",
c.MaxAge, tc.name, tc.why,
)
}
})
}
}

View File

@@ -32,7 +32,6 @@ func NewForTest(
return &Session{ return &Session{
store: store, store: store,
key: key, key: key,
config: cfg,
log: log, log: log,
idleTimeout: cfg.SessionIdleTimeout, idleTimeout: cfg.SessionIdleTimeout,
now: now, now: now,