Compare commits
1 Commits
next
...
4c1b7b616f
| Author | SHA1 | Date | |
|---|---|---|---|
| 4c1b7b616f |
102
README.md
102
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
|
||||
<https://git.eeqj.de/sneak/webhooker/issues/187>.
|
||||
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
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
@@ -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
|
||||
)
|
||||
|
||||
|
||||
203
internal/middleware/recoverer.go
Normal file
203
internal/middleware/recoverer.go
Normal file
@@ -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,
|
||||
)
|
||||
}
|
||||
588
internal/middleware/recoverer_test.go
Normal file
588
internal/middleware/recoverer_test.go
Normal file
@@ -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))
|
||||
}
|
||||
@@ -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
|
||||
}
|
||||
|
||||
285
internal/server/recoverer_test.go
Normal file
285
internal/server/recoverer_test.go
Normal file
@@ -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=<nil>", 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,
|
||||
)
|
||||
}
|
||||
@@ -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,
|
||||
|
||||
@@ -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,
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user