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() req, err := http.NewRequestWithContext( t.Context(), http.MethodGet, p.server.URL+"/probe", nil, ) require.NoError(t, err) 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 } // TestRecovererBoundsTheStack drives the widest record the recoverer // can be made to write: an oversized stack and an oversized panic // value on the same record, 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. func TestRecovererBoundsTheStack(t *testing.T) { t.Parallel() for _, handler := range panicLogHandlers() { t.Run(handler.name, func(t *testing.T) { t.Parallel() // The escape-heavy fill is the expensive one: every rune // costs two encoded bytes, so a budget counted raw would // buy twice the field. value := strings.Repeat(`"`, oversizedSegmentBytes) + tailMarker probe := newRecovererProbe( t, handler.text, func(http.ResponseWriter, *http.Request) { _ = deepPanic(512, 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() // 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 { stack, ok := probe.panicRecord(t)["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", ) } 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)) }