Compare commits
1 Commits
74a57ad237
...
99968231ad
| Author | SHA1 | Date | |
|---|---|---|---|
| 99968231ad |
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