Bound the access log line against client-chosen text (closes #146)
All checks were successful
check / check (push) Successful in 3m16s
All checks were successful
check / check (push) Successful in 3m16s
The access log wrote one INFO line per request carrying r.URL.String(). Registered with Use, it runs ahead of the route limiter, so a client flooding the unauthenticated receiver with invented paths wrote attacker-chosen text of attacker-chosen length into the operator's log, one line per request. 3xx and 4xx responses now log the chi route pattern in place of the concrete URL, and the fixed literal "(unmatched)" when routing matched nothing at all. One line per request is retained, so real traffic stays observable and rate accounting still works, but the line's content is now bounded by the service's own route table. The pattern is only populated after routing, so it is read in the deferred part of the handler rather than before next.ServeHTTP. The route pattern alone does not close the hole, because it leaves two other ways for a request to choose the size of the line it writes. The query string is one: /.well-known/healthcheck and /s/* answer 200 to anyone with no rate limiter in front of them, and /pages/login behind only the login limiter, so appending 8 KB after the '?' bought the same amplification as an invented 404 path. The branches that keep the concrete URL now log the path only, with the query replaced by the fixed marker "?(redacted)". Nothing debuggable is lost: `page`, on the authenticated pagination links, is the only query parameter this service reads. The headers are the other: useragent and referer are logged on every line, including the correctly redacted ones, so an 8 KB User-Agent plus an 8 KB Referer produced a 24 KB line whose url field read "(unmatched)". Each field a client supplies is now truncated rather than dropped -- a truncated User-Agent is still worth reading -- to 512 bytes for url, useragent and referer, 128 for request_id (chi passes an inbound X-Request-Id header straight through), and 32 for method, which Go accepts as any token up to the header size limit. Truncation also drops invalid UTF-8, which an encoder would otherwise expand six-fold past the budget. Each budget is spent in encoded bytes rather than in the bytes the client sent, because the line an operator stores is the encoded one. slog's JSON handler escapes a quotation mark, a backslash and a tab to two bytes each and a non-printable rune to six; its text handler spells any non-printable rune the same six-byte way; and Go's header parser accepts all of them in a header value. Counted raw, a 512-byte budget therefore bought a 1,024-byte field. Plain ASCII still encodes one byte for one, so a real browser's User-Agent fits whole, while a value built out of escapes keeps a proportionally shorter prefix. A complete line is now at most 2,560 bytes: 3*(512+11) for url, useragent and referer, 128+11 for request_id, 32+11 for method and a 336-byte fixed portion come to 2,087, stated with headroom. The tests assert it against 8 KB in the path, in the query and in each of the three headers, including values built from the characters the handler escapes, and against a 5xx whose concrete url is at its own budget on the same line. The README states it so an operator can size log storage against it.
This commit is contained in:
61
README.md
61
README.md
@@ -928,8 +928,65 @@ requests and has the rest of its aggregate budget rejected there, so
|
||||
the aggregate limit is what bounds those `WARN` lines — to under ten
|
||||
times `RECEIVER_RATE_LIMIT` per minute per client IP, 1080 at the
|
||||
defaults, where before it there was no bound at all. The access log is
|
||||
bounded by neither limit: every request is recorded once at `INFO` with
|
||||
its full URL, served or rejected alike.
|
||||
bounded by neither limit: every request is recorded once at `INFO`,
|
||||
served or rejected alike.
|
||||
|
||||
What the access log does bound is the _content_ of those lines. A 3xx
|
||||
or 4xx response logs the chi route pattern — `/webhook/{uuid}`,
|
||||
`/user/{username}//`, or the literal `(unmatched)` when the request hit
|
||||
no route at all — in place of the concrete URL. Those are the outcomes
|
||||
an unauthenticated client can drive for free: 404 and 429 on any
|
||||
invented receiver path, a login redirect on any invented profile path.
|
||||
Logging the URL there would let a flood write text of its own choosing,
|
||||
at a length of its own choosing, into the log. 2xx and 5xx responses
|
||||
keep the concrete path — a success resolved against a static route or
|
||||
against the operator's own data (on the receiver, against a stored
|
||||
entrypoint UUID), and a 5xx is a bug in this service, where the exact
|
||||
path is the evidence and no client can provoke one at will.
|
||||
|
||||
The query string is never logged; it is replaced by the fixed marker
|
||||
`?(redacted)`. It is client-chosen on every route, and
|
||||
`/.well-known/healthcheck` and `/s/*` answer 200 to anyone with no rate
|
||||
limiter in front of them, so a query on a fixed 200 URL would otherwise
|
||||
buy the same amplification as an invented path. Nothing debuggable is
|
||||
lost: `page`, on the authenticated pagination links, is the only query
|
||||
parameter this service reads.
|
||||
|
||||
The remaining client-supplied fields are truncated rather than dropped,
|
||||
each to a fixed budget: 512 bytes for `url`, `useragent` and `referer`,
|
||||
128 for `request_id` (chi passes an inbound `X-Request-Id` header
|
||||
through), and 32 for `method`. A truncated `User-Agent` is still worth
|
||||
reading; an absent one is not. A cut value ends in `[truncated]`, which
|
||||
is charged on top of the budget rather than inside it.
|
||||
|
||||
Each budget is spent in _encoded_ bytes, not in the bytes the client
|
||||
sent. The log handler escapes a quotation mark, a backslash and a tab
|
||||
to two bytes each and a non-printable rune to six, and Go's header
|
||||
parser accepts all of them in a header value, so a budget counted raw
|
||||
would buy a field twice its nominal size — and the line, not the
|
||||
header, is what an operator has to store. Plain ASCII encodes one byte
|
||||
for one, so a real browser's `User-Agent` still fits whole; a value
|
||||
built out of escapes keeps a proportionally shorter prefix, which is
|
||||
the right trade.
|
||||
|
||||
Net: **one `INFO` line per request, of at most 2,560 bytes.** That
|
||||
ceiling is arithmetic, not an observation: 3 × (512 + 11) for `url`,
|
||||
`useragent` and `referer`, plus 128 + 11 for `request_id`, plus 32 + 11
|
||||
for `method`, plus a 336-byte fixed portion (the field names, the
|
||||
punctuation, both timestamps at their longest, an IPv6 `remoteIP` with
|
||||
a zone, the status and the latency) — 2,087 bytes, stated at 2,560 so
|
||||
the figure has headroom. `internal/middleware/accesslog_test.go`
|
||||
asserts it against 8 KB of client-chosen text in the path, in the
|
||||
query, and in each of `User-Agent`, `Referer` and `X-Request-Id`,
|
||||
including cases built from the characters the handler escapes, and
|
||||
against the widest line the service can be made to write: a 5xx that
|
||||
keeps its concrete path while all three header fields are also at their
|
||||
budget. Measured over a real connection, that line is 1,972 bytes.
|
||||
|
||||
Multiply that ceiling by the request rate to size log storage. Note
|
||||
that the rate is not bounded by the limits above on every route:
|
||||
`/.well-known/healthcheck` and `/s/*` sit behind no limiter, so there
|
||||
the multiplier is whatever the deployment will serve.
|
||||
|
||||
Every limiter here — receiver, login, and password change — identifies
|
||||
the client the same way, through one shared key function: the
|
||||
|
||||
542
internal/middleware/accesslog_test.go
Normal file
542
internal/middleware/accesslog_test.go
Normal file
@@ -0,0 +1,542 @@
|
||||
package middleware_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"encoding/json"
|
||||
"log/slog"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/go-chi/chi"
|
||||
chimw "github.com/go-chi/chi/middleware"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"sneak.berlin/go/webhooker/internal/config"
|
||||
"sneak.berlin/go/webhooker/internal/middleware"
|
||||
)
|
||||
|
||||
// floodRequests is the number of distinct invented paths each flood
|
||||
// test drives through the access log.
|
||||
const floodRequests = 64
|
||||
|
||||
// attackerMarker is embedded in every invented path. No access log
|
||||
// line for a redirected or rejected request may contain it.
|
||||
const attackerMarker = "QQATTACKERTEXTQQ"
|
||||
|
||||
// maxLineBytes bounds a single access log line whose client-supplied
|
||||
// fields are of ordinary size. Well above what the fixed fields need,
|
||||
// well below the length of the oversized input the amplification tests
|
||||
// send.
|
||||
const maxLineBytes = 1024
|
||||
|
||||
// maxCappedLineBytes bounds a single access log line when every
|
||||
// client-supplied field arrives oversized and is truncated to its
|
||||
// budget. This is the number the README quotes as the per-line cost an
|
||||
// operator sizes log storage against, and it is a bound on the
|
||||
// ENCODED line, which is what the operator's disk holds.
|
||||
const maxCappedLineBytes = 2560
|
||||
|
||||
// oversizedSegmentBytes is the length of the single attacker-chosen
|
||||
// path segment, query string or header used to show line size does not
|
||||
// track input size.
|
||||
const oversizedSegmentBytes = 8192
|
||||
|
||||
// tailMarker is placed at the END of an oversized header value, so its
|
||||
// absence from the log proves the value was truncated rather than
|
||||
// merely being short.
|
||||
const tailMarker = "QQTRUNCATEDTAILQQ"
|
||||
|
||||
// These mirror the middleware's own budgets, which are unexported.
|
||||
// They are duplicated rather than exported so that widening a budget
|
||||
// in the middleware has to be restated here deliberately.
|
||||
const (
|
||||
maxFieldBytes = 512
|
||||
maxRequestIDBytes = 128
|
||||
truncationSuffix = "[truncated]"
|
||||
unmatchedRouteLiteral = "(unmatched)"
|
||||
)
|
||||
|
||||
// capturingMiddleware returns a Middleware whose logger writes JSON
|
||||
// lines into the returned buffer, so the access log can be asserted
|
||||
// on directly.
|
||||
func capturingMiddleware(t *testing.T) (*middleware.Middleware, *bytes.Buffer) {
|
||||
t.Helper()
|
||||
|
||||
buf := new(bytes.Buffer)
|
||||
log := slog.New(slog.NewJSONHandler(
|
||||
buf,
|
||||
&slog.HandlerOptions{Level: slog.LevelInfo},
|
||||
))
|
||||
|
||||
cfg := &config.Config{Environment: config.EnvironmentDev}
|
||||
|
||||
return middleware.NewForTest(log, cfg, nil), buf
|
||||
}
|
||||
|
||||
// accessLogRouter mirrors the production route shapes that an
|
||||
// unauthenticated client can reach: the public receiver, the
|
||||
// authenticated profile route (which redirects to login rather than
|
||||
// rejecting outright), the health check (which answers 200 to anyone,
|
||||
// behind no rate limiter at all), and a plain static route.
|
||||
func accessLogRouter(m *middleware.Middleware) *chi.Mux {
|
||||
router := chi.NewRouter()
|
||||
// Production registers RequestID ahead of Logging, and chi's
|
||||
// RequestID passes an inbound X-Request-Id header straight
|
||||
// through, so the request_id field is client-supplied too.
|
||||
router.Use(chimw.RequestID)
|
||||
router.Use(m.Logging())
|
||||
|
||||
router.Get(
|
||||
"/.well-known/healthcheck",
|
||||
func(w http.ResponseWriter, _ *http.Request) {
|
||||
w.WriteHeader(http.StatusOK)
|
||||
},
|
||||
)
|
||||
|
||||
router.HandleFunc(
|
||||
"/webhook/{uuid}",
|
||||
func(w http.ResponseWriter, r *http.Request) {
|
||||
// Stands in for the real handler: an unknown entrypoint
|
||||
// UUID 404s, a known one succeeds.
|
||||
if chi.URLParam(r, "uuid") != "known" {
|
||||
http.Error(w, "not found", http.StatusNotFound)
|
||||
|
||||
return
|
||||
}
|
||||
|
||||
w.WriteHeader(http.StatusOK)
|
||||
},
|
||||
)
|
||||
|
||||
router.Route("/user/{username}", func(r chi.Router) {
|
||||
r.Get("/", func(w http.ResponseWriter, r *http.Request) {
|
||||
http.Redirect(
|
||||
w, r, "/pages/login", http.StatusSeeOther,
|
||||
)
|
||||
})
|
||||
})
|
||||
|
||||
boom := func(w http.ResponseWriter, _ *http.Request) {
|
||||
http.Error(w, "boom", http.StatusInternalServerError)
|
||||
}
|
||||
|
||||
router.Get("/boom", boom)
|
||||
// The 5xx branch keeps the concrete path, so it needs a route that
|
||||
// answers 500 to a path of the client's choosing: that is where the
|
||||
// url field and the header fields are both at their budget on the
|
||||
// same line.
|
||||
router.Get("/boom/*", boom)
|
||||
|
||||
return router
|
||||
}
|
||||
|
||||
// accessLogEntries decodes the captured buffer into one map per
|
||||
// logged line, holding every line to maxLineBytes.
|
||||
func accessLogEntries(
|
||||
t *testing.T,
|
||||
buf *bytes.Buffer,
|
||||
) []map[string]any {
|
||||
t.Helper()
|
||||
|
||||
return accessLogEntriesWithin(t, buf, maxLineBytes)
|
||||
}
|
||||
|
||||
// accessLogEntriesWithin decodes the captured buffer into one map per
|
||||
// logged line, holding every line to bound bytes.
|
||||
func accessLogEntriesWithin(
|
||||
t *testing.T,
|
||||
buf *bytes.Buffer,
|
||||
bound int,
|
||||
) []map[string]any {
|
||||
t.Helper()
|
||||
|
||||
var entries []map[string]any
|
||||
|
||||
for line := range strings.SplitSeq(
|
||||
strings.TrimSpace(buf.String()), "\n",
|
||||
) {
|
||||
if line == "" {
|
||||
continue
|
||||
}
|
||||
|
||||
require.LessOrEqual(
|
||||
t, len(line), bound,
|
||||
"access log line exceeded its bound",
|
||||
)
|
||||
|
||||
var entry map[string]any
|
||||
|
||||
require.NoError(t, json.Unmarshal([]byte(line), &entry))
|
||||
|
||||
entries = append(entries, entry)
|
||||
}
|
||||
|
||||
return entries
|
||||
}
|
||||
|
||||
// get drives one GET through the router.
|
||||
func get(t *testing.T, router *chi.Mux, target string) int {
|
||||
t.Helper()
|
||||
|
||||
return getWithHeaders(t, router, target, nil)
|
||||
}
|
||||
|
||||
// getWithHeaders drives one GET through the router with the supplied
|
||||
// request headers set.
|
||||
func getWithHeaders(
|
||||
t *testing.T,
|
||||
router *chi.Mux,
|
||||
target string,
|
||||
headers map[string]string,
|
||||
) int {
|
||||
t.Helper()
|
||||
|
||||
req := httptest.NewRequestWithContext(
|
||||
context.Background(), http.MethodGet, target, nil,
|
||||
)
|
||||
|
||||
for name, value := range headers {
|
||||
req.Header.Set(name, value)
|
||||
}
|
||||
|
||||
w := httptest.NewRecorder()
|
||||
router.ServeHTTP(w, req)
|
||||
|
||||
return w.Code
|
||||
}
|
||||
|
||||
// assertFloodIsBounded drives floodRequests distinct invented paths
|
||||
// built by pathFor and asserts every logged line names wantURL, that
|
||||
// none carries the invented text, and that the line count is exactly
|
||||
// one per request.
|
||||
func assertFloodIsBounded(
|
||||
t *testing.T,
|
||||
pathFor func(i int) string,
|
||||
wantStatus int,
|
||||
wantURL string,
|
||||
) {
|
||||
t.Helper()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
for i := range floodRequests {
|
||||
assert.Equal(t, wantStatus, get(t, router, pathFor(i)))
|
||||
}
|
||||
|
||||
assert.NotContains(
|
||||
t, buf.String(), attackerMarker,
|
||||
"access log carried attacker-chosen path text",
|
||||
)
|
||||
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, floodRequests)
|
||||
|
||||
for _, entry := range entries {
|
||||
assert.Equal(t, wantURL, entry["url"])
|
||||
assert.InDelta(
|
||||
t, float64(wantStatus), entry["status"], 0,
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
func TestAccessLog_InventedReceiverPathsLogRoutePattern(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
assertFloodIsBounded(
|
||||
t,
|
||||
func(i int) string {
|
||||
return "/webhook/" + attackerMarker +
|
||||
strings.Repeat("x", i) + "?q=" + attackerMarker
|
||||
},
|
||||
http.StatusNotFound,
|
||||
"/webhook/{uuid}",
|
||||
)
|
||||
}
|
||||
|
||||
func TestAccessLog_InventedProfilePathsLogRoutePattern(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
// The login redirect is a 3xx, not a 4xx, but it is just as free
|
||||
// for an unauthenticated client to drive with invented input.
|
||||
// The doubled slash is what chi's RoutePattern yields for a
|
||||
// mounted subrouter's index route.
|
||||
assertFloodIsBounded(
|
||||
t,
|
||||
func(i int) string {
|
||||
return "/user/" + attackerMarker +
|
||||
strings.Repeat("x", i) + "/"
|
||||
},
|
||||
http.StatusSeeOther,
|
||||
"/user/{username}//",
|
||||
)
|
||||
}
|
||||
|
||||
func TestAccessLog_UnroutablePathsLogFixedLiteral(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
assertFloodIsBounded(
|
||||
t,
|
||||
func(i int) string {
|
||||
return "/" + attackerMarker + strings.Repeat("x", i)
|
||||
},
|
||||
http.StatusNotFound,
|
||||
"(unmatched)",
|
||||
)
|
||||
}
|
||||
|
||||
// oversizedValue builds an 8 KB header value out of repetitions of ch,
|
||||
// with the tail marker at its end.
|
||||
//
|
||||
// The leading 'x' is load-bearing for tab: net/textproto strips leading
|
||||
// and trailing whitespace from a header value, so a value that were
|
||||
// nothing but tabs would arrive empty over a real connection and the
|
||||
// case would prove nothing.
|
||||
func oversizedValue(ch string) string {
|
||||
return "x" + strings.Repeat(ch, oversizedSegmentBytes) + tailMarker
|
||||
}
|
||||
|
||||
// oversizedHeaders fills every client-supplied header the access log
|
||||
// reads with the same value.
|
||||
func oversizedHeaders(value string) map[string]string {
|
||||
return map[string]string{
|
||||
"User-Agent": value,
|
||||
"Referer": value,
|
||||
"X-Request-Id": value,
|
||||
}
|
||||
}
|
||||
|
||||
// sizeCase is one way of pointing 8 KB of client-chosen text at the
|
||||
// access log.
|
||||
type sizeCase struct {
|
||||
target string
|
||||
headers map[string]string
|
||||
wantStatus int
|
||||
wantURL string
|
||||
bound int
|
||||
}
|
||||
|
||||
// lineSizeCases enumerates every part of a request that reaches the
|
||||
// access log, at 8 KB apiece.
|
||||
func lineSizeCases() map[string]sizeCase {
|
||||
cases := map[string]sizeCase{
|
||||
"oversized path segment": {
|
||||
target: "/webhook/" + attackerMarker +
|
||||
strings.Repeat("x", oversizedSegmentBytes),
|
||||
wantStatus: http.StatusNotFound,
|
||||
wantURL: "/webhook/{uuid}",
|
||||
bound: maxLineBytes,
|
||||
},
|
||||
// /.well-known/healthcheck answers 200 to anyone and has no
|
||||
// rate limiter in front of it, so an oversized query appended
|
||||
// to it would otherwise buy the same amplification as an
|
||||
// invented 404 path, unauthenticated and unthrottled.
|
||||
"oversized query on an unauthenticated 200": {
|
||||
target: "/.well-known/healthcheck?q=" + attackerMarker +
|
||||
strings.Repeat("x", oversizedSegmentBytes),
|
||||
wantStatus: http.StatusOK,
|
||||
wantURL: "/.well-known/healthcheck?(redacted)",
|
||||
bound: maxLineBytes,
|
||||
},
|
||||
// These reach the line on every request, including one whose
|
||||
// url field is correctly redacted.
|
||||
"oversized headers": {
|
||||
target: "/" + attackerMarker,
|
||||
headers: oversizedHeaders(oversizedValue("h")),
|
||||
wantStatus: http.StatusNotFound,
|
||||
wantURL: unmatchedRouteLiteral,
|
||||
bound: maxCappedLineBytes,
|
||||
},
|
||||
}
|
||||
|
||||
// The url field on a 5xx keeps the concrete path, so it reaches its
|
||||
// own budget on the same line as the three header fields. That is
|
||||
// the widest line the service can be made to write.
|
||||
longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
|
||||
wantLongURL := longPath[:maxFieldBytes] + truncationSuffix
|
||||
|
||||
// escapeChars are the bytes Go's header parser accepts in a header
|
||||
// value and the log handler then escapes, one byte in and two or
|
||||
// more out. A budget counted in raw bytes lets any of them buy a
|
||||
// field twice its nominal size, so every one of them gets a case.
|
||||
escapeChars := map[string]string{
|
||||
"quote": `"`,
|
||||
"backslash": `\`,
|
||||
"tab": "\t",
|
||||
}
|
||||
|
||||
for kind, char := range escapeChars {
|
||||
fill := oversizedValue(char)
|
||||
|
||||
cases["oversized "+kind+" headers"] = sizeCase{
|
||||
target: "/" + attackerMarker,
|
||||
headers: oversizedHeaders(fill),
|
||||
wantStatus: http.StatusNotFound,
|
||||
wantURL: unmatchedRouteLiteral,
|
||||
bound: maxCappedLineBytes,
|
||||
}
|
||||
|
||||
cases["oversized "+kind+" headers with a 5xx concrete url"] =
|
||||
sizeCase{
|
||||
target: longPath,
|
||||
headers: oversizedHeaders(fill),
|
||||
wantStatus: http.StatusInternalServerError,
|
||||
wantURL: wantLongURL,
|
||||
bound: maxCappedLineBytes,
|
||||
}
|
||||
}
|
||||
|
||||
return cases
|
||||
}
|
||||
|
||||
// TestAccessLog_LineSizeDoesNotTrackInputSize drives 8 KB of
|
||||
// client-chosen text at the access log through each part of the
|
||||
// request that reaches it, and holds the resulting line to a fixed
|
||||
// bound in every case.
|
||||
//
|
||||
// The bound is on the ENCODED line, so the cases built out of
|
||||
// characters the handler escapes are the ones that matter: a budget
|
||||
// spent in raw bytes passes every plain-ASCII case here and still
|
||||
// writes a line half again as long as the stated ceiling.
|
||||
func TestAccessLog_LineSizeDoesNotTrackInputSize(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
require.Equal(
|
||||
t, middleware.MaxAccessLogLineBytes, maxCappedLineBytes,
|
||||
"the README quotes this ceiling and the middleware derives "+
|
||||
"it; they have to agree",
|
||||
)
|
||||
|
||||
for name, tc := range lineSizeCases() {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t,
|
||||
tc.wantStatus,
|
||||
getWithHeaders(t, router, tc.target, tc.headers),
|
||||
)
|
||||
|
||||
// accessLogEntriesWithin enforces the bound, which is
|
||||
// orders of magnitude smaller than the input just sent.
|
||||
entries := accessLogEntriesWithin(t, buf, tc.bound)
|
||||
require.Len(t, entries, 1)
|
||||
assert.Equal(t, tc.wantURL, entries[0]["url"])
|
||||
|
||||
// The markers sit at the far end of the client-chosen
|
||||
// text, so their absence is what proves the redaction and
|
||||
// the truncation actually ran.
|
||||
assert.NotContains(
|
||||
t, buf.String(), attackerMarker,
|
||||
"access log carried attacker-chosen text",
|
||||
)
|
||||
assert.NotContains(
|
||||
t, buf.String(), tailMarker,
|
||||
"access log carried an untruncated client field",
|
||||
)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestAccessLog_OversizedHeadersKeepATruncatedPrefix checks the other
|
||||
// half of the header cap: the fields are cut, not dropped, so a
|
||||
// truncated User-Agent is still worth reading.
|
||||
func TestAccessLog_OversizedHeadersKeepATruncatedPrefix(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t,
|
||||
http.StatusNotFound,
|
||||
getWithHeaders(
|
||||
t, router, "/nope",
|
||||
oversizedHeaders(oversizedValue("h")),
|
||||
),
|
||||
)
|
||||
|
||||
entries := accessLogEntriesWithin(t, buf, maxCappedLineBytes)
|
||||
require.Len(t, entries, 1)
|
||||
|
||||
for key, budget := range map[string]int{
|
||||
"useragent": maxFieldBytes,
|
||||
"referer": maxFieldBytes,
|
||||
"request_id": maxRequestIDBytes,
|
||||
} {
|
||||
value, ok := entries[0][key].(string)
|
||||
require.True(t, ok, key)
|
||||
assert.LessOrEqual(
|
||||
t, len(value), budget+len(truncationSuffix), key,
|
||||
)
|
||||
assert.Contains(t, value, truncationSuffix, key)
|
||||
assert.Contains(t, value, "hhhh", key)
|
||||
}
|
||||
}
|
||||
|
||||
func TestAccessLog_SuccessKeepsConcretePathAndRedactsQuery(
|
||||
t *testing.T,
|
||||
) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t, http.StatusOK, get(t, router, "/webhook/known?src=ci"),
|
||||
)
|
||||
|
||||
// The path resolved against a stored entrypoint, so it stays. The
|
||||
// query never does: see TestAccessLog_UnauthenticatedSuccess...
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 1)
|
||||
assert.Equal(t, "/webhook/known?(redacted)", entries[0]["url"])
|
||||
assert.NotContains(t, buf.String(), "src=ci")
|
||||
}
|
||||
|
||||
func TestAccessLog_ServerErrorKeepsConcreteURL(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t, http.StatusInternalServerError, get(t, router, "/boom"),
|
||||
)
|
||||
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 1)
|
||||
assert.Equal(t, "/boom", entries[0]["url"])
|
||||
}
|
||||
|
||||
func TestAccessLog_RetainsEveryOtherField(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
m, buf := capturingMiddleware(t)
|
||||
router := accessLogRouter(m)
|
||||
|
||||
assert.Equal(
|
||||
t,
|
||||
http.StatusNotFound,
|
||||
get(t, router, "/webhook/"+attackerMarker),
|
||||
)
|
||||
|
||||
entries := accessLogEntries(t, buf)
|
||||
require.Len(t, entries, 1)
|
||||
|
||||
for _, key := range []string{
|
||||
"request_start", "method", "url", "useragent", "request_id",
|
||||
"referer", "proto", "remoteIP", "status", "latency_ms",
|
||||
} {
|
||||
assert.Contains(t, entries[0], key)
|
||||
}
|
||||
|
||||
assert.Equal(t, http.MethodGet, entries[0]["method"])
|
||||
assert.Equal(t, "HTTP/1.1", entries[0]["proto"])
|
||||
}
|
||||
@@ -6,9 +6,13 @@ import (
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/http"
|
||||
"strings"
|
||||
"time"
|
||||
"unicode"
|
||||
"unicode/utf8"
|
||||
|
||||
basicauth "github.com/99designs/basicauth-go"
|
||||
"github.com/go-chi/chi"
|
||||
"github.com/go-chi/chi/middleware"
|
||||
"github.com/go-chi/cors"
|
||||
metrics "github.com/slok/go-http-metrics/metrics/prometheus"
|
||||
@@ -25,6 +29,71 @@ const (
|
||||
// corsMaxAge is the maximum time (in seconds) that a
|
||||
// preflight response can be cached.
|
||||
corsMaxAge = 300
|
||||
|
||||
// unmatchedRoute is logged in the access log's url field when a
|
||||
// redirected or rejected request matched no route pattern at
|
||||
// all. Every byte of such a path is client-chosen, so none of it
|
||||
// is logged.
|
||||
unmatchedRoute = "(unmatched)"
|
||||
|
||||
// redactedQuery stands in for the query string on the access log
|
||||
// branches that keep the concrete URL. The query is client-chosen
|
||||
// on every route, including the ones that answer an
|
||||
// unauthenticated 200, so logging it verbatim would let a client
|
||||
// pick the size of the line it writes.
|
||||
redactedQuery = "?(redacted)"
|
||||
|
||||
// maxLogFieldBytes bounds each access log field whose value the
|
||||
// client supplies outright: the URL, the User-Agent and the
|
||||
// Referer. The budget is spent in ENCODED bytes (see
|
||||
// truncateLogField), so 512 still holds a real browser's User-Agent
|
||||
// whole — those are plain ASCII, which encodes one byte for one —
|
||||
// while a value built from characters the encoder escapes keeps a
|
||||
// shorter prefix. That is the intended trade: 500 quotation marks
|
||||
// are not a debugging asset.
|
||||
maxLogFieldBytes = 512
|
||||
|
||||
// maxLogRequestIDBytes bounds the request id, which is also
|
||||
// client-supplied: chi's RequestID middleware passes an inbound
|
||||
// X-Request-Id header through verbatim. Its generated form is an
|
||||
// order of magnitude shorter than this.
|
||||
maxLogRequestIDBytes = 128
|
||||
|
||||
// maxLogMethodBytes bounds the method. Go accepts any RFC 7230
|
||||
// token there, bounded only by the header size limit, so it is
|
||||
// client-chosen text like the rest. The longest registered method
|
||||
// is half this.
|
||||
maxLogMethodBytes = 32
|
||||
|
||||
// truncationMarker is appended to any field the access log cut, so
|
||||
// a short value and a truncated one cannot be confused. It is
|
||||
// charged on top of the budget, not inside it.
|
||||
truncationMarker = "[truncated]"
|
||||
|
||||
// MaxAccessLogLineBytes is the ceiling on one JSON access log line,
|
||||
// and the number an operator multiplies by the request rate to size
|
||||
// log storage. It is not an observation of a sample: it is the sum
|
||||
// of the budgets above, each of which truncateLogField enforces in
|
||||
// ENCODED bytes, plus the part of the line no client can influence.
|
||||
//
|
||||
// url, useragent, referer 3*(512+11) = 1569
|
||||
// request_id 128+11 = 139
|
||||
// method 32+11 = 43
|
||||
// fixed portion = 336
|
||||
// ----
|
||||
// 2087
|
||||
//
|
||||
// The fixed portion is the JSON punctuation, the field names, the
|
||||
// level and the message, both timestamps at their longest, an IPv6
|
||||
// remoteIP with a zone, a three-digit status and a full-width int64
|
||||
// latency. Stated at 2560 so the figure carries headroom rather
|
||||
// than sitting on the arithmetic.
|
||||
//
|
||||
// The tty text handler in internal/logger is covered by the same
|
||||
// figure: encodedLogFieldBytes charges the worse of the two
|
||||
// handlers' escapes, and the text handler's fixed portion is the
|
||||
// smaller of the two.
|
||||
MaxAccessLogLineBytes = 2560
|
||||
)
|
||||
|
||||
//nolint:revive // MiddlewareParams is a standard fx naming convention.
|
||||
@@ -94,6 +163,161 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) {
|
||||
lrw.ResponseWriter.WriteHeader(code)
|
||||
}
|
||||
|
||||
// encodedLogFieldBytes is what r costs on the line once the log
|
||||
// handler has escaped it, taking the worse of the two handlers
|
||||
// internal/logger configures.
|
||||
//
|
||||
// slog's JSON handler escapes quote, backslash, newline, carriage
|
||||
// return and tab to two bytes each, and every other C0 control plus
|
||||
// LINE SEPARATOR and PARAGRAPH SEPARATOR to a six-byte \u escape. Its
|
||||
// text handler quotes with strconv.Quote, which spells any
|
||||
// non-printable rune the same six-byte way. Both pass printable runes
|
||||
// through as their own UTF-8, so unicode.IsPrint separates the two
|
||||
// cases for either handler. Go's header parser accepts quote,
|
||||
// backslash, tab and non-printable multi-byte runes in a header value,
|
||||
// so every one of these is reachable from a request.
|
||||
func encodedLogFieldBytes(r rune) int {
|
||||
const (
|
||||
// A backslash and the character itself.
|
||||
shortEscapeBytes = 2
|
||||
// \uXXXX, which is also the width of \u00XX.
|
||||
escapedRuneBytes = 6
|
||||
)
|
||||
|
||||
switch {
|
||||
case r == '"' || r == '\\' || r == '\n' || r == '\r' || r == '\t':
|
||||
return shortEscapeBytes
|
||||
case !unicode.IsPrint(r):
|
||||
return escapedRuneBytes
|
||||
default:
|
||||
return utf8.RuneLen(r)
|
||||
}
|
||||
}
|
||||
|
||||
// truncateLogField caps s at maxBytes of ENCODED output, marking the
|
||||
// value when it cuts.
|
||||
//
|
||||
// Budgeting raw bytes would not bound the line. Escaping only ever
|
||||
// grows a value, so a raw budget spent on characters the encoder
|
||||
// escapes buys a field several times its nominal size — and the line
|
||||
// is the thing an operator is told to multiply by their request rate.
|
||||
// Charging each rune what it will actually cost is what makes
|
||||
// MaxAccessLogLineBytes true rather than merely larger. The visible
|
||||
// consequence is that an escape-heavy value keeps a shorter prefix
|
||||
// than a plain one, which is the correct trade.
|
||||
//
|
||||
// The result is always valid UTF-8. A cut on a byte boundary can split
|
||||
// a multi-byte rune, and a header can carry bytes that were never
|
||||
// valid UTF-8 to begin with; both are dropped rather than kept, since
|
||||
// an encoder would otherwise spend six bytes replacing each one.
|
||||
func truncateLogField(s string, maxBytes int) string {
|
||||
// No rune encodes to fewer bytes than it occupies, so nothing past
|
||||
// maxBytes raw can fit the budget. Slicing first bounds the scan
|
||||
// below to the budget rather than to the size of the header the
|
||||
// client sent.
|
||||
window, cut := s, false
|
||||
if len(window) > maxBytes {
|
||||
window, cut = window[:maxBytes], true
|
||||
}
|
||||
|
||||
var (
|
||||
kept strings.Builder
|
||||
spent int
|
||||
)
|
||||
|
||||
for i := 0; i < len(window); {
|
||||
r, size := utf8.DecodeRuneInString(window[i:])
|
||||
if r == utf8.RuneError && size == 1 {
|
||||
i += size
|
||||
|
||||
continue
|
||||
}
|
||||
|
||||
cost := encodedLogFieldBytes(r)
|
||||
if spent+cost > maxBytes {
|
||||
cut = true
|
||||
|
||||
break
|
||||
}
|
||||
|
||||
spent += cost
|
||||
|
||||
kept.WriteString(window[i : i+size])
|
||||
|
||||
i += size
|
||||
}
|
||||
|
||||
if !cut {
|
||||
return kept.String()
|
||||
}
|
||||
|
||||
return kept.String() + truncationMarker
|
||||
}
|
||||
|
||||
// concreteLogURL renders the request's own URL for the access log
|
||||
// branches that keep it, with the query string replaced by a fixed
|
||||
// marker.
|
||||
//
|
||||
// The path on those branches is bounded by the service's routes or by
|
||||
// the operator's data — a 2xx on the receiver means the UUID named a
|
||||
// stored entrypoint, a 2xx under /s means the file is in the embedded
|
||||
// tree. The query is not bounded by anything: /.well-known/healthcheck
|
||||
// and /s/* take no authentication and sit behind no rate limiter, and
|
||||
// /pages/login behind only the login limiter, so any of them will
|
||||
// answer 200 to a URL carrying an arbitrary number of arbitrary bytes
|
||||
// after the '?'. Keeping the path and dropping the query is what makes
|
||||
// this branch as bounded as the pattern branches below.
|
||||
//
|
||||
// Nothing debuggable is lost. One route in the service reads a query
|
||||
// parameter at all — `page`, on the authenticated pagination links in
|
||||
// internal/handlers/source_management.go — and the alternatives that
|
||||
// would preserve more (a key count, a key allowlist) all require
|
||||
// parsing an attacker-sized query on every request, which is work an
|
||||
// unauthenticated client would then be choosing for us.
|
||||
func concreteLogURL(r *http.Request) string {
|
||||
path := r.URL.EscapedPath()
|
||||
|
||||
if r.URL.RawQuery == "" && !r.URL.ForceQuery {
|
||||
return path
|
||||
}
|
||||
|
||||
return path + redactedQuery
|
||||
}
|
||||
|
||||
// accessLogURL returns the value for the access log's url field.
|
||||
//
|
||||
// 2xx and 5xx responses get the concrete path (see concreteLogURL). A
|
||||
// success resolved against a static route or against the operator's
|
||||
// own data — on the receiver, a 2xx means the UUID named a stored
|
||||
// entrypoint — and a server error is our own bug, where the exact URL
|
||||
// is the primary evidence and which no client can provoke at will.
|
||||
//
|
||||
// 3xx and 4xx responses get the chi route pattern instead. Those are
|
||||
// the outcomes an unauthenticated client drives for free: 404 or 429
|
||||
// on any invented /webhook/ path, 303 to the login page on any
|
||||
// invented /user/ path. Logging the concrete URL there lets a flood
|
||||
// write attacker-chosen text, of attacker-chosen length, into the
|
||||
// operator's log at one line per request. The pattern comes from the
|
||||
// router's own table, so it is bounded by the service's routes while
|
||||
// still naming which class of request was rejected.
|
||||
//
|
||||
// The pattern is only populated once routing has run, so this must be
|
||||
// called after the handler returns, not before.
|
||||
func accessLogURL(r *http.Request, status int) string {
|
||||
if status < http.StatusMultipleChoices ||
|
||||
status >= http.StatusInternalServerError {
|
||||
return concreteLogURL(r)
|
||||
}
|
||||
|
||||
if rc := chi.RouteContext(r.Context()); rc != nil {
|
||||
if pattern := rc.RoutePattern(); pattern != "" {
|
||||
return pattern
|
||||
}
|
||||
}
|
||||
|
||||
return unmatchedRoute
|
||||
}
|
||||
|
||||
// Logging returns middleware that logs each HTTP request with
|
||||
// timing and metadata.
|
||||
func (s *Middleware) Logging() func(http.Handler) http.Handler {
|
||||
@@ -118,13 +342,27 @@ func (s *Middleware) Logging() func(http.Handler) http.Handler {
|
||||
}
|
||||
}
|
||||
|
||||
// Every field below that a client can influence is
|
||||
// truncated to a fixed budget, so the size of this
|
||||
// line does not track the size of the request.
|
||||
s.log.Info("http request",
|
||||
"request_start", start,
|
||||
"method", r.Method,
|
||||
"url", r.URL.String(),
|
||||
"useragent", r.UserAgent(),
|
||||
"request_id", requestID,
|
||||
"referer", r.Referer(),
|
||||
"method", truncateLogField(
|
||||
r.Method, maxLogMethodBytes,
|
||||
),
|
||||
"url", truncateLogField(
|
||||
accessLogURL(r, lrw.statusCode),
|
||||
maxLogFieldBytes,
|
||||
),
|
||||
"useragent", truncateLogField(
|
||||
r.UserAgent(), maxLogFieldBytes,
|
||||
),
|
||||
"request_id", truncateLogField(
|
||||
requestID, maxLogRequestIDBytes,
|
||||
),
|
||||
"referer", truncateLogField(
|
||||
r.Referer(), maxLogFieldBytes,
|
||||
),
|
||||
"proto", r.Proto,
|
||||
"remoteIP", ipFromHostPort(r.RemoteAddr),
|
||||
"status", lrw.statusCode,
|
||||
|
||||
Reference in New Issue
Block a user