7 Commits
Author SHA1 Message Date
clawbot 0d38aea12c Keep the entrypoint UUID out of webhooker's own logs (closes #531)
check / check (push) Waiting to run
On the receiver route the access log and the per-entrypoint 429 line
name the route pattern whatever the status. A request chi never routed,
such as a dev-mode CORS preflight to the receiver, logs (unmatched).
The access log keeps only the scheme and host of a Referer. The
received line names the entrypoint and webhook IDs, and the
unknown-entrypoint line logs no path. The pattern is
middleware.ReceiverRoute, which routes.go registers the receiver with.

The README says the proxy's access log holds the UUID and must be
protected like the URL, and that a log target writes the request's
headers as received. Its access-log, rate-limit, Sentry and log-size
passages now match the code.

Model: opus-5-5
2026-10-15 14:58:35 +02:00
clawbot c0f7cc29fd Leave a delivery cut off by a stop for the next start (closes #527)
check / check (push) Waiting to run
Stopping the engine cancels the context every http and slack request is
sent with. An attempt cut off that way was recorded as failed, which for
a target with no retries, or on a last retry, ended the delivery failed
and nothing sent it again.

The shared retry core now records nothing for a failed attempt when the
engine's context is cancelled: no result, no circuit breaker outcome, no
status change, no count in the attempt metrics. The delivery stays
pending or retrying and startup recovery sends it again. A target's own
timeout is still a failed attempt. The README says what happens to an
attempt in flight at a stop and no longer claims every attempt is
recorded.

Model: opus-5-5
2026-10-15 12:29:17 +02:00
clawbot f14fe02011 Store delivery and archive times without the monotonic reading (closes #529)
check / check (push) Waiting to run
finished_at, archived_at and the updated_at stamp a re-dispatch
writes came from a bare time.Now(). The SQLite driver stores a time
as time.Time.String(), which appends the monotonic clock reading
(" m=+…") to a time read from time.Now(). All three now come from
GORM's own clock, NowFunc(), which stamps created_at, so they are
stored in the same form. The tests for each write read the stored
text back.

Model: opus-5-5
2026-10-15 11:15:35 +02:00
clawbot 573f7f986a Build the image's static binary with netgo, osusergo and sqlite_omit_load_extension (closes #525)
check / check (push) Successful in 7m24s
The image's static relink linked glibc's getaddrinfo (from Go's cgo DNS
resolver) and dlopen (from SQLite extension loading). A static binary
still needs glibc's shared libraries at run time for both, and the
Alpine runtime has none. The relink now passes the standard build tags
netgo, osusergo and sqlite_omit_load_extension through a GO_TAGS
variable, which the Makefile's build target hands to go build as -tags
next to GO_LDFLAGS, so the version stamp is composed as before.

Model: opus-5-5
2026-10-13 10:43:47 +02:00
clawbot 373a2f828d Describe code in its own terms, not by an earlier build's data (closes #522)
check / check (push) Successful in 8m12s
Several comments justified code by what an earlier build would have
left in a database or on disk. Each now says what the code does:
reserveSQLiteFile sets the mode on every open whoever created the
file, and expired treats a session lacking a deadline's timestamp as
expired. The comments on retention, resubmitted events, archive
pruning, target headers, the redactor and the delivery result view
drop their mentions of older rows. parseMaxRetries loses its
paragraph on targets saved before the ceiling existed, and neither
BeforeSave nor retentionCutoff cites a migration. Comments only.

Model: opus-5-5
2026-10-13 09:57:24 +02:00
clawbot 267d5b12f2 Escape the database path in the SQLite connection string (closes #518)
check / check (push) Successful in 7m13s
SQLite reads a file: URI's path only up to the first ? or #, and
decodes %XX escapes in it. With a data directory such as
/srv/hooks#1, every database opened the one file /srv/hooks. The
connection string is now built with url.URL, which escapes the path,
and OmitHost keeps a relative path relative.

Tests open databases in a directory whose name holds #, ? and %, and
at a relative path, and check through PRAGMA database_list that each
opened the file asked for. A handlers test comment that blamed # in
the temporary directory's path is dropped, as that is no longer true.

Model: opus-5-5
2026-10-13 09:30:24 +02:00
clawbot e73beb20df Remove upgrade and older-build text from the README (closes #520)
check / check (push) Canceled after 0s
The schema comes from 001_schema.sql, edited in place before 1.0, so the
README's upgrade procedure, downgrade note, BIND_ADDRESS upgrade note and
remarks about what older builds wrote are removed.

The description of the SQL schema files moves to a new Schema subsection
under Database Architecture, the health check command moves to Version
stamping, and the section is renamed Backup and Restore. The sentences on
session timestamps, file modes and the retention clamp now say only what
the code does.

Model: opus-5-5
2026-10-13 08:31:51 +02:00
35 changed files with 796 additions and 339 deletions
+15 -9
View File
@@ -214,16 +214,22 @@ RUN version="$(make version VERSION="$VERSION")"; \
# (Alpine.js, extracted from its tarball in 3p/) first. # (Alpine.js, extracted from its tarball in 3p/) first.
RUN make build VERSION="$VERSION" RUN make build VERSION="$VERSION"
# Rebuild with static linking for Alpine runtime. # Rebuild with static linking for the Alpine runtime. The cgo binary the
# make build already verified compilation. # step above builds is dynamically linked against glibc, which Alpine
# The CGO binary from `make build` is dynamically linked against glibc, # (musl) does not have.
# which doesn't exist on Alpine (musl). Rebuild with static linking so
# the binary runs on Alpine without glibc.
# #
# The static flags go in through GO_LDFLAGS rather than a -ldflags of # A statically linked glibc still loads shared libraries at run time for
# their own: the build target composes them with the -X that stamps the # getaddrinfo and dlopen, and Alpine has none to load, so the build tags
# version, so this relink cannot silently drop the stamp. # keep both out of the binary: netgo and osusergo select Go's own DNS
RUN CGO_ENABLED=1 make build VERSION="$VERSION" GO_LDFLAGS='-extldflags "-static"' # resolver and user lookup instead of glibc's, and
# sqlite_omit_load_extension leaves out SQLite extension loading, which
# webhooker never uses.
#
# The static flags and tags go in through GO_LDFLAGS and GO_TAGS rather
# than a -ldflags of their own: the build target composes them with the
# -X that stamps the version, so this relink cannot silently drop the
# stamp.
RUN CGO_ENABLED=1 make build VERSION="$VERSION" GO_TAGS=netgo,osusergo,sqlite_omit_load_extension GO_LDFLAGS='-extldflags "-static"'
# Runtime stage # Runtime stage
# alpine:3.21, 2026-03-17 # alpine:3.21, 2026-03-17
+6 -4
View File
@@ -16,14 +16,16 @@ VERSION ?= $(shell script/version)
# exists to correct. # exists to correct.
override VERSION := $(or $(strip $(VERSION)),$(shell script/version)) override VERSION := $(or $(strip $(VERSION)),$(shell script/version))
# Extra linker flags for the build target. The static relink in the # Extra linker flags and build tags for the build target. The static
# Dockerfile adds -extldflags here rather than passing its own -ldflags, # relink in the Dockerfile passes -extldflags and its build tags through
# so composing flags cannot drop the version stamp. # these rather than a -ldflags of its own, so composing flags cannot drop
# the version stamp.
# #
# The build target itself always passes -trimpath and -s -w, as the Go # The build target itself always passes -trimpath and -s -w, as the Go
# Dockerfile in REPO_POLICIES.md does: no build paths, symbol table or # Dockerfile in REPO_POLICIES.md does: no build paths, symbol table or
# debug information in the binary. # debug information in the binary.
GO_LDFLAGS ?= GO_LDFLAGS ?=
GO_TAGS ?=
bootstrap: bootstrap:
@script/bootstrap @script/bootstrap
@@ -53,7 +55,7 @@ check:
@script/check @script/check
build: assets build: assets
go build -trimpath -ldflags '$(strip -s -w -X main.version=$(VERSION) $(GO_LDFLAGS))' -o bin/webhooker ./cmd/webhooker go build -trimpath -tags '$(GO_TAGS)' -ldflags '$(strip -s -w -X main.version=$(VERSION) $(GO_LDFLAGS))' -o bin/webhooker ./cmd/webhooker
run: build run: build
./bin/webhooker ./bin/webhooker
+119 -115
View File
@@ -465,10 +465,7 @@ idle timestamp is rewritten at most once per tenth of the idle window rather
than on every request, which means a session may expire up to 10% early relative than on every request, which means a session may expire up to 10% early relative
to the user's true last request, but never late. to the user's true last request, but never late.
Both clocks are anchored by timestamps stored in the session cookie. Sessions Both clocks are anchored by timestamps stored in the session cookie.
issued before this feature existed carry neither, so they are treated as
expired: upgrading to a build that has it logs every existing session out once,
and those users sign in again.
#### Invalid values abort startup #### Invalid values abort startup
@@ -702,11 +699,11 @@ app as that user.
`webhooker.db` holds target configuration in plaintext — bearer tokens, API `webhooker.db` holds target configuration in plaintext — bearer tokens, API
keys, Slack webhook URLs — along with the session encryption key, so webhooker keys, Slack webhook URLs — along with the session encryption key, so webhooker
creates every SQLite file it owns `0600`: each database and both of its `-wal` creates every SQLite file it owns `0600`: each database and both of its `-wal`
and `-shm` sidecars, across all three tiers. Files an earlier build left `0644` and `-shm` sidecars, across all three tiers. Any of them found at another mode
are tightened when they are opened. The directory's `0750` is defence in depth — is set to `0600` when the database is opened. The directory's `0750` is defence
it stops other local users listing the directory and learning your webhook UUIDs in depth — it stops other local users listing the directory and learning your
from the `events-{uuid}.db` filenames — not the barrier protecting the webhook UUIDs from the `events-{uuid}.db` filenames — not the barrier protecting
credentials. the credentials.
### Running under upaas ### Running under upaas
@@ -805,7 +802,12 @@ comes up, serves pages, and is broken in a way nothing reports.
proxy's log names it regardless. nginx's default `combined` format already proxy's log names it regardless. nginx's default `combined` format already
logs `$remote_addr`; do not replace it with one that drops the client logs `$remote_addr`; do not replace it with one that drops the client
address, and retain those logs as long as you would want to answer a question address, and retain those logs as long as you would want to answer a question
about traffic. about traffic. That log also records the full request path, so it holds the
entrypoint UUID of every event a sender posts. webhooker's own log does not,
apart from the line a `log` target writes. Protect the proxy's log as you
would the entrypoint URLs themselves: anyone who can read it can post events
to every entrypoint in it (see
[The entrypoint URL is the authentication secret](#the-entrypoint-url-is-the-authentication-secret)).
### nginx ### nginx
@@ -831,7 +833,9 @@ server {
client_max_body_size 1m; client_max_body_size 1m;
# $remote_addr is the client. webhooker's own log names it, as # $remote_addr is the client. webhooker's own log names it, as
# clientIP, only while TRUSTED_PROXIES covers this proxy. # clientIP, only while TRUSTED_PROXIES covers this proxy. The
# request path in this log holds the entrypoint UUID, so protect
# the file like the entrypoint URL itself.
access_log /var/log/nginx/webhooker.access.log combined; access_log /var/log/nginx/webhooker.access.log combined;
location / { location / {
@@ -918,7 +922,7 @@ replaces the `max-age` it stored, so to end the policy sooner, set a short
`HSTS_MAX_AGE` such as `1s` and keep it until returning browsers have picked it `HSTS_MAX_AGE` such as `1s` and keep it until returning browsers have picked it
up, or have a reverse proxy send `max-age=0`. up, or have a reverse proxy send `max-age=0`.
## Backup, Restore, and Upgrades ## Backup and Restore
### What to back up ### What to back up
@@ -1071,60 +1075,14 @@ beside it, or wait until there are none.
4. Start the service. The container gives the directory and the restored files 4. Start the service. The container gives the directory and the restored files
to the `webhooker` user before the app starts, whoever restored them (see to the `webhooker` user before the app starts, whoever restored them (see
[Running with Docker](#running-with-docker)). Each restored database gets any [Running with Docker](#running-with-docker)).
of its SQL migrations it has not had as it is opened (see
[Upgrades](#upgrades)).
### Upgrades
**Back up before every upgrade.** Each kind of database file has its schema in
SQL files built into the binary, one directory per kind under
`internal/db/migrations/`. In each, `000_migration.sql` creates the
`schema_migrations` table, which records the number of every file the database
has had, and `001_schema.sql` holds the whole schema. Opening a database runs,
in one transaction, every file in its directory that `schema_migrations` does
not list:
- `main/` for the main database, on connect — settings, users, API keys,
webhooks, entrypoints and targets
- `events/` for each event database, when it is lazily opened — events,
deliveries, delivery results and their running totals
- `archive/` for each archive database, on every open and reopen
There are no down migrations.
Upgrade procedure:
1. Stop the service.
2. Back up `DATA_DIR` using one of the procedures above.
3. Pull the new image and start it.
4. Confirm `database migrations completed` in the logs before putting traffic
back on it.
5. Confirm the new build is the one running:
`curl -s http://host:8080/.well-known/healthcheck` reports the version it was
stamped with (see [Version stamping](#version-stamping)).
**Upgrading past the introduction of `BIND_ADDRESS`:** earlier versions always
bound every interface. **Container deployments are unaffected** — the image
ships `ENV BIND_ADDRESS=0.0.0.0`, so a `docker run` or Compose service that
worked before still works with nothing changed.
A **bare binary** is the case that changes: the listener now binds `127.0.0.1`
unless `BIND_ADDRESS` says otherwise, so a deployment that relied on reaching it
from another host becomes unreachable until it sets the address the proxy
connects to. Check the `bindAddress` field of the startup log to see what a
running process bound. See [Bind address](#bind-address).
**Downgrade is unsupported.** Once a newer binary has migrated the files there
is no way to move them back. The only supported way back to an older version is
restoring the pre-upgrade backup, which discards everything received since that
backup was taken.
### Version stamping ### Version stamping
The binary reports its version at `/.well-known/healthcheck` (the `version` The binary reports its version at `/.well-known/healthcheck` (the `version`
field), in the UI footer, and in the startup log line (`msg=starting`, field), in the UI footer, and in the startup log line (`msg=starting`,
`version=...`). It is also the Sentry release name, as `webhooker-{version}`. `version=...`). It is also the Sentry release name, as `webhooker-{version}`.
`curl -s http://host:8080/.well-known/healthcheck` shows which build is running.
The value is stamped in at build time by the linker; it is not read from a file The value is stamped in at build time by the linker; it is not read from a file
at runtime, so it identifies the build itself. at runtime, so it identifies the build itself.
@@ -1209,7 +1167,16 @@ What that means for an operator:
- **The URL is a capability, so treat it as a secret.** Keep it out of logs, - **The URL is a capability, so treat it as a secret.** Keep it out of logs,
ticket bodies, chat messages and screenshots. Anyone who reads it anywhere can ticket bodies, chat messages and screenshots. Anyone who reads it anywhere can
post events as that sender. post events as that sender. Apart from a `log` target's line, webhooker's own
log lines never carry the UUID: they name a request to the receiver by the
route pattern `/h/{uuid}`, the `webhook request received` line names the
entrypoint by its `entrypoint_id`, and the access log keeps only the scheme
and host of a `Referer`. A `log` target writes the request's headers as
received, so a `Referer` naming the entrypoint URL appears in its line, as it
does when a sender has followed a redirect from `http://` to `https://`. The
reverse proxy's access log does carry the UUID, in the request path, so it
must be protected like the URL itself (see
[Deployment behind a reverse proxy](#deployment-behind-a-reverse-proxy)).
- **Rotating means minting a new entrypoint, not changing a key.** There is no - **Rotating means minting a new entrypoint, not changing a key.** There is no
way to rotate the UUID in place. To retire one, delete the entrypoint (or way to rotate the UUID in place. To retire one, delete the entrypoint (or
deactivate it, which answers `410`) and create a new one, then point the deactivate it, which answers `410`) and create a new one, then point the
@@ -1366,20 +1333,22 @@ webhooker solves this by acting as a durable intermediary:
nothing is lost if downstream targets are unavailable. nothing is lost if downstream targets are unavailable.
2. **Guaranteed delivery** — Events are queued for delivery to each configured 2. **Guaranteed delivery** — Events are queued for delivery to each configured
target. Failed deliveries are retried with configurable backoff. Every target. Failed deliveries are retried with configurable backoff. Delivery
delivery attempt is logged with status codes, response bodies, and timing. attempts are logged with status codes, response bodies, and timing.
**That guarantee is at-least-once, not exactly-once.** When a send reaches **That guarantee is at-least-once, not exactly-once.** When a send reaches
its target but the write recording that outcome fails, the delivery is its target but the write recording that outcome fails, the delivery is
deliberately left in a recoverable state rather than marked done — losing a deliberately left in a recoverable state rather than marked done — losing a
delivery is the worse failure — so the pending sweep picks it up about delivery is the worse failure — so the pending sweep picks it up about
fifteen minutes later, or the next restart does, and the target receives a fifteen minutes later, or the next restart does, and the target receives a
payload it already got. webhooker adds no delivery identifier of its own to payload it already got. A send still in flight when the service stops is
an outbound request, so **make your receiver idempotent** against whatever left the same way: its attempt is not recorded, and the next start sends it
the payload itself carries. again (see Shutdown). webhooker adds no delivery identifier of its own to an
outbound request, so **make your receiver idempotent** against whatever the
payload itself carries.
3. **Observability** — Full request/response logging for every webhook received 3. **Observability** — Full request/response logging for every webhook received
and every delivery attempted. Prometheus metrics expose volume, latency, and and for delivery attempts. Prometheus metrics expose volume, latency, and
error rates. The web UI provides real-time visibility into event flow. error rates. The web UI provides real-time visibility into event flow.
4. **Fan-out** — A single incoming webhook can be delivered to multiple targets 4. **Fan-out** — A single incoming webhook can be delivered to multiple targets
@@ -1583,8 +1552,7 @@ The cap is not arbitrary: the reaper computes its cutoff as a `time.Duration`,
an int64 nanosecond count, and a longer period overflows it. An overflowed an int64 nanosecond count, and a longer period overflows it. An overflowed
cutoff lands in the future, where it matches every row, so the sweep would cutoff lands in the future, where it matches every row, so the sweep would
delete every event the webhook has instead of none. The reaper also clamps the delete every event the webhook has instead of none. The reaper also clamps the
value it is given, so a row written by an older version cannot trigger that value it reads to the cap, so no stored value can trigger that either.
either.
#### Entrypoint #### Entrypoint
@@ -1818,7 +1786,7 @@ is what bounds it.
#### DeliveryResult #### DeliveryResult
The result of a single delivery attempt. Every attempt (including retries) is The result of a single delivery attempt. Every attempt (including retries) is
individually logged for full observability. individually logged, except one cut off by a stop (see Shutdown).
| Field | Type | Description | | Field | Type | Description |
| --------------- | ------- | ----------------------------------------- | | --------------- | ------- | ----------------------------------------- |
@@ -1967,7 +1935,7 @@ and application state:
- **APIKeys** — programmatic access credentials - **APIKeys** — programmatic access credentials
On first startup the main database is created from its SQL files (see On first startup the main database is created from its SQL files (see
[Upgrades](#upgrades)), a session encryption key is generated and stored, and an [Schema](#schema)), a session encryption key is generated and stored, and an
`admin` user is created. `admin` user is created.
**Per-Webhook Event Databases** (`{DATA_DIR}/events-{webhook_uuid}.db`) — each **Per-Webhook Event Databases** (`{DATA_DIR}/events-{webhook_uuid}.db`) — each
@@ -2164,6 +2132,21 @@ The database uses the
though CGO is required at build time due to the transitive `mattn/go-sqlite3` though CGO is required at build time due to the transitive `mattn/go-sqlite3`
dependency from `gorm.io/driver/sqlite`. dependency from `gorm.io/driver/sqlite`.
#### Schema
Each kind of database file has its schema in SQL files built into the binary,
one directory per kind under `internal/db/migrations/`. In each,
`000_migration.sql` creates the `schema_migrations` table, which records the
number of every file the database has had, and `001_schema.sql` holds the whole
schema. Opening a database runs, in one transaction, every file in its directory
that `schema_migrations` does not list:
- `main/` for the main database, on connect — settings, users, API keys,
webhooks, entrypoints and targets
- `events/` for each event database, when it is lazily opened — events,
deliveries, delivery results and their running totals
- `archive/` for each archive database, on every open and reopen
### Request Flow ### Request Flow
``` ```
@@ -2241,12 +2224,16 @@ This means:
buffer rather than spawning more goroutines. buffer rather than spawning more goroutines.
- **Independent results** — each worker records its own delivery result in the - **Independent results** — each worker records its own delivery result in the
per-webhook database without coordination. per-webhook database without coordination.
- **Graceful shutdown** — cancel the context, workers finish their current task - **Graceful shutdown** — the stop hook cancels the workers' context. A worker
and exit. The stop hook waits for the pool via `lifecycle.WaitForShutdown`, may still take tasks already queued before it exits. An `http` or `slack`
which bounds that wait by fx's stop timeout rather than blocking forever on a request in flight is cut off, and one started after the cancel fails at once.
wedged worker. On timeout it logs at `ERROR` and returns an error, and the Neither is recorded or counted in the metrics, and the next start sends the
goroutines that did not finish are still running — an unclean shutdown is delivery again (see Shutdown). A `database` or `log` task runs as normal. The
reported rather than hidden. stop hook waits for the pool via `lifecycle.WaitForShutdown`, which bounds
that wait by fx's stop timeout rather than blocking forever on a wedged
worker. On timeout it logs at `ERROR` and returns an error, and the goroutines
that did not finish are still running — an unclean shutdown is reported rather
than hidden.
**Recovery paths:** **Recovery paths:**
@@ -2352,7 +2339,7 @@ getting anywhere.
| Metric | Type | Meaning | | Metric | Type | Meaning |
| -------------------------------------- | --------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | -------------------------------------- | --------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
| `webhooker_events_received_total` | counter | Events received and durably stored. Compare against the delivery counters on one dashboard | | `webhooker_events_received_total` | counter | Events received and durably stored. Compare against the delivery counters on one dashboard |
| `webhooker_delivery_attempts_total` | counter | Delivery attempts actually dispatched to a target. A delivery a circuit breaker refused is not one: it is counted as a retry instead, but only when the refusal moves it into `retrying` | | `webhooker_delivery_attempts_total` | counter | Delivery attempts actually dispatched to a target. A delivery a circuit breaker refused is not one: it is counted as a retry instead, but only when the refusal moves it into `retrying`. An attempt cut off by a stop is not counted (see Shutdown) |
| `webhooker_deliveries_succeeded_total` | counter | Deliveries that reached `delivered` | | `webhooker_deliveries_succeeded_total` | counter | Deliveries that reached `delivered` |
| `webhooker_deliveries_failed_total` | counter | Deliveries that failed terminally and will not be retried | | `webhooker_deliveries_failed_total` | counter | Deliveries that failed terminally and will not be retried |
| `webhooker_delivery_retries_total` | counter | Deliveries put back into `retrying` | | `webhooker_delivery_retries_total` | counter | Deliveries put back into `retrying` |
@@ -2451,27 +2438,32 @@ log volume it caps rather than eliminates. A path that names no entrypoint is
recorded by the handler at `DEBUG`, and the aggregate limiter logs its own recorded by the handler at `DEBUG`, and the aggregate limiter logs its own
rejections at `DEBUG` and without the path, so neither appears at all under the rejections at `DEBUG` and without the path, so neither appears at all under the
default level. The per-entrypoint limiter is the loud one: it logs every default level. The per-entrypoint limiter is the loud one: it logs every
rejection at `WARN` with the request path, which on this route is rejection at `WARN`, naming the route pattern `/h/{uuid}` rather than the
attacker-controlled text. A client hammering a single invented path is served request path. A client hammering a single invented path is served
`RECEIVER_RATE_LIMIT` requests and has the rest of its aggregate budget rejected `RECEIVER_RATE_LIMIT` requests and has the rest of its aggregate budget rejected
there, so the aggregate limit is what bounds the _number_ of those `WARN` lines there, so the aggregate limit is what bounds the _number_ of those `WARN` lines
— to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the — to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the
defaults, where before it there was no bound at all. Their _width_ is bounded by defaults, where before it there was no bound at all. The access log is bounded
the field budgets below, the same ones the access log spends. The access log is by neither limit: every request is recorded once at `INFO`, served or rejected
bounded by neither limit: every request is recorded once at `INFO`, served or alike.
rejected alike.
What the access log does bound is the _content_ of those lines. A 3xx or 4xx What the access log does bound is the _content_ of those lines. On the receiver
response logs the chi route pattern — `/h/{uuid}`, `/user/{username}//`, or the route it logs the route pattern `/h/{uuid}` whatever the status, because the
literal `(unmatched)` when the request hit no route at all — in place of the concrete path carries the entrypoint UUID, which is the entrypoint's credential
concrete URL. Those are the outcomes an unauthenticated client can drive for (see
free: 404 and 429 on any invented receiver path, a login redirect on any [The entrypoint URL is the authentication secret](#the-entrypoint-url-is-the-authentication-secret)).
invented profile path. Logging the URL there would let a flood write text of its A request chi never routed, because it matched no route or because a middleware
own choosing, at a length of its own choosing, into the log. 2xx and 5xx answered it first, logs the literal `(unmatched)` whatever the status. In the
responses keep the concrete path — a success resolved against a static route or `dev` environment the CORS middleware answers a preflight that way, so a
against the operator's own data (on the receiver, against a stored entrypoint preflight to the receiver does not log its UUID either. On every other route, a
UUID), and a 5xx is a bug in this service, where the exact path is the evidence 3xx or 4xx response logs the chi route pattern, such as `/user/{username}//`, in
and no client can provoke one at will. place of the concrete URL. Those are the outcomes an unauthenticated client can
drive for free: a 404 on any invented path, a login redirect on any invented
profile path. Logging the URL there would let a flood write text of its own
choosing, at a length of its own choosing, into the log. 2xx and 5xx responses
keep the concrete path — a success resolved against a static route or against
the operator's own data, and a 5xx is a bug in this service, where the exact
path is the evidence and no client can provoke one at will.
The query string is never logged; it is replaced by the fixed marker The query string is never logged; it is replaced by the fixed marker
`?(redacted)`. It is client-chosen on every route, and `?(redacted)`. It is client-chosen on every route, and
@@ -2483,6 +2475,11 @@ to, `notice`, which names the line a page shows after an action, and the event
log's `show`, which picks the events it lists. A query string sent to an log's `show`, which picks the events it lists. A query string sent to an
entrypoint is not lost either: the event stores it, and the event log shows it. entrypoint is not lost either: the event stores it, and the event log shows it.
The `referer` field keeps only the scheme and host of the request's `Referer`,
and logs `(redacted)` for one without them, because its path can be an
entrypoint URL: a sender that follows the `http://` to `https://` redirect in
the nginx example sends the URL it was redirected from.
Client-supplied request content does not leave the host by the other route Client-supplied request content does not leave the host by the other route
either. The Sentry SDK attaches the request to every event it captures, either. The Sentry SDK attaches the request to every event it captures,
independently of the access log, and `SendDefaultPII=false` does not cover all independently of the access log, and `SendDefaultPII=false` does not cover all
@@ -2497,9 +2494,10 @@ The same hook rewrites the request URL. The SDK builds it as
`scheme://host/path` from the concrete path, which on the receiver route is `scheme://host/path` from the concrete path, which on the receiver route is
`/h/<uuid>` in full — and that UUID is a write capability, not an identifier: `/h/<uuid>` in full — and that UUID is a write capability, not an identifier:
anyone holding it can post events this service accepts and its targets then anyone holding it can post events this service accepts and its targets then
deliver. A tracker has its own retention, access control and deletion policy, so deliver. What is sent is the chi route pattern instead: `http://host/h/{uuid}`.
the rule the access log follows above does not carry across that boundary. What A tracker has its own retention, access control and deletion policy, so the
is sent is the chi route pattern instead: `http://host/h/{uuid}`. pattern is sent on every route, including the 2xx and 5xx responses outside the
receiver for which the access log keeps the concrete path.
The scheme and the host are kept, and everything else in the URL is discarded The scheme and the host are kept, and everything else in the URL is discarded
rather than edited, so a future SDK version that starts appending a query string rather than edited, so a future SDK version that starts appending a query string
@@ -2628,9 +2626,7 @@ than it:
| ------------------------------------------ | ------- | ------------------- | ------------------------------------------ | | ------------------------------------------ | ------- | ------------------- | ------------------------------------------ |
| `request body exceeds limit` (413) | `WARN` | path, method | yes — `MaxBodySize` precedes `RequireAuth` | | `request body exceeds limit` (413) | `WARN` | path, method | yes — `MaxBodySize` precedes `RequireAuth` |
| `csrf: token validation failed` (403) | `WARN` | path, method | yes — `CSRF` precedes `RequireAuth` | | `csrf: token validation failed` (403) | `WARN` | path, method | yes — `CSRF` precedes `RequireAuth` |
| `... rate limit exceeded` (429) | `WARN` | path | yes, on the receiver |
| `auth middleware: unauthenticated request` | `DEBUG` | path, method | yes, by definition | | `auth middleware: unauthenticated request` | `DEBUG` | path, method | yes, by definition |
| `entrypoint not found` | `DEBUG` | entrypoint UUID | yes, on the receiver |
| `user not found` / `invalid password` | `DEBUG` | username | yes, on the sign-in form | | `user not found` / `invalid password` | `DEBUG` | username | yes, on the sign-in form |
| `login failure limit exceeded` (429) | `WARN` | path | yes, on the sign-in form | | `login failure limit exceeded` (429) | `WARN` | path | yes, on the sign-in form |
| `password verification capacity exhausted` | `WARN` | path | yes, on the sign-in form | | `password verification capacity exhausted` | `WARN` | path | yes, on the sign-in form |
@@ -2658,13 +2654,12 @@ wider of the two handlers spends more on than the client spent sending them.
Every case holds each line to the 2,560-byte ceiling. That per-line ceiling is Every case holds each line to the 2,560-byte ceiling. That per-line ceiling is
what the figure above states, and every row establishes it. what the figure above states, and every row establishes it.
Three of the sites go further and bound the whole flood's output — the total Two of the sites go further and bound the whole flood's output — the total bytes
bytes a run of distinct invented values wrote, which is the shape an operator a run of distinct invented values wrote, which is the shape an operator sizing
sizing storage cares about. They are `request body exceeds limit` storage cares about. They are `request body exceeds limit`
(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`), (`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`) and `user not found`
`entrypoint not found` and `user not found` (the last two through (through `assertBoundedFlood`). The other rows carry no aggregate assertion; the
`assertBoundedFlood`). The other rows carry no aggregate assertion; the per-line per-line ceiling is what they establish.
ceiling is what they establish.
`internal/logfield/logfield_test.go` measures the per-rune charge against what `internal/logfield/logfield_test.go` measures the per-rune charge against what
the handlers really emit, over roughly 3,000 code points on each, so an the handlers really emit, over roughly 3,000 code points on each, so an
@@ -2682,7 +2677,7 @@ everything else, so its lines take the level the operator set and the handler
`internal/logger` selected, and every value it emits is spent through the same `internal/logger` selected, and every value it emits is spent through the same
`internal/logfield` budget. A record-not-found is not logged as an error: it is `internal/logfield` budget. A record-not-found is not logged as an error: it is
the expected outcome on both of those paths, and each handler already records the expected outcome on both of those paths, and each handler already records
its own miss at `DEBUG` — bounded, per the table above — without the SQL. Slow its own miss at `DEBUG`, without the SQL and within the ceiling above. Slow
statements are kept, at `WARN`, above the same 200 ms threshold GORM used and statements are kept, at `WARN`, above the same 200 ms threshold GORM used and
with the statement bounded, because that report is the one thing GORM's logger with the statement bounded, because that report is the one thing GORM's logger
gave an operator that nothing else here does. The adapter orders its cases gave an operator that nothing else here does. The adapter orders its cases
@@ -3319,7 +3314,8 @@ stop-hook log:
3. `server` — the HTTP drain, bounded by `server.ShutdownTimeout` (**3 3. `server` — the HTTP drain, bounded by `server.ShutdownTimeout` (**3
seconds**) and by what the hooks before it left, then a Sentry flush if seconds**) and by what the hooks before it left, then a Sentry flush if
`SENTRY_DSN` is set `SENTRY_DSN` is set
4. `delivery.Engine` — waits for its workers, then closes the archive databases 4. `delivery.Engine` — cuts off any `http` or `slack` request in flight, waits
for its workers, then closes the archive databases
5. `healthcheck` 5. `healthcheck`
6. `WebhookDBManager` 6. `WebhookDBManager`
7. the database close 7. the database close
@@ -3330,6 +3326,12 @@ by the stop context, so a wedge there consumes the 5 seconds before the HTTP
server hook is ever entered. The hooks after the server are microsecond-scale in server hook is ever entered. The hooks after the server are microsecond-scale in
normal operation. normal operation.
The delivery engine cancels a delivery request in flight. That attempt is not
recorded or counted in the metrics, and the delivery keeps its `pending` or
`retrying` status, so startup recovery sends it again on the next start (see
Recovery paths under Bounded Worker Pool). If the receiver already had it, it
receives it twice: the at-least-once duplicate described under Rationale.
The HTTP drain budget is deliberately **shorter** than the sequence budget. Were The HTTP drain budget is deliberately **shorter** than the sequence budget. Were
the two equal, a drain that used its whole budget would exhaust the sequence the two equal, a drain that used its whole budget would exhaust the sequence
budget at the instant it finished, and every later hook — the delivery engine, budget at the instant it finished, and every later hook — the delivery engine,
@@ -3454,12 +3456,14 @@ fixed independently of the compiler's:
phases and the `css-check` and `markdown-check` stages passing (it copies a phases and the `css-check` and `markdown-check` stages passing (it copies a
file from each), runs `make build` (which extracts Alpine.js from `3p/` file from each), runs `make build` (which extracts Alpine.js from `3p/`
first), and then rebuilds the binary with `CGO_ENABLED=1` and static linking first), and then rebuilds the binary with `CGO_ENABLED=1` and static linking
so it runs on musl. Both builds go through `make build`, the relink adding so it runs on musl, with the build tags `netgo`, `osusergo` and
its `-extldflags` via `GO_LDFLAGS`, so neither can drop the `-X` that stamps `sqlite_omit_load_extension` so it needs none of glibc's shared libraries at
the version. The version is the `VERSION` build arg if one is given, run time. Both builds go through `make build`, the relink adding its
otherwise derived from the `.git` in the context, and the stage fails if a `-extldflags` via `GO_LDFLAGS` and its tags via `GO_TAGS`, so neither can
context with `.git` would stamp an empty version, `dev` or `unknown` (see drop the `-X` that stamps the version. The version is the `VERSION` build arg
[Version stamping](#version-stamping)). if one is given, otherwise derived from the `.git` in the context, and the
stage fails if a context with `.git` would stamp an empty version, `dev` or
`unknown` (see [Version stamping](#version-stamping)).
7. **Runtime stage** (`alpine:3.21`) — copies the static binary and 7. **Runtime stage** (`alpine:3.21`) — copies the static binary and
`deploy/docker-entrypoint.sh`, creates the `/var/lib/webhooker` directory for `deploy/docker-entrypoint.sh`, creates the `/var/lib/webhooker` directory for
all SQLite databases, exposes port 8080, and includes a health check against all SQLite databases, exposes port 8080, and includes a health check against
+1 -2
View File
@@ -45,8 +45,7 @@ type Event struct {
// ResubmittedFromID names the event this one was copied from by // ResubmittedFromID names the event this one was copied from by
// an operator resubmit. It is nil for an event that arrived on // an operator resubmit. It is nil for an event that arrived on
// the receiver, which is every event created before the column // the receiver. It is not a foreign key: the source event can be
// existed. It is not a foreign key: the source event can be
// reaped by retention while its copies remain, and the id is // reaped by retention while its copies remain, and the id is
// kept as the record of where the copy came from either way. // kept as the record of where the copy came from either way.
ResubmittedFromID *string `gorm:"type:uuid;index:idx_events_resubmitted_from_id,priority:1;index:idx_events_entrypoint_id,priority:3" json:"resubmittedFromId,omitempty"` ResubmittedFromID *string `gorm:"type:uuid;index:idx_events_resubmitted_from_id,priority:1;index:idx_events_entrypoint_id,priority:3" json:"resubmittedFromId,omitempty"`
+3 -3
View File
@@ -82,7 +82,7 @@ type Webhook struct {
// value while building the insert statement, which runs after // value while building the insert statement, which runs after
// BeforeSave; rewriting any later than this loses that race and the // BeforeSave; rewriting any later than this loses that race and the
// row lands at 30 days. Living on the model also means a future call // row lands at 30 days. Living on the model also means a future call
// site — a REST API, a fixture, a migration — cannot bypass it. // site, such as a REST API or a fixture, cannot bypass it.
func (w *Webhook) BeforeSave(_ *gorm.DB) error { func (w *Webhook) BeforeSave(_ *gorm.DB) error {
if w.RetentionDays <= 0 { if w.RetentionDays <= 0 {
w.RetentionDays = RetentionForeverDays w.RetentionDays = RetentionForeverDays
@@ -98,8 +98,8 @@ func (w *Webhook) BeforeSave(_ *gorm.DB) error {
// are exempt from reaping. // are exempt from reaping.
// //
// It accepts the RetentionForeverDays sentinel written by BeforeSave // It accepts the RetentionForeverDays sentinel written by BeforeSave
// and, defensively, the non-positive values that rows written before // and, defensively, any non-positive value, which BeforeSave treats
// the sentinel existed may still carry. // as a request to retain forever.
func retainsForever(retentionDays int) bool { func retainsForever(retentionDays int) bool {
return retentionDays <= 0 || return retentionDays <= 0 ||
retentionDays >= RetentionForeverDays retentionDays >= RetentionForeverDays
+1 -1
View File
@@ -253,7 +253,7 @@ func (r *RetentionReaper) reapWebhook(
// row in the database: the sweep then deletes every event, delivery, // row in the database: the sweep then deletes every event, delivery,
// and delivery result, including ones created seconds ago. Rejecting // and delivery result, including ones created seconds ago. Rejecting
// out-of-range input at the form is the primary guard; saturating here // out-of-range input at the form is the primary guard; saturating here
// means an old row, a migration, or a future call site cannot turn a // means a value that reaches the row by any other path cannot turn a
// too-large retention into total data loss. // too-large retention into total data loss.
func retentionCutoff( func retentionCutoff(
now time.Time, now time.Time,
+2 -3
View File
@@ -118,9 +118,8 @@ const SQLiteFilePerm fs.FileMode = 0o600
// SQLite still reports the absence rather than this function // SQLite still reports the absence rather than this function
// materializing an empty database the caller asked not to create. // materializing an empty database the caller asked not to create.
// //
// Chmod of a file that already exists is what tightens a data // The mode is set on every open, whoever created the file, so a
// directory an earlier build left at 0644 — including a developer's // database or sidecar found at a wider mode is tightened too.
// own scratch directory — without any migration machinery.
func reserveSQLiteFile(path string, create bool) error { func reserveSQLiteFile(path string, create bool) error {
if create { if create {
// gosec G304: the path is the database file the caller asked // gosec G304: the path is the database file the caller asked
+31 -5
View File
@@ -2,6 +2,7 @@ package database_test
import ( import (
"context" "context"
"database/sql"
"os" "os"
"path/filepath" "path/filepath"
"strings" "strings"
@@ -120,7 +121,6 @@ func TestMainDBAppliesPragmasOnALiveHandle(t *testing.T) {
func TestOpenSQLiteOpensThePathAskedFor(t *testing.T) { func TestOpenSQLiteOpensThePathAskedFor(t *testing.T) {
t.Parallel() t.Parallel()
ctx := context.Background()
dir := filepath.Join(t.TempDir(), "hooks#1?x%41") dir := filepath.Join(t.TempDir(), "hooks#1?x%41")
require.NoError(t, os.Mkdir(dir, 0o700)) require.NoError(t, os.Mkdir(dir, 0o700))
@@ -137,15 +137,42 @@ func TestOpenSQLiteOpensThePathAskedFor(t *testing.T) {
t.Cleanup(func() { assert.NoError(t, sqlDB.Close()) }) t.Cleanup(func() { assert.NoError(t, sqlDB.Close()) })
// database_list names the file SQLite actually opened, with assertOpenedFile(t, sqlDB, path)
// symlinks resolved, so the files are compared, not the names. }
}
// TestOpenSQLiteOpensARelativePath opens a database at a path relative
// to the working directory, which is what a relative DATA_DIR such as
// the README's DATA_DIR=../webhooker-data gives OpenSQLite.
//
//nolint:paralleltest // t.Chdir moves the whole process.
func TestOpenSQLiteOpensARelativePath(t *testing.T) {
t.Chdir(t.TempDir())
require.NoError(t, os.Mkdir("data", 0o700))
path := filepath.Join("data", database.MainDBFileName)
sqlDB, err := database.OpenSQLite(path, database.SQLiteModeCreate)
require.NoError(t, err)
defer func() { require.NoError(t, sqlDB.Close()) }()
assertOpenedFile(t, sqlDB, path)
}
// assertOpenedFile checks that sqlDB is the SQLite file at path.
// database_list names the file SQLite actually opened, as an absolute
// path with symlinks resolved, so the files are compared, not the names.
func assertOpenedFile(t *testing.T, sqlDB *sql.DB, path string) {
t.Helper()
var ( var (
seq int seq int
schema, file string schema, file string
) )
require.NoError(t, sqlDB. require.NoError(t, sqlDB.
QueryRowContext(ctx, "pragma database_list"). QueryRowContext(t.Context(), "pragma database_list").
Scan(&seq, &schema, &file)) Scan(&seq, &schema, &file))
asked, err := os.Stat(path) asked, err := os.Stat(path)
@@ -158,7 +185,6 @@ func TestOpenSQLiteOpensThePathAskedFor(t *testing.T) {
t, os.SameFile(asked, opened), t, os.SameFile(asked, opened),
"asked for %s, SQLite opened %s", path, file, "asked for %s, SQLite opened %s", path, file,
) )
}
} }
// TestConcurrentReaderDoesNotBlockWrites is the unit-scale form of the // TestConcurrentReaderDoesNotBlockWrites is the unit-scale form of the
+1 -2
View File
@@ -201,8 +201,7 @@ func (s *ArchiveSweeper) sweep(ctx context.Context) {
// sweepTarget prunes the archive of a single database target. // sweepTarget prunes the archive of a single database target.
// A missing, empty, or "never" expiry parses as a zero duration // A missing, empty, or "never" expiry parses as a zero duration
// and is skipped entirely, so those archives keep exactly the // and is skipped entirely, so those archives are never pruned.
// behaviour they had before the sweep existed.
func (s *ArchiveSweeper) sweepTarget(target *database.Target) { func (s *ArchiveSweeper) sweepTarget(target *database.Target) {
expiry, err := parseArchiveExpiry(target.Config) expiry, err := parseArchiveExpiry(target.Config)
if err != nil { if err != nil {
+13 -2
View File
@@ -32,8 +32,9 @@ func targetTotals(
// TestUpdateDeliveryStatus_FinishTimeAndTargetTotals pins what a status // TestUpdateDeliveryStatus_FinishTimeAndTargetTotals pins what a status
// write records for the webhook page's statistics: the time a delivery // write records for the webhook page's statistics: the time a delivery
// finished, set only when it becomes delivered or failed, and one more // finished, set only when it becomes delivered or failed and stored in
// on its target's delivered or failed total. // the same form as created_at, and one more on its target's delivered
// or failed total.
func TestUpdateDeliveryStatus_FinishTimeAndTargetTotals(t *testing.T) { func TestUpdateDeliveryStatus_FinishTimeAndTargetTotals(t *testing.T) {
t.Parallel() t.Parallel()
@@ -75,6 +76,16 @@ func TestUpdateDeliveryStatus_FinishTimeAndTargetTotals(t *testing.T) {
if tt.finished { if tt.finished {
require.NotNil(t, stored.FinishedAt) require.NotNil(t, stored.FinishedAt)
assert.False(t, stored.FinishedAt.Before(before)) assert.False(t, stored.FinishedAt.Before(before))
var createdAt, finishedAt string
require.NoError(t, db.Raw(
`SELECT CAST(created_at AS TEXT),
CAST(finished_at AS TEXT)
FROM deliveries WHERE id = ?`, d.ID,
).Row().Scan(&createdAt, &finishedAt))
assertStoredTime(t, createdAt)
assertStoredTime(t, finishedAt)
} else { } else {
assert.Nil(t, stored.FinishedAt) assert.Nil(t, stored.FinishedAt)
} }
+6 -2
View File
@@ -1702,7 +1702,10 @@ func writeDeliveryStatus(
}). }).
Updates(map[string]any{ Updates(map[string]any{
"status": status, "status": status,
"finished_at": time.Now(), // GORM's clock, the one that stamps created_at. A bare
// time.Now() carries a monotonic clock reading, which the
// driver would store as an " m=+…" suffix.
"finished_at": tx.NowFunc(),
}) })
if res.Error != nil || res.RowsAffected == 0 { if res.Error != nil || res.RowsAffected == 0 {
return res.Error return res.Error
@@ -1906,12 +1909,13 @@ func (e *Engine) takeForRedispatch(
return false return false
} }
// GORM's clock, as writeDeliveryStatus explains.
res := webhookDB. res := webhookDB.
Model(&database.Delivery{}). Model(&database.Delivery{}).
Where( Where(
"id = ? AND status = ?", deliveryID, eligible, "id = ? AND status = ?", deliveryID, eligible,
). ).
UpdateColumn("updated_at", time.Now()) UpdateColumn("updated_at", webhookDB.NowFunc())
if res.Error != nil { if res.Error != nil {
e.log.Error( e.log.Error(
+153
View File
@@ -2,11 +2,16 @@ package delivery_test
import ( import (
"context" "context"
"io"
"net/http"
"net/http/httptest"
"path/filepath" "path/filepath"
"sync"
"testing" "testing"
"time" "time"
"github.com/google/uuid" "github.com/google/uuid"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"go.uber.org/fx" "go.uber.org/fx"
"gorm.io/gorm/clause" "gorm.io/gorm/clause"
@@ -272,6 +277,154 @@ func TestEngine_StopHookHonoursStopTimeout(t *testing.T) {
requireStopHookExpires(t, lc.hooks[0], "delivery engine") requireStopHookExpires(t, lc.hooks[0], "delivery engine")
} }
// seedHeldDelivery gives the setup's webhook an http target with
// maxRetries, pointed at a receiver that keeps every request open until
// the client gives up on it, and seeds one delivery to that target at
// status. It returns the task that sends attempt attemptNum of the
// delivery, and a channel that is closed when a request reaches the
// receiver.
func seedHeldDelivery(
t *testing.T,
s iSetup,
maxRetries int,
status database.DeliveryStatus,
attemptNum int,
) (delivery.Task, <-chan struct{}) {
t.Helper()
arrived := make(chan struct{})
var once sync.Once
ts := httptest.NewServer(http.HandlerFunc(
func(_ http.ResponseWriter, r *http.Request) {
// The server notices the client hanging up only once the
// body has been read; until then r.Context() never ends.
_, _ = io.Copy(io.Discard, r.Body)
once.Do(func() { close(arrived) })
<-r.Context().Done()
},
))
t.Cleanup(ts.Close)
cfg := iHTTPConfig(ts.URL)
targetID := uuid.New().String()
iCreateWebhook(t, s.MainDB, s.WebhookID, "hook")
iCreateTarget(
t, s.MainDB, targetID, s.WebhookID, "held",
database.TargetTypeHTTP, cfg, maxRetries,
)
event := iSeedEvent(t, s.WebhookDB, s.WebhookID, `{"held":true}`)
d := iSeedDelivery(t, s.WebhookDB, event.ID, targetID, status)
bodyStr := event.Body
return iTask(
d, event, s.WebhookID, targetID, "held", cfg,
maxRetries, attemptNum, &bodyStr,
), arrived
}
// stopDuringAttempt waits until the receiver holds an attempt open, then
// stops the engine through its real stop hook.
func stopDuringAttempt(
t *testing.T, lc *recordingLifecycle, arrived <-chan struct{},
) {
t.Helper()
select {
case <-arrived:
case <-time.After(5 * time.Second):
t.Fatal("the delivery attempt never reached the receiver")
}
require.NoError(t, lc.hooks[0].OnStop(context.Background()))
}
// requireRequeued runs restart recovery on the stopped engine and
// requires it to queue task's attempt again on ch.
func requireRequeued(
t *testing.T, s iSetup, ch <-chan delivery.Task, task delivery.Task,
) {
t.Helper()
s.Engine.ExportRecoverWebhookDeliveries(
context.Background(), s.WebhookID,
)
select {
case got := <-ch:
assert.Equal(t, task.DeliveryID, got.DeliveryID)
assert.Equal(t, task.AttemptNum, got.AttemptNum)
case <-time.After(5 * time.Second):
t.Fatal("restart recovery did not queue the delivery again")
}
}
// TestEngine_StopLeavesFireAndForgetAttemptPending is the regression
// test for a stop that turned an attempt in flight into a terminal
// failure. Stopping the engine cancels the request; for a target with
// no retries that was the delivery's only attempt, recorded as failed
// with "context canceled", and nothing ever sent it again. The
// delivery must instead stay pending, with no result and no count in
// the attempt metrics, for restart recovery to send.
func TestEngine_StopLeavesFireAndForgetAttemptPending(t *testing.T) {
t.Parallel()
s := newISetup(t)
reg := mIsolate(t, s)
lc := startEngineViaHook(t, s.Engine)
task, arrived := seedHeldDelivery(
t, s, 0, database.DeliveryStatusPending, 1,
)
s.Engine.Notify([]delivery.Task{task})
stopDuringAttempt(t, lc, arrived)
iAssertStatus(
t, s.WebhookDB, task.DeliveryID, database.DeliveryStatusPending,
)
assert.Empty(t, iResults(t, s.WebhookDB, task.DeliveryID))
assert.Zero(t, mCounter(t, reg, mAttempts, mTypeHTTP))
assert.Zero(t, mHTTPDurations(t, reg))
requireRequeued(t, s, s.Engine.ExportDeliveryCh(), task)
}
// TestEngine_StopLeavesLastRetryAttemptRetrying is the same regression
// for a target with retries, on its last attempt: the cancelled attempt
// used to exhaust the retries and end the delivery failed. It must stay
// retrying with only its earlier attempt recorded, and restart recovery
// must send that last attempt again.
func TestEngine_StopLeavesLastRetryAttemptRetrying(t *testing.T) {
t.Parallel()
const maxRetries = 2
s := newISetup(t)
lc := startEngineViaHook(t, s.Engine)
task, arrived := seedHeldDelivery(
t, s, maxRetries, database.DeliveryStatusRetrying, maxRetries,
)
iSeedFailedResult(t, s.WebhookDB, task.DeliveryID)
s.Engine.ExportScheduleRetry(task, 0)
stopDuringAttempt(t, lc, arrived)
iAssertStatus(
t, s.WebhookDB, task.DeliveryID, database.DeliveryStatusRetrying,
)
assert.Len(t, iResults(t, s.WebhookDB, task.DeliveryID), 1)
requireRequeued(t, s, s.Engine.ExportRetryCh(), task)
}
// deliverToArchive gives the setup's webhook a database target, // deliverToArchive gives the setup's webhook a database target,
// runs one delivery to it through the running engine, and returns // runs one delivery to it through the running engine, and returns
// the target's ID and archive file path. The archive writer holds // the target's ID and archive file path. The archive writer holds
+12
View File
@@ -117,6 +117,18 @@ func seedDelivery(
return d return d
} }
// assertStoredTime asserts that text, a timestamp as SQLite holds it,
// is in the form GORM stores created_at in: the layout of
// time.Time.String, with no " m=+…" monotonic clock reading after it.
func assertStoredTime(t *testing.T, text string) {
t.Helper()
_, err := time.Parse(
"2006-01-02 15:04:05.999999999 -0700 MST", text,
)
assert.NoError(t, err, "stored as %q", text)
}
// httpDeliveryFixture holds the task and delivery needed // httpDeliveryFixture holds the task and delivery needed
// for HTTP delivery tests. // for HTTP delivery tests.
type httpDeliveryFixture struct { type httpDeliveryFixture struct {
+11 -1
View File
@@ -462,7 +462,8 @@ func TestScheduledRetryIsNotSweptDuringBackoff(t *testing.T) {
// TestRedispatchStampsTheRow pins the cadence control: a stranded // TestRedispatchStampsTheRow pins the cadence control: a stranded
// delivery that has just been handed out is not selected again by the // delivery that has just been handed out is not selected again by the
// next tick a minute later. // next tick a minute later. The stamp is stored in the same form as
// created_at.
func TestRedispatchStampsTheRow(t *testing.T) { func TestRedispatchStampsTheRow(t *testing.T) {
t.Parallel() t.Parallel()
@@ -493,4 +494,13 @@ func TestRedispatchStampsTheRow(t *testing.T) {
"a re-dispatched delivery must be stamped so the "+ "a re-dispatched delivery must be stamped so the "+
"next tick does not select it again", "next tick does not select it again",
) )
var createdAt, updatedAt string
require.NoError(t, s.WebhookDB.Raw(
`SELECT CAST(created_at AS TEXT), CAST(updated_at AS TEXT)
FROM deliveries WHERE id = ?`, d.ID,
).Row().Scan(&createdAt, &updatedAt))
assertStoredTime(t, createdAt)
assertStoredTime(t, updatedAt)
} }
+2 -1
View File
@@ -32,7 +32,8 @@ type Scheduler interface {
// Engine.observeAttempt, alongside the DeliveryResult it records for // Engine.observeAttempt, alongside the DeliveryResult it records for
// it. Deliver is also entered for attempts that never happen — an // it. Deliver is also entered for attempts that never happen — an
// open circuit breaker refuses one — so the count cannot be taken // open circuit breaker refuses one — so the count cannot be taken
// from around this call. // from around this call. An attempt cut off by a stop is neither
// counted nor recorded.
type Target interface { type Target interface {
Deliver( Deliver(
ctx context.Context, ctx context.Context,
+5 -1
View File
@@ -277,7 +277,11 @@ func (w *archiveWriter) write(
} }
} }
row.ArchivedAt = time.Now() // GORM's clock, the one that stamps created_at in the other
// databases, so this is stored in the same form. A bare time.Now()
// carries a monotonic clock reading, which the driver would store
// as an " m=+…" suffix.
row.ArchivedAt = w.db.NowFunc()
err := w.db.Create(&row).Error err := w.db.Create(&row).Error
if err != nil { if err != nil {
@@ -150,6 +150,13 @@ func TestArchiveWriter_WritesRow(t *testing.T) {
assert.Equal(t, row.ContentType, got[0].ContentType) assert.Equal(t, row.ContentType, got[0].ContentType)
assert.JSONEq(t, `{"hello":"world"}`, got[0].Body) assert.JSONEq(t, `{"hello":"world"}`, got[0].Body)
assert.False(t, got[0].ArchivedAt.IsZero()) assert.False(t, got[0].ArchivedAt.IsZero())
var archivedAt string
require.NoError(t, w.DB().Raw(
"SELECT CAST(archived_at AS TEXT) FROM archived_events",
).Row().Scan(&archivedAt))
assertStoredTime(t, archivedAt)
} }
func TestArchiveWriter_RecreatesAfterRemoval( func TestArchiveWriter_RecreatesAfterRemoval(
+2 -2
View File
@@ -82,8 +82,8 @@ func isReservedTargetHeader(name string) bool {
// one pair silently overwriting the other. // one pair silently overwriting the other.
// //
// An input with no pairs yields an empty map, which omitempty drops // An input with no pairs yields an empty map, which omitempty drops
// from the stored config: a target configured with no headers keeps // from the stored config, so a target configured with no headers
// the same config JSON it had before this field existed. // stores no headers key at all.
func ParseTargetHeaders(raw string) (map[string]string, error) { func ParseTargetHeaders(raw string) (map[string]string, error) {
headers := make(map[string]string) headers := make(map[string]string)
+46 -3
View File
@@ -57,7 +57,11 @@ type httpCore struct {
// recorded and no circuit breaker is consulted. A positive // recorded and no circuit breaker is consulted. A positive
// maxRetries gates the attempt on the circuit breaker and // maxRetries gates the attempt on the circuit breaker and
// schedules a backed-off retry on failure. // schedules a backed-off retry on failure.
//
// ctx is the context attempt sends its request with. Stopping the
// engine cancels it; see interruptedByStop.
func (c *httpCore) deliver( func (c *httpCore) deliver(
ctx context.Context,
webhookDB *gorm.DB, webhookDB *gorm.DB,
d *database.Delivery, d *database.Delivery,
task *Task, task *Task,
@@ -66,21 +70,55 @@ func (c *httpCore) deliver(
attempt func() attemptResult, attempt func() attemptResult,
) { ) {
if maxRetries == 0 { if maxRetries == 0 {
c.fireAndForget(webhookDB, d, attempt()) c.fireAndForget(ctx, webhookDB, d, attempt())
return return
} }
c.withRetry( c.withRetry(
webhookDB, d, task, sched, maxRetries, attempt, ctx, webhookDB, d, task, sched, maxRetries, attempt,
) )
} }
// interruptedByStop reports whether an attempt failed because the
// engine is stopping, which cancels the context its request is made
// with. Such an attempt is not recorded: no DeliveryResult, no circuit
// breaker outcome, no status change, no count in the attempt metrics.
// The delivery stays pending or retrying, and startup recovery sends
// it again on the next start.
//
// A target's own timeout leaves that context alone, so its attempt is
// still recorded as the failure it is.
func (c *httpCore) interruptedByStop(
ctx context.Context,
d *database.Delivery,
res attemptResult,
) bool {
if res.success || ctx.Err() == nil {
return false
}
c.eng.log.Warn(
"delivery attempt interrupted by shutdown; not recorded, "+
"it is sent again on the next start",
"delivery_id", d.ID,
"event_id", d.EventID,
"target_id", d.TargetID,
)
return true
}
func (c *httpCore) fireAndForget( func (c *httpCore) fireAndForget(
ctx context.Context,
webhookDB *gorm.DB, webhookDB *gorm.DB,
d *database.Delivery, d *database.Delivery,
res attemptResult, res attemptResult,
) { ) {
if c.interruptedByStop(ctx, d, res) {
return
}
c.eng.observeAttempt(d.Target.Type, res.elapsed()) c.eng.observeAttempt(d.Target.Type, res.elapsed())
err := c.eng.recordResult( err := c.eng.recordResult(
@@ -110,6 +148,7 @@ func (c *httpCore) fireAndForget(
} }
func (c *httpCore) withRetry( func (c *httpCore) withRetry(
ctx context.Context,
webhookDB *gorm.DB, webhookDB *gorm.DB,
d *database.Delivery, d *database.Delivery,
task *Task, task *Task,
@@ -131,6 +170,10 @@ func (c *httpCore) withRetry(
res := attempt() res := attempt()
if c.interruptedByStop(ctx, d, res) {
return
}
c.eng.observeAttempt(d.Target.Type, res.elapsed()) c.eng.observeAttempt(d.Target.Type, res.elapsed())
err := c.eng.recordResult( err := c.eng.recordResult(
@@ -395,7 +438,7 @@ func (t *httpTarget) Deliver(
} }
t.deliver( t.deliver(
webhookDB, d, task, sched, ctx, webhookDB, d, task, sched,
d.Target.MaxRetries, attempt, d.Target.MaxRetries, attempt,
) )
} }
+3 -3
View File
@@ -13,9 +13,9 @@ import (
const RedactionMarker = "(redacted)" const RedactionMarker = "(redacted)"
// Redactor removes one target's own credential material from // Redactor removes one target's own credential material from
// text that target's remote peer chose: a delivery response // a delivery response body, whose text the target's remote
// body, or a delivery error stored before the delivery path // peer chose, and from a stored delivery error as a second
// learned to mask the URLs it embeds. // line behind the delivery path's own URL masking.
// //
// It removes byte-identical echoes of strings taken from the // It removes byte-identical echoes of strings taken from the
// target's stored configuration, and nothing else. Anything // target's stored configuration, and nothing else. Anything
+1 -1
View File
@@ -82,7 +82,7 @@ func (t *slackTarget) Deliver(
} }
t.deliver( t.deliver(
webhookDB, d, task, sched, ctx, webhookDB, d, task, sched,
d.Target.MaxRetries, attempt, d.Target.MaxRetries, attempt,
) )
} }
@@ -42,9 +42,6 @@ func TestDeliveryAttempts_ReadInTheTargetTypesOwnTerms(t *testing.T) {
{database.TargetTypeLog, true, 0, "", "written to the log", ""}, {database.TargetTypeLog, true, 0, "", "written to the log", ""},
} }
// Named for type and outcome, so that no two cases share a name:
// Go adds "#01" to a repeated one, and a "#" in the temporary
// directory's path cuts the path SQLiteDSN gives SQLite short.
for _, tc := range cases { for _, tc := range cases {
t.Run(string(tc.targetType)+" "+tc.outcome, func(t *testing.T) { t.Run(string(tc.targetType)+" "+tc.outcome, func(t *testing.T) {
t.Parallel() t.Parallel()
+6 -8
View File
@@ -12,13 +12,12 @@ import (
// //
// The bound is enforced here and in SQL, because this page's // The bound is enforced here and in SQL, because this page's
// memory profile must not depend on a constant in another // memory profile must not depend on a constant in another
// package staying where it is, and because rows predating the // package staying where it is, or on every stored row having
// delivery engine's own cap or restored from an archive are // been written by the delivery engine under its own cap.
// not covered by it at all.
// //
// It happens to equal that engine cap, so a row written by the // It happens to equal that engine cap, so a row written by the
// current engine reaches this one exactly and is never cut // engine reaches this one exactly and is never cut twice.
// twice. Nothing here may assume the two differ: see view. // Nothing here may assume the two differ: see view.
const maxRenderedResponseBytes = 4096 const maxRenderedResponseBytes = 4096
// deliveryResultColumns is the delivery attempt projection. // deliveryResultColumns is the delivery attempt projection.
@@ -40,9 +39,8 @@ const deliveryResultColumns = "delivery_id, attempt_num, created_at, " +
// //
// Both Error and ResponseBody have been through the target's // Both Error and ResponseBody have been through the target's
// Redactor. The engine already masks the URL out of the // Redactor. The engine already masks the URL out of the
// errors it stores, so for errors this is a second line // errors it stores, so for errors this is a second line; for
// covering rows written before it did; for response bodies it // response bodies it is the only line, and its reach is what
// is the only line, and its reach is what
// delivery.Redactor documents. // delivery.Redactor documents.
type DeliveryResultView struct { type DeliveryResultView struct {
AttemptNum int AttemptNum int
+8 -49
View File
@@ -1,19 +1,15 @@
package handlers_test package handlers_test
// The handler-side half of the log-field audit. Two slog calls in // The handler-side half of the log-field audit. The slog calls in
// this package reach a value an UNAUTHENTICATED client picks outright // this package that reach a value an UNAUTHENTICATED client picks
// and of a length it picks outright: // outright, and of a length it picks outright, are the failed-login
// DEBUG lines, whose username is a form field.
// //
// - the unknown-entrypoint DEBUG line on /h/{uuid}, whose // They are at DEBUG, which is off in production by default. That is
// path segment matched no stored entrypoint and so is bounded by
// nothing;
// - the failed-login DEBUG lines, whose username is a form field.
//
// Both are at DEBUG, which is off in production by default. That is
// not a bound: an operator turning DEBUG on to diagnose a flood must // not a bound: an operator turning DEBUG on to diagnose a flood must
// not thereby hand the flood an unbounded write. Both spend the same // not thereby hand the flood an unbounded write. They spend the same
// internal/logfield budget as the access log, and both are held here // internal/logfield budget as the access log, and are held here to
// to middleware.MaxAccessLogLineBytes. // middleware.MaxAccessLogLineBytes.
// //
// The two login lines past the username lookup — "invalid password" // The two login lines past the username lookup — "invalid password"
// and "user logged in" — carry the same cap without needing it, since // and "user logged in" — carry the same cap without needing it, since
@@ -260,43 +256,6 @@ func postLoginWithPassword(
return w.Code return w.Code
} }
// TestUnknownEntrypoint_LogLineDoesNotTrackPathSize drives 8 KB of
// client-chosen path at the unauthenticated receiver's
// unknown-entrypoint DEBUG line and holds it to the same ceiling the
// access log states.
func TestUnknownEntrypoint_LogLineDoesNotTrackPathSize(t *testing.T) {
t.Parallel()
for handlerName, newHandler := range logHandlers() {
for fillName, fill := range escapeFills() {
t.Run(handlerName+"/"+fillName, func(t *testing.T) {
t.Parallel()
h, buf := capturingHandlers(t, newHandler)
router := receiverRouter(h)
for i := range floodRequests {
assert.Equal(
t,
http.StatusNotFound,
postReceiver(
t, router,
oversizedFill(fill)+
strings.Repeat("y", i),
),
)
}
lines := logLines(t, buf)
require.Len(t, lines, floodRequests)
assertNoClientText(t, buf)
assertBoundedFlood(t, buf.Len())
})
}
}
}
// TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of // TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of
// client-chosen username at the unauthenticated login endpoint's // client-chosen username at the unauthenticated login endpoint's
// DEBUG line and holds it to the same ceiling. // DEBUG line and holds it to the same ceiling.
-7
View File
@@ -49,13 +49,6 @@ var (
// working retry configuration over a typo. A default answers a // working retry configuration over a typo. A default answers a
// question that was not asked; it never answers one that was asked // question that was not asked; it never answers one that was asked
// badly. // badly.
//
// A target stored with a count above the ceiling before this
// validation existed keeps rendering and keeps delivering — nothing
// clamps the row. Re-saving it from the edit form does have to bring
// it into range, because the form submits the pre-filled value back
// and accepting it would be the ceiling not applying to the edit
// path. The 400 names the ceiling, so the fix is one field.
func parseMaxRetries(raw string, fallback int) (int, error) { func parseMaxRetries(raw string, fallback int) (int, error) {
raw = strings.TrimSpace(raw) raw = strings.TrimSpace(raw)
if raw == "" { if raw == "" {
+10 -19
View File
@@ -10,7 +10,6 @@ import (
"gorm.io/gorm" "gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/database" "sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/delivery" "sneak.berlin/go/webhooker/internal/delivery"
"sneak.berlin/go/webhooker/internal/logfield"
"sneak.berlin/go/webhooker/internal/middleware" "sneak.berlin/go/webhooker/internal/middleware"
) )
@@ -49,14 +48,13 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc {
return return
} }
// Logged only once the UUID is known to name a real // Logged only once the lookup has found the entrypoint, so
// entrypoint. The UUID comes straight out of the path on // an invented path writes no INFO line; a miss is logged at
// the one unauthenticated endpoint, so logging it before // DEBUG. The entrypoint is named by its ID: the UUID is its
// the lookup let a client write an INFO line per invented // credential and is never logged.
// path; the request itself is already in the access log
// and a miss is already logged at DEBUG.
h.log.Info("webhook request received", h.log.Info("webhook request received",
"entrypoint_uuid", entrypointUUID, "entrypoint_id", entrypoint.ID,
"webhook_id", entrypoint.WebhookID,
"method", r.Method, "method", r.Method,
"remoteIP", middleware.RemoteIP(r), "remoteIP", middleware.RemoteIP(r),
"clientIP", middleware.ClientIP(r), "clientIP", middleware.ClientIP(r),
@@ -133,17 +131,10 @@ func (h *Handlers) lookupEntrypoint(
"path = ?", entrypointUUID, "path = ?", entrypointUUID,
).First(&entrypoint) ).First(&entrypoint)
if result.Error != nil { if result.Error != nil {
// The receiver is unauthenticated and /h/{uuid} // Not even an unknown UUID is logged. The receiver's log
// matches any single segment, so this value is entirely // lines never carry the path segment, which is a credential
// client-chosen on exactly the branch where the lookup // whenever it names an entrypoint.
// failed. DEBUG is off by default; the cap is what keeps h.log.Debug("entrypoint not found")
// turning it on from restoring an unbounded write.
h.log.Debug(
"entrypoint not found",
"path", logfield.Truncate(
entrypointUUID, logfield.MaxBytes,
),
)
http.NotFound(w, r) http.NotFound(w, r)
return entrypoint, false return entrypoint, false
+84
View File
@@ -12,12 +12,15 @@ import (
"testing" "testing"
"github.com/go-chi/chi" "github.com/go-chi/chi"
"github.com/google/uuid"
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require" "github.com/stretchr/testify/require"
"gorm.io/gorm/clause"
"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/handlers" "sneak.berlin/go/webhooker/internal/handlers"
"sneak.berlin/go/webhooker/internal/middleware" "sneak.berlin/go/webhooker/internal/middleware"
"sneak.berlin/go/webhooker/internal/middleware/middlewaretest"
) )
// TestHandleWebhook_LogsClientNextToThePeer checks that the // TestHandleWebhook_LogsClientNextToThePeer checks that the
@@ -99,6 +102,87 @@ func TestHandleWebhook_LogsClientNextToThePeer(t *testing.T) {
} }
} }
// TestHandleWebhook_LogsNoEntrypointUUID sends an accepted event, a
// request over the receiver rate limit and a request for an unknown
// UUID through the receiver as routes.go mounts it, and checks that
// nothing logged, at any level, carries either UUID.
func TestHandleWebhook_LogsNoEntrypointUUID(t *testing.T) {
t.Parallel()
var (
h *handlers.Handlers
db *database.Database
)
cfg := &config.Config{DataDir: t.TempDir(), ReceiverRateLimit: 1}
app := newTestAppWithConfig(t, cfg, &h, &db)
app.RequireStart()
t.Cleanup(app.RequireStop)
buf := new(bytes.Buffer)
log := slog.New(slog.NewJSONHandler(
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
))
h.SetLogForTest(log)
mw := middlewaretest.New(t, log, cfg, nil)
webhook := seedWebhook(t, db)
entrypoint := &database.Entrypoint{
WebhookID: webhook.ID,
Path: uuid.New().String(),
Active: true,
}
require.NoError(t, db.DB().Omit(clause.Associations).
Create(entrypoint).Error)
unknownUUID := uuid.New().String()
router := chi.NewRouter()
router.Use(mw.Logging())
router.With(mw.ReceiverRateLimit()).HandleFunc(
middleware.ReceiverRoute, h.HandleWebhook(),
)
// In order: the limit is one request per minute per path, so the
// second request for the known UUID is the rejected one.
for _, step := range []struct {
entrypointUUID string
wantStatus int
}{
{entrypoint.Path, http.StatusOK},
{entrypoint.Path, http.StatusTooManyRequests},
{unknownUUID, http.StatusNotFound},
} {
req := httptest.NewRequestWithContext(
context.Background(), http.MethodPost,
"/h/"+step.entrypointUUID, strings.NewReader("{}"),
)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
require.Equal(t, step.wantStatus, w.Code)
}
// The lines this test is about were all written, so the checks
// below are not passing on an empty log.
for _, msg := range []string{
"webhook request received",
"webhook receiver rate limit exceeded",
"entrypoint not found",
} {
assert.Contains(t, buf.String(), `"msg":"`+msg+`"`)
}
assert.NotContains(t, buf.String(), entrypoint.Path)
assert.NotContains(t, buf.String(), unknownUUID)
line := receivedLine(t, buf)
assert.Equal(t, entrypoint.ID, line["entrypoint_id"])
assert.Equal(t, webhook.ID, line["webhook_id"])
}
// receivedLine returns the one "webhook request received" line in the // receivedLine returns the one "webhook request received" line in the
// captured JSON log. // captured JSON log.
func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any { func receivedLine(t *testing.T, buf *bytes.Buffer) map[string]any {
+123 -15
View File
@@ -7,6 +7,7 @@ import (
"log/slog" "log/slog"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"strconv"
"strings" "strings"
"testing" "testing"
@@ -27,6 +28,13 @@ const floodRequests = 64
// line for a redirected or rejected request may contain it. // line for a redirected or rejected request may contain it.
const attackerMarker = "QQATTACKERTEXTQQ" const attackerMarker = "QQATTACKERTEXTQQ"
// knownEntrypointUUID and failingEntrypointUUID are the UUIDs the
// stand-in receiver in accessLogRouter answers 200 and 500 to.
const (
knownEntrypointUUID = "6f1e2a9c-4b7d-4e3a-9c2f-1d8b5a7e3c60"
failingEntrypointUUID = "0b7c3e5a-2d9f-4a61-8e4b-7c1d6f2a9e35"
)
// maxLineBytes bounds a single access log line whose client-supplied // maxLineBytes bounds a single access log line whose client-supplied
// fields are of ordinary size. Well above what the fixed fields need, // fields are of ordinary size. Well above what the fixed fields need,
// well below the length of the oversized input the amplification tests // well below the length of the oversized input the amplification tests
@@ -132,17 +140,21 @@ func accessLogRouter(m *middleware.Middleware) *chi.Mux {
) )
router.HandleFunc( router.HandleFunc(
"/h/{uuid}", middleware.ReceiverRoute,
func(w http.ResponseWriter, r *http.Request) { func(w http.ResponseWriter, r *http.Request) {
// Stands in for the real handler: an unknown entrypoint // Stands in for the real handler: a known entrypoint
// UUID 404s, a known one succeeds. // UUID succeeds, a failing one is a server error, and
if chi.URLParam(r, "uuid") != "known" { // any other 404s.
http.Error(w, "not found", http.StatusNotFound) switch chi.URLParam(r, "uuid") {
case knownEntrypointUUID:
return
}
w.WriteHeader(http.StatusOK) w.WriteHeader(http.StatusOK)
case failingEntrypointUUID:
http.Error(
w, "boom", http.StatusInternalServerError,
)
default:
http.Error(w, "not found", http.StatusNotFound)
}
}, },
) )
@@ -335,11 +347,13 @@ func oversizedValue(ch string) string {
} }
// oversizedHeaders fills every client-supplied header the access log // oversizedHeaders fills every client-supplied header the access log
// reads with the same value. // reads with the same value. The Referer carries it as the host of an
// absolute URL, because the access log keeps only a Referer's scheme
// and host.
func oversizedHeaders(value string) map[string]string { func oversizedHeaders(value string) map[string]string {
return map[string]string{ return map[string]string{
"User-Agent": value, "User-Agent": value,
"Referer": value, "Referer": "http://" + value,
"X-Request-Id": value, "X-Request-Id": value,
} }
} }
@@ -649,17 +663,111 @@ func TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery(
router := accessLogRouter(m) router := accessLogRouter(m)
assert.Equal( assert.Equal(
t, http.StatusOK, get(t, router, "/h/known?src=ci"), t, http.StatusOK,
get(t, router, "/.well-known/healthcheck?src=ci"),
) )
// The path resolved against a stored entrypoint, so it stays. The
// query never does: see TestAccessLog_UnauthenticatedSuccess...
entries := accessLogEntries(t, buf) entries := accessLogEntries(t, buf)
require.Len(t, entries, 1) require.Len(t, entries, 1)
assert.Equal(t, "/h/known?(redacted)", entries[0]["url"]) assert.Equal(
t, "/.well-known/healthcheck?(redacted)", entries[0]["url"],
)
assert.NotContains(t, buf.String(), "src=ci") assert.NotContains(t, buf.String(), "src=ci")
} }
// TestAccessLog_ReceiverNeverLogsTheUUID covers the two statuses that
// keep the concrete path on every other route. On the receiver that
// path carries the entrypoint UUID, so the line names the route
// pattern instead.
func TestAccessLog_ReceiverNeverLogsTheUUID(t *testing.T) {
t.Parallel()
for entrypointUUID, wantStatus := range map[string]int{
knownEntrypointUUID: http.StatusOK,
failingEntrypointUUID: http.StatusInternalServerError,
} {
t.Run(strconv.Itoa(wantStatus), func(t *testing.T) {
t.Parallel()
m, buf := capturingMiddleware(t)
router := accessLogRouter(m)
assert.Equal(
t, wantStatus,
get(t, router, "/h/"+entrypointUUID+"?src=ci"),
)
entries := accessLogEntries(t, buf)
require.Len(t, entries, 1)
assert.Equal(t, middleware.ReceiverRoute, entries[0]["url"])
assert.NotContains(t, buf.String(), entrypointUUID)
})
}
}
// TestAccessLog_ReceiverPreflightNeverLogsTheUUID sends a CORS
// preflight to the receiver in dev, in the production middleware
// order. CORS answers it with 200 before chi routes it, so the line
// names no route and carries no UUID.
func TestAccessLog_ReceiverPreflightNeverLogsTheUUID(t *testing.T) {
t.Parallel()
m, buf := capturingMiddleware(t)
router := chi.NewRouter()
router.Use(m.Logging())
router.Use(m.CORS())
router.HandleFunc(
middleware.ReceiverRoute,
func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusOK)
},
)
req := httptest.NewRequestWithContext(
context.Background(), http.MethodOptions,
"/h/"+knownEntrypointUUID, nil,
)
req.Header.Set("Origin", "https://sender.example")
req.Header.Set("Access-Control-Request-Method", http.MethodPost)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
assert.Equal(t, http.StatusOK, w.Code)
entries := accessLogEntries(t, buf)
require.Len(t, entries, 1)
assert.Equal(t, unmatchedRouteLiteral, entries[0]["url"])
assert.NotContains(t, buf.String(), knownEntrypointUUID)
}
// TestAccessLog_RefererNeverLogsTheUUID sends receiver requests whose
// Referer is the entrypoint URL, as a sender's is after it follows a
// redirect from http:// to https://. The referer field keeps only the
// scheme and host, and a Referer without them is logged as a marker.
func TestAccessLog_RefererNeverLogsTheUUID(t *testing.T) {
t.Parallel()
m, buf := capturingMiddleware(t)
router := accessLogRouter(m)
for _, referer := range []string{
"http://webhooker.example/h/" + knownEntrypointUUID + "?src=ci",
"/h/" + knownEntrypointUUID,
} {
assert.Equal(t, http.StatusOK, getWithHeaders(
t, router, "/h/"+knownEntrypointUUID,
map[string]string{"Referer": referer},
))
}
entries := accessLogEntries(t, buf)
require.Len(t, entries, 2)
assert.Equal(t, "http://webhooker.example", entries[0]["referer"])
assert.Equal(t, "(redacted)", entries[1]["referer"])
assert.NotContains(t, buf.String(), knownEntrypointUUID)
}
func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) { func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
t.Parallel() t.Parallel()
+12 -6
View File
@@ -10,8 +10,10 @@ package middleware_test
// the client's choosing. // the client's choosing.
// - CSRF's 403 rejection, at WARN, also registered ahead of // - CSRF's 403 rejection, at WARN, also registered ahead of
// RequireAuth. // RequireAuth.
// - The rate limiters' 429 rejection, at WARN, on the // - The rate limiters' 429 rejection, at WARN. On the receiver
// unauthenticated receiver among others. // route it names the route pattern rather than the path, and
// the limiters that log a path sit behind RequireAuth, so its cap
// is defensive.
// - RequireAuth's own unauthenticated-request line, at DEBUG. // - RequireAuth's own unauthenticated-request line, at DEBUG.
// - RecordLoginFailure's throttle rejection, at WARN. Its cap is // - RecordLoginFailure's throttle rejection, at WARN. Its cap is
// defensive rather than load-bearing today: chi pins the one // defensive rather than load-bearing today: chi pins the one
@@ -268,10 +270,14 @@ func logSites() map[string]logSite {
send: postNoToken, send: postNoToken,
wantStatus: http.StatusForbidden, wantStatus: http.StatusForbidden,
}, },
// The per-entrypoint receiver limiter, unauthenticated. Its // The 429 line every limiter but the aggregate one shares.
// bucket is keyed on the path, so the first request through a // Mounted outside any route, as here, it logs the path, as
// fresh path is served and only the ones after it are // it does for the limiters behind RequireAuth; on
// rejected; sendUntilLimited absorbs that. // ReceiverRoute it names the pattern instead. The
// per-entrypoint receiver limiter's bucket is keyed on the
// path, so the first request through a fresh path is served
// and only the ones after it are rejected; sendUntilLimited
// absorbs that.
"receiver rate limit 429": { "receiver rate limit 429": {
build: func( build: func(
t *testing.T, m *middleware.Middleware, t *testing.T, m *middleware.Middleware,
+2 -1
View File
@@ -41,7 +41,8 @@ const unmatchedMethod = unmatchedRoute
// after /h/ is client-chosen, so labelling by path lets any // after /h/ is client-chosen, so labelling by path lets any
// unauthenticated client mint permanent series at will, and publishes // unauthenticated client mint permanent series at will, and publishes
// the entrypoint UUID (the receiver's only credential) in the scrape // the entrypoint UUID (the receiver's only credential) in the scrape
// while doing it. // while doing it. The access log and the 429 line read it for the
// same reason: see ReceiverRoute.
// //
// chi populates the route context during routeHTTP, so this is only // chi populates the route context during routeHTTP, so this is only
// valid once routing has run. Every caller below is on the recording // valid once routing has run. Every caller below is on the recording
+68 -34
View File
@@ -13,7 +13,6 @@ import (
"time" "time"
basicauth "github.com/99designs/basicauth-go" basicauth "github.com/99designs/basicauth-go"
"github.com/go-chi/chi"
"github.com/go-chi/chi/middleware" "github.com/go-chi/chi/middleware"
"github.com/go-chi/cors" "github.com/go-chi/cors"
"github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus"
@@ -49,6 +48,10 @@ const (
// pick the size of the line it writes. // pick the size of the line it writes.
redactedQuery = "?(redacted)" redactedQuery = "?(redacted)"
// redactedReferer stands in for a Referer the access log cannot
// reduce to its scheme and host; see accessLogReferer.
redactedReferer = "(redacted)"
// maxLogRequestIDBytes bounds the request id, which is also // maxLogRequestIDBytes bounds the request id, which is also
// client-supplied: chi's RequestID middleware passes an inbound // client-supplied: chi's RequestID middleware passes an inbound
// X-Request-Id header through verbatim. Its generated form is an // X-Request-Id header through verbatim. Its generated form is an
@@ -96,14 +99,14 @@ const (
// It is also the ceiling on every OTHER line this service writes // It is also the ceiling on every OTHER line this service writes
// THROUGH SLOG that carries text an UNAUTHENTICATED client // THROUGH SLOG that carries text an UNAUTHENTICATED client
// supplies. Those lines — the MaxBodySize rejection, the CSRF // supplies. Those lines — the MaxBodySize rejection, the CSRF
// rejection, the rate-limit rejection, the unauthenticated-request // rejection, the unauthenticated-request DEBUG line, the
// and unknown-entrypoint DEBUG lines, the failed-login DEBUG // failed-login DEBUG lines, and the two login-throttle WARN
// lines, and the two login-throttle WARN lines ("login failure // lines ("login failure limit exceeded" in loginguard.go and
// limit exceeded" in loginguard.go and "password verification // "password verification capacity exhausted" in
// capacity exhausted" in internal/handlers/auth.go) — spend the // internal/handlers/auth.go) — spend the same per-field budgets,
// same per-field budgets, and each carries strictly fewer // and each carries strictly fewer client-supplied fields than the
// client-supplied fields than the access log does, // access log does, so none of them can reach a width the access
// so none of them can reach a width the access log cannot. That is // log cannot. That is
// asserted directly, per line and under both handlers, rather than // asserted directly, per line and under both handlers, rather than
// left to the reasoning: see logbound_test.go in this package and // left to the reasoning: see logbound_test.go in this package and
// in internal/handlers. // in internal/handlers.
@@ -151,6 +154,12 @@ const (
MaxAccessLogLineBytes = 2560 MaxAccessLogLineBytes = 2560
) )
// ReceiverRoute is the route pattern the webhook receiver is served
// at. Its path carries the entrypoint UUID, which is the receiver's
// only credential, so the log lines this package writes name a
// request on this route by the pattern, never by its path.
const ReceiverRoute = "/h/{uuid}"
//nolint:revive // MiddlewareParams is a standard fx naming convention. //nolint:revive // MiddlewareParams is a standard fx naming convention.
type MiddlewareParams struct { type MiddlewareParams struct {
fx.In fx.In
@@ -268,14 +277,14 @@ func (lrw *loggingResponseWriter) Unwrap() http.ResponseWriter {
// marker. // marker.
// //
// The path on those branches is bounded by the service's routes or by // The path on those branches is bounded by the service's routes or by
// the operator's data — a 2xx on the receiver means the UUID named a // the operator's data — a 2xx under /s means the file is in the
// stored entrypoint, a 2xx under /s means the file is in the embedded // embedded tree. The query is not bounded by anything:
// tree. The query is not bounded by anything: /.well-known/healthcheck // /.well-known/healthcheck and /s/* take no authentication and sit
// and /s/* take no authentication and sit behind no rate limiter, and // behind no rate limiter, and /pages/login behind only the login
// /pages/login behind only the login limiter, so any of them will // limiter, so any of them will answer 200 to a URL carrying an
// answer 200 to a URL carrying an arbitrary number of arbitrary bytes // arbitrary number of arbitrary bytes after the '?'. Keeping the path
// after the '?'. Keeping the path and dropping the query is what makes // and dropping the query is what makes this branch as bounded as the
// this branch as bounded as the pattern branches below. // pattern branches below.
// //
// Nothing debuggable is lost. The only query parameters the service // Nothing debuggable is lost. The only query parameters the service
// reads are the login page's `next`, the page to return to, // reads are the login page's `next`, the page to return to,
@@ -297,36 +306,61 @@ func concreteLogURL(r *http.Request) string {
// accessLogURL returns the value for the access log's url field. // accessLogURL returns the value for the access log's url field.
// //
// 2xx and 5xx responses get the concrete path (see concreteLogURL). A // On ReceiverRoute it is the route pattern whatever the status, so
// success resolved against a static route or against the operator's // the entrypoint UUID in the path is never logged. A request chi never
// own data — on the receiver, a 2xx means the UUID named a stored // routed gets unmatchedRoute whatever the status, for the same reason:
// entrypoint — and a server error is our own bug, where the exact URL // in dev, CORS answers a preflight to the receiver before routing.
// is the primary evidence and which no client can provoke at will. //
// On every other route, 2xx and 5xx responses get the concrete path
// (see concreteLogURL). A success resolved against a static route or
// against the operator's own data, and a server error is our own bug,
// where the exact URL is the primary evidence and which no client can
// provoke at will.
// //
// 3xx and 4xx responses get the chi route pattern instead. Those are // 3xx and 4xx responses get the chi route pattern instead. Those are
// the outcomes an unauthenticated client drives for free: 404 or 429 // the outcomes an unauthenticated client drives for free, such as a
// on any invented /h/ path, 303 to the login page on any // 303 to the login page on any invented /user/ path. Logging the
// invented /user/ path. Logging the concrete URL there lets a flood // concrete URL there lets a flood write attacker-chosen text, of
// write attacker-chosen text, of attacker-chosen length, into the // attacker-chosen length, into the operator's log at one line per
// operator's log at one line per request. The pattern comes from the // request. The pattern comes from the router's own table, so it is
// router's own table, so it is bounded by the service's routes while // bounded by the service's routes while still naming which class of
// still naming which class of request was rejected. // request was rejected.
// //
// The pattern is only populated once routing has run, so this must be // The pattern is only populated once routing has run, so this must be
// called after the handler returns, not before. // called after the handler returns, not before.
func accessLogURL(r *http.Request, status int) string { func accessLogURL(r *http.Request, status int) string {
pattern := routePatternID(r.Context())
if pattern == ReceiverRoute || pattern == unmatchedRoute {
return pattern
}
if status < http.StatusMultipleChoices || if status < http.StatusMultipleChoices ||
status >= http.StatusInternalServerError { status >= http.StatusInternalServerError {
return concreteLogURL(r) return concreteLogURL(r)
} }
if rc := chi.RouteContext(r.Context()); rc != nil {
if pattern := rc.RoutePattern(); pattern != "" {
return pattern return pattern
} }
// accessLogReferer returns the value for the access log's referer
// field: the Referer's scheme and host, never its path or query. The
// path can be an entrypoint URL, which carries the UUID: a sender that
// follows a redirect from http:// to https:// sends the URL it was
// redirected from, and a browser sends the 404 page's URL under /h/
// when it fetches that page's stylesheet. A Referer without both a
// scheme and a host is logged as redactedReferer.
func accessLogReferer(r *http.Request) string {
referer := r.Referer()
if referer == "" {
return ""
} }
return unmatchedRoute parsed, err := url.Parse(referer)
if err != nil || parsed.Scheme == "" || parsed.Host == "" {
return redactedReferer
}
return parsed.Scheme + "://" + parsed.Host
} }
// Logging returns middleware that logs each HTTP request with // Logging returns middleware that logs each HTTP request with
@@ -379,7 +413,7 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
requestID, maxLogRequestIDBytes, requestID, maxLogRequestIDBytes,
), ),
"referer", logfield.Truncate( "referer", logfield.Truncate(
r.Referer(), logfield.MaxBytes, accessLogReferer(r), logfield.MaxBytes,
), ),
"proto", r.Proto, "proto", r.Proto,
"remoteIP", RemoteIP(r), "remoteIP", RemoteIP(r),
+12 -10
View File
@@ -259,26 +259,28 @@ func (m *Middleware) clientAddr(r *http.Request) (netip.Addr, bool) {
return peer, true return peer, true
} }
// tooManyRequests returns the 429 handler used by the // tooManyRequests returns the 429 handler used by the postRateLimit
// password-change and per-entrypoint receiver limiters: it logs the // limiters and the per-entrypoint receiver limiter: it logs the
// rejection with logMessage and answers with responseMessage. // rejection with logMessage and answers with responseMessage.
// httprate adds the Retry-After header (RFC 6585). The aggregate // httprate adds the Retry-After header (RFC 6585). The aggregate
// receiver limiter uses floodTooManyRequests instead. // receiver limiter uses floodTooManyRequests instead.
// //
// The path is capped against the same budget as the access log's url // On ReceiverRoute the line names the route pattern, so the
// field. The per-entrypoint receiver limiter is unauthenticated and // entrypoint UUID in the path is never logged. Elsewhere it names the
// its path is a client-chosen segment of client-chosen length, so at // path, capped against the same budget as the access log's url field;
// WARN an uncapped path would let a sender pick the size of the line // the limiters there sit behind RequireAuth, so the cap is defensive.
// it writes — the same defect the access log capping closed.
func (m *Middleware) tooManyRequests( func (m *Middleware) tooManyRequests(
logMessage, responseMessage string, logMessage, responseMessage string,
) http.HandlerFunc { ) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) { return func(w http.ResponseWriter, r *http.Request) {
path := r.URL.Path
if routePatternID(r.Context()) == ReceiverRoute {
path = ReceiverRoute
}
m.log.Warn( m.log.Warn(
logMessage, logMessage,
"path", logfield.Truncate( "path", logfield.Truncate(path, logfield.MaxBytes),
r.URL.Path, logfield.MaxBytes,
),
"remoteIP", RemoteIP(r), "remoteIP", RemoteIP(r),
"clientIP", ClientIP(r), "clientIP", ClientIP(r),
) )
+4 -3
View File
@@ -6,7 +6,8 @@ import (
sentryhttp "github.com/getsentry/sentry-go/http" sentryhttp "github.com/getsentry/sentry-go/http"
"github.com/go-chi/chi" "github.com/go-chi/chi"
"github.com/go-chi/chi/middleware" chimw "github.com/go-chi/chi/middleware"
"sneak.berlin/go/webhooker/internal/middleware"
"sneak.berlin/go/webhooker/static" "sneak.berlin/go/webhooker/static"
) )
@@ -60,7 +61,7 @@ func (s *Server) SetupRoutes() {
} }
func (s *Server) setupGlobalMiddleware() { func (s *Server) setupGlobalMiddleware() {
s.router.Use(middleware.RequestID) s.router.Use(chimw.RequestID)
s.router.Use(s.mw.SecurityHeaders()) s.router.Use(s.mw.SecurityHeaders())
s.router.Use(s.mw.Logging()) s.router.Use(s.mw.Logging())
@@ -345,7 +346,7 @@ func (s *Server) setupWebhookRoutes() {
// unauthenticated endpoint's body; TestReceiver_OversizeBodyRefused // unauthenticated endpoint's body; TestReceiver_OversizeBodyRefused
// pins it. // pins it.
s.router.With(s.mw.ReceiverRateLimit()).HandleFunc( s.router.With(s.mw.ReceiverRateLimit()).HandleFunc(
"/h/{uuid}", middleware.ReceiverRoute,
s.h.HandleWebhook(), s.h.HandleWebhook(),
) )
} }
+3 -4
View File
@@ -441,10 +441,9 @@ func (s *Session) Regenerate(
// //
// Whichever comes first ends the session. // Whichever comes first ends the session.
// //
// A session that claims to be authenticated but carries no // A session that claims to be authenticated but lacks the timestamp
// timestamps predates this check; it is treated as expired so the // a deadline is measured from is treated as expired, so the user
// user re-authenticates rather than being granted an unbounded // re-authenticates rather than being granted an unbounded session.
// session.
func (s *Session) expired(sess *sessions.Session) bool { func (s *Session) expired(sess *sessions.Session) bool {
now := s.now() now := s.now()
@@ -156,7 +156,8 @@ func TestVersion_IsStableAcrossInvocations(t *testing.T) {
// The build target is the only place composing linker flags. If a // The build target is the only place composing linker flags. If a
// future edit drops either half, the binary silently reports "dev" // future edit drops either half, the binary silently reports "dev"
// again (the defect this package exists for) or fails to link on // again (the defect this package exists for) or fails to link on
// Alpine. // Alpine. If it stops passing GO_TAGS, the image's static binary links
// glibc's getaddrinfo and dlopen again.
func TestMakefile_BuildComposesVersionAndExtraFlags(t *testing.T) { func TestMakefile_BuildComposesVersionAndExtraFlags(t *testing.T) {
t.Parallel() t.Parallel()
@@ -164,6 +165,7 @@ func TestMakefile_BuildComposesVersionAndExtraFlags(t *testing.T) {
require.Contains(t, makefile, "-X main.version=$(VERSION)") require.Contains(t, makefile, "-X main.version=$(VERSION)")
require.Contains(t, makefile, "$(GO_LDFLAGS)") require.Contains(t, makefile, "$(GO_LDFLAGS)")
require.Contains(t, makefile, "-tags '$(GO_TAGS)'")
require.Contains(t, makefile, "VERSION ?= $(shell script/version)") require.Contains(t, makefile, "VERSION ?= $(shell script/version)")
} }
@@ -233,7 +235,9 @@ func TestDockerfile_BuildsThroughTheMakeTarget(t *testing.T) {
"a raw go build bypasses the Makefile's -X flag") "a raw go build bypasses the Makefile's -X flag")
require.Contains(t, dockerfile, "ARG VERSION") require.Contains(t, dockerfile, "ARG VERSION")
require.Contains(t, dockerfile, require.Contains(t, dockerfile,
`make build VERSION="$VERSION" GO_LDFLAGS='-extldflags "-static"'`) `make build VERSION="$VERSION"`+
` GO_TAGS=netgo,osusergo,sqlite_omit_load_extension`+
` GO_LDFLAGS='-extldflags "-static"'`)
} }
func read(t *testing.T, path string) string { func read(t *testing.T, path string) string {