Label requests for a subrouter's own path unmatched in metrics

For /v1 and /v1/, the path the image subrouter is mounted at, chi's
Find answers that path as the pattern without asking the subrouter,
which chi hands the request as / and which has no route there, so the
router answers 404. routePattern now asks the subrouter mounted there
whether it has a route for /, and labels the request "unmatched" when
it has none.

Model: opus-5-5

README.md

@@ -198,11 +198,9 @@ path under `/v1/` answers 200, in maintenance mode too.
   redirects to, is `localhost`, ends in `.localhost` or `.local`, or has an
   address in a blocked network (see `blocked_networks`); 429 over
   `image_requests_per_minute` (below); 415 when the upstream answers with a
-  `Content-Type` that is not one of the source formats (below), with a body
-  whose first bytes are not those of the format its `Content-Type` names, or
-  with an image whose first bytes libvips reads as another format; 502 when the
-  upstream answered with an error status, and for 5 minutes after that, or after
-  a body whose first bytes are not those of its `Content-Type`, for the same
+  `Content-Type` that is not one of the source formats (below), or with an image
+  whose first bytes libvips reads as another format; 502 when the upstream
+  answered with an error status, and for 5 minutes after that for the same
   source URL; 503 when pixa is busy or in maintenance mode; 500 for any other
   failure.
 - `GET` or `HEAD` `/v1/e/<token>/<name>` — an image through an encrypted URL
@@ -281,12 +279,8 @@ above 8192.
 The source image may be JPEG, PNG, GIF, WebP, AVIF or JPEG XL. The upstream's
 `Content-Type` must name its format, and the image's first bytes must match it.
 An upstream answering with any other `Content-Type`, SVG included, is refused
-with 415. So is a body whose first bytes are not those of the format its
-`Content-Type` names, such as a JPEG sent as `image/png`, text sent as an image,
-or an empty body. pixa then does not fetch that source URL again for 5 minutes,
-and answers 502 for it meanwhile, as after an upstream error status. An image
-whose first bytes libvips reads as another format, such as an SVG whose first
-bytes pass the check for AVIF, is refused with 415 too.
+with 415, and so is an image whose first bytes libvips reads as another format,
+such as an SVG whose first bytes pass the check for AVIF.
 
 With the format `auto`, pixa chooses the format for each request from its
 `Accept` header, in this order:
@@ -637,7 +631,10 @@ See `configs/config.example.yml` for all options with defaults.
 - **Metrics**: Prometheus, at `/metrics`: generic HTTP request metrics
   (duration, response size, requests in flight) and the Go runtime and process
   metrics; requests are measured and `/metrics` is served only when
-  `metrics.username` and `metrics.password` are set
+  `metrics.username` and `metrics.password` are set. A request's `handler` label
+  is the pattern of the route it matches, such as `/v1/image/*`, never its path.
+  Requests that match no route share the label `unmatched`: those the router
+  answers 404 or 405, and CORS preflights
 - **Logging**: stdlib slog
 
 ## Entrypoints

TODO.md

@@ -30,15 +30,15 @@ P2: security: per-origin rate limiting
 
 # Completed Steps
 
-- 2026-10-15 a source whose first bytes do not match its `Content-Type` answers
-  415 (closes #253): a body whose first bytes are not those of the format its
-  `Content-Type` names, such as a JPEG sent as `image/png`, text, or a body
-  under 12 bytes, answered 500 on both image routes and was logged as an error
-  of pixa's, and each request for it fetched the whole body again. Both routes
-  now answer 415, and the image service logs it at warning level as a refused
-  source. It also gets a negative cache entry, as an upstream error status does,
-  so the source URL is not fetched again for 5 minutes and answers 502
-  meanwhile.
+- 2026-10-15 the request metrics are labelled by route, not by path (closes
+  #254): their `handler` label was each request's path, so every new path, a 404
+  or an encrypted URL, added series to the Prometheus registry that were never
+  removed, and `/metrics` listed every encrypted URL's token. The label is now
+  the pattern of the chi route the request matches, such as `/v1/image/*`, or
+  `unmatched` for a request that matches none: one the router answers 404 or
+  405, or a CORS preflight. The metrics library takes the label before the
+  request is routed, so the metrics middleware asks the router which route
+  matches.
 - 2026-10-15 a `:` in the source path or query no longer moves where the path
   ends and the query begins (closes #247): the signed data and the cache key
   joined host, path and query with `:` and no escaping, so a URL signed for

internal/handlers/first_bytes_internal_test.go

@@ -1,180 +0,0 @@
-package handlers
-
-import (
-	"bytes"
-	"encoding/json"
-	"image/color"
-	"log/slog"
-	"net/http"
-	"slices"
-	"testing"
-	"testing/fstest"
-	"time"
-
-	"github.com/go-chi/chi/v5"
-	"sneak.berlin/go/pixa/internal/encurl"
-	"sneak.berlin/go/pixa/internal/httpfetcher"
-	"sneak.berlin/go/pixa/internal/imgcache"
-)
-
-// mismatchedSourcePath is the path of the source that
-// TestFirstBytesNotMatchingContentType serves on allowlistedHost. The mock
-// fetcher names a file's Content-Type from its extension, so the source is
-// sent as image/png.
-const mismatchedSourcePath = "/images/source.png"
-
-// newRoutesFetchingThrough returns both image routes, and the Handlers behind
-// them, whose image service fetches through fetcher and has allowlistedHost on
-// its allowlist. The handlers and the image service log to log.
-func newRoutesFetchingThrough(
-	t *testing.T, fetcher httpfetcher.Fetcher, log *slog.Logger,
-) (*Handlers, http.Handler) {
-	t.Helper()
-
-	cache, err := imgcache.NewCache(setupTestDB(t), imgcache.CacheConfig{
-		StateDir:    t.TempDir(),
-		NegativeTTL: 5 * time.Minute,
-	})
-	if err != nil {
-		t.Fatalf("imgcache.NewCache() error = %v", err)
-	}
-
-	svc, err := imgcache.NewService(&imgcache.ServiceConfig{
-		Cache:      cache,
-		Fetcher:    fetcher,
-		SigningKey: testSigningKey,
-		Allowlist:  []string{allowlistedHost},
-		Logger:     log,
-	})
-	if err != nil {
-		t.Fatalf("imgcache.NewService() error = %v", err)
-	}
-
-	encGen, err := encurl.NewGenerator(testSigningKey)
-	if err != nil {
-		t.Fatalf("encurl.NewGenerator() error = %v", err)
-	}
-
-	h := &Handlers{log: log, imgSvc: svc, encGen: encGen}
-
-	r := chi.NewRouter()
-	r.Get("/v1/image/*", h.HandleImage())
-	r.Get("/v1/e/{token}/*", h.HandleImageEnc())
-
-	return h, r
-}
-
-// mismatchedSourcePlainURL returns the /v1/image/ URL of mismatchedSourcePath
-// on allowlistedHost at 50x50 as a JPEG.
-func mismatchedSourcePlainURL(*testing.T, *Handlers) string {
-	return "/v1/image/" + allowlistedHost + mismatchedSourcePath + "/50x50.jpeg"
-}
-
-// mismatchedSourceEncURL returns an encrypted /v1/e/ URL, made with h's
-// generator, of mismatchedSourcePath on allowlistedHost at 50x50 as a JPEG.
-func mismatchedSourceEncURL(t *testing.T, h *Handlers) string {
-	t.Helper()
-
-	token, err := h.encGen.Generate(&encurl.Payload{
-		SourceHost: allowlistedHost,
-		SourcePath: mismatchedSourcePath,
-		Width:      50,
-		Height:     50,
-		Format:     imgcache.FormatJPEG,
-	})
-	if err != nil {
-		t.Fatalf("Generate() error = %v", err)
-	}
-
-	return "/v1/e/" + token + "/img.jpg"
-}
-
-// loggedLevels reads the JSON log lines in logs and returns the messages
-// logged at each level.
-func loggedLevels(t *testing.T, logs *bytes.Buffer) map[string][]string {
-	t.Helper()
-
-	t.Logf("logged:\n%s", logs.String())
-
-	messages := make(map[string][]string)
-
-	dec := json.NewDecoder(logs)
-	for dec.More() {
-		var line struct {
-			Level string `json:"level"`
-			Msg   string `json:"msg"`
-		}
-
-		err := dec.Decode(&line)
-		if err != nil {
-			t.Fatalf("decoding log line: %v", err)
-		}
-
-		messages[line.Level] = append(messages[line.Level], line.Msg)
-	}
-
-	return messages
-}
-
-// TestFirstBytesNotMatchingContentType checks that both image routes answer
-// 415 for an upstream body whose first bytes are not those of the format its
-// Content-Type names, and log it as a refused source, not as an error of
-// pixa's. The next request for that source must answer 502 without fetching
-// it again, as after an upstream error status.
-func TestFirstBytesNotMatchingContentType(t *testing.T) {
-	t.Parallel()
-
-	bodies := map[string][]byte{
-		"JPEG sent as image/png":          generateTestJPEG(t, 10, 10, color.Black),
-		"text sent as image/png":          []byte("This is just text, not a PNG"),
-		"body too short to name a format": []byte("short"),
-	}
-
-	// The source's URL on each image route.
-	sourceURLs := map[string]func(*testing.T, *Handlers) string{
-		"plain URL":     mismatchedSourcePlainURL,
-		"encrypted URL": mismatchedSourceEncURL,
-	}
-
-	for bodyName, body := range bodies {
-		for urlName, sourceURL := range sourceURLs {
-			t.Run(urlName+", "+bodyName, func(t *testing.T) {
-				t.Parallel()
-
-				fetcher := &countingFetcher{
-					Fetcher: httpfetcher.NewMock(fstest.MapFS{
-						allowlistedHost + mismatchedSourcePath: &fstest.MapFile{
-							Data: body,
-						},
-					}),
-				}
-
-				var logs bytes.Buffer
-
-				h, routes := newRoutesFetchingThrough(t, fetcher,
-					slog.New(slog.NewJSONHandler(&logs, nil)))
-				target := sourceURL(t, h)
-
-				checkErrorBody(t, sendGet(t, routes, target),
-					http.StatusUnsupportedMediaType, "unsupported source format")
-
-				levels := loggedLevels(t, &logs)
-				if len(levels[slog.LevelError.String()]) != 0 {
-					t.Errorf("logged at error level: %q",
-						levels[slog.LevelError.String()])
-				}
-
-				if !slices.Contains(levels[slog.LevelWarn.String()], "source refused") {
-					t.Error(`no "source refused" line logged at warning level`)
-				}
-
-				checkErrorBody(t, sendGet(t, routes, target),
-					http.StatusBadGateway, "upstream error")
-
-				if n := fetcher.fetches.Load(); n != 1 {
-					t.Errorf("upstream fetched %d times, want 1", n)
-				}
-			})
-		}
-	}
-}

internal/handlers/image.go

@@ -15,7 +15,6 @@ import (
 	"sneak.berlin/go/pixa/internal/httpfetcher"
 	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imgcache"
-	"sneak.berlin/go/pixa/internal/magic"
 )
 
 // HandleImage handles the main image proxy route:
@@ -221,18 +220,6 @@ func (s *Handlers) HandleTooManyRequests() http.HandlerFunc {
 func (s *Handlers) respondImageError(
 	w http.ResponseWriter, req *imgcache.ImageRequest, err error,
 ) {
-	// An upstream body whose first bytes are not those of the format its
-	// Content-Type names is the upstream's error, not pixa's: the image
-	// service has logged it as a refused source.
-	if errors.Is(err, magic.ErrMagicByteMismatch) ||
-		errors.Is(err, magic.ErrUnknownFormat) ||
-		errors.Is(err, magic.ErrNotEnoughData) {
-		s.respondError(w, "unsupported source format",
-			http.StatusUnsupportedMediaType)
-
-		return
-	}
-
 	s.log.Error("failed to get image",
 		"host", req.SourceHost,
 		"path", req.SourcePath,

internal/handlers/imageenc.go

@@ -15,7 +15,6 @@ import (
 	"sneak.berlin/go/pixa/internal/httpfetcher"
 	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imgcache"
-	"sneak.berlin/go/pixa/internal/magic"
 )
 
 // HandleImageEnc handles requests to /v1/e/{token}/* for encrypted
@@ -163,10 +162,7 @@ func (s *Handlers) handleImageError(w http.ResponseWriter, err error) {
 		s.respondError(w, "server busy, try again later",
 			http.StatusServiceUnavailable)
 	case errors.Is(err, httpfetcher.ErrInvalidContentType),
-		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat),
-		errors.Is(err, magic.ErrMagicByteMismatch),
-		errors.Is(err, magic.ErrUnknownFormat),
-		errors.Is(err, magic.ErrNotEnoughData):
+		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat):
 		s.respondError(w, "unsupported source format",
 			http.StatusUnsupportedMediaType)
 	case errors.Is(err, imageprocessor.ErrOutputTooLarge):

internal/imgcache/service.go

@@ -438,7 +438,13 @@ func (s *Service) fetchAndProcess(
 	if err != nil {
 		// Store negative cache for certain errors
 		if isNegativeCacheable(err) {
-			s.storeNegative(ctx, req, extractStatusCode(err), err)
+			statusCode := extractStatusCode(err)
+
+			storeErr := s.cache.StoreNegative(ctx, req, statusCode, err.Error())
+			if storeErr != nil {
+				s.log.Warn("failed to store negative cache entry",
+					"host", req.SourceHost, "path", req.SourcePath, "error", storeErr)
+			}
 		}
 
 		return nil, fmt.Errorf("upstream fetch failed: %w", err)
@@ -484,16 +490,9 @@ func (s *Service) fetchAndProcess(
 		"cipher", fetchResult.TLSCipherSuite,
 	)
 
-	// Validate magic bytes match content type. A body that does not is the
-	// upstream's error, so it gets a negative cache entry, as an upstream
-	// error status does.
+	// Validate magic bytes match content type
 	err = magic.ValidateMagicBytes(sourceData, fetchResult.ContentType)
 	if err != nil {
-		s.log.Warn("source refused", "request_id", middleware.GetReqID(ctx),
-			"host", req.SourceHost, "path", req.SourcePath,
-			"content_type", fetchResult.ContentType, "error", err)
-		s.storeNegative(ctx, req, httpStatusUnsupportedMediaType, err)
-
 		return nil, fmt.Errorf("content validation failed: %w", err)
 	}
 
@@ -509,19 +508,6 @@ func (s *Service) fetchAndProcess(
 	)
 }
 
-// storeNegative stores a negative cache entry for req's source, whose fetch
-// failed with err, so the source is not fetched again until the entry
-// expires. A failure to store the entry is only logged.
-func (s *Service) storeNegative(
-	ctx context.Context, req *ImageRequest, statusCode int, err error,
-) {
-	storeErr := s.cache.StoreNegative(ctx, req, statusCode, err.Error())
-	if storeErr != nil {
-		s.log.Warn("failed to store negative cache entry",
-			"host", req.SourceHost, "path", req.SourcePath, "error", storeErr)
-	}
-}
-
 // processedVariant is a variant as processAndStore made it. Each request that
 // shared its processing serves it through a reader of its own.
 type processedVariant struct {
@@ -630,9 +616,8 @@ func signatureRequest(req *ImageRequest) *signature.Request {
 
 // HTTP status codes for error responses.
 const (
-	httpStatusBadGateway           = 502
-	httpStatusInternalError        = 500
-	httpStatusUnsupportedMediaType = 415
+	httpStatusBadGateway    = 502
+	httpStatusInternalError = 500
 )
 
 // isNegativeCacheable returns true if the error should be cached.

internal/middleware/middleware.go

@@ -8,12 +8,15 @@ import (
 	"net/http"
 	"net/netip"
 	"regexp"
+	"strings"
 	"time"
 
 	basicauth "github.com/99designs/basicauth-go"
+	"github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
 	"github.com/go-chi/cors"
 	"github.com/go-chi/httprate"
+	"github.com/prometheus/client_golang/prometheus"
 	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"
@@ -63,6 +66,10 @@ type Middleware struct {
 	log      *slog.Logger
 	config   *config.Config
 	clientIP *clientip.Resolver
+
+	// metricsRegistry is the registry Metrics registers its metrics with.
+	// nil is Prometheus' default registry, the one /metrics serves.
+	metricsRegistry prometheus.Registerer
 }
 
 // New creates a new Middleware instance.
@@ -209,17 +216,61 @@ func (s *Middleware) CORS() func(http.Handler) http.Handler {
 	})
 }
 
-// Metrics returns a Prometheus metrics middleware.
+// Metrics returns a Prometheus metrics middleware. Its handler label is the
+// pattern of the chi route a request matches, such as /v1/image/*, or
+// "unmatched" for a request that matches none, so the routes fix how many
+// values the label has. It is never the path, with which any client could
+// add series to the registry without limit.
 func (s *Middleware) Metrics() func(http.Handler) http.Handler {
 	mdlw := ghmm.New(ghmm.Config{
-		Recorder: metrics.NewRecorder(metrics.Config{}),
+		Recorder: metrics.NewRecorder(metrics.Config{
+			Registry: s.metricsRegistry,
+		}),
 	})
 
 	return func(next http.Handler) http.Handler {
-		return std.Handler("", mdlw, next)
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			std.Handler(routePattern(r), mdlw, next).ServeHTTP(w, r)
+		})
 	}
 }
 
+// routePattern returns the pattern of the chi route r matches, or
+// "unmatched" when it matches none or is not served by a chi router. The
+// metrics library takes the label before the request is routed, so the
+// router is asked which route matches, with the path it routes on:
+// r.URL.RawPath when set, else r.URL.Path.
+func routePattern(r *http.Request) string {
+	pattern := ""
+
+	rctx := chi.RouteContext(r.Context())
+	if rctx != nil {
+		path := r.URL.RawPath
+		if path == "" {
+			path = r.URL.Path
+		}
+
+		pattern = rctx.Routes.Find(chi.NewRouteContext(), r.Method, path)
+
+		// For the path a subrouter is mounted at, such as /v1 or /v1/, Find
+		// answers that path without asking the subrouter, which chi hands
+		// the request as /.
+		for _, route := range rctx.Routes.Routes() {
+			if route.SubRoutes != nil &&
+				route.Pattern == strings.TrimSuffix(pattern, "/")+"/*" &&
+				!route.SubRoutes.Match(chi.NewRouteContext(), r.Method, "/") {
+				pattern = ""
+			}
+		}
+	}
+
+	if pattern == "" {
+		return "unmatched"
+	}
+
+	return pattern
+}
+
 // MetricsAuth returns a basic auth middleware for the metrics endpoint.
 func (s *Middleware) MetricsAuth() func(http.Handler) http.Handler {
 	return basicauth.New(

internal/middleware/middleware_internal_test.go

@@ -3,12 +3,15 @@ package middleware
 import (
 	"bytes"
 	"log/slog"
+	"maps"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
 	"strings"
 	"testing"
 
+	"github.com/go-chi/chi/v5"
+	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 
 	"sneak.berlin/go/pixa/internal/config"
@@ -198,7 +201,7 @@ func TestMetricsRecordsServedRequest(t *testing.T) {
 
 	// The line /metrics shows once one GET /test has been served.
 	const want = `http_request_duration_seconds_count{` +
-		`code="200",handler="/test",method="GET",service=""} 1`
+		`code="200",handler="unmatched",method="GET",service=""} 1`
 
 	mw := &Middleware{log: slog.Default(), config: &config.Config{}}
 
@@ -220,6 +223,86 @@ func TestMetricsRecordsServedRequest(t *testing.T) {
 	}
 }
 
+// TestMetricsLabelsRequestsByRoute checks that the metrics middleware labels
+// each request with the pattern of the route that answers it, never with its
+// path: two paths one route answers share that route's pattern, and requests
+// no route answers, a 404 or a 405, share "unmatched", among them requests for
+// the path the subrouter is mounted at, /v1 and /v1/. With a label per path,
+// any client could add series to the registry without limit. The middleware
+// registers with a registry of its own here, as another test in this package
+// registers with Prometheus' default registry, which can be done only once.
+func TestMetricsLabelsRequestsByRoute(t *testing.T) {
+	t.Parallel()
+
+	registry := prometheus.NewRegistry()
+	mw := &Middleware{
+		log:             slog.Default(),
+		config:          &config.Config{},
+		metricsRegistry: registry,
+	}
+
+	// The image route is in a subrouter, as in pixa's router.
+	router := chi.NewRouter()
+	router.Use(mw.Metrics())
+	router.Route("/v1", func(r chi.Router) {
+		r.Get("/image/*", func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusOK)
+		})
+	})
+
+	for _, req := range []struct{ method, path string }{
+		{http.MethodGet, "/v1/image/a.example.com/one.jpg/1x1.png"},
+		{http.MethodGet, "/v1/image/b.example.com/two.jpg/1x1.png"},
+		{http.MethodGet, "/no-such-route"},
+		{http.MethodGet, "/v1/no-such-route"},
+		{http.MethodGet, "/v1"},
+		{http.MethodGet, "/v1/"},
+		{http.MethodPost, "/v1/image/a.example.com/one.jpg/1x1.png"},
+	} {
+		router.ServeHTTP(httptest.NewRecorder(), httptest.NewRequestWithContext(
+			t.Context(), req.method, req.path, nil))
+	}
+
+	got := requestCountsByHandler(t, registry)
+	t.Logf("requests counted by handler label: %v", got)
+
+	want := map[string]uint64{"/v1/image/*": 2, "unmatched": 5}
+	if !maps.Equal(got, want) {
+		t.Errorf("requests counted by handler label = %v, want %v", got, want)
+	}
+}
+
+// requestCountsByHandler returns how many requests the request duration
+// histogram in registry counted under each value of its handler label.
+func requestCountsByHandler(
+	t *testing.T, registry *prometheus.Registry,
+) map[string]uint64 {
+	t.Helper()
+
+	families, err := registry.Gather()
+	if err != nil {
+		t.Fatalf("registry.Gather() error = %v", err)
+	}
+
+	counts := map[string]uint64{}
+
+	for _, family := range families {
+		if family.GetName() != "http_request_duration_seconds" {
+			continue
+		}
+
+		for _, metric := range family.GetMetric() {
+			for _, label := range metric.GetLabel() {
+				if label.GetName() == "handler" {
+					counts[label.GetValue()] += metric.GetHistogram().GetSampleCount()
+				}
+			}
+		}
+	}
+
+	return counts
+}
+
 // TestLoggingLeavesOutSubmittedSigningKey checks that a login, a POST /
 // whose form carries the signing key, leaves no trace of the key in the
 // request's log line.