webhooker/internal/handlers/logbound_test.go

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,
	)
}