webhooker/internal/middleware/accesslog_test.go

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
	maxMethodBytes        = 32
	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
}

// capturingTextMiddleware is capturingMiddleware for the other handler
// internal/logger can select: slog's text handler, which
// internal/logger/logger.go installs when stderr is a tty. It escapes
// differently from the JSON one, so the line bound has to be asserted
// against both.
func capturingTextMiddleware(
	t *testing.T,
) (*middleware.Middleware, *bytes.Buffer) {
	t.Helper()

	buf := new(bytes.Buffer)
	log := slog.New(slog.NewTextHandler(
		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 access log line the service can be made to write.
	longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes)
	wantLongURL := longPath[:maxFieldBytes] + truncationSuffix

	// escapeChars are the runes Go's header parser accepts in a header
	// value and the log handler then escapes, 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, so every one of them
	// gets a case.
	//
	// The astral one is the case the JSON handler alone does not
	// reach: U+1000C 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. The JSON handler passes it through as
	// its four UTF-8 bytes, so only the text-handler shape of this
	// test holds the ten-byte charge honest.
	escapeChars := map[string]string{
		"quote":     `"`,
		"backslash": `\`,
		"tab":       "\t",
		"astral":    "\U0001000C",
	}

	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_LineSizeDoesNotTrackInputSizeOnTheTextHandler runs the
// same cases through slog's text handler, which internal/logger
// selects on a tty.
//
// MaxAccessLogLineBytes is quoted to operators unqualified, so it has
// to hold for whichever handler is installed — and the two do not
// escape alike. The astral case is the one that separates them: the
// JSON handler emits U+1000C as its four UTF-8 bytes, while
// strconv.Quote spells it \U0001000C at ten. Charging six for it, as
// this code did, put a real 2,676-byte line on the wire here while
// every JSON case stayed comfortably inside the bound.
//
// Only the size bound is asserted; the url field's contents are the
// JSON shape's business above.
func TestAccessLog_LineSizeDoesNotTrackInputSizeOnTheTextHandler(
	t *testing.T,
) {
	t.Parallel()

	for name, tc := range lineSizeCases() {
		t.Run(name, func(t *testing.T) {
			t.Parallel()

			m, buf := capturingTextMiddleware(t)
			router := accessLogRouter(m)

			assert.Equal(
				t,
				tc.wantStatus,
				getWithHeaders(t, router, tc.target, tc.headers),
			)

			line := strings.TrimSpace(buf.String())

			require.NotEmpty(t, line)
			assert.NotContains(
				t, line, "\n", "expected exactly one log line",
			)
			require.LessOrEqual(
				t, len(line), tc.bound,
				"access log line exceeded its bound",
			)
			assert.Contains(t, line, "url=")
			assert.NotContains(
				t, line, attackerMarker,
				"access log carried attacker-chosen text",
			)
			assert.NotContains(
				t, line, tailMarker,
				"access log carried an untruncated client field",
			)
		})
	}
}

// TestAccessLog_OversizedMethodIsTruncated covers the last term in the
// MaxAccessLogLineBytes arithmetic that the size cases above cannot
// reach: Go accepts any RFC 7230 token as a method, and getWithHeaders
// only ever sends GET.
func TestAccessLog_OversizedMethodIsTruncated(t *testing.T) {
	t.Parallel()

	m, buf := capturingMiddleware(t)
	router := accessLogRouter(m)

	method := strings.Repeat("M", oversizedSegmentBytes) + attackerMarker
	req := httptest.NewRequestWithContext(
		context.Background(), method, "/"+attackerMarker, nil,
	)
	rec := httptest.NewRecorder()
	router.ServeHTTP(rec, req)

	entries := accessLogEntriesWithin(t, buf, maxLineBytes)
	require.Len(t, entries, 1)
	assert.Equal(
		t,
		strings.Repeat("M", maxMethodBytes)+truncationSuffix,
		entries[0]["method"],
	)
	assert.NotContains(
		t, buf.String(), attackerMarker,
		"access log carried attacker-chosen text",
	)
}

// 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"])
}