Compare commits
1 Commits
next
...
fe9454f7b3
| Author | SHA1 | Date | |
|---|---|---|---|
| fe9454f7b3 |
111
README.md
111
README.md
@@ -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
|
entrypoint is recorded by the handler at `DEBUG`, and the aggregate
|
||||||
limiter logs its own rejections at `DEBUG` and without the path, so
|
limiter logs its own rejections at `DEBUG` and without the path, so
|
||||||
neither appears at all under the default level. The per-entrypoint
|
neither appears at all under the default level. The per-entrypoint
|
||||||
limiter is the loud one: it still logs every rejection at `WARN` with
|
limiter is the loud one: it logs every rejection at `WARN` with the
|
||||||
the request path, which on this route is attacker-controlled text. A
|
request path, which on this route is attacker-controlled text. A client
|
||||||
client hammering a single invented path is served `RECEIVER_RATE_LIMIT`
|
hammering a single invented path is served `RECEIVER_RATE_LIMIT`
|
||||||
requests and has the rest of its aggregate budget rejected there, so
|
requests and has the rest of its aggregate budget rejected there, so
|
||||||
the aggregate limit is what bounds those `WARN` lines — to under ten
|
the aggregate limit is what bounds the _number_ of those `WARN` lines —
|
||||||
times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the
|
to under ten times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080
|
||||||
defaults, where before it there was no bound at all. The access log is
|
at the defaults, where before it there was no bound at all. Their
|
||||||
bounded by neither limit: every request is recorded once at `INFO`,
|
_width_ is bounded by the field budgets below, the same ones the access
|
||||||
served or rejected alike.
|
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
|
What the access log does bound is the _content_ of those lines. A 3xx
|
||||||
or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
|
or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
|
||||||
@@ -1152,6 +1153,100 @@ that the rate is not bounded by the limits above on every route:
|
|||||||
`/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
|
`/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
|
||||||
the multiplier is whatever the deployment will serve.
|
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`, and a future caller on a
|
||||||
|
route with a URL parameter would widen the line. Since no request
|
||||||
|
through the mux can, both caps are pinned by tests that call those two
|
||||||
|
entry points directly with the path such a caller would supply.
|
||||||
|
Removing either cap fails 14 subtests.
|
||||||
|
|
||||||
|
`internal/middleware/logbound_test.go` and
|
||||||
|
`internal/handlers/logbound_test.go` drive 8 KB of client-chosen text
|
||||||
|
at each of these — 1 KB at `invalid password`, whose accounts are
|
||||||
|
shared with the successful-login line, where a username past 4 KB
|
||||||
|
overflows the session cookie and answers 500 before that line is
|
||||||
|
written — through both handlers, and through seven fills: plain text
|
||||||
|
as the baseline, and then the quotation mark, backslash, tab, newline,
|
||||||
|
C0 control and astral non-printable, six characters the wider of the
|
||||||
|
two handlers spends more on than the client spent sending them. Every
|
||||||
|
case holds each line to the 2,560-byte ceiling. That per-line ceiling
|
||||||
|
is what the figure above states, and every row establishes it.
|
||||||
|
|
||||||
|
Three of the sites go further and bound the whole flood's output — the
|
||||||
|
total bytes a run of distinct invented values wrote, which is the
|
||||||
|
shape an operator sizing storage cares about. They are
|
||||||
|
`request body exceeds limit`
|
||||||
|
(`TestMaxBodySize_FloodOfOversizePathsDoesNotGrowTheLog`),
|
||||||
|
`entrypoint not found` and `user not found` (the last two through
|
||||||
|
`assertBoundedFlood`). The other rows carry no aggregate assertion;
|
||||||
|
the per-line ceiling is what they establish.
|
||||||
|
|
||||||
|
`internal/logfield/logfield_test.go` measures the per-rune charge
|
||||||
|
against what 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
|
Every limiter here — receiver, login, and password change — identifies
|
||||||
the client the same way, through one shared key function: the
|
the client the same way, through one shared key function: the
|
||||||
connection's own address, unless the peer is listed in
|
connection's own address, unless the peer is listed in
|
||||||
|
|||||||
@@ -11,6 +11,17 @@ import (
|
|||||||
// inbound webhook — the full request body and headers, plus
|
// inbound webhook — the full request body and headers, plus
|
||||||
// the method, content type, and the webhook and entrypoint
|
// the method, content type, and the webhook and entrypoint
|
||||||
// ids — then records a single successful attempt.
|
// 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 {
|
type logTarget struct {
|
||||||
eng *Engine
|
eng *Engine
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -5,6 +5,7 @@ import (
|
|||||||
"strconv"
|
"strconv"
|
||||||
|
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
"sneak.berlin/go/webhooker/internal/database"
|
||||||
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
)
|
)
|
||||||
|
|
||||||
// HandleLoginPage returns a handler for the login page (GET)
|
// HandleLoginPage returns a handler for the login page (GET)
|
||||||
@@ -70,7 +71,9 @@ func (h *Handlers) HandleLoginSubmit() http.HandlerFunc {
|
|||||||
|
|
||||||
h.log.Info(
|
h.log.Info(
|
||||||
"user logged in",
|
"user logged in",
|
||||||
"username", username,
|
"username", logfield.Truncate(
|
||||||
|
username, logfield.MaxBytes,
|
||||||
|
),
|
||||||
"user_id", user.ID,
|
"user_id", user.ID,
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -117,7 +120,9 @@ func (h *Handlers) authenticateUser(
|
|||||||
if !ok {
|
if !ok {
|
||||||
h.log.Warn(
|
h.log.Warn(
|
||||||
"password verification capacity exhausted",
|
"password verification capacity exhausted",
|
||||||
"path", r.URL.Path,
|
"path", logfield.Truncate(
|
||||||
|
r.URL.Path, logfield.MaxBytes,
|
||||||
|
),
|
||||||
)
|
)
|
||||||
h.renderLoginError(
|
h.renderLoginError(
|
||||||
w, r,
|
w, r,
|
||||||
@@ -142,7 +147,17 @@ func (h *Handlers) authenticateUser(
|
|||||||
h.dummyVerifications.Add(1)
|
h.dummyVerifications.Add(1)
|
||||||
database.VerifyDummyPassword(password)
|
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)
|
h.rejectLogin(w, r, username)
|
||||||
|
|
||||||
return user, err
|
return user, err
|
||||||
@@ -160,7 +175,17 @@ func (h *Handlers) authenticateUser(
|
|||||||
}
|
}
|
||||||
|
|
||||||
if !valid {
|
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)
|
h.rejectLogin(w, r, username)
|
||||||
|
|
||||||
return user, errInvalidPassword
|
return user, errInvalidPassword
|
||||||
|
|||||||
@@ -2,11 +2,19 @@ package handlers
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"html/template"
|
"html/template"
|
||||||
|
"log/slog"
|
||||||
"net/http"
|
"net/http"
|
||||||
|
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
"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
|
// MaxRenderedBodyBytesForTest exposes the event log's body cap
|
||||||
// to the handlers_test package.
|
// to the handlers_test package.
|
||||||
const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes
|
const MaxRenderedBodyBytesForTest = maxRenderedBodyBytes
|
||||||
|
|||||||
543
internal/handlers/logbound_test.go
Normal file
543
internal/handlers/logbound_test.go
Normal file
@@ -0,0 +1,543 @@
|
|||||||
|
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.
|
||||||
|
//
|
||||||
|
// So is the "password verification capacity exhausted" WARN line,
|
||||||
|
// whose path chi pins to the constant "/pages/login" on the one route
|
||||||
|
// that reaches it. Its cap is defensive, and the test below drives the
|
||||||
|
// handler directly with the path a parameterised route would give it,
|
||||||
|
// because an unasserted cap is one a later edit removes for free.
|
||||||
|
|
||||||
|
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
|
||||||
|
}
|
||||||
|
|
||||||
|
// capturingHandlers builds a Handlers whose log is captured into the
|
||||||
|
// returned buffer at DEBUG through the named handler.
|
||||||
|
//
|
||||||
|
// extra is passed to fx.Populate alongside the Handlers, for the call
|
||||||
|
// sites that also need the database the client's value is looked up
|
||||||
|
// in, or the Middleware whose resource has to be exhausted before the
|
||||||
|
// branch under test is reached.
|
||||||
|
func capturingHandlers(
|
||||||
|
t *testing.T,
|
||||||
|
newHandler func(io.Writer, *slog.HandlerOptions) slog.Handler,
|
||||||
|
extra ...any,
|
||||||
|
) (*handlers.Handlers, *bytes.Buffer) {
|
||||||
|
t.Helper()
|
||||||
|
|
||||||
|
var h *handlers.Handlers
|
||||||
|
|
||||||
|
app := newTestApp(t, append([]any{&h}, extra...)...)
|
||||||
|
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 the stated per-line ceiling.
|
||||||
|
func logLines(t *testing.T, buf *bytes.Buffer) []string {
|
||||||
|
t.Helper()
|
||||||
|
|
||||||
|
var lines []string
|
||||||
|
|
||||||
|
for line := range strings.SplitSeq(
|
||||||
|
strings.TrimSpace(buf.String()), "\n",
|
||||||
|
) {
|
||||||
|
if line == "" {
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
|
||||||
|
require.LessOrEqual(
|
||||||
|
t, len(line), middleware.MaxAccessLogLineBytes,
|
||||||
|
"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)
|
||||||
|
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)
|
||||||
|
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()
|
||||||
|
|
||||||
|
var db *database.Database
|
||||||
|
|
||||||
|
h, buf := capturingHandlers(t, newHandler, &db)
|
||||||
|
|
||||||
|
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)
|
||||||
|
require.Len(t, lines, 2*len(fills))
|
||||||
|
assertNoClientText(t, buf)
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// maxVerificationSlots bounds how many slots the loop below will
|
||||||
|
// take before it gives up, so a semaphore that never fills fails the
|
||||||
|
// test instead of hanging it. It is deliberately larger than the
|
||||||
|
// real concurrency bound, which is not exported to this package.
|
||||||
|
const maxVerificationSlots = 64
|
||||||
|
|
||||||
|
// canceledContext returns a context that is already done. A
|
||||||
|
// verification request carrying one takes the ctx.Done() branch of
|
||||||
|
// the semaphore's bounded wait immediately, so these cases turn on
|
||||||
|
// the semaphore being full rather than on a five-second timer firing.
|
||||||
|
// Nothing here is timing-dependent.
|
||||||
|
func canceledContext() context.Context {
|
||||||
|
ctx, cancel := context.WithCancel(context.Background())
|
||||||
|
cancel()
|
||||||
|
|
||||||
|
return ctx
|
||||||
|
}
|
||||||
|
|
||||||
|
// holdEveryVerificationSlot takes verification slots until one is
|
||||||
|
// refused, and releases them when the test ends. A free slot is
|
||||||
|
// handed out before any context is consulted, so a canceled context
|
||||||
|
// cannot make this loop stop early: it stops exactly when the slots
|
||||||
|
// are gone.
|
||||||
|
func holdEveryVerificationSlot(
|
||||||
|
t *testing.T, mw *middleware.Middleware,
|
||||||
|
) {
|
||||||
|
t.Helper()
|
||||||
|
|
||||||
|
for range maxVerificationSlots {
|
||||||
|
release, ok := mw.BeginPasswordVerification(canceledContext())
|
||||||
|
if !ok {
|
||||||
|
return
|
||||||
|
}
|
||||||
|
|
||||||
|
t.Cleanup(release)
|
||||||
|
}
|
||||||
|
|
||||||
|
require.Fail(t, "the verification semaphore never filled")
|
||||||
|
}
|
||||||
|
|
||||||
|
// postLoginAtPath submits the login form at a path of the caller's
|
||||||
|
// choosing, with a canceled context.
|
||||||
|
func postLoginAtPath(
|
||||||
|
t *testing.T, h *handlers.Handlers, path string,
|
||||||
|
) int {
|
||||||
|
t.Helper()
|
||||||
|
|
||||||
|
form := url.Values{
|
||||||
|
"username": {"someone"},
|
||||||
|
"password": {"not-the-password"},
|
||||||
|
}
|
||||||
|
|
||||||
|
req := httptest.NewRequestWithContext(
|
||||||
|
canceledContext(),
|
||||||
|
http.MethodPost,
|
||||||
|
path,
|
||||||
|
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
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestVerificationCapacity_LogLineDoesNotTrackPathSize pins the cap
|
||||||
|
// on the "password verification capacity exhausted" WARN line.
|
||||||
|
//
|
||||||
|
// The one route that reaches it is chi's static "/pages/login", so no
|
||||||
|
// request through the mux can widen the line; the handler is driven
|
||||||
|
// directly here with the path a parameterised route would give it,
|
||||||
|
// which is what that cap exists for. Without this test, removing the
|
||||||
|
// logfield.Truncate there fails nothing.
|
||||||
|
func TestVerificationCapacity_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()
|
||||||
|
|
||||||
|
var mw *middleware.Middleware
|
||||||
|
|
||||||
|
h, buf := capturingHandlers(t, newHandler, &mw)
|
||||||
|
|
||||||
|
holdEveryVerificationSlot(t, mw)
|
||||||
|
|
||||||
|
assert.Equal(
|
||||||
|
t,
|
||||||
|
http.StatusServiceUnavailable,
|
||||||
|
postLoginAtPath(
|
||||||
|
t, h,
|
||||||
|
"/source/"+url.PathEscape(
|
||||||
|
oversizedFill(fill),
|
||||||
|
)+"/login",
|
||||||
|
),
|
||||||
|
)
|
||||||
|
|
||||||
|
lines := logLines(t, buf)
|
||||||
|
require.Len(t, lines, 1)
|
||||||
|
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,
|
||||||
|
)
|
||||||
|
}
|
||||||
@@ -9,6 +9,7 @@ import (
|
|||||||
"gorm.io/gorm"
|
"gorm.io/gorm"
|
||||||
"sneak.berlin/go/webhooker/internal/database"
|
"sneak.berlin/go/webhooker/internal/database"
|
||||||
"sneak.berlin/go/webhooker/internal/delivery"
|
"sneak.berlin/go/webhooker/internal/delivery"
|
||||||
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
@@ -125,9 +126,16 @@ func (h *Handlers) lookupEntrypoint(
|
|||||||
"path = ?", entrypointUUID,
|
"path = ?", entrypointUUID,
|
||||||
).First(&entrypoint)
|
).First(&entrypoint)
|
||||||
if result.Error != nil {
|
if result.Error != nil {
|
||||||
|
// The receiver is unauthenticated and /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(
|
h.log.Debug(
|
||||||
"entrypoint not found",
|
"entrypoint not found",
|
||||||
"path", entrypointUUID,
|
"path", logfield.Truncate(
|
||||||
|
entrypointUUID, logfield.MaxBytes,
|
||||||
|
),
|
||||||
)
|
)
|
||||||
http.NotFound(w, r)
|
http.NotFound(w, r)
|
||||||
|
|
||||||
|
|||||||
143
internal/logfield/logfield.go
Normal file
143
internal/logfield/logfield.go
Normal 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
|
||||||
|
}
|
||||||
221
internal/logfield/logfield_test.go
Normal file
221
internal/logfield/logfield_test.go
Normal 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))
|
||||||
|
}
|
||||||
@@ -4,6 +4,7 @@ import (
|
|||||||
"net/http"
|
"net/http"
|
||||||
|
|
||||||
"github.com/gorilla/csrf"
|
"github.com/gorilla/csrf"
|
||||||
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
)
|
)
|
||||||
|
|
||||||
// CSRFToken retrieves the CSRF token from the request context.
|
// 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.
|
// csrf.Secure option is set at creation time, not per-request.
|
||||||
func (m *Middleware) CSRF() func(http.Handler) http.Handler {
|
func (m *Middleware) CSRF() func(http.Handler) http.Handler {
|
||||||
csrfErrorHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
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",
|
m.log.Warn("csrf: token validation failed",
|
||||||
"method", r.Method,
|
"method", logfield.Truncate(
|
||||||
"path", r.URL.Path,
|
r.Method, maxLogMethodBytes,
|
||||||
|
),
|
||||||
|
"path", logfield.Truncate(
|
||||||
|
r.URL.Path, logfield.MaxBytes,
|
||||||
|
),
|
||||||
"remote_addr", r.RemoteAddr,
|
"remote_addr", r.RemoteAddr,
|
||||||
"reason", csrf.FailureReason(r),
|
"reason", csrf.FailureReason(r),
|
||||||
)
|
)
|
||||||
|
|||||||
544
internal/middleware/logbound_test.go
Normal file
544
internal/middleware/logbound_test.go
Normal file
@@ -0,0 +1,544 @@
|
|||||||
|
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.
|
||||||
|
// - RecordLoginFailure's throttle rejection, at WARN. Its cap is
|
||||||
|
// defensive rather than load-bearing today: chi pins the one
|
||||||
|
// route that calls it to the constant path "/pages/login". The
|
||||||
|
// method is exported and takes any *http.Request, so the test
|
||||||
|
// below hands it the request a caller on a parameterised route
|
||||||
|
// would, which is what the cap exists for.
|
||||||
|
//
|
||||||
|
// 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)
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// TestLoginThrottle_LogLineDoesNotTrackPathSize pins the cap on
|
||||||
|
// RecordLoginFailure's "login failure limit exceeded" WARN line.
|
||||||
|
//
|
||||||
|
// That site does not fit logSites above: it is not a middleware
|
||||||
|
// wrapping a handler but an exported method the login handler calls,
|
||||||
|
// and the only route that calls it today is chi's static
|
||||||
|
// "/pages/login", so no request through the mux can widen the line.
|
||||||
|
// Driving the method directly is therefore the whole point rather
|
||||||
|
// than a shortcut — it is exactly the call a second caller on a route
|
||||||
|
// with a URL parameter would make, and without this test removing the
|
||||||
|
// logfield.Truncate there fails nothing.
|
||||||
|
func TestLoginThrottle_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()
|
||||||
|
|
||||||
|
m, buf := capturingBoundMiddleware(
|
||||||
|
t, newHandler,
|
||||||
|
)
|
||||||
|
|
||||||
|
req := httptest.NewRequestWithContext(
|
||||||
|
context.Background(),
|
||||||
|
http.MethodPost,
|
||||||
|
"/source/"+
|
||||||
|
oversizedPathSegment(fill)+"/login",
|
||||||
|
nil,
|
||||||
|
)
|
||||||
|
req.RemoteAddr = "203.0.113.9:5555"
|
||||||
|
|
||||||
|
// The budget is spent per client and username,
|
||||||
|
// so one more failure than the budget allows is
|
||||||
|
// what takes the throttled branch.
|
||||||
|
var throttled bool
|
||||||
|
for range middleware.LoginRateLimitConst + 1 {
|
||||||
|
throttled = m.RecordLoginFailure(
|
||||||
|
req, "someone",
|
||||||
|
)
|
||||||
|
}
|
||||||
|
|
||||||
|
require.True(
|
||||||
|
t, throttled,
|
||||||
|
"the throttled branch never ran, so the "+
|
||||||
|
"bound proves nothing",
|
||||||
|
)
|
||||||
|
|
||||||
|
lines := logLines(
|
||||||
|
t, buf, middleware.MaxAccessLogLineBytes,
|
||||||
|
)
|
||||||
|
require.NotEmpty(t, lines)
|
||||||
|
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,
|
||||||
|
)
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -7,6 +7,8 @@ import (
|
|||||||
"net/http"
|
"net/http"
|
||||||
"sync"
|
"sync"
|
||||||
"time"
|
"time"
|
||||||
|
|
||||||
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
@@ -372,8 +374,17 @@ func (m *Middleware) RecordLoginFailure(
|
|||||||
) bool {
|
) bool {
|
||||||
throttled := m.guard().fail(m.clientKey(r), username)
|
throttled := m.guard().fail(m.clientKey(r), username)
|
||||||
if throttled {
|
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. logbound_test.go pins the cap by making exactly
|
||||||
|
// that call, since no request through the mux can.
|
||||||
m.log.Warn(
|
m.log.Warn(
|
||||||
"login failure limit exceeded", "path", r.URL.Path,
|
"login failure limit exceeded",
|
||||||
|
"path", logfield.Truncate(
|
||||||
|
r.URL.Path, logfield.MaxBytes,
|
||||||
|
),
|
||||||
)
|
)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -6,11 +6,8 @@ import (
|
|||||||
"log/slog"
|
"log/slog"
|
||||||
"net"
|
"net"
|
||||||
"net/http"
|
"net/http"
|
||||||
"strings"
|
|
||||||
"sync"
|
"sync"
|
||||||
"time"
|
"time"
|
||||||
"unicode"
|
|
||||||
"unicode/utf8"
|
|
||||||
|
|
||||||
basicauth "github.com/99designs/basicauth-go"
|
basicauth "github.com/99designs/basicauth-go"
|
||||||
"github.com/go-chi/chi"
|
"github.com/go-chi/chi"
|
||||||
@@ -22,6 +19,7 @@ import (
|
|||||||
"go.uber.org/fx"
|
"go.uber.org/fx"
|
||||||
"sneak.berlin/go/webhooker/internal/config"
|
"sneak.berlin/go/webhooker/internal/config"
|
||||||
"sneak.berlin/go/webhooker/internal/globals"
|
"sneak.berlin/go/webhooker/internal/globals"
|
||||||
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
"sneak.berlin/go/webhooker/internal/logger"
|
"sneak.berlin/go/webhooker/internal/logger"
|
||||||
"sneak.berlin/go/webhooker/internal/session"
|
"sneak.berlin/go/webhooker/internal/session"
|
||||||
)
|
)
|
||||||
@@ -44,16 +42,6 @@ const (
|
|||||||
// pick the size of the line it writes.
|
// pick the size of the line it writes.
|
||||||
redactedQuery = "?(redacted)"
|
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
|
// maxLogRequestIDBytes bounds the request id, which is also
|
||||||
// client-supplied: chi's RequestID middleware passes an inbound
|
// client-supplied: chi's RequestID middleware passes an inbound
|
||||||
// X-Request-Id header through verbatim. Its generated form is an
|
// X-Request-Id header through verbatim. Its generated form is an
|
||||||
@@ -66,15 +54,10 @@ const (
|
|||||||
// is half this.
|
// is half this.
|
||||||
maxLogMethodBytes = 32
|
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,
|
// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
|
||||||
// and the number an operator multiplies by the request rate to size
|
// 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
|
// 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.
|
// ENCODED bytes, plus the part of the line no client can influence.
|
||||||
//
|
//
|
||||||
// url, useragent, referer 3*(512+11) = 1569
|
// url, useragent, referer 3*(512+11) = 1569
|
||||||
@@ -91,13 +74,55 @@ const (
|
|||||||
// than sitting on the arithmetic.
|
// than sitting on the arithmetic.
|
||||||
//
|
//
|
||||||
// The tty text handler in internal/logger is covered by the same
|
// 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
|
// the wider of the two handlers emits for it — including the ten
|
||||||
// bytes strconv.Quote spends on a non-printable rune at or above
|
// bytes strconv.Quote spends on a non-printable rune at or above
|
||||||
// U+10000, which is four more than the JSON handler ever spends —
|
// U+10000, which is four more than the JSON handler ever spends —
|
||||||
// so each budget bounds the encoded field under either handler.
|
// so each budget bounds the encoded field under either handler.
|
||||||
// The text handler's fixed portion is 286, the smaller of the two,
|
// The text handler's fixed portion is 286, the smaller of the two,
|
||||||
// which puts its worst case at 2037.
|
// 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.
|
||||||
|
//
|
||||||
|
// The two login-throttle lines are capped defensively: chi pins
|
||||||
|
// their route to the constant path "/pages/login", so no request
|
||||||
|
// through the mux can widen either one. Their assertions call
|
||||||
|
// RecordLoginFailure and the login handler directly with the path
|
||||||
|
// a caller on a parameterised route would supply, which is the
|
||||||
|
// only way those caps can be pinned at all.
|
||||||
|
//
|
||||||
|
// 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
|
MaxAccessLogLineBytes = 2560
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -174,114 +199,6 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
|
|||||||
lrw.ResponseWriter.WriteHeader(code)
|
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
|
// concreteLogURL renders the request's own URL for the access log
|
||||||
// branches that keep it, with the query string replaced by a fixed
|
// branches that keep it, with the query string replaced by a fixed
|
||||||
// marker.
|
// marker.
|
||||||
@@ -375,21 +292,21 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
|
|||||||
// line does not track the size of the request.
|
// line does not track the size of the request.
|
||||||
s.log.Info("http request",
|
s.log.Info("http request",
|
||||||
"request_start", start,
|
"request_start", start,
|
||||||
"method", truncateLogField(
|
"method", logfield.Truncate(
|
||||||
r.Method, maxLogMethodBytes,
|
r.Method, maxLogMethodBytes,
|
||||||
),
|
),
|
||||||
"url", truncateLogField(
|
"url", logfield.Truncate(
|
||||||
accessLogURL(r, lrw.statusCode),
|
accessLogURL(r, lrw.statusCode),
|
||||||
maxLogFieldBytes,
|
logfield.MaxBytes,
|
||||||
),
|
),
|
||||||
"useragent", truncateLogField(
|
"useragent", logfield.Truncate(
|
||||||
r.UserAgent(), maxLogFieldBytes,
|
r.UserAgent(), logfield.MaxBytes,
|
||||||
),
|
),
|
||||||
"request_id", truncateLogField(
|
"request_id", logfield.Truncate(
|
||||||
requestID, maxLogRequestIDBytes,
|
requestID, maxLogRequestIDBytes,
|
||||||
),
|
),
|
||||||
"referer", truncateLogField(
|
"referer", logfield.Truncate(
|
||||||
r.Referer(), maxLogFieldBytes,
|
r.Referer(), logfield.MaxBytes,
|
||||||
),
|
),
|
||||||
"proto", r.Proto,
|
"proto", r.Proto,
|
||||||
"remoteIP", ipFromHostPort(r.RemoteAddr),
|
"remoteIP", ipFromHostPort(r.RemoteAddr),
|
||||||
@@ -457,10 +374,21 @@ func (s *Middleware) RequireAuth() func(http.Handler) http.Handler {
|
|||||||
// session lands here and is sent back to the login
|
// session lands here and is sent back to the login
|
||||||
// page.
|
// page.
|
||||||
if !s.session.IsAuthenticated(sess) {
|
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(
|
s.log.Debug(
|
||||||
"auth middleware: unauthenticated request",
|
"auth middleware: unauthenticated request",
|
||||||
"path", r.URL.Path,
|
"path", logfield.Truncate(
|
||||||
"method", r.Method,
|
r.URL.Path, logfield.MaxBytes,
|
||||||
|
),
|
||||||
|
"method", logfield.Truncate(
|
||||||
|
r.Method, maxLogMethodBytes,
|
||||||
|
),
|
||||||
)
|
)
|
||||||
http.Redirect(
|
http.Redirect(
|
||||||
w, r, "/pages/login", http.StatusSeeOther,
|
w, r, "/pages/login", http.StatusSeeOther,
|
||||||
@@ -620,10 +548,26 @@ func (s *Middleware) MaxBodySize(
|
|||||||
}
|
}
|
||||||
|
|
||||||
if r.ContentLength > maxBytes {
|
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(
|
s.log.Warn(
|
||||||
"request body exceeds limit",
|
"request body exceeds limit",
|
||||||
"method", r.Method,
|
"method", logfield.Truncate(
|
||||||
"path", r.URL.Path,
|
r.Method, maxLogMethodBytes,
|
||||||
|
),
|
||||||
|
"path", logfield.Truncate(
|
||||||
|
r.URL.Path, logfield.MaxBytes,
|
||||||
|
),
|
||||||
"content_length", r.ContentLength,
|
"content_length", r.ContentLength,
|
||||||
"limit", maxBytes,
|
"limit", maxBytes,
|
||||||
)
|
)
|
||||||
|
|||||||
@@ -57,7 +57,21 @@ func testMiddlewareWithSessionClock(
|
|||||||
SessionIdleTimeout: idleTimeout,
|
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)
|
key := make([]byte, testKeySize)
|
||||||
|
|
||||||
for i := range key {
|
for i := range key {
|
||||||
@@ -79,11 +93,7 @@ func testMiddlewareWithSessionClock(
|
|||||||
now = clock.Now
|
now = clock.Now
|
||||||
}
|
}
|
||||||
|
|
||||||
sessManager := session.NewForTest(store, cfg, log, key, now)
|
return session.NewForTest(store, cfg, log, key, now)
|
||||||
|
|
||||||
m := middleware.NewForTest(log, cfg, sessManager)
|
|
||||||
|
|
||||||
return m, sessManager, clock
|
|
||||||
}
|
}
|
||||||
|
|
||||||
// fakeClock is a manually advanced clock, so session expiry can be
|
// fakeClock is a manually advanced clock, so session expiry can be
|
||||||
|
|||||||
@@ -9,6 +9,7 @@ import (
|
|||||||
"time"
|
"time"
|
||||||
|
|
||||||
"github.com/go-chi/httprate"
|
"github.com/go-chi/httprate"
|
||||||
|
"sneak.berlin/go/webhooker/internal/logfield"
|
||||||
)
|
)
|
||||||
|
|
||||||
const (
|
const (
|
||||||
@@ -225,11 +226,22 @@ func (m *Middleware) clientKey(r *http.Request) string {
|
|||||||
// rejection with logMessage and answers with responseMessage.
|
// rejection with logMessage and answers with responseMessage.
|
||||||
// httprate adds the Retry-After header (RFC 6585). The aggregate
|
// httprate adds the Retry-After header (RFC 6585). The aggregate
|
||||||
// receiver limiter uses floodTooManyRequests instead.
|
// receiver limiter uses floodTooManyRequests instead.
|
||||||
|
//
|
||||||
|
// The path is capped against the same budget as the access log's url
|
||||||
|
// 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(
|
func (m *Middleware) tooManyRequests(
|
||||||
logMessage, responseMessage string,
|
logMessage, responseMessage string,
|
||||||
) http.HandlerFunc {
|
) http.HandlerFunc {
|
||||||
return func(w http.ResponseWriter, r *http.Request) {
|
return func(w http.ResponseWriter, r *http.Request) {
|
||||||
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)
|
http.Error(w, responseMessage, http.StatusTooManyRequests)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -14,6 +14,28 @@ import (
|
|||||||
// maxFormBodySize is the maximum allowed request body size (in
|
// maxFormBodySize is the maximum allowed request body size (in
|
||||||
// bytes) for form POST endpoints. 1 MB is generous for any form
|
// bytes) for form POST endpoints. 1 MB is generous for any form
|
||||||
// submission while preventing abuse from oversized payloads.
|
// 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
|
const maxFormBodySize int64 = 1 * 1024 * 1024 // 1 MB
|
||||||
|
|
||||||
// requestTimeout is the maximum time allowed for a single HTTP
|
// requestTimeout is the maximum time allowed for a single HTTP
|
||||||
@@ -90,8 +112,8 @@ func (s *Server) setupRoutes() {
|
|||||||
|
|
||||||
func (s *Server) setupPageRoutes() {
|
func (s *Server) setupPageRoutes() {
|
||||||
s.router.Route("/pages", func(r chi.Router) {
|
s.router.Route("/pages", func(r chi.Router) {
|
||||||
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
||||||
// form, so the cap has to be installed before it runs.
|
// see maxFormBodySize for why, and for what it costs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
@@ -111,8 +133,8 @@ func (s *Server) setupPageRoutes() {
|
|||||||
|
|
||||||
func (s *Server) setupUserRoutes() {
|
func (s *Server) setupUserRoutes() {
|
||||||
s.router.Route("/user/{username}", func(r chi.Router) {
|
s.router.Route("/user/{username}", func(r chi.Router) {
|
||||||
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
||||||
// form, so the cap has to be installed before it runs.
|
// see maxFormBodySize for why, and for what it costs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
@@ -126,8 +148,8 @@ func (s *Server) setupUserRoutes() {
|
|||||||
|
|
||||||
func (s *Server) setupSourceRoutes() {
|
func (s *Server) setupSourceRoutes() {
|
||||||
s.router.Route("/sources", func(r chi.Router) {
|
s.router.Route("/sources", func(r chi.Router) {
|
||||||
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
||||||
// form, so the cap has to be installed before it runs.
|
// see maxFormBodySize for why, and for what it costs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
@@ -138,8 +160,8 @@ func (s *Server) setupSourceRoutes() {
|
|||||||
})
|
})
|
||||||
|
|
||||||
s.router.Route("/source/{sourceID}", func(r chi.Router) {
|
s.router.Route("/source/{sourceID}", func(r chi.Router) {
|
||||||
// MaxBodySize must precede CSRF: gorilla/csrf parses the
|
// MaxBodySize precedes CSRF and RequireAuth deliberately;
|
||||||
// form, so the cap has to be installed before it runs.
|
// see maxFormBodySize for why, and for what it costs.
|
||||||
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
r.Use(s.mw.MaxBodySize(maxFormBodySize))
|
||||||
r.Use(s.mw.CSRF())
|
r.Use(s.mw.CSRF())
|
||||||
r.Use(s.mw.NoCache())
|
r.Use(s.mw.NoCache())
|
||||||
|
|||||||
Reference in New Issue
Block a user