Author SHA1 Message Date
sneak 5ec908df6c Label a request with an empty path by the / route in metrics
check / check (push) Waiting to run
When both r.URL.Path and r.URL.RawPath are empty, as for the request
line GET http://pixa.example HTTP/1.1, chi routes the request as /, but
routePattern asked Find about the empty path and labelled it unmatched.
It now uses / then, as chi does. After the rebase onto next, the TODO.md
entry is back at the top of Completed Steps.

Model: opus-5-5
2026-10-15 12:32:27 +00:00
sneak 874e9217c1 Test that metrics label a request with an empty path as /
check / check (push) Waiting to run
A request line such as GET http://pixa.example HTTP/1.1 leaves the
request's path empty; chi routes it as /, so its label is the / route's
pattern.

Model: opus-5-5
2026-10-15 12:18:06 +00:00
sneak 61bf034f7e Keep the metrics entry at the top of Completed Steps
The rebase onto next placed the entry for this change below the one
next gained meanwhile; the TODO.md workflow puts a finished step at
the top.

Model: opus-5-5
2026-10-15 12:16:02 +00:00
sneak fe799dd94a 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
2026-10-15 12:16:02 +00:00
sneak 95621636c7 Test that metrics label requests for /v1 and /v1/ unmatched
No route answers /v1 or /v1/, the path the image subrouter is mounted
at, and the router answers both with 404, yet the metrics middleware
labels them "/v1" and "/v1/". The test now sends both and expects them
counted under "unmatched". It fails.

Model: opus-5-5
2026-10-15 12:16:02 +00:00
sneak c16618a7fc Label request metrics by route, not by path (closes #254)
The metrics middleware gave the handler label each request's path, so
every new path added series that were never removed, and /metrics
listed encrypted URL tokens. The label is now the pattern of the chi
route the request matches, or "unmatched" for one that matches none.
The metrics library takes the label before calling the handler, so the
middleware asks the router with chi's Find which route matches.

Model: opus-5-5
2026-10-15 12:16:02 +00:00
sneak 2f85b861bd Test that metrics label requests by route, not path
The new test sends two paths one route answers and three requests no
route answers through the metrics middleware, and expects the handler
label to hold the route's pattern and "unmatched". It fails: the label
is each request's path, so every new path adds series.

TestMetricsRecordsServedRequest serves its request outside any router,
so it now expects handler="unmatched" where it expected the path
handler="/test", as the owner approved in
#254 (comment).

Middleware gets a metricsRegistry field, nil being Prometheus' default
registry, so the new test can register with a registry of its own:
TestMetricsRecordsServedRequest registers with the default one.

Model: opus-5-5
2026-10-15 12:16:02 +00:00
11 changed files with 196 additions and 284 deletions
+7 -21
View File
@@ -314,26 +314,9 @@ cache at once, they share one upstream fetch (or one read of the cached source)
and one transcode: the first request does the work, and the others wait for its
image or its error, holding no upstream connection or processing slot of their
own. A waiting request stops waiting when its own client goes away. The work
goes on for the others even if the first request's client goes away. The shared
fetch sends the first request's ID upstream, and the lines logged for the fetch
and the transcode carry that ID.
A transcode whose request's `downstream_timeout` has ended (for a shared one,
the first request's) stops waiting for a processing slot, or, once it has one,
gives it back without beginning to encode. A request waiting for a shared
transcode that stops this way is answered 503 with the error
`server busy, try again later`, though its own `downstream_timeout` may not have
ended. govips gives pixa no way to stop libvips once an encode has begun, so an
encode keeps its slot until it finishes, which can be after
`downstream_timeout`. The limit of 8192 on each side of the source and of the
output bounds how long that takes. With one libvips thread, as pixad runs it,
encoding 8192x8192 random pixels takes up to about 1 second as JPEG, 15 as PNG,
16 as GIF, 63 as WebP, 110 as AVIF and 96 as JPEG XL, the slowest of 8 or 16
bits per sample, with or without an alpha channel. WebP, AVIF and JPEG XL are
that slow only with an alpha channel: 8-bit RGB takes about 44, 53 and 28
seconds. Decoding such a source adds up to about 11 seconds. A WebP, AVIF or
JPEG XL encode can therefore hold its slot past the default `downstream_timeout`
of 60 seconds.
goes on for the others even if the first request's client goes away, until that
request's `downstream_timeout` ends. The shared fetch sends the first request's
ID upstream, and the lines logged for the fetch and the transcode carry that ID.
The login form (`POST /`) is limited to 5 attempts per minute per client
address, counting an IPv6 client by its /64; an attempt over the limit is
@@ -657,7 +640,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
+14 -23
View File
@@ -30,24 +30,15 @@ P2: security: per-origin rate limiting
# Completed Steps
- 2026-10-15 a transcode stops once its request's `downstream_timeout` has
ended, unless it has begun encoding (closes #243): the image processor looked
at its context only while it waited for a processing slot, so an image was
decoded and encoded, holding the slot, however long after its request's
deadline that took. `Process` now returns the context's error, and gives the
slot back, when the context has ended by the time it has the slot or before it
encodes. A request that waited for a shared transcode stopped at the first
request's deadline is answered 503 `server busy, try again later`, not 500,
though its own `downstream_timeout` may not have ended. govips gives pixa no
way to stop libvips once an encode has begun, so that encode keeps its slot
until it finishes; the limit of 8192 on each side of the source and of the
output bounds how long that takes. With one libvips thread, 8192x8192 random
pixels take up to about 1 second to encode as JPEG, 15 as PNG, 16 as GIF, 63
as WebP, 110 as AVIF and 96 as JPEG XL, the last three with an alpha channel,
plus up to about 11 seconds to decode the source; `README.md` gives these
times and no longer says the work stops when `downstream_timeout` ends. The
settings of the WebP, AVIF and JPEG XL encoders, which can hold a slot past
the default `downstream_timeout` of 60 seconds, are unchanged.
- 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 cached variant is served while its source URL is in the negative
cache (closes #245): `Get` checked the negative cache before the variant
cache, so once a fetch of the source failed, as one does when another variant
@@ -540,11 +531,11 @@ P2: security: per-origin rate limiting
cancellation but keeps its deadline, and the others wait for its image or
error holding no upstream connection or processing slot, and stop waiting when
their own context ends; the request doing the processing waits for it even
then, until it ends, which can be after its deadline; a request whose context
has already ended starts nothing; each request counts one miss, and the
processing counts its fetch and transcode once; a panic while processing is
reported to Sentry when `sentry_dsn` is set and becomes an error for every
waiting request instead of stopping pixad; documented in `README.md`.
then, up to its deadline; a request whose context has already ended starts
nothing; each request counts one miss, and the processing counts its fetch and
transcode once; a panic while processing is reported to Sentry when
`sentry_dsn` is set and becomes an error for every waiting request instead of
stopping pixad; documented in `README.md`.
- 2026-09-29 only the image routes send CORS headers (closes #98): the CORS
middleware, with the `access_control_allow_origin` origin, moved from the
router root onto a `/v1` subrouter holding `/v1/image/` and `/v1/e/`, where it
+1 -2
View File
@@ -240,8 +240,7 @@ func (s *Handlers) respondImageError(
}
if errors.Is(err, httpfetcher.ErrTooManyConnections) ||
errors.Is(err, imageprocessor.ErrTooManyImages) ||
errors.Is(err, imgcache.ErrProcessingTimedOut) {
errors.Is(err, imageprocessor.ErrTooManyImages) {
s.respondError(w, "server busy, try again later",
http.StatusServiceUnavailable)
+1 -2
View File
@@ -158,8 +158,7 @@ func (s *Handlers) handleImageError(w http.ResponseWriter, err error) {
case errors.Is(err, httpfetcher.ErrUpstreamTimeout):
s.respondError(w, "upstream timeout", http.StatusGatewayTimeout)
case errors.Is(err, httpfetcher.ErrTooManyConnections),
errors.Is(err, imageprocessor.ErrTooManyImages),
errors.Is(err, imgcache.ErrProcessingTimedOut):
errors.Is(err, imageprocessor.ErrTooManyImages):
s.respondError(w, "server busy, try again later",
http.StatusServiceUnavailable)
case errors.Is(err, httpfetcher.ErrInvalidContentType),
@@ -1,7 +1,6 @@
package handlers
import (
"context"
"fmt"
"log/slog"
"net/http"
@@ -48,40 +47,3 @@ func TestServerBusyAnswers503(t *testing.T) {
}
}
}
// TestProcessingTimedOutAnswers503 checks that respondImageError and
// handleImageError, which answer the errors of the two image routes, answer
// 503 with the server busy error when the image service reports that
// processing stopped at the deadline of the request doing it, wrapped as the
// service wraps it. A request that waited for that processing gets this error
// while its own deadline may have time left. The request's source only goes
// into a log line, so it is left empty.
func TestProcessingTimedOutAnswers503(t *testing.T) {
t.Parallel()
h := &Handlers{log: slog.New(slog.DiscardHandler)}
err := fmt.Errorf("%w: failed to encode: %w",
imgcache.ErrProcessingTimedOut, context.DeadlineExceeded)
plain := httptest.NewRecorder()
h.respondImageError(plain, &imgcache.ImageRequest{}, err)
encrypted := httptest.NewRecorder()
h.handleImageError(encrypted, err)
for name, rec := range map[string]*httptest.ResponseRecorder{
"respondImageError": plain, "handleImageError": encrypted,
} {
t.Logf("%s: status = %d, body = %q", name, rec.Code, rec.Body.String())
if rec.Code != http.StatusServiceUnavailable {
t.Errorf("%s: status = %d, want %d",
name, rec.Code, http.StatusServiceUnavailable)
}
if !strings.Contains(rec.Body.String(), "server busy, try again later") {
t.Errorf("%s: body = %q, want the server busy error",
name, rec.Body.String())
}
}
}
@@ -1,106 +0,0 @@
package imageprocessor
import (
"bytes"
"context"
"errors"
"io"
"testing"
"time"
)
// readerAfterDeadline is a Process input whose first Read waits until done
// is closed, so the deadline passes after Process has taken its slot and
// before it encodes.
type readerAfterDeadline struct {
data *bytes.Reader
done <-chan struct{}
waited bool
}
func (r *readerAfterDeadline) Read(p []byte) (int, error) {
if !r.waited {
r.waited = true
<-r.done
}
return r.data.Read(p)
}
// inputNotToBeRead is a Process input that fails the test when it is read.
type inputNotToBeRead struct {
t *testing.T
}
func (r inputNotToBeRead) Read([]byte) (int, error) {
r.t.Error("Process read its input although its deadline had passed")
return 0, io.EOF
}
// TestProcessStopsWhenDeadlinePassed checks that Process returns
// context.DeadlineExceeded, and holds no slot afterwards, when its context's
// deadline has passed before it starts, then without reading its input, or
// while it reads its input. govips gives pixa no way to stop libvips once an
// encode has begun, so Process must not begin one for a request that has
// ended.
func TestProcessStopsWhenDeadlinePassed(t *testing.T) {
t.Parallel()
input := createTestJPEG(t, 50, 50)
t.Run("before Process starts", func(t *testing.T) {
t.Parallel()
ctx, cancel := context.WithDeadline(t.Context(),
time.Now().Add(-time.Second))
defer cancel()
// With a slot free, the select in acquireSlot takes the slot or sees
// the ended context at random, so Process is called many times
for range 100 {
checkProcessStopsAtDeadline(ctx, t, inputNotToBeRead{t: t})
}
})
t.Run("while Process reads its input", func(t *testing.T) {
t.Parallel()
ctx, cancel := context.WithTimeout(t.Context(), 100*time.Millisecond)
defer cancel()
checkProcessStopsAtDeadline(ctx, t, &readerAfterDeadline{
data: bytes.NewReader(input), done: ctx.Done(),
})
})
}
// checkProcessStopsAtDeadline runs Process on input with ctx, whose deadline
// has passed by the time Process could encode, and fails the test unless
// Process returns context.DeadlineExceeded and gives its slot back.
func checkProcessStopsAtDeadline(
ctx context.Context, t *testing.T, input io.Reader,
) {
t.Helper()
proc := New(Params{MaxConcurrentProcessing: 1})
result, err := proc.Process(ctx, input, smallJPEGRequest())
if result != nil {
t.Logf("Process() made a %dx%d image after its deadline passed",
result.Width, result.Height)
_ = result.Content.Close()
}
t.Logf("Process() error = %v", err)
if !errors.Is(err, context.DeadlineExceeded) {
t.Errorf("Process() error = %v, want context.DeadlineExceeded", err)
}
if held := len(proc.processingSemaphore); held != 0 {
t.Errorf("%d slots still held after Process() returned", held)
}
}
+20 -34
View File
@@ -208,10 +208,7 @@ func New(params Params) *ImageProcessor {
// Process transforms an image according to the request. When
// MaxConcurrentProcessing images are already being processed, it waits up
// to ProcessingWaitTimeout for one to finish, then fails with
// ErrTooManyImages. When ctx has ended once Process has a slot, or before it
// encodes, it returns ctx's error and gives the slot back. govips gives pixa
// no way to stop libvips once an encode has begun, so an encode keeps its
// slot until it finishes.
// ErrTooManyImages.
func (p *ImageProcessor) Process(
ctx context.Context,
input io.Reader,
@@ -293,7 +290,7 @@ func (p *ImageProcessor) Process(
}
// Encode to target format
output, err := p.encode(ctx, img, outputFormat, req.Quality)
output, err := p.encode(img, outputFormat, req.Quality)
if err != nil {
return nil, fmt.Errorf("failed to encode: %w", err)
}
@@ -420,28 +417,25 @@ func (p *ImageProcessor) WaitForProcessing(ctx context.Context) int {
// acquireSlot takes a slot in processingSemaphore, waiting at most
// processingWaitTimeout for one to free up, and returns the func that gives
// it back. When ctx has ended by the time it has a slot, it gives the slot
// back and returns ctx's error.
// it back. A free slot is taken even when ctx has ended; only the wait for
// one stops when ctx ends, as the rest of Process does not check ctx.
func (p *ImageProcessor) acquireSlot(ctx context.Context) (func(), error) {
release := func() { <-p.processingSemaphore }
select {
case p.processingSemaphore <- struct{}{}:
return release, nil
default:
}
select {
case p.processingSemaphore <- struct{}{}:
return release, nil
case <-time.After(p.processingWaitTimeout):
return nil, ErrTooManyImages
case <-ctx.Done():
return nil, ctx.Err()
}
release := func() { <-p.processingSemaphore }
// select takes the slot even when ctx has ended at the same moment
err := ctx.Err()
if err != nil {
release()
return nil, err
}
return release, nil
}
// detectFormat returns the format string for a govips image type.
@@ -533,17 +527,10 @@ func (p *ImageProcessor) resize(
const defaultQuality = 85
// encode encodes an image to the specified format. govips gives pixa no way
// to stop libvips once an encode has begun, so when ctx has ended encode
// returns ctx's error without beginning one.
// encode encodes an image to the specified format.
func (p *ImageProcessor) encode(
ctx context.Context, img *vips.ImageRef, format Format, quality int,
img *vips.ImageRef, format Format, quality int,
) ([]byte, error) {
err := ctx.Err()
if err != nil {
return nil, err
}
if quality <= 0 {
quality = defaultQuality
}
@@ -553,7 +540,7 @@ func (p *ImageProcessor) encode(
// libvips' built-in profile; govips' own sRGB path variable is set on
// first use but read without a lock, so concurrent requests race on it.
if img.HasICCProfile() {
err = img.TransformICCProfileWithFallback("srgb", "srgb")
err := img.TransformICCProfileWithFallback("srgb", "srgb")
if err != nil {
return nil, fmt.Errorf("failed to convert to sRGB: %w", err)
}
@@ -645,11 +632,10 @@ func exportWebP(img *vips.ImageRef, quality int) ([]byte, error) {
// avifEffort is the AVIF effort, from 0 (fastest) to 9; 1 is the lowest
// govips can set. With one thread, as pixad runs libvips, 1 takes about 51
// seconds to save an 8192x8192 RGB image of random pixels, and about 110
// with an alpha channel, the worst case, against the default
// downstream_timeout of 60 seconds. On an image of milder noise, which 1
// saves in about 12 seconds, 2 takes nearly a minute and libvips' default,
// 4, takes minutes.
// seconds to save an 8192x8192 image of random pixels, the worst case,
// against the default downstream_timeout of 60 seconds. On an image of
// milder noise, which 1 saves in about 12 seconds, 2 takes nearly a minute
// and libvips' default, 4, takes minutes.
const avifEffort = 1
// avifBitdepth is the AVIF bit depth, 8 bits per sample for every image.
@@ -15,7 +15,6 @@ import (
"github.com/getsentry/sentry-go"
"sneak.berlin/go/pixa/internal/httpfetcher"
"sneak.berlin/go/pixa/internal/imageprocessor"
"sneak.berlin/go/pixa/internal/magic"
)
@@ -436,47 +435,6 @@ func TestService_Get_ReturnsByItsDeadline(t *testing.T) {
}
}
// TestService_Get_WaiterGetsProcessingTimedOut has a request with no deadline
// join the held fetch of a first request with a short one. With the only
// processing slot held, the first request's transcode waits for it until the
// first request's deadline ends, and stops then. The waiting request, whose
// own context has not ended, must get ErrProcessingTimedOut, which the image
// routes answer 503 as when pixa is busy.
func TestService_Get_WaiterGetsProcessingTimedOut(t *testing.T) {
t.Parallel()
svc, fixtures, fetcher := setupHeldFetchService(t)
svc.processor = imageprocessor.New(
imageprocessor.Params{MaxConcurrentProcessing: 1},
)
holdProcessingSlot(t, svc.processor)
const firstTimeout = 500 * time.Millisecond
firstCtx, cancelFirst := context.WithTimeout(t.Context(), firstTimeout)
defer cancelFirst()
first := startGet(firstCtx, svc, photoVariant(fixtures, 85, FitCover))
<-fetcher.started
waiter := startGet(t.Context(), svc, photoVariant(fixtures, 85, FitCover))
time.Sleep(arrivalWait)
fetcher.releaseFetches()
t.Logf("first request: Get() error = %v", (<-first).err)
got := <-waiter
t.Logf("waiting request: Get() error = %v", got.err)
if !errors.Is(got.err, ErrProcessingTimedOut) {
t.Errorf("waiting request: Get() error = %v, want %v",
got.err, ErrProcessingTimedOut)
}
}
// panickingFetcher panics on every fetch.
type panickingFetcher struct{}
-12
View File
@@ -129,12 +129,6 @@ func NewService(cfg *ServiceConfig) (*Service, error) {
// ErrNegativeCached is returned when a URL is in the negative cache (recently failed).
var ErrNegativeCached = errors.New("request is in negative cache (recently failed)")
// ErrProcessingTimedOut is returned when processing an image stopped because
// the downstream_timeout of the request doing it ended, to that request and to
// every request that waited for its image.
var ErrProcessingTimedOut = errors.New(
"image processing stopped at the deadline of the request doing it")
// Get retrieves a processed image, fetching and processing if necessary.
// While its source URL is in the negative cache, a cached variant is still
// served and a variant not in the cache is still made from a cached source;
@@ -555,13 +549,7 @@ func (s *Service) processAndStore(
FitMode: imageprocessor.FitMode(req.FitMode),
}
// ctx has the deadline of the request doing the processing, which can
// end while a request waiting for its image has time left
processResult, err := s.processor.Process(ctx, source, processReq)
if errors.Is(err, context.DeadlineExceeded) {
return nil, fmt.Errorf("%w: %w", ErrProcessingTimedOut, err)
}
if err != nil {
return nil, fmt.Errorf("image processing failed: %w", err)
}
+58 -3
View File
@@ -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,65 @@ 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, else /.
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
}
if path == "" {
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(
@@ -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,97 @@ 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/. A request with an empty
// path is answered by the / route, as chi routes it as /, and is labelled /.
// 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.Get("/", func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusOK)
})
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"},
// The request line GET http://pixa.example HTTP/1.1 leaves both
// r.URL.Path and r.URL.RawPath empty.
{http.MethodGet, "http://pixa.example"},
} {
r := httptest.NewRequestWithContext(
t.Context(), req.method, req.path, nil)
t.Logf("%s %s: r.URL.Path %q, r.URL.RawPath %q",
req.method, req.path, r.URL.Path, r.URL.RawPath)
router.ServeHTTP(httptest.NewRecorder(), r)
}
got := requestCountsByHandler(t, registry)
t.Logf("requests counted by handler label: %v", got)
want := map[string]uint64{"/": 1, "/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.