diff --git a/internal/middleware/export_test.go b/internal/middleware/export_test.go index 31abd52..d0033d4 100644 --- a/internal/middleware/export_test.go +++ b/internal/middleware/export_test.go @@ -4,8 +4,28 @@ import ( "context" "net/http" "time" + + httpmetrics "github.com/slok/go-http-metrics/metrics" ) +// MetricsMiddlewareForTest builds the metrics recording middleware +// against a caller-supplied recorder, so a test can gather from its +// own Prometheus registry rather than the process-wide default one +// that Middleware.Metrics uses. +func MetricsMiddlewareForTest( + rec httpmetrics.Recorder, +) func(http.Handler) http.Handler { + return metricsMiddleware(rec) +} + +// UnmatchedRouteConst exposes the sentinel that stands in for a +// request matching no route pattern. +const UnmatchedRouteConst = unmatchedRoute + +// InflightHandlerConst exposes the fixed handler label on the +// inflight gauge. +const InflightHandlerConst = inflightHandler + // NewLoggingResponseWriterForTest wraps newLoggingResponseWriter // for use in external test packages. func NewLoggingResponseWriterForTest( diff --git a/internal/middleware/metrics.go b/internal/middleware/metrics.go new file mode 100644 index 0000000..14d36a2 --- /dev/null +++ b/internal/middleware/metrics.go @@ -0,0 +1,135 @@ +package middleware + +import ( + "context" + "net/http" + "time" + + "github.com/go-chi/chi" + httpmetrics "github.com/slok/go-http-metrics/metrics" + prommetrics "github.com/slok/go-http-metrics/metrics/prometheus" + ghmm "github.com/slok/go-http-metrics/middleware" + "github.com/slok/go-http-metrics/middleware/std" +) + +// inflightHandler is the fixed `handler` label on +// http_requests_inflight, the one HTTP metric here that cannot carry +// a route pattern. +// +// The gauge is incremented before the wrapped handler runs and +// decremented after it returns, and the pattern only exists between +// those two moments. Deriving the label from the route would +// therefore increment one series and decrement another, leaving every +// pattern permanently off by the number of requests it served — a +// broken gauge, on top of the per-path cardinality this file exists +// to remove. So the gauge is deliberately aggregate: one series, +// counting the requests in flight across the whole service. +const inflightHandler = "(all)" + +// routePatternID is the `handler` label for a request: the chi route +// pattern, never the concrete path. +// +// The pattern is what bounds the label's domain to the routes the +// service registers. The path does not bound it at all — every byte +// after /webhook/ is client-chosen, so labelling by path lets any +// unauthenticated client mint permanent series at will, and publishes +// the entrypoint UUID (the receiver's only credential) in the scrape +// while doing it. +// +// chi populates the route context during routeHTTP, so this is only +// valid once routing has run. Every caller below is on the recording +// side of the middleware, which go-http-metrics defers until after +// the wrapped handler returns. +func routePatternID(ctx context.Context) string { + if rc := chi.RouteContext(ctx); rc != nil { + if pattern := rc.RoutePattern(); pattern != "" { + return pattern + } + } + + return unmatchedRoute +} + +// routePatternRecorder wraps a go-http-metrics recorder and replaces +// the handler id on every observation with the request's route +// pattern. +// +// This is the seam that makes the pattern usable at all. The metrics +// middleware is global (see Server.setupGlobalMiddleware), so it is +// entered before chi has matched anything, and go-http-metrics fixes +// its handler id up front — passing the pattern in as that id is not +// possible, and leaving the id empty makes the library substitute the +// raw URL path, which is the defect. What the library does hand over +// is the request context, unchanged, on each recorder call; that +// context carries the same *chi.Context pointer routing mutates in +// place, and the duration and size calls happen after the wrapped +// handler has returned. Reading the pattern there is what the access +// log already does in accessLogURL. +// +// Recording after the whole chain returns is also what makes this +// hold for requests the route-level receiver rate limiter rejects. +// Those never reach a handler, but chi has already matched the route +// by the time the limiter runs, so their 429s land on the pattern +// like any other response. +type routePatternRecorder struct { + inner httpmetrics.Recorder +} + +func (r routePatternRecorder) ObserveHTTPRequestDuration( + ctx context.Context, + props httpmetrics.HTTPReqProperties, + duration time.Duration, +) { + props.ID = routePatternID(ctx) + r.inner.ObserveHTTPRequestDuration(ctx, props, duration) +} + +func (r routePatternRecorder) ObserveHTTPResponseSize( + ctx context.Context, + props httpmetrics.HTTPReqProperties, + sizeBytes int64, +) { + props.ID = routePatternID(ctx) + r.inner.ObserveHTTPResponseSize(ctx, props, sizeBytes) +} + +func (r routePatternRecorder) AddInflightRequests( + ctx context.Context, + props httpmetrics.HTTPProperties, + quantity int, +) { + props.ID = inflightHandler + r.inner.AddInflightRequests(ctx, props, quantity) +} + +var _ httpmetrics.Recorder = routePatternRecorder{} + +// Metrics returns middleware that records Prometheus HTTP metrics on +// the default registry, which is the one the /metrics route gathers. +func (s *Middleware) Metrics() func(http.Handler) http.Handler { + return metricsMiddleware( + prommetrics.NewRecorder(prommetrics.Config{}), + ) +} + +// metricsMiddleware builds the recording middleware against a given +// recorder, so tests can gather from a registry of their own instead +// of the process-wide default. +func metricsMiddleware( + rec httpmetrics.Recorder, +) func(http.Handler) http.Handler { + mdlw := ghmm.New(ghmm.Config{ + Recorder: routePatternRecorder{inner: rec}, + }) + + return func(next http.Handler) http.Handler { + // The handler id is unmatchedRoute rather than "" so that + // the client-chosen URL path never enters the metrics + // pipeline at all: an empty id is the library's signal to + // substitute it. routePatternRecorder overwrites this value + // on every observation, so it is reachable only if that + // decorator is removed — in which case the metrics collapse + // to one series instead of leaking again. + return std.Handler(unmatchedRoute, mdlw, next) + } +} diff --git a/internal/middleware/metrics_test.go b/internal/middleware/metrics_test.go new file mode 100644 index 0000000..39776f2 --- /dev/null +++ b/internal/middleware/metrics_test.go @@ -0,0 +1,434 @@ +package middleware_test + +import ( + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/go-chi/chi" + "github.com/google/uuid" + "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" + prommetrics "github.com/slok/go-http-metrics/metrics/prometheus" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/config" + "sneak.berlin/go/webhooker/internal/middleware" +) + +const ( + // metricsProbePaths is how many distinct receiver paths each + // cardinality assertion drives. The defect these tests pin cost + // roughly 26 permanent series per distinct path, so a couple of + // hundred puts a regression thousands of series over the bound + // rather than leaving it to a rounding argument. + metricsProbePaths = 250 + + // receiverRoutePattern is the one handler label every receiver + // request must produce, however the client varies the path. + receiverRoutePattern = "/webhook/{uuid}" + + // okRoute is a static route used to pin that the response-writer + // interceptor still reports status and size after the handler id + // stopped coming from the URL. + okRoute = "/ok" + + // okBody is what okRoute writes, so the recorded response size is + // a number the test knows. + okBody = "ok" + + // generousReceiverLimit is a per-entrypoint receiver limit high + // enough that no probe in this file trips the limiter unless it + // means to. + generousReceiverLimit = 100000 + + // tightReceiverLimit forces the receiver's aggregate limiter to + // reject: the aggregate ceiling is ten times this, so a probe of + // metricsProbePaths requests spends it many times over. + tightReceiverLimit = 1 +) + +// metricsTestRouter builds a router whose middleware ordering mirrors +// the real server's: the metrics recorder is GLOBAL, installed by +// Server.setupGlobalMiddleware before chi has matched anything, and +// the receiver rate limiter is ROUTE-LEVEL, installed by +// Server.setupWebhookRoutes inside it. That ordering is the whole +// defect, so a test that flattens it would prove nothing. +// +// The recorder writes to a registry of the test's own rather than the +// process-wide default one, so each test observes only its own +// traffic. +func metricsTestRouter( + t *testing.T, + receiverLimit int, +) (http.Handler, *prometheus.Registry) { + t.Helper() + + log := slog.New(slog.DiscardHandler) + cfg := &config.Config{ + Environment: "prod", + ReceiverRateLimit: receiverLimit, + } + m := middleware.NewForTest( + log, cfg, newTestSessionManager(cfg, log, nil), + ) + + reg := prometheus.NewRegistry() + rec := prommetrics.NewRecorder(prommetrics.Config{Registry: reg}) + + r := chi.NewRouter() + r.Use(middleware.MetricsMiddlewareForTest(rec)) + + r.Get(okRoute, func(w http.ResponseWriter, _ *http.Request) { + _, _ = w.Write([]byte(okBody)) + }) + + // The real receiver answers 404 for a UUID naming no stored + // entrypoint, which is what every invented path here is. + r.With(m.ReceiverRateLimit()).HandleFunc( + receiverRoutePattern, + func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusNotFound) + }, + ) + + return r, reg +} + +// drivePaths sends one POST per supplied path and returns how many +// responses carried each status code. +func drivePaths( + t *testing.T, + h http.Handler, + paths []string, +) map[int]int { + t.Helper() + + codes := make(map[int]int) + + for _, p := range paths { + req := httptest.NewRequestWithContext( + t.Context(), http.MethodPost, p, nil, + ) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + codes[w.Code]++ + } + + return codes +} + +// receiverPaths returns n distinct /webhook/ paths, each naming a +// fresh UUID exactly as an unauthenticated flood would. +func receiverPaths(n int) []string { + paths := make([]string, 0, n) + + for range n { + paths = append(paths, "/webhook/"+uuid.NewString()) + } + + return paths +} + +// gatherMetrics returns the registry's current families, failing the +// test if gathering does. +func gatherMetrics( + t *testing.T, + reg *prometheus.Registry, +) []*dto.MetricFamily { + t.Helper() + + families, err := reg.Gather() + require.NoError(t, err) + + return families +} + +// labelValue returns the named label from a gathered metric. +func labelValue(m *dto.Metric, name string) string { + for _, pair := range m.GetLabel() { + if pair.GetName() == name { + return pair.GetValue() + } + } + + return "" +} + +// handlerLabels returns the set of distinct `handler` label values +// across every gathered series. +func handlerLabels(families []*dto.MetricFamily) map[string]struct{} { + seen := make(map[string]struct{}) + + for _, fam := range families { + for _, m := range fam.GetMetric() { + seen[labelValue(m, "handler")] = struct{}{} + } + } + + return seen +} + +// seriesCount is the number of distinct label sets held across every +// family: the quantity that grew without bound and was never +// reclaimed. +func seriesCount(families []*dto.MetricFamily) int { + total := 0 + + for _, fam := range families { + total += len(fam.GetMetric()) + } + + return total +} + +// keys returns the members of a set, for assertion messages. +func keys(set map[string]struct{}) []string { + out := make([]string, 0, len(set)) + + for k := range set { + out = append(out, k) + } + + return out +} + +// TestMetrics_DistinctReceiverPathsMintOneLabelSet is the direct +// assertion the issue asks for: N requests to N distinct +// /webhook/ paths must produce exactly ONE handler label, the +// route pattern. Before the fix this produced N of them. +func TestMetrics_DistinctReceiverPathsMintOneLabelSet(t *testing.T) { + t.Parallel() + + h, reg := metricsTestRouter(t, generousReceiverLimit) + + paths := receiverPaths(metricsProbePaths) + codes := drivePaths(t, h, paths) + require.Equal( + t, metricsProbePaths, codes[http.StatusNotFound], + "every invented UUID should have reached the receiver", + ) + + families := gatherMetrics(t, reg) + labels := handlerLabels(families) + + assert.Equal( + t, + map[string]struct{}{ + receiverRoutePattern: {}, + middleware.InflightHandlerConst: {}, + }, + labels, + "receiver traffic must collapse onto the route pattern", + ) + + // The scrape must not republish the UUIDs it was driven with. + // They are the receiver's only credential. + for _, p := range paths { + id := strings.TrimPrefix(p, "/webhook/") + for label := range labels { + assert.NotContains( + t, label, id, + "an entrypoint UUID reached a metrics label", + ) + } + } +} + +// TestMetrics_SeriesCountIsFlatUnderAFlood pins the property the +// issue measured against a live instance: driving thousands more +// distinct paths must not add series. The first batch establishes +// every label set the route can produce; the second must land on +// exactly those. +func TestMetrics_SeriesCountIsFlatUnderAFlood(t *testing.T) { + t.Parallel() + + h, reg := metricsTestRouter(t, generousReceiverLimit) + + drivePaths(t, h, receiverPaths(metricsProbePaths)) + before := seriesCount(gatherMetrics(t, reg)) + + drivePaths(t, h, receiverPaths(metricsProbePaths*4)) + after := seriesCount(gatherMetrics(t, reg)) + + assert.Equal( + t, before, after, + "a flood of distinct paths must not mint series", + ) +} + +// TestMetrics_RateLimitedRequestsCarryTheRoutePattern covers the +// majority case: most of the leaked series were 429s. Those requests +// never reach a handler, so they take a different path through the +// stack — but chi has already matched the route by the time the +// route-level limiter rejects them, and the recording happens after +// the whole chain returns, so they must land on the pattern too. +func TestMetrics_RateLimitedRequestsCarryTheRoutePattern(t *testing.T) { + t.Parallel() + + h, reg := metricsTestRouter(t, tightReceiverLimit) + + codes := drivePaths(t, h, receiverPaths(metricsProbePaths)) + require.Positive( + t, codes[http.StatusTooManyRequests], + "the probe must actually exhaust the aggregate limiter", + ) + + families := gatherMetrics(t, reg) + + assert.Equal( + t, + map[string]struct{}{ + receiverRoutePattern: {}, + middleware.InflightHandlerConst: {}, + }, + handlerLabels(families), + "rejected requests must collapse onto the route pattern", + ) + + rejected := 0 + + for _, fam := range families { + for _, m := range fam.GetMetric() { + if labelValue(m, "code") != "429" { + continue + } + + rejected++ + + assert.Equal( + t, receiverRoutePattern, + labelValue(m, "handler"), + "a 429 series carried a non-pattern handler", + ) + } + } + + assert.Positive( + t, rejected, "no 429 series was recorded at all", + ) +} + +// TestMetrics_UnmatchedPathsCollapseToTheSentinel decides and pins the +// unmatched-route case. A path matching no route has no pattern, so +// it carries the same fixed sentinel the access log uses. Without +// that, an unmatched flood leaks exactly as the receiver did. +func TestMetrics_UnmatchedPathsCollapseToTheSentinel(t *testing.T) { + t.Parallel() + + h, reg := metricsTestRouter(t, generousReceiverLimit) + + paths := make([]string, 0, metricsProbePaths) + + for i := range metricsProbePaths { + id := uuid.NewString() + + // Two shapes: one matching no prefix at all, and one under + // the receiver prefix but with a segment count the pattern + // cannot match. + if i%2 == 0 { + paths = append(paths, "/"+id) + } else { + paths = append(paths, "/webhook/"+id+"/"+id) + } + } + + codes := drivePaths(t, h, paths) + require.Equal( + t, metricsProbePaths, codes[http.StatusNotFound], + "every probe path should have gone unmatched", + ) + + labels := handlerLabels(gatherMetrics(t, reg)) + + assert.Equal( + t, + map[string]struct{}{ + middleware.UnmatchedRouteConst: {}, + middleware.InflightHandlerConst: {}, + }, + labels, + "unmatched paths must collapse onto one sentinel, got %v", + keys(labels), + ) +} + +// TestMetrics_InflightGaugeIsAggregateAndBalanced pins the one metric +// that cannot carry a pattern. It is incremented before routing and +// decremented after, so it gets a fixed label -- and the two calls +// must therefore agree, leaving the gauge at zero once the traffic +// has drained rather than stuck above it. +func TestMetrics_InflightGaugeIsAggregateAndBalanced(t *testing.T) { + t.Parallel() + + h, reg := metricsTestRouter(t, generousReceiverLimit) + + drivePaths(t, h, receiverPaths(metricsProbePaths)) + + var inflight []*dto.Metric + + for _, fam := range gatherMetrics(t, reg) { + if strings.HasSuffix(fam.GetName(), "requests_inflight") { + inflight = fam.GetMetric() + } + } + + require.Len( + t, inflight, 1, + "the inflight gauge must hold exactly one series", + ) + assert.Equal( + t, middleware.InflightHandlerConst, + labelValue(inflight[0], "handler"), + ) + assert.InDelta( + t, 0.0, inflight[0].GetGauge().GetValue(), 0.0, + "the gauge must balance back to zero", + ) +} + +// TestMetrics_StatusAndSizeStillRecorded guards the response-writer +// interceptor the recording middleware wraps around every request. +// The handler label changed; what the interceptor reports must not +// have. +func TestMetrics_StatusAndSizeStillRecorded(t *testing.T) { + t.Parallel() + + h, reg := metricsTestRouter(t, generousReceiverLimit) + + req := httptest.NewRequestWithContext( + t.Context(), http.MethodGet, okRoute, nil, + ) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + + require.Equal(t, http.StatusOK, w.Code) + require.Equal(t, okBody, w.Body.String()) + + var size *dto.Metric + + for _, fam := range gatherMetrics(t, reg) { + if !strings.HasSuffix(fam.GetName(), "response_size_bytes") { + continue + } + + for _, m := range fam.GetMetric() { + if labelValue(m, "handler") == okRoute { + size = m + } + } + } + + require.NotNil( + t, size, "no response size series for the static route", + ) + assert.Equal(t, "200", labelValue(size, "code")) + assert.Equal(t, uint64(1), size.GetHistogram().GetSampleCount()) + assert.InDelta( + t, float64(len(okBody)), + size.GetHistogram().GetSampleSum(), 0.0, + "the interceptor must still count written bytes", + ) +} diff --git a/internal/middleware/middleware.go b/internal/middleware/middleware.go index fe76fa0..98140fb 100644 --- a/internal/middleware/middleware.go +++ b/internal/middleware/middleware.go @@ -13,9 +13,6 @@ import ( "github.com/go-chi/chi" "github.com/go-chi/chi/middleware" "github.com/go-chi/cors" - metrics "github.com/slok/go-http-metrics/metrics/prometheus" - ghmm "github.com/slok/go-http-metrics/middleware" - "github.com/slok/go-http-metrics/middleware/std" "go.uber.org/fx" "sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/globals" @@ -29,10 +26,15 @@ const ( // preflight response can be cached. corsMaxAge = 300 - // unmatchedRoute is logged in the access log's url field when a - // redirected or rejected request matched no route pattern at - // all. Every byte of such a path is client-chosen, so none of it - // is logged. + // unmatchedRoute stands in for a request that matched no route + // pattern at all. Every byte of such a path is client-chosen, so + // none of it is kept. + // + // It is the access log's url field on a redirected or rejected + // request, and it is the metrics `handler` label on the same + // request; see metrics.go. Both surfaces are written once per + // request from a path the client picks, so both have to collapse + // the unmatched case into one fixed value. unmatchedRoute = "(unmatched)" // redactedQuery stands in for the query string on the access log @@ -438,17 +440,6 @@ func (s *Middleware) RequireAuth() func(http.Handler) http.Handler { } } -// Metrics returns middleware that records Prometheus HTTP metrics. -func (s *Middleware) Metrics() func(http.Handler) http.Handler { - mdlw := ghmm.New(ghmm.Config{ - Recorder: metrics.NewRecorder(metrics.Config{}), - }) - - return func(next http.Handler) http.Handler { - return std.Handler("", mdlw, next) - } -} - // MetricsAuth returns middleware that protects metrics endpoints // with basic auth. func (s *Middleware) MetricsAuth() func(http.Handler) http.Handler {