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