webhooker/internal/middleware/recoverer_test.go

package middleware_test

import (
	"bytes"
	"encoding/json"
	"io"
	"log"
	"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/middleware"
)

// panicMarker is the panic value the probe handlers raise. The
// recoverer's whole job is to put this string, and not some second
// panic's, in front of an operator.
const panicMarker = "QQORIGINALPANICVALUEQQ"

// probeFuncName appears in the stack of every panic raised below,
// since that is the function raising it. Its presence is how these
// tests tell a real stack from an empty field.
const probeFuncName = "panicProbe"

// committedStatus is the status a handler sends before panicking in
// the already-committed case. It is deliberately not 200, so a test
// cannot pass on net/http's implicit default.
const committedStatus = http.StatusMultiStatus

// recovererProbe is a test server carrying one panicking route,
// behind the production recoverer.
type recovererProbe struct {
	server *httptest.Server

	// logs holds every record the middleware wrote.
	logs *bytes.Buffer

	// serverErrors holds everything net/http wrote to its own error
	// log. A working recoverer leaves it empty: net/http only reports
	// a request when a panic escapes the handler chain, which is the
	// failure this issue is about.
	serverErrors *bytes.Buffer
}

// newRecovererProbe stands up a real HTTP server — a real listener, a
// real connection, a real client — behind the production recoverer.
//
// A real server rather than an httptest.ResponseRecorder, because a
// recorder cannot express the outcome that made this a defect: chi's
// Recoverer left net/http to close the connection, which a recorder
// records as an ordinary unwritten response while a client sees EOF.
// The status a client actually receives is only observable over a
// socket.
func newRecovererProbe(
	t *testing.T,
	textHandler bool,
	handler http.HandlerFunc,
) *recovererProbe {
	t.Helper()

	newMiddleware := capturingMiddleware
	if textHandler {
		newMiddleware = capturingTextMiddleware
	}

	m, logs := newMiddleware(t)

	router := chi.NewRouter()
	// The registration order the production router uses: RequestID
	// outside so the recoverer's record can name the request,
	// Logging outside so the recovered 500 is the status it records.
	router.Use(chimw.RequestID)
	router.Use(m.Logging())
	router.Use(m.Recoverer())
	router.Get("/probe", handler)

	serverErrors := new(bytes.Buffer)

	server := httptest.NewUnstartedServer(router)
	server.Config.ErrorLog = log.New(serverErrors, "", 0)
	server.Start()
	t.Cleanup(server.Close)

	return &recovererProbe{
		server:       server,
		logs:         logs,
		serverErrors: serverErrors,
	}
}

// get drives one request at the probe route and returns the response,
// or the transport error if the connection was dropped instead.
func (p *recovererProbe) get(t *testing.T) (*http.Response, error) {
	t.Helper()

	return p.getWithRequestID(t, "")
}

// getWithRequestID drives the same request carrying a client-supplied
// X-Request-Id. chi's RequestID middleware adopts that header verbatim
// when it is present and only generates a value when it is absent, so
// this is the third growable field on the panic record and the only
// one a client fills outright.
func (p *recovererProbe) getWithRequestID(
	t *testing.T,
	requestID string,
) (*http.Response, error) {
	t.Helper()

	req, err := http.NewRequestWithContext(
		t.Context(), http.MethodGet, p.server.URL+"/probe", nil,
	)
	require.NoError(t, err)

	if requestID != "" {
		req.Header.Set(chimw.RequestIDHeader, requestID)
	}

	return p.server.Client().Do(req)
}

// wait shuts the server down and blocks until every in-flight request
// has finished, which is what makes the log buffer safe to read.
//
// A client returns as soon as the response is complete — or, for a
// deliberately aborted connection, as soon as it is closed — while the
// access log line for the same request is still being written on the
// server goroutine. It is idempotent, so a test may call it directly
// before reading the buffer itself.
func (p *recovererProbe) wait() {
	p.server.Close()
}

// records decodes every JSON log line the probe captured.
func (p *recovererProbe) records(t *testing.T) []map[string]any {
	t.Helper()

	p.wait()

	var out []map[string]any

	for line := range strings.SplitSeq(
		strings.TrimSpace(p.logs.String()), "\n",
	) {
		if line == "" {
			continue
		}

		record := map[string]any{}
		require.NoError(t, json.Unmarshal([]byte(line), &record))

		out = append(out, record)
	}

	return out
}

// panicRecord returns the single "handler panic" record, failing if
// there is not exactly one.
func (p *recovererProbe) panicRecord(t *testing.T) map[string]any {
	t.Helper()

	var found []map[string]any

	for _, record := range p.records(t) {
		if record["msg"] == "handler panic" {
			found = append(found, record)
		}
	}

	require.Len(
		t, found, 1,
		"exactly one panic record expected, log was:\n%s",
		p.logs.String(),
	)

	return found[0]
}

// panicProbe panics with the marker. It is a named function so the
// stack assertions have something to look for.
func panicProbe(http.ResponseWriter, *http.Request) {
	panic(panicMarker)
}

func TestRecovererAnswers500AndLogsTheOriginalPanic(t *testing.T) {
	t.Parallel()

	probe := newRecovererProbe(t, false, panicProbe)

	resp, err := probe.get(t)
	require.NoError(
		t, err,
		"a panicking handler must answer, not drop the connection",
	)

	defer func() { _ = resp.Body.Close() }()

	body, err := io.ReadAll(resp.Body)
	require.NoError(t, err)

	assert.Equal(t, http.StatusInternalServerError, resp.StatusCode)
	assert.Contains(t, string(body), "Internal Server Error")

	record := probe.panicRecord(t)
	assert.Equal(t, "ERROR", record["level"])
	assert.Equal(t, panicMarker, record["panic"])
	assert.Equal(t, false, record["response_committed"])

	stack, ok := record["stack"].(string)
	require.True(t, ok, "the record must carry a stack")
	assert.Contains(
		t, stack, probeFuncName,
		"the stack must reach the function that panicked",
	)
	assert.NotContains(
		t, stack, "slice bounds out of range",
		"a secondary panic must not have occurred",
	)

	assert.Empty(
		t, probe.serverErrors.String(),
		"net/http must not have had to report anything",
	)
}

// TestRecovererStatusReachesTheAccessLog pins the placement. The
// recoverer runs inside the logging middleware precisely so the status
// it writes is the one the access log records; registered outside it,
// as chi's Recoverer was, the same request is logged as a 200 that the
// client never received.
func TestRecovererStatusReachesTheAccessLog(t *testing.T) {
	t.Parallel()

	probe := newRecovererProbe(t, false, panicProbe)

	resp, err := probe.get(t)
	require.NoError(t, err)
	require.NoError(t, resp.Body.Close())
	require.Equal(t, http.StatusInternalServerError, resp.StatusCode)

	var access map[string]any

	for _, record := range probe.records(t) {
		if record["msg"] == "http request" {
			access = record
		}
	}

	require.NotNil(t, access, "the request must still be logged")
	assert.EqualValues(
		t, http.StatusInternalServerError, access["status"],
		"the access log must record the status the client got",
	)

	// The panic record identifies its request by request_id alone,
	// so that join has to work.
	assert.Equal(
		t, access["request_id"],
		probe.panicRecord(t)["request_id"],
	)
	assert.NotEmpty(t, access["request_id"])
}

// TestRecovererRepanicsErrAbortHandler covers the one panic value that
// must not be turned into a 500. net/http documents it as the way a
// handler abandons a connection deliberately and special-cases it,
// suppressing both the response and its own stack report.
func TestRecovererRepanicsErrAbortHandler(t *testing.T) {
	t.Parallel()

	probe := newRecovererProbe(
		t, false,
		func(http.ResponseWriter, *http.Request) {
			panic(http.ErrAbortHandler)
		},
	)

	resp, err := probe.get(t)
	if err == nil {
		_ = resp.Body.Close()
	}

	require.Error(
		t, err,
		"an aborted handler must not answer with a status",
	)

	for _, record := range probe.records(t) {
		assert.NotEqual(
			t, "handler panic", record["msg"],
			"a deliberate abort is not a fault to report",
		)
	}

	assert.Empty(
		t, probe.serverErrors.String(),
		"net/http suppresses ErrAbortHandler; it must still see it",
	)
}

// TestRecovererKeepsAnAlreadyCommittedResponse covers a handler that
// panics after sending its status. The bytes are already on the wire,
// so a second WriteHeader would change nothing the client sees and
// would draw net/http's "superfluous response.WriteHeader" report.
func TestRecovererKeepsAnAlreadyCommittedResponse(t *testing.T) {
	t.Parallel()

	probe := newRecovererProbe(
		t, false,
		func(w http.ResponseWriter, _ *http.Request) {
			w.WriteHeader(committedStatus)
			_, _ = w.Write([]byte("partial"))

			panic(panicMarker)
		},
	)

	resp, err := probe.get(t)
	require.NoError(t, err)

	defer func() { _ = resp.Body.Close() }()

	body, err := io.ReadAll(resp.Body)
	require.NoError(t, err)

	assert.Equal(t, committedStatus, resp.StatusCode)
	assert.Equal(t, "partial", string(body))

	record := probe.panicRecord(t)
	assert.Equal(t, panicMarker, record["panic"])
	assert.Equal(
		t, true, record["response_committed"],
		"the record must say why no 500 was sent",
	)

	assert.NotContains(
		t, probe.serverErrors.String(),
		"superfluous response.WriteHeader",
	)
}

// TestRecovererKeepsAnImplicitlyCommittedResponse is the same case
// without an explicit WriteHeader: a bare Write commits the response
// to 200 just as surely.
func TestRecovererKeepsAnImplicitlyCommittedResponse(t *testing.T) {
	t.Parallel()

	probe := newRecovererProbe(
		t, false,
		func(w http.ResponseWriter, _ *http.Request) {
			_, _ = w.Write([]byte("partial"))

			panic(panicMarker)
		},
	)

	resp, err := probe.get(t)
	require.NoError(t, err)
	require.NoError(t, resp.Body.Close())

	assert.Equal(t, http.StatusOK, resp.StatusCode)
	assert.Equal(
		t, true, probe.panicRecord(t)["response_committed"],
	)
	assert.NotContains(
		t, probe.serverErrors.String(),
		"superfluous response.WriteHeader",
	)
}

// panicLogHandler names one of the two handlers internal/logger can
// install. The recoverer's probe selects between them with a bool
// rather than by constructing one, which is why this does not reuse
// logHandlers() the way the fills reuse escapeFills().
type panicLogHandler struct {
	name string
	text bool
}

func panicLogHandlers() []panicLogHandler {
	return []panicLogHandler{{"json", false}, {"text", true}}
}

// TestRecovererBoundsThePanicRecord holds the record to its stated
// ceiling with a panic value the size of a request. A handler is free
// to build a panic value out of what the client sent, so the value is
// charged a client-sized budget even though the stack is not.
func TestRecovererBoundsThePanicRecord(t *testing.T) {
	t.Parallel()

	for _, handler := range panicLogHandlers() {
		// The fills are internal/middleware's own access log fills,
		// shared rather than restated: plain text, the characters
		// both handlers escape to two bytes, a bare C0 control, and
		// an astral non-printable the text handler spells with a
		// ten-byte \U escape.
		for fillName, fillRune := range escapeFills() {
			t.Run(handler.name+"/"+fillName, func(t *testing.T) {
				t.Parallel()

				value := strings.Repeat(
					fillRune, oversizedSegmentBytes,
				) + tailMarker

				probe := newRecovererProbe(
					t, handler.text,
					func(http.ResponseWriter, *http.Request) {
						panic(value)
					},
				)

				resp, err := probe.get(t)
				require.NoError(t, err)
				require.NoError(t, resp.Body.Close())
				require.Equal(
					t, http.StatusInternalServerError,
					resp.StatusCode,
				)
				probe.wait()

				for line := range strings.SplitSeq(
					strings.TrimSpace(probe.logs.String()), "\n",
				) {
					assert.LessOrEqual(
						t, len(line),
						middleware.MaxPanicLogLineBytes,
						"log line exceeded its stated bound",
					)
					assert.NotContains(
						t, line, tailMarker,
						"the far end of the panic value reached "+
							"the log, so nothing truncated it",
					)
				}
			})
		}
	}
}

// deepPanic recurses to depth and then panics, so the stack itself
// overruns its budget. It is the only way to exercise the stack cut:
// the shipped middleware chain does not come close (see
// TestPanicThroughProductionRouter in internal/server).
func deepPanic(depth int, value string) int {
	if depth == 0 {
		panic(value)
	}

	return deepPanic(depth-1, value) + 1
}

// assertEveryFieldWasCut holds each of the record's three growable
// fields to its own budget, which is what the ceiling is the sum of.
// The stack is cut at its far end, so its near end — the panic site —
// has to survive; the request id is the client's own bytes, so its
// cut is the one that bounds an attacker rather than our own call
// depth.
func assertEveryFieldWasCut(t *testing.T, record map[string]any) {
	t.Helper()

	stack, ok := record["stack"].(string)
	require.True(t, ok)
	assert.True(
		t, strings.HasSuffix(stack, truncationSuffix),
		"an oversized stack must be marked as cut",
	)
	assert.Contains(
		t, stack, "deepPanic",
		"the near end of the stack must survive the cut",
	)
	assert.NotContains(
		t, stack, "net/http.(*conn).serve",
		"the far end is what a cut discards",
	)

	id, ok := record["request_id"].(string)
	require.True(t, ok)
	assert.True(
		t, strings.HasSuffix(id, truncationSuffix),
		"an oversized request id must be marked as cut",
	)
	assert.LessOrEqual(
		t, len(id), maxRequestIDBytes+len(truncationSuffix),
		"the request id must be held to its own budget",
	)

	value, ok := record["panic"].(string)
	require.True(t, ok)
	assert.True(
		t, strings.HasSuffix(value, truncationSuffix),
		"an oversized panic value must be marked as cut",
	)
}

// TestRecovererBoundsTheStack drives every growable field on the
// record past its budget at once — an oversized stack, an oversized
// panic value and an oversized client-supplied X-Request-Id — over
// both log handlers. It holds that line to the stated ceiling and
// reports what it measured, and it pins that a cut stack keeps its
// near end — the panic site — rather than its far one.
//
// The two fields the test picks the content of — the panic value and
// the request id — are filled with the quotation mark. Both handlers
// escape it to two bytes, which is exactly what logfield charges for
// it, so each of those fields emits every byte of its budget; no fill
// emits more, since logfield charges each rune the wider of the two
// handlers and a field can therefore never emit more than it spent.
// The stack is not a fill: recursion drives it past its budget and
// the cut lands wherever its own content puts it, which is why the
// measured widths move by a byte between runs.
func TestRecovererBoundsTheStack(t *testing.T) {
	t.Parallel()

	for _, handler := range panicLogHandlers() {
		t.Run(handler.name, func(t *testing.T) {
			t.Parallel()

			value := strings.Repeat(`"`, oversizedSegmentBytes) +
				tailMarker
			requestID := strings.Repeat(`"`, oversizedSegmentBytes) +
				tailMarker

			probe := newRecovererProbe(
				t, handler.text,
				func(http.ResponseWriter, *http.Request) {
					_ = deepPanic(512, value)
				},
			)

			resp, err := probe.getWithRequestID(t, requestID)
			require.NoError(t, err)
			require.NoError(t, resp.Body.Close())
			require.Equal(
				t, http.StatusInternalServerError, resp.StatusCode,
			)
			probe.wait()

			// The text handler does not emit JSON, so the field-level
			// assertions run on the JSON one; the line bound below
			// is asserted on both, which is the point of the sweep.
			if !handler.text {
				assertEveryFieldWasCut(t, probe.panicRecord(t))
			}

			widest := 0

			for line := range strings.SplitSeq(
				strings.TrimSpace(probe.logs.String()), "\n",
			) {
				assert.LessOrEqual(
					t, len(line), middleware.MaxPanicLogLineBytes,
				)
				assert.NotContains(t, line, tailMarker)

				widest = max(widest, len(line))
			}

			t.Logf(
				"widest line measured: %d bytes (ceiling %d)",
				widest, middleware.MaxPanicLogLineBytes,
			)
		})
	}
}

// TestRecovererIgnoresANonPanickingHandler is the negative control:
// the middleware must be inert on the ordinary path.
func TestRecovererIgnoresANonPanickingHandler(t *testing.T) {
	t.Parallel()

	probe := newRecovererProbe(
		t, false,
		func(w http.ResponseWriter, _ *http.Request) {
			w.WriteHeader(http.StatusTeapot)
		},
	)

	resp, err := probe.get(t)
	require.NoError(t, err)
	require.NoError(t, resp.Body.Close())

	assert.Equal(t, http.StatusTeapot, resp.StatusCode)

	for _, record := range probe.records(t) {
		assert.NotEqual(t, "handler panic", record["msg"])
	}
}

// TestRecovererKeepsResponseControllerWorking pins the Unwrap method.
// The middleware wraps the ResponseWriter to learn whether the
// response was committed, and a wrapper without Unwrap hides
// net/http's own writer from http.ResponseController, so a handler
// that flushes or sets a deadline starts failing.
//
// The recoverer is the only middleware in the chain here. The access
// logger's own wrapper does not implement Unwrap, so a chain
// containing it fails this regardless of what the recoverer does;
// what is being pinned is that the recoverer adds no such opacity of
// its own.
func TestRecovererKeepsResponseControllerWorking(t *testing.T) {
	t.Parallel()

	m, _ := capturingMiddleware(t)

	handler := m.Recoverer()(http.HandlerFunc(
		func(w http.ResponseWriter, _ *http.Request) {
			_, _ = w.Write([]byte("chunk"))

			flushErr := http.NewResponseController(w).Flush()
			if flushErr != nil {
				http.Error(
					w, "flush failed",
					http.StatusInternalServerError,
				)

				return
			}
		},
	))

	server := httptest.NewServer(handler)
	t.Cleanup(server.Close)

	req, err := http.NewRequestWithContext(
		t.Context(), http.MethodGet, server.URL, nil,
	)
	require.NoError(t, err)

	resp, err := server.Client().Do(req)
	require.NoError(t, err)

	defer func() { _ = resp.Body.Close() }()

	body, err := io.ReadAll(resp.Body)
	require.NoError(t, err)

	assert.Equal(t, http.StatusOK, resp.StatusCode)
	assert.Equal(t, "chunk", string(body))
}