diff --git a/.claude/skills/verify/SKILL.md b/.claude/skills/verify/SKILL.md index 9b6de29..79dfaa8 100644 --- a/.claude/skills/verify/SKILL.md +++ b/.claude/skills/verify/SKILL.md @@ -1,13 +1,13 @@ --- name: verify -description: Use when the user runs /verify or asks to run make verify. Runs the full verification suite (tests, lint, coverage, benchmarks, license) and fixes every issue found. +description: Use when the user runs /verify or asks to run make verify. Runs the full verification suite (tests, license, lint, coverage) and fixes every issue found. --- # verify Run `make verify` and fix all issues until it passes clean. -`make verify` runs in order: `test` → `ui-test` → `license-check` → `lint` → `benchmark` → `coverage` +`make verify` runs in order: `test` → `license-check` → `lint` → `coverage` ## How to run diff --git a/AGENTS.md b/AGENTS.md index c80b7b4..f93422d 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -5,10 +5,10 @@ This file provides guidance to AI coding agents (e.g. Claude Code) when working ## Commands ```bash -make test # run all tests with coverage +make test # run all tests with the race detector and coverage make lint # run golangci-lint (must be installed externally) make benchmark # run benchmarks -make verify # run tests + lint + benchmarks + coverage check +make verify # run tests + license check + lint + coverage check (incl. TestWrapResourceBudget) go test ./... # run all tests go test ./middleware/ # run tests for a single package go test ./middleware/ -run TestMiddleware # run a single test @@ -24,17 +24,19 @@ This is a Go library (`github.com/go-bumbu/http`) providing reusable HTTP compon - **middleware/metrics/** — Prometheus-backed `Observer` implementation, configured with a `metrics.Cfg`: `NewObserver` builds the registered request-duration histogram and wraps it as `middleware.Observer` (`NopObserver` is an explicit no-op; buckets are validated ascending at construction). The only package that imports `prometheus/client_golang`. - **spa/** — Single Page Application handler serving files from an `fs.FS` (typically embedded), built with `spa.New(spa.Cfg{...})`. Blocks dotfiles (except `.well-known/`) and normalises `PathPrefix`. - **outbound/** — Client-side resilience for a service's own outbound calls to third-party APIs: a throttled, retrying `Client` (built with `outbound.New(outbound.Cfg{...})`) with a typed `*Error` carrying a status, a user-facing message, and a `Kind`. The only package that imports `golang.org/x/time/rate`. -- **problemjson/** — RFC 9457 (`application/problem+json`) error-response `Writer`, built with `problemjson.New(problemjson.Cfg{...})`. `ModeMasked` strips detail in production; `WriteUpstream` bridges an `outbound.*Error` via the structural `UpstreamError` interface (no import) and, in dev mode, adds a `reason` field from an optional `UpstreamReason()` method. +- **problemjson/** — RFC 9457 (`application/problem+json`) error-response `Writer`, built with `problemjson.New(problemjson.Cfg{...})`. `ModeMasked` strips detail in production, and the optional `Cfg.OnProblem` hook receives the unmasked `Problem` — `Details` (same `reference`) plus validation field errors, upstream reason, and upstream error — exactly once on every write path so the real detail can be logged; `WriteUpstream` bridges an `outbound.*Error` via the structural `UpstreamError` interface (no import) and, in dev mode, adds a `reason` field from an optional `UpstreamReason()` method. ### Key Design Decisions - **StatWriter** (`middleware/respwriter.go`) wraps `http.ResponseWriter` to intercept the status code and the error-response body. On an error status it simultaneously buffers the body for logging and forwards (tees) it to the client — this prevents reverse-proxy hangs when the upstream writes an error body. The middleware never replaces the body; success and 1xx responses pass through untouched. -- **Streaming**: StatWriter implements `Flush`/`FlushError` and `Hijack` directly (not just `Unwrap`), so handlers using either `http.ResponseController` or the older `w.(http.Flusher)` / `w.(http.Hijacker)` type assertions can stream. The first flush calls `releaseInterception`, which commits the status code and switches to passthrough (error bodies are already teed as they are written, so nothing is buffered-but-unsent). `Streaming()` reports that the response has been streamed or hijacked and `Started()` reports that any bytes have been committed (any `Write` latches the status); panic recovery synthesises a 500 only when neither holds, so it never appends `Internal Server Error` over a body the client has already begun receiving — matching net/http. After a hijack, `flushHeader` writes nothing. -- **Error classification**: `IsStatusError()` (>= 400) vs `IsServerErr()` (>= 500) drives log levels — server errors log at ERROR, client errors at INFO. 1xx informational responses (e.g. 103 Early Hints) pass through without latching the status. -- **Panic recovery re-panics on `http.ErrAbortHandler`**: it's net/http's sentinel to abort a response so the client detects truncation (`ReverseProxy` uses it when the upstream dies mid-copy); swallowing it would make truncated responses look complete. -- **Bounded Prometheus label cardinality** (in `middleware/metrics`): the `addr` label uses `r.Pattern` (route pattern, requires Go 1.23 for the `r.Pattern` field) when matched, else the constant `"unmatched"` — never the raw request path. The `method` label is normalised to the standard HTTP methods, else `"other"`. Both cap the label sets so an attacker cannot mint unbounded time-series (net/http accepts any token as a method, and a non-pattern mux leaves `r.Pattern` empty). +- **Streaming**: StatWriter implements `Flush`/`FlushError` and `Hijack` directly (not just `Unwrap`), so handlers using either `http.ResponseController` or the older `w.(http.Flusher)` / `w.(http.Hijacker)` type assertions can stream. The first flush calls `releaseInterception`, which commits the status code and switches to passthrough (error bodies are already teed as they are written, so nothing is buffered-but-unsent). `Streaming()` reports that the response has been streamed or hijacked and `Started()` reports that any bytes have been committed (any `Write` latches the status); panic recovery synthesises a 500 only when neither holds, so it never appends `Internal Server Error` over a body the client has already begun receiving. When either holds it still logs the panic and records the request, then re-panics with `http.ErrAbortHandler` so net/http aborts the connection and the client detects the truncation — matching net/http without recovery. After a hijack, `flushHeader` writes nothing. +- **Error classification**: `IsStatusError()` (>= 400) vs `IsServerErr()` (>= 500) drives log levels — server errors log at ERROR, client errors at INFO. 1xx informational responses (e.g. 103 Early Hints) pass through without latching the status; 101 Switching Protocols is the exception and latches like a final status, and a hijack with no status written records 101 for logs/metrics. +- **Panic recovery re-panics on `http.ErrAbortHandler`**: it's net/http's sentinel to abort a response so the client detects truncation (`ReverseProxy` uses it when the upstream dies mid-copy); swallowing it would make truncated responses look complete. Every path that aborts the connection (a panic without recovery, `http.ErrAbortHandler`, `runtime.Goexit`) goes through `recordAborted`: if no status was committed (`!Started() && !Streaming()`), the request is recorded — logged at ERROR and observed — as 500, never the StatWriter's default 200 (the client got a reset connection); nothing is written. A status already committed (flushed or written 200, 101 after a hijack) is recorded unchanged. +- **Bounded Prometheus label cardinality** (in `middleware/metrics`): the `addr` label uses the route resolved by `middleware.Route` when matched, else the constant `"unmatched"` — never the raw request path. The `method` label is normalised to the standard HTTP methods, else `"other"`. Both cap the label sets so an attacker cannot mint unbounded time-series (net/http accepts any token as a method, and a non-pattern mux leaves `r.Pattern` empty). +- **Route resolution** (`middleware/route.go`): only when `Metrics` is set (nothing else reads the route, and it costs a request copy), `Wrap` passes down a request copy carrying a pointer "route slot" in its context and hands that same copy to the `Observer` — `http.ServeMux` writes `r.Pattern` onto the request it receives, so using the caller's original would lose every stdlib route. A deferred restore copies `r.Pattern` back onto the caller's request (path values are unexported and can't be), so wrappers outside `Wrap` still read it. Because the slot is a pointer, `SetRoute` on any further copy (gorilla/chi copy on match) still reaches it; the slot's mutex covers `SetRoute` from another goroutine (`http.TimeoutHandler`). A wrapper between `Wrap` and a `ServeMux` that copies the request (`r.WithContext` in auth/tracing middleware, `TimeoutHandler`, `MaxBytesHandler`, `StripPrefix`) hides the mux's `r.Pattern` from `Wrap`; the recommended setup is `middleware.CaptureRoute` placed directly around the mux. Around an `*http.ServeMux` it looks the pattern up with `ServeMux.Handler` *before* dispatch (same `findHandler` result `ServeHTTP` writes to `r.Pattern`), so a request `TimeoutHandler` times out — observed while the handler goroutine still runs — keeps its route; around any other handler it records `r.Pattern` after it returns (deferred, so also on panic). The context value is a `routeScope{slot, depth}`: each `CaptureRoute` hands its handler a copy one level deeper (and copies that copy's `r.Pattern` back, also on panic), and both reporters are ranked by that depth, not write time (`SetRoute` records `setDepth`, a capture `capturedDepth`; each is overwritten only by a same-or-deeper report). After the handler, the route is resolved by one rule: the innermost reporter wins — `SetRoute` or a `CaptureRoute` whose mux matched — whether it reports before or after dispatch (gorilla's `Use` before, chi's glue after), so a nested mux under `StripPrefix` beats an outer router's template; at equal depth `SetRoute` wins; empty reports (a mux miss, `SetRoute(r, "")`) are ignored and claim no depth, so an inner miss keeps the outer template; with no report it falls back to `r.Pattern`. The inner pattern is relative to the stripped prefix (the template syntaxes differ, so they are deliberately not joined). The result is then mapped through `Cfg.RouteGroups` (whole-segment path prefixes, longest first), and stored for `middleware.Route`; nested middlewares share one slot and each resolves with its own groups. Routers report with `SetRoute`, `ServeMux` through `CaptureRoute`, and the `Observer` interface is unchanged so any backend reads the same route. - **Backend-agnostic seams**: the combined middleware depends on the `Observer` (metrics) and `Logger` (logging) interfaces, not concrete types. `*slog.Logger` satisfies `Logger` structurally; `metrics.NewObserver` supplies `Observer`. This keeps `middleware` free of any third-party dependency — Prometheus is compiled only when a consumer imports `middleware/metrics`. - **Bounded log buffer**: error-response bodies are captured for logging in an unexported `middleware.limitBuf` (cap `bufMaxBytes` = 2000) that *composes* (not embeds) `bytes.Buffer` and behaves like a capped `io.Discard` — writes past the cap are dropped and flagged via `Truncated()`, so a large error body cannot grow middleware memory without bound. Composition (not embedding) is deliberate: it prevents a promoted `bytes.Buffer` method (`WriteString`, `ReadFrom`, …) from bypassing the cap. +- **Log hygiene** (`middleware/slog.go`, `middleware/clientip.go`): the `url` field is `r.URL.EscapedPath()` — the query string is never logged (tokens, signatures). The `ip` field comes from `Cfg.ClientIP`, a plain `func(*http.Request) string` like `Cfg.RequestID`; the default `ClientIPDirect` ignores forwarding headers because clients can forge them. `ClientIPFromRealIP`/`ClientIPFromXFF` believe headers only when the direct peer is in a trusted `netip.Prefix` list, and XFF is walked right to left past trusted hops (the leftmost entry is client-controlled). `ClientIPFromXFFHops` picks by position for proxies without stable ranges and does not check the peer. - **Constructor convention**: configurable constructors take a single `Cfg` struct — `middleware.New`, `outbound.New`, `problemjson.New`, `spa.New`, and `metrics.NewObserver` — so adjacent same-typed arguments can't be transposed and options can grow without breaking callers. The low-level `middleware.NewWriter(w)` is the deliberate exception (a single wrapper argument, like `bufio.NewWriter`). - **spa dotfile blocking & prefix normalisation** (`spa/spa.go`): `http.FileServerFS` serves dotfiles, so `spa.Handler` returns 404 for any path segment beginning with `.` — except the standard `.well-known/` tree — so `/.env` or `/.git/config` can't leak over an `os.DirFS` build directory. A plain `//go:embed dir` already excludes dotfiles from the binary; the serve-time block covers `os.DirFS` and `all:` embeds. `PathPrefix` is normalised in the constructor (`ui`, `/ui`, `/ui/` → `/ui`), so a missing leading slash can't silently route every asset to `index.html`. - **Upstream-failure presentation seam**: `outbound` owns the failure taxonomy (`Kind` → HTTP status); `problemjson` owns presentation (status → slug/title). The HTTP status is the deliberate contract between them, so several `Kind`s collapse to one 502 slug by design — the finer `Kind` stays in server logs, and in `problemjson` dev mode it also appears in the `reason` field (read via an optional `UpstreamReason()` method). Neither package imports the other. diff --git a/Makefile b/Makefile index 9acb3ab..918bf0d 100644 --- a/Makefile +++ b/Makefile @@ -6,8 +6,8 @@ default: help #========================================================================================== ##@ Testing #========================================================================================== -test: ## run fast go tests - @go test ./... -cover +test: ## run go tests with the race detector (needs cgo) + @go test -race ./... -cover lint: ## run go linter # depends on https://github.com/golangci/golangci-lint @@ -23,21 +23,22 @@ license-check: ## check for invalid licenses COVERAGE_THRESHOLD ?= 70 .PHONY: coverage -coverage: ## check code coverage per package - @out=$$(go test -cover -covermode=atomic $$(go list ./middleware/... ./spa/...)) || { echo "$$out"; exit 1; }; \ +coverage: ## check code coverage of every package + @out=$$(go test -cover -covermode=atomic $$(go list ./...)) || { echo "$$out"; exit 1; }; \ echo "$$out" | awk -v threshold=$(COVERAGE_THRESHOLD) ' \ - /\[no test files\]/ { printf "⚠️ %-70s no test files\n", $$2; next } \ + /\[no test files\]/ { printf "❌ %-70s no test files (0%%, below %s%%)\n", $$2, threshold; fail = 1; next } \ /coverage:/ { \ + pkg = ($$1 == "ok") ? $$2 : $$1; \ for (i = 1; i <= NF; i++) if ($$i == "coverage:") { cov = $$(i+1); sub(/%/, "", cov); break }; \ - if (cov + 0 < threshold) { printf "❌ %-70s %s%% (below %s%%)\n", $$2, cov, threshold; fail = 1 } \ - else { printf "✅ %-70s %s%%\n", $$2, cov } \ + if (cov + 0 < threshold) { printf "❌ %-70s %s%% (below %s%%)\n", pkg, cov, threshold; fail = 1 } \ + else { printf "✅ %-70s %s%%\n", pkg, cov } \ } \ END { exit fail }' .PHONY: verify verify: ## run all checks; runs every check and fails if any fail @fail=0; \ - for target in test license-check lint benchmark coverage; do \ + for target in test license-check lint coverage; do \ echo "==================== make $$target ===================="; \ $(MAKE) --no-print-directory $$target || fail=1; \ done; \ diff --git a/README.md b/README.md index b8a3dee..0d40e91 100644 --- a/README.md +++ b/README.md @@ -43,6 +43,30 @@ mux.Handle("/", m.Wrap(handler)) It depends only on the standard library; Prometheus is pulled in only when you import `middleware/metrics`. +Panics are logged and recorded once, then handled like net/http does: + +- `PanicRecover: true`, response not started yet: the client gets a `500 Internal Server Error` and `Wrap` returns normally. +- `PanicRecover: true`, response already started (a status written, body bytes written, flushed, or hijacked): a 500 can no longer be sent, so `Wrap` re-panics with `http.ErrAbortHandler` and net/http aborts the connection, letting the client detect the truncated reply. A handler's own `http.ErrAbortHandler` panic (e.g. from `httputil.ReverseProxy`) is passed through the same way. +- `PanicRecover: false`: nothing is written; the panic is recorded (as a 500 if no status was sent) and carries on out of `Wrap`. + +So a panic can escape `Wrap` either way: an outer recoverer will see it, and a test that calls the handler directly with `httptest.ResponseRecorder` must expect the panic rather than a normal return. + +The logged `url` field is the request path only: the query string is never logged, since it often carries tokens or signatures. + +The logged `ip` field is the direct peer by default; forwarding headers are ignored because any client can set them. Behind a reverse proxy, tell the middleware which proxies to trust so it logs the real client: + +```go +middleware.Cfg{ + Logger: slog.Default(), + ClientIP: middleware.ClientIPFromXFF(netip.MustParsePrefix("10.0.0.0/8")), +} +``` + +- `ClientIPDirect` — the peer address, no headers (default) +- `ClientIPFromRealIP(trusted...)` — `X-Real-Ip`, when the peer is a trusted proxy +- `ClientIPFromXFF(trusted...)` — `X-Forwarded-For`, walked right to left past trusted proxies +- `ClientIPFromXFFHops(n)` — `X-Forwarded-For` by position, for proxies without a stable address range + `ReqDelay` is a standalone, development-only helper: `middleware.ReqDelay{...}.Delay` adds a random delay between a min and max duration to simulate slow backends. #### middleware/metrics @@ -53,6 +77,104 @@ histogram and wraps it as a `middleware.Observer` for `middleware.Cfg.Metrics` to avoid time-series cardinality blow-ups. This is the only package that imports the Prometheus client, so importing `middleware` alone stays dependency-free. +#### Route labels + +Metrics are labelled by route template (`/users/{id}`), never by raw path, so +`/users/1` and `/users/2` share one series. The middleware resolves the route after the +handler runs, by one rule: the innermost reporter wins. A reporter is a +`middleware.SetRoute` call or a `middleware.CaptureRoute` whose mux matched, and +"innermost" means nested inside the most `CaptureRoute`s, whether it reports before or +after the handler. At equal depth `SetRoute` wins; empty reports (a mux miss, +`SetRoute(r, "")`) are ignored. With no report the middleware uses the `http.ServeMux` +pattern it sees; anything else records as `unmatched`. `Cfg.RouteGroups` is applied to +the result. + +With `http.ServeMux` directly under the middleware nothing is needed. When another +wrapper sits in between and passes a request copy down (`r.WithContext` in an auth or +tracing middleware, `http.TimeoutHandler`, `http.MaxBytesHandler`, `http.StripPrefix`), +the mux writes its pattern onto a copy the middleware never sees, and every request +records as `unmatched`. Wrap the mux in `CaptureRoute`, directly around it: + +```go +http.ListenAndServe(":8080", m.Wrap(auth(middleware.CaptureRoute(mux)))) +``` + +For a mux mounted under another router or mux with `http.StripPrefix`, wrap the inner +mux in `CaptureRoute`: its pattern wins over the outer template (`/api/`, gorilla's +`/api/{version}/`, chi's `/api/*`), and the outer one is kept when the inner mux has no +match. The inner pattern is relative to the stripped path (`GET /users/{id}`, not +`/api/users/{id}`), so mounting the same mux under `/v1` and `/v2` shares its series. +To keep the full path, register the inner mux with full patterns +(`GET /api/users/{id}`) and skip `StripPrefix`. + +This rule changed label values in mixed router setups: an outer `SetRoute` used to win +over an inner `CaptureRoute`, so such routes now record the inner, relative pattern +instead of the outer template. Check dashboards and `RouteGroups` after upgrading: an +`/api` group does not match a relative inner pattern like `GET /users/{id}`. + +Other routers report their match with `SetRoute`, from a router-level middleware. +gorilla/mux: + +```go +// Reports gorilla's matched template. gorilla runs Use middlewares after matching. +setGorillaRoute := func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if route := mux.CurrentRoute(r); route != nil { + if tmpl, err := route.GetPathTemplate(); err == nil { + middleware.SetRoute(r, tmpl) + } + } + next.ServeHTTP(w, r) + }) +} +m := middleware.New(middleware.Cfg{Metrics: obs}) +router := mux.NewRouter() + +// A) wrap the whole router: every request is seen, including 404/405. +router.Use(setGorillaRoute) +http.ListenAndServe(":8080", m.Wrap(router)) + +// B) or inside the router. Order matters: m.Wrap first, so the setter runs inside it. +// gorilla skips Use middlewares for 404/405, so wrap those handlers too. +router.Use(m.Wrap, setGorillaRoute) +router.NotFoundHandler = m.Wrap(http.NotFoundHandler()) +router.MethodNotAllowedHandler = m.Wrap(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + http.Error(w, http.StatusText(http.StatusMethodNotAllowed), http.StatusMethodNotAllowed) +})) +``` + +Use one setup, not both: every request would be logged and counted twice. + +chi runs `Use` middlewares *before* routing, so read the pattern after the handler: + +```go +router := chi.NewRouter() +router.Use(func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r) + middleware.SetRoute(r, chi.RouteContext(r.Context()).RoutePattern()) + }) +}) +http.ListenAndServe(":8080", m.Wrap(router)) +``` + +Pass `SetRoute` a template, never the raw path: each distinct value is a new series. + +Notes: +- Route shapes differ by router: a `ServeMux` pattern keeps its method when registered + with one (`GET /users/{id}`), a gorilla or chi template has none (`/users/{id}`). The + method is always its own label as well. +- With metrics on, handlers receive a copy of the request. The middleware copies + `r.Pattern` back for wrappers outside it, but not the path values: `r.PathValue` is + empty outside the middleware. + +`Cfg.RouteGroups` collapses routes under a prefix into one series: +`RouteGroups: []string{"/api"}` records `GET /api/apple` and `GET /api/banana` as +`GET /api`. Entries are paths (a method is stripped, a host is not supported); they +match whole segments (`/api` does not group `/apiary`) and the longest wins. Groups +match the resolved route, so a relative pattern from an inner `CaptureRoute` +(`GET /users/{id}` under a stripped `/api`) is not in an `/api` group. + ### spa Single Page Application handler that serves files from an `fs.FS` (typically `embed.FS`). @@ -67,6 +189,10 @@ spaHandler, err := spa.New(spa.Cfg{FS: embeddedFS, SubDir: "dist", PathPrefix: " - `SubDir` — sub-directory within the FS to serve from (empty for the FS root) - `PathPrefix` — URL path the SPA is mounted under; normalised to a single leading slash, so `ui`, `/ui`, and `/ui/` are equivalent (empty mounts at the root) +`New` returns an error if the served tree (`FS` after `SubDir`) has no `index.html` file, +so a mistyped `SubDir` or a missing build fails at startup. The entrypoint is served +directly, never as a directory listing. + Dotfiles are not served — `GET /.env` or `/.git/config` returns 404 — except the standard `.well-known/` tree. A plain `//go:embed dist` already keeps dotfiles out of the binary (prefer it to `//go:embed all:dist`); the serve-time block is the defense for `os.DirFS` @@ -81,22 +207,38 @@ timeouts), `Retry-After` compliance, and a typed `*Error` carrying both the tech detail (for logs) and a human-readable sentence naming the service (for the UI). ```go -client := outbound.New(outbound.Cfg{Service: "Cover Art Archive", RPS: 5}) +client := outbound.New(outbound.Cfg{Service: "Cover Art Archive", RPS: 5, Timeout: 8 * time.Second}) resp, err := client.Get(ctx, url, nil) // on failure: outbound.HTTPStatus(err) and outbound.UserMessage(err, fallback) ``` +The `Client`'s timeout (20s by default) bounds each attempt; set `Timeout` to cap the +whole call — attempts, backoff, and the body read — for user-facing requests. If the +context or budget ends after an upstream failure, the error still carries that +`*Error` (and `errors.Is` matches the context error). + This is the only package that pulls in `golang.org/x/time/rate`; the inbound packages above do not. ### problemjson Writes RFC 9457 (`application/problem+json`) error responses — one consistent, -spec-shaped error body (a stable `type` URI, `title`/`detail`, and the request path -as `instance`) in place of ad-hoc `{"error":...}` shapes. `ModeMasked` strips -handler-supplied detail in production while keeping a correlation `reference`. +spec-shaped error body (a stable `type` URI, `title`/`detail`, and the escaped +request path as `instance`) in place of ad-hoc `{"error":...}` shapes. `ModeMasked` strips +handler-supplied detail in production while keeping a correlation `reference`; set +`OnProblem` to log the unmasked problem (same `reference`) so the real cause is not lost: +it receives the `Details` plus the validation field errors, the upstream reason, and the +upstream error, all of which a masked body omits. ```go -pj, err := problemjson.New(problemjson.Cfg{BaseURI: "https://errors.example.com"}) +pj, err := problemjson.New(problemjson.Cfg{ + BaseURI: "https://errors.example.com", + Mode: problemjson.ModeMasked, + RequestID: requestIDFrom, // func(*http.Request) string + OnProblem: func(r *http.Request, p problemjson.Problem) { + slog.Error("problem", "status", p.Status, "detail", p.Detail, "reference", p.Reference, + "fields", p.Errors, "reason", p.Reason, "err", p.Err) + }, +}) // handle err pj.Write(w, r, http.StatusNotFound, problemjson.SlugNotFound, "no such release") pj.WriteUpstream(w, r, err, "The catalog is unavailable.") // maps an outbound.*Error @@ -104,5 +246,6 @@ pj.WriteUpstream(w, r, err, "The catalog is unavailable.") // maps an outbound.* In dev mode, `WriteUpstream` adds an extra `reason` field naming the exact failure (e.g. `unreachable`) whenever the error can supply one through an optional -`UpstreamReason() string` method (`outbound.*Error` does). `ModeMasked` strips it, and +`UpstreamReason() string` method (`outbound.*Error` does). `ModeMasked` strips it from the +body (`OnProblem` still gets it in `Problem.Reason`), and neither package imports the other — the reason travels through the method name alone. diff --git a/TODO.md b/TODO.md index d8ccc7c..87445db 100644 --- a/TODO.md +++ b/TODO.md @@ -1,6 +1,6 @@ - + +# Middleware diff --git a/middleware/bench_test.go b/middleware/bench_test.go new file mode 100644 index 0000000..7666a65 --- /dev/null +++ b/middleware/bench_test.go @@ -0,0 +1,213 @@ +package middleware_test + +import ( + "bytes" + "io" + "log/slog" + "math" + "net/http" + "net/http/httptest" + "runtime" + "testing" + "time" + + "github.com/go-bumbu/http/middleware" +) + +// Resource budget: TestWrapResourceBudget fails when a case costs more than its recorded +// baseline times these factors. They are deliberately loose — the guard is for a change that +// blows the cost up, not for a few percent — and time gets far more room than memory because +// it depends on the machine (CI runners, coverage instrumentation) while allocations do not. +const ( + memBudgetFactor = 2.0 // allocs/op and B/op + timeBudgetFactor = 10.0 // ns/op +) + +// wrapBenchCase is one request path through Middleware.Wrap. The baseline fields are the cost +// measured when the case was last tuned (go1.27, amd64, no race detector); after an intended +// cost change, re-measure with `go test -run=^$ -bench=BenchmarkWrap -benchmem ./middleware/` +// and update them. +type wrapBenchCase struct { + name string + cfg middleware.Cfg + handler http.Handler + + baseNs, baseBytes, baseAllocs float64 +} + +func wrapBenchCases() []wrapBenchCase { + mux := http.NewServeMux() + mux.Handle("GET /users/{id}", testHandler(http.StatusOK, "ok")) + + info := slog.New(slog.NewJSONHandler(io.Discard, nil)) + debug := slog.New(slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug})) + + // A body far larger than the capped log buffer: it is teed to the client in full while + // only bufMaxBytes are captured, so this case catches the cap being lost. + largeBody := bytes.Repeat([]byte("x"), 4096) + largeErr := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusBadGateway) + for range 16 { // 64 KiB + _, _ = w.Write(largeBody) + } + }) + panics := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { panic("boom") }) + chunk := []byte("data: chunk\n\n") + stream := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + rc := http.NewResponseController(w) + for range 8 { + _, _ = w.Write(chunk) + _ = rc.Flush() + } + }) + + return []wrapBenchCase{ + { + name: "no metrics", cfg: middleware.Cfg{}, handler: mux, + baseNs: 210, baseBytes: 128, baseAllocs: 3, + }, + { + name: "metrics", cfg: middleware.Cfg{Metrics: nopObserver{}}, handler: mux, + baseNs: 430, baseBytes: 616, baseAllocs: 8, + }, + { + name: "metrics+groups", cfg: middleware.Cfg{Metrics: nopObserver{}, RouteGroups: []string{"/users"}}, handler: mux, + baseNs: 430, baseBytes: 632, baseAllocs: 9, + }, + { + name: "metrics+CaptureRoute", cfg: middleware.Cfg{Metrics: nopObserver{}}, handler: middleware.CaptureRoute(mux), + baseNs: 660, baseBytes: 1017, baseAllocs: 12, + }, + { + name: "logger", cfg: middleware.Cfg{Logger: info}, handler: mux, + baseNs: 1300, baseBytes: 433, baseAllocs: 6, + }, + { + name: "logger+error body", cfg: middleware.Cfg{Logger: info}, handler: testHandler(http.StatusInternalServerError, "db connection broken"), + baseNs: 1400, baseBytes: 1018, baseAllocs: 8, + }, + { + name: "logger+large error body", cfg: middleware.Cfg{Logger: info}, handler: largeErr, + baseNs: 4500, baseBytes: 7085, baseAllocs: 9, + }, + { + name: "logger+debug headers", cfg: middleware.Cfg{Logger: debug, LogHeaders: true}, handler: mux, + baseNs: 2600, baseBytes: 1122, baseAllocs: 14, + }, + { + name: "logger+panic recovered", cfg: middleware.Cfg{Logger: info, PanicRecover: true}, handler: panics, + baseNs: 17000, baseBytes: 6111, baseAllocs: 15, + }, + { + name: "logger+streaming", cfg: middleware.Cfg{Logger: info}, handler: stream, + baseNs: 1200, baseBytes: 416, baseAllocs: 5, + }, + { + name: "full", cfg: middleware.Cfg{ + Logger: info, Metrics: nopObserver{}, PanicRecover: true, RouteGroups: []string{"/users"}, + }, handler: middleware.CaptureRoute(mux), + baseNs: 1950, baseBytes: 1339, baseAllocs: 16, + }, + } +} + +// benchRequest is the request every case serves; the headers feed the debug header log +// (Authorization exercises redaction). +func benchRequest() *http.Request { + r := httptest.NewRequest(http.MethodGet, "/users/1", nil) + r.Header.Set("Authorization", "Bearer secret") + r.Header.Set("User-Agent", "bench") + r.Header.Set("Request-Id", "req-1") + return r +} + +// discardWriter drops the response body, so the numbers are the middleware's own cost and not +// a recorder buffering every iteration's response. It supports Flush for the streaming case. +type discardWriter struct{ h http.Header } + +func newDiscardWriter() *discardWriter { return &discardWriter{h: http.Header{}} } + +func (w *discardWriter) Header() http.Header { return w.h } +func (w *discardWriter) Write(p []byte) (int, error) { return len(p), nil } +func (w *discardWriter) WriteHeader(int) {} +func (w *discardWriter) Flush() {} + +// BenchmarkWrap measures the per-request cost of Middleware.Wrap on each path: with and +// without metrics (the route slot and request copy are only added with metrics), CaptureRoute's +// extra request copy, access logging, error-body capture, debug header logging, panic +// recovery, and streaming. +func BenchmarkWrap(b *testing.B) { + for _, bc := range wrapBenchCases() { + b.Run(bc.name, func(b *testing.B) { + h := middleware.New(bc.cfg).Wrap(bc.handler) + r := benchRequest() + w := newDiscardWriter() + b.ReportAllocs() + for b.Loop() { + h.ServeHTTP(w, r) + } + }) + } +} + +// TestWrapResourceBudget guards against a change that makes the middleware dramatically more +// expensive: each BenchmarkWrap case must stay within its baseline times memBudgetFactor +// (allocs/op, B/op) and timeBudgetFactor (ns/op). Unlike the benchmark it runs with go test, +// so CI enforces it. +func TestWrapResourceBudget(t *testing.T) { + if testing.Short() { + t.Skip("resource budget measurement skipped in -short mode") + } + if raceEnabled { + // The race detector slows everything down and makes sync.Pool drop items at random, + // so neither time nor allocations are comparable to the baseline. + t.Skip("resource budget measurement skipped under the race detector") + } + for _, bc := range wrapBenchCases() { + t.Run(bc.name, func(t *testing.T) { + h := middleware.New(bc.cfg).Wrap(bc.handler) + got := measure(h, benchRequest(), 5, 2000) + t.Logf("%.0f ns/op, %.0f B/op, %.0f allocs/op", got.ns, got.bytes, got.allocs) + + check := func(metric string, got, base, factor float64) { + t.Helper() + if limit := base * factor; got > limit { + t.Errorf("%s = %.0f, over budget %.0f (baseline %.0f × %.0f); if the increase is intended, "+ + "update the baseline in wrapBenchCases", metric, got, limit, base, factor) + } + } + check("allocs/op", got.allocs, bc.baseAllocs, memBudgetFactor) + check("B/op", got.bytes, bc.baseBytes, memBudgetFactor) + check("ns/op", got.ns, bc.baseNs, timeBudgetFactor) + }) + } +} + +type cost struct{ ns, bytes, allocs float64 } + +// measure serves r through h in rounds of n requests and returns the per-request cost of the +// cheapest round for each metric, counted the way testing.B does (runtime.MemStats) but in a +// few milliseconds instead of a second per case. Taking the minimum over rounds discards +// rounds disturbed by GC or the scheduler. +func measure(h http.Handler, r *http.Request, rounds, n int) cost { + defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1)) + w := newDiscardWriter() + h.ServeHTTP(w, r) // warm up lazily initialised state and pools + + best := cost{ns: math.Inf(1), bytes: math.Inf(1), allocs: math.Inf(1)} + var before, after runtime.MemStats + for range rounds { + runtime.ReadMemStats(&before) + start := time.Now() + for range n { + h.ServeHTTP(w, r) + } + elapsed := time.Since(start) + runtime.ReadMemStats(&after) + + best.ns = min(best.ns, float64(elapsed.Nanoseconds())/float64(n)) + best.bytes = min(best.bytes, float64(after.TotalAlloc-before.TotalAlloc)/float64(n)) + best.allocs = min(best.allocs, float64(after.Mallocs-before.Mallocs)/float64(n)) + } + return best +} diff --git a/middleware/clientip.go b/middleware/clientip.go new file mode 100644 index 0000000..b2a61be --- /dev/null +++ b/middleware/clientip.go @@ -0,0 +1,137 @@ +package middleware + +import ( + "net/http" + "net/netip" + "slices" + "strings" +) + +// Client IP extractors for Cfg.ClientIP. Each one has the signature +// func(*http.Request) string and returns the address logged as the "ip" field. +// +// Forwarding headers (X-Real-Ip, X-Forwarded-For) are set by whoever sent the request, so they +// are only believed when the request arrived from a proxy you trust; otherwise any client could +// write a fake address into your logs. Pick the extractor that matches your deployment: +// +// - exposed directly to clients: ClientIPDirect (the default) +// - behind a proxy that sets X-Real-Ip (e.g. nginx): ClientIPFromRealIP +// - behind one or more proxies that append to X-Forwarded-For: ClientIPFromXFF +// - behind proxies with no stable address range (some cloud load balancers): ClientIPFromXFFHops +// +// Every extractor accepts addresses with or without a port, unmaps IPv4-in-IPv6 addresses, and +// falls back to the direct peer when a header is missing or not a valid IP, so a malformed +// header never reaches the log. + +// ClientIPDirect returns the address of the direct peer (r.RemoteAddr without its port) and +// ignores all forwarding headers. It cannot be spoofed by the client, and it is the default +// when Cfg.ClientIP is nil. Behind a reverse proxy it returns the proxy's address. A RemoteAddr +// that is not an IP (e.g. a unix socket) is returned unchanged. +func ClientIPDirect(r *http.Request) string { + if a, ok := parseIP(r.RemoteAddr); ok { + return a.String() + } + return r.RemoteAddr +} + +// ClientIPFromRealIP returns the X-Real-Ip header when the direct peer is inside one of the +// trusted proxy ranges, and the direct peer otherwise. A single proxy address is a /32 (IPv4) +// or /128 (IPv6) prefix. +func ClientIPFromRealIP(trusted ...netip.Prefix) func(*http.Request) string { + proxies := slices.Clone(trusted) + return func(r *http.Request) string { + peer, ok := parseIP(r.RemoteAddr) + if !ok || !inPrefixes(proxies, peer) { + return ClientIPDirect(r) + } + if a, ok := parseIP(r.Header.Get("X-Real-Ip")); ok { + return a.String() + } + return peer.String() + } +} + +// ClientIPFromXFF resolves the client from X-Forwarded-For when the direct peer is inside one of +// the trusted proxy ranges, and returns the direct peer otherwise. +// +// Each proxy appends the address it received the request from, so the left end of the list is +// whatever the client sent and cannot be trusted. The list (all header lines, in order) is walked +// from the right, skipping trusted proxies; the first untrusted address is the client. If every +// entry is trusted the leftmost one is returned, and an invalid entry stops the walk at the last +// trusted hop before it. With no trusted ranges it behaves like ClientIPDirect. +func ClientIPFromXFF(trusted ...netip.Prefix) func(*http.Request) string { + proxies := slices.Clone(trusted) + return func(r *http.Request) string { + peer, ok := parseIP(r.RemoteAddr) + if !ok || !inPrefixes(proxies, peer) { + return ClientIPDirect(r) + } + client := peer + entries := xffEntries(r) + for i := len(entries) - 1; i >= 0; i-- { + a, ok := parseIP(entries[i]) + if !ok { + break + } + client = a + if !inPrefixes(proxies, a) { + break + } + } + return client.String() + } +} + +// ClientIPFromXFFHops resolves the client from X-Forwarded-For by position, for deployments +// whose proxies have no stable address range to list: hops is the number of proxies in front of +// the server, so with one proxy the rightmost entry is the client. When the list is shorter than +// hops the leftmost entry is returned; when the header is missing, the selected entry is invalid, +// or hops < 1, the direct peer is returned. +// +// It does not check where the request came from, so it is only safe when clients cannot reach +// the server without going through those proxies. Prefer ClientIPFromXFF when you can list the +// proxy ranges. +func ClientIPFromXFFHops(hops int) func(*http.Request) string { + return func(r *http.Request) string { + entries := xffEntries(r) + if hops < 1 || len(entries) == 0 { + return ClientIPDirect(r) + } + idx := max(len(entries)-hops, 0) + if a, ok := parseIP(entries[idx]); ok { + return a.String() + } + return ClientIPDirect(r) + } +} + +// xffEntries returns the X-Forwarded-For list across all header lines, in order. +func xffEntries(r *http.Request) []string { + var entries []string + for _, line := range r.Header.Values("X-Forwarded-For") { + entries = append(entries, strings.Split(line, ",")...) + } + return entries +} + +// parseIP parses an address with or without a port ("1.2.3.4", "1.2.3.4:80", "[::1]:80"), +// unmapping IPv4-in-IPv6 and dropping any IPv6 zone so prefix matching works. +func parseIP(s string) (netip.Addr, bool) { + s = strings.TrimSpace(s) + if ap, err := netip.ParseAddrPort(s); err == nil { + return ap.Addr().Unmap().WithZone(""), true + } + if a, err := netip.ParseAddr(s); err == nil { + return a.Unmap().WithZone(""), true + } + return netip.Addr{}, false +} + +func inPrefixes(prefixes []netip.Prefix, a netip.Addr) bool { + for _, p := range prefixes { + if p.Contains(a) { + return true + } + } + return false +} diff --git a/middleware/clientip_test.go b/middleware/clientip_test.go new file mode 100644 index 0000000..2515aa3 --- /dev/null +++ b/middleware/clientip_test.go @@ -0,0 +1,227 @@ +package middleware_test + +import ( + "bytes" + "log/slog" + "net/http" + "net/http/httptest" + "net/netip" + "strings" + "testing" + + "github.com/go-bumbu/http/middleware" +) + +// proxyNet is the trusted proxy range used throughout these tests. +var proxyNet = netip.MustParsePrefix("10.0.0.0/8") + +func ipRequest(remoteAddr string, headers map[string][]string) *http.Request { + r := httptest.NewRequest("GET", "/", nil) + r.RemoteAddr = remoteAddr + for k, vs := range headers { + for _, v := range vs { + r.Header.Add(k, v) + } + } + return r +} + +func TestClientIPDirect(t *testing.T) { + tcs := []struct { + name string + remoteAddr string + headers map[string][]string + want string + }{ + {name: "strips the port", remoteAddr: "203.0.113.7:4321", want: "203.0.113.7"}, + {name: "ipv6 with port", remoteAddr: "[2001:db8::1]:4321", want: "2001:db8::1"}, + {name: "unmaps ipv4-in-ipv6", remoteAddr: "[::ffff:203.0.113.7]:4321", want: "203.0.113.7"}, + {name: "no port", remoteAddr: "203.0.113.7", want: "203.0.113.7"}, + {name: "unparseable is returned as-is", remoteAddr: "@", want: "@"}, + { + name: "ignores forwarding headers", + remoteAddr: "203.0.113.7:4321", + headers: map[string][]string{ + "X-Real-Ip": {"198.51.100.1"}, + "X-Forwarded-For": {"198.51.100.2"}, + }, + want: "203.0.113.7", + }, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + if got := middleware.ClientIPDirect(ipRequest(tc.remoteAddr, tc.headers)); got != tc.want { + t.Errorf("got %q, want %q", got, tc.want) + } + }) + } +} + +func TestClientIPFromRealIP(t *testing.T) { + extract := middleware.ClientIPFromRealIP(proxyNet) + tcs := []struct { + name string + remoteAddr string + realIP string + want string + }{ + {name: "trusted peer: header is used", remoteAddr: "10.1.2.3:80", realIP: "203.0.113.7", want: "203.0.113.7"}, + {name: "untrusted peer: header is ignored", remoteAddr: "198.51.100.9:80", realIP: "203.0.113.7", want: "198.51.100.9"}, + {name: "trusted peer, header missing", remoteAddr: "10.1.2.3:80", want: "10.1.2.3"}, + {name: "trusted peer, header garbage", remoteAddr: "10.1.2.3:80", realIP: "not-an-ip", want: "10.1.2.3"}, + {name: "header with port", remoteAddr: "10.1.2.3:80", realIP: "203.0.113.7:5555", want: "203.0.113.7"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + h := map[string][]string{} + if tc.realIP != "" { + h["X-Real-Ip"] = []string{tc.realIP} + } + if got := extract(ipRequest(tc.remoteAddr, h)); got != tc.want { + t.Errorf("got %q, want %q", got, tc.want) + } + }) + } +} + +func TestClientIPFromXFF(t *testing.T) { + tcs := []struct { + name string + trusted []netip.Prefix + remoteAddr string + xff []string + want string + }{ + { + name: "untrusted peer: header is ignored", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "198.51.100.9:80", + xff: []string{"203.0.113.7"}, + want: "198.51.100.9", + }, + { + name: "no trusted proxies: header is ignored", + remoteAddr: "10.1.2.3:80", + xff: []string{"203.0.113.7"}, + want: "10.1.2.3", + }, + { + name: "single proxy", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + xff: []string{"203.0.113.7"}, + want: "203.0.113.7", + }, + { + name: "client-forged leftmost entry is skipped", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + xff: []string{"1.1.1.1, 203.0.113.7"}, + want: "203.0.113.7", + }, + { + name: "trusted hops are skipped right to left", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + xff: []string{"1.1.1.1, 203.0.113.7, 10.9.9.9, 10.8.8.8"}, + want: "203.0.113.7", + }, + { + name: "multiple header lines are one list", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + xff: []string{"1.1.1.1, 203.0.113.7", "10.9.9.9"}, + want: "203.0.113.7", + }, + { + name: "all hops trusted: leftmost is the client", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + xff: []string{"10.5.5.5, 10.9.9.9"}, + want: "10.5.5.5", + }, + { + name: "garbage entry stops the walk at the last trusted hop", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + xff: []string{"203.0.113.7, bogus, 10.9.9.9"}, + want: "10.9.9.9", + }, + { + name: "header missing", + trusted: []netip.Prefix{proxyNet}, + remoteAddr: "10.1.2.3:80", + want: "10.1.2.3", + }, + { + name: "entries with ports and ipv6", + trusted: []netip.Prefix{proxyNet, netip.MustParsePrefix("fd00::/8")}, + remoteAddr: "[fd00::1]:80", + xff: []string{"[2001:db8::7]:5555, 10.9.9.9:80"}, + want: "2001:db8::7", + }, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + extract := middleware.ClientIPFromXFF(tc.trusted...) + r := ipRequest(tc.remoteAddr, map[string][]string{"X-Forwarded-For": tc.xff}) + if got := extract(r); got != tc.want { + t.Errorf("got %q, want %q", got, tc.want) + } + }) + } +} + +func TestClientIPFromXFFHops(t *testing.T) { + tcs := []struct { + name string + hops int + xff []string + want string + }{ + {name: "one proxy: rightmost entry", hops: 1, xff: []string{"1.1.1.1, 203.0.113.7"}, want: "203.0.113.7"}, + {name: "two proxies", hops: 2, xff: []string{"1.1.1.1, 203.0.113.7, 10.9.9.9"}, want: "203.0.113.7"}, + {name: "fewer entries than hops: leftmost", hops: 3, xff: []string{"203.0.113.7, 10.9.9.9"}, want: "203.0.113.7"}, + {name: "header missing: peer", hops: 1, want: "10.1.2.3"}, + {name: "zero hops: peer", hops: 0, xff: []string{"203.0.113.7"}, want: "10.1.2.3"}, + {name: "garbage entry: peer", hops: 1, xff: []string{"bogus"}, want: "10.1.2.3"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + extract := middleware.ClientIPFromXFFHops(tc.hops) + r := ipRequest("10.1.2.3:80", map[string][]string{"X-Forwarded-For": tc.xff}) + if got := extract(r); got != tc.want { + t.Errorf("got %q, want %q", got, tc.want) + } + }) + } +} + +// TestLog_ClientIP verifies the "ip" log field: by default it is the direct peer (forwarding +// headers are not trusted), and Cfg.ClientIP replaces the extractor. +func TestLog_ClientIP(t *testing.T) { + tcs := []struct { + name string + clientIP func(*http.Request) string + want string + }{ + {name: "default ignores spoofable headers", want: "ip=10.1.2.3 "}, + {name: "configured extractor", clientIP: middleware.ClientIPFromXFF(proxyNet), want: "ip=203.0.113.7 "}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewTextHandler(&buf, nil)) + m := middleware.New(middleware.Cfg{Logger: logger, ClientIP: tc.clientIP}) + r := ipRequest("10.1.2.3:80", map[string][]string{ + "X-Forwarded-For": {"203.0.113.7"}, + "X-Real-Ip": {"198.51.100.1"}, + }) + m.Wrap(testHandler(200, "ok")).ServeHTTP(httptest.NewRecorder(), r) + + if got := buf.String(); !strings.Contains(got, tc.want) { + t.Errorf("expected log to contain %q, got %q", tc.want, got) + } + }) + } +} diff --git a/middleware/metrics/metrics.go b/middleware/metrics/metrics.go index dd3b903..d310c93 100644 --- a/middleware/metrics/metrics.go +++ b/middleware/metrics/metrics.go @@ -118,14 +118,15 @@ func normalizeMethod(method string) string { } } -// metricAddr returns the value for the "addr" label. It uses the matched route -// pattern (e.g. "GET /users/{id}"), a bounded set, and reports "unmatched" for -// requests that did not match a pattern-aware http.ServeMux route (Go 1.22+). -// The raw r.URL.Path is attacker-controlled and would create one time series -// per distinct URL, so it is deliberately never used as a label value. +// metricAddr returns the value for the "addr" label: the route resolved by the +// middleware (see middleware.Route — a SetRoute value or the ServeMux pattern such +// as "GET /users/{id}", after RouteGroups), a bounded set, or "unmatched" when no +// route matched. The raw r.URL.Path is attacker-controlled and +// would create one time series per distinct URL, so it is deliberately never used as +// a label value. func metricAddr(r *http.Request) string { - if r.Pattern != "" { - return r.Pattern + if route := middleware.Route(r); route != "" { + return route } return "unmatched" } diff --git a/middleware/metrics/metrics_test.go b/middleware/metrics/metrics_test.go index 94f5b3b..207fee8 100644 --- a/middleware/metrics/metrics_test.go +++ b/middleware/metrics/metrics_test.go @@ -136,6 +136,43 @@ func TestObserver_PatternLabel(t *testing.T) { } } +// TestObserver_RouteLabel verifies the "addr" label follows the middleware's route +// resolution for non-ServeMux routers: a route set with SetRoute, and RouteGroups +// collapsing sub-routes into one series. +func TestObserver_RouteLabel(t *testing.T) { + reg := prometheus.NewRegistry() + obs, err := metrics.NewObserver(metrics.Cfg{Registry: reg}) + if err != nil { + t.Fatalf("NewObserver: %v", err) + } + // Stands in for a gorilla/chi router reporting its matched template. + router := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + switch r.URL.Path { + case "/users/1", "/users/2": + middleware.SetRoute(r, "/users/{id}") + case "/api/apple": + middleware.SetRoute(r, "/api/apple") + case "/api/banana": + middleware.SetRoute(r, "/api/banana") + } + w.WriteHeader(200) + }) + h := middleware.New(middleware.Cfg{Metrics: obs, RouteGroups: []string{"/api"}}).Wrap(router) + for _, p := range []string{"/users/1", "/users/2", "/api/apple", "/api/banana"} { + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", p, nil)) + } + + body := scrape(t, reg) + for _, want := range []string{ + `requests_http_duration_seconds_count{addr="/users/{id}",method="GET",status="200",type="HTTP/1.1"} 2`, + `requests_http_duration_seconds_count{addr="/api",method="GET",status="200",type="HTTP/1.1"} 2`, + } { + if !strings.Contains(body, want) { + t.Errorf("missing expected series:\n%s\nmetrics:\n%s", want, body) + } + } +} + // TestNopObserver verifies NopObserver is a non-nil Observer that is safe to call // directly and leaves the response untouched — this is the sharp edge a nil // interface sentinel would hit. diff --git a/middleware/middleware.go b/middleware/middleware.go index b41d64f..c802f6e 100644 --- a/middleware/middleware.go +++ b/middleware/middleware.go @@ -20,6 +20,24 @@ type Observer interface { } type Cfg struct { + // PanicRecover controls what Wrap does when the handler panics. Every panic is logged and + // observed exactly once either way; a request aborted before any status was committed is + // recorded as 500. + // + // When true, a panic before the response has started (no final status written via + // WriteHeader, no Write, flush, or hijack) is logged with its stack and turned into a 500 + // "Internal Server Error" response, and Wrap returns normally. A panic after the response + // has started cannot be turned into a clean reply: it is logged and recorded, then Wrap + // re-panics with http.ErrAbortHandler so net/http aborts the connection and the client + // detects the truncation. A handler that panics with http.ErrAbortHandler itself (e.g. + // httputil.ReverseProxy when the upstream dies mid-copy) is recorded and re-panicked as is. + // + // When false, nothing is written to the client: the panic is recorded and then propagates + // out of Wrap unchanged, and net/http aborts the connection. + // + // So with either setting a panic can escape Wrap: an outer recoverer sees it, and a test + // calling the handler directly with httptest.ResponseRecorder must expect it (e.g. with a + // deferred recover) instead of a normal return. PanicRecover bool Logger Logger Metrics Observer @@ -30,6 +48,12 @@ type Cfg struct { // or the request context. An empty result logs an empty req-id. RequestID func(*http.Request) string + // ClientIP extracts the client address logged as the "ip" field. When nil it defaults to + // ClientIPDirect: the direct peer, ignoring forwarding headers, which a client could forge. + // Behind a reverse proxy, use ClientIPFromRealIP or ClientIPFromXFF with the proxy's + // address range (or ClientIPFromXFFHops), so the real client is logged. + ClientIP func(*http.Request) string + // LogHeaders, when true, causes the middleware to emit one additional // log record per request at slog.LevelDebug containing request and // response headers. The record is only emitted when the configured @@ -46,6 +70,14 @@ type Cfg struct { // built-in redact list and ExtraRedactHeaders are both ignored. // Intended for local debugging only. DisableRedaction bool + + // RouteGroups lists URL path prefixes that collapse every route beneath them into one + // metric route: with "/api", "GET /api/apple" and "GET /api/banana" both record as + // "GET /api". Prefixes match whole path segments and the longest one wins. Entries are + // paths only: a leading method ("GET /api") is stripped, a host is not supported, a + // leading slash is added, repeated or trailing slashes are dropped, and a bare "/" is + // ignored. Only used when Metrics is set. + RouteGroups []string } func New(cfg Cfg) *Middleware { @@ -53,7 +85,12 @@ func New(cfg Cfg) *Middleware { if requestID == nil { requestID = defaultRequestID } + clientIP := cfg.ClientIP + if clientIP == nil { + clientIP = ClientIPDirect + } m := Middleware{ + clientIP: clientIP, panicRecover: cfg.PanicRecover, metrics: cfg.Metrics, logger: cfg.Logger, @@ -61,6 +98,7 @@ func New(cfg Cfg) *Middleware { disableRedaction: cfg.DisableRedaction, redact: newRedactSet(cfg.ExtraRedactHeaders), requestID: requestID, + routeGroups: newRouteGroups(cfg.RouteGroups), } return &m } @@ -85,43 +123,76 @@ type Middleware struct { disableRedaction bool redact redactSet requestID func(*http.Request) string + clientIP func(*http.Request) string + routeGroups routeGroups } // Wrap returns an http.Handler that runs next with the configured request logging, metrics, // and panic recovery. It never modifies the response body; see the Middleware type doc for -// the streaming, error-tee, and passthrough guarantees. +// the streaming, error-tee, and passthrough guarantees. A handler panic may re-panic out of the +// returned handler (always when PanicRecover is false; as http.ErrAbortHandler when the +// response had already started); see Cfg.PanicRecover. func (m *Middleware) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // With metrics on, pass a copy carrying the route slot down the chain. ServeMux sets + // r.Pattern on the request it receives, so every step below (finalize, observe) must + // use this copy. restore hands the pattern back to the caller's request; deferred + // first, it runs last: after panic recovery, and while an abort panic unwinds. + r, slot, restore := m.withRouteSlot(r) + defer restore() timeStart := time.Now() // The middleware never modifies the body; tee error responses so the client still // receives them during e.g. a reverse-proxy copy—avoids an indefinite hang on 401. respWriter := NewWriter(w) - if m.panicRecover { - defer func() { - if rec := recover(); rec != nil { - if isAbort(rec) { - // net/http's sentinel to abort the response so the client - // sees a truncated reply (ReverseProxy panics with it when - // the upstream dies mid-copy). Swallowing it would make the - // truncated response look complete; hand it back to net/http. - m.observe(r, respWriter.StatusCode(), time.Since(timeStart)) - panic(rec) - } - m.handlePanic(r, respWriter, rec, debug.Stack()) - } - m.finalize(r, respWriter, timeStart) - }() - } + // Deferred unconditionally so the request is logged and observed exactly once on every + // path, panics included; completed tells a normal return from an unwinding panic. + completed := false + defer func() { + if completed { + m.finalize(r, slot, respWriter, timeStart) + return + } + if m.panicRecover { + m.recovered(r, slot, respWriter, timeStart, recover()) + return + } + // Not recovering: record the request, write nothing, and let the panic carry on + // to net/http, which aborts the connection. + m.recordAborted(r, slot, respWriter, timeStart) + }() next.ServeHTTP(respWriter, r) - - if !m.panicRecover { - m.finalize(r, respWriter, timeStart) - } + completed = true }) } +// recovered handles a handler that did not return normally, with rec the value recover +// returned. It returns normally only when it turned the panic into a 500 response, or when +// there was no panic to recover (runtime.Goexit, which then carries on); otherwise it records +// the request and re-panics so net/http aborts the connection. +func (m *Middleware) recovered(r *http.Request, slot *routeSlot, respWriter *StatWriter, timeStart time.Time, rec any) { + if rec == nil { + m.recordAborted(r, slot, respWriter, timeStart) + return + } + if isAbort(rec) { + // net/http's sentinel to abort the response so the client sees a truncated reply + // (ReverseProxy panics with it when the upstream dies mid-copy). Swallowing it would + // make the truncated response look complete; hand it back to net/http. + m.recordAborted(r, slot, respWriter, timeStart) + panic(rec) + } + if !m.handlePanic(r, respWriter, rec, debug.Stack()) { + // The response had started: the client already holds a status and maybe part of the + // body. Finishing normally would make the truncated reply look complete, so record it + // and abort the connection, as net/http does for an unrecovered panic. + m.recordAborted(r, slot, respWriter, timeStart) + panic(http.ErrAbortHandler) + } + m.finalize(r, slot, respWriter, timeStart) +} + // isAbort reports whether a recovered panic value is http.ErrAbortHandler, the stdlib // sentinel that means "abort this response, let the client detect the truncation". func isAbort(rec any) bool { @@ -130,14 +201,15 @@ func isAbort(rec any) bool { } // handlePanic logs a recovered panic and, when the response has not started, turns it into a -// 500 response. http.ErrAbortHandler must not reach here (see isAbort): it is the stdlib's -// sentinel for deliberately aborting the response so the client detects truncation; recovering -// it would make a truncated reply look complete. -func (m *Middleware) handlePanic(r *http.Request, respWriter *StatWriter, rec any, stack []byte) { +// 500 response and returns true. It returns false when the response had already started; the +// caller must then abort the connection so the client detects the truncation. +// http.ErrAbortHandler must not reach here (see isAbort): it is the stdlib's sentinel for +// deliberately aborting the response; recovering it would make a truncated reply look complete. +func (m *Middleware) handlePanic(r *http.Request, respWriter *StatWriter, rec any, stack []byte) bool { if m.logger != nil { m.logger.LogAttrs(r.Context(), slog.LevelError, "panic recovered", slog.String("method", r.Method), - slog.String("url", r.RequestURI), + slog.String("url", logURL(r)), slog.String("panic", fmt.Sprint(rec)), slog.String("stack", string(stack)), ) @@ -148,26 +220,48 @@ func (m *Middleware) handlePanic(r *http.Request, respWriter *StatWriter, rec an // error text would corrupt that response under its already-sent status, exactly as // net/http declines to do. if respWriter.Streaming() || respWriter.Started() { - return + return false } respWriter.WriteHeader(http.StatusInternalServerError) _, _ = respWriter.Write([]byte(http.StatusText(http.StatusInternalServerError))) + return true } -func (m *Middleware) finalize(r *http.Request, respWriter *StatWriter, timeStart time.Time) { +// finalize completes a request that is ending normally: it commits the status and records it. +func (m *Middleware) finalize(r *http.Request, slot *routeSlot, respWriter *StatWriter, timeStart time.Time) { + respWriter.flushHeader() + m.record(r, slot, respWriter, timeStart) +} + +// recordAborted records a request whose handler did not return normally and whose connection +// net/http is about to abort. If no status was committed, the client gets a reset connection, +// not the StatWriter's default 200, so the request is recorded as a 500 (logged at ERROR); +// nothing is written to the client. A status already committed (headers flushed, a body +// written, 101 after a hijack) is what the client saw, so it is recorded unchanged. +func (m *Middleware) recordAborted(r *http.Request, slot *routeSlot, respWriter *StatWriter, timeStart time.Time) { + if !respWriter.Started() && !respWriter.Streaming() { + respWriter.statusCode = http.StatusInternalServerError + } + m.record(r, slot, respWriter, timeStart) +} + +// record writes the access log line and observes the request; it must run exactly once per +// request. It writes nothing to the response, so an aborting path calls it directly. +func (m *Middleware) record(r *http.Request, slot *routeSlot, respWriter *StatWriter, timeStart time.Time) { timeDiff := time.Since(timeStart) errMsg := getErrMsg(respWriter.statusCode, respWriter.buf) m.log(r, respWriter.StatusCode(), errMsg, timeDiff) m.logHeadersDebug(r, respWriter.Header()) - respWriter.flushHeader() - - m.observe(r, respWriter.StatusCode(), timeDiff) + m.observe(r, slot, respWriter.StatusCode(), timeDiff) } -func (m *Middleware) observe(r *http.Request, statusCode int, dur time.Duration) { +// observe settles the request's route (read back by Observers via Route) and records the +// metric. r must be the request copy carrying slot, so r.Pattern reflects a ServeMux match. +func (m *Middleware) observe(r *http.Request, slot *routeSlot, statusCode int, dur time.Duration) { if m.metrics != nil { + m.resolveRoute(r, slot) m.metrics.Observe(statusCode, r, dur) } } diff --git a/middleware/norace_test.go b/middleware/norace_test.go new file mode 100644 index 0000000..f767ff8 --- /dev/null +++ b/middleware/norace_test.go @@ -0,0 +1,6 @@ +//go:build !race + +package middleware_test + +// raceEnabled reports whether the tests run under the race detector. +const raceEnabled = false diff --git a/middleware/observer_test.go b/middleware/observer_test.go index 0c61ef2..9b7644a 100644 --- a/middleware/observer_test.go +++ b/middleware/observer_test.go @@ -1,8 +1,14 @@ package middleware_test import ( + "bufio" + "errors" + "fmt" + "net" "net/http" "net/http/httptest" + "runtime" + "strings" "testing" "time" @@ -40,3 +46,130 @@ func TestCombinedMiddleware_CallsObserver(t *testing.T) { t.Errorf("observed duration = %v, want >= 0", spy.dur) } } + +// TestCombinedMiddleware_ObservesOncePerPath is the regression test for requests that went +// unrecorded on a panic: with PanicRecover off any panic skipped both the access log and the +// Observer, and with it on a handler's own http.ErrAbortHandler was observed but not logged. +// Every path must log one access line and call Observe exactly once, and a panic the +// middleware does not turn into a 500 must still reach the caller. +// +// It also pins the recorded status: a request aborted before any status was committed is +// recorded as a 500 at ERROR (the client gets a reset connection, not the StatWriter's +// default 200), while one aborted after committing a status keeps that status. +func TestCombinedMiddleware_ObservesOncePerPath(t *testing.T) { + errBoom := errors.New("boom") + ok := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { _, _ = w.Write([]byte("ok")) }) + boom := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { panic(errBoom) }) + abort := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { panic(http.ErrAbortHandler) }) + startedBoom := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + _, _ = w.Write([]byte("partial")) + panic(errBoom) + }) + flushedBoom := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.(http.Flusher).Flush() + panic(errBoom) + }) + hijackedBoom := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + conn, _, err := w.(http.Hijacker).Hijack() + if err != nil { + panic(err) + } + _ = conn.Close() + panic(errBoom) + }) + + tcs := []struct { + name string + recover bool + handler http.Handler + wantPanic error // nil: the request must complete normally + wantStatus int + wantLevel string + }{ + {name: "normal, recovery on", recover: true, handler: ok, wantStatus: 200, wantLevel: "INFO"}, + {name: "normal, recovery off", recover: false, handler: ok, wantStatus: 200, wantLevel: "INFO"}, + {name: "recovered 500", recover: true, handler: boom, wantStatus: 500, wantLevel: "ERROR"}, + {name: "started then panic, recovery on", recover: true, handler: startedBoom, wantPanic: http.ErrAbortHandler, wantStatus: 200, wantLevel: "INFO"}, + {name: "started then panic, recovery off", recover: false, handler: startedBoom, wantPanic: errBoom, wantStatus: 200, wantLevel: "INFO"}, + {name: "flushed then panic, recovery on", recover: true, handler: flushedBoom, wantPanic: http.ErrAbortHandler, wantStatus: 200, wantLevel: "INFO"}, + {name: "flushed then panic, recovery off", recover: false, handler: flushedBoom, wantPanic: errBoom, wantStatus: 200, wantLevel: "INFO"}, + {name: "hijacked then panic, recovery on", recover: true, handler: hijackedBoom, wantPanic: http.ErrAbortHandler, wantStatus: 101, wantLevel: "INFO"}, + {name: "hijacked then panic, recovery off", recover: false, handler: hijackedBoom, wantPanic: errBoom, wantStatus: 101, wantLevel: "INFO"}, + {name: "ErrAbortHandler, recovery on", recover: true, handler: abort, wantPanic: http.ErrAbortHandler, wantStatus: 500, wantLevel: "ERROR"}, + {name: "panic, recovery off", recover: false, handler: boom, wantPanic: errBoom, wantStatus: 500, wantLevel: "ERROR"}, + {name: "ErrAbortHandler, recovery off", recover: false, handler: abort, wantPanic: http.ErrAbortHandler, wantStatus: 500, wantLevel: "ERROR"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + buf, logger := newMemSlog() + spy := &spyObserver{} + h := middleware.New(middleware.Cfg{PanicRecover: tc.recover, Logger: logger, Metrics: spy}).Wrap(tc.handler) + + var got any + func() { + defer func() { got = recover() }() + h.ServeHTTP(&hijackRecorder{ResponseRecorder: httptest.NewRecorder()}, httptest.NewRequest("GET", "/x", nil)) + }() + + if tc.wantPanic == nil && got != nil { + t.Errorf("unexpected panic %v", got) + } + if tc.wantPanic != nil && got != tc.wantPanic { + t.Errorf("panic = %v, want %v", got, tc.wantPanic) + } + if spy.calls != 1 { + t.Errorf("Observe called %d times, want 1", spy.calls) + } + if spy.status != tc.wantStatus { + t.Errorf("observed status = %d, want %d", spy.status, tc.wantStatus) + } + if n := strings.Count(buf.String(), "response-code="); n != 1 { + t.Errorf("access log lines = %d, want 1; log %q", n, buf.String()) + } + wantLine := fmt.Sprintf("%s method=GET url=/x response-code=%d ", tc.wantLevel, tc.wantStatus) + if !strings.Contains(buf.String(), wantLine) { + t.Errorf("access log missing %q; log %q", wantLine, buf.String()) + } + }) + } +} + +// hijackRecorder is an httptest.ResponseRecorder that can also be hijacked, handing out one +// end of a net.Pipe so the hijack succeeds without a real server. +type hijackRecorder struct { + *httptest.ResponseRecorder +} + +func (h *hijackRecorder) Hijack() (net.Conn, *bufio.ReadWriter, error) { + server, client := net.Pipe() + _ = client.Close() + return server, bufio.NewReadWriter(bufio.NewReader(server), bufio.NewWriter(server)), nil +} + +// TestCombinedMiddleware_GoexitRecordedAs500 pins the runtime.Goexit path (e.g. t.FailNow in a +// handler): net/http closes the connection without a response, so a request that committed no +// status is recorded as a 500 at ERROR rather than the StatWriter's default 200. +func TestCombinedMiddleware_GoexitRecordedAs500(t *testing.T) { + for _, recoverOn := range []bool{true, false} { + t.Run(fmt.Sprintf("recover=%v", recoverOn), func(t *testing.T) { + buf, logger := newMemSlog() + spy := &spyObserver{} + h := middleware.New(middleware.Cfg{PanicRecover: recoverOn, Logger: logger, Metrics: spy}). + Wrap(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { runtime.Goexit() })) + + done := make(chan struct{}) + go func() { + defer close(done) + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/x", nil)) + }() + <-done + + if spy.calls != 1 || spy.status != http.StatusInternalServerError { + t.Errorf("Observe calls = %d status = %d, want 1 call with 500", spy.calls, spy.status) + } + if want := "ERROR method=GET url=/x response-code=500 "; !strings.Contains(buf.String(), want) { + t.Errorf("access log missing %q; log %q", want, buf.String()) + } + }) + } +} diff --git a/middleware/panicrecover_test.go b/middleware/panicrecover_test.go index 4403f18..ac1aada 100644 --- a/middleware/panicrecover_test.go +++ b/middleware/panicrecover_test.go @@ -1,6 +1,7 @@ package middleware_test import ( + "io" "net/http" "net/http/httptest" "strings" @@ -44,7 +45,8 @@ func TestPanicRecover_BundledMiddleware(t *testing.T) { // TestPanicRecover_NoBodyAppendedAfterStart is the regression test for a panic that fires // after the handler has already committed the response — written the header and part of the // body — without flushing. Recovery must not append "Internal Server Error" under the -// already-sent status, matching net/http, which does not write to a started response. +// already-sent status, matching net/http, which does not write to a started response. Instead +// recovery re-panics with http.ErrAbortHandler (see TestPanicRecover_StartedResponseAborts). func TestPanicRecover_NoBodyAppendedAfterStart(t *testing.T) { buf, logger := newMemSlog() m := middleware.New(middleware.Cfg{PanicRecover: true, Logger: logger}) @@ -55,7 +57,14 @@ func TestPanicRecover_NoBodyAppendedAfterStart(t *testing.T) { })) rec := httptest.NewRecorder() - handler.ServeHTTP(rec, httptest.NewRequest("GET", "/boom", nil)) + func() { + defer func() { + if got := recover(); got != http.ErrAbortHandler { + t.Errorf("expected a re-panic with http.ErrAbortHandler, got %v", got) + } + }() + handler.ServeHTTP(rec, httptest.NewRequest("GET", "/boom", nil)) + }() if rec.Code != http.StatusOK { t.Errorf("committed status 200 must stand, got %d", rec.Code) @@ -67,3 +76,48 @@ func TestPanicRecover_NoBodyAppendedAfterStart(t *testing.T) { t.Errorf("panic must still be logged, got %q", buf.String()) } } + +// TestPanicRecover_StartedResponseAborts is the regression test for a recovered panic after the +// response started: finishing it normally gave the client a clean EOF, so a truncated body +// looked complete. Recovery must abort the connection, as net/http does without recovery, while +// still logging the panic and recording the metric. +func TestPanicRecover_StartedResponseAborts(t *testing.T) { + for _, tc := range []struct { + name string + flush bool + }{ + {name: "flushed", flush: true}, + {name: "unflushed", flush: false}, + } { + t.Run(tc.name, func(t *testing.T) { + buf, logger := newMemSlog() + spy := &routeSpy{} + m := middleware.New(middleware.Cfg{PanicRecover: true, Logger: logger, Metrics: spy}) + srv := httptest.NewServer(m.Wrap(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = w.Write([]byte(`{"items":[`)) + if tc.flush { + _ = http.NewResponseController(w).Flush() + } + panic("boom mid-body") + }))) + defer srv.Close() + + resp, err := http.Get(srv.URL) + var readErr error + if err == nil { + _, readErr = io.ReadAll(resp.Body) + _ = resp.Body.Close() + } + if err == nil && readErr == nil { + t.Error("expected the client to detect the truncation, got a clean EOF") + } + srv.Close() // waits for the handler, so its log and metric are complete + if !strings.Contains(buf.String(), "panic recovered") { + t.Errorf("panic must still be logged, got %q", buf.String()) + } + if spy.calls != 1 { + t.Errorf("expected one metric observation, got %d", spy.calls) + } + }) + } +} diff --git a/middleware/race_test.go b/middleware/race_test.go new file mode 100644 index 0000000..5b065ae --- /dev/null +++ b/middleware/race_test.go @@ -0,0 +1,6 @@ +//go:build race + +package middleware_test + +// raceEnabled reports whether the tests run under the race detector. +const raceEnabled = true diff --git a/middleware/respwriter.go b/middleware/respwriter.go index 3222bde..1d6d366 100644 --- a/middleware/respwriter.go +++ b/middleware/respwriter.go @@ -76,12 +76,13 @@ type writerOnly struct { // WriteHeader records and forwards the response status code. 1xx informational responses // (e.g. 103 Early Hints) pass through without latching, so the real final status is still -// captured and written. +// captured and written. 101 Switching Protocols is the exception: it ends the HTTP/1.1 +// exchange, so it latches like a final status. func (r *StatWriter) WriteHeader(code int) { if r.headerWritten || r.hijacked { return } - if code >= 100 && code < 200 { + if code >= 100 && code < 200 && code != http.StatusSwitchingProtocols { // 1xx informational responses (e.g. 103 Early Hints) may be sent multiple // times before the final status; pass through without latching, so the // real status code is still captured and written later. @@ -132,12 +133,17 @@ func (r *StatWriter) FlushError() error { // Hijack implements http.Hijacker, both for handlers using the type assertion directly // and to record that the connection was taken over: after a hijack the middleware must -// not write a status code or body to the underlying writer. +// not write a status code or body to the underlying writer. If no status was written yet, +// 101 Switching Protocols is recorded for logs and metrics (a hijack is typically an +// upgrade whose raw response the handler writes itself); nothing is written for it. func (r *StatWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { conn, brw, err := http.NewResponseController(r.ResponseWriter).Hijack() if err != nil { return nil, nil, err } + if !r.headerWritten { + r.statusCode = http.StatusSwitchingProtocols + } // The handler now writes the raw response itself. hijacked suppresses our header // write; streaming stops the middleware from synthesising a body afterwards. r.hijacked = true diff --git a/middleware/respwriter_test.go b/middleware/respwriter_test.go index 9ce1dd8..347ac8b 100644 --- a/middleware/respwriter_test.go +++ b/middleware/respwriter_test.go @@ -215,6 +215,63 @@ func TestStatWriter_HijackSuppressesHeaderWrite(t *testing.T) { } } +// TestStatWriter_SwitchingProtocolsLatches verifies that 101 is treated as a final status: +// it is recorded for logs/metrics and flushHeader does not write a second (200) header, +// which net/http would log as "superfluous response.WriteHeader call". +func TestStatWriter_SwitchingProtocolsLatches(t *testing.T) { + crw := &countingRW{} + sw := NewWriter(crw) + + sw.WriteHeader(http.StatusSwitchingProtocols) + sw.flushHeader() + + if sw.StatusCode() != http.StatusSwitchingProtocols { + t.Errorf("expected status 101, got %d", sw.StatusCode()) + } + if crw.writeHeaderCalls != 1 { + t.Errorf("expected exactly 1 WriteHeader call, got %d", crw.writeHeaderCalls) + } + if !sw.Started() { + t.Error("a 101 response must count as started") + } +} + +// TestStatWriter_HijackRecordsSwitchingProtocols verifies that a hijack with no status +// written records 101 for logs/metrics (the handler owns the raw response, typically an +// upgrade), without writing anything to the underlying writer. +func TestStatWriter_HijackRecordsSwitchingProtocols(t *testing.T) { + hw := &hijackableRW{countingRW: countingRW{}} + sw := NewWriter(hw) + + if _, _, err := sw.Hijack(); err != nil { + t.Fatalf("unexpected hijack error: %v", err) + } + sw.flushHeader() + + if sw.StatusCode() != http.StatusSwitchingProtocols { + t.Errorf("expected status 101 after hijack, got %d", sw.StatusCode()) + } + if hw.writeHeaderCalls != 0 { + t.Errorf("expected no WriteHeader after hijack, got %d calls", hw.writeHeaderCalls) + } +} + +// TestStatWriter_HijackKeepsLatchedStatus verifies that a hijack after a final status was +// already written keeps that status rather than overwriting it with 101. +func TestStatWriter_HijackKeepsLatchedStatus(t *testing.T) { + hw := &hijackableRW{countingRW: countingRW{}} + sw := NewWriter(hw) + + sw.WriteHeader(http.StatusBadRequest) + if _, _, err := sw.Hijack(); err != nil { + t.Fatalf("unexpected hijack error: %v", err) + } + + if sw.StatusCode() != http.StatusBadRequest { + t.Errorf("expected latched status 400 to be kept, got %d", sw.StatusCode()) + } +} + // hijackableRW is a countingRW that also supports hijacking, returning a connection // backed by a net.Pipe so the call succeeds without a real server. type hijackableRW struct { @@ -540,6 +597,7 @@ func TestPanicRecover_ErrAbortHandlerPropagates(t *testing.T) { if readErr == nil { t.Error("expected a read error signalling truncation, got clean EOF") } + srv.Close() // waits for the handler, which logs the request before re-panicking if strings.Contains(logBuf.String(), "panic recovered") { t.Error("ErrAbortHandler must not be logged as a recovered panic") } diff --git a/middleware/route.go b/middleware/route.go new file mode 100644 index 0000000..0b5cc63 --- /dev/null +++ b/middleware/route.go @@ -0,0 +1,242 @@ +package middleware + +import ( + "cmp" + "context" + "net/http" + "slices" + "strings" + "sync" +) + +type routeKey struct{} + +// routeScope is the request-context value under routeKey. The slot is shared by every +// request copy below the Middleware that created it; depth counts the CaptureRoutes the +// request has passed through (0 directly under the Middleware). Depth lives in the context, +// so it follows the request path rather than the timing of the calls. +type routeScope struct { + slot *routeSlot + depth int +} + +// scopeOf returns the route scope r carries, or nil when r did not pass through a +// Middleware with metrics enabled. +func scopeOf(r *http.Request) *routeScope { + sc, _ := r.Context().Value(routeKey{}).(*routeScope) + return sc +} + +// routeSlot travels in the request context as a pointer, so a route set on any request +// copy further down the chain (gorilla/mux and chi copy the request when they match) +// is visible to the Middleware that created the slot. The mutex covers handlers that +// call SetRoute from another goroutine, e.g. under http.TimeoutHandler. +type routeSlot struct { + mu sync.Mutex + set string // from SetRoute + captured string // from the innermost CaptureRoute whose ServeMux matched + resolved string // final route, written by the Middleware before it calls the Observer + + setDepth int // scope depth of the request SetRoute was last called on + capturedDepth int // scope depth of the CaptureRoute that wrote captured (its handler's depth) +} + +// capture records pattern from a CaptureRoute whose handler runs at depth, unless a deeper +// (inner) CaptureRoute has already recorded its own. At the same depth the later one wins. +func (s *routeSlot) capture(depth int, pattern string) { + if pattern == "" { + return + } + s.mu.Lock() + defer s.mu.Unlock() + if depth >= s.capturedDepth { + s.captured, s.capturedDepth = pattern, depth + } +} + +// source returns the reported route: the innermost reporter (SetRoute or CaptureRoute, +// SetRoute on a tie), else pattern. The caller holds s.mu. +func (s *routeSlot) source(pattern string) string { + if s.set != "" && s.setDepth >= s.capturedDepth { + return s.set + } + if s.captured != "" { + return s.captured + } + if s.set != "" { + return s.set + } + return pattern +} + +func noRestore() {} + +// withRouteSlot prepares r for route resolution. Only metrics read the route, so without +// an Observer it returns r unchanged and a nil slot. Otherwise it returns a copy of r +// carrying an empty slot (or r itself when an outer Middleware already added one, so +// nested middlewares share a slot), and a restore func that copies the ServeMux pattern +// from the copy back onto the caller's request, so wrappers outside this Middleware still +// read r.Pattern after the handler. ServeMux's path values are unexported and cannot be +// copied back: r.PathValue stays empty outside the Middleware. +func (m *Middleware) withRouteSlot(r *http.Request) (*http.Request, *routeSlot, func()) { + if m.metrics == nil { + return r, nil, noRestore + } + if sc := scopeOf(r); sc != nil { + return r, sc.slot, noRestore + } + s := &routeSlot{} + cp := r.WithContext(context.WithValue(r.Context(), routeKey{}, &routeScope{slot: s})) + return cp, s, func() { r.Pattern = cp.Pattern } +} + +// SetRoute records the matched route for the current request, for routers that do not set +// r.Pattern (gorilla/mux, chi, …). Call it from inside the router, e.g. from a router-level +// middleware; it may be called before or after the handler runs, as long as it is before +// the request finishes. +// +// Pass a route template such as "/users/{id}", never the raw request path: every distinct +// value becomes its own metric series. An empty route is no report: it is ignored, so it +// neither clears nor shadows a route reported elsewhere. SetRoute is a no-op on a request +// that did not pass through a Middleware with metrics enabled. +// +// When several report a route, the innermost reporter wins: the one nested inside the most +// CaptureRoutes, whether it reports before or after the handler runs. At equal depth SetRoute +// beats a CaptureRoute, and between two SetRoute calls the later one wins. With no report the +// Middleware falls back to r.Pattern, then applies Cfg.RouteGroups to the result. +func SetRoute(r *http.Request, route string) { + sc := scopeOf(r) + if sc == nil || route == "" { + return + } + s := sc.slot + s.mu.Lock() + // An outer router's report (gorilla before dispatch, chi after the handler) must not + // override one from inside a CaptureRoute; at the same depth the later call wins. + if sc.depth >= s.setDepth { + s.set, s.setDepth = route, sc.depth + } + s.mu.Unlock() +} + +// CaptureRoute reports the pattern of the http.ServeMux it wraps, for setups where another +// wrapper sits between the Middleware and the mux and passes a request copy down +// (r.WithContext in an auth or tracing middleware, http.TimeoutHandler, http.MaxBytesHandler, +// http.StripPrefix). ServeMux writes r.Pattern onto the copy it receives, which the +// Middleware never sees, so without CaptureRoute such a route records as unmatched. Place it +// directly around the mux: m.Wrap(auth(middleware.CaptureRoute(mux))). +// +// When several report a route, the innermost reporter wins: a SetRoute or a CaptureRoute +// whose mux matched, nested inside more CaptureRoutes, beats an outer one; at equal depth +// SetRoute wins; empty reports (a mux miss, SetRoute with "") are ignored; with no report the +// Middleware uses r.Pattern; Cfg.RouteGroups is applied after. So with a mux mounted under +// another router or mux through http.StripPrefix, wrapping the inner mux records its pattern +// rather than the outer template ("/api/{version}/"), and the outer one is kept when the +// inner mux has no match. The inner pattern is relative to the stripped path +// ("GET /users/{id}", not "/api/users/{id}"); to keep the full path, register the inner mux +// with full patterns and skip StripPrefix. +// +// Around an *http.ServeMux, CaptureRoute looks the pattern up (ServeMux.Handler) before +// dispatching, so the route is recorded even when http.TimeoutHandler times out and the +// Middleware observes the 503 while the handler is still running, and even if the handler +// panics. Around any other handler it records r.Pattern after the handler returns (also on +// panic). CaptureRoute is a no-op on a request that did not pass through a Middleware with +// metrics enabled. +func CaptureRoute(mux http.Handler) http.Handler { + sm, isMux := mux.(*http.ServeMux) + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + sc := scopeOf(r) + if sc == nil { + mux.ServeHTTP(w, r) + return + } + // Hand the handler a copy one level deeper, so routes reported below this point know + // they come from inside it. The handler (a ServeMux) writes r.Pattern onto that copy; + // copy it back, also while a panic unwinds, so wrappers above still read it. + inner := &routeScope{slot: sc.slot, depth: sc.depth + 1} + cp := r.WithContext(context.WithValue(r.Context(), routeKey{}, inner)) + defer func() { r.Pattern = cp.Pattern }() + + // ServeMux.ServeHTTP answers "*" itself without matching, so leave it unrecorded. + if isMux && r.RequestURI != "*" { + _, pattern := sm.Handler(r) + inner.slot.capture(inner.depth, pattern) + } else { + defer func() { inner.slot.capture(inner.depth, cp.Pattern) }() + } + mux.ServeHTTP(w, cp) + }) +} + +// Route returns the route an Observer should record for r: the route the Middleware +// resolved, or "" when no route matched. The innermost non-empty report wins (SetRoute or +// CaptureRoute, SetRoute at equal depth), else r.Pattern, then Cfg.RouteGroups is applied. +// On a request that did not pass through a Middleware with metrics enabled it returns +// r.Pattern. +func Route(r *http.Request) string { + sc := scopeOf(r) + if sc == nil { + return r.Pattern + } + s := sc.slot + s.mu.Lock() + defer s.mu.Unlock() + // Grouping never empties a route, so an empty resolved value means nothing resolved yet + // or nothing matched; either way the raw sources give the right answer. + if s.resolved != "" { + return s.resolved + } + return s.source(r.Pattern) +} + +// resolveRoute settles the route for r, after the handler has run, and stores it in the +// slot for Route to return: the innermost non-empty report (SetRoute or CaptureRoute, +// SetRoute at equal depth), else r.Pattern, then mapped through the route groups. Each +// nested Middleware resolves from the raw sources with its own groups. +func (m *Middleware) resolveRoute(r *http.Request, s *routeSlot) { + s.mu.Lock() + defer s.mu.Unlock() + s.resolved = m.routeGroups.apply(s.source(r.Pattern)) +} + +// routeGroups is a list of path prefixes, longest first, that collapse every route beneath +// them into the prefix itself. +type routeGroups []string + +// newRouteGroups normalises the prefixes to clean paths: a leading method ("GET /api") is +// stripped, repeated leading and trailing slashes are dropped and one leading slash added, +// so "api", "/api/", "//api" and "GET /api" are all "/api". A bare "/" (or empty string) +// is ignored, since it would collapse every route into one. +func newRouteGroups(prefixes []string) routeGroups { + var g routeGroups + for _, p := range prefixes { + p = strings.TrimSpace(p) + if i := strings.LastIndexByte(p, ' '); i >= 0 { + p = p[i+1:] + } + p = strings.Trim(p, "/") + if p == "" { + continue + } + g = append(g, "/"+p) + } + slices.SortStableFunc(g, func(a, b string) int { return cmp.Compare(len(b), len(a)) }) + return g +} + +// apply maps route onto its group. Any method or host before the path is kept +// ("GET /api/apple" → "GET /api"), and prefixes match whole segments only, so "/api" +// groups "/api/apple" but not "/apiary". +func (g routeGroups) apply(route string) string { + i := strings.IndexByte(route, '/') + if i < 0 { + return route + } + head, path := route[:i], route[i:] + for _, p := range g { + if path == p || strings.HasPrefix(path, p+"/") { + return head + p + } + } + return route +} diff --git a/middleware/route_test.go b/middleware/route_test.go new file mode 100644 index 0000000..3a4be38 --- /dev/null +++ b/middleware/route_test.go @@ -0,0 +1,536 @@ +package middleware_test + +import ( + "context" + "errors" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/go-bumbu/http/middleware" +) + +// routeSpy records the route the Observer sees via middleware.Route. +type routeSpy struct { + calls int + route string +} + +func (s *routeSpy) Observe(_ int, r *http.Request, _ time.Duration) { + s.calls++ + s.route = middleware.Route(r) +} + +// serve wraps h with a Middleware built from cfg (Metrics set to a fresh spy), +// serves one request to target, and returns the route the observer saw. +func serve(t *testing.T, cfg middleware.Cfg, h http.Handler, target string) string { + t.Helper() + spy := &routeSpy{} + cfg.Metrics = spy + middleware.New(cfg).Wrap(h).ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", target, nil)) + if spy.calls != 1 { + t.Fatalf("Observe called %d times, want 1", spy.calls) + } + return spy.route +} + +// setRoute returns a handler that reports route via SetRoute, then writes 200. +func setRoute(route string) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + middleware.SetRoute(r, route) + w.WriteHeader(200) + }) +} + +// TestRoute_ServeMuxPattern is the regression guard for the route slot: the middleware +// passes a request copy down the chain, and ServeMux writes r.Pattern onto that copy, so +// the observer must be handed the copy — otherwise every stdlib route reads as empty. +func TestRoute_ServeMuxPattern(t *testing.T) { + mux := http.NewServeMux() + mux.Handle("GET /users/{id}", testHandler(200, "ok")) + + if got := serve(t, middleware.Cfg{}, mux, "/users/42"); got != "GET /users/{id}" { + t.Errorf("route = %q, want %q", got, "GET /users/{id}") + } + if got := serve(t, middleware.Cfg{}, mux, "/nope"); got != "" { + t.Errorf("unmatched route = %q, want empty", got) + } +} + +// TestRoute_SetRouteBeatsPattern checks the resolution order: SetRoute, then r.Pattern. +func TestRoute_SetRouteBeatsPattern(t *testing.T) { + mux := http.NewServeMux() + mux.Handle("GET /p", setRoute("/explicit")) + if got := serve(t, middleware.Cfg{}, mux, "/p"); got != "/explicit" { + t.Errorf("route = %q, want %q", got, "/explicit") + } +} + +// TestRoute_OuterSeesPattern guards wrappers outside the Middleware (tracing, access logs) +// that read r.Pattern after the handler: the Middleware passes a copy down, so it must hand +// the ServeMux pattern back to the caller's request — also when a panic unwinds. +func TestRoute_OuterSeesPattern(t *testing.T) { + mux := http.NewServeMux() + mux.Handle("GET /u/{id}", testHandler(200, "ok")) + mux.Handle("GET /abort", http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + panic(http.ErrAbortHandler) + })) + + tcs := []struct { + name string + cfg middleware.Cfg + h http.Handler // defaults to mux + target string + want string + }{ + {name: "metrics off", cfg: middleware.Cfg{}, target: "/u/1", want: "GET /u/{id}"}, + {name: "metrics on", cfg: middleware.Cfg{Metrics: &routeSpy{}}, target: "/u/1", want: "GET /u/{id}"}, + {name: "abort panic", cfg: middleware.Cfg{Metrics: &routeSpy{}, PanicRecover: true}, target: "/abort", want: "GET /abort"}, + {name: "CaptureRoute directly under Wrap", cfg: middleware.Cfg{Metrics: &routeSpy{}}, h: middleware.CaptureRoute(mux), target: "/u/1", want: "GET /u/{id}"}, + {name: "CaptureRoute abort panic", cfg: middleware.Cfg{Metrics: &routeSpy{}, PanicRecover: true}, h: middleware.CaptureRoute(mux), target: "/abort", want: "GET /abort"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + next := tc.h + if next == nil { + next = mux + } + h := middleware.New(tc.cfg).Wrap(next) + r := httptest.NewRequest("GET", tc.target, nil) + func() { + defer func() { _ = recover() }() // the abort case re-panics by design + h.ServeHTTP(httptest.NewRecorder(), r) + }() + if r.Pattern != tc.want { + t.Errorf("outer r.Pattern = %q, want %q", r.Pattern, tc.want) + } + }) + } +} + +// TestRoute_NoCopyWithoutMetrics checks the route slot (and its request copy) is only paid +// for when an Observer is configured. +func TestRoute_NoCopyWithoutMetrics(t *testing.T) { + for _, tc := range []struct { + name string + cfg middleware.Cfg + wantSame bool + }{ + {name: "metrics off", cfg: middleware.Cfg{}, wantSame: true}, + {name: "metrics on", cfg: middleware.Cfg{Metrics: &routeSpy{}}, wantSame: false}, + } { + t.Run(tc.name, func(t *testing.T) { + var got *http.Request + h := middleware.New(tc.cfg).Wrap(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + got = r + })) + r := httptest.NewRequest("GET", "/", nil) + h.ServeHTTP(httptest.NewRecorder(), r) + if (got == r) != tc.wantSame { + t.Errorf("handler got the caller's request = %v, want %v", got == r, tc.wantSame) + } + }) + } +} + +type routerKey struct{} + +// fakeRouter mimics gorilla/mux: on a match it stores the route template on a request +// copy's context and calls next with that copy. +func fakeRouter(template string, next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r.WithContext(context.WithValue(r.Context(), routerKey{}, template))) + }) +} + +// routeFromRouter mimics the app's glue: a router-level middleware that reads the match +// (mux.CurrentRoute in gorilla) and reports it with SetRoute. +func routeFromRouter(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + route, _ := r.Context().Value(routerKey{}).(string) + middleware.SetRoute(r, route) + next.ServeHTTP(w, r) + }) +} + +// TestRoute_RouterUseMode mimics gorilla's router.Use(m.Wrap, routeFromRouter): the router +// matches first, then runs the Middleware, then the glue inside it. +func TestRoute_RouterUseMode(t *testing.T) { + spy := &routeSpy{} + m := middleware.New(middleware.Cfg{Metrics: spy}) + h := fakeRouter("/users/{id}", m.Wrap(routeFromRouter(testHandler(200, "ok")))) + + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/users/1", nil)) + if spy.route != "/users/{id}" { + t.Errorf("route = %q, want %q", spy.route, "/users/{id}") + } +} + +// TestRoute_WrapWholeRouter mimics m.Wrap(router) with the glue inside the router: the +// router copies the request, and SetRoute on the copy must still reach the Middleware. +func TestRoute_WrapWholeRouter(t *testing.T) { + router := fakeRouter("/users/{id}", routeFromRouter(testHandler(200, "ok"))) + if got := serve(t, middleware.Cfg{}, router, "/users/1"); got != "/users/{id}" { + t.Errorf("route = %q, want %q", got, "/users/{id}") + } +} + +// TestRoute_Nested checks that nested middlewares share one slot, each resolving the route +// from the raw sources with its own groups, and that an inner Middleware with metrics works +// under an outer one without. +func TestRoute_Nested(t *testing.T) { + api := []string{"/api"} + tcs := []struct { + name string + outer, inner middleware.Cfg + wantOuter, wantInner string + }{ + {name: "outer groups", outer: middleware.Cfg{RouteGroups: api}, wantOuter: "/api", wantInner: "/api/items/{id}"}, + {name: "inner groups", inner: middleware.Cfg{RouteGroups: api}, wantOuter: "/api/items/{id}", wantInner: "/api"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + outer, inner := &routeSpy{}, &routeSpy{} + tc.outer.Metrics, tc.inner.Metrics = outer, inner + h := middleware.New(tc.outer).Wrap(middleware.New(tc.inner).Wrap(setRoute("/api/items/{id}"))) + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/api/items/1", nil)) + if outer.route != tc.wantOuter { + t.Errorf("outer route = %q, want %q", outer.route, tc.wantOuter) + } + if inner.route != tc.wantInner { + t.Errorf("inner route = %q, want %q", inner.route, tc.wantInner) + } + }) + } + + t.Run("outer without metrics", func(t *testing.T) { + inner := &routeSpy{} + h := middleware.New(middleware.Cfg{}).Wrap( + middleware.New(middleware.Cfg{Metrics: inner}).Wrap(setRoute("/x/{id}"))) + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/x/1", nil)) + if inner.route != "/x/{id}" { + t.Errorf("inner route = %q, want %q", inner.route, "/x/{id}") + } + }) +} + +// TestRoute_Panic checks the route is resolved when the observer runs from panic recovery. +func TestRoute_Panic(t *testing.T) { + h := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + middleware.SetRoute(r, "/boom") + panic("boom") + }) + if got := serve(t, middleware.Cfg{PanicRecover: true}, h, "/boom"); got != "/boom" { + t.Errorf("route = %q, want %q", got, "/boom") + } +} + +// TestRoute_AbortPanic checks the route is resolved on the http.ErrAbortHandler path, +// where the Middleware records the metric and then re-panics. +func TestRoute_AbortPanic(t *testing.T) { + spy := &routeSpy{} + h := middleware.New(middleware.Cfg{Metrics: spy, PanicRecover: true}).Wrap( + http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + middleware.SetRoute(r, "/abort") + panic(http.ErrAbortHandler) + })) + + func() { + defer func() { + rec := recover() + if err, ok := rec.(error); !ok || !errors.Is(err, http.ErrAbortHandler) { + t.Errorf("recovered %v, want http.ErrAbortHandler", rec) + } + }() + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/abort", nil)) + }() + if spy.calls != 1 || spy.route != "/abort" { + t.Errorf("calls = %d, route = %q, want 1 and %q", spy.calls, spy.route, "/abort") + } +} + +// TestRoute_SetRouteAfterTimeout pins down why the slot has a mutex: under +// http.TimeoutHandler the handler goroutine can call SetRoute while the Middleware is +// resolving the route. Nothing orders the two accesses, so without the lock -race reports +// them; the resolved route itself depends on timing and is not asserted. +func TestRoute_SetRouteAfterTimeout(t *testing.T) { + done := make(chan struct{}) + slow := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + defer close(done) + time.Sleep(5 * time.Millisecond) + middleware.SetRoute(r, "/late") + }) + h := middleware.New(middleware.Cfg{Metrics: &routeSpy{}}).Wrap(http.TimeoutHandler(slow, time.Millisecond, "timeout")) + + rec := httptest.NewRecorder() + h.ServeHTTP(rec, httptest.NewRequest("GET", "/slow", nil)) + <-done + + if rec.Code != http.StatusServiceUnavailable { + t.Errorf("status = %d, want %d", rec.Code, http.StatusServiceUnavailable) + } +} + +// TestRoute_OutsideMiddleware: SetRoute is a no-op and Route falls back to r.Pattern. +func TestRoute_OutsideMiddleware(t *testing.T) { + r := httptest.NewRequest("GET", "/x", nil) + middleware.SetRoute(r, "/ignored") + if got := middleware.Route(r); got != "" { + t.Errorf("route = %q, want empty", got) + } + r.Pattern = "/x" + if got := middleware.Route(r); got != "/x" { + t.Errorf("route = %q, want %q", got, "/x") + } +} + +type ctxKey struct{} + +// withContext stands in for an auth/tracing middleware: it passes a request copy down, so +// the pattern ServeMux writes onto that copy never reaches the Middleware's request. +func withContext(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r.WithContext(context.WithValue(r.Context(), ctxKey{}, "v"))) + }) +} + +// TestRoute_CaptureRoute covers a request-copying wrapper between the Middleware and a +// ServeMux: without CaptureRoute the pattern is lost (or the outer, less specific one is +// recorded); CaptureRoute directly around each mux reports it, and the innermost wins. +func TestRoute_CaptureRoute(t *testing.T) { + mux := http.NewServeMux() + mux.Handle("GET /users/{id}", testHandler(200, "ok")) + mux.Handle("GET /boom", http.HandlerFunc(func(http.ResponseWriter, *http.Request) { panic("boom") })) + + inner := http.NewServeMux() + inner.Handle("GET /users/{id}", testHandler(200, "ok")) + inner.Handle("GET /explicit", setRoute("/api/explicit")) + nested := func(capture bool) http.Handler { + var h http.Handler = inner + if capture { + h = middleware.CaptureRoute(inner) + } + outer := http.NewServeMux() + outer.Handle("/api/", http.StripPrefix("/api", h)) + return outer + } + + tcs := []struct { + name string + cfg middleware.Cfg + h http.Handler + target string + want string + }{ + {name: "copy hides the pattern", h: withContext(mux), target: "/users/1", want: ""}, + {name: "WithContext", h: withContext(middleware.CaptureRoute(mux)), target: "/users/1", want: "GET /users/{id}"}, + {name: "TimeoutHandler", h: http.TimeoutHandler(middleware.CaptureRoute(mux), time.Second, "timeout"), target: "/users/1", want: "GET /users/{id}"}, + {name: "MaxBytesHandler", h: http.MaxBytesHandler(middleware.CaptureRoute(mux), 1<<10), target: "/users/1", want: "GET /users/{id}"}, + {name: "unmatched", h: withContext(middleware.CaptureRoute(mux)), target: "/nope", want: ""}, + {name: "panic", cfg: middleware.Cfg{PanicRecover: true}, h: withContext(middleware.CaptureRoute(mux)), target: "/boom", want: "GET /boom"}, + {name: "groups apply", cfg: middleware.Cfg{RouteGroups: []string{"/users"}}, h: withContext(middleware.CaptureRoute(mux)), target: "/users/1", want: "GET /users"}, + {name: "StripPrefix records the outer pattern", h: nested(false), target: "/api/users/1", want: "/api/"}, + {name: "StripPrefix inner capture wins", h: nested(true), target: "/api/users/1", want: "GET /users/{id}"}, + {name: "StripPrefix outer capture does not override inner", h: middleware.CaptureRoute(nested(true)), target: "/api/users/1", want: "GET /users/{id}"}, + {name: "StripPrefix inner miss falls back to outer", h: middleware.CaptureRoute(nested(true)), target: "/api/nope", want: "/api/"}, + {name: "inner SetRoute beats its mux capture", h: middleware.CaptureRoute(nested(true)), target: "/api/explicit", want: "/api/explicit"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + if got := serve(t, tc.cfg, tc.h, tc.target); got != tc.want { + t.Errorf("route = %q, want %q", got, tc.want) + } + }) + } + + t.Run("matches what the mux records", func(t *testing.T) { + tree := http.NewServeMux() + tree.Handle("/tree/", testHandler(200, "ok")) + tree.Handle("POST /form", testHandler(200, "ok")) + for _, target := range []string{"/tree/x", "/tree", "/a/../tree/x", "/form", "/nope"} { + if got, want := serve(t, middleware.Cfg{}, withContext(middleware.CaptureRoute(tree)), target), serve(t, middleware.Cfg{}, tree, target); got != want { + t.Errorf("%s: route = %q, want %q", target, got, want) + } + } + }) + + // A CaptureRoute around a handler that is not a ServeMux records after it returns; an + // outer CaptureRoute around a ServeMux records before dispatch, and must not block it. + t.Run("inner non-mux capture beats outer mux capture", func(t *testing.T) { + outer := http.NewServeMux() + outer.Handle("/api/", http.StripPrefix("/api", middleware.CaptureRoute(http.HandlerFunc(inner.ServeHTTP)))) + if got := serve(t, middleware.Cfg{}, middleware.CaptureRoute(outer), "/api/users/1"); got != "GET /users/{id}" { + t.Errorf("route = %q, want %q", got, "GET /users/{id}") + } + }) + + t.Run("without a Middleware", func(t *testing.T) { + rec := httptest.NewRecorder() + middleware.CaptureRoute(mux).ServeHTTP(rec, httptest.NewRequest("GET", "/users/1", nil)) + if rec.Code != 200 { + t.Errorf("status = %d, want 200", rec.Code) + } + }) +} + +// setRouteAfter mimics chi's Mount with the README glue: it passes a request copy down and +// reports its own template with SetRoute after the handler returns. +func setRouteAfter(template string, next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r.WithContext(context.WithValue(r.Context(), routerKey{}, template))) + middleware.SetRoute(r, template) + }) +} + +// TestRoute_InnermostReporterWins: when an outer router reports its template with SetRoute +// and a nested ServeMux is wrapped in CaptureRoute, the innermost reporter wins, regardless +// of whether the outer router reports before or after the handler. At the same depth +// SetRoute wins, and SetRoute anywhere beats the pattern the Middleware itself sees. +func TestRoute_InnermostReporterWins(t *testing.T) { + inner := http.NewServeMux() + inner.Handle("GET /users/{id}", testHandler(200, "ok")) + inner.Handle("GET /explicit", setRoute("/explicit")) + + // gorilla: PathPrefix("/api/{version}/").Handler(StripPrefix(CaptureRoute(mux))) with + // router.Use(setRoute), which reports before dispatch. + gorilla := fakeRouter("/api/{version}/", routeFromRouter(http.StripPrefix("/api/v1", middleware.CaptureRoute(inner)))) + // chi: Mount("/api", CaptureRoute(mux)) with SetRoute called after the handler. + chi := setRouteAfter("/api/*", http.StripPrefix("/api", middleware.CaptureRoute(inner))) + + depth0 := http.NewServeMux() + depth0.Handle("GET /p", setRoute("/explicit")) + + // An inner SetRoute with an empty route is no report: it must not shadow the outer one. + emptyInner := setRouteAfter("/api/{v}/", http.StripPrefix("/api", middleware.CaptureRoute( + http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + middleware.SetRoute(r, "") + inner.ServeHTTP(w, r) + })))) + + tcs := []struct { + name string + h http.Handler + target string + want string + }{ + {name: "outer SetRoute before dispatch", h: gorilla, target: "/api/v1/users/1", want: "GET /users/{id}"}, + {name: "outer SetRoute after the handler", h: chi, target: "/api/users/1", want: "GET /users/{id}"}, + {name: "inner mux miss falls back to outer SetRoute", h: gorilla, target: "/api/v1/nope", want: "/api/{version}/"}, + {name: "inner mux miss falls back to outer SetRoute after the handler", h: chi, target: "/api/nope", want: "/api/*"}, + {name: "inner SetRoute beats outer SetRoute before dispatch", h: gorilla, target: "/api/v1/explicit", want: "/explicit"}, + {name: "inner SetRoute beats outer SetRoute after the handler", h: chi, target: "/api/explicit", want: "/explicit"}, + {name: "SetRoute at depth 0 beats the pattern", h: depth0, target: "/p", want: "/explicit"}, + {name: "inner empty SetRoute does not shadow outer SetRoute", h: emptyInner, target: "/api/nope", want: "/api/{v}/"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + if got := serve(t, middleware.Cfg{}, tc.h, tc.target); got != tc.want { + t.Errorf("route = %q, want %q", got, tc.want) + } + }) + } + + // The Middleware resolves while the timed-out handler still runs; the capture recorded + // before dispatch is deeper than the outer SetRoute, whenever that is called. + for _, tc := range []struct { + name string + wrap func(http.Handler) http.Handler + }{ + {name: "outer SetRoute before dispatch with timeout", wrap: func(h http.Handler) http.Handler { + return fakeRouter("/slow/", routeFromRouter(h)) + }}, + {name: "outer SetRoute after the handler with timeout", wrap: func(h http.Handler) http.Handler { + return setRouteAfter("/slow/*", h) + }}, + } { + t.Run(tc.name, func(t *testing.T) { + release := make(chan struct{}) + done := make(chan struct{}) + mux := http.NewServeMux() + mux.Handle("GET /slow/{id}", http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + defer close(done) + <-release + })) + + spy := &statusRouteSpy{} + h := middleware.New(middleware.Cfg{Metrics: spy}). + Wrap(tc.wrap(http.TimeoutHandler(middleware.CaptureRoute(mux), 50*time.Millisecond, "timeout"))) + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/slow/1", nil)) + close(release) + <-done + + if spy.status != http.StatusServiceUnavailable || spy.route != "GET /slow/{id}" { + t.Errorf("status = %d, route = %q, want %d and %q", spy.status, spy.route, http.StatusServiceUnavailable, "GET /slow/{id}") + } + }) + } +} + +type statusRouteSpy struct { + status int + route string +} + +func (s *statusRouteSpy) Observe(status int, r *http.Request, _ time.Duration) { + s.status = status + s.route = middleware.Route(r) +} + +// TestRoute_CaptureRouteTimeout: when http.TimeoutHandler times out, the Middleware +// resolves the route while the mux handler is still running, so CaptureRoute must record +// the pattern before dispatch, not after the mux returns. +func TestRoute_CaptureRouteTimeout(t *testing.T) { + release := make(chan struct{}) + done := make(chan struct{}) + mux := http.NewServeMux() + mux.Handle("GET /slow/{id}", http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + defer close(done) + <-release + })) + + spy := &statusRouteSpy{} + h := middleware.New(middleware.Cfg{Metrics: spy}). + Wrap(http.TimeoutHandler(middleware.CaptureRoute(mux), 50*time.Millisecond, "timeout")) + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/slow/1", nil)) + close(release) + <-done + + if spy.status != http.StatusServiceUnavailable || spy.route != "GET /slow/{id}" { + t.Errorf("status = %d, route = %q, want %d and %q", spy.status, spy.route, http.StatusServiceUnavailable, "GET /slow/{id}") + } +} + +func TestRoute_Groups(t *testing.T) { + tcs := []struct { + name string + groups []string + route string + want string + }{ + {name: "groups a sub-route", groups: []string{"/api"}, route: "/api/banana", want: "/api"}, + {name: "keeps the method", groups: []string{"/api"}, route: "GET /api/apple/{id}", want: "GET /api"}, + {name: "keeps a host", groups: []string{"/api"}, route: "GET example.com/api/x", want: "GET example.com/api"}, + {name: "exact match", groups: []string{"/api"}, route: "/api", want: "/api"}, + {name: "subtree pattern", groups: []string{"/api"}, route: "/api/", want: "/api"}, + {name: "whole segments only", groups: []string{"/api"}, route: "/apiary", want: "/apiary"}, + {name: "longest prefix wins", groups: []string{"/api", "/api/admin"}, route: "/api/admin/users", want: "/api/admin"}, + {name: "missing and trailing slash", groups: []string{"api/"}, route: "/api/x", want: "/api"}, + {name: "repeated slashes", groups: []string{"//api//"}, route: "/api/x", want: "/api"}, + {name: "method stripped from prefix", groups: []string{"GET /api"}, route: "POST /api/x", want: "POST /api"}, + {name: "bare slash ignored", groups: []string{"/"}, route: "/x/y", want: "/x/y"}, + {name: "no route stays empty", groups: []string{"/api"}, route: "", want: ""}, + {name: "unrelated route untouched", groups: []string{"/api"}, route: "/home", want: "/home"}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + if got := serve(t, middleware.Cfg{RouteGroups: tc.groups}, setRoute(tc.route), "/"); got != tc.want { + t.Errorf("route = %q, want %q", got, tc.want) + } + }) + } +} + +type nopObserver struct{} + +func (nopObserver) Observe(int, *http.Request, time.Duration) {} diff --git a/middleware/slog.go b/middleware/slog.go index 74d2d1b..0efaaab 100644 --- a/middleware/slog.go +++ b/middleware/slog.go @@ -87,10 +87,10 @@ func (m *Middleware) log(r *http.Request, statusCode int, errmsg string, dur tim attrs := []slog.Attr{ slog.String("method", r.Method), - slog.String("url", r.RequestURI), + slog.String("url", logURL(r)), slog.Duration("req-dur", dur), slog.Int("response-code", statusCode), - slog.String("ip", userIp(r)), + slog.String("ip", m.clientIP(r)), slog.String("req-id", m.requestID(r)), } if IsStatusError(statusCode) { @@ -118,7 +118,7 @@ func (m *Middleware) logHeadersDebug(r *http.Request, respHeaders http.Header) { } attrs := []slog.Attr{ slog.String("method", r.Method), - slog.String("url", r.RequestURI), + slog.String("url", logURL(r)), slog.String("req-id", m.requestID(r)), m.redact.headerAttrs("req-headers", r.Header, m.disableRedaction), m.redact.headerAttrs("resp-headers", respHeaders, m.disableRedaction), @@ -126,17 +126,9 @@ func (m *Middleware) logHeadersDebug(r *http.Request, respHeaders http.Header) { m.logger.LogAttrs(r.Context(), slog.LevelDebug, "", attrs...) } -// userIp returns the client IP for logging. X-Real-Ip and X-Forwarded-For are trusted -// unconditionally: this assumes the server runs behind a reverse proxy that sets them. -// If the server is exposed directly, clients can spoof these headers — do not use the -// logged IP for security decisions. -func userIp(r *http.Request) string { - IPAddress := r.Header.Get("X-Real-Ip") - if IPAddress == "" { - IPAddress = r.Header.Get("X-Forwarded-For") - } - if IPAddress == "" { - IPAddress = r.RemoteAddr - } - return IPAddress +// logURL returns the request path for the "url" log field. The query string is deliberately +// dropped: it often carries tokens, signatures, or reset codes that must not end up in logs. +// The escaped form is used so an encoded "%2F" stays distinguishable from a real "/". +func logURL(r *http.Request) string { + return r.URL.EscapedPath() } diff --git a/middleware/slog_test.go b/middleware/slog_test.go index 6f812ac..bca0337 100644 --- a/middleware/slog_test.go +++ b/middleware/slog_test.go @@ -77,6 +77,40 @@ func TestSlogMiddleware(t *testing.T) { } } +// TestLog_URLOmitsQuery verifies that every log record (access, debug headers, panic) logs only +// the request path: query strings often carry tokens or signatures that must not reach logs. +func TestLog_URLOmitsQuery(t *testing.T) { + tcs := []struct { + name string + handler http.Handler + }{ + {name: "access and debug header log", handler: testHandler(200, "ok")}, + {name: "panic log", handler: http.HandlerFunc(func(http.ResponseWriter, *http.Request) { panic("boom") })}, + } + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + buf, logger := newMemSlog() + m := middleware.New(middleware.Cfg{Logger: logger, LogHeaders: true, PanicRecover: true}) + handler := m.Wrap(tc.handler) + + rec := httptest.NewRecorder() + req := httptest.NewRequest("GET", "/reset/a%2Fb?token=s3cret&page=2", nil) + handler.ServeHTTP(rec, req) + + got := buf.String() + // The escaped path is kept so an encoded slash stays distinguishable from a real one. + if n := strings.Count(got, "url=/reset/a%2Fb "); n < 2 { + t.Errorf("expected at least 2 records with the escaped path, got %d\nfull log:\n%s", n, got) + } + for _, avoid := range []string{"token", "s3cret"} { + if strings.Contains(got, avoid) { + t.Errorf("log unexpectedly contained %q\nfull log:\n%s", avoid, got) + } + } + }) + } +} + // TestLog_RequestID verifies the "req-id" field: the default extractor reads the Request-Id // header, and a Cfg.RequestID override reads whatever header (or context) it chooses. func TestLog_RequestID(t *testing.T) { diff --git a/outbound/outbound.go b/outbound/outbound.go index 98e7d18..3dafc40 100644 --- a/outbound/outbound.go +++ b/outbound/outbound.go @@ -14,6 +14,7 @@ import ( "context" "errors" "fmt" + "io" "net/http" "strconv" "time" @@ -197,14 +198,27 @@ func UserMessage(err error, fallback string) string { // them at construction rather than mutating a Client after New. type Cfg struct { // Service is the provider's display name, used in error messages. - Service string + Service string + // UserAgent is the default User-Agent; a User-Agent in Get's header + // argument overrides it for that call. UserAgent string // RPS throttles requests to this many per second (burst 1). A value <= 0 // leaves the client unthrottled. RPS float64 - // Client overrides the default *http.Client (20s timeout). + // Client overrides the default *http.Client (20s timeout). Its timeout + // bounds each attempt, not the whole call; see Timeout. Client *http.Client + // Timeout is an overall budget for one Get call: every attempt, the + // backoff and Retry-After waits between them, and reading the response + // body (like http.Client.Timeout, it stays armed until the caller closes + // the body). When it runs out, Get stops retrying: if an attempt already + // failed upstream, that *Error is returned (see Get); otherwise the call + // fails as a KindTimeout *Error. Either way errors.Is(err, + // context.DeadlineExceeded) holds. Zero (or negative) adds no budget, so a + // call is bounded only by ctx and MaxAttempts × the per-attempt timeout + // plus backoff — about a minute with the defaults. + Timeout time.Duration // Limiter overrides the limiter built from RPS. Limiter *rate.Limiter // MaxAttempts bounds the total number of requests per call (1 = no retry); @@ -232,6 +246,7 @@ type Client struct { maxAttempts int backoff time.Duration retryAfterCap time.Duration + timeout time.Duration wait func(ctx context.Context, d time.Duration) error } @@ -246,6 +261,7 @@ func New(cfg Cfg) *Client { maxAttempts: cfg.MaxAttempts, backoff: cfg.Backoff, retryAfterCap: cfg.RetryAfterCap, + timeout: cfg.Timeout, wait: cfg.Wait, } if c.client == nil { @@ -288,8 +304,67 @@ func sleep(ctx context.Context, d time.Duration) error { // "404 = no data here", which is not an error for most providers); every other // non-2xx becomes an *Error. // +// If ctx ends (or the throttle fails) after an attempt already failed upstream, +// the returned error wraps both: errors.As finds that upstream *Error, whose +// Kind still decides HTTPStatus and UserMessage, and errors.Is matches the +// context error. Before any upstream failure, the context error is returned +// as-is. +// +// Cfg.Timeout, when set, bounds the whole call including the body read. +// +// Each header name in header replaces the client's default for that name (e.g. +// Cfg.UserAgent); multiple values under one name are all sent. +// // On success the caller owns resp.Body and must close it. func (c *Client) Get(ctx context.Context, url string, header http.Header, allowStatus ...int) (*http.Response, error) { + if c.timeout <= 0 { + return c.get(ctx, url, header, allowStatus) + } + bctx, cancel := context.WithTimeout(ctx, c.timeout) + resp, err := c.get(bctx, url, header, allowStatus) + if err != nil { + budgetSpent := ctx.Err() == nil && + (bctx.Err() != nil || (errors.Is(err, context.DeadlineExceeded) && budgetIsEarliest(ctx, bctx))) + cancel() + var uerr *Error + if budgetSpent && !errors.As(err, &uerr) { + // Our own budget ran out before any upstream failure: that is the + // provider being too slow, not the caller giving up. + return nil, &Error{Service: c.service, Kind: KindTimeout, Err: err, Attempts: 1} + } + return nil, err + } + // The budget covers the body read, so release it only when the caller + // closes the body. + resp.Body = &cancelOnClose{ReadCloser: resp.Body, cancel: cancel} + return resp, nil +} + +// budgetIsEarliest reports whether bctx's deadline (the Cfg.Timeout budget) is +// earlier than the caller ctx's own. A deadline error raised before either +// expires (a throttle wait refused for outlasting the deadline) is then ours, +// not the caller's. +func budgetIsEarliest(ctx, bctx context.Context) bool { + budget, _ := bctx.Deadline() + caller, ok := ctx.Deadline() + return !ok || budget.Before(caller) +} + +// cancelOnClose releases a Get's time budget when the response body is closed. +type cancelOnClose struct { + io.ReadCloser + cancel context.CancelFunc +} + +func (b *cancelOnClose) Close() error { + err := b.ReadCloser.Close() + b.cancel() + return err +} + +// get is the retry loop behind Get, running under ctx (already carrying the +// Cfg.Timeout budget when one is set). +func (c *Client) get(ctx context.Context, url string, header http.Header, allowStatus []int) (*http.Response, error) { attempts := c.maxAttempts backoff := c.backoff var last *Error @@ -300,8 +375,15 @@ func (c *Client) Get(ctx context.Context, url string, header http.Header, allowS if last != nil && last.retryAfter > 0 { wait = last.retryAfter } + // A wait that would outlast the deadline (the Cfg.Timeout budget or + // the caller's own) can never lead to another attempt: fail now + // with the error sleeping it out would end in, rather than burning + // the rest of the latency budget first. + if deadline, ok := ctx.Deadline(); ok && wait > time.Until(deadline) { + return nil, withLast(last, context.DeadlineExceeded) + } if err := c.wait(ctx, wait); err != nil { - return nil, err + return nil, withLast(last, err) } backoff *= 2 } @@ -312,7 +394,7 @@ func (c *Client) Get(ctx context.Context, url string, header http.Header, allowS // them as-is and do not burn retries on them. var uerr *Error if !errors.As(err, &uerr) { - return nil, err + return nil, withLast(last, err) } uerr.Attempts = attempt if !uerr.retryable { @@ -327,7 +409,7 @@ func (c *Client) Get(ctx context.Context, url string, header http.Header, allowS } serr := c.statusError(resp) - _ = resp.Body.Close() + discardBody(resp.Body) serr.Attempts = attempt if !serr.retryable { return nil, serr @@ -341,6 +423,34 @@ func (c *Client) Get(ctx context.Context, url string, header http.Header, allowS return nil, last } +// maxDrainBytes bounds how much of a discarded response body is read so its +// keep-alive connection can be reused; a larger body is not worth reading and +// the Transport simply closes that connection. +const maxDrainBytes = 64 << 10 + +// discardBody drains (up to maxDrainBytes) and closes a response body we will +// not return. Closing an unread body makes the Transport drop the connection, +// so every retry during a 5xx/429 storm would otherwise open a new TCP/TLS +// connection. +func discardBody(body io.ReadCloser) { + _, _ = io.CopyN(io.Discard, body, maxDrainBytes) + _ = body.Close() +} + +// withLast attaches the upstream failure of a previous attempt to err, an +// error of our own (a cancelled context, an expired deadline, the throttle) +// that cut the retry loop short. Dropping last would turn a precise upstream +// failure into a bare "context canceled" that callers can only render +// generically, so both stay in the chain: errors.As finds the *Error — whose +// Kind decides HTTPStatus and UserMessage — and errors.Is still matches the +// context error. With no previous failure, err is returned unchanged. +func withLast(last *Error, err error) error { + if last == nil { + return err + } + return fmt.Errorf("%w: %w", last, err) +} + // do performs one throttled request, classifying transport failures. func (c *Client) do(ctx context.Context, url string, header http.Header) (*http.Response, error) { req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil) @@ -350,6 +460,13 @@ func (c *Client) do(ctx context.Context, url string, header http.Header) (*http. if c.userAgent != "" { req.Header.Set("User-Agent", c.userAgent) } + // Each caller header replaces any default under the same name (so a + // per-call User-Agent wins over Cfg.UserAgent instead of being dropped by + // the Transport, which sends only the first value) while keeping all of the + // caller's own values for that name. + for k := range header { + req.Header.Del(k) + } for k, vals := range header { for _, v := range vals { req.Header.Add(k, v) @@ -357,7 +474,7 @@ func (c *Client) do(ctx context.Context, url string, header http.Header) (*http. } if c.limiter != nil { if err := c.limiter.Wait(ctx); err != nil { - return nil, fmt.Errorf("%s throttle: %w", c.service, err) + return nil, c.throttleError(ctx, err) } } resp, err := c.client.Do(req) @@ -376,6 +493,21 @@ func (c *Client) do(ctx context.Context, url string, header http.Header) (*http. return resp, nil } +// throttleError wraps a failed limiter wait. rate.Limiter fails a wait that +// would outlast ctx's deadline at once, before the deadline arrives, with an +// error that does not match context.DeadlineExceeded (and ctx.Err() is still +// nil). That is the deadline running out all the same, so it is made to match +// context.DeadlineExceeded; a limiter whose burst can never admit a request +// fails for an unrelated reason and is left as-is. +func (c *Client) throttleError(ctx context.Context, err error) error { + _, hasDeadline := ctx.Deadline() + burstFailure := c.limiter.Burst() < 1 && c.limiter.Limit() != rate.Inf + if hasDeadline && ctx.Err() == nil && !burstFailure { + return fmt.Errorf("%s throttle: %w: %w", c.service, context.DeadlineExceeded, err) + } + return fmt.Errorf("%s throttle: %w", c.service, err) +} + // statusError classifies a non-2xx response. 5xx and 429 are transient (worth // a retry); every other 4xx is a refusal we must not hammer. func (c *Client) statusError(resp *http.Response) *Error { diff --git a/outbound/outbound_test.go b/outbound/outbound_test.go index 5efaa40..a204db5 100644 --- a/outbound/outbound_test.go +++ b/outbound/outbound_test.go @@ -3,6 +3,8 @@ package outbound import ( "context" "errors" + "io" + "net" "net/http" "net/http/httptest" "strings" @@ -349,6 +351,247 @@ func TestGetClampsRetryAfterToCap(t *testing.T) { } } +// When the caller's context ends during the backoff after an upstream 503, the +// upstream failure must not be lost: the returned error still carries the +// typed *Error (so HTTPStatus/UserMessage stay precise) and also reports the +// context error, so errors.Is(err, context.Canceled) keeps working. +func TestGetKeepsUpstreamErrorWhenContextEndsDuringBackoff(t *testing.T) { + for _, ctxErr := range []error{context.Canceled, context.DeadlineExceeded} { + t.Run(ctxErr.Error(), func(t *testing.T) { + var hits int32 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + atomic.AddInt32(&hits, 1) + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer srv.Close() + + c := New(Cfg{ + Service: "Example Service", + Client: srv.Client(), + Wait: func(context.Context, time.Duration) error { + return ctxErr // the context ends while we back off + }, + }) + _, err := c.Get(context.Background(), srv.URL, nil) + + var uerr *Error + if !errors.As(err, &uerr) { + t.Fatalf("want *outbound.Error in the chain, got %T: %v", err, err) + } + if uerr.Status != http.StatusServiceUnavailable || uerr.Kind != KindUnavailable { + t.Fatalf("upstream error lost: kind=%v status=%d", uerr.Kind, uerr.Status) + } + if !errors.Is(err, ctxErr) { + t.Fatalf("errors.Is(err, %v) = false; err = %v", ctxErr, err) + } + if got := HTTPStatus(err); got != http.StatusBadGateway { + t.Fatalf("HTTPStatus = %d, want 502", got) + } + if n := atomic.LoadInt32(&hits); n != 1 { + t.Fatalf("want 1 attempt before the backoff was cut short, got %d", n) + } + }) + } +} + +// Cfg.Timeout caps the whole call. Without it, an upstream that hangs on every +// attempt costs MaxAttempts per-attempt timeouts plus the backoff; with it, the +// call ends at the budget and reads as an upstream timeout. +func TestGetTimeoutCapsWholeCall(t *testing.T) { + var hits int32 + srv := httptest.NewServer(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + atomic.AddInt32(&hits, 1) + select { // hang until the client gives up + case <-r.Context().Done(): + case <-time.After(5 * time.Second): + } + })) + defer srv.Close() + + c := New(Cfg{ + Service: "Example Service", + Client: srv.Client(), // no per-attempt timeout: only the budget can end the call + Backoff: 10 * time.Millisecond, + Timeout: 100 * time.Millisecond, + }) + start := time.Now() + _, err := c.Get(context.Background(), srv.URL, nil) + if elapsed := time.Since(start); elapsed > time.Second { + t.Fatalf("Get took %v, want it capped near the 100ms budget", elapsed) + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("errors.Is(err, DeadlineExceeded) = false; err = %v", err) + } + var uerr *Error + if !errors.As(err, &uerr) || uerr.Kind != KindTimeout { + t.Fatalf("want a KindTimeout *outbound.Error, got %T: %v", err, err) + } + if got := HTTPStatus(err); got != http.StatusGatewayTimeout { + t.Fatalf("HTTPStatus = %d, want 504", got) + } + if n := atomic.LoadInt32(&hits); n != 1 { + t.Fatalf("want 1 attempt within the budget, got %d", n) + } +} + +// A budget that runs out during the backoff after a 503 ends the call there, +// keeping the upstream failure rather than replacing it with a timeout. +func TestGetTimeoutDuringBackoffKeepsUpstreamError(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer srv.Close() + + c := New(Cfg{ + Service: "Example Service", + Client: srv.Client(), + Backoff: 5 * time.Second, // far beyond the budget + Timeout: 50 * time.Millisecond, + }) + start := time.Now() + _, err := c.Get(context.Background(), srv.URL, nil) + if elapsed := time.Since(start); elapsed > time.Second { + t.Fatalf("Get took %v, want the backoff cut short by the 50ms budget", elapsed) + } + var uerr *Error + if !errors.As(err, &uerr) || uerr.Status != http.StatusServiceUnavailable || uerr.Kind != KindUnavailable { + t.Fatalf("want the upstream 503 *outbound.Error, got %T: %v", err, err) + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("errors.Is(err, DeadlineExceeded) = false; err = %v", err) + } +} + +// A throttle wait that cannot finish within the Cfg.Timeout budget fails at +// once (rate.Limiter refuses a wait past the deadline before the deadline +// arrives). That is the budget running out, so it must read as a KindTimeout +// *Error that matches context.DeadlineExceeded — not a bare throttle error. +func TestGetThrottleWaitBeyondBudgetIsTimeout(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + defer srv.Close() + + c := New(Cfg{ + Service: "Example Service", + Client: srv.Client(), + RPS: 1, // the second call must wait ~1s for a token + Timeout: 300 * time.Millisecond, + }) + resp, err := c.Get(context.Background(), srv.URL, nil) + if err != nil { + t.Fatalf("first Get: %v", err) + } + _ = resp.Body.Close() + + start := time.Now() + _, err = c.Get(context.Background(), srv.URL, nil) + if elapsed := time.Since(start); elapsed > 200*time.Millisecond { + t.Fatalf("Get took %v, want an immediate failure", elapsed) + } + var uerr *Error + if !errors.As(err, &uerr) || uerr.Kind != KindTimeout { + t.Fatalf("want a KindTimeout *outbound.Error, got %T: %v", err, err) + } + if got := HTTPStatus(err); got != http.StatusGatewayTimeout { + t.Fatalf("HTTPStatus = %d, want 504", got) + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("errors.Is(err, DeadlineExceeded) = false; err = %v", err) + } +} + +// When the caller's own deadline is earlier than the Cfg.Timeout budget, a +// throttle wait that would outlast it is the caller giving up, not the +// provider being slow: the context error is returned as-is (no *Error), but it +// still matches context.DeadlineExceeded. +func TestGetThrottleWaitBeyondCallerDeadlineIsNotBudgetTimeout(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + defer srv.Close() + + c := New(Cfg{ + Service: "Example Service", + Client: srv.Client(), + RPS: 1, + Timeout: 5 * time.Second, // later than the caller's deadline + }) + resp, err := c.Get(context.Background(), srv.URL, nil) + if err != nil { + t.Fatalf("first Get: %v", err) + } + _ = resp.Body.Close() + + ctx, cancel := context.WithTimeout(context.Background(), 300*time.Millisecond) + defer cancel() + start := time.Now() + _, err = c.Get(ctx, srv.URL, nil) + if elapsed := time.Since(start); elapsed > 200*time.Millisecond { + t.Fatalf("Get took %v, want an immediate failure", elapsed) + } + if err == nil { + t.Fatal("expected the throttle wait to fail") + } + var uerr *Error + if errors.As(err, &uerr) { + t.Fatalf("caller deadline must not become an upstream *Error, got kind=%v: %v", uerr.Kind, err) + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("errors.Is(err, DeadlineExceeded) = false; err = %v", err) + } +} + +// A limiter whose burst can never admit a request fails for a reason that has +// nothing to do with any deadline, so it must not be dressed up as one. +func TestGetThrottleBurstFailureIsNotDeadline(t *testing.T) { + c := New(Cfg{ + Service: "Example Service", + Limiter: rate.NewLimiter(1, 0), + Timeout: time.Second, + }) + _, err := c.Get(context.Background(), "http://127.0.0.1:0/", nil) + if err == nil { + t.Fatal("expected the throttle to block the request") + } + if errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("burst failure reported as a deadline: %v", err) + } + var uerr *Error + if errors.As(err, &uerr) { + t.Fatalf("burst failure must not become an upstream *Error, got kind=%v: %v", uerr.Kind, err) + } +} + +// The budget also covers reading the body (like http.Client.Timeout), so it +// must stay alive after Get returns: the response is readable in full, and +// the budget is released when the caller closes the body. +func TestGetTimeoutLeavesBodyReadable(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + w.(http.Flusher).Flush() // Get returns on the headers... + time.Sleep(20 * time.Millisecond) // ...before the body arrives + _, _ = w.Write([]byte(`{"ok":true}`)) + })) + defer srv.Close() + + c := New(Cfg{Service: "Example Service", Client: srv.Client(), Timeout: time.Second}) + resp, err := c.Get(context.Background(), srv.URL, nil) + if err != nil { + t.Fatalf("Get: %v", err) + } + body, err := io.ReadAll(resp.Body) + if err != nil { + t.Fatalf("reading the body after Get returned: %v", err) + } + if string(body) != `{"ok":true}` { + t.Fatalf("body = %q", body) + } + if err := resp.Body.Close(); err != nil { + t.Fatalf("Close: %v", err) + } +} + // Retry-After may be an HTTP-date instead of delay-seconds; it is parsed and // then clamped to the cap like any other wait. func TestGetParsesHTTPDateRetryAfter(t *testing.T) { @@ -371,3 +614,143 @@ func TestGetParsesHTTPDateRetryAfter(t *testing.T) { } } } + +// A retried error response must leave its keep-alive connection reusable: +// closing an unread body makes the Transport drop the connection, so a 5xx/429 +// storm would open a new TCP/TLS connection for every attempt. +func TestGetRetryReusesConnection(t *testing.T) { + var hits, conns int32 + srv := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + if atomic.AddInt32(&hits, 1) == 1 { + http.Error(w, "upstream is overloaded, try again later", http.StatusServiceUnavailable) + return + } + _, _ = w.Write([]byte(`{"ok":true}`)) + })) + srv.Config.ConnState = func(_ net.Conn, s http.ConnState) { + if s == http.StateNew { + atomic.AddInt32(&conns, 1) + } + } + srv.Start() + defer srv.Close() + + c, _ := newTestClient(t, srv) + resp, err := c.Get(context.Background(), srv.URL, nil) + if err != nil { + t.Fatalf("Get: %v", err) + } + _ = resp.Body.Close() + if n := atomic.LoadInt32(&hits); n != 2 { + t.Fatalf("want 2 attempts, got %d", n) + } + if n := atomic.LoadInt32(&conns); n != 1 { + t.Fatalf("the retry opened a new connection: %d connections, want 1", n) + } +} + +// A caller-supplied User-Agent replaces the configured one rather than being +// sent alongside it. +func TestGetCallerUserAgentOverridesConfigured(t *testing.T) { + var gotUA, gotAccept []string + srv := httptest.NewServer(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + gotUA = r.Header.Values("User-Agent") + gotAccept = r.Header.Values("Accept") + })) + defer srv.Close() + + c, _ := newTestClient(t, srv) + resp, err := c.Get(context.Background(), srv.URL, http.Header{ + "User-Agent": []string{"caller/2.0"}, + "Accept": []string{"application/json", "text/plain"}, + }) + if err != nil { + t.Fatalf("Get: %v", err) + } + _ = resp.Body.Close() + if len(gotUA) != 1 || gotUA[0] != "caller/2.0" { + t.Fatalf("User-Agent values = %q, want exactly [caller/2.0]", gotUA) + } + if len(gotAccept) != 2 { + t.Fatalf("multi-valued caller header lost values: Accept = %q", gotAccept) + } +} + +// A backoff or Retry-After wait that cannot finish before the deadline (the +// Cfg.Timeout budget or the caller's own) is not slept: the call fails at once +// with the error the post-sleep path would have produced — the upstream *Error +// in the chain, matching context.DeadlineExceeded — instead of burning the +// remaining latency budget on a retry that can never happen. +func TestGetWaitBeyondDeadlineFailsAtOnce(t *testing.T) { + cases := []struct { + name string + backoff time.Duration + retryAfter string + budget time.Duration + callerTTL time.Duration + }{ + {name: "backoff beyond budget", backoff: 2 * time.Second, budget: 300 * time.Millisecond}, + {name: "retry-after beyond budget", backoff: 10 * time.Millisecond, retryAfter: "5", budget: 300 * time.Millisecond}, + {name: "backoff beyond caller deadline", backoff: 2 * time.Second, callerTTL: 300 * time.Millisecond}, + {name: "retry-after beyond caller deadline", backoff: 10 * time.Millisecond, retryAfter: "5", callerTTL: 300 * time.Millisecond}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + var hits int32 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + atomic.AddInt32(&hits, 1) + if tc.retryAfter != "" { + w.Header().Set("Retry-After", tc.retryAfter) + } + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer srv.Close() + + c := New(Cfg{Service: "Example Service", Client: srv.Client(), Backoff: tc.backoff, Timeout: tc.budget}) + ctx := context.Background() + if tc.callerTTL > 0 { + var cancel context.CancelFunc + ctx, cancel = context.WithTimeout(ctx, tc.callerTTL) + defer cancel() + } + start := time.Now() + _, err := c.Get(ctx, srv.URL, nil) + if elapsed := time.Since(start); elapsed > 100*time.Millisecond { + t.Fatalf("Get took %v, want an immediate failure", elapsed) + } + var uerr *Error + if !errors.As(err, &uerr) || uerr.Status != http.StatusServiceUnavailable || uerr.Kind != KindUnavailable { + t.Fatalf("want the upstream 503 *outbound.Error, got %T: %v", err, err) + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("errors.Is(err, DeadlineExceeded) = false; err = %v", err) + } + if n := atomic.LoadInt32(&hits); n != 1 { + t.Fatalf("want 1 attempt, got %d", n) + } + }) + } +} + +// A wait that fits in the remaining budget is still slept and retried. +func TestGetWaitWithinBudgetStillRetries(t *testing.T) { + var hits int32 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + if atomic.AddInt32(&hits, 1) == 1 { + w.WriteHeader(http.StatusServiceUnavailable) + return + } + w.WriteHeader(http.StatusOK) + })) + defer srv.Close() + + c := New(Cfg{Service: "Example Service", Client: srv.Client(), Backoff: 10 * time.Millisecond, Timeout: time.Second}) + resp, err := c.Get(context.Background(), srv.URL, nil) + if err != nil { + t.Fatalf("Get: %v", err) + } + _ = resp.Body.Close() + if n := atomic.LoadInt32(&hits); n != 2 { + t.Fatalf("want 2 attempts, got %d", n) + } +} diff --git a/problemjson/problemjson.go b/problemjson/problemjson.go index b107fd0..3b9fbb5 100644 --- a/problemjson/problemjson.go +++ b/problemjson/problemjson.go @@ -4,7 +4,7 @@ // It replaces ad-hoc {"error":..., "code":...} error shapes with one // consistent, spec-shaped error body: a stable, dereferenceable-looking but // never-fetched Type URI in place of a loose code string, a human title/detail, -// and the request path as instance. +// and the escaped request path as instance. // // Construct a Writer with New, giving it the base URI that namespaces every // problem's Type and, optionally, titles for your own slugs (merged over the @@ -35,7 +35,8 @@ const ( // ModeMasked strips the detail and validation fields and replaces the // type/title with a generic identity (SlugMasked), leaving only the HTTP // status, the request instance, and the correlation reference. Use it in - // production so internal specifics never reach the client. + // production so internal specifics never reach the client; set + // Cfg.OnProblem to log the unmasked Problem the reference points at. ModeMasked ) @@ -87,7 +88,8 @@ type Details struct { Instance string `json:"instance,omitempty"` // Reference is a caller-supplied correlation id (RFC 9457 extension member, // from Cfg.RequestID), emitted in both modes when non-empty so a masked - // response can still be traced to its real detail in logs. + // response can be matched to the unmasked Problem passed to Cfg.OnProblem + // (which the caller logs). Reference string `json:"reference,omitempty"` } @@ -109,6 +111,21 @@ type ValidationDetails struct { Errors []FieldError `json:"errors,omitempty"` } +// Problem is everything a write knows about a problem, unmasked, as handed to +// Cfg.OnProblem for logging: the Details plus what the body may omit — the +// validation field errors (WriteValidation), and the upstream reason and error +// (WriteUpstream). Fields a write path does not produce are left zero. +type Problem struct { + Details + // Errors are WriteValidation's field errors; nil on other paths. + Errors []FieldError + // Reason is the upstream error's UpstreamReason() token, in every mode + // (the body's "reason" member is dev-only); "" when the error names none. + Reason string + // Err is the error passed to WriteUpstream; nil on other paths. + Err error +} + // upstreamDetails extends Details with the specific upstream reason. WriteUpstream // emits it only in dev mode when the error can name its reason; otherwise (reason // unknown, or ModeMasked) the plain Details is written and the field is absent. @@ -128,7 +145,8 @@ type UpstreamError interface { // upstreamReasoner is an optional companion to UpstreamError: a failed call that // can name its specific reason with a short, stable token (e.g. "unreachable"). -// WriteUpstream surfaces it only in dev mode. Like UpstreamError it is matched +// WriteUpstream puts it in the body only in dev mode, and in Problem.Reason for +// Cfg.OnProblem in both modes. Like UpstreamError it is matched // structurally, so this package still imports nothing from the client that // produced the error. type upstreamReasoner interface { @@ -146,12 +164,21 @@ type Cfg struct { // RequestID, when set, is called per response to obtain a correlation // reference (typically the caller's request-id / trace-id from context or // a header). Its non-empty result is written to Details.Reference so a - // masked client-facing error can still be traced to the real detail in - // logs. Return "" (or leave RequestID nil) to omit the reference. + // masked client-facing error can be matched to the unmasked Details that + // OnProblem receives. Return "" (or leave RequestID nil) to omit the + // reference. RequestID func(*http.Request) string // Mode selects verbose (ModeDev, the zero value) vs masked (ModeMasked) // rendering for every response this Writer emits. Mode Mode + // OnProblem, when set, is called once per response, in every mode and from + // every Write method, with the full unmasked Problem — the Details + // (including Reference) plus validation field errors, upstream reason, and + // upstream error — before any masking and before the body is written. It is + // the hook that keeps a ModeMasked response traceable: log the Problem here + // and the reference the client sees points at the real detail. Nil means no + // hook. + OnProblem func(r *http.Request, p Problem) } // Writer emits problem+json responses for one base URI and title set. @@ -160,6 +187,7 @@ type Writer struct { titles map[string]string requestID func(*http.Request) string mode Mode + onProblem func(*http.Request, Problem) } // New returns a Writer configured by cfg. It errors when BaseURI is empty: the @@ -180,70 +208,58 @@ func New(cfg Cfg) (*Writer, error) { titles: titles, requestID: cfg.RequestID, mode: cfg.Mode, + onProblem: cfg.OnProblem, }, nil } // Write emits an application/problem+json response. Type is built from slug // (BaseURI + "/" + slug) and Title is derived from slug via TitleFor; Instance -// is always the request path, so a client can tell which call failed without -// re-reading its own request. +// is always the escaped request path (r.URL.EscapedPath(), never the query), so +// a client can tell which call failed without re-reading its own request and +// the value stays a valid URI reference as RFC 9457 requires. // Under ModeMasked the type and title are replaced with the generic // SlugMasked identity and detail is omitted; a non-empty reference is -// included in both modes. +// included in both modes, and Cfg.OnProblem receives the unmasked Problem. +// +// A problem is always an error: a status outside 400-599 (0, a 2xx/3xx, or an +// out-of-range code) is written as 500, and the body's status and the Details +// passed to Cfg.OnProblem carry that normalised value. func (wr *Writer) Write(w http.ResponseWriter, r *http.Request, status int, slug, detail string) { - d := Details{ - Type: wr.TypeURI(slug), - Title: wr.TitleFor(slug), - Status: status, - Detail: detail, - Instance: r.URL.Path, - Reference: wr.reference(r), - } - if wr.mode == ModeMasked { - d = wr.mask(d) - } - writeProblem(w, status, d) + status = errorStatus(status, http.StatusInternalServerError) + wr.emit(w, r, Problem{Details: wr.details(r, status, slug, detail)}) } // WriteValidation reports a well-formed but invalid request: always 422, // optionally itemising which fields failed and why. // Under ModeMasked the field errors are dropped and the body collapses -// to the generic SlugMasked identity (still 422). +// to the generic SlugMasked identity (still 422); Cfg.OnProblem still +// receives them in Problem.Errors. func (wr *Writer) WriteValidation(w http.ResponseWriter, r *http.Request, detail string, fields ...FieldError) { - const status = http.StatusUnprocessableEntity - d := Details{ - Type: wr.TypeURI(SlugValidationError), - Title: wr.TitleFor(SlugValidationError), - Status: status, - Detail: detail, - Instance: r.URL.Path, - Reference: wr.reference(r), - } - if wr.mode == ModeMasked { - writeProblem(w, status, wr.mask(d)) - return - } - writeProblem(w, status, ValidationDetails{Details: d, Errors: fields}) + d := wr.details(r, http.StatusUnprocessableEntity, SlugValidationError, detail) + wr.emit(w, r, Problem{Details: d, Errors: fields}) } // WriteUpstream reports a failed call to an external service: 429 when the // provider is rate-limiting, 504 on a timeout, otherwise 502 (see // UpstreamError.HTTPStatus). Detail is the error's human-readable sentence, or // fallback for an error that does not implement UpstreamError — never a raw Go -// error. +// error. A status from HTTPStatus outside 400-599 (e.g. 0 from a foreign +// implementation) is written as 502, in the body and to Cfg.OnProblem too. // // In dev mode, when err can also name its specific reason (an optional // UpstreamReason() string method), that token is added as a "reason" extension // member so a developer sees the exact cause behind the coarse status. Under // ModeMasked the type, title, detail, and reason are all stripped as for Write — // only the status, instance, and reference remain — so the internal reason never -// reaches a production client. +// reaches a production client. Cfg.OnProblem receives the reason and err in +// both modes, for logging. func (wr *Writer) WriteUpstream(w http.ResponseWriter, r *http.Request, err error, fallback string) { status, detail := http.StatusBadGateway, fallback var ue UpstreamError if errors.As(err, &ue) { status, detail = ue.HTTPStatus(), ue.UserMessage() } + status = errorStatus(status, http.StatusBadGateway) slug := SlugUpstreamError switch status { case http.StatusTooManyRequests: @@ -252,24 +268,12 @@ func (wr *Writer) WriteUpstream(w http.ResponseWriter, r *http.Request, err erro slug = SlugUpstreamTimeout } - if wr.mode != ModeMasked { - var ur upstreamReasoner - if errors.As(err, &ur) { - if reason := ur.UpstreamReason(); reason != "" { - d := Details{ - Type: wr.TypeURI(slug), - Title: wr.TitleFor(slug), - Status: status, - Detail: detail, - Instance: r.URL.Path, - Reference: wr.reference(r), - } - writeProblem(w, status, upstreamDetails{Details: d, Reason: reason}) - return - } - } + p := Problem{Details: wr.details(r, status, slug, detail), Err: err} + var ur upstreamReasoner + if errors.As(err, &ur) { + p.Reason = ur.UpstreamReason() } - wr.Write(w, r, status, slug, detail) + wr.emit(w, r, p) } // TypeURI builds the stable Type URI (BaseURI + "/" + slug) a problem carries. @@ -289,6 +293,20 @@ func (wr *Writer) TitleFor(slug string) string { return slug } +// details builds the unmasked Details for a problem: the one place every Write +// path derives Type, Title, Instance, and Reference, so they cannot drift. +// status must already be normalised by errorStatus. +func (wr *Writer) details(r *http.Request, status int, slug, detail string) Details { + return Details{ + Type: wr.TypeURI(slug), + Title: wr.TitleFor(slug), + Status: status, + Detail: detail, + Instance: r.URL.EscapedPath(), + Reference: wr.reference(r), + } +} + // mask rewrites d for ModeMasked: a generic type/title and no detail, // preserving the status, instance, and reference so the response is still // classifiable and traceable without leaking specifics. @@ -302,6 +320,26 @@ func (wr *Writer) mask(d Details) Details { } } +// emit is the single exit of every Write method: it hands the unmasked p to the +// OnProblem hook (if configured) exactly once, then writes the body — masked +// under ModeMasked, otherwise the Details plus whichever of the field errors or +// reason p carries. +func (wr *Writer) emit(w http.ResponseWriter, r *http.Request, p Problem) { + if wr.onProblem != nil { + wr.onProblem(r, p) + } + switch { + case wr.mode == ModeMasked: + writeProblem(w, p.Status, wr.mask(p.Details)) + case p.Reason != "": + writeProblem(w, p.Status, upstreamDetails{Details: p.Details, Reason: p.Reason}) + case len(p.Errors) > 0: + writeProblem(w, p.Status, ValidationDetails{Details: p.Details, Errors: p.Errors}) + default: + writeProblem(w, p.Status, p.Details) + } +} + // reference resolves the correlation reference for r, or "" when no extractor // is configured. Callers place it in Details.Reference (omitted when empty). func (wr *Writer) reference(r *http.Request) string { @@ -321,6 +359,17 @@ func Slug(typeURI string) string { return typeURI } +// errorStatus returns status when it is an HTTP error status (400-599), else +// fallback, so a problem body never carries a success status and WriteHeader +// never sees an invalid code. It is the single place the Write methods apply +// that rule. +func errorStatus(status, fallback int) int { + if status < http.StatusBadRequest || status > 599 { + return fallback + } + return status +} + // writeProblem sets the problem+json content type and status before encoding // body, satisfying every caller's requirement to set headers before WriteHeader. func writeProblem(w http.ResponseWriter, status int, body any) { diff --git a/problemjson/problemjson_test.go b/problemjson/problemjson_test.go index 972066d..8505b4a 100644 --- a/problemjson/problemjson_test.go +++ b/problemjson/problemjson_test.go @@ -4,6 +4,7 @@ import ( "encoding/json" "net/http" "net/http/httptest" + "reflect" "testing" ) @@ -78,6 +79,48 @@ func TestWrite(t *testing.T) { } } +// TestInstanceKeepsEscapedPath pins instance to the escaped request path: RFC +// 9457 §3.1.5 requires a URI reference, so "/files/a b" (decoded) is invalid +// and "/a%2Fb" must not collapse to "/a/b". Both modes and the Details handed +// to OnProblem carry the same value. +func TestInstanceKeepsEscapedPath(t *testing.T) { + tcs := []struct { + name, target, want string + }{ + {name: "escaped space", target: "/files/a%20b", want: "/files/a%20b"}, + {name: "escaped slash", target: "/a%2Fb", want: "/a%2Fb"}, + {name: "plain path", target: "/api/v0/x", want: "/api/v0/x"}, + } + modes := []struct { + name string + mode Mode + }{{"dev", ModeDev}, {"masked", ModeMasked}} + for _, m := range modes { + for _, tc := range tcs { + t.Run(m.name+"/"+tc.name, func(t *testing.T) { + var notified Details + wr, err := New(Cfg{BaseURI: testBaseURI, Mode: m.mode, OnProblem: func(_ *http.Request, p Problem) { notified = p.Details }}) + if err != nil { + t.Fatalf("New: %v", err) + } + w := httptest.NewRecorder() + wr.Write(w, httptest.NewRequest(http.MethodGet, tc.target, nil), http.StatusNotFound, SlugNotFound, "gone") + + var got Details + if err := json.Unmarshal(w.Body.Bytes(), &got); err != nil { + t.Fatalf("decode body: %v; body=%s", err, w.Body.String()) + } + if got.Instance != tc.want { + t.Errorf("body instance = %q, want %q", got.Instance, tc.want) + } + if notified.Instance != tc.want { + t.Errorf("OnProblem instance = %q, want %q", notified.Instance, tc.want) + } + }) + } + } +} + func TestWriteValidation(t *testing.T) { wr := newTestWriter(t) req := httptest.NewRequest(http.MethodPost, "/api/v0/x", nil) @@ -562,3 +605,361 @@ func TestMaskedWriteUpstreamOmitsReason(t *testing.T) { t.Fatalf("masked mode must not include detail, body=%s", w.Body.String()) } } + +// TestOnProblemReceivesUnmaskedDetails pins that a masked response stays +// traceable: OnProblem sees the real detail on every write path while the +// client body stays masked, and both carry the same reference. +func TestOnProblemReceivesUnmaskedDetails(t *testing.T) { + type call struct { + path string + d Details + } + var calls []call + wr, err := New(Cfg{ + BaseURI: testBaseURI, + Mode: ModeMasked, + RequestID: func(r *http.Request) string { return "ref-" + r.URL.Path }, + OnProblem: func(r *http.Request, p Problem) { calls = append(calls, call{r.URL.Path, p.Details}) }, + }) + if err != nil { + t.Fatalf("New: %v", err) + } + + tests := []struct { + name string + write func(w http.ResponseWriter, r *http.Request) + wantStatus int + wantSlug string + wantDetail string + }{ + { + name: "Write", + write: func(w http.ResponseWriter, r *http.Request) { + wr.Write(w, r, http.StatusInternalServerError, SlugInternal, "db: connection refused") + }, + wantStatus: http.StatusInternalServerError, wantSlug: SlugInternal, wantDetail: "db: connection refused", + }, + { + name: "WriteValidation", + write: func(w http.ResponseWriter, r *http.Request) { + wr.WriteValidation(w, r, "too many items", FieldError{Pointer: "/items", Detail: "max 10"}) + }, + wantStatus: http.StatusUnprocessableEntity, wantSlug: SlugValidationError, wantDetail: "too many items", + }, + { + name: "WriteUpstream", + write: func(w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, stubUpstreamReason{ + stubUpstream: stubUpstream{status: http.StatusGatewayTimeout, msg: "provider slow"}, + reason: "timeout", + }, "fallback") + }, + wantStatus: http.StatusGatewayTimeout, wantSlug: SlugUpstreamTimeout, wantDetail: "provider slow", + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + calls = nil + path := "/api/v0/" + tc.name + req := httptest.NewRequest(http.MethodGet, path, nil) + w := httptest.NewRecorder() + + tc.write(w, req) + + var body Details + if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil { + t.Fatalf("decode: %v; body=%s", err, w.Body.String()) + } + if body.Detail != "" || Slug(body.Type) != SlugMasked { + t.Fatalf("body not masked: %+v", body) + } + if len(calls) != 1 { + t.Fatalf("OnProblem called %d times, want 1", len(calls)) + } + got := calls[0] + want := Details{ + Type: testBaseURI + "/" + tc.wantSlug, + Title: wr.TitleFor(tc.wantSlug), + Status: tc.wantStatus, + Detail: tc.wantDetail, + Instance: path, + Reference: "ref-" + path, + } + if got.path != path || got.d != want { + t.Fatalf("OnProblem got (%s, %+v), want (%s, %+v)", got.path, got.d, path, want) + } + if got.d.Reference != body.Reference { + t.Fatalf("hook reference %q != response reference %q", got.d.Reference, body.Reference) + } + }) + } +} + +// TestOnProblemDevModeCalledOnce pins that the hook also fires in dev mode, +// exactly once even on WriteUpstream's reason path. +func TestOnProblemDevModeCalledOnce(t *testing.T) { + n := 0 + wr, err := New(Cfg{BaseURI: testBaseURI, OnProblem: func(*http.Request, Problem) { n++ }}) + if err != nil { + t.Fatalf("New: %v", err) + } + req := httptest.NewRequest(http.MethodGet, "/x", nil) + wr.WriteUpstream(httptest.NewRecorder(), req, stubUpstreamReason{ + stubUpstream: stubUpstream{status: http.StatusBadGateway, msg: "down"}, + reason: "unreachable", + }, "fallback") + wr.WriteUpstream(httptest.NewRecorder(), req, stubUpstream{status: http.StatusBadGateway, msg: "down"}, "fallback") + if n != 2 { + t.Fatalf("OnProblem called %d times for two writes, want 2", n) + } +} + +// TestOnProblemMaskedKeepsFieldErrorsAndReason pins that a masked 422/502 stays +// diagnosable: the hook receives the validation field errors, and the upstream +// reason and error, even though ModeMasked strips them all from the body. +func TestOnProblemMaskedKeepsFieldErrorsAndReason(t *testing.T) { + var got []Problem + wr, err := New(Cfg{BaseURI: testBaseURI, Mode: ModeMasked, OnProblem: func(_ *http.Request, p Problem) { got = append(got, p) }}) + if err != nil { + t.Fatalf("New: %v", err) + } + + t.Run("WriteValidation", func(t *testing.T) { + got = nil + fields := []FieldError{{Pointer: "/items", Detail: "max 10"}, {Pointer: "/name", Detail: "required"}} + w := httptest.NewRecorder() + wr.WriteValidation(w, httptest.NewRequest(http.MethodPost, "/x", nil), "bad input", fields...) + + var body map[string]any + if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil { + t.Fatalf("decode: %v; body=%s", err, w.Body.String()) + } + if _, ok := body["errors"]; ok { + t.Fatalf("masked body must not include field errors, body=%s", w.Body.String()) + } + if len(got) != 1 { + t.Fatalf("OnProblem called %d times, want 1", len(got)) + } + if !reflect.DeepEqual(got[0].Errors, fields) { + t.Fatalf("OnProblem Errors = %+v, want %+v", got[0].Errors, fields) + } + if got[0].Reason != "" || got[0].Err != nil { + t.Fatalf("validation problem must carry no reason/err, got %+v", got[0]) + } + }) + + t.Run("WriteUpstream", func(t *testing.T) { + got = nil + upErr := stubUpstreamReason{stubUpstream: stubUpstream{status: http.StatusBadGateway, msg: "down"}, reason: "unreachable"} + w := httptest.NewRecorder() + wr.WriteUpstream(w, httptest.NewRequest(http.MethodGet, "/x", nil), upErr, "fallback") + + var body map[string]any + if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil { + t.Fatalf("decode: %v; body=%s", err, w.Body.String()) + } + if _, ok := body["reason"]; ok { + t.Fatalf("masked body must not include reason, body=%s", w.Body.String()) + } + if len(got) != 1 { + t.Fatalf("OnProblem called %d times, want 1", len(got)) + } + if got[0].Reason != "unreachable" { + t.Fatalf("OnProblem Reason = %q, want %q", got[0].Reason, "unreachable") + } + if got[0].Err != upErr { + t.Fatalf("OnProblem Err = %v, want the upstream error %v", got[0].Err, upErr) + } + if got[0].Errors != nil { + t.Fatalf("upstream problem must carry no field errors, got %+v", got[0].Errors) + } + }) +} + +// TestStatusNormalised pins that a status outside 400-599 never reaches the +// client: Write maps it to 500 and WriteUpstream to 502 (no WriteHeader panic +// on 0, no problem body behind a success status), and the body's status and +// the OnProblem hook both see the normalised value. +func TestStatusNormalised(t *testing.T) { + var hookStatus int + wr, err := New(Cfg{BaseURI: testBaseURI, OnProblem: func(_ *http.Request, p Problem) { hookStatus = p.Status }}) + if err != nil { + t.Fatalf("New: %v", err) + } + write := func(status int) func(http.ResponseWriter, *http.Request) { + return func(w http.ResponseWriter, r *http.Request) { wr.Write(w, r, status, SlugInternal, "boom") } + } + upstream := func(status int) func(http.ResponseWriter, *http.Request) { + return func(w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, stubUpstream{status: status, msg: "down"}, "fallback") + } + } + upstreamReason := func(status int) func(http.ResponseWriter, *http.Request) { + return func(w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, stubUpstreamReason{stubUpstream: stubUpstream{status: status, msg: "down"}, reason: "x"}, "fallback") + } + } + tests := []struct { + name string + write func(http.ResponseWriter, *http.Request) + want int + }{ + {"Write 0", write(0), http.StatusInternalServerError}, + {"Write 200", write(http.StatusOK), http.StatusInternalServerError}, + {"Write 302", write(http.StatusFound), http.StatusInternalServerError}, + {"Write 399", write(399), http.StatusInternalServerError}, + {"Write 600", write(600), http.StatusInternalServerError}, + {"Write 400", write(http.StatusBadRequest), http.StatusBadRequest}, + {"Write 404", write(http.StatusNotFound), http.StatusNotFound}, + {"Write 599", write(599), 599}, + {"WriteUpstream 0", upstream(0), http.StatusBadGateway}, + {"WriteUpstream 200", upstream(http.StatusOK), http.StatusBadGateway}, + {"WriteUpstream 600", upstream(600), http.StatusBadGateway}, + {"WriteUpstream 429", upstream(http.StatusTooManyRequests), http.StatusTooManyRequests}, + {"WriteUpstream 503", upstream(http.StatusServiceUnavailable), http.StatusServiceUnavailable}, + {"WriteUpstream reason 0", upstreamReason(0), http.StatusBadGateway}, + {"WriteUpstream reason 504", upstreamReason(http.StatusGatewayTimeout), http.StatusGatewayTimeout}, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + hookStatus = 0 + w := httptest.NewRecorder() + tc.write(w, httptest.NewRequest(http.MethodGet, "/x", nil)) + + if w.Code != tc.want { + t.Fatalf("status = %d, want %d", w.Code, tc.want) + } + var body Details + if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil { + t.Fatalf("decode: %v; body=%s", err, w.Body.String()) + } + if body.Status != tc.want { + t.Fatalf("body status = %d, want %d", body.Status, tc.want) + } + if hookStatus != tc.want { + t.Fatalf("OnProblem status = %d, want %d", hookStatus, tc.want) + } + }) + } +} + +// TestBodyPinnedPerPath pins the exact wire body and the OnProblem Details of +// every write path in both modes, so the shared Details construction cannot +// drift between Write, WriteValidation, and WriteUpstream (with and without a +// dev-mode reason). +func TestBodyPinnedPerPath(t *testing.T) { + const ( + path = "/api/v0/p" + ref = "ref-1" + ) + tests := []struct { + name string + mode Mode + write func(wr *Writer, w http.ResponseWriter, r *http.Request) + wantCode int + wantBody string + wantHook Problem + }{ + { + name: "Write dev", mode: ModeDev, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.Write(w, r, http.StatusConflict, SlugConflict, "already exists") + }, + wantCode: http.StatusConflict, + wantBody: `{"type":"https://example.test/probs/conflict","title":"Conflict","status":409,"detail":"already exists","instance":"/api/v0/p","reference":"ref-1"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/conflict", Title: "Conflict", Status: 409, Detail: "already exists", Instance: path, Reference: ref}}, + }, + { + name: "Write masked", mode: ModeMasked, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.Write(w, r, http.StatusConflict, SlugConflict, "already exists") + }, + wantCode: http.StatusConflict, + wantBody: `{"type":"https://example.test/probs/error","title":"An error occurred","status":409,"instance":"/api/v0/p","reference":"ref-1"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/conflict", Title: "Conflict", Status: 409, Detail: "already exists", Instance: path, Reference: ref}}, + }, + { + name: "WriteValidation dev", mode: ModeDev, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.WriteValidation(w, r, "bad input", FieldError{Pointer: "/qty", Detail: "too big"}) + }, + wantCode: http.StatusUnprocessableEntity, + wantBody: `{"type":"https://example.test/probs/validation_error","title":"Validation error","status":422,"detail":"bad input","instance":"/api/v0/p","reference":"ref-1","errors":[{"pointer":"/qty","detail":"too big"}]}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/validation_error", Title: "Validation error", Status: 422, Detail: "bad input", Instance: path, Reference: ref}, Errors: []FieldError{{Pointer: "/qty", Detail: "too big"}}}, + }, + { + name: "WriteValidation masked", mode: ModeMasked, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.WriteValidation(w, r, "bad input", FieldError{Pointer: "/qty", Detail: "too big"}) + }, + wantCode: http.StatusUnprocessableEntity, + wantBody: `{"type":"https://example.test/probs/error","title":"An error occurred","status":422,"instance":"/api/v0/p","reference":"ref-1"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/validation_error", Title: "Validation error", Status: 422, Detail: "bad input", Instance: path, Reference: ref}, Errors: []FieldError{{Pointer: "/qty", Detail: "too big"}}}, + }, + { + name: "WriteUpstream reason dev", mode: ModeDev, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, stubUpstreamReason{stubUpstream: stubUpstream{status: http.StatusGatewayTimeout, msg: "provider slow"}, reason: "timeout"}, "fallback") + }, + wantCode: http.StatusGatewayTimeout, + wantBody: `{"type":"https://example.test/probs/upstream_timeout","title":"Upstream timeout","status":504,"detail":"provider slow","instance":"/api/v0/p","reference":"ref-1","reason":"timeout"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/upstream_timeout", Title: "Upstream timeout", Status: 504, Detail: "provider slow", Instance: path, Reference: ref}, Reason: "timeout", Err: stubUpstreamReason{stubUpstream: stubUpstream{status: http.StatusGatewayTimeout, msg: "provider slow"}, reason: "timeout"}}, + }, + { + name: "WriteUpstream reason masked", mode: ModeMasked, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, stubUpstreamReason{stubUpstream: stubUpstream{status: http.StatusGatewayTimeout, msg: "provider slow"}, reason: "timeout"}, "fallback") + }, + wantCode: http.StatusGatewayTimeout, + wantBody: `{"type":"https://example.test/probs/error","title":"An error occurred","status":504,"instance":"/api/v0/p","reference":"ref-1"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/upstream_timeout", Title: "Upstream timeout", Status: 504, Detail: "provider slow", Instance: path, Reference: ref}, Reason: "timeout", Err: stubUpstreamReason{stubUpstream: stubUpstream{status: http.StatusGatewayTimeout, msg: "provider slow"}, reason: "timeout"}}, + }, + { + name: "WriteUpstream no reason dev", mode: ModeDev, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, stubUpstream{status: http.StatusTooManyRequests, msg: "slow down"}, "fallback") + }, + wantCode: http.StatusTooManyRequests, + wantBody: `{"type":"https://example.test/probs/upstream_rate_limited","title":"Upstream rate limited","status":429,"detail":"slow down","instance":"/api/v0/p","reference":"ref-1"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/upstream_rate_limited", Title: "Upstream rate limited", Status: 429, Detail: "slow down", Instance: path, Reference: ref}, Err: stubUpstream{status: http.StatusTooManyRequests, msg: "slow down"}}, + }, + { + name: "WriteUpstream fallback masked", mode: ModeMasked, + write: func(wr *Writer, w http.ResponseWriter, r *http.Request) { + wr.WriteUpstream(w, r, errNotUpstream, "fallback") + }, + wantCode: http.StatusBadGateway, + wantBody: `{"type":"https://example.test/probs/error","title":"An error occurred","status":502,"instance":"/api/v0/p","reference":"ref-1"}`, + wantHook: Problem{Details: Details{Type: testBaseURI + "/upstream_error", Title: "Upstream error", Status: 502, Detail: "fallback", Instance: path, Reference: ref}, Err: errNotUpstream}, + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + var hook []Problem + wr, err := New(Cfg{ + BaseURI: testBaseURI, + Mode: tc.mode, + RequestID: func(*http.Request) string { return ref }, + OnProblem: func(_ *http.Request, p Problem) { hook = append(hook, p) }, + }) + if err != nil { + t.Fatalf("New: %v", err) + } + w := httptest.NewRecorder() + tc.write(wr, w, httptest.NewRequest(http.MethodGet, path, nil)) + + if w.Code != tc.wantCode { + t.Fatalf("status = %d, want %d", w.Code, tc.wantCode) + } + if ct := w.Header().Get("Content-Type"); ct != "application/problem+json" { + t.Fatalf("Content-Type = %q, want application/problem+json", ct) + } + if got := w.Body.String(); got != tc.wantBody+"\n" { + t.Fatalf("body =\n%s\nwant\n%s", got, tc.wantBody) + } + if len(hook) != 1 || !reflect.DeepEqual(hook[0], tc.wantHook) { + t.Fatalf("OnProblem got %+v, want exactly [%+v]", hook, tc.wantHook) + } + }) + } +} diff --git a/spa/spa.go b/spa/spa.go index 74bdfc3..2f1e3f8 100644 --- a/spa/spa.go +++ b/spa/spa.go @@ -1,11 +1,13 @@ package spa import ( - _ "embed" + "bytes" "errors" "fmt" + "io" "io/fs" "net/http" + "net/url" "strings" ) @@ -19,11 +21,18 @@ type Cfg struct { SubDir string // PathPrefix is the URL path the SPA is mounted under, e.g. "/ui" for // http://host/ui/. It is normalised to a single leading slash and no trailing - // slash, so "ui", "/ui", and "/ui/" are equivalent; "" mounts at the root. + // slash, so "ui", "/ui", and "/ui/" are equivalent; "" or "/" mounts at the + // root. It matches whole path segments: under "/ui", /ui and /ui/... are + // served, while /uix.js or /uifoo/bar get a 404. PathPrefix string } +// indexFile is the SPA entrypoint served for the root and every deep link. +const indexFile = "index.html" + // New returns a Handler serving the single-page application described by cfg. +// It returns an error if the served tree (FS, after SubDir) has no index.html +// file. func New(cfg Cfg) (Handler, error) { if cfg.FS == nil { return Handler{}, fmt.Errorf("spa: Cfg.FS cannot be nil") @@ -36,6 +45,16 @@ func New(cfg Cfg) (Handler, error) { } assets = sub } + // Validate the entrypoint up front: fs.Sub does not check that SubDir + // exists, so a typo, the parent of the build dir, or a missing build would + // otherwise only surface as 404s or directory listings on every deep link. + info, err := fs.Stat(assets, indexFile) + if err != nil { + return Handler{}, fmt.Errorf("spa: %s not found in FS (SubDir %q): %w", indexFile, cfg.SubDir, err) + } + if info.IsDir() { + return Handler{}, fmt.Errorf("spa: %s in FS (SubDir %q) is a directory", indexFile, cfg.SubDir) + } return Handler{ fs: assets, pathPrefix: normalizePrefix(cfg.PathPrefix), @@ -44,12 +63,14 @@ func New(cfg Cfg) (Handler, error) { // normalizePrefix canonicalises the mount prefix to a single leading slash and // no trailing slash ("ui", "/ui", "/ui/" -> "/ui"), so a caller cannot silently -// break asset serving by omitting the leading slash. "" stays "" (root mount). +// break asset serving by omitting the leading slash. "" and "/" both become "" +// (root mount). func normalizePrefix(p string) string { + p = strings.Trim(p, "/") if p == "" { return "" } - return "/" + strings.Trim(p, "/") + return "/" + p } // Handler is an http.Handler that serves a single-page application from an @@ -61,6 +82,12 @@ type Handler struct { } func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + // Requests outside the mount prefix are not the SPA's: neither an asset nor + // a deep link, so 404 rather than serve /uix.js as x.js under "/ui". + if !h.underPrefix(r.URL) { + http.NotFound(w, r) + return + } reqPath := strings.TrimPrefix(r.URL.Path, h.pathPrefix) if reqPath == "" || reqPath == "/" { reqPath = "./" @@ -84,6 +111,16 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } + // An unclean path (an empty segment from "//", e.g. /ui//app.js) is not a + // valid fs path. os.DirFS rejects it with fs.ErrInvalid, which would + // otherwise surface as a client-triggerable 500, and other FSes report it as + // not-exist and fall back to the index; answer 404 on every FS instead. + // ("." and ".." segments are already caught as hidden segments above.) + if !fs.ValidPath(reqPath) { + http.NotFound(w, r) + return + } + // fs.Stat opens and closes internally (via the StatFS fast path that both // os.DirFS and embed.FS implement), so it leaks no descriptor; the file // itself is opened exactly once, by http.FileServerFS below. @@ -95,8 +132,36 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { case err != nil: http.Error(w, "internal server error", http.StatusInternalServerError) default: - http.StripPrefix(h.pathPrefix, http.FileServerFS(h.fs)).ServeHTTP(w, r) + http.StripPrefix(h.pathPrefix, http.FileServerFS(h.fs)).ServeHTTP(w, withURLCopy(r)) + } +} + +// underPrefix reports whether u is within the mount prefix on a whole-segment +// boundary: "/ui" and "/ui/..." are, "/uix.js" and "/uifoo/bar" are not. The +// root mount ("") holds every path. When the URL carries an escaped form, +// RawPath must also start with the prefix, mirroring http.StripPrefix, so that +// asset serving and the index fallback accept exactly the same requests. +func (h Handler) underPrefix(u *url.URL) bool { + p := h.pathPrefix + if p == "" { + return true } + if u.Path != p && !strings.HasPrefix(u.Path, p+"/") { + return false + } + return u.RawPath == "" || strings.HasPrefix(u.RawPath, p) +} + +// withURLCopy returns a shallow copy of r with its own URL, so the file server +// cannot mutate the caller's request: http.StripPrefix("") passes r through +// as-is, and the file server then rewrites r.URL.Path to add a leading slash +// (e.g. "app.js" left by an outer http.StripPrefix("/static/", ...)). +func withURLCopy(r *http.Request) *http.Request { + r2 := new(http.Request) + *r2 = *r + u := *r.URL + r2.URL = &u + return r2 } // hasHiddenSegment reports whether any element of the slash-separated path @@ -112,9 +177,43 @@ func hasHiddenSegment(p string) bool { return false } -// serveIndex serves the SPA entrypoint by rewriting the request to the FS root -// and delegating to the file server. +// serveIndex serves the SPA entrypoint with http.ServeContent rather than a +// file server on "/", so it can never fall back to a directory listing: if +// index.html has gone missing (e.g. an os.DirFS build dir mid-rebuild) the +// response is a 404. ServeContent sets the same Content-Type, Last-Modified, +// and conditional/range handling the file server did. func (h Handler) serveIndex(w http.ResponseWriter, r *http.Request) { - r.URL.Path = "/" - http.FileServerFS(h.fs).ServeHTTP(w, r) + f, err := h.fs.Open(indexFile) + if err != nil { + if errors.Is(err, fs.ErrNotExist) { + http.NotFound(w, r) + return + } + http.Error(w, "internal server error", http.StatusInternalServerError) + return + } + defer func() { _ = f.Close() }() + + info, err := f.Stat() + if err != nil { + http.Error(w, "internal server error", http.StatusInternalServerError) + return + } + if info.IsDir() { + http.NotFound(w, r) + return + } + + content, ok := f.(io.ReadSeeker) + if !ok { + // os.DirFS, embed.FS, and fstest.MapFS files all seek; buffer any FS + // whose files do not, so ServeContent can still size and range them. + data, err := io.ReadAll(f) + if err != nil { + http.Error(w, "internal server error", http.StatusInternalServerError) + return + } + content = bytes.NewReader(data) + } + http.ServeContent(w, r, indexFile, info.ModTime(), content) } diff --git a/spa/spa_test.go b/spa/spa_test.go index 0a45fde..98e0815 100644 --- a/spa/spa_test.go +++ b/spa/spa_test.go @@ -211,3 +211,261 @@ func TestHandlerNormalizesPathPrefix(t *testing.T) { } } } + +// PathPrefix matches whole path segments only: /uix.js and /uifoo/bar are not +// under /ui, so they must 404 instead of serving x.js or the SPA entrypoint. +func TestHandlerPathPrefixMatchesWholeSegments(t *testing.T) { + fsys := mapFS() + fsys["x.js"] = &fstest.MapFile{Data: []byte("x js")} + fsys["app.js"] = &fstest.MapFile{Data: []byte("root app js")} + + cases := []struct { + prefix, target string + want int + body string + }{ + {prefix: "/ui", target: "/uix.js", want: http.StatusNotFound}, + {prefix: "/ui", target: "/uifoo/bar", want: http.StatusNotFound}, + {prefix: "/ui", target: "/uifoo/", want: http.StatusNotFound}, + {prefix: "/ui", target: "/other/app.js", want: http.StatusNotFound}, + {prefix: "/ui", target: "/%75i/app.js", want: http.StatusNotFound}, // StripPrefix cannot strip the escaped form + {prefix: "/ui", target: "/%75i/deep", want: http.StatusNotFound}, + {prefix: "/ui", target: "/ui", want: http.StatusOK, body: "test index"}, + {prefix: "/ui", target: "/ui/", want: http.StatusOK, body: "test index"}, + {prefix: "/ui", target: "/ui/app.js", want: http.StatusOK, body: "root app js"}, + {prefix: "/ui", target: "/ui/x.js", want: http.StatusOK, body: "x js"}, + {prefix: "/ui", target: "/ui/users/42", want: http.StatusOK, body: "test index"}, + {prefix: "/ui", target: "/ui/users/a%2Fb", want: http.StatusOK, body: "test index"}, + {prefix: "/static/ui", target: "/static/uix.js", want: http.StatusNotFound}, + {prefix: "/static/ui", target: "/static/ui/x.js", want: http.StatusOK, body: "x js"}, + {prefix: "", target: "/uix.js", want: http.StatusOK, body: "test index"}, + {prefix: "", target: "/x.js", want: http.StatusOK, body: "x js"}, + {prefix: "", target: "/uifoo/bar", want: http.StatusOK, body: "test index"}, + {prefix: "/", target: "/x.js", want: http.StatusOK, body: "x js"}, + {prefix: "/", target: "/uifoo/bar", want: http.StatusOK, body: "test index"}, + } + for _, c := range cases { + h, err := New(Cfg{FS: fsys, PathPrefix: c.prefix}) + if err != nil { + t.Fatal(err) + } + req := httptest.NewRequest(http.MethodGet, c.target, nil) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if w.Code != c.want { + t.Errorf("prefix %q %s: code = %d, want %d (body %q)", c.prefix, c.target, w.Code, c.want, w.Body.String()) + continue + } + if c.body != "" && w.Body.String() != c.body { + t.Errorf("prefix %q %s: body = %q, want %q", c.prefix, c.target, w.Body.String(), c.body) + } + } +} + +// A SubDir that does not hold index.html — the parent of the build dir, a +// missing build output, or a path that does not exist — must fail at New +// instead of serving a directory listing (or a 404) for every deep link. +func TestNewRequiresIndex(t *testing.T) { + fsys := fstest.MapFS{ + "web/dist/index.html": {Data: []byte("test index")}, + "web/.env": {Data: []byte("SECRET=1")}, + "dirindex/index.html/x": {Data: []byte("not a file")}, + } + for _, sub := range []string{"web", "missing", "dirindex"} { + if _, err := New(Cfg{FS: fsys, SubDir: sub}); err == nil { + t.Errorf("SubDir %q: New must reject a tree without an index.html file", sub) + } + } + if _, err := New(Cfg{FS: fsys, SubDir: "web/dist"}); err != nil { + t.Errorf("SubDir web/dist: unexpected error %v", err) + } +} + +// Deep links serve index.html itself, never a directory listing, with the +// same content headers the file server set. +func TestHandlerServesIndexForDeepLinks(t *testing.T) { + h, err := New(Cfg{FS: mapFS(), PathPrefix: "/ui"}) + if err != nil { + t.Fatal(err) + } + for _, p := range []string{"/ui/", "/ui/users/42", "/ui/assets", "/ui/assets/"} { + req := httptest.NewRequest(http.MethodGet, p, nil) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if w.Code != http.StatusOK || w.Body.String() != "test index" { + t.Errorf("%s: code=%d body=%q, want 200 index", p, w.Code, w.Body.String()) + } + if ct := w.Header().Get("Content-Type"); ct != "text/html; charset=utf-8" { + t.Errorf("%s: Content-Type = %q, want text/html", p, ct) + } + } +} + +// The handler must never mutate the caller's request: an outer wrapper (e.g. +// logging middleware) reads r.URL after ServeHTTP returns, and a deep link +// once came back as url=/ because the fallback rewrote r.URL.Path. +func TestHandlerDoesNotMutateRequest(t *testing.T) { + cases := []struct { + name, prefix, target string + path string // overrides the parsed Path, e.g. as left by an outer http.StripPrefix + }{ + {name: "root deep link", target: "/users/42"}, + {name: "root asset", target: "/assets/app.js"}, + {name: "root dotfile", target: "/.env"}, + {name: "root index", target: "/"}, + {name: "prefixed deep link", prefix: "/ui", target: "/ui/users/42"}, + {name: "prefixed escaped deep link", prefix: "/ui", target: "/ui/users/a%2Fb"}, + {name: "prefixed asset", prefix: "/ui", target: "/ui/assets/app.js"}, + {name: "prefixed escaped asset", prefix: "/ui", target: "/ui/assets/app%2Ejs"}, + {name: "prefixed directory", prefix: "/ui", target: "/ui/assets/"}, + {name: "root asset without leading slash", target: "/assets/app.js", path: "assets/app.js"}, + {name: "root deep link without leading slash", target: "/users/42", path: "users/42"}, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + h, err := New(Cfg{FS: mapFS(), PathPrefix: c.prefix}) + if err != nil { + t.Fatal(err) + } + req := httptest.NewRequest(http.MethodGet, c.target, nil) + if c.path != "" { + req.URL.Path = c.path + } + wantURL := *req.URL + h.ServeHTTP(httptest.NewRecorder(), req) + if req.URL.Path != wantURL.Path || req.URL.RawPath != wantURL.RawPath { + t.Errorf("caller's URL mutated: Path=%q RawPath=%q, want Path=%q RawPath=%q", + req.URL.Path, req.URL.RawPath, wantURL.Path, wantURL.RawPath) + } + }) + } +} + +// If index.html vanishes after New (an os.DirFS build dir being rebuilt), a +// deep link must 404 rather than fall back to a directory listing. +func TestHandlerNeverListsDirectory(t *testing.T) { + fsys := mapFS() + h, err := New(Cfg{FS: fsys}) + if err != nil { + t.Fatal(err) + } + delete(fsys, "index.html") + req := httptest.NewRequest(http.MethodGet, "/users/42", nil) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if w.Code != http.StatusNotFound || strings.Contains(w.Body.String(), "assets") { + t.Errorf("code=%d body=%q, want 404 without a listing", w.Code, w.Body.String()) + } +} + +// noSeekFS hides Seek on its files, and can fail Open with a non-NotExist error +// after construction, to exercise serveIndex's fallback and error paths. +type noSeekFS struct { + fstest.MapFS + openErr error +} + +type noSeekFile struct{ fs.File } + +func (f noSeekFS) Open(name string) (fs.File, error) { + if f.openErr != nil && name == "index.html" { + return nil, f.openErr + } + file, err := f.MapFS.Open(name) + if err != nil { + return nil, err + } + return noSeekFile{file}, nil +} + +func TestHandlerServeIndexEdgeCases(t *testing.T) { + get := func(h Handler) *httptest.ResponseRecorder { + w := httptest.NewRecorder() + h.ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/users/42", nil)) + return w + } + + t.Run("non-seekable file is buffered", func(t *testing.T) { + h, err := New(Cfg{FS: noSeekFS{MapFS: mapFS()}}) + if err != nil { + t.Fatal(err) + } + if w := get(h); w.Code != http.StatusOK || w.Body.String() != "test index" { + t.Errorf("code=%d body=%q, want 200 index", w.Code, w.Body.String()) + } + }) + + t.Run("index replaced by a directory", func(t *testing.T) { + fsys := mapFS() + h, err := New(Cfg{FS: fsys}) + if err != nil { + t.Fatal(err) + } + delete(fsys, "index.html") + fsys["index.html/x"] = &fstest.MapFile{Data: []byte("x")} + if w := get(h); w.Code != http.StatusNotFound { + t.Errorf("code=%d, want 404", w.Code) + } + }) + + t.Run("open error is a 500", func(t *testing.T) { + fsys := &noSeekFS{MapFS: mapFS()} + h, err := New(Cfg{FS: fsys}) + if err != nil { + t.Fatal(err) + } + fsys.openErr = fs.ErrPermission + if w := get(h); w.Code != http.StatusInternalServerError { + t.Errorf("code=%d, want 500", w.Code) + } + }) +} + +// An unclean request path (an empty segment from "//", or a "." segment) is not +// a valid fs path: os.DirFS answers fs.Stat with fs.ErrInvalid, which once +// surfaced as a client-triggerable 500. It must be a 404 on every FS. +func TestHandlerUncleanPathIsNotFound(t *testing.T) { + dir := t.TempDir() + for name, data := range map[string]string{"index.html": "test index", "app.js": "app js"} { + if err := os.WriteFile(dir+"/"+name, []byte(data), 0o600); err != nil { + t.Fatal(err) + } + } + fileSystems := map[string]fs.FS{ + "dirFS": os.DirFS(dir), + "mapFS": fstest.MapFS{"index.html": {Data: []byte("test index")}, "app.js": {Data: []byte("app js")}}, + } + for fsName, fsys := range fileSystems { + h, err := New(Cfg{FS: fsys, PathPrefix: "/ui"}) + if err != nil { + t.Fatal(err) + } + cases := []struct { + path string + want int + body string + }{ + {path: "/ui//app.js", want: http.StatusNotFound}, + {path: "/ui/a//b", want: http.StatusNotFound}, + {path: "/ui/./app.js", want: http.StatusNotFound}, + {path: "/ui/a/./b", want: http.StatusNotFound}, + {path: "/ui/app.js", want: http.StatusOK, body: "app js"}, + {path: "/ui/a/b", want: http.StatusOK, body: "test index"}, + {path: "/ui/a//", want: http.StatusOK, body: "test index"}, // directory request + {path: "/ui", want: http.StatusOK, body: "test index"}, + {path: "/ui/", want: http.StatusOK, body: "test index"}, + } + for _, c := range cases { + req := httptest.NewRequest(http.MethodGet, c.path, nil) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if w.Code != c.want { + t.Errorf("%s %s: code = %d, want %d (body %q)", fsName, c.path, w.Code, c.want, w.Body.String()) + continue + } + if c.body != "" && w.Body.String() != c.body { + t.Errorf("%s %s: body = %q, want %q", fsName, c.path, w.Body.String(), c.body) + } + } + } +}