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