1 Commits
Author SHA1 Message Date
sneak 766f33a956 Milestone: next into main (#380)
check / check (push) Canceled after 0s
Reviewed-on: #380
2026-10-15 11:36:37 +02:00
14 changed files with 189 additions and 545 deletions
+48 -75
View File
@@ -802,11 +802,7 @@ 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. That log also records the full request path, so it holds the about traffic.
entrypoint UUID of every event a sender posts. webhooker's own log never
does. 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
@@ -832,9 +828,7 @@ 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. The # clientIP, only while TRUSTED_PROXIES covers this proxy.
# 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 / {
@@ -1166,12 +1160,7 @@ 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. webhooker's own log lines never carry the UUID: post events as that sender.
they name a request to the receiver by the route pattern `/h/{uuid}`, and the
`webhook request received` line names the entrypoint by its `entrypoint_id`.
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
@@ -1328,22 +1317,20 @@ 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. Delivery target. Failed deliveries are retried with configurable backoff. Every
attempts are logged with status codes, response bodies, and timing. delivery attempt is 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. A send still in flight when the service stops is payload it already got. webhooker adds no delivery identifier of its own to
left the same way: its attempt is not recorded, and the next start sends it an outbound request, so **make your receiver idempotent** against whatever
again (see Shutdown). webhooker adds no delivery identifier of its own to an the payload itself carries.
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 for delivery attempts. Prometheus metrics expose volume, latency, and and every delivery attempted. 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
@@ -1781,7 +1768,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, except one cut off by a stop (see Shutdown). individually logged for full observability.
| Field | Type | Description | | Field | Type | Description |
| --------------- | ------- | ----------------------------------------- | | --------------- | ------- | ----------------------------------------- |
@@ -2219,16 +2206,12 @@ 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** — the stop hook cancels the workers' context. A worker - **Graceful shutdown** — cancel the context, workers finish their current task
may still take tasks already queued before it exits. An `http` or `slack` and exit. The stop hook waits for the pool via `lifecycle.WaitForShutdown`,
request in flight is cut off, and one started after the cancel fails at once. which bounds that wait by fx's stop timeout rather than blocking forever on a
Neither is recorded or counted in the metrics, and the next start sends the wedged worker. On timeout it logs at `ERROR` and returns an error, and the
delivery again (see Shutdown). A `database` or `log` task runs as normal. The goroutines that did not finish are still running — an unclean shutdown is
stop hook waits for the pool via `lifecycle.WaitForShutdown`, which bounds reported rather than hidden.
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:**
@@ -2334,7 +2317,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`. An attempt cut off by a stop is not counted (see Shutdown) | | `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_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` |
@@ -2433,32 +2416,27 @@ 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`, naming the route pattern `/h/{uuid}` rather than the rejection at `WARN` with the request path, which on this route is
request path. A client hammering a single invented path is served attacker-controlled text. 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. The access log is bounded defaults, where before it there was no bound at all. Their _width_ is bounded by
by neither limit: every request is recorded once at `INFO`, served or rejected the field budgets below, the same ones the access log spends. The access log is
alike. bounded by neither limit: every request is recorded once at `INFO`, served or
rejected alike.
What the access log does bound is the _content_ of those lines. On the receiver What the access log does bound is the _content_ of those lines. A 3xx or 4xx
route it logs the route pattern `/h/{uuid}` whatever the status, because the response logs the chi route pattern — `/h/{uuid}`, `/user/{username}//`, or the
concrete path carries the entrypoint UUID, which is the entrypoint's credential literal `(unmatched)` when the request hit no route at all — in place of the
(see concrete URL. Those are the outcomes an unauthenticated client can drive for
[The entrypoint URL is the authentication secret](#the-entrypoint-url-is-the-authentication-secret)). free: 404 and 429 on any invented receiver path, a login redirect on any
A request chi never routed, because it matched no route or because a middleware invented profile path. Logging the URL there would let a flood write text of its
answered it first, logs the literal `(unmatched)` whatever the status. In the own choosing, at a length of its own choosing, into the log. 2xx and 5xx
`dev` environment the CORS middleware answers a preflight that way, so a responses keep the concrete path — a success resolved against a static route or
preflight to the receiver does not log its UUID either. On every other route, a against the operator's own data (on the receiver, against a stored entrypoint
3xx or 4xx response logs the chi route pattern, such as `/user/{username}//`, in UUID), and a 5xx is a bug in this service, where the exact path is the evidence
place of the concrete URL. Those are the outcomes an unauthenticated client can and no client can provoke one at will.
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
@@ -2484,10 +2462,9 @@ 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. What is sent is the chi route pattern instead: `http://host/h/{uuid}`. deliver. A tracker has its own retention, access control and deletion policy, so
A tracker has its own retention, access control and deletion policy, so the the rule the access log follows above does not carry across that boundary. What
pattern is sent on every route, including the 2xx and 5xx responses outside the is sent is the chi route pattern instead: `http://host/h/{uuid}`.
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
@@ -2616,7 +2593,9 @@ 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 |
@@ -2644,12 +2623,13 @@ 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.
Two of the sites go further and bound the whole flood's output — the total bytes Three of the sites go further and bound the whole flood's output — the total
a run of distinct invented values wrote, which is the shape an operator sizing bytes a run of distinct invented values wrote, which is the shape an operator
storage cares about. They are `request body exceeds limit` sizing storage cares about. They are `request body exceeds limit`
(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`) and `user not found` (`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`),
(through `assertBoundedFlood`). The other rows carry no aggregate assertion; the `entrypoint not found` and `user not found` (the last two through
per-line ceiling is what they establish. `assertBoundedFlood`). The other rows carry no aggregate assertion; the per-line
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
@@ -2667,7 +2647,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`, without the SQL and within the ceiling above. Slow its own miss at `DEBUG` — bounded, per the table above — without the SQL. 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
@@ -3304,8 +3284,7 @@ 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` — cuts off any `http` or `slack` request in flight, waits 4. `delivery.Engine` — waits for its workers, then closes the archive databases
for its workers, then closes the archive databases
5. `healthcheck` 5. `healthcheck`
6. `WebhookDBManager` 6. `WebhookDBManager`
7. the database close 7. the database close
@@ -3316,12 +3295,6 @@ 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,
-153
View File
@@ -2,16 +2,11 @@ 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"
@@ -277,154 +272,6 @@ 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
+1 -2
View File
@@ -32,8 +32,7 @@ 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. An attempt cut off by a stop is neither // from around this call.
// counted nor recorded.
type Target interface { type Target interface {
Deliver( Deliver(
ctx context.Context, ctx context.Context,
+3 -46
View File
@@ -57,11 +57,7 @@ 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,
@@ -70,55 +66,21 @@ func (c *httpCore) deliver(
attempt func() attemptResult, attempt func() attemptResult,
) { ) {
if maxRetries == 0 { if maxRetries == 0 {
c.fireAndForget(ctx, webhookDB, d, attempt()) c.fireAndForget(webhookDB, d, attempt())
return return
} }
c.withRetry( c.withRetry(
ctx, webhookDB, d, task, sched, maxRetries, attempt, 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(
@@ -148,7 +110,6 @@ 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,
@@ -170,10 +131,6 @@ 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(
@@ -438,7 +395,7 @@ func (t *httpTarget) Deliver(
} }
t.deliver( t.deliver(
ctx, webhookDB, d, task, sched, webhookDB, d, task, sched,
d.Target.MaxRetries, attempt, d.Target.MaxRetries, attempt,
) )
} }
+1 -1
View File
@@ -82,7 +82,7 @@ func (t *slackTarget) Deliver(
} }
t.deliver( t.deliver(
ctx, webhookDB, d, task, sched, webhookDB, d, task, sched,
d.Target.MaxRetries, attempt, d.Target.MaxRetries, attempt,
) )
} }
+49 -8
View File
@@ -1,15 +1,19 @@
package handlers_test package handlers_test
// The handler-side half of the log-field audit. The slog calls in // The handler-side half of the log-field audit. Two slog calls in
// this package that reach a value an UNAUTHENTICATED client picks // this package reach a value an UNAUTHENTICATED client picks outright
// outright, and of a length it picks outright, are the failed-login // and of a length it picks outright:
// DEBUG lines, whose username is a form field.
// //
// They are at DEBUG, which is off in production by default. That is // - the unknown-entrypoint DEBUG line on /h/{uuid}, whose
// 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. They spend the same // not thereby hand the flood an unbounded write. Both spend the same
// internal/logfield budget as the access log, and are held here to // internal/logfield budget as the access log, and both are held here
// middleware.MaxAccessLogLineBytes. // to 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
@@ -256,6 +260,43 @@ 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.
+19 -10
View File
@@ -10,6 +10,7 @@ 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"
) )
@@ -48,13 +49,14 @@ func (h *Handlers) HandleWebhook() http.HandlerFunc {
return return
} }
// Logged only once the lookup has found the entrypoint, so // Logged only once the UUID is known to name a real
// an invented path writes no INFO line; a miss is logged at // entrypoint. The UUID comes straight out of the path on
// DEBUG. The entrypoint is named by its ID: the UUID is its // the one unauthenticated endpoint, so logging it before
// credential and is never logged. // the lookup let a client write an INFO line per invented
// 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_id", entrypoint.ID, "entrypoint_uuid", entrypointUUID,
"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),
@@ -131,10 +133,17 @@ func (h *Handlers) lookupEntrypoint(
"path = ?", entrypointUUID, "path = ?", entrypointUUID,
).First(&entrypoint) ).First(&entrypoint)
if result.Error != nil { if result.Error != nil {
// Not even an unknown UUID is logged. The receiver's log // The receiver is unauthenticated and /h/{uuid}
// lines never carry the path segment, which is a credential // matches any single segment, so this value is entirely
// whenever it names an entrypoint. // client-chosen on exactly the branch where the lookup
h.log.Debug("entrypoint not found") // failed. DEBUG is off by default; the cap is what keeps
// 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,15 +12,12 @@ 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
@@ -102,87 +99,6 @@ 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 {
+12 -91
View File
@@ -7,7 +7,6 @@ import (
"log/slog" "log/slog"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"strconv"
"strings" "strings"
"testing" "testing"
@@ -28,13 +27,6 @@ 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
@@ -140,21 +132,17 @@ func accessLogRouter(m *middleware.Middleware) *chi.Mux {
) )
router.HandleFunc( router.HandleFunc(
middleware.ReceiverRoute, "/h/{uuid}",
func(w http.ResponseWriter, r *http.Request) { func(w http.ResponseWriter, r *http.Request) {
// Stands in for the real handler: a known entrypoint // Stands in for the real handler: an unknown entrypoint
// UUID succeeds, a failing one is a server error, and // UUID 404s, a known one succeeds.
// any other 404s. if chi.URLParam(r, "uuid") != "known" {
switch chi.URLParam(r, "uuid") {
case knownEntrypointUUID:
w.WriteHeader(http.StatusOK)
case failingEntrypointUUID:
http.Error(
w, "boom", http.StatusInternalServerError,
)
default:
http.Error(w, "not found", http.StatusNotFound) http.Error(w, "not found", http.StatusNotFound)
return
} }
w.WriteHeader(http.StatusOK)
}, },
) )
@@ -661,84 +649,17 @@ func TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery(
router := accessLogRouter(m) router := accessLogRouter(m)
assert.Equal( assert.Equal(
t, http.StatusOK, t, http.StatusOK, get(t, router, "/h/known?src=ci"),
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( assert.Equal(t, "/h/known?(redacted)", entries[0]["url"])
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)
}
func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) { func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
t.Parallel() t.Parallel()
+6 -12
View File
@@ -10,10 +10,8 @@ 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 receiver // - The rate limiters' 429 rejection, at WARN, on the
// route it names the route pattern rather than the path, and // unauthenticated receiver among others.
// 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
@@ -270,14 +268,10 @@ func logSites() map[string]logSite {
send: postNoToken, send: postNoToken,
wantStatus: http.StatusForbidden, wantStatus: http.StatusForbidden,
}, },
// The 429 line every limiter but the aggregate one shares. // The per-entrypoint receiver limiter, unauthenticated. Its
// Mounted outside any route, as here, it logs the path, as // bucket is keyed on the path, so the first request through a
// it does for the limiters behind RequireAuth; on // fresh path is served and only the ones after it are
// ReceiverRoute it names the pattern instead. The // rejected; sendUntilLimited absorbs that.
// 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,
+1 -2
View File
@@ -41,8 +41,7 @@ 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. The access log and the 429 line read it for the // while doing it.
// 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
+35 -44
View File
@@ -13,6 +13,7 @@ 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"
@@ -95,14 +96,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 unauthenticated-request DEBUG line, the // rejection, the rate-limit rejection, the unauthenticated-request
// failed-login DEBUG lines, and the two login-throttle WARN // and unknown-entrypoint DEBUG lines, the failed-login DEBUG
// lines ("login failure limit exceeded" in loginguard.go and // lines, and the two login-throttle WARN lines ("login failure
// "password verification capacity exhausted" in // limit exceeded" in loginguard.go and "password verification
// internal/handlers/auth.go) — spend the same per-field budgets, // capacity exhausted" in internal/handlers/auth.go) — spend the
// and each carries strictly fewer client-supplied fields than the // same per-field budgets, and each carries strictly fewer
// access log does, so none of them can reach a width the access // client-supplied fields than the access log does,
// log cannot. That is // so none of them can reach a width the access 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.
@@ -150,12 +151,6 @@ 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
@@ -273,14 +268,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 under /s means the file is in the // the operator's data — a 2xx on the receiver means the UUID named a
// embedded tree. The query is not bounded by anything: // stored entrypoint, a 2xx under /s means the file is in the embedded
// /.well-known/healthcheck and /s/* take no authentication and sit // tree. The query is not bounded by anything: /.well-known/healthcheck
// behind no rate limiter, and /pages/login behind only the login // and /s/* take no authentication and sit behind no rate limiter, and
// limiter, so any of them will answer 200 to a URL carrying an // /pages/login behind only the login limiter, so any of them will
// arbitrary number of arbitrary bytes after the '?'. Keeping the path // answer 200 to a URL carrying an arbitrary number of arbitrary bytes
// and dropping the query is what makes this branch as bounded as the // after the '?'. Keeping the path and dropping the query is what makes
// pattern branches below. // this branch as bounded as the 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,
@@ -302,41 +297,37 @@ 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.
// //
// On ReceiverRoute it is the route pattern whatever the status, so // 2xx and 5xx responses get the concrete path (see concreteLogURL). A
// the entrypoint UUID in the path is never logged. A request chi never // success resolved against a static route or against the operator's
// routed gets unmatchedRoute whatever the status, for the same reason: // own data — on the receiver, a 2xx means the UUID named a stored
// in dev, CORS answers a preflight to the receiver before routing. // entrypoint — and a server error is our own bug, where the exact URL
// // 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, such as a // the outcomes an unauthenticated client drives for free: 404 or 429
// 303 to the login page on any invented /user/ path. Logging the // on any invented /h/ path, 303 to the login page on any
// concrete URL there lets a flood write attacker-chosen text, of // invented /user/ path. Logging the concrete URL there lets a flood
// attacker-chosen length, into the operator's log at one line per // write attacker-chosen text, of attacker-chosen length, into the
// request. The pattern comes from the router's own table, so it is // operator's log at one line per request. The pattern comes from the
// bounded by the service's routes while still naming which class of // router's own table, so it is bounded by the service's routes while
// request was rejected. // still naming which class of 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
} }
}
return unmatchedRoute
}
// Logging returns middleware that logs each HTTP request with // Logging returns middleware that logs each HTTP request with
// timing and metadata. // timing and metadata.
+10 -12
View File
@@ -259,28 +259,26 @@ func (m *Middleware) clientAddr(r *http.Request) (netip.Addr, bool) {
return peer, true return peer, true
} }
// tooManyRequests returns the 429 handler used by the postRateLimit // tooManyRequests returns the 429 handler used by the
// limiters and the per-entrypoint receiver limiter: it logs the // password-change and per-entrypoint receiver limiters: 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.
// //
// On ReceiverRoute the line names the route pattern, so the // The path is capped against the same budget as the access log's url
// entrypoint UUID in the path is never logged. Elsewhere it names the // field. The per-entrypoint receiver limiter is unauthenticated and
// path, capped against the same budget as the access log's url field; // its path is a client-chosen segment of client-chosen length, so at
// the limiters there sit behind RequireAuth, so the cap is defensive. // WARN an uncapped path would let a sender pick the size of the line
// 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.MaxBytes), "path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
"remoteIP", RemoteIP(r), "remoteIP", RemoteIP(r),
"clientIP", ClientIP(r), "clientIP", ClientIP(r),
) )
+3 -4
View File
@@ -6,8 +6,7 @@ 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"
chimw "github.com/go-chi/chi/middleware" "github.com/go-chi/chi/middleware"
"sneak.berlin/go/webhooker/internal/middleware"
"sneak.berlin/go/webhooker/static" "sneak.berlin/go/webhooker/static"
) )
@@ -61,7 +60,7 @@ func (s *Server) SetupRoutes() {
} }
func (s *Server) setupGlobalMiddleware() { func (s *Server) setupGlobalMiddleware() {
s.router.Use(chimw.RequestID) s.router.Use(middleware.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())
@@ -346,7 +345,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(
middleware.ReceiverRoute, "/h/{uuid}",
s.h.HandleWebhook(), s.h.HandleWebhook(),
) )
} }