diff --git a/README.md b/README.md index 4e8e972..323e830 100644 --- a/README.md +++ b/README.md @@ -1144,10 +1144,10 @@ including cases built from the characters the handlers escape, and against the widest access log line the service can be made to write: a 5xx that keeps its concrete path while all three header fields are also at their budget. Every case runs through both handlers -`internal/logger` can select — the JSON one and the text one it -installs on a tty — since the -two do not escape alike and the ceiling is quoted unqualified. Measured -over a real connection, the widest line is 1,972 bytes. +`internal/logger` can select — the JSON one and the text one it installs +on a tty — since the two do not escape alike and the ceiling is quoted +unqualified. Measured over a real connection, the widest access log line +is 1,972 bytes. Multiply that ceiling by the request rate to size log storage. Note that the rate is not bounded by the limits above on every route: @@ -1155,10 +1155,12 @@ that the rate is not bounded by the limits above on every route: the multiplier is whatever the deployment will serve. **The same ceiling covers every other line the service writes through -`slog` that carries text an unauthenticated client supplies.** The -access log is not the only line a client can put its own text into, and -a budget that held for one line and not the others would be worse than -no stated budget at all. Every `slog` call an unauthenticated request +`slog` that carries text an unauthenticated client supplies**, with one +exception stated below it: the recovered-panic record, which spends the +same per-field budgets but has its own wider ceiling. The access log is +not the only line a client can put its own text into, and a budget that +held for one line and not the others would be worse than no stated +budget at all. Every `slog` call an unauthenticated request can reach spends the same per-field budget through `internal/logfield`, and each carries strictly fewer client-supplied fields than the access log does, so none of them can be wider than it: @@ -1280,23 +1282,46 @@ read as more than it is: `internal/logger` calls `slog.SetDefault`, which redirects that logger into whichever handler it installed. Those lines therefore arrive on standard output, shaped like every other line, at `INFO`. They are not - truncated and they are not bounded by the ceiling: a handler panic - arrives as one record carrying a whole goroutine stack, above the - ceiling's 2,560 bytes — measured at roughly 2,770 in one checkout. The - exact width is not an invariant, since it moves with the goroutine - number and with the source paths baked into the stack; that it exceeds - the ceiling does not move. The value is the runtime's, not a client's. -- **A handler panic reaches that path** rather than the one it looks - like it should. `internal/server/routes.go` installs chi's - `middleware.Recoverer` in front of every route, which is meant to - print the panic and its stack to standard error and answer 500. On the - Go version this service builds against it does neither: chi v1.5.5's - stack pretty-printer looks for a `panic(0x` frame that the runtime no - longer emits, walks past the end of its own slice, and panics before - writing a byte. That second panic escapes to `net/http`, which drops - the connection and reports it through the nil `ErrorLog` above. - Tracked separately in - . + truncated. A handler panic is no longer one of them: the recover + middleware below answers it and writes it as the bounded record + described there instead, and `internal/server/recoverer_test.go` + requires that `http: panic serving` appear in neither of the process's + two streams when a panic is driven through the production router. The + one panic still handed back to `net/http` is `http.ErrAbortHandler`, + which it special-cases and does not log at all. What is left on this + path is `net/http`'s own diagnostics, whose values are the runtime's, + not a client's. + +Wider than that 2,560-byte ceiling, and stated separately rather than +carved out of it: the record a recovered panic produces. The recover +middleware in `internal/middleware` answers `500` and writes one `ERROR` +record through `internal/logger` carrying the panic value, the stack and +the request id — the same `request_id` the access log line for that +request carries, which is how the two are joined. It replaced chi's +`middleware.Recoverer`, which on a current Go release crashed inside its +own stack pretty-printer: the connection was dropped rather than +answered, and what reached the operator described that crash rather than +the fault behind it. + +That record is bounded the same way, in the same encoded bytes and +through the same `internal/logfield` budget: 512 for the panic value, +because a handler is free to build one out of the request, and 8,192 for +the stack, cut at its far end so that the panic site survives a cut and +`net/http`'s accept frames are what is lost. Net: **at most 10,240 +bytes, once per recovered panic** — 9,121 by the arithmetic (523 + 8,203 ++ 139 + a 256-byte fixed portion), stated at 10,240 for headroom. +`internal/middleware/recoverer_test.go` measures 8,898 bytes with the +stack and the panic value both driven past their budgets, over both +handlers; that figure carries no source paths and reproduces across +checkouts. The real case is far below it: through the shipped middleware +chain the whole record measures roughly 3,960 bytes over a roughly +3,690-byte stack, taken by `internal/server/recoverer_test.go` from the +process's own file descriptors while driving a panic through the +production router over a real server in a subprocess. That pair is +**not** an invariant — `debug.Stack()` embeds absolute source paths, so +it moves with where the tree is checked out, and three checkouts have +reported 3,959, 3,961 and 4,026. What the tests assert is the ceiling +and that the stack arrived uncut, never the number. Every limiter here — receiver, login, and password change — identifies the client the same way, through one shared key function: the @@ -1635,19 +1660,32 @@ to record results. Applied to all routes in this order: -1. **Recoverer** — Panic recovery (chi built-in) -2. **RequestID** — Generate unique request IDs (chi built-in) -3. **SecurityHeaders** — Production security headers on every response +1. **RequestID** — Generate unique request IDs (chi built-in) +2. **SecurityHeaders** — Production security headers on every response (HSTS, X-Content-Type-Options, X-Frame-Options, CSP, Referrer-Policy, Permissions-Policy) -4. **Logging** — Structured request logging (method, URL, status, +3. **Logging** — Structured request logging (method, URL, status, latency, remote IP, user agent, request ID) -5. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set) -6. **CORS** — Cross-origin resource sharing headers -7. **Timeout** — 60-second request timeout +4. **Metrics** — Prometheus HTTP metrics (if `METRICS_USERNAME` is set) +5. **CORS** — Cross-origin resource sharing headers +6. **Timeout** — 60-second request timeout +7. **Recoverer** — Panic recovery: one `ERROR` record through + `internal/logger` and a `500` 8. **Sentry** — Error reporting to Sentry (if `SENTRY_DSN` is set; configured with `Repanic: true` so panics still reach Recoverer) +Recoverer sits seventh rather than first, and both neighbours are the +reason. It runs **inside** everything that observes the response, so +the `500` it writes for a panicking handler is the status the access +log records and the metrics count; registered first, as chi's own +`middleware.Recoverer` was, the same request was logged as a `200` that +the client never received. It runs **outside** the Sentry handler, so +`Repanic: true` has something to re-raise into: an operator with +`SENTRY_DSN` set keeps the report, and one without it now gets the +local record instead of nothing. What that placement gives up is +recovery of a panic in the six entries above it, none of which does +more than set a header or start a timer. + Additionally, form endpoints (`/pages`, `/user/*`, `/sources`, `/source/*`) apply a **MaxBodySize** middleware that limits POST/PUT/PATCH request bodies to 1 MB. It is registered ahead of the diff --git a/internal/middleware/accesslog_test.go b/internal/middleware/accesslog_test.go index 6c8d9fc..337e096 100644 --- a/internal/middleware/accesslog_test.go +++ b/internal/middleware/accesslog_test.go @@ -376,7 +376,7 @@ func lineSizeCases() map[string]sizeCase { // 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 line the service can be made to write. + // the widest access log line the service can be made to write. longPath := "/boom/" + strings.Repeat("x", oversizedSegmentBytes) wantLongURL := longPath[:maxFieldBytes] + truncationSuffix diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index dcc944e..565a663 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -133,16 +133,12 @@ const ( // - The "log" delivery target, which exists to write the whole // inbound event to the log. Deliberate; see // internal/delivery/target_log.go. - // - The widest line the service can write, which is neither an - // access log line nor client-chosen. A handler panic arrives - // through net/http's nil ErrorLog as one record carrying a - // whole goroutine stack, above this figure — measured at - // roughly 2,770 bytes. The exact width is not an invariant: it - // moves with the goroutine number and with the source paths - // baked into the stack. That it exceeds this ceiling does not - // move. The value is the runtime's, not a client's; see - // README.md and - // https://git.eeqj.de/sneak/webhooker/issues/187. + // - The record a recovered panic writes, which is neither an + // access log line nor client-chosen: it carries a whole + // goroutine stack and is wider than this figure. It has its + // own stated ceiling, MaxPanicLogLineBytes in recoverer.go, + // and is written once per recovered panic rather than once + // per request. MaxAccessLogLineBytes = 2560 ) diff --git a/internal/middleware/recoverer.go b/internal/middleware/recoverer.go new file mode 100644 index 0000000..36420b2 --- /dev/null +++ b/internal/middleware/recoverer.go @@ -0,0 +1,203 @@ +package middleware + +import ( + "errors" + "fmt" + "net/http" + "runtime/debug" + + "github.com/go-chi/chi/middleware" + "sneak.berlin/go/webhooker/internal/logfield" +) + +const ( + // maxPanicValueBytes bounds the recovered panic value. The value + // is our own text, but a handler is free to build one out of the + // request — panic(fmt.Sprintf("bad %q", r.URL.Path)) — so it is + // charged the same budget the access log gives a field the + // client supplies outright. + maxPanicValueBytes = logfield.MaxBytes + + // maxPanicStackBytes bounds the stack, in the same ENCODED bytes + // logfield.Truncate charges everywhere else. Nothing a client + // sends chooses the depth of our own call stack, so this is not + // a safety limit; it is what makes MaxPanicLogLineBytes an + // arithmetic ceiling rather than an observation. A stack is cut + // at its far end, which is net/http's accept frames — the panic + // site and the handler that reached it are at the near end and + // are always kept. + // + // For scale: a handler panicking under the full shipped + // middleware chain produces a stack of roughly 3,690 bytes in a + // record of roughly 3,960, so this budget holds better than + // twice the depth that case reaches. Neither number is an + // invariant — debug.Stack() embeds absolute source paths, so + // both move with where the tree sits, and three checkouts have + // reported records of 3,959, 3,961 and 4,026 bytes. + // internal/server's TestPanicThroughProductionRouter asserts the + // ceiling and that the stack arrived uncut, not the figures. + maxPanicStackBytes = 8192 + + // MaxPanicLogLineBytes is the ceiling on the single line a + // recovered panic writes. It is wider than + // MaxAccessLogLineBytes, which bounds a line written once per + // request, where this one is written once per recovered panic. + // + // panic 512+11 = 523 + // stack 8192+11 = 8203 + // request_id 128+11 = 139 + // fixed portion = 256 + // ---- + // 9121 + // + // The fixed portion is the JSON punctuation, the field names, + // the level, the message, the timestamp at its longest and the + // response_committed boolean. + // + // Stated at 10240 so the figure carries headroom rather than + // sitting on the arithmetic, exactly as MaxAccessLogLineBytes + // is. Both handlers internal/logger can install are covered, for + // the reason given there: logfield.EncodedBytes charges every + // rune the wider of the two. + // + // Measured, the widest line either handler produces with both + // the stack and the panic value driven past their budgets is + // 8,898 bytes (TestRecovererBoundsTheStack). That figure carries + // no source paths and reproduces across checkouts. + MaxPanicLogLineBytes = 10240 +) + +// recoverResponseWriter records whether the response has been +// committed, which is the one thing the recoverer cannot learn from +// the panic itself: a handler that panics after writing a status has +// already spent the response, and a second WriteHeader would only +// draw net/http's "superfluous response.WriteHeader" complaint +// without changing what the client received. +type recoverResponseWriter struct { + http.ResponseWriter + + committed bool +} + +func (w *recoverResponseWriter) WriteHeader(code int) { + w.committed = true + + w.ResponseWriter.WriteHeader(code) +} + +func (w *recoverResponseWriter) Write(b []byte) (int, error) { + // An unheralded Write commits the response just as surely as + // WriteHeader does: net/http sends 200 in front of it. + w.committed = true + + //nolint:wrapcheck // Pass the writer's own error through unchanged. + return w.ResponseWriter.Write(b) +} + +// Unwrap lets http.ResponseController reach the writer underneath, so +// a handler can still flush or set a write deadline through this +// wrapper. +func (w *recoverResponseWriter) Unwrap() http.ResponseWriter { + return w.ResponseWriter +} + +// Recoverer returns middleware that turns a handler panic into one +// structured ERROR record and a 500, rather than a dropped +// connection. +// +// It replaces chi's middleware.Recoverer, which does neither on a +// current Go release. chi v1.5.5's pretty-printer scans the stack for +// a frame beginning "panic(0x", which the runtime has not emitted +// since it started printing "panic({0x...}"; the scan therefore never +// terminates early, every line reaches decorateFuncCallLine, and that +// function slices pkg[strings.Index(pkg, "."):] without checking for +// -1. The resulting second panic escapes chi's own deferred function, +// so its WriteHeader(500) never runs and net/http closes the +// connection reporting its own crash instead of the original one. +// See https://git.eeqj.de/sneak/webhooker/issues/187. +// +// chi v5.3.1 has since fixed both halves of that — it scans for +// "panic(" and guards the index — so upgrading would restore the 500. +// It would not give what this does: v5 still writes an ANSI-coloured +// pretty stack straight to os.Stderr, outside internal/logger, outside +// any budget, at no level the operator set. +// +// Where this sits in the chain is load-bearing, and routes.go states +// it: inside everything that observes the response, so the 500 is +// what the access log records and the metrics count, and outside the +// sentryhttp handler, whose Repanic option depends on something +// further out recovering what it re-raises. +func (s *Middleware) Recoverer() func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func( + w http.ResponseWriter, + r *http.Request, + ) { + rw := &recoverResponseWriter{ResponseWriter: w} + + defer func() { + rvr := recover() + if rvr == nil { + return + } + + // http.ErrAbortHandler is a handler stating that it + // is abandoning the connection on purpose, not a + // fault. net/http special-cases it, suppressing both + // the stack trace and any response, so it is passed + // straight back out rather than logged and answered. + err, isError := rvr.(error) + if isError && + errors.Is(err, http.ErrAbortHandler) { + panic(rvr) + } + + s.logPanic(r, rvr, rw.committed) + + if rw.committed { + return + } + + http.Error( + rw, + http.StatusText( + http.StatusInternalServerError, + ), + http.StatusInternalServerError, + ) + }() + + next.ServeHTTP(rw, r) + }) + } +} + +// logPanic writes the record. Every field it can grow is truncated to +// a fixed budget, so MaxPanicLogLineBytes holds. +// +// The request is identified by request_id alone rather than by +// repeating the method, URL and address: the access log line for the +// same request carries all of those, already bounded, and — because +// the recoverer runs inside the logging middleware — now carries the +// 500 as its status too. Repeating them here would double those +// budgets against a line already wider than the access log's ceiling, +// to say a second time what one join already says. +func (s *Middleware) logPanic( + r *http.Request, + rvr any, + committed bool, +) { + s.log.Error("handler panic", + "panic", logfield.Truncate( + fmt.Sprint(rvr), maxPanicValueBytes, + ), + "stack", logfield.Truncate( + string(debug.Stack()), maxPanicStackBytes, + ), + "request_id", logfield.Truncate( + middleware.GetReqID(r.Context()), + maxLogRequestIDBytes, + ), + "response_committed", committed, + ) +} diff --git a/internal/middleware/recoverer_test.go b/internal/middleware/recoverer_test.go new file mode 100644 index 0000000..fba0aab --- /dev/null +++ b/internal/middleware/recoverer_test.go @@ -0,0 +1,588 @@ +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)) +} diff --git a/internal/server/export_test.go b/internal/server/export_test.go index 2118a1d..d5b05be 100644 --- a/internal/server/export_test.go +++ b/internal/server/export_test.go @@ -54,3 +54,40 @@ func NewRouterForTest( return s.router } + +// ProbePattern is the route NewRouterWithProbeForTest adds to the +// production route tree. +const ProbePattern = "/probe" + +// NewRouterWithProbeForTest builds the production route tree exactly +// as NewRouterForTest does and then registers probe at ProbePattern, +// so a test can drive a handler that panics through the shipped +// global middleware chain rather than a hand-assembled one. Nothing +// about the chain is rebuilt here: the probe is an extra leaf under +// the same Use() registrations every other route gets. +// +// sentryEnabled selects whether the sentryhttp handler is registered, +// which in production a configured SENTRY_DSN decides. It is a +// parameter because the relationship between that handler's Repanic +// option and the recoverer registered outside it is the thing a test +// has to be able to pin. +func NewRouterWithProbeForTest( + log *slog.Logger, + cfg *config.Config, + mw *middleware.Middleware, + h *handlers.Handlers, + sentryEnabled bool, + probe http.HandlerFunc, +) http.Handler { + s := &Server{ + log: log, + mw: mw, + h: h, + params: ServerParams{Config: cfg}, + sentryEnabled: sentryEnabled, + } + s.SetupRoutes() + s.router.Handle(ProbePattern, probe) + + return s.router +} diff --git a/internal/server/recoverer_test.go b/internal/server/recoverer_test.go new file mode 100644 index 0000000..25a90f0 --- /dev/null +++ b/internal/server/recoverer_test.go @@ -0,0 +1,285 @@ +package server_test + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "net/http" + "net/http/httptest" + "os" + "os/exec" + "strings" + "testing" + + "github.com/getsentry/sentry-go" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/middleware" + "sneak.berlin/go/webhooker/internal/server" +) + +// panicProbeMarker is the value the probe handler panics with. The +// defect this pins lost it entirely: what reached the operator was the +// recoverer's own secondary panic, naming chi's decorateFuncCallLine +// and nothing about the fault that caused it. +const panicProbeMarker = "QQPRODUCTIONPANICVALUEQQ" + +// panicChildEnv, when set, tells the re-executed test binary to run +// the child half of the fd-level probe below. +const panicChildEnv = "WEBHOOKER_PANIC_PROBE_CHILD" + +// panicChildResultPrefix labels the child's own one-line report of +// what the HTTP client saw, so the parent can find it among whatever +// else lands on the child's standard output. +const panicChildResultPrefix = "PANIC-PROBE-RESULT " + +// stackTruncationMarker mirrors what internal/middleware appends to a +// field it cut. It is duplicated rather than exported, as the access +// log's budgets are, so that changing it has to be restated here +// deliberately. +const stackTruncationMarker = "[truncated]" + +// TestPanicThroughProductionRouter drives a handler panic through the +// shipped router, over a real server, in a subprocess whose actual +// file descriptors are captured. +// +// Every part of that is load-bearing. +// +// A subprocess, because the question is what reaches fd 1 and fd 2 of +// the process an operator runs. The defect's signature was 0 bytes on +// standard error and a 2,772-byte record on standard output describing +// chi's own crash, and neither is visible to a test that swaps the +// logger for a buffer. +// +// A real server, because a panicking handler under chi's Recoverer +// dropped the connection: the client got EOF, not a status. An +// httptest.ResponseRecorder has no connection to drop and would have +// recorded the same unwritten response either way, which is why this +// defect survived the existing suite. +// +// The production router, because the placement of the recoverer among +// the other global middleware is part of the fix. +func TestPanicThroughProductionRouter(t *testing.T) { + t.Parallel() + + if os.Getenv(panicChildEnv) != "" { + t.Skip("child half; run by the parent below") + } + + //nolint:gosec // Re-executing this test binary, with a fixed arg. + cmd := exec.CommandContext( + t.Context(), os.Args[0], + "-test.run", "^TestPanicProbeChild$", + ) + + cmd.Env = append(os.Environ(), panicChildEnv+"=1") + + var stdout, stderr bytes.Buffer + + cmd.Stdout = &stdout + cmd.Stderr = &stderr + + require.NoError( + t, cmd.Run(), + "child failed\nstdout:\n%s\nstderr:\n%s", + stdout.String(), stderr.String(), + ) + + assertPanicProbeOutput(t, stdout.String(), stderr.String()) +} + +// assertPanicProbeOutput holds the child's descriptors to what a +// working recoverer produces. +func assertPanicProbeOutput(t *testing.T, stdout, stderr string) { + t.Helper() + + result := "" + + var record map[string]any + + for line := range strings.SplitSeq(stdout, "\n") { + if after, found := strings.CutPrefix( + line, panicChildResultPrefix, + ); found { + result = after + + continue + } + + if !strings.HasPrefix(line, `{"time"`) { + continue + } + + decoded := map[string]any{} + if json.Unmarshal([]byte(line), &decoded) != nil { + continue + } + + if decoded["msg"] == "handler panic" { + require.Nil( + t, record, "one panic record expected, got two", + ) + + record = decoded + + assert.LessOrEqual( + t, len(line), middleware.MaxPanicLogLineBytes, + "the panic record must hold its stated ceiling", + ) + + t.Logf( + "panic record through the shipped chain: %d bytes "+ + "(ceiling %d)", + len(line), middleware.MaxPanicLogLineBytes, + ) + } + } + + // What the client got. Under the defect this read + // `status=0 err=... EOF`. + require.Equal( + t, "status=500 err=", result, + "the client must receive a 500, not a dropped connection", + ) + + // What the operator got. Under the defect there was no such + // record: standard output carried net/http reporting chi's own + // crash, at INFO, with the original panic value nowhere in it. + require.NotNil( + t, record, + "no structured panic record reached standard output", + ) + assert.Equal(t, "ERROR", record["level"]) + assert.Equal(t, panicProbeMarker, record["panic"]) + assert.Equal(t, false, record["response_committed"]) + + stack, ok := record["stack"].(string) + require.True(t, ok) + assert.Contains(t, stack, "panicProbeHandler") + assert.NotContains( + t, stack, stackTruncationMarker, + "the shipped middleware chain's own stack must fit the "+ + "stack budget without being cut", + ) + t.Logf("stack through the shipped chain: %d bytes", len(stack)) + + // The secondary panic, in every form it took. net/http's report + // is the tell: it only logs a request when something escaped the + // handler chain. + assert.NotContains(t, stdout, "http: panic serving") + assert.NotContains(t, stdout, "slice bounds out of range") + assert.NotContains(t, stdout, "decorateFuncCallLine") + assert.Empty( + t, strings.TrimSpace(stderr), + "nothing may reach standard error", + ) +} + +// panicProbeHandler is the panicking route the child installs. It is a +// named function so the stack assertion has something to look for. +func panicProbeHandler(http.ResponseWriter, *http.Request) { + panic(panicProbeMarker) +} + +// TestPanicProbeChild is the child half of the probe above. It runs +// only when re-executed with panicChildEnv set; in an ordinary run it +// returns immediately. +// +// It writes its result to standard output with a prefix rather than +// asserting, because the assertions belong to the parent, which is the +// only side that can see both descriptors. +func TestPanicProbeChild(t *testing.T) { + t.Parallel() + + if os.Getenv(panicChildEnv) == "" { + return + } + + env := newTestEnv(t) + + router := server.NewRouterWithProbeForTest( + env.log.Get(), env.cfg, env.mw, env.hnd, + false, panicProbeHandler, + ) + + srv := httptest.NewServer(router) + defer srv.Close() + + req, err := http.NewRequestWithContext( + context.Background(), http.MethodGet, + srv.URL+server.ProbePattern, nil, + ) + require.NoError(t, err) + + status := 0 + + resp, err := srv.Client().Do(req) + if err == nil { + status = resp.StatusCode + + _ = resp.Body.Close() + } + + // Written to the descriptor rather than through the testing + // package's own output, because fd 1 is exactly what the parent + // is measuring. + _, writeErr := fmt.Fprintf( + os.Stdout, "%sstatus=%d err=%v\n", + panicChildResultPrefix, status, err, + ) + require.NoError(t, writeErr) +} + +// TestSentryStillSeesAPanic pins the relationship the recoverer's +// placement has to preserve. sentryhttp is registered with +// Repanic: true, inside the recoverer, so an operator with SENTRY_DSN +// set keeps the report and the client still gets a 500. Registered the +// other way round, the SDK would swallow the panic and the recoverer +// would never see it. +func TestSentryStillSeesAPanic(t *testing.T) { + t.Parallel() + + env := newTestEnv(t) + + transport := &captureTransport{} + + opts := server.SentryClientOptionsForTest( + "https://public@sentry.invalid/1", "webhooker-test", + ) + opts.Transport = transport + + client, err := sentry.NewClient(opts) + require.NoError(t, err) + + router := server.NewRouterWithProbeForTest( + env.log.Get(), env.cfg, env.mw, env.hnd, + true, panicProbeHandler, + ) + + req := httptest.NewRequestWithContext( + sentry.SetHubOnContext( + context.Background(), + sentry.NewHub(client, sentry.NewScope()), + ), + http.MethodGet, server.ProbePattern, nil, + ) + + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + + assert.Equal( + t, http.StatusInternalServerError, w.Code, + "the recoverer must still answer what sentryhttp re-raised", + ) + + events := transport.events + require.Len(t, events, 1, "Sentry must still see the panic") + assert.Equal(t, sentry.LevelFatal, events[0].Level) + // The SDK renders a string panic value as the event message + // rather than an exception, so the whole payload is checked for + // the value rather than one field of it. + assert.Contains( + t, marshalEvent(t, events[0]), panicProbeMarker, + ) +} diff --git a/internal/server/routes.go b/internal/server/routes.go index db017d5..2fbcd09 100644 --- a/internal/server/routes.go +++ b/internal/server/routes.go @@ -51,7 +51,6 @@ func (s *Server) SetupRoutes() { } func (s *Server) setupGlobalMiddleware() { - s.router.Use(middleware.Recoverer) s.router.Use(middleware.RequestID) s.router.Use(s.mw.SecurityHeaders()) s.router.Use(s.mw.Logging()) @@ -64,8 +63,21 @@ func (s *Server) setupGlobalMiddleware() { s.router.Use(s.mw.CORS()) s.router.Use(middleware.Timeout(requestTimeout)) + // Panic recovery, deliberately here rather than first. It has to + // run inside every middleware that observes the response, so the + // 500 it writes is the status the access log records and the + // metrics count, and outside the sentryhttp handler below, whose + // Repanic option needs something further out to catch what it + // re-raises. chi's own middleware.Recoverer held the first slot + // until it was measured: on a current Go release it crashes + // inside its stack pretty-printer instead of recovering, so the + // connection dropped and the original panic was never reported. + // See https://git.eeqj.de/sneak/webhooker/issues/187. + s.router.Use(s.mw.Recoverer()) + // Sentry error reporting (if SENTRY_DSN is set). Repanic is - // true so panics still bubble up to the Recoverer middleware. + // true so panics still bubble up to the Recoverer middleware + // registered immediately above. if s.sentryEnabled { sentryHandler := sentryhttp.New(sentryhttp.Options{ Repanic: true, diff --git a/internal/server/routes_test.go b/internal/server/routes_test.go index cf9a5f1..13fbd0d 100644 --- a/internal/server/routes_test.go +++ b/internal/server/routes_test.go @@ -52,6 +52,15 @@ type testEnv struct { sess *session.Session db *database.Database dbMgr *database.WebhookDBManager + + // The collaborators the router was built from, kept so a test + // that needs a second router over the same graph — one carrying + // a panicking probe route, or one with Sentry registered — can + // build it without wiring the graph again. + log *logger.Logger + cfg *config.Config + mw *middleware.Middleware + hnd *handlers.Handlers } // newTestEnv wires the dependency graph with fx and builds the @@ -100,6 +109,10 @@ func newTestEnv(t *testing.T) *testEnv { sess: sess, db: db, dbMgr: dbMgr, + log: log, + cfg: cfg, + mw: mw, + hnd: hnd, } } diff --git a/internal/server/sentry_test.go b/internal/server/sentry_test.go index 9b7148e..cb5f1a6 100644 --- a/internal/server/sentry_test.go +++ b/internal/server/sentry_test.go @@ -127,12 +127,14 @@ func (c sentryCase) capture(t *testing.T) []*sentry.Event { return transport.events } -// router mirrors setupGlobalMiddleware's ordering over the two route -// patterns these tests need: a recovering middleware first, then the +// router mirrors the one ordering these tests depend on, over the two +// route patterns they need: a recovering middleware outside, then the // sentryhttp handler registered with Use and Repanic set, exactly as -// routes.go registers it. The local recover stands in for chi's -// middleware.Recoverer, which holds that slot in production; it is -// here only to keep panic stacks out of the test output. +// routes.go orders the two. The bare recover stands in for +// Middleware.Recoverer, which holds that outer slot in production; it +// is here only to keep panic stacks out of the test output. That the +// production one really does catch what sentryhttp re-raises is +// pinned separately, by TestSentryStillSeesAPanic. func (c sentryCase) router() http.Handler { handler := func(_ http.ResponseWriter, r *http.Request) { // This call is what drains the body tee and fills the