Compare commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
1ae38a2425 | ||
|
|
5101b9c4de | ||
|
|
a453aa9798 | ||
|
|
1ba4c8d39f | ||
|
|
74ce122dc4 |
@@ -314,9 +314,26 @@ 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, 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.
|
||||
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.
|
||||
|
||||
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
|
||||
@@ -640,10 +657,7 @@ 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. 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
|
||||
`metrics.username` and `metrics.password` are set
|
||||
- **Logging**: stdlib slog
|
||||
|
||||
## Entrypoints
|
||||
|
||||
@@ -30,15 +30,24 @@ P2: security: per-origin rate limiting
|
||||
|
||||
# Completed Steps
|
||||
|
||||
- 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 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 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
|
||||
@@ -531,11 +540,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, 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`.
|
||||
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`.
|
||||
- 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
|
||||
|
||||
@@ -240,7 +240,8 @@ func (s *Handlers) respondImageError(
|
||||
}
|
||||
|
||||
if errors.Is(err, httpfetcher.ErrTooManyConnections) ||
|
||||
errors.Is(err, imageprocessor.ErrTooManyImages) {
|
||||
errors.Is(err, imageprocessor.ErrTooManyImages) ||
|
||||
errors.Is(err, imgcache.ErrProcessingTimedOut) {
|
||||
s.respondError(w, "server busy, try again later",
|
||||
http.StatusServiceUnavailable)
|
||||
|
||||
|
||||
@@ -158,7 +158,8 @@ 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, imageprocessor.ErrTooManyImages),
|
||||
errors.Is(err, imgcache.ErrProcessingTimedOut):
|
||||
s.respondError(w, "server busy, try again later",
|
||||
http.StatusServiceUnavailable)
|
||||
case errors.Is(err, httpfetcher.ErrInvalidContentType),
|
||||
|
||||
@@ -1,6 +1,7 @@
|
||||
package handlers
|
||||
|
||||
import (
|
||||
"context"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"net/http"
|
||||
@@ -47,3 +48,40 @@ 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())
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -0,0 +1,106 @@
|
||||
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)
|
||||
}
|
||||
}
|
||||
@@ -208,7 +208,10 @@ 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.
|
||||
// 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.
|
||||
func (p *ImageProcessor) Process(
|
||||
ctx context.Context,
|
||||
input io.Reader,
|
||||
@@ -290,7 +293,7 @@ func (p *ImageProcessor) Process(
|
||||
}
|
||||
|
||||
// Encode to target format
|
||||
output, err := p.encode(img, outputFormat, req.Quality)
|
||||
output, err := p.encode(ctx, img, outputFormat, req.Quality)
|
||||
if err != nil {
|
||||
return nil, fmt.Errorf("failed to encode: %w", err)
|
||||
}
|
||||
@@ -417,25 +420,28 @@ 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. 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.
|
||||
// it back. When ctx has ended by the time it has a slot, it gives the slot
|
||||
// back and returns ctx's error.
|
||||
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.
|
||||
@@ -527,10 +533,17 @@ func (p *ImageProcessor) resize(
|
||||
|
||||
const defaultQuality = 85
|
||||
|
||||
// encode encodes an image to the specified format.
|
||||
// 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.
|
||||
func (p *ImageProcessor) encode(
|
||||
img *vips.ImageRef, format Format, quality int,
|
||||
ctx context.Context, img *vips.ImageRef, format Format, quality int,
|
||||
) ([]byte, error) {
|
||||
err := ctx.Err()
|
||||
if err != nil {
|
||||
return nil, err
|
||||
}
|
||||
|
||||
if quality <= 0 {
|
||||
quality = defaultQuality
|
||||
}
|
||||
@@ -540,7 +553,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)
|
||||
}
|
||||
@@ -632,10 +645,11 @@ 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 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.
|
||||
// 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.
|
||||
const avifEffort = 1
|
||||
|
||||
// avifBitdepth is the AVIF bit depth, 8 bits per sample for every image.
|
||||
|
||||
@@ -15,6 +15,7 @@ import (
|
||||
|
||||
"github.com/getsentry/sentry-go"
|
||||
"sneak.berlin/go/pixa/internal/httpfetcher"
|
||||
"sneak.berlin/go/pixa/internal/imageprocessor"
|
||||
"sneak.berlin/go/pixa/internal/magic"
|
||||
)
|
||||
|
||||
@@ -435,6 +436,47 @@ 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{}
|
||||
|
||||
|
||||
@@ -129,6 +129,12 @@ 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;
|
||||
@@ -549,7 +555,13 @@ 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)
|
||||
}
|
||||
|
||||
@@ -8,15 +8,12 @@ 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"
|
||||
@@ -66,10 +63,6 @@ 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.
|
||||
@@ -216,65 +209,17 @@ func (s *Middleware) CORS() func(http.Handler) http.Handler {
|
||||
})
|
||||
}
|
||||
|
||||
// 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.
|
||||
// Metrics returns a Prometheus metrics middleware.
|
||||
func (s *Middleware) Metrics() func(http.Handler) http.Handler {
|
||||
mdlw := ghmm.New(ghmm.Config{
|
||||
Recorder: metrics.NewRecorder(metrics.Config{
|
||||
Registry: s.metricsRegistry,
|
||||
}),
|
||||
Recorder: metrics.NewRecorder(metrics.Config{}),
|
||||
})
|
||||
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
std.Handler(routePattern(r), mdlw, next).ServeHTTP(w, r)
|
||||
})
|
||||
return std.Handler("", mdlw, next)
|
||||
}
|
||||
}
|
||||
|
||||
// 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,15 +3,12 @@ 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"
|
||||
@@ -201,7 +198,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="unmatched",method="GET",service=""} 1`
|
||||
`code="200",handler="/test",method="GET",service=""} 1`
|
||||
|
||||
mw := &Middleware{log: slog.Default(), config: &config.Config{}}
|
||||
|
||||
@@ -223,97 +220,6 @@ 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.
|
||||
|
||||
Reference in New Issue
Block a user