Report handler panics through the logger and answer 500 (closes #187)

internal/middleware/recoverer.go

@@ -0,0 +1,209 @@
+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 four checkouts have
+	// reported records of 3,959, 3,961, 3,984 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.
+	//
+	// The 9121 and the 10240 are the invariants here. What follows
+	// is illustration: with all three growable fields — the stack,
+	// the panic value and a client-supplied X-Request-Id — driven
+	// past their budgets at once, TestRecovererBoundsTheStack
+	// measured 9,009 bytes on the JSON handler and 8,982 to 8,983 on
+	// the text one in this checkout. Neither is fixed: the stack's
+	// own content decides where its cut lands, so the figures move by
+	// a byte or so between runs and with the checkout. The test
+	// asserts the ceiling and that every growable field was cut,
+	// never the figures.
+	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,
+	)
+}