Compare commits

2 Commits

Author SHA1 Message Date
ec5acee69f Bound every slog line against client-chosen text (closes #176)
Some checks failed
check / check (push) Has been cancelled
MaxBodySize logged r.URL.Path untruncated at WARN, and routes.go
registers it ahead of RequireAuth, so an unauthenticated
POST /source/<8 KB>/edit with an oversize declared Content-Length wrote
attacker-chosen text of attacker-chosen length into the operator's log,
for the cost of a request with no body. The 2,560-byte per-line budget
from #146 did not reach it: that budget lives in the access log's field
capping and this is a separate slog call.

The capping mechanism moves out of internal/middleware into
internal/logfield so there is one budget and one implementation rather
than a second ad-hoc truncation. Truncate and EncodedBytes are
unchanged; the access log now spends logfield.MaxBytes where it spent
maxLogFieldBytes.

The sweep the issue asked for found five more call sites of the same
shape, all reachable unauthenticated, all now capped: the CSRF 403
(also registered ahead of RequireAuth), the rate limiters' 429 (the
per-entrypoint receiver limiter is unauthenticated), RequireAuth's own
DEBUG line, the unknown-entrypoint DEBUG line on the receiver, and the
failed-login DEBUG lines. DEBUG being off by default is not a bound: an
operator turning it on to diagnose a flood must not thereby hand the
flood an unbounded write. Every other slog call in the tree was read
and judged; the PR body lists all of them, including the ones left
alone and why.

Two further sites arrived in next with #171 after the first sweep was
written and are capped here as well: "login failure limit exceeded" in
loginguard.go and "password verification capacity exhausted" in
handlers/auth.go, both WARN on the unauthenticated login POST. Neither
was ever wide — chi routes that POST on a static pattern, so r.URL.Path
is the 12-byte constant /pages/login and each line lands near 120
bytes, and removing either cap breaks no test. They are capped because
RecordLoginFailure is exported and takes any *http.Request, so the
bound rests on a routing invariant nobody wrote down, and because the
same message at handlers/profile.go logs no path at all.

MaxBodySize stays ahead of RequireAuth. An oversize body should be
refused before the request buys a cookie decrypt and a session load,
and rejecting first is what keeps an unauthenticated flood from
choosing how much session work the process does. The ordering and what
it costs are now written at the registration, on maxFormBodySize.

MaxAccessLogLineBytes is restated as the ceiling on every slog line
carrying text an UNAUTHENTICATED client supplies, not just the access
log's: each of these lines carries strictly fewer client-supplied
fields than the access log does, so none can be wider. That is asserted
per line under both handlers rather than argued. The claim is qualified
rather than universal because three kinds of writer are outside it, and
the README and the constant now name all three: lines carrying an
authenticated operator's own input, which are not truncated at all (the
webhook name on "webhook created" reaches 600 KB on one line from a
100 KB form field, measured; the SSRF-rejection url and the target_name
lines are the same shape) and are left uncapped deliberately, since
truncating the operator's own configuration echoed back costs
debuggability against no adversary; the log delivery target, which
exists to emit the whole event; and GORM's default logger, which prints
the interpolated SQL to stdout on a record-not-found and is unbounded
on the receiver and login lookups. That last one is a real defect this
audit turned up and is filed separately as #178, not fixed here.

Tests drive 8 KB of client-chosen text at all six sites, through both
handlers internal/logger can install and through each character they
escape — including a bare C0 control, which costs six bytes on the line
against the one it cost to send and is the case a raw-byte budget
breaks on first. Each holds the encoded line to the ceiling, holds the
whole flood's output to what that ceiling allows, and asserts the
markers at the far end of the input are absent, so a value that merely
happened to be short cannot pass. The two login lines past the username
lookup, capped for uniformity rather than need, are pinned too.
internal/logfield gains a test that measures the per-rune charge
against what the handlers really emit over roughly 3,000 code points on
each, so an undercharged rune fails a test instead of quietly
falsifying the ceiling.

Verified by mutation: reverting the MaxBodySize cap alone fails 28
subtests with a 16,583-byte line against the 2,560 ceiling; reverting
the other five fails 70; uncapping either of the two login lines past
the username lookup fails both handlers on its own, so those two are
independently pinned rather than jointly; budgeting raw bytes instead
of encoded ones fails 23 across three packages. The two login-throttle
WARN caps are the exception and are recorded as such: reverting them
fails nothing, because the constant path gives the mutation nothing to
widen.
2026-08-18 00:52:43 +00:00
b573959a26 Send the chi route pattern to Sentry, not the concrete path (closes #179)
All checks were successful
check / check (push) Successful in 2m51s
#160 scrubbed the Sentry body, query, cookies, env and headers but kept
Request.URL, which the SDK builds from the concrete path. On the
receiver that path is /webhook/<uuid> in full — a write capability, not
an identifier: anyone holding it can inject events the operator's
targets then deliver. #146's "2xx and 5xx keep the concrete path" ruling
was reasoned about a log the operator owns and does not transfer to a
tracker with its own retention and access control.

The chi route pattern now replaces the path on every route, reached via
the request the SDK carries on hint.Context. Unconditional, because a
route-conditional rule leaks on any route someone forgets to add, and on
a static route the pattern is the path anyway. The fallback is never the
concrete path.

Also rewrites event.Transaction, which carries the same UUID on the
sibling dispatch and which the issue did not name. Tracing is off today,
so that half is a floor rather than a live fix — and it is why enabling
tracing later needs #185 first, or every transaction collapses into one
bucket.

Independently reviewed. The reviewer ran fourteen adversarial probes —
404 and 405 panics, panics in middleware before and after routing,
direct CaptureException, mounted subrouters, wildcards, tracing on and
off — and found no path where the concrete URL survives, and no third
field carrying it.

Merge note: the final round was a two-comment documentation fix on an
already-passed review, correcting a rationale that called the host
operator configuration when it is the client's Host header. I verified
that amend is comment-only myself rather than spending a fifth review
round on it.
2026-08-18 02:42:58 +02:00
17 changed files with 2098 additions and 252 deletions

196
README.md
View File

@@ -994,15 +994,16 @@ costs; 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 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 still logs every rejection at `WARN` with
the request path, which on this route is attacker-controlled text. A
client hammering a single invented path is served `RECEIVER_RATE_LIMIT`
limiter is the loud one: it logs every rejection at `WARN` with the
request path, which on this route is 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 there, so
the aggregate limit is what bounds those `WARN` lines — 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 by neither limit: every request is recorded once at `INFO`,
served or rejected alike.
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 defaults, where before it there was no bound at all. Their
_width_ is bounded by the field budgets below, the same ones the access
log spends. The access log is 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. A 3xx
or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
@@ -1037,38 +1038,77 @@ reduces the headers to a fixed allowlist — `Accept`, `Content-Length`,
`Content-Type`, `Host`, `Origin`, `Referer`, `User-Agent` and
`X-Request-Id`.
The body is replaced on every route rather than filtered by route, and
that is a choice rather than a limitation: the route is reachable from
the hook. `sentryhttp`'s recover path puts the request on the context
it hands to `RecoverWithContext`, and the SDK carries that context
through to `BeforeSend` as `hint.Context`, so
`hint.Context.Value(sentry.RequestContextKey)` yields the live request
and chi's `RoutePattern()` yields the matched pattern off it. There
are two reasons to redact unconditionally anyway. Nothing debuggable
is lost:
every handler reads its fields with `PostFormValue`, so the body is
exactly where the credentials are — the target destination URL, the
login password, both password-change fields — and the one route whose
body is genuine signal is the receiver, whose body is already stored
on the event and served from the UI, so a tracker is not where anyone
reads it. And an unconditional rule cannot leak on a route somebody
forgets to add to it, which a route-conditional one can.
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 `/webhook/<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 deliver. A tracker has its own
retention, access control and deletion policy, so the rule the access
log follows above does not carry across that boundary. What is sent is
the chi route pattern instead: `http://host/webhook/{uuid}`.
The headers are an allowlist for that second reason: the SDK's own
filter removes four names and passes everything else, which would ship
`X-CSRF-Token` and the shared secrets senders put on the receiver
route. What survives still names the failing route — scheme, host,
path, method — and `X-Request-Id` ties the event to the local access
log line that holds the rest. Nothing dropped is needed for the
likeliest use, debugging a CSRF rejection. Its three inputs are the
TLS decision, `Origin` and `Referer`; the latter two are kept, and the
first is already in the retained URL, because the SDK derives that
URL's scheme from `r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"`
byte for byte the predicate `internal/middleware/csrf.go` uses to
choose between the `csrf.Secure(true)` and `csrf.Secure(false)`
handlers. So dropping `X-Forwarded-Proto` costs nothing. The dropped
provider headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are
real signal but are recorded locally on the event, and
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 cannot widen this. The scheme has to survive
for the reason given below. The host is whatever the request's `Host`
header carried — this service validates no hostname, so on a directly
exposed deployment a client sets it — and that same header is on the
allowlist above, so scrubbing the host out of the URL would withhold
nothing that is not sent anyway.
The body, the query string and the URL are all handled on every route
rather than filtered by route. For the URL that is also what keeps the
event locatable: an error event is grouped by its exception and stack
trace, not by its URL, so replacing the path with the pattern costs no
grouping and the pattern still names the route in the UI. And an
unconditional rule cannot leak on a route somebody forgets to add to
it, which a route-conditional one can. For the body there is a second
reason: nothing debuggable is lost, because every handler reads its
fields with `PostFormValue`, so the body is exactly where the
credentials are — the target destination URL, the login password, both
password-change fields — and the one route whose body is genuine
signal is the receiver, whose body is already stored on the event and
served from the UI, so a tracker is not where anyone reads it.
The route is reachable from the hook only on the error dispatch.
`sentryhttp`'s recover path puts the request on the context it hands
to `RecoverWithContext`, and the SDK carries that context through to
`BeforeSend` as `hint.Context`, so
`hint.Context.Value(sentry.RequestContextKey)` yields the live request
and chi's `RoutePattern()` yields the matched pattern off it. The
transaction dispatch has no such request: a finished span captures
with a nil hint, which the client replaces with an empty one, so
`BeforeSendTransaction` sees no context at all. Tracing is off in this
service, so no transaction event is produced today, but the hook is
installed on both dispatches as a floor.
Where the pattern is out of reach — the transaction dispatch, an event
captured outside the router, or a request that matched no route — the
fallback is never the concrete path. The path becomes the literal
`/(redacted)`, so the URL reads `http://host/(redacted)`; a URL the
rewrite cannot parse into a scheme is withheld whole. A transaction
event additionally carries the SDK's own `METHOD /path` name, built
from the concrete path as well; it is rewritten on the same terms, to
`POST /webhook/{uuid}` where the pattern is known and `POST
/(redacted)` where it is not.
The headers are an allowlist for the same reason the rules above are
unconditional: the SDK's own filter removes four names and passes
everything else, which would ship `X-CSRF-Token` and the shared
secrets senders put on the receiver route. What survives still names
the failing route — scheme, host, route pattern, method — and
`X-Request-Id` ties the event to the local access log line that holds
the rest. Nothing dropped is needed for the likeliest use, debugging a
CSRF rejection. Its three inputs are the TLS decision, `Origin` and
`Referer`; the latter two are kept, and the first is the scheme of the
retained URL, because the SDK derives that scheme from
`r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"` — byte
for byte the predicate `internal/middleware/csrf.go` uses to choose
between the `csrf.Secure(true)` and `csrf.Secure(false)` handlers.
That is what the rewrite above preserves it for, and it is why
dropping `X-Forwarded-Proto` costs nothing. The dropped provider
headers (`X-GitHub-Event`, `X-Gitlab-Event` and the like) are real
signal but are recorded locally on the event, and
`Sentry-Trace`/`Baggage` are already reflected in the event's trace
context.
@@ -1113,6 +1153,84 @@ that the rate is not bounded by the limits above on every route:
`/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
the multiplier is whatever the deployment will serve.
**The same ceiling covers every other line the service writes through
`slog` that carries text an unauthenticated client supplies.** The
access log is not the only line a client can put its own text into, and
a budget that held for one line and not the others would be worse than
no stated budget at all. Every `slog` call an unauthenticated request
can reach spends the same per-field budget through `internal/logfield`,
and each carries strictly fewer client-supplied fields than the access
log does, so none of them can be wider than it:
| Log line | Level | Client-chosen value | Reachable unauthenticated |
| ------------------------------------------ | ------- | ------------------- | ----------------------------------------- |
| `request body exceeds limit` (413) | `WARN` | path, method | yes — `MaxBodySize` 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 |
| `entrypoint not found` | `DEBUG` | entrypoint UUID | yes, on the receiver |
| `user not found` / `invalid password` | `DEBUG` | username | yes, on the login form |
| `login failure limit exceeded` (429) | `WARN` | path | yes, on the login form |
| `password verification capacity exhausted` | `WARN` | path | yes, on the login form |
`DEBUG` being off by default is not a bound. An operator turning it on
to diagnose a flood must not thereby hand the flood an unbounded write,
so those lines are capped too.
The last two rows are capped defensively rather than against a
demonstrated width: chi routes `POST /pages/login` on a static pattern,
so `r.URL.Path` there is the 12-byte constant `/pages/login` and each
line lands near 120 bytes. `RecordLoginFailure` is nonetheless an
exported method taking any `*http.Request`, so a future caller on a
route with a URL parameter would widen the line with nothing failing.
Removing either cap therefore breaks no test — recorded here because a
cap whose absence is undetectable is worth saying so about.
`internal/middleware/logbound_test.go` and
`internal/handlers/logbound_test.go` drive 8 KB of client-chosen text at
each of these, through both handlers and through every character the
handlers escape, and hold each line to the 2,560-byte ceiling — and the
whole flood's output to what that ceiling allows, which is the property
an operator actually cares about.
`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 undercharged rune fails a test rather than quietly
falsifying the ceiling.
What that ceiling does **not** cover, stated here so the figure is not
read as more than it is:
- **Lines carrying an authenticated operator's own input**, which are
not truncated at all. `webhook created` logs the submitted `name`
verbatim and `target URL blocked by SSRF protection` logs the target
host (both `internal/handlers/source_management.go`), as do the
`target_name` lines in `internal/delivery/engine.go` and
`internal/delivery/target_http.go`. The only bound on any of them is
the 1 MB form body cap, so a 100 KB `name` writes a single line of
roughly 600 KB — measured. This is deliberate: every one of these
requires an authenticated operator on a service with no
self-registration, and truncating the operator's own configuration
echoed back would cost debuggability against no adversary. It does
mean the 2,560-byte figure sizes unauthenticated traffic, not the
operator's own administrative requests.
- The **`log` delivery target**, which writes the whole inbound event —
headers and body — to the log. This one is deliberate: capping it
would defeat the target, since emitting the payload is the delivery.
It costs nothing unless an authenticated operator creates a target of
that type on a specific webhook, and each line it writes is bounded
per event by the 1 MB receiver body cap. Adding one is a decision to
spend log volume on that webhook's payloads.
- **GORM's default logger**, which prints the fully interpolated SQL to
stdout on every record-not-found — including the client-chosen path
on `/webhook/{uuid}` and the submitted username on the login form.
This one is not deliberate and not yet fixed; it does not go through
`internal/logger` at all, so no level the operator sets and no budget
above applies to it. Tracked at
<https://git.eeqj.de/sneak/webhooker/issues/178>. Until it is fixed,
an unauthenticated flood can still write text of its own choosing and
its own length to the operator's stdout, and the ceiling above
describes only the `slog` half of the picture.
Every limiter here — receiver, login, and password change — identifies
the client the same way, through one shared key function: the
connection's own address, unless the peer is listed in

View File

@@ -11,6 +11,17 @@ import (
// inbound webhook — the full request body and headers, plus
// the method, content type, and the webhook and entrypoint
// ids — then records a single successful attempt.
//
// This is the one log call in the service that deliberately writes
// unbounded client-chosen bytes, so it is the one exception to the
// per-field budgets in internal/logfield and to the ceiling stated on
// middleware.MaxAccessLogLineBytes. Capping here would defeat the
// target: emitting the payload IS the delivery. It costs nothing by
// default — an authenticated operator has to create a target of this
// type on a specific webhook before a single line is written — and the
// bytes it writes are bounded per event by maxWebhookBodySize (1 MB).
// An operator who adds one is choosing to spend log volume on the
// payloads that webhook receives.
type logTarget struct {
eng *Engine
}

View File

@@ -5,6 +5,7 @@ import (
"strconv"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/logfield"
)
// HandleLoginPage returns a handler for the login page (GET)
@@ -70,7 +71,9 @@ func (h *Handlers) HandleLoginSubmit() http.HandlerFunc {
h.log.Info(
"user logged in",
"username", username,
"username", logfield.Truncate(
username, logfield.MaxBytes,
),
"user_id", user.ID,
)
@@ -117,7 +120,9 @@ func (h *Handlers) authenticateUser(
if !ok {
h.log.Warn(
"password verification capacity exhausted",
"path", r.URL.Path,
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
)
h.renderLoginError(
w, r,
@@ -142,7 +147,17 @@ func (h *Handlers) authenticateUser(
h.dummyVerifications.Add(1)
database.VerifyDummyPassword(password)
h.log.Debug("user not found", "username", username)
// Login is unauthenticated, and the submitted username is
// a form field the client fills to any length the 1 MB
// body cap allows. On this branch it matched no row, so
// nothing else bounds it. The rate limiter caps how often
// the line is written, not how wide it is.
h.log.Debug(
"user not found",
"username", logfield.Truncate(
username, logfield.MaxBytes,
),
)
h.rejectLogin(w, r, username)
return user, err
@@ -160,7 +175,17 @@ func (h *Handlers) authenticateUser(
}
if !valid {
h.log.Debug("invalid password", "username", username)
// Reached only once the username matched a stored row, so
// it is bounded by the operator's own data. Capped anyway,
// so that every username this unauthenticated endpoint
// logs is capped and no reader has to work out which
// branch narrowed it.
h.log.Debug(
"invalid password",
"username", logfield.Truncate(
username, logfield.MaxBytes,
),
)
h.rejectLogin(w, r, username)
return user, errInvalidPassword

View File

@@ -2,11 +2,19 @@ package handlers
import (
"html/template"
"log/slog"
"net/http"
"sneak.berlin/go/webhooker/internal/database"
)
// SetLogForTest replaces the handler's logger, so the handlers_test
// package can assert on what a log line actually contains rather than
// on what it is meant to contain.
func (s *Handlers) SetLogForTest(log *slog.Logger) {
s.log = log
}
// MaxRenderedBodyBytesForTest exposes the event log's body cap
// to the handlers_test package.
const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes

View File

@@ -0,0 +1,451 @@
package handlers_test
// The handler-side half of the log-field audit. Two slog calls in
// this package reach a value an UNAUTHENTICATED client picks outright
// and of a length it picks outright:
//
// - the unknown-entrypoint DEBUG line on /webhook/{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 thereby hand the flood an unbounded write. Both spend the same
// internal/logfield budget as the access log, and both are held here
// to middleware.MaxAccessLogLineBytes.
//
// The two login lines past the username lookup — "invalid password"
// and "user logged in" — carry the same cap without needing it, since
// by then the value is a stored row rather than the client's. They are
// pinned here too, so the caps cannot be dropped silently.
import (
"bytes"
"context"
"io"
"log/slog"
"net/http"
"net/http/httptest"
"net/url"
"strings"
"testing"
"github.com/go-chi/chi"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/handlers"
"sneak.berlin/go/webhooker/internal/middleware"
)
// floodRequests is the number of distinct invented values each flood
// drives through the call site under test.
const floodRequests = 32
// oversizedFillBytes is the length of the single client-chosen value
// used to show that line size does not track input size.
const oversizedFillBytes = 8192
// attackerMarker and tailMarker sit at the END of every oversized
// value, past every budget. Their absence from the log is what
// proves the value was cut rather than merely being short.
const (
attackerMarker = "QQATTACKERTEXTQQ"
tailMarker = "QQTRUNCATEDTAILQQ"
)
// escapeFills are the characters the log handlers escape, so a value
// built out of them costs more on the line than it did on the wire. A
// budget counted in raw bytes passes the plain case and fails these.
//
// U+1000C is unassigned, hence non-printable, and strconv.Quote
// spells it as a ten-byte \UXXXXXXXX while the JSON handler passes
// its four UTF-8 bytes through; only the text shape of these tests
// reaches that charge.
func escapeFills() map[string]string {
return map[string]string{
"plain": "x",
"quote": `"`,
"backslash": `\`,
"tab": "\t",
"newline": "\n",
// A C0 control neither handler has a short escape for, so
// each one costs six bytes on the line against the single
// byte it cost to send: the widest multiplier a client can
// drive, and the case a raw-byte budget breaks on first.
//
// This fill is load-bearing, not decoration. Budgeting raw
// bytes instead of encoded is caught by this fill alone,
// and only under the JSON handler, at 3,072 bytes against
// the 2,560 ceiling. Drop it and that mutation passes.
"control": "\x01",
"astral": "\U0001000C",
}
}
// logHandlers are the two handlers internal/logger can install.
func logHandlers() map[string]func(
io.Writer, *slog.HandlerOptions,
) slog.Handler {
return map[string]func(
io.Writer, *slog.HandlerOptions,
) slog.Handler{
"json": func(
w io.Writer, o *slog.HandlerOptions,
) slog.Handler {
return slog.NewJSONHandler(w, o)
},
"text": func(
w io.Writer, o *slog.HandlerOptions,
) slog.Handler {
return slog.NewTextHandler(w, o)
},
}
}
// oversizedFill builds an 8 KB client-chosen value out of
// repetitions of ch, with both markers at its far end.
func oversizedFill(ch string) string {
return "x" + strings.Repeat(ch, oversizedFillBytes) +
attackerMarker + tailMarker
}
// capturingHandlersWithDB is capturingHandlers plus the database, for
// the call sites that write their line only once the client's value
// matched a stored row.
func capturingHandlersWithDB(
t *testing.T,
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
) (*handlers.Handlers, *database.Database, *bytes.Buffer) {
t.Helper()
var (
h *handlers.Handlers
db *database.Database
)
app := newTestApp(t, &h, &db)
app.RequireStart()
t.Cleanup(app.RequireStop)
buf := new(bytes.Buffer)
h.SetLogForTest(slog.New(newHandler(
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
)))
return h, db, buf
}
// capturingHandlers builds a Handlers whose log is captured into the
// returned buffer at DEBUG through the named handler.
func capturingHandlers(
t *testing.T,
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
) (*handlers.Handlers, *bytes.Buffer) {
t.Helper()
var h *handlers.Handlers
app := newTestApp(t, &h)
app.RequireStart()
t.Cleanup(app.RequireStop)
buf := new(bytes.Buffer)
h.SetLogForTest(slog.New(newHandler(
buf, &slog.HandlerOptions{Level: slog.LevelDebug},
)))
return h, buf
}
// logLines splits the captured buffer into non-empty lines, holding
// each to bound bytes.
func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string {
t.Helper()
var lines []string
for line := range strings.SplitSeq(
strings.TrimSpace(buf.String()), "\n",
) {
if line == "" {
continue
}
require.LessOrEqual(
t, len(line), bound,
"log line exceeded its bound: %s", line,
)
lines = append(lines, line)
}
return lines
}
// assertNoClientText fails if the far end of the client-chosen input
// survived into the log.
func assertNoClientText(t *testing.T, buf *bytes.Buffer) {
t.Helper()
assert.NotContains(
t, buf.String(), attackerMarker,
"log carried attacker-chosen text",
)
assert.NotContains(
t, buf.String(), tailMarker,
"log carried the tail of the attacker-chosen text",
)
}
// receiverRouter mounts the real receiver handler at the production
// route pattern.
func receiverRouter(h *handlers.Handlers) *chi.Mux {
router := chi.NewRouter()
router.Post("/webhook/{uuid}", h.HandleWebhook())
return router
}
// postReceiver sends one POST at /webhook/<segment>.
//
// RawPath is cleared after parsing so chi routes on the decoded path
// and the handler sees the raw bytes rather than their percent-escaped
// spelling. That is the harder case for the budget: the escaped
// spelling is plain ASCII, which costs one byte per byte, while the
// decoded bytes are what the log handler has to escape.
func postReceiver(
t *testing.T, router *chi.Mux, segment string,
) int {
t.Helper()
req := httptest.NewRequestWithContext(
context.Background(),
http.MethodPost,
"/webhook/"+url.PathEscape(segment),
strings.NewReader(""),
)
req.URL.RawPath = ""
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
return w.Code
}
// postLogin submits the login form with the given username and a
// non-empty password.
func postLogin(
t *testing.T, h *handlers.Handlers, username string,
) int {
t.Helper()
return postLoginWithPassword(t, h, username, "not-the-password")
}
// postLoginWithPassword submits the login form with both credentials
// chosen by the caller, so a test can reach the branches past the
// username lookup.
func postLoginWithPassword(
t *testing.T, h *handlers.Handlers, username, password string,
) int {
t.Helper()
form := url.Values{
"username": {username},
"password": {password},
}
req := httptest.NewRequestWithContext(
context.Background(),
http.MethodPost,
"/pages/login",
strings.NewReader(form.Encode()),
)
req.Header.Set(
"Content-Type", "application/x-www-form-urlencoded",
)
w := httptest.NewRecorder()
h.HandleLoginSubmit().ServeHTTP(w, req)
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, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests)
assertNoClientText(t, buf)
assertBoundedFlood(t, buf.Len())
})
}
}
}
// TestFailedLogin_LogLineDoesNotTrackUsernameSize drives 8 KB of
// client-chosen username at the unauthenticated login endpoint's
// DEBUG line and holds it to the same ceiling.
func TestFailedLogin_LogLineDoesNotTrackUsernameSize(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)
for i := range floodRequests {
assert.Equal(
t,
http.StatusUnauthorized,
postLogin(
t, h,
oversizedFill(fill)+
strings.Repeat("y", i),
),
)
}
lines := logLines(
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests)
assertNoClientText(t, buf)
assertBoundedFlood(t, buf.Len())
})
}
}
}
// storedUserPassword is the password held by the oversize accounts
// the test below creates.
const storedUserPassword = "correct-horse-battery-staple"
// storedFillBytes is the raw length of the client-chosen value in
// those accounts' usernames. It is well past the 512-byte field
// budget, so the line is still truncated, but short enough that the
// session cookie a successful login writes stays inside
// securecookie's 4 KB limit: the cookie is written BEFORE the
// "user logged in" line, so an 8 KB username answers 500 and never
// reaches it.
const storedFillBytes = 1024
// storedFill builds a username fill of storedFillBytes raw bytes out
// of repetitions of ch, with both markers at its far end.
func storedFill(ch string) string {
return "x" + strings.Repeat(ch, storedFillBytes/len(ch)) +
attackerMarker + tailMarker
}
// TestStoredUsername_LogLinesDoNotTrackUsernameSize pins the two
// login lines that are reached only AFTER the username matched a
// stored row: "invalid password" and "user logged in". Neither
// strictly needs its cap — the value is the operator's own data by
// then, not the client's — but both carry one so that every username
// this unauthenticated endpoint logs is capped, and an unasserted cap
// is one a later edit removes for free.
//
// One app per handler with the accounts created inside it, and no
// parallelism below that level: every account costs an Argon2id hash
// and every attempt costs a verification.
func TestStoredUsername_LogLinesDoNotTrackUsernameSize(t *testing.T) {
t.Parallel()
for handlerName, newHandler := range logHandlers() {
t.Run(handlerName, func(t *testing.T) {
t.Parallel()
h, db, buf := capturingHandlersWithDB(t, newHandler)
hash, err := database.HashPassword(storedUserPassword)
require.NoError(t, err)
fills := escapeFills()
for fillName, fill := range fills {
username := storedFill(fill) + fillName
require.NoError(t, db.DB().Create(&database.User{
Username: username,
Password: hash,
}).Error)
// Matched the row, wrong secret: "invalid
// password".
assert.Equal(
t, http.StatusUnauthorized,
postLoginWithPassword(
t, h, username, "not-the-password",
),
)
// Matched the row, right secret: "user logged
// in".
assert.Equal(
t, http.StatusSeeOther,
postLoginWithPassword(
t, h, username, storedUserPassword,
),
)
}
lines := logLines(
t, buf, middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, 2*len(fills))
assertNoClientText(t, buf)
})
}
}
// assertBoundedFlood holds the whole flood's log output to what the
// stated per-line ceiling allows. The flood sent
// floodRequests * oversizedFillBytes bytes of client-chosen text;
// this is the assertion that the log did not grow with it.
func assertBoundedFlood(t *testing.T, got int) {
t.Helper()
sent := floodRequests * oversizedFillBytes
require.Less(
t, got, sent/2,
"log volume tracked the size of the flood's input",
)
require.LessOrEqual(
t, got,
floodRequests*middleware.MaxAccessLogLineBytes,
)
}

View File

@@ -9,6 +9,7 @@ import (
"gorm.io/gorm"
"sneak.berlin/go/webhooker/internal/database"
"sneak.berlin/go/webhooker/internal/delivery"
"sneak.berlin/go/webhooker/internal/logfield"
)
const (
@@ -125,9 +126,16 @@ func (h *Handlers) lookupEntrypoint(
"path = ?", entrypointUUID,
).First(&entrypoint)
if result.Error != nil {
// The receiver is unauthenticated and /webhook/{uuid}
// matches any single segment, so this value is entirely
// client-chosen on exactly the branch where the lookup
// 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", entrypointUUID,
"path", logfield.Truncate(
entrypointUUID, logfield.MaxBytes,
),
)
http.NotFound(w, r)

View File

@@ -0,0 +1,143 @@
// Package logfield bounds the client-supplied values this service
// writes into its logs.
//
// Any log field whose content a client picks is spent against a budget
// here, in ENCODED bytes rather than in the bytes the client sent, so
// that escaping cannot multiply a field past its nominal size. One
// budget and one implementation serves the access log in
// internal/middleware and every other slog call that reaches a
// client-chosen path, header or form value; a second, ad-hoc
// truncation somewhere else in the tree is the thing this package
// exists to prevent.
package logfield
import (
"strings"
"unicode"
"unicode/utf8"
)
const (
// MaxBytes is the default budget for a log field whose value the
// client supplies outright: a URL, a path, a header, a form value.
// The budget is spent in ENCODED bytes (see Truncate), so 512 still
// holds a real browser's User-Agent whole — those are plain ASCII,
// which encodes one byte for one — while a value built from
// characters the encoder escapes keeps a shorter prefix. That is
// the intended trade: 500 quotation marks are not a debugging
// asset.
MaxBytes = 512
// TruncationMarker is appended to any field that was cut, so a
// short value and a truncated one cannot be confused. It is charged
// on top of the budget, not inside it.
TruncationMarker = "[truncated]"
)
// EncodedBytes is what r costs on the line once the log handler has
// escaped it, taking the worse of the two handlers internal/logger
// configures.
//
// slog's JSON handler escapes quote, backslash, newline, carriage
// return and tab to two bytes each, and every other C0 control plus
// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
// passes every other rune through as its own UTF-8. Its text handler
// quotes with strconv.Quote, which spells a non-printable rune below
// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
// bytes, not six. The text handler is therefore the worse of the two
// for every non-printable rune, and by four bytes apiece for the
// 955,086 unassigned, private-use and format code points on planes 1
// to 16.
//
// Charging ten there is what makes the stated line ceilings hold for
// the tty handler as well: U+1000C encodes as F0 90 80 8C, every byte
// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
// net/textproto does not strip, so a header can be filled with them.
//
// Both handlers pass printable runes through as their own UTF-8, so
// unicode.IsPrint separates the escaped cases from the plain ones for
// either handler.
func EncodedBytes(r rune) int {
const (
// A backslash and the character itself.
shortEscapeBytes = 2
// \uXXXX, which is also the width of \u00XX.
escapedRuneBytes = 6
// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
// rune outside the basic multilingual plane.
escapedAstralRuneBytes = 10
// The first code point strconv.Quote spells with \U.
firstAstralRune = 0x10000
)
switch {
case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
return shortEscapeBytes
case !unicode.IsPrint(r) && r >= firstAstralRune:
return escapedAstralRuneBytes
case !unicode.IsPrint(r):
return escapedRuneBytes
default:
return utf8.RuneLen(r)
}
}
// Truncate caps s at maxBytes of ENCODED output, marking the value
// when it cuts.
//
// Budgeting raw bytes would not bound the line. Escaping only ever
// grows a value, so a raw budget spent on characters the encoder
// escapes buys a field several times its nominal size — and the line
// is the thing an operator is told to multiply by their request rate.
// Charging each rune what it will actually cost is what makes a stated
// ceiling true rather than merely larger. The visible consequence is
// that an escape-heavy value keeps a shorter prefix than a plain one,
// which is the correct trade.
//
// The result is always valid UTF-8. A cut on a byte boundary can split
// a multi-byte rune, and a header can carry bytes that were never
// valid UTF-8 to begin with; both are dropped rather than kept, since
// an encoder would otherwise spend six bytes replacing each one.
func Truncate(s string, maxBytes int) string {
// No rune encodes to fewer bytes than it occupies, so nothing past
// maxBytes raw can fit the budget. Slicing first bounds the scan
// below to the budget rather than to the size of the header the
// client sent.
window, cut := s, false
if len(window) > maxBytes {
window, cut = window[:maxBytes], true
}
var (
kept strings.Builder
spent int
)
for i := 0; i < len(window); {
r, size := utf8.DecodeRuneInString(window[i:])
if r == utf8.RuneError && size == 1 {
i += size
continue
}
cost := EncodedBytes(r)
if spent+cost > maxBytes {
cut = true
break
}
spent += cost
kept.WriteString(window[i : i+size])
i += size
}
if !cut {
return kept.String()
}
return kept.String() + TruncationMarker
}

View File

@@ -0,0 +1,221 @@
package logfield_test
import (
"bytes"
"io"
"log/slog"
"strings"
"testing"
"unicode/utf8"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/logfield"
)
// budget is the field budget these tests spend. Small enough that a
// cut is unambiguous, large enough to hold several runes of every
// width.
const budget = 64
// sampleRunes is how many runes wide the values in the charge test
// are. The handlers add a constant per field — a pair of quotes when
// the value needs quoting — so the per-rune charge is only visible
// once it is amortised over a run of them.
const sampleRunes = 64
// quotingSlack is that constant: the pair of quotes a handler adds to
// a value that needs them and omits from one that does not.
const quotingSlack = 2
// newHandlers are the two handlers internal/logger can install. Time
// is dropped so a line's width is a function of its value alone —
// RFC3339Nano trims trailing zeros, so two consecutive timestamps do
// not render to the same number of bytes.
func newHandlers() map[string]func(io.Writer) slog.Handler {
opts := &slog.HandlerOptions{
Level: slog.LevelDebug,
ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
if a.Key == slog.TimeKey {
return slog.Attr{}
}
return a
},
}
return map[string]func(io.Writer) slog.Handler{
"json": func(w io.Writer) slog.Handler {
return slog.NewJSONHandler(w, opts)
},
"text": func(w io.Writer) slog.Handler {
return slog.NewTextHandler(w, opts)
},
}
}
// renderedWidth is the number of bytes a handler writes for a line
// carrying value in a single attribute.
func renderedWidth(
newHandler func(io.Writer) slog.Handler,
value string,
) int {
buf := new(bytes.Buffer)
slog.New(newHandler(buf)).Info("m", "v", value)
return buf.Len()
}
// chargeTestRunes is the set of code points the charge test measures:
// every rune in the first two planes' worth of the BMP that the
// handlers are most likely to treat specially, the separators that
// only slog's JSON handler escapes, and a stratified sample across
// the rest of Unicode so the astral charge is exercised on more than
// one hand-picked rune.
func chargeTestRunes() []rune {
const (
denseCeiling = 0x800
stride = 1021
surrogateLo = 0xD800
surrogateHi = 0xDFFF
)
var runes []rune
keep := func(r rune) {
if r >= surrogateLo && r <= surrogateHi {
return
}
runes = append(runes, r)
}
for r := range rune(denseCeiling) {
keep(r)
}
for _, r := range []rune{
0x2028, 0x2029, 0x200B, 0x4E00, 0xE000, 0xFFFD,
0x1000C, 0x1F600, 0xE0001, 0x10FFFF,
} {
keep(r)
}
for r := rune(denseCeiling); r <= utf8.MaxRune; r += stride {
keep(r)
}
return runes
}
// TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit is the property
// the whole capping scheme rests on: a rune may not cost more on the
// line than the budget was charged for it. An undercharged rune is
// how a stated ceiling becomes false without any test noticing, so
// the charge is measured against what the handlers actually write
// rather than against the escaping rules as read.
func TestEncodedBytes_ChargesAtLeastWhatTheHandlersEmit(t *testing.T) {
t.Parallel()
for name, newHandler := range newHandlers() {
t.Run(name, func(t *testing.T) {
t.Parallel()
// 'a' is a printable ASCII rune, charged exactly one
// byte, so it is the zero point the other runes are
// measured against.
base := renderedWidth(
newHandler, strings.Repeat("a", sampleRunes),
)
for _, r := range chargeTestRunes() {
got := renderedWidth(
newHandler,
strings.Repeat(string(r), sampleRunes),
)
charged := sampleRunes *
(logfield.EncodedBytes(r) - 1)
require.LessOrEqual(
t, got-base, charged+quotingSlack,
"U+%04X costs more on the line than "+
"EncodedBytes charges for it",
r,
)
}
})
}
}
// TestTruncate_SpendsNoMoreThanTheBudget holds the result to the
// budget in ENCODED bytes, which is the unit the budget is stated in.
// A raw-byte cap passes the ASCII case here and fails every other
// one.
func TestTruncate_SpendsNoMoreThanTheBudget(t *testing.T) {
t.Parallel()
for name, fill := range map[string]string{
"plain": "x",
"quote": `"`,
"backslash": `\`,
"tab": "\t",
"newline": "\n",
"control": "\x01",
"astral": "\U0001000C",
// U+4E00, a printable multi-byte rune, charged its three
// UTF-8 bytes rather than an escape. Spelled numerically
// because gosmopolitan rejects Han in a string literal.
"cjk": string(rune(0x4E00)),
} {
t.Run(name, func(t *testing.T) {
t.Parallel()
got := logfield.Truncate(
strings.Repeat(fill, budget*8), budget,
)
require.True(
t, strings.HasSuffix(
got, logfield.TruncationMarker,
),
"an oversized value must be marked as cut",
)
spent := 0
for _, r := range strings.TrimSuffix(
got, logfield.TruncationMarker,
) {
spent += logfield.EncodedBytes(r)
}
assert.LessOrEqual(t, spent, budget)
assert.True(t, utf8.ValidString(got))
})
}
}
// TestTruncate_LeavesShortValuesAlone keeps the marker meaningful: a
// value that fits comes back byte for byte, so a marked value is
// always a cut one.
func TestTruncate_LeavesShortValuesAlone(t *testing.T) {
t.Parallel()
for _, s := range []string{
"", "GET", "/source/abc/edit", "Mozilla/5.0 (X11)",
} {
assert.Equal(t, s, logfield.Truncate(s, budget))
}
}
// TestTruncate_DropsInvalidUTF8 covers the bytes a header can carry
// that were never valid UTF-8. Keeping them would make the encoder
// spend six bytes apiece replacing them, which is exactly the
// amplification the budget exists to prevent.
func TestTruncate_DropsInvalidUTF8(t *testing.T) {
t.Parallel()
got := logfield.Truncate("a\xffb\xfe\xfec", budget)
assert.Equal(t, "abc", got)
assert.True(t, utf8.ValidString(got))
}

View File

@@ -4,6 +4,7 @@ import (
"net/http"
"github.com/gorilla/csrf"
"sneak.berlin/go/webhooker/internal/logfield"
)
// CSRFToken retrieves the CSRF token from the request context.
@@ -42,9 +43,22 @@ func isClientTLS(r *http.Request) bool {
// csrf.Secure option is set at creation time, not per-request.
func (m *Middleware) CSRF() func(http.Handler) http.Handler {
csrfErrorHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
// CSRF is registered ahead of RequireAuth on every route
// group that uses it, so this WARN is reachable by an
// unauthenticated client: a POST with no token to
// /source/<any length of any text>/edit lands here. The
// method and path are capped against the same budgets as
// the access log. remote_addr is set by net/http from the
// accepted connection rather than by the client, and
// csrf.FailureReason returns one of gorilla/csrf's own
// fixed error values, so neither is client-sized.
m.log.Warn("csrf: token validation failed",
"method", r.Method,
"path", r.URL.Path,
"method", logfield.Truncate(
r.Method, maxLogMethodBytes,
),
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
"remote_addr", r.RemoteAddr,
"reason", csrf.FailureReason(r),
)

View File

@@ -0,0 +1,480 @@
package middleware_test
// This file covers the log lines OUTSIDE the access log that carry a
// client-chosen value. accesslog_test.go bounds the one INFO line the
// Logging middleware writes; these are the separate slog calls that
// were never in that sweep and so never got the budget:
//
// - MaxBodySize's 413 rejection, at WARN, registered ahead of
// RequireAuth and therefore reachable unauthenticated at a URL of
// the client's choosing.
// - CSRF's 403 rejection, at WARN, also registered ahead of
// RequireAuth.
// - The rate limiters' 429 rejection, at WARN, on the
// unauthenticated receiver among others.
// - RequireAuth's own unauthenticated-request line, at DEBUG.
//
// Every case here holds the ENCODED line to
// middleware.MaxAccessLogLineBytes, under both handlers
// internal/logger can install, against 8 KB of client-chosen text
// built out of the characters those handlers escape. A budget spent
// in raw bytes passes the plain-ASCII cases and fails the rest.
import (
"bytes"
"context"
"io"
"log/slog"
"net/http"
"net/http/httptest"
"net/url"
"strings"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/middleware"
)
// bodyLimitBytes is the MaxBodySize cap these tests install. Any
// declared Content-Length above it takes the 413 branch.
const bodyLimitBytes = 1024
// declaredBodyBytes is the Content-Length an oversize request
// declares. Nothing is actually sent: the 413 branch fires off the
// declaration alone, which is what makes the attack free.
const declaredBodyBytes = bodyLimitBytes * 2
// receiverLimitPerMinute is the per-entrypoint receiver limit these
// tests install. The aggregate limiter sits at ten times this, so a
// flood stays under it and the rejections come from the
// per-entrypoint limiter, which is the one that logs the path.
const receiverLimitPerMinute = 8
// escapeFills are the characters a client can put in a request that
// the log handlers then escape, coming out wider than they went in.
// A budget counted in raw bytes lets any of them buy a field several
// times its nominal size.
//
// U+1000C is the case the JSON handler alone does not reach: it is
// unassigned, so it is non-printable, and strconv.Quote spells a
// non-printable rune at or above U+10000 as a ten-byte \UXXXXXXXX
// while the JSON handler passes its four UTF-8 bytes through. Only
// the text-handler shape of these tests holds that charge honest.
func escapeFills() map[string]string {
return map[string]string{
"plain": "x",
"quote": `"`,
"backslash": `\`,
"tab": "\t",
"newline": "\n",
// A C0 control neither handler has a short escape for, so
// each one costs six bytes on the line against the single
// byte it cost to send. This is the widest multiplier a
// client can drive, and the case a raw-byte budget breaks
// on first.
//
// This fill is load-bearing, not decoration. Budgeting raw
// bytes instead of encoded is caught by this fill alone,
// and only under the JSON handler, at 3,072 bytes against
// the 2,560 ceiling. Drop it and that mutation passes.
"control": "\x01",
"astral": "\U0001000C",
}
}
// logHandlers are the two handlers internal/logger can install: the
// JSON one, and the text one it selects when stderr is a tty. They do
// not escape alike, and MaxAccessLogLineBytes is quoted unqualified,
// so every case runs through both.
func logHandlers() map[string]func(
io.Writer, *slog.HandlerOptions,
) slog.Handler {
return map[string]func(
io.Writer, *slog.HandlerOptions,
) slog.Handler{
"json": func(
w io.Writer, o *slog.HandlerOptions,
) slog.Handler {
return slog.NewJSONHandler(w, o)
},
"text": func(
w io.Writer, o *slog.HandlerOptions,
) slog.Handler {
return slog.NewTextHandler(w, o)
},
}
}
// oversizedPathSegment builds an 8 KB client-chosen path segment out
// of repetitions of ch, percent-encoded so it survives URL parsing
// into r.URL.Path the way it would arriving off a socket.
//
// Both markers sit at the END, past every budget, so their absence
// from the log is what proves the value was cut rather than merely
// being short. The leading 'x' keeps the segment non-empty for fills
// that a parser might otherwise fold away.
func oversizedPathSegment(ch string) string {
return url.PathEscape(
"x" + strings.Repeat(ch, oversizedSegmentBytes) +
attackerMarker + tailMarker,
)
}
// capturingLogger returns a logger at DEBUG writing into the returned
// buffer through the named handler.
func capturingLogger(
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
) (*slog.Logger, *bytes.Buffer) {
buf := new(bytes.Buffer)
opts := &slog.HandlerOptions{Level: slog.LevelDebug}
return slog.New(newHandler(buf, opts)), buf
}
// capturingBoundMiddleware builds a Middleware with a real session
// manager (CSRF needs its key, RequireAuth needs its store) whose log
// is captured at DEBUG.
func capturingBoundMiddleware(
t *testing.T,
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
) (*middleware.Middleware, *bytes.Buffer) {
t.Helper()
log, buf := capturingLogger(newHandler)
cfg := &config.Config{
Environment: config.EnvironmentDev,
ReceiverRateLimit: receiverLimitPerMinute,
}
sess := newTestSessionManager(cfg, log, nil)
return middleware.NewForTest(log, cfg, sess), buf
}
// unreachable is a next-handler that fails the test if the middleware
// under test let the request through. Every site here rejects.
func unreachable(t *testing.T) http.Handler {
t.Helper()
return http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
assert.Fail(t, "rejected request reached the next handler")
})
}
// logSite is one non-access-log call site that logs a client-chosen
// path. drive sends requests at it that all take the rejecting
// branch; linesPerRequest is how many log lines one such request
// produces there.
type logSite struct {
// build wraps the site's middleware around a handler that must
// not be reached.
build func(
t *testing.T, m *middleware.Middleware,
) http.Handler
// send issues one request for the given client-chosen path and
// returns the status. Some sites need a warm-up request before
// they reject, which send performs itself.
send func(h http.Handler, path string) int
// wantStatus is the status the rejecting branch answers with.
wantStatus int
}
// postOversize sends a POST whose declared Content-Length exceeds the
// body limit without sending a body, which is the whole cost of the
// attack on the MaxBodySize branch.
func postOversize(h http.Handler, path string) int {
req := httptest.NewRequestWithContext(
context.Background(), http.MethodPost, path, nil,
)
req.ContentLength = declaredBodyBytes
req.Header.Set(
"Content-Type", "application/x-www-form-urlencoded",
)
w := httptest.NewRecorder()
h.ServeHTTP(w, req)
return w.Code
}
// postNoToken sends a POST carrying no CSRF token and no session
// cookie, which is what an unauthenticated client sends.
func postNoToken(h http.Handler, path string) int {
req := httptest.NewRequestWithContext(
context.Background(), http.MethodPost, path,
strings.NewReader(""),
)
req.Header.Set(
"Content-Type", "application/x-www-form-urlencoded",
)
w := httptest.NewRecorder()
h.ServeHTTP(w, req)
return w.Code
}
// getNoSession sends a GET with no session cookie.
func getNoSession(h http.Handler, path string) int {
req := httptest.NewRequestWithContext(
context.Background(), http.MethodGet, path, nil,
)
w := httptest.NewRecorder()
h.ServeHTTP(w, req)
return w.Code
}
// logSites enumerates the call sites under test.
func logSites() map[string]logSite {
return map[string]logSite{
// The site this file exists for: WARN, on by default, and
// registered ahead of RequireAuth.
"maxbodysize 413": {
build: func(
t *testing.T, m *middleware.Middleware,
) http.Handler {
t.Helper()
return m.MaxBodySize(bodyLimitBytes)(
unreachable(t),
)
},
send: postOversize,
wantStatus: http.StatusRequestEntityTooLarge,
},
// Also ahead of RequireAuth, also WARN.
"csrf 403": {
build: func(
t *testing.T, m *middleware.Middleware,
) http.Handler {
t.Helper()
return m.CSRF()(unreachable(t))
},
send: postNoToken,
wantStatus: http.StatusForbidden,
},
// The per-entrypoint receiver limiter, unauthenticated. Its
// 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": {
build: func(
t *testing.T, m *middleware.Middleware,
) http.Handler {
t.Helper()
return m.ReceiverRateLimit()(okHandler())
},
send: sendUntilLimited,
wantStatus: http.StatusTooManyRequests,
},
// RequireAuth's own line. DEBUG is off in production by
// default, but turning it on to diagnose a flood must not
// restore an unbounded write.
"requireauth redirect": {
build: func(
t *testing.T, m *middleware.Middleware,
) http.Handler {
t.Helper()
return m.RequireAuth()(unreachable(t))
},
send: getNoSession,
wantStatus: http.StatusSeeOther,
},
}
}
// sendUntilLimited drives the per-entrypoint receiver limiter past
// its allowance on one path and returns the status of the rejected
// request. Every request before the last is served, and only the last
// one logs.
func sendUntilLimited(h http.Handler, path string) int {
code := http.StatusOK
for range receiverLimitPerMinute + 1 {
req := httptest.NewRequestWithContext(
context.Background(), http.MethodPost, path, nil,
)
req.RemoteAddr = "203.0.113.7:5555"
w := httptest.NewRecorder()
h.ServeHTTP(w, req)
code = w.Code
}
return code
}
// logLines splits the captured buffer into non-empty lines, holding
// each to bound bytes.
func logLines(t *testing.T, buf *bytes.Buffer, bound int) []string {
t.Helper()
var lines []string
for line := range strings.SplitSeq(
strings.TrimSpace(buf.String()), "\n",
) {
if line == "" {
continue
}
require.LessOrEqual(
t, len(line), bound,
"log line exceeded its bound: %s", line,
)
lines = append(lines, line)
}
return lines
}
// assertNoClientText fails if any marker from the far end of the
// client-chosen input survived into the log. Their absence is what
// distinguishes a real cut from a value that merely happened to be
// short.
func assertNoClientText(t *testing.T, buf *bytes.Buffer) {
t.Helper()
assert.NotContains(
t, buf.String(), attackerMarker,
"log carried attacker-chosen text",
)
assert.NotContains(
t, buf.String(), tailMarker,
"log carried the tail of the attacker-chosen text",
)
}
// TestLogLines_ClientChosenPathDoesNotSizeTheLine points 8 KB of
// client-chosen path at each non-access-log call site that logs one,
// through both handlers and through every character those handlers
// escape, and holds the resulting line to MaxAccessLogLineBytes.
//
// Removing any one of the logfield.Truncate calls at those sites
// fails this test: the line grows to roughly the size of the input,
// or to several times it on the escaping fills.
func TestLogLines_ClientChosenPathDoesNotSizeTheLine(t *testing.T) {
t.Parallel()
for siteName, site := range logSites() {
for handlerName, newHandler := range logHandlers() {
for fillName, fill := range escapeFills() {
name := siteName + "/" + handlerName + "/" + fillName
t.Run(name, func(t *testing.T) {
t.Parallel()
m, buf := capturingBoundMiddleware(
t, newHandler,
)
path := "/source/" +
oversizedPathSegment(fill) + "/edit"
assert.Equal(
t,
site.wantStatus,
site.send(site.build(t, m), path),
)
lines := logLines(
t, buf,
middleware.MaxAccessLogLineBytes,
)
require.NotEmpty(
t, lines,
"the site under test logged nothing, "+
"so the bound proves nothing",
)
assertNoClientText(t, buf)
})
}
}
}
}
// TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog is the
// flood shape from the issue: an unauthenticated client posting
// oversize declarations at invented 8 KB paths, as fast as it likes.
//
// It asserts the property directly rather than by proxy — the bytes
// the flood writes to the operator's log do not track the bytes the
// flood sent. The same flood at a one-character path is the control:
// 8 KB of extra input per request buys at most the field budget, not
// 8 KB of log.
func TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog(
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()
flood := func(segment func(i int) string) int {
m, buf := capturingBoundMiddleware(
t, newHandler,
)
h := m.MaxBodySize(bodyLimitBytes)(
unreachable(t),
)
for i := range floodRequests {
assert.Equal(
t,
http.StatusRequestEntityTooLarge,
postOversize(
h,
"/source/"+segment(i)+"/edit",
),
)
}
lines := logLines(
t, buf,
middleware.MaxAccessLogLineBytes,
)
require.Len(t, lines, floodRequests)
assertNoClientText(t, buf)
return buf.Len()
}
sent := oversizedSegmentBytes * floodRequests
oversize := flood(func(i int) string {
return oversizedPathSegment(fill) +
strings.Repeat("y", i)
})
control := flood(func(i int) string {
return "a" + strings.Repeat("y", i)
})
// The whole point: 8 KB per request of extra
// client-chosen input bought a bounded amount of
// log, not a proportional amount.
assert.Less(
t, oversize-control, sent/2,
"log volume tracked the size of the flood's "+
"input",
)
assert.LessOrEqual(
t,
oversize,
floodRequests*
middleware.MaxAccessLogLineBytes,
)
})
}
}
}

View File

@@ -7,6 +7,8 @@ import (
"net/http"
"sync"
"time"
"sneak.berlin/go/webhooker/internal/logfield"
)
const (
@@ -344,8 +346,16 @@ func (m *Middleware) RecordLoginFailure(
) bool {
throttled := m.guard().fail(m.clientKey(r), username)
if throttled {
// Truncated even though chi pins this route's path to
// the 12-byte constant "/pages/login": RecordLoginFailure
// is exported and takes any *http.Request, so a caller on
// a route with a URL parameter would otherwise widen this
// line with nothing failing.
m.log.Warn(
"login failure limit exceeded", "path", r.URL.Path,
"login failure limit exceeded",
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
)
}

View File

@@ -6,11 +6,8 @@ import (
"log/slog"
"net"
"net/http"
"strings"
"sync"
"time"
"unicode"
"unicode/utf8"
basicauth "github.com/99designs/basicauth-go"
"github.com/go-chi/chi"
@@ -22,6 +19,7 @@ import (
"go.uber.org/fx"
"sneak.berlin/go/webhooker/internal/config"
"sneak.berlin/go/webhooker/internal/globals"
"sneak.berlin/go/webhooker/internal/logfield"
"sneak.berlin/go/webhooker/internal/logger"
"sneak.berlin/go/webhooker/internal/session"
)
@@ -44,16 +42,6 @@ const (
// pick the size of the line it writes.
redactedQuery = "?(redacted)"
// maxLogFieldBytes bounds each access log field whose value the
// client supplies outright: the URL, the User-Agent and the
// Referer. The budget is spent in ENCODED bytes (see
// truncateLogField), so 512 still holds a real browser's User-Agent
// whole — those are plain ASCII, which encodes one byte for one —
// while a value built from characters the encoder escapes keeps a
// shorter prefix. That is the intended trade: 500 quotation marks
// are not a debugging asset.
maxLogFieldBytes = 512
// maxLogRequestIDBytes bounds the request id, which is also
// client-supplied: chi's RequestID middleware passes an inbound
// X-Request-Id header through verbatim. Its generated form is an
@@ -66,15 +54,10 @@ const (
// is half this.
maxLogMethodBytes = 32
// truncationMarker is appended to any field the access log cut, so
// a short value and a truncated one cannot be confused. It is
// charged on top of the budget, not inside it.
truncationMarker = "[truncated]"
// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
// and the number an operator multiplies by the request rate to size
// log storage. It is not an observation of a sample: it is the sum
// of the budgets above, each of which truncateLogField enforces in
// of the budgets above, each of which logfield.Truncate enforces in
// ENCODED bytes, plus the part of the line no client can influence.
//
// url, useragent, referer 3*(512+11) = 1569
@@ -91,13 +74,48 @@ const (
// than sitting on the arithmetic.
//
// The tty text handler in internal/logger is covered by the same
// figure. encodedLogFieldBytes charges every rune at least what
// figure. logfield.EncodedBytes charges every rune at least what
// the wider of the two handlers emits for it — including the ten
// bytes strconv.Quote spends on a non-printable rune at or above
// U+10000, which is four more than the JSON handler ever spends —
// so each budget bounds the encoded field under either handler.
// The text handler's fixed portion is 286, the smaller of the two,
// which puts its worst case at 2037.
//
// It is also the ceiling on every OTHER line this service writes
// THROUGH SLOG that carries text an UNAUTHENTICATED client
// supplies. Those lines — the MaxBodySize rejection, the CSRF
// rejection, the rate-limit rejection, the unauthenticated-request
// and unknown-entrypoint DEBUG lines, the failed-login DEBUG
// lines, and the two login-throttle WARN lines ("login failure
// limit exceeded" in loginguard.go and "password verification
// capacity exhausted" in internal/handlers/auth.go) — spend the
// same per-field budgets, and each carries
// strictly fewer client-supplied fields than the access log does,
// so none of them can reach a width the access log cannot. That is
// asserted directly, per line and under both handlers, rather than
// left to the reasoning: see logbound_test.go in this package and
// in internal/handlers.
//
// What it does NOT cover, so that the figure above is not read as
// more than it is:
//
// - Lines carrying an AUTHENTICATED operator's own input, which
// are not truncated at all: the webhook name on "webhook
// created" and the target host on "target URL blocked by SSRF
// protection" (both internal/handlers/source_management.go),
// and target_name in internal/delivery/engine.go and
// target_http.go. Each is bounded only by the 1 MB form body
// cap, so a 100 KB name writes one line of roughly 600 KB.
// Deliberate: truncating the operator's own configuration
// echoed back costs debuggability against no adversary.
// - The "log" delivery target, which exists to write the whole
// inbound event to the log. Deliberate; see
// internal/delivery/target_log.go.
// - GORM's default logger, which prints the interpolated SQL to
// stdout on a record-not-found and so is unbounded on the
// receiver and login lookups. NOT deliberate; filed as
// https://git.eeqj.de/sneak/webhooker/issues/178.
MaxAccessLogLineBytes = 2560
)
@@ -174,114 +192,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
lrw.ResponseWriter.WriteHeader(code)
}
// encodedLogFieldBytes is what r costs on the line once the log
// handler has escaped it, taking the worse of the two handlers
// internal/logger configures.
//
// slog's JSON handler escapes quote, backslash, newline, carriage
// return and tab to two bytes each, and every other C0 control plus
// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape; it
// passes every other rune through as its own UTF-8. Its text handler
// quotes with strconv.Quote, which spells a non-printable rune below
// U+10000 as \uXXXX but one at or above U+10000 as \UXXXXXXXX — ten
// bytes, not six. The text handler is therefore the worse of the two
// for every non-printable rune, and by four bytes apiece for the
// 955,086 unassigned, private-use and format code points on planes 1
// to 16.
//
// Charging ten there is what makes MaxAccessLogLineBytes hold for the
// tty handler as well: U+1000C encodes as F0 90 80 8C, every byte
// >= 0x80, which httpguts.ValidHeaderFieldValue accepts and
// net/textproto does not strip, so a header can be filled with them.
//
// Both handlers pass printable runes through as their own UTF-8, so
// unicode.IsPrint separates the escaped cases from the plain ones for
// either handler.
func encodedLogFieldBytes(r rune) int {
const (
// A backslash and the character itself.
shortEscapeBytes = 2
// \uXXXX, which is also the width of \u00XX.
escapedRuneBytes = 6
// \UXXXXXXXX, strconv.Quote's spelling of a non-printable
// rune outside the basic multilingual plane.
escapedAstralRuneBytes = 10
// The first code point strconv.Quote spells with \U.
firstAstralRune = 0x10000
)
switch {
case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
return shortEscapeBytes
case !unicode.IsPrint(r) && r >= firstAstralRune:
return escapedAstralRuneBytes
case !unicode.IsPrint(r):
return escapedRuneBytes
default:
return utf8.RuneLen(r)
}
}
// truncateLogField caps s at maxBytes of ENCODED output, marking the
// value when it cuts.
//
// Budgeting raw bytes would not bound the line. Escaping only ever
// grows a value, so a raw budget spent on characters the encoder
// escapes buys a field several times its nominal size — and the line
// is the thing an operator is told to multiply by their request rate.
// Charging each rune what it will actually cost is what makes
// MaxAccessLogLineBytes true rather than merely larger. The visible
// consequence is that an escape-heavy value keeps a shorter prefix
// than a plain one, which is the correct trade.
//
// The result is always valid UTF-8. A cut on a byte boundary can split
// a multi-byte rune, and a header can carry bytes that were never
// valid UTF-8 to begin with; both are dropped rather than kept, since
// an encoder would otherwise spend six bytes replacing each one.
func truncateLogField(s string, maxBytes int) string {
// No rune encodes to fewer bytes than it occupies, so nothing past
// maxBytes raw can fit the budget. Slicing first bounds the scan
// below to the budget rather than to the size of the header the
// client sent.
window, cut := s, false
if len(window) > maxBytes {
window, cut = window[:maxBytes], true
}
var (
kept strings.Builder
spent int
)
for i := 0; i < len(window); {
r, size := utf8.DecodeRuneInString(window[i:])
if r == utf8.RuneError && size == 1 {
i += size
continue
}
cost := encodedLogFieldBytes(r)
if spent+cost > maxBytes {
cut = true
break
}
spent += cost
kept.WriteString(window[i : i+size])
i += size
}
if !cut {
return kept.String()
}
return kept.String() + truncationMarker
}
// concreteLogURL renders the request's own URL for the access log
// branches that keep it, with the query string replaced by a fixed
// marker.
@@ -375,21 +285,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
// line does not track the size of the request.
s.log.Info("http request",
"request_start", start,
"method", truncateLogField(
"method", logfield.Truncate(
r.Method, maxLogMethodBytes,
),
"url", truncateLogField(
"url", logfield.Truncate(
accessLogURL(r, lrw.statusCode),
maxLogFieldBytes,
logfield.MaxBytes,
),
"useragent", truncateLogField(
r.UserAgent(), maxLogFieldBytes,
"useragent", logfield.Truncate(
r.UserAgent(), logfield.MaxBytes,
),
"request_id", truncateLogField(
"request_id", logfield.Truncate(
requestID, maxLogRequestIDBytes,
),
"referer", truncateLogField(
r.Referer(), maxLogFieldBytes,
"referer", logfield.Truncate(
r.Referer(), logfield.MaxBytes,
),
"proto", r.Proto,
"remoteIP", ipFromHostPort(r.RemoteAddr),
@@ -457,10 +367,21 @@ func (s *Middleware) RequireAuth() func(http.Handler) http.Handler {
// session lands here and is sent back to the login
// page.
if !s.session.IsAuthenticated(sess) {
// This is the unauthenticated branch, so both
// fields are entirely client-chosen and neither
// is bounded by anything the router did. DEBUG
// is off by default, but turning it on to
// diagnose a problem must not hand a client an
// unbounded write into the log, so the same
// budgets apply here as in the access log.
s.log.Debug(
"auth middleware: unauthenticated request",
"path", r.URL.Path,
"method", r.Method,
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
"method", logfield.Truncate(
r.Method, maxLogMethodBytes,
),
)
http.Redirect(
w, r, "/pages/login", http.StatusSeeOther,
@@ -620,10 +541,26 @@ func (s *Middleware) MaxBodySize(
}
if r.ContentLength > maxBytes {
// This runs ahead of RequireAuth (see
// setupUserRoutes and friends in
// internal/server/routes.go), so an
// unauthenticated client reaches it with a path
// of its own choosing and its own length —
// POST /source/<8 KB>/edit with an oversize
// declared Content-Length costs nothing to
// send. At WARN, on by default, that is a
// write into the operator's log sized by the
// attacker unless the path is capped. Same
// budgets as the access log, so this line
// cannot be wider than that one.
s.log.Warn(
"request body exceeds limit",
"method", r.Method,
"path", r.URL.Path,
"method", logfield.Truncate(
r.Method, maxLogMethodBytes,
),
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
"content_length", r.ContentLength,
"limit", maxBytes,
)

View File

@@ -57,7 +57,21 @@ func testMiddlewareWithSessionClock(
SessionIdleTimeout: idleTimeout,
}
// Create a real session manager with a known key
sessManager := newTestSessionManager(cfg, log, clock)
m := middleware.NewForTest(log, cfg, sessManager)
return m, sessManager, clock
}
// newTestSessionManager builds the real session.Session the
// middleware tests run against: an in-memory cookie store with a
// known key, and optionally a manually advanced clock.
func newTestSessionManager(
cfg *config.Config,
log *slog.Logger,
clock *fakeClock,
) *session.Session {
key := make([]byte, testKeySize)
for i := range key {
@@ -79,11 +93,7 @@ func testMiddlewareWithSessionClock(
now = clock.Now
}
sessManager := session.NewForTest(store, cfg, log, key, now)
m := middleware.NewForTest(log, cfg, sessManager)
return m, sessManager, clock
return session.NewForTest(store, cfg, log, key, now)
}
// fakeClock is a manually advanced clock, so session expiry can be

View File

@@ -9,6 +9,7 @@ import (
"time"
"github.com/go-chi/httprate"
"sneak.berlin/go/webhooker/internal/logfield"
)
const (
@@ -225,11 +226,22 @@ func (m *Middleware) clientKey(r *http.Request) string {
// rejection with logMessage and answers with responseMessage.
// httprate adds the Retry-After header (RFC 6585). The aggregate
// receiver limiter uses floodTooManyRequests instead.
//
// The path is capped against the same budget as the access log's url
// field. The per-entrypoint receiver limiter is unauthenticated and
// its path is a client-chosen segment of client-chosen length, so at
// 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(
logMessage, responseMessage string,
) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
m.log.Warn(logMessage, "path", r.URL.Path)
m.log.Warn(
logMessage,
"path", logfield.Truncate(
r.URL.Path, logfield.MaxBytes,
),
)
http.Error(w, responseMessage, http.StatusTooManyRequests)
}
}

View File

@@ -14,6 +14,28 @@ import (
// maxFormBodySize is the maximum allowed request body size (in
// bytes) for form POST endpoints. 1 MB is generous for any form
// submission while preventing abuse from oversized payloads.
//
// Every route group below installs MaxBodySize(maxFormBodySize) as
// its FIRST middleware, ahead of both CSRF and RequireAuth. Both
// orderings are deliberate.
//
// Ahead of CSRF because gorilla/csrf parses the form. The cap has to
// be installed before anything reads the body, or the parse runs
// under net/http's 10 MB default instead of this one.
//
// Ahead of RequireAuth because an oversize body should be refused
// before the request buys a cookie decrypt, a session load and the
// database read behind it. Rejecting first is the cheaper failure,
// and it is the ordering that keeps an unauthenticated flood from
// choosing how much session work the process does.
//
// What that ordering costs: the 413 branch is reachable
// unauthenticated, at a URL of the client's choosing and of the
// client's chosen length. So is the CSRF rejection, which sits in
// front of RequireAuth for the same reason. Both log that path, so
// both cap it — see the log calls in Middleware.MaxBodySize and
// Middleware.CSRF, which spend the same per-field budget as the
// access log.
const maxFormBodySize int64 = 1 * 1024 * 1024 // 1 MB
// requestTimeout is the maximum time allowed for a single HTTP
@@ -90,8 +112,8 @@ func (s *Server) setupRoutes() {
func (s *Server) setupPageRoutes() {
s.router.Route("/pages", func(r chi.Router) {
// MaxBodySize must precede CSRF: gorilla/csrf parses the
// form, so the cap has to be installed before it runs.
// MaxBodySize precedes CSRF and RequireAuth deliberately;
// see maxFormBodySize for why, and for what it costs.
r.Use(s.mw.MaxBodySize(maxFormBodySize))
r.Use(s.mw.CSRF())
r.Use(s.mw.NoCache())
@@ -111,8 +133,8 @@ func (s *Server) setupPageRoutes() {
func (s *Server) setupUserRoutes() {
s.router.Route("/user/{username}", func(r chi.Router) {
// MaxBodySize must precede CSRF: gorilla/csrf parses the
// form, so the cap has to be installed before it runs.
// MaxBodySize precedes CSRF and RequireAuth deliberately;
// see maxFormBodySize for why, and for what it costs.
r.Use(s.mw.MaxBodySize(maxFormBodySize))
r.Use(s.mw.CSRF())
r.Use(s.mw.NoCache())
@@ -126,8 +148,8 @@ func (s *Server) setupUserRoutes() {
func (s *Server) setupSourceRoutes() {
s.router.Route("/sources", func(r chi.Router) {
// MaxBodySize must precede CSRF: gorilla/csrf parses the
// form, so the cap has to be installed before it runs.
// MaxBodySize precedes CSRF and RequireAuth deliberately;
// see maxFormBodySize for why, and for what it costs.
r.Use(s.mw.MaxBodySize(maxFormBodySize))
r.Use(s.mw.CSRF())
r.Use(s.mw.NoCache())
@@ -138,8 +160,8 @@ func (s *Server) setupSourceRoutes() {
})
s.router.Route("/source/{sourceID}", func(r chi.Router) {
// MaxBodySize must precede CSRF: gorilla/csrf parses the
// form, so the cap has to be installed before it runs.
// MaxBodySize precedes CSRF and RequireAuth deliberately;
// see maxFormBodySize for why, and for what it costs.
r.Use(s.mw.MaxBodySize(maxFormBodySize))
r.Use(s.mw.CSRF())
r.Use(s.mw.NoCache())

View File

@@ -2,8 +2,11 @@ package server
import (
"net/http"
"net/url"
"strings"
"github.com/getsentry/sentry-go"
"github.com/go-chi/chi"
)
// sentryRedacted stands in for a withheld field on every event shipped
@@ -11,6 +14,12 @@ import (
// can tell a suppressed value from an absent one.
const sentryRedacted = "(redacted)"
// sentryRedactedPath is what stands in for the request path when the
// route pattern is not reachable. It is deliberately not the concrete
// path: on the receiver route that path carries the entrypoint UUID,
// which is a write capability rather than an identifier.
const sentryRedactedPath = "/" + sentryRedacted
// sentryClientOptions builds the options the SDK is initialised with.
// It is its own function so a test can stand up a client wired exactly
// as production is, with only the transport swapped.
@@ -44,18 +53,43 @@ func sentryClientOptions(dsn, release string) sentry.ClientOptions {
// login password and both password-change fields. None of that may
// reach a third-party service.
//
// URL is the third such field. NewRequest builds it as
// scheme://host/path (interfaces.go:183), and on the receiver route
// that path is /webhook/<uuid> in full — a write capability, not an
// identifier. It is rebuilt here from the chi route pattern, on every
// route, keeping the scheme and the host.
//
// This hook is a floor, not a default: the fields it clears stay
// cleared even if SendDefaultPII is ever turned on.
func scrubSentryRequest(
event *sentry.Event,
_ *sentry.EventHint,
hint *sentry.EventHint,
) *sentry.Event {
if event == nil || event.Request == nil {
if event == nil {
return event
}
pattern := sentryRoutePattern(hint)
// Only transaction events carry a Transaction name, and the SDK
// builds it from the concrete path too (sentryhttp.go:105 via
// tracing.go:553). Rewritten on the same terms.
if event.Transaction != "" {
event.Transaction = sentryTransactionName(
event.Transaction, pattern,
)
}
if event.Request == nil {
return event
}
req := event.Request
if req.URL != "" {
req.URL = sentryRouteURL(req.URL, pattern)
}
if req.QueryString != "" {
req.QueryString = sentryRedacted
}
@@ -71,6 +105,91 @@ func scrubSentryRequest(
return event
}
// sentryRoutePattern returns the chi route pattern for the request the
// hint carries, or "" when it is not reachable.
//
// The request is reachable on the error dispatch only. sentryhttp's
// recover path calls RecoverWithContext with the request on the
// context under sentry.RequestContextKey (sentryhttp.go:124-125), and
// the client copies that context onto the hint (client.go:484-485)
// before handing it to BeforeSend (client.go:631). chi's routing
// context is a pointer placed on the request context before the
// middleware chain runs (chi mux.go:84) and filled in as the mux
// routes, so by the time a handler panics it names the matched route.
//
// The transaction dispatch has no such request: Span.doFinish calls
// hub.CaptureEvent (tracing.go:356), which passes a nil hint that the
// client replaces with an empty one (client.go:620-622). The pattern
// is therefore always "" there, and the callers fall back.
func sentryRoutePattern(hint *sentry.EventHint) string {
if hint == nil || hint.Context == nil {
return ""
}
req, ok := hint.Context.Value(
sentry.RequestContextKey,
).(*http.Request)
if !ok || req == nil {
return ""
}
rctx := chi.RouteContext(req.Context())
if rctx == nil {
return ""
}
// Empty when no route matched, which is the fallback case too.
return rctx.RoutePattern()
}
// sentryRouteURL rebuilds an event's request URL with the route
// pattern in place of the concrete path.
//
// The scheme is load-bearing and is kept: the SDK derives it from
// r.TLS != nil || r.Header.Get("X-Forwarded-Proto") == "https"
// (interfaces.go:180), byte for byte the predicate
// internal/middleware/csrf.go uses, so it is the CSRF TLS decision and
// the reason dropping X-Forwarded-Proto from the header allowlist
// costs nothing. The host is parsed.Host of the SDK's
// scheme://r.Host/path, so it is whatever the client's Host header
// carried: this service validates no hostname. It is kept because that
// same header is on the allowlist, so scrubbing it here would withhold
// nothing that is not sent anyway.
//
// Everything else in the URL is discarded rather than edited, so a
// future SDK that starts appending a query string cannot widen this.
func sentryRouteURL(rawURL, pattern string) string {
parsed, err := url.Parse(rawURL)
if err != nil || parsed.Scheme == "" {
// Not a shape this can safely take apart.
return sentryRedacted
}
if pattern == "" {
pattern = sentryRedactedPath
}
return parsed.Scheme + "://" + parsed.Host + pattern
}
// sentryTransactionName rebuilds the SDK's "METHOD /path" transaction
// name with the route pattern in place of the concrete path. Method is
// kept for the same reason Request.Method is: net/http admits only a
// bounded token there. A name in any other shape is withheld whole,
// since nothing can be said about which part of it is a path.
func sentryTransactionName(name, pattern string) string {
method, _, found := strings.Cut(name, " ")
if !found {
return sentryRedacted
}
if pattern == "" {
pattern = sentryRedactedPath
}
return method + " " + pattern
}
// keptSentryHeaders returns the subset of headers an event may carry
// off-host. Dropping by allowlist rather than by blocklist is what
// makes an unrecognised header safe: the SDK's own filter removes four

View File

@@ -13,12 +13,13 @@ import (
"github.com/getsentry/sentry-go"
sentryhttp "github.com/getsentry/sentry-go/http"
"github.com/go-chi/chi"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/webhooker/internal/server"
)
// The three markers below are the credentials a captured event could
// The four markers below are the credentials a captured event could
// carry off-host, one per field of sentry.Request that the SDK fills
// from the request without a SendDefaultPII guard.
const (
@@ -33,6 +34,12 @@ const (
// sentryHeaderMarker rides X-Csrf-Token, which gorilla/csrf
// accepts in place of the form field.
sentryHeaderMarker = "QQSENTRYHEADERMARKERQQ"
// sentryReceiverUUID is the entrypoint identifier in the path of
// a receiver request. It is a write capability: anyone holding
// it can POST events this service accepts and its targets then
// deliver, so it may not reach a third-party tracker.
sentryReceiverUUID = "6d1f9c2a-3b7e-4f58-9a0d-c0ffeebadc0d"
)
// sentryKeptUserAgent is a non-secret header value planted so the
@@ -58,19 +65,41 @@ func (c *captureTransport) SendEvent(event *sentry.Event) {
c.events = append(c.events, event)
}
// captureThroughSentryHTTP panics inside a form handler wrapped in the
// real sentryhttp middleware and returns the event the SDK produced.
// sentryCase drives one request through the real sentryhttp middleware
// inside a real chi router and returns the events the SDK produced.
//
// This is the only construction path on which Request.Data appears:
// sentryhttp calls Scope.SetRequest, which tees r.Body into a 10 KiB
// buffer, ParseForm drains the tee, and Scope.ApplyToEvent copies the
// buffer into the event inside prepareEvent — before BeforeSend runs.
// A hand-built sentry.NewRequest never reads the body and so cannot
// regress-test any of it.
// Routing through a chi mux is load-bearing, not decoration. chi puts
// its routing context on the request context before the middleware
// chain runs and fills it in as it matches, so a hand-built request
// carries no route pattern at all and could not distinguish the hook
// working from the hook falling back.
//
// scrub selects whether the production BeforeSend hooks are installed,
// so the same path shows both what the SDK collects and what survives.
func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
// This is also the only construction path on which Request.Data
// appears: sentryhttp calls Scope.SetRequest, which tees r.Body into a
// 10 KiB buffer, ParseForm drains the tee, and Scope.ApplyToEvent
// copies the buffer into the event inside prepareEvent — before
// BeforeSend runs. A hand-built sentry.NewRequest never reads the body
// and so cannot regress-test any of it.
type sentryCase struct {
// scrub selects whether the production BeforeSend hooks are
// installed, so the same path shows both what the SDK collects
// and what survives.
scrub bool
// tracing enables the transaction dispatch, which the service
// leaves off. With it on, a served request produces a
// transaction event through BeforeSendTransaction.
tracing bool
// panics selects the error dispatch, via BeforeSend.
panics bool
// request builds the request to serve, given the client whose
// hub it must carry.
request func(*sentry.Client) *http.Request
}
func (c sentryCase) capture(t *testing.T) []*sentry.Event {
t.Helper()
transport := &captureTransport{}
@@ -80,57 +109,107 @@ func captureThroughSentryHTTP(t *testing.T, scrub bool) *sentry.Event {
)
opts.Transport = transport
if !scrub {
if !c.scrub {
opts.BeforeSend = nil
opts.BeforeSendTransaction = nil
}
if c.tracing {
opts.EnableTracing = true
opts.TracesSampleRate = 1.0
}
client, err := sentry.NewClient(opts)
require.NoError(t, err)
handler := sentryhttp.New(sentryhttp.Options{}).Handle(
http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
// This call is what drains the tee and fills the
// buffer. Its success is asserted by the unscrubbed
// case below, which sees the body in the event.
_ = r.ParseForm()
c.router().ServeHTTP(httptest.NewRecorder(), c.request(client))
panic("boom")
}),
)
handler.ServeHTTP(
httptest.NewRecorder(),
sentryLoginRequest(client),
)
require.Len(t, transport.events, 1)
return transport.events[0]
return transport.events
}
// sentryLoginRequest builds the password POST the capture above drives,
// with a credential planted in the body, the query and a header.
// router mirrors setupGlobalMiddleware's ordering over the two route
// patterns these tests need: a recovering middleware first, then the
// sentryhttp handler registered with Use and Repanic set, exactly as
// routes.go registers it. The local recover stands in for chi's
// middleware.Recoverer, which holds that slot in production; it is
// here only to keep panic stacks out of the test output.
func (c sentryCase) router() http.Handler {
handler := func(_ http.ResponseWriter, r *http.Request) {
// This call is what drains the body tee and fills the
// buffer. Its success is asserted by the unscrubbed case
// below, which sees the body in the event.
_ = r.ParseForm()
if c.panics {
panic("boom")
}
}
router := chi.NewRouter()
router.Use(recoveringMiddleware)
router.Use(
sentryhttp.New(sentryhttp.Options{Repanic: true}).Handle,
)
router.HandleFunc("/pages/login", handler)
router.HandleFunc("/webhook/{uuid}", handler)
return router
}
func recoveringMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(
func(w http.ResponseWriter, r *http.Request) {
defer func() { _ = recover() }()
next.ServeHTTP(w, r)
},
)
}
// sentryLoginRequest builds the password POST most cases drive, with a
// credential planted in the body, the query and a header.
func sentryLoginRequest(client *sentry.Client) *http.Request {
form := url.Values{}
form.Set("username", "admin")
form.Set("password", sentryBodyMarker)
req := sentryRequest(
client,
"/pages/login?url=https://hooks.slack.com/services/"+
sentryQueryMarker,
form.Encode(),
)
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
return req
}
// sentryReceiverRequest builds a POST to the receiver route, whose
// concrete path carries the entrypoint capability.
func sentryReceiverRequest(client *sentry.Client) *http.Request {
return sentryRequest(
client, "/webhook/"+sentryReceiverUUID, "payload=hello",
)
}
func sentryRequest(
client *sentry.Client,
target, body string,
) *http.Request {
req := httptest.NewRequestWithContext(
sentry.SetHubOnContext(
context.Background(),
sentry.NewHub(client, sentry.NewScope()),
),
http.MethodPost,
"/pages/login?url=https://hooks.slack.com/services/"+
sentryQueryMarker,
strings.NewReader(form.Encode()),
target,
strings.NewReader(body),
)
req.Header.Set(
"Content-Type", "application/x-www-form-urlencoded",
)
req.Header.Set("X-Csrf-Token", sentryHeaderMarker)
req.Header.Set("User-Agent", sentryKeptUserAgent)
return req
@@ -146,15 +225,27 @@ func marshalEvent(t *testing.T, event *sentry.Event) string {
return string(encoded)
}
// onlyEvent asserts a single event was captured and returns it.
func onlyEvent(t *testing.T, events []*sentry.Event) *sentry.Event {
t.Helper()
require.Len(t, events, 1)
require.NotNil(t, events[0].Request)
return events[0]
}
// TestSentryScrub_SDKCollectsTheRequestUnscrubbed pins the premise the
// hook exists for. Without it the SDK ships the whole POST body, the
// raw query and the CSRF header, none of which SendDefaultPII=false
// suppresses.
// raw query, the CSRF header and the concrete request path, none of
// which SendDefaultPII=false suppresses.
func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
t.Parallel()
event := captureThroughSentryHTTP(t, false)
require.NotNil(t, event.Request)
event := onlyEvent(t, sentryCase{
panics: true,
request: sentryLoginRequest,
}.capture(t))
assert.Contains(
t, event.Request.Data, sentryBodyMarker,
@@ -165,6 +256,18 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
assert.Contains(
t, marshalEvent(t, event), sentryHeaderMarker,
)
receiver := onlyEvent(t, sentryCase{
panics: true,
request: sentryReceiverRequest,
}.capture(t))
assert.Contains(
t, receiver.Request.URL, sentryReceiverUUID,
"the SDK is expected to build Request.URL from the "+
"concrete path; if it no longer does, the route "+
"pattern rewrite's premise changed",
)
}
// TestSentryScrub_RedactsTheCapturedRequest is the regression test: no
@@ -173,8 +276,11 @@ func TestSentryScrub_SDKCollectsTheRequestUnscrubbed(t *testing.T) {
func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
t.Parallel()
event := captureThroughSentryHTTP(t, true)
require.NotNil(t, event.Request)
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryLoginRequest,
}.capture(t))
encoded := marshalEvent(t, event)
@@ -189,16 +295,45 @@ func TestSentryScrub_RedactsTheCapturedRequest(t *testing.T) {
assert.Empty(t, event.Request.Env)
}
// TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern is the
// regression test for the receiver URL: the entrypoint UUID is a write
// capability and may not reach the tracker, while the route it names
// must still be readable there.
func TestSentryScrub_ReplacesTheCapabilityPathWithTheRoutePattern(
t *testing.T,
) {
t.Parallel()
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryReceiverRequest,
}.capture(t))
assert.NotContains(
t, marshalEvent(t, event), sentryReceiverUUID,
)
assert.Equal(
t, "http://example.com/webhook/{uuid}", event.Request.URL,
)
}
// TestSentryScrub_KeepsTheRoutingContext checks the hook does not cost
// the debugging signal: the route, the method and the metadata headers
// still identify what failed.
// the debugging signal: the route, its scheme and host, the method and
// the metadata headers still identify what failed. On a static route
// the pattern is the path, so the URL is unchanged there.
func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
t.Parallel()
event := captureThroughSentryHTTP(t, true)
require.NotNil(t, event.Request)
event := onlyEvent(t, sentryCase{
scrub: true,
panics: true,
request: sentryLoginRequest,
}.capture(t))
assert.Contains(t, event.Request.URL, "/pages/login")
assert.Equal(
t, "http://example.com/pages/login", event.Request.URL,
)
assert.Equal(t, http.MethodPost, event.Request.Method)
assert.Equal(
t,
@@ -212,6 +347,127 @@ func TestSentryScrub_KeepsTheRoutingContext(t *testing.T) {
)
}
// TestSentryScrub_RedactsTheTransactionDispatch covers the other hook.
// Span.doFinish captures with a nil hint, so BeforeSendTransaction
// gets one with no context and no request: the route pattern is out of
// reach and both the URL and the SDK-built transaction name have to
// fall back. Tracing is off in this service, so no transaction event
// is produced today; the hook is a floor against that changing.
func TestSentryScrub_RedactsTheTransactionDispatch(t *testing.T) {
t.Parallel()
events := sentryCase{
scrub: true,
tracing: true,
request: sentryReceiverRequest,
}.capture(t)
event := onlyEvent(t, events)
require.Equal(t, "transaction", event.Type)
assert.NotContains(
t, marshalEvent(t, event), sentryReceiverUUID,
)
assert.Equal(
t, "http://example.com/(redacted)", event.Request.URL,
)
assert.Equal(t, "POST /(redacted)", event.Transaction)
}
// TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook pins
// that dispatch's premise the same way, since it is the one the
// service does not exercise today.
func TestSentryScrub_TransactionDispatchIsUnscrubbedWithoutTheHook(
t *testing.T,
) {
t.Parallel()
event := onlyEvent(t, sentryCase{
tracing: true,
request: sentryReceiverRequest,
}.capture(t))
require.Equal(t, "transaction", event.Type)
assert.Contains(t, event.Request.URL, sentryReceiverUUID)
assert.Contains(t, event.Transaction, sentryReceiverUUID)
}
// TestSentryScrub_FallsBackWithoutARoutePattern covers every way the
// pattern can be missing. None of them may fall back to the concrete
// path, and all of them keep the scheme, which is the CSRF TLS
// decision.
func TestSentryScrub_FallsBackWithoutARoutePattern(t *testing.T) {
t.Parallel()
concrete := "https://example.com/webhook/" + sentryReceiverUUID
// A request with no chi routing context on it at all, which is
// what an event captured outside the router would carry.
unrouted := httptest.NewRequestWithContext(
context.Background(), http.MethodPost, concrete, nil,
)
for name, hint := range map[string]*sentry.EventHint{
"no hint": nil,
"no context": {},
"no request": {Context: context.Background()},
"unrouted request": {
Context: context.WithValue(
context.Background(),
sentry.RequestContextKey,
unrouted,
),
},
} {
t.Run(name, func(t *testing.T) {
t.Parallel()
event := sentry.NewEvent()
event.Request = &sentry.Request{URL: concrete}
event.Transaction = "POST /webhook/" +
sentryReceiverUUID
scrubbed := server.ScrubSentryRequestForTest(
event, hint,
)
require.NotNil(t, scrubbed)
assert.Equal(
t,
"https://example.com/(redacted)",
scrubbed.Request.URL,
)
assert.Equal(
t, "POST /(redacted)", scrubbed.Transaction,
)
assert.NotContains(
t,
marshalEvent(t, scrubbed),
sentryReceiverUUID,
)
})
}
}
// TestSentryScrub_WithholdsUnparseableValues covers the shapes the
// rewrite cannot take apart. Withholding them whole is the safe
// answer, since nothing can be said about which part is a path.
func TestSentryScrub_WithholdsUnparseableValues(t *testing.T) {
t.Parallel()
event := sentry.NewEvent()
event.Request = &sentry.Request{
URL: "/webhook/" + sentryReceiverUUID,
}
event.Transaction = "/webhook/" + sentryReceiverUUID
scrubbed := server.ScrubSentryRequestForTest(event, nil)
require.NotNil(t, scrubbed)
assert.Equal(t, "(redacted)", scrubbed.Request.URL)
assert.Equal(t, "(redacted)", scrubbed.Transaction)
}
// TestSentryScrub_ToleratesEventsWithoutARequest covers the events the
// hook sees outside an HTTP handler, where no request is attached.
func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
@@ -223,5 +479,6 @@ func TestSentryScrub_ToleratesEventsWithoutARequest(t *testing.T) {
require.NotNil(t, scrubbed)
assert.Nil(t, scrubbed.Request)
assert.Empty(t, scrubbed.Transaction)
assert.Nil(t, server.ScrubSentryRequestForTest(nil, nil))
}