Answer 502 for an upstream host with no address or a failed fetch (closes #367)

The image routes answered 500 and logged at error level when the upstream
host had no address, when the fetch failed before the upstream answered,
or when the fetcher refused a redirect. Such a failure is now
ErrInvalidHost or ErrUpstreamRequestFailed, which respondImageError
answers 502 "upstream error" and logs at warn level. A TLS handshake, an
address lookup or a connection that times out is now ErrUpstreamTimeout
and answers 504; its log line keeps the cause. A cancelled fetch or
address lookup is neither ErrUpstreamRequestFailed nor ErrInvalidHost.
README Routes lists these answers.

Model: opus-5-5

.gitignore

@@ -70,4 +70,3 @@ vendor/
 # Local dev configs
 config.yml
 config.yaml
-config.dev.yml

Makefile

@@ -79,12 +79,15 @@ docker-versioned:
 docker-test:
 	@script/test
 
-# Run local dev server in Docker
+# Run local dev server in Docker, with debug on and a new random signing
+# key each run. Log in to the page with the key it prints.
 devserver: docker-versioned devserver-stop
+	@key="$$(head -c 32 /dev/urandom | base64)" && \
 	docker run -d --name pixad-dev -p 8080:8080 \
-		-v $(CURDIR)/config.dev.yml:/etc/pixa/config.yml:ro \
-		pixa:latest
-	@echo "pixad running at http://localhost:8080"
+		-e PIXA_SIGNING_KEY="$$key" -e PIXA_DEBUG=true \
+		pixa:latest >/dev/null && \
+	echo "pixad running at http://localhost:8080" && \
+	echo "signing key: $$key"
 
 # Stop dev server
 devserver-stop:

README.md

@@ -15,9 +15,10 @@ In this document, the upstream host is the server that holds an original image.
 ## Getting Started
 
 ```bash
-# clone and build
+# clone, install what compiling needs, and build
 git clone https://git.eeqj.de/sneak/pixa.git
 cd pixa
+script/bootstrap --cgo
 make build
 
 # make a config file from the example and put a real signing key in it
@@ -26,18 +27,30 @@ openssl rand -base64 32   # prints a new signing key
 $EDITOR config.yml        # replace the signing_key placeholder with it
 ./bin/pixad --config config.yml
 
-# or build and run the Docker image
+# or build and run the Docker image with that signing key
 make docker
-docker run -p 8080:8080 -e PIXA_SIGNING_KEY="$(openssl rand -base64 32)" pixa:latest
+docker run -p 8080:8080 -e PIXA_SIGNING_KEY='the new signing key' pixa:latest
 ```
 
-`make build` compiles pixa on your machine into `bin/pixad`. `pixad` is the
-server program. Compiling needs the libraries `script/bootstrap --cgo` installs
-(see Deployment).
+`script/bootstrap --cgo` installs Go, a C compiler and the image libraries pixa
+needs (see Deployment). `make build` then compiles pixa on your machine into
+`bin/pixad`. `pixad` is the server program.
 
 The signing key is pixa's one required secret. It must be 32 characters or
 longer. The placeholder in the example file is refused at startup.
 
+A container takes its settings from environment variables (see Configuration).
+Only `PIXA_SIGNING_KEY` is required. Without it, the container exits at startup
+and names the variable. Every other setting has a built-in default. A config
+file mounted at `/etc/pixa/config.yml` is read when present. An environment
+variable wins over the same setting in the file.
+
+pixa's login page is at `http://localhost:8080/`. Logging in there works only
+with `debug: true` in `config.yml`, or `-e PIXA_DEBUG=true` for the container.
+Otherwise pixa refuses the login with 403, because the page was opened over
+plain HTTP. Use `debug` only on your own machine. A pixa that others use serves
+its pages over HTTPS through a reverse proxy (see Deployment).
+
 Once pixa runs, it serves images through URLs of this form:
 
 ```
@@ -60,11 +73,25 @@ The example config allowlists no host. Every image on an allowlisted host is
 served to anyone, without a signature, at any size and in any format. So
 allowlist only hosts you control, where nobody else can put images.
 
-A container takes its settings from environment variables (see Configuration).
-Only `PIXA_SIGNING_KEY` is required. Without it, the container exits at startup
-and names the variable. Every other setting has a built-in default. A config
-file mounted at `/etc/pixa/config.yml` is read when present. An environment
-variable wins over the same setting in the file.
+To see pixa serve an image, sign a URL for an image on any public HTTPS server.
+Run this in a second terminal while pixa runs, with your own signing key and
+image:
+
+```bash
+key='the new signing key'
+image_host=cdn.example.com    # a public HTTPS server
+image_path=/photos/cat.jpg    # an image on it
+exp=$(($(date +%s) + 3600))   # the URL expires in one hour
+sig=$(printf '%s' "$image_host:$image_path::400:300:webp:$exp:85:cover" |
+    openssl dgst -sha256 -hmac "$key" -binary | base64 | tr '+/' '-_')
+curl --fail-with-body -o cat.webp \
+    "http://localhost:8080/v1/image/$image_host$image_path/400x300.webp?sig=$sig&exp=$exp"
+```
+
+`cat.webp` is then the image at 400x300. If pixa refuses the request, curl
+reports an error and `cat.webp` holds pixa's error message instead. The image
+path must not hold a `%`, a `:` or a query. Signed URLs explains how to sign
+those.
 
 ## Deployment
 
@@ -310,8 +337,19 @@ to any method the list does not give for it.
       neither the image nor its source in its cache.
     - 502 likewise for 5 minutes after a body whose first bytes are not those of
       its `Content-Type`.
+    - 502 when the upstream host, or a host it redirects to, has no address.
+    - 502 when the upstream redirects to a URL that is not `https`, or redirects
+      10 times.
+    - 502 when the fetch fails before the upstream answers, such as on a refused
+      connection or a failed TLS handshake.
     - 503 when pixa is busy (see Limits).
     - 503 in maintenance mode.
+    - 504 when the address lookup of the upstream host, or of a host it
+      redirects to, times out.
+    - 504 when the connection to the upstream host, or to a host it redirects
+      to, times out.
+    - 504 when the upstream has not finished the TLS handshake within 10
+      seconds.
     - 504 when the upstream has not sent its response headers within
       `upstream_fetch_timeout`.
     - 500 when that time runs out while the image itself is still arriving.
@@ -376,6 +414,10 @@ instead. Plain HTTP is for development on the browser's own machine. The login
 session cookie is always marked `Secure`. Over plain HTTP a browser keeps such a
 cookie only for its own machine (`localhost`), if at all.
 
+A form refused with 403 gets a page that names the cause and what to do about
+it. pixa logs a `form refused` warning with the request ID and the form-token
+library's reason, such as `origin invalid`.
+
 The image routes answer the errors listed for them with a JSON body holding
 `error`, `status` and `timestamp`.
 
@@ -1167,10 +1209,33 @@ Each item below is one setting, named by its config key:
     - the Go runtime and process metrics
     - `pixa_cache_hits_total`: image requests served from the cache
     - `pixa_cache_misses_total`: image requests not served from the cache
+    - `pixa_source_cache_hits_total`: variants made or checked whose source was
+      in the cache
+    - `pixa_source_cache_misses_total`: variants made or checked whose source
+      was not in the cache
+    - `pixa_cache_usage_bytes`: the bytes of sources and variants in the cache,
+      as eviction last read them; eviction runs after each store and every five
+      minutes
+    - `pixa_cache_max_bytes`: the disk cache limit, `cache_max_bytes`
+    - `pixa_cache_evictions_total`: sources and variants removed by eviction
+    - `pixa_cache_evicted_bytes_total`: the bytes those evictions freed
     - `pixa_upstream_fetches_total`: fetches of a source image that read any
       bytes
     - `pixa_upstream_fetch_bytes_total`: the bytes those fetches read
+    - `pixa_upstream_fetch_duration_seconds`: a histogram of how long those
+      fetches took, up to the last byte of the response
+    - `pixa_upstream_fetch_errors_total`: fetches of a source image that failed,
+      before or while reading the response
     - `pixa_transforms_total`: images converted
+    - `pixa_transform_duration_seconds`: a histogram of how long those
+      conversions took, including the wait for a processing slot
+    - `pixa_transforms_in_progress`: images being converted or waiting for a
+      processing slot
+
+    pixa measures the `pixa_` metrics whether or not `/metrics` is served. They
+    have no labels, so their number never grows with the hosts and paths pixa
+    serves. Requests that share work (see Limits) count one source cache hit or
+    miss between them.
 
     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

TODO.md

@@ -27,12 +27,5 @@ P2: security: per-origin rate limiting
 - P2: HTTP response handling
     - Last-Modified headers
 - P2: operational
-    - Prometheus metrics still missing:
-        - cache hits and misses, split into source images and variants
-        - cache size on disk and its limit
-        - evictions and the bytes they free
-        - upstream fetch duration and errors
-        - transcode duration
-        - images in processing
     - measure the 1k to 5k req/s target with `script/loadtest` on a machine not
       shared with other work

configs/config.example.yml

@@ -158,8 +158,9 @@ access_control_allow_origin: "*"
 # Sentry DSN for error reporting (default: empty, which turns it off)
 sentry_dsn: ""
 
-# Username and password for /metrics, set together (default: unset). Metrics
-# are measured and /metrics is served only when both are set.
+# Username and password for /metrics, set together (default: unset). pixa
+# serves /metrics, and measures HTTP requests, only when both are set. It
+# measures the pixa_ metrics either way.
 # metrics:
 #   username: "admin"
 #   password: "secret"

go.mod

@@ -17,6 +17,7 @@ require (
 	github.com/prometheus/client_golang v1.23.2
 	github.com/slok/go-http-metrics v0.13.0
 	github.com/spf13/cobra v1.10.2
+	go.uber.org/dig v1.19.0
 	go.uber.org/fx v1.24.0
 	golang.org/x/crypto v0.41.0
 	golang.org/x/sync v0.19.0
@@ -126,7 +127,6 @@ require (
 	go.opentelemetry.io/otel v1.36.0 // indirect
 	go.opentelemetry.io/otel/metric v1.36.0 // indirect
 	go.opentelemetry.io/otel/trace v1.36.0 // indirect
-	go.uber.org/dig v1.19.0 // indirect
 	go.uber.org/multierr v1.11.0 // indirect
 	go.uber.org/zap v1.27.0 // indirect
 	go.yaml.in/yaml/v2 v2.4.2 // indirect

internal/app/app.go

@@ -2,13 +2,16 @@
 package app
 
 import (
+	"context"
 	"fmt"
+	"io"
 	"os"
 	"os/signal"
 	"syscall"
 
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/spf13/cobra"
+	"go.uber.org/dig"
 	"go.uber.org/fx"
 	"sneak.berlin/go/pixa/internal/config"
 	"sneak.berlin/go/pixa/internal/database"
@@ -53,7 +56,10 @@ func run(_ *cobra.Command, _ []string) {
 	// A write to a closed stdout or stderr must not end the process.
 	signal.Ignore(syscall.SIGPIPE)
 
-	fx.New(
+	app := fx.New(
+		// pixad logs with slog only; runApp prints a startup or shutdown
+		// error itself.
+		fx.NopLogger,
 		fx.Provide(
 			config.New,
 			database.New,
@@ -71,5 +77,40 @@ func run(_ *cobra.Command, _ []string) {
 			func(log *logger.Logger) { log.Identify() },
 			func(*server.Server) {},
 		),
-	).Run()
+	)
+
+	exitCode := runApp(app, os.Stderr)
+	if exitCode != 0 {
+		os.Exit(exitCode)
+	}
+}
+
+// runApp starts app, waits for a signal or a shutdown request, stops app,
+// and returns the status pixad exits with, as fx.App.Run does. It prints
+// a start or stop error to stderr, once, as the error that caused it:
+// dig.RootCause drops the frames fx and dig wrap around it.
+func runApp(app *fx.App, stderr io.Writer) int {
+	startCtx, cancelStart := context.WithTimeout(context.Background(), app.StartTimeout())
+	defer cancelStart()
+
+	err := app.Start(startCtx)
+	if err != nil {
+		_, _ = fmt.Fprintln(stderr, dig.RootCause(err))
+
+		return 1
+	}
+
+	shutdown := <-app.Wait()
+
+	stopCtx, cancelStop := context.WithTimeout(context.Background(), app.StopTimeout())
+	defer cancelStop()
+
+	err = app.Stop(stopCtx)
+	if err != nil {
+		_, _ = fmt.Fprintln(stderr, dig.RootCause(err))
+
+		return 1
+	}
+
+	return shutdown.ExitCode
 }

internal/app/app_internal_test.go

@@ -0,0 +1,65 @@
+package app
+
+import (
+	"bytes"
+	"context"
+	"errors"
+	"io"
+	"testing"
+
+	"go.uber.org/fx"
+)
+
+var errTestStopFailed = errors.New("test stop hook failed")
+
+// TestRunAppPrintsStopErrorOnce checks that when a stop hook fails, runApp
+// prints the hook's error once and returns exit status 1.
+func TestRunAppPrintsStopErrorOnce(t *testing.T) {
+	t.Parallel()
+
+	app := fx.New(
+		fx.NopLogger,
+		fx.Invoke(func(lifecycle fx.Lifecycle, shutdowner fx.Shutdowner) {
+			lifecycle.Append(fx.Hook{
+				// Ask to shut down as soon as the app has started, so
+				// that runApp goes on to stop it.
+				OnStart: func(context.Context) error { return shutdowner.Shutdown() },
+				OnStop:  func(context.Context) error { return errTestStopFailed },
+			})
+		}),
+	)
+
+	var stderr bytes.Buffer
+
+	exitCode := runApp(app, &stderr)
+	if exitCode != 1 {
+		t.Errorf("runApp() = %d, want 1", exitCode)
+	}
+
+	want := errTestStopFailed.Error() + "\n"
+	if stderr.String() != want {
+		t.Errorf("stderr = %q, want %q", stderr.String(), want)
+	}
+}
+
+// TestRunAppReturnsShutdownExitCode checks that runApp returns the exit
+// code a shutdown request names.
+func TestRunAppReturnsShutdownExitCode(t *testing.T) {
+	t.Parallel()
+
+	app := fx.New(
+		fx.NopLogger,
+		fx.Invoke(func(lifecycle fx.Lifecycle, shutdowner fx.Shutdowner) {
+			lifecycle.Append(fx.Hook{
+				OnStart: func(context.Context) error {
+					return shutdowner.Shutdown(fx.ExitCode(3))
+				},
+			})
+		}),
+	)
+
+	exitCode := runApp(app, io.Discard)
+	if exitCode != 3 {
+		t.Errorf("runApp() = %d, want 3", exitCode)
+	}
+}

internal/app/app_test.go

@@ -0,0 +1,177 @@
+package app_test
+
+import (
+	"bytes"
+	"errors"
+	"fmt"
+	"net"
+	"net/http"
+	"os"
+	"os/exec"
+	"strconv"
+	"syscall"
+	"testing"
+	"time"
+
+	"sneak.berlin/go/pixa/internal/app"
+)
+
+// These tests run pixad in a child process: the test binary itself,
+// started again with runPixadInChildEnvVar set, which makes TestMain run
+// pixad instead of the tests.
+const runPixadInChildEnvVar = "TEST_RUN_PIXAD_IN_CHILD"
+
+const validTestSigningKey = "test-signing-key-for-app-tests-0123456789"
+
+func TestMain(m *testing.M) {
+	if os.Getenv(runPixadInChildEnvVar) == "1" {
+		os.Args = []string{"pixad"}
+
+		app.Run("test")
+		os.Exit(0)
+	}
+
+	os.Exit(m.Run())
+}
+
+// pixadCommand returns a command that runs pixad with only the given
+// environment, in an empty directory with an empty HOME, so that no
+// config file is found.
+func pixadCommand(t *testing.T, env ...string) (*exec.Cmd, *bytes.Buffer) {
+	t.Helper()
+
+	testBinary := os.Args[0]
+	cmd := exec.CommandContext(t.Context(), testBinary) //nolint:gosec // not tainted
+	cmd.Dir = t.TempDir()
+	// A test binary built with -cover warns on stderr at exit when
+	// GOCOVERDIR is not set.
+	cmd.Env = append([]string{
+		runPixadInChildEnvVar + "=1",
+		"HOME=" + t.TempDir(),
+		"GOCOVERDIR=" + t.TempDir(),
+	}, env...)
+
+	var stderr bytes.Buffer
+
+	cmd.Stderr = &stderr
+
+	return cmd, &stderr
+}
+
+// TestRunPrintsStartupErrorOnce checks that an invalid setting is
+// printed once, as the line that names it, and nothing else goes to
+// stderr.
+func TestRunPrintsStartupErrorOnce(t *testing.T) {
+	t.Parallel()
+
+	cmd, stderr := pixadCommand(t, "PIXA_SIGNING_KEY=short")
+
+	err := cmd.Run()
+
+	var exitErr *exec.ExitError
+	if !errors.As(err, &exitErr) || exitErr.ExitCode() != 1 {
+		t.Fatalf("pixad: got %v, want exit status 1; stderr:\n%s", err, stderr)
+	}
+
+	want := `config key "signing_key" (environment variable PIXA_SIGNING_KEY): ` +
+		"value too short: must be at least 32 characters, got 5\n"
+	if stderr.String() != want {
+		t.Errorf("stderr:\n%s\nwant:\n%s", stderr, want)
+	}
+}
+
+// TestRunWritesNothingToStderrOnStartAndStop starts pixad, waits until
+// it answers its health check, stops it with SIGTERM, and checks that it
+// wrote nothing to stderr.
+func TestRunWritesNothingToStderrOnStartAndStop(t *testing.T) {
+	t.Parallel()
+
+	port := freePort(t)
+	cmd, stderr := pixadCommand(t,
+		"PORT="+strconv.Itoa(port),
+		"PIXA_STATE_DIR="+t.TempDir(),
+		"PIXA_SIGNING_KEY="+validTestSigningKey,
+	)
+
+	err := cmd.Start()
+	if err != nil {
+		t.Fatalf("starting pixad: %v", err)
+	}
+
+	waitForHealthCheck(t, cmd, port, stderr)
+
+	err = cmd.Process.Signal(syscall.SIGTERM)
+	if err != nil {
+		t.Fatalf("signalling pixad: %v", err)
+	}
+
+	err = cmd.Wait()
+	if err != nil {
+		t.Fatalf("pixad: got %v, want exit status 0; stderr:\n%s", err, stderr)
+	}
+
+	if stderr.Len() != 0 {
+		t.Errorf("stderr is not empty:\n%s", stderr)
+	}
+}
+
+// freePort returns a TCP port on the loopback address that nothing
+// listens on.
+func freePort(t *testing.T) int {
+	t.Helper()
+
+	var listenConfig net.ListenConfig
+
+	listener, err := listenConfig.Listen(t.Context(), "tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatalf("finding a free port: %v", err)
+	}
+
+	addr, ok := listener.Addr().(*net.TCPAddr)
+	if !ok {
+		t.Fatalf("listener address %v is not a TCP address", listener.Addr())
+	}
+
+	err = listener.Close()
+	if err != nil {
+		t.Fatalf("closing listener: %v", err)
+	}
+
+	return addr.Port
+}
+
+// waitForHealthCheck waits up to 30 seconds for pixad, started as cmd, to
+// answer its health check on port. If it does not, it stops pixad and
+// fails the test with what pixad wrote to stderr.
+func waitForHealthCheck(t *testing.T, cmd *exec.Cmd, port int, stderr *bytes.Buffer) {
+	t.Helper()
+
+	url := fmt.Sprintf("http://127.0.0.1:%d/.well-known/healthcheck.json", port)
+	deadline := time.Now().Add(30 * time.Second)
+
+	for time.Now().Before(deadline) {
+		req, err := http.NewRequestWithContext(t.Context(), http.MethodGet, url, nil)
+		if err != nil {
+			t.Fatalf("health check request: %v", err)
+		}
+
+		resp, err := http.DefaultClient.Do(req)
+		if err == nil {
+			_ = resp.Body.Close()
+
+			if resp.StatusCode == http.StatusOK {
+				return
+			}
+		}
+
+		time.Sleep(100 * time.Millisecond)
+	}
+
+	// Stop pixad first: stderr is complete, and safe to read, only once
+	// cmd.Wait has returned.
+	_ = cmd.Process.Kill()
+	_ = cmd.Wait()
+
+	t.Fatalf("pixad did not answer its health check on port %d; stderr:\n%s",
+		port, stderr)
+}

internal/handlers/auth_csrf_internal_test.go

@@ -55,7 +55,7 @@ func newCSRFTestRouter(t *testing.T) (*Handlers, http.Handler) {
 		config:      cfg,
 		sessMgr:     session.NewManager(keys.SessionHashKey, keys.SessionBlockKey),
 		encGen:      encurl.NewGenerator(keys.EncryptedURLKey),
-		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug),
+		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug, slog.New(slog.DiscardHandler)),
 	}
 
 	r := chi.NewRouter()

internal/handlers/bodylimit_internal_test.go

@@ -43,7 +43,7 @@ func newBodyLimitTestRouter(
 		config:      cfg,
 		sessMgr:     session.NewManager(keys.SessionHashKey, keys.SessionBlockKey),
 		encGen:      encurl.NewGenerator(keys.EncryptedURLKey),
-		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug),
+		csrfProtect: newCSRFProtect(keys.CSRFKey, cfg.Debug, slog.New(slog.DiscardHandler)),
 	}
 
 	r := chi.NewRouter()

internal/handlers/csrf.go

@@ -1,18 +1,43 @@
 package handlers
 
 import (
+	"bytes"
+	"errors"
 	"html/template"
+	"log/slog"
 	"net/http"
+	"net/url"
 
+	"github.com/go-chi/chi/v5/middleware"
 	"github.com/gorilla/csrf"
 
 	"sneak.berlin/go/pixa/internal/seal"
+	"sneak.berlin/go/pixa/internal/templates"
+)
+
+// The causes the form-refused page names, each with what to do about it.
+const (
+	causePlainHTTP = "This page was opened over plain HTTP while debug is " +
+		"off. Open it over HTTPS, or turn debug on to use plain HTTP on " +
+		"your own machine."
+	causeHTTPSWithDebug = "This page was opened over HTTPS while debug is " +
+		"on. Turn debug off, or open the page over plain HTTP."
+	causeOtherHost = "The form was sent from another host than the one in " +
+		"the request's Host header. A reverse proxy in front of pixa must " +
+		"pass the Host header on unchanged."
+	causeNoReferer = "The browser sent neither an Origin nor a Referer " +
+		"header, and over HTTPS pixa needs one to check where the form " +
+		"came from. Let the browser send the Referer header to this site."
+	causeStaleToken = "The form token is missing or out of date. Reload " +
+		"the page and submit the form again."
 )
 
 // newCSRFProtect builds the CSRF-protection middleware for the
 // state-mutating HTML form routes. The token lives in its own cookie,
 // independent of the session cookie, so it also protects the login POST
-// where no session exists yet (login CSRF). key signs that cookie.
+// where no session exists yet (login CSRF). key signs that cookie. A
+// refused form is answered by the handler that handleFormRefused returns.
+// log gets a warning with the library's reason, such as "origin invalid".
 //
 // When plaintext is true (local HTTP development), requests are marked
 // plaintext so the library neither demands an https Referer nor sets a
@@ -20,13 +45,14 @@ import (
 // service runs behind a TLS-terminating proxy, so plaintext is false and
 // the library enforces its https Referer origin check.
 func newCSRFProtect(
-	key [seal.KeySize]byte, plaintext bool,
+	key [seal.KeySize]byte, plaintext bool, log *slog.Logger,
 ) func(http.Handler) http.Handler {
 	protect := csrf.Protect(
 		key[:],
 		csrf.Path("/"),
 		csrf.Secure(!plaintext),
 		csrf.SameSite(csrf.SameSiteStrictMode),
+		csrf.ErrorHandler(handleFormRefused(plaintext, log)),
 	)
 
 	if !plaintext {
@@ -42,6 +68,84 @@ func newCSRFProtect(
 	}
 }
 
+// handleFormRefused returns the handler the CSRF middleware calls when it
+// refuses a request. It logs the library's reason with the request ID and
+// answers 403 with a page naming the cause and what to do. A reason that is
+// not a refusal, such as a failure to make a token, answers 500.
+func handleFormRefused(plaintext bool, log *slog.Logger) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		reason := csrf.FailureReason(r)
+		requestID := middleware.GetReqID(r.Context())
+
+		cause := formRefusedCause(r, reason, plaintext)
+		if cause == "" {
+			log.Error("CSRF middleware failed",
+				"request_id", requestID, "error", reason)
+			http.Error(w, "Internal server error",
+				http.StatusInternalServerError)
+
+			return
+		}
+
+		log.Warn("form refused", "request_id", requestID, "reason", reason)
+
+		var page bytes.Buffer
+
+		err := templates.Render(&page, "form_refused.html",
+			struct{ Cause string }{Cause: cause})
+		if err != nil {
+			log.Error("failed to render form refused template", "error", err)
+			http.Error(w, "Internal server error",
+				http.StatusInternalServerError)
+
+			return
+		}
+
+		w.Header().Set("Content-Type", "text/html; charset=utf-8")
+		w.WriteHeader(http.StatusForbidden)
+
+		_, err = page.WriteTo(w)
+		if err != nil {
+			log.Error("failed to write form refused page", "error", err)
+		}
+	})
+}
+
+// formRefusedCause returns the cause the form-refused page names for the
+// CSRF middleware's reason, or "" when the reason is not a refusal.
+func formRefusedCause(r *http.Request, reason error, plaintext bool) string {
+	switch {
+	case errors.Is(reason, csrf.ErrNoToken), errors.Is(reason, csrf.ErrBadToken):
+		return causeStaleToken
+	case errors.Is(reason, csrf.ErrNoReferer):
+		return causeNoReferer
+	case errors.Is(reason, csrf.ErrBadOrigin):
+		return pageAddressCause(r.Header.Get("Origin"), r.Host, plaintext)
+	case errors.Is(reason, csrf.ErrBadReferer):
+		return pageAddressCause(r.Referer(), r.Host, plaintext)
+	default:
+		return ""
+	}
+}
+
+// pageAddressCause returns the cause for a form whose page address, the
+// Origin or Referer header, the CSRF middleware refused. The middleware
+// expects the request's own host, with https when plaintext is false and
+// http when it is true. So on the request's own host, only the scheme was
+// wrong.
+func pageAddressCause(pageAddress, host string, plaintext bool) string {
+	page, err := url.Parse(pageAddress)
+	if err != nil || page.Host != host {
+		return causeOtherHost
+	}
+
+	if plaintext {
+		return causeHTTPSWithDebug
+	}
+
+	return causePlainHTTP
+}
+
 // CSRF returns the CSRF-protection middleware for the login and generator
 // form routes.
 func (s *Handlers) CSRF() func(http.Handler) http.Handler {

internal/handlers/csrf_refused_internal_test.go

@@ -0,0 +1,205 @@
+package handlers
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"html/template"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"net/url"
+	"strings"
+	"testing"
+
+	"github.com/go-chi/chi/v5/middleware"
+	"github.com/gorilla/csrf"
+
+	"sneak.berlin/go/pixa/internal/seal"
+)
+
+// refusedFormRequestID is the request ID of the requests postRefusedForm
+// sends, which the warning for a refused form must carry.
+const refusedFormRequestID = "test-request-id"
+
+// TestFormRefusedNamesCause verifies that a form the CSRF middleware refuses
+// answers 403 with a page naming the cause, and logs a warning with the
+// request ID and the middleware's reason.
+func TestFormRefusedNamesCause(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name       string
+		debug      bool
+		origin     string
+		referer    string
+		wantCause  string
+		wantReason error
+	}{
+		{
+			name:       "plain HTTP origin with debug off",
+			origin:     "http://example.com",
+			wantCause:  causePlainHTTP,
+			wantReason: csrf.ErrBadOrigin,
+		},
+		{
+			name:       "plain HTTP referer with debug off",
+			referer:    "http://example.com/",
+			wantCause:  causePlainHTTP,
+			wantReason: csrf.ErrBadReferer,
+		},
+		{
+			name:       "origin on another host",
+			origin:     "https://proxy.example.net",
+			wantCause:  causeOtherHost,
+			wantReason: csrf.ErrBadOrigin,
+		},
+		{
+			name:       "referer on another host",
+			referer:    "https://proxy.example.net/",
+			wantCause:  causeOtherHost,
+			wantReason: csrf.ErrBadReferer,
+		},
+		{
+			name:       "HTTPS origin with debug on",
+			debug:      true,
+			origin:     "https://example.com",
+			wantCause:  causeHTTPSWithDebug,
+			wantReason: csrf.ErrBadOrigin,
+		},
+		{
+			name:       "no origin or referer with debug off",
+			wantCause:  causeNoReferer,
+			wantReason: csrf.ErrNoReferer,
+		},
+		{
+			name:       "missing token",
+			debug:      true,
+			origin:     "http://example.com",
+			wantCause:  causeStaleToken,
+			wantReason: csrf.ErrNoToken,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			rec, logLine := postRefusedForm(t, tt.debug, tt.origin, tt.referer,
+				nil, "")
+			checkFormRefused(t, rec, logLine, tt.wantCause, tt.wantReason)
+		})
+	}
+}
+
+// TestFormRefusedNamesCauseForForeignToken verifies that a form whose token
+// does not match its CSRF cookie answers 403 with a page naming
+// causeStaleToken, and logs a warning with the request ID and the
+// middleware's reason.
+func TestFormRefusedNamesCauseForForeignToken(t *testing.T) {
+	t.Parallel()
+
+	// The router and postRefusedForm derive their CSRF key from
+	// testSigningKey, so cookiesA is valid there and only tokenB is wrong.
+	_, router := newCSRFTestRouter(t)
+	cookiesA, _ := csrfCredentials(t, router, nil)
+	_, tokenB := csrfCredentials(t, router, nil)
+
+	rec, logLine := postRefusedForm(t, true, "http://example.com", "",
+		cookiesA, tokenB)
+	checkFormRefused(t, rec, logLine, causeStaleToken, csrf.ErrBadToken)
+}
+
+// postRefusedForm sends a POST with the given cookies to the CSRF
+// middleware built for debug. It adds the form token and the Origin and
+// Referer headers when they are not empty. It returns the response and the
+// one JSON log line the middleware wrote.
+func postRefusedForm(
+	t *testing.T, debug bool, origin, referer string,
+	cookies []*http.Cookie, token string,
+) (*httptest.ResponseRecorder, map[string]any) {
+	t.Helper()
+
+	keys, err := seal.DeriveKeys(testSigningKey)
+	if err != nil {
+		t.Fatalf("seal.DeriveKeys() error = %v", err)
+	}
+
+	var logs bytes.Buffer
+
+	log := slog.New(slog.NewJSONHandler(&logs, nil))
+	reached := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {
+		t.Error("the refused form reached the handler behind the middleware")
+	})
+	srv := newCSRFProtect(keys.CSRFKey, debug, log)(reached)
+
+	form := url.Values{loginKeyField: {"x"}}
+	if token != "" {
+		form.Set(csrfTokenField, token)
+	}
+
+	ctx := context.WithValue(context.Background(),
+		middleware.RequestIDKey, refusedFormRequestID)
+	req := httptest.NewRequestWithContext(ctx, http.MethodPost,
+		"http://example.com/", strings.NewReader(form.Encode()))
+	req.Header.Set("Content-Type", "application/x-www-form-urlencoded")
+
+	for _, c := range cookies {
+		req.AddCookie(c)
+	}
+
+	if origin != "" {
+		req.Header.Set("Origin", origin)
+	}
+
+	if referer != "" {
+		req.Header.Set("Referer", referer)
+	}
+
+	rec := httptest.NewRecorder()
+	srv.ServeHTTP(rec, req)
+
+	var logLine map[string]any
+
+	err = json.Unmarshal(logs.Bytes(), &logLine)
+	if err != nil {
+		t.Fatalf("decoding log line %q: %v", logs.String(), err)
+	}
+
+	return rec, logLine
+}
+
+// checkFormRefused checks that rec is a 403 page naming wantCause and that
+// logLine is a warning carrying the request ID and wantReason.
+func checkFormRefused(
+	t *testing.T, rec *httptest.ResponseRecorder, logLine map[string]any,
+	wantCause string, wantReason error,
+) {
+	t.Helper()
+
+	if rec.Code != http.StatusForbidden {
+		t.Errorf("status = %d, want %d", rec.Code, http.StatusForbidden)
+	}
+
+	body := rec.Body.String()
+	t.Logf("body: %s", body)
+
+	if !strings.Contains(body, template.HTMLEscapeString(wantCause)) {
+		t.Errorf("page does not name the cause %q", wantCause)
+	}
+
+	t.Logf("log line: %v", logLine)
+
+	if logLine["level"] != "WARN" || logLine["msg"] != "form refused" {
+		t.Errorf("log line = %v, want a WARN \"form refused\"", logLine)
+	}
+
+	if logLine["request_id"] != refusedFormRequestID {
+		t.Errorf("logged request_id = %v, want %q",
+			logLine["request_id"], refusedFormRequestID)
+	}
+
+	if logLine["reason"] != wantReason.Error() {
+		t.Errorf("logged reason = %v, want %q", logLine["reason"], wantReason)
+	}
+}

internal/handlers/handlers.go

@@ -56,14 +56,16 @@ type Handlers struct {
 
 // New creates a new Handlers instance.
 func New(_ fx.Lifecycle, params Params) *Handlers {
+	log := params.Logger.Get()
+
 	return &Handlers{
-		log:              params.Logger.Get(),
+		log:              log,
 		hc:               params.Healthcheck,
 		config:           params.Config,
 		imgSvc:           params.ImageService,
 		sessMgr:          params.SessionManager,
 		encGen:           params.EncryptedURLGenerator,
-		csrfProtect:      newCSRFProtect(params.Keys.CSRFKey, params.Config.Debug),
+		csrfProtect:      newCSRFProtect(params.Keys.CSRFKey, params.Config.Debug, log),
 		signer:           signature.New(params.Config.SigningKey),
 		allowlist:        allowlist.New(params.Config.AllowlistHosts),
 		refererBlocklist: allowlist.New(params.Config.RefererBlocklist),

internal/handlers/image.go

@@ -254,7 +254,9 @@ func (s *Handlers) respondImageError(
 	switch {
 	case errors.Is(err, httpfetcher.ErrSSRFBlocked):
 		status, message = http.StatusForbidden, "forbidden"
-	case errors.Is(err, httpfetcher.ErrUpstreamError):
+	case errors.Is(err, httpfetcher.ErrUpstreamError),
+		errors.Is(err, httpfetcher.ErrInvalidHost),
+		errors.Is(err, httpfetcher.ErrUpstreamRequestFailed):
 		status, message = http.StatusBadGateway, "upstream error"
 	case errors.Is(err, httpfetcher.ErrUpstreamTimeout):
 		status, message = http.StatusGatewayTimeout, "upstream timeout"

internal/handlers/image_cache_control_internal_test.go

@@ -185,13 +185,13 @@ func TestHandleImageEnc_MaxAge(t *testing.T) {
 
 	tests := []struct {
 		name        string
-		expires     time.Time
+		ttl         time.Duration
 		wantAtLeast int
 		wantAtMost  int
 	}{
-		{"60 second TTL", time.Now().Add(time.Minute), 50, 60},
-		{"two-year TTL", time.Now().Add(2 * 365 * 24 * time.Hour), 31536000, 31536000},
-		{"no TTL", time.Time{}, 31536000, 31536000},
+		{"60 second TTL", time.Minute, 50, 60},
+		{"two-year TTL", 2 * 365 * 24 * time.Hour, 31536000, 31536000},
+		{"no TTL", 0, 31536000, 31536000},
 	}
 
 	for _, tt := range tests {
@@ -200,6 +200,14 @@ func TestHandleImageEnc_MaxAge(t *testing.T) {
 
 			h, srv := newSignedHostServer(t, slog.New(slog.DiscardHandler))
 
+			// The expiry is set here, not in the table: a parallel subtest
+			// can wait behind other tests for more than the 10 seconds the
+			// 60 second case allows.
+			var expires time.Time
+			if tt.ttl != 0 {
+				expires = time.Now().Add(tt.ttl)
+			}
+
 			token, err := h.encGen.Generate(&imagerequest.Request{
 				Source: imagerequest.Source{
 					Host: signedHost,
@@ -209,7 +217,7 @@ func TestHandleImageEnc_MaxAge(t *testing.T) {
 					Size:   imagerequest.Size{Width: 50, Height: 50},
 					Format: imagerequest.FormatJPEG,
 				},
-			}, tt.expires)
+			}, expires)
 			if err != nil {
 				t.Fatalf("Generate() error = %v", err)
 			}

internal/handlers/image_errors_internal_test.go

@@ -12,6 +12,7 @@ import (
 	"net/http/httptest"
 	"slices"
 	"strings"
+	"syscall"
 	"testing"
 	"testing/fstest"
 	"time"
@@ -461,6 +462,13 @@ func TestImageRoutes_SameErrorAnswers(t *testing.T) {
 		{"upstream error status",
 			fmt.Errorf("%w: status 404", httpfetcher.ErrUpstreamError),
 			http.StatusBadGateway, slog.LevelWarn},
+		{"upstream host with no address",
+			fmt.Errorf("%w: cdn.example.com", httpfetcher.ErrInvalidHost),
+			http.StatusBadGateway, slog.LevelWarn},
+		{"connection refused",
+			fmt.Errorf("%w: %w", httpfetcher.ErrUpstreamRequestFailed,
+				syscall.ECONNREFUSED),
+			http.StatusBadGateway, slog.LevelWarn},
 		{"no response headers within the fetch timeout",
 			httpfetcher.ErrUpstreamTimeout, http.StatusGatewayTimeout,
 			slog.LevelWarn},

internal/httpfetcher/httpfetcher.go

@@ -69,7 +69,11 @@ var (
 	ErrInvalidContentType = errors.New("invalid or unsupported content type")
 	ErrUpstreamError      = errors.New("upstream server error")
 	ErrUpstreamTimeout    = errors.New("upstream request timeout")
-	ErrTooManyConnections = errors.New("too many concurrent upstream connections")
+	// ErrUpstreamRequestFailed is a fetch that failed before the upstream
+	// answered, other than by timeout or cancellation: a failed connection
+	// or TLS handshake, or a redirect the fetcher refuses.
+	ErrUpstreamRequestFailed = errors.New("upstream request failed")
+	ErrTooManyConnections    = errors.New("too many concurrent upstream connections")
 )
 
 // Internal fetcher errors.
@@ -283,11 +287,7 @@ func (f *HTTPFetcher) Fetch(
 	fetchDuration := time.Since(startTime)
 
 	if err != nil {
-		if errors.Is(err, context.DeadlineExceeded) {
-			return nil, ErrUpstreamTimeout
-		}
-
-		return nil, fmt.Errorf("upstream request failed: %w", err)
+		return nil, upstreamRequestError(err)
 	}
 
 	// The deferred release gives the connection back, as no body follows
@@ -316,6 +316,33 @@ func (f *HTTPFetcher) Fetch(
 	return result, nil
 }
 
+// upstreamRequestError returns the error Fetch reports when its upstream
+// request fails with err:
+//   - err wrapped in ErrUpstreamTimeout for a timeout, so the log names what
+//     timed out.
+//   - err, still matching context.Canceled, when the caller cancelled the
+//     fetch.
+//   - err wrapped in ErrUpstreamRequestFailed otherwise.
+func upstreamRequestError(err error) error {
+	var netErr net.Error
+
+	switch {
+	case errors.Is(err, context.DeadlineExceeded),
+		errors.Is(err, ErrUpstreamTimeout),
+		errors.As(err, &netErr) && netErr.Timeout():
+		// A timeout other than the fetch timeout, such as the TLS
+		// handshake timeout, does not match context.DeadlineExceeded. An
+		// address lookup or a connection that timed out is
+		// ErrUpstreamTimeout already, so its log line names that error twice.
+		return fmt.Errorf("%w: %w", ErrUpstreamTimeout, err)
+	case errors.Is(err, context.Canceled):
+		// The caller cancelled the fetch; the upstream did not fail
+		return fmt.Errorf("upstream request cancelled: %w", err)
+	default:
+		return fmt.Errorf("%w: %w", ErrUpstreamRequestFailed, err)
+	}
+}
+
 // requestHeaders returns the headers of a fetch: User-Agent, Accept, the
 // ID of the request the fetch serves, so the fetch can be found in the
 // upstream host's logs, and a non-empty ifNoneMatch or ifModifiedSince.
@@ -505,7 +532,7 @@ func validateURL(ctx context.Context, fetchURL *neturl.URL, allowHTTP bool) erro
 	// Resolve the host to check IP addresses
 	addrs, err := net.DefaultResolver.LookupIPAddr(ctx, host)
 	if err != nil {
-		return fmt.Errorf("%w: %s", ErrInvalidHost, host)
+		return addressLookupError(host, err)
 	}
 
 	private := slices.ContainsFunc(addrs, func(addr net.IPAddr) bool {
@@ -518,6 +545,23 @@ func validateURL(ctx context.Context, fetchURL *neturl.URL, allowHTTP bool) erro
 	return nil
 }
 
+// addressLookupError returns the error for a failed address lookup of host:
+//   - ErrUpstreamTimeout when the lookup timed out.
+//   - err, still matching context.Canceled, when the lookup was cancelled.
+//   - ErrInvalidHost otherwise.
+func addressLookupError(host string, err error) error {
+	var netErr net.Error
+	if errors.As(err, &netErr) && netErr.Timeout() {
+		return fmt.Errorf("%w: address lookup of %s", ErrUpstreamTimeout, host)
+	}
+
+	if errors.Is(err, context.Canceled) {
+		return fmt.Errorf("address lookup cancelled: %w", err)
+	}
+
+	return fmt.Errorf("%w: %s", ErrInvalidHost, host)
+}
+
 // isLocalhost checks if the host is localhost.
 func isLocalhost(host string) bool {
 	host = strings.ToLower(host)
@@ -646,7 +690,7 @@ func dialSSRFSafe(
 	// Resolve the address
 	ips, err := net.DefaultResolver.LookupIP(ctx, "ip", host)
 	if err != nil {
-		return nil, fmt.Errorf("%w: %s", ErrInvalidHost, host)
+		return nil, addressLookupError(host, err)
 	}
 
 	// Check all resolved IPs
@@ -657,7 +701,10 @@ func dialSSRFSafe(
 	}
 
 	// Connect using the first valid IP
-	var dialer net.Dialer
+	var (
+		dialer      net.Dialer
+		lastDialErr error
+	)
 
 	for _, ip := range ips {
 		addr := net.JoinHostPort(ip.String(), port)
@@ -666,9 +713,18 @@ func dialSSRFSafe(
 		if err == nil {
 			return conn, nil
 		}
+
+		lastDialErr = err
 	}
 
-	return nil, fmt.Errorf("%w to %s", errConnectFailed, host)
+	// Only the last address tried decides whether the connection timed out
+	var netErr net.Error
+	if errors.As(lastDialErr, &netErr) && netErr.Timeout() {
+		return nil, fmt.Errorf("%w: connect to %s: %w",
+			ErrUpstreamTimeout, host, lastDialErr)
+	}
+
+	return nil, fmt.Errorf("%w to %s: %w", errConnectFailed, host, lastDialErr)
 }
 
 // limitedReader wraps a reader and refuses a body longer than remaining

internal/httpfetcher/request_failed_internal_test.go

@@ -0,0 +1,213 @@
+package httpfetcher
+
+import (
+	"context"
+	"errors"
+	"net"
+	"os"
+	"syscall"
+	"testing"
+	"time"
+)
+
+// TestFetchFailedBeforeAnswer checks the error of a fetch whose connection
+// fails:
+//   - refused: ErrUpstreamRequestFailed.
+//   - timed out: ErrUpstreamTimeout, still matching the dial's error, even for
+//     a timeout error that does not match context.DeadlineExceeded, such as
+//     the TLS handshake timeout.
+//   - cancelled by its caller: context.Canceled, not ErrUpstreamRequestFailed.
+func TestFetchFailedBeforeAnswer(t *testing.T) {
+	t.Parallel()
+
+	tests := []struct {
+		name       string
+		dial       func(cancel context.CancelFunc) error
+		wantErrs   []error
+		wantNotErr error
+	}{
+		{
+			name: "connection refused",
+			dial: func(context.CancelFunc) error {
+				return syscall.ECONNREFUSED
+			},
+			wantErrs:   []error{ErrUpstreamRequestFailed},
+			wantNotErr: context.Canceled,
+		},
+		{
+			name: "timed out while connecting",
+			dial: func(context.CancelFunc) error {
+				return os.ErrDeadlineExceeded
+			},
+			wantErrs:   []error{ErrUpstreamTimeout, os.ErrDeadlineExceeded},
+			wantNotErr: ErrUpstreamRequestFailed,
+		},
+		{
+			name: "cancelled while connecting",
+			dial: func(cancel context.CancelFunc) error {
+				cancel()
+
+				return context.Canceled
+			},
+			wantErrs:   []error{context.Canceled},
+			wantNotErr: ErrUpstreamRequestFailed,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Parallel()
+
+			ctx, cancel := context.WithCancel(testContext(t))
+			defer cancel()
+
+			f := New(&Config{
+				Timeout:               30 * time.Second,
+				MaxResponseSize:       50 << 20,
+				AllowHTTP:             true,
+				MaxConnectionsPerHost: 20,
+				MaxConnections:        64,
+				DialContext: func(context.Context, string, string) (net.Conn, error) {
+					return nil, tt.dial(cancel)
+				},
+			})
+
+			_, err := f.Fetch(ctx, upstreamSource("/image"), "", "")
+			t.Logf("Fetch() error: %v", err)
+
+			for _, wantErr := range tt.wantErrs {
+				if !errors.Is(err, wantErr) {
+					t.Errorf("Fetch() error = %v, want %v", err, wantErr)
+				}
+			}
+
+			if errors.Is(err, tt.wantNotErr) {
+				t.Errorf("Fetch() error = %v, must not be %v", err, tt.wantNotErr)
+			}
+		})
+	}
+}
+
+// TestFetchAddressLookupTimedOut checks that a fetch whose address lookup
+// times out fails with ErrUpstreamTimeout, both for the lookup of the source
+// host and for the lookup while connecting. The error must match neither
+// ErrInvalidHost nor ErrUpstreamRequestFailed, which the image routes answer
+// 502. A context whose deadline has passed makes the lookup time out.
+func TestFetchAddressLookupTimedOut(t *testing.T) {
+	t.Parallel()
+
+	checkTimedOut := func(t *testing.T, err error) {
+		t.Helper()
+		t.Logf("Fetch() error: %v", err)
+
+		if !errors.Is(err, ErrUpstreamTimeout) {
+			t.Errorf("Fetch() error = %v, want ErrUpstreamTimeout", err)
+		}
+
+		if errors.Is(err, ErrInvalidHost) || errors.Is(err, ErrUpstreamRequestFailed) {
+			t.Errorf("Fetch() error = %v, must match neither ErrInvalidHost "+
+				"nor ErrUpstreamRequestFailed", err)
+		}
+	}
+
+	t.Run("lookup of the source host", func(t *testing.T) {
+		t.Parallel()
+
+		ctx, cancel := context.WithTimeout(testContext(t), 0)
+		defer cancel()
+
+		f := New(&Config{
+			Timeout:               30 * time.Second,
+			MaxResponseSize:       50 << 20,
+			MaxConnectionsPerHost: 20,
+			MaxConnections:        64,
+		})
+
+		_, err := f.Fetch(ctx, imageSourceOn("cdn.example.com"), "", "")
+		checkTimedOut(t, err)
+	})
+
+	t.Run("lookup while connecting", func(t *testing.T) {
+		t.Parallel()
+
+		// The source host is an address, which validateURL does not look up;
+		// the dialer looks up a name
+		f := New(&Config{
+			Timeout:               30 * time.Second,
+			MaxResponseSize:       50 << 20,
+			MaxConnectionsPerHost: 20,
+			MaxConnections:        64,
+			DialContext: func(ctx context.Context, network, _ string) (net.Conn, error) {
+				ctx, cancel := context.WithTimeout(ctx, 0)
+				defer cancel()
+
+				return dialSSRFSafe(ctx, network, "img.example.com:443", nil)
+			},
+		})
+
+		_, err := f.Fetch(testContext(t), upstreamSource("/image"), "", "")
+		checkTimedOut(t, err)
+	})
+}
+
+// TestFetchConnectionTimedOut checks that a fetch whose connection in
+// dialSSRFSafe times out fails with ErrUpstreamTimeout, which the image
+// routes answer 504. The error must match neither ErrUpstreamRequestFailed
+// nor ErrInvalidHost, which they answer 502. A context whose deadline has
+// passed makes the connection time out without touching the network.
+func TestFetchConnectionTimedOut(t *testing.T) {
+	t.Parallel()
+
+	f := New(&Config{
+		Timeout:               30 * time.Second,
+		MaxResponseSize:       50 << 20,
+		MaxConnectionsPerHost: 20,
+		MaxConnections:        64,
+		DialContext: func(ctx context.Context, network, addr string) (net.Conn, error) {
+			ctx, cancel := context.WithTimeout(ctx, 0)
+			defer cancel()
+
+			return dialSSRFSafe(ctx, network, addr, nil)
+		},
+	})
+
+	_, err := f.Fetch(testContext(t), upstreamSource("/image"), "", "")
+	t.Logf("Fetch() error: %v", err)
+
+	if !errors.Is(err, ErrUpstreamTimeout) {
+		t.Errorf("Fetch() error = %v, want ErrUpstreamTimeout", err)
+	}
+
+	if errors.Is(err, ErrUpstreamRequestFailed) || errors.Is(err, ErrInvalidHost) {
+		t.Errorf("Fetch() error = %v, must match neither "+
+			"ErrUpstreamRequestFailed nor ErrInvalidHost", err)
+	}
+}
+
+// TestFetchAddressLookupCancelled checks that a fetch whose address lookup
+// its caller cancelled fails with an error matching context.Canceled, not
+// ErrInvalidHost, which the image routes answer 502.
+func TestFetchAddressLookupCancelled(t *testing.T) {
+	t.Parallel()
+
+	ctx, cancel := context.WithCancel(testContext(t))
+	cancel()
+
+	f := New(&Config{
+		Timeout:               30 * time.Second,
+		MaxResponseSize:       50 << 20,
+		MaxConnectionsPerHost: 20,
+		MaxConnections:        64,
+	})
+
+	_, err := f.Fetch(ctx, imageSourceOn("cdn.example.com"), "", "")
+	t.Logf("Fetch() error: %v", err)
+
+	if !errors.Is(err, context.Canceled) {
+		t.Errorf("Fetch() error = %v, want context.Canceled", err)
+	}
+
+	if errors.Is(err, ErrInvalidHost) {
+		t.Errorf("Fetch() error = %v, must not be ErrInvalidHost", err)
+	}
+}

internal/imageproxy/imageproxy.go

@@ -37,11 +37,15 @@ type Proxy struct {
 	// same time share one fetch and one transcode.
 	variantsInProgress singleflight.Group
 
-	// The counts of upstream fetches and transforms, made and registered by
-	// New. They are kept in memory, so adding to one waits for nothing.
-	upstreamFetches    prometheus.Counter
-	upstreamFetchBytes prometheus.Counter
-	transforms         prometheus.Counter
+	// The metrics of upstream fetches and transforms, made and registered by
+	// New. They are kept in memory, so updating one waits for nothing.
+	upstreamFetches        prometheus.Counter
+	upstreamFetchBytes     prometheus.Counter
+	upstreamFetchDurations prometheus.Histogram
+	upstreamFetchErrors    prometheus.Counter
+	transforms             prometheus.Counter
+	transformDurations     prometheus.Histogram
+	transformsInProgress   prometheus.Gauge
 }
 
 // Config holds the proxy's configuration.
@@ -62,9 +66,9 @@ type Config struct {
 // errCacheRequired is returned when the proxy is built without a cache.
 var errCacheRequired = errors.New("cache is required")
 
-// New creates a new image proxy and registers its counters on
+// New creates a new image proxy and registers its metrics on
 // metricsRegistry. pixad passes Prometheus' default registry, the one
-// /metrics serves. It fails when metricsRegistry already holds counters of
+// /metrics serves. It fails when metricsRegistry already holds metrics of
 // the same names.
 func New(
 	cfg *Config, metricsRegistry prometheus.Registerer,
@@ -99,18 +103,39 @@ func New(
 			Name: "pixa_upstream_fetch_bytes_total",
 			Help: "Bytes read from upstream by fetches of source images.",
 		}),
+		upstreamFetchDurations: prometheus.NewHistogram(prometheus.HistogramOpts{
+			Name: "pixa_upstream_fetch_duration_seconds",
+			Help: "Duration of the fetches pixa_upstream_fetches_total counts, " +
+				"until the response's last byte.",
+		}),
+		upstreamFetchErrors: prometheus.NewCounter(prometheus.CounterOpts{
+			Name: "pixa_upstream_fetch_errors_total",
+			Help: "Fetches of a source image from upstream that failed, " +
+				"before or while reading the response.",
+		}),
 		transforms: prometheus.NewCounter(prometheus.CounterOpts{
 			Name: "pixa_transforms_total",
 			Help: "Images the image processor transformed.",
 		}),
+		transformDurations: prometheus.NewHistogram(prometheus.HistogramOpts{
+			Name: "pixa_transform_duration_seconds",
+			Help: "Duration of the transforms pixa_transforms_total counts, " +
+				"waiting for a processing slot included.",
+		}),
+		transformsInProgress: prometheus.NewGauge(prometheus.GaugeOpts{
+			Name: "pixa_transforms_in_progress",
+			Help: "Images being transformed or waiting for a processing slot.",
+		}),
 	}
 
-	for _, counter := range []prometheus.Counter{
-		p.upstreamFetches, p.upstreamFetchBytes, p.transforms,
+	for _, metric := range []prometheus.Collector{
+		p.upstreamFetches, p.upstreamFetchBytes, p.upstreamFetchDurations,
+		p.upstreamFetchErrors, p.transforms, p.transformDurations,
+		p.transformsInProgress,
 	} {
-		err = metricsRegistry.Register(counter)
+		err = metricsRegistry.Register(metric)
 		if err != nil {
-			return nil, fmt.Errorf("failed to register the proxy's counters: %w", err)
+			return nil, fmt.Errorf("failed to register the proxy's metrics: %w", err)
 		}
 	}
 
@@ -341,7 +366,10 @@ func (p *Proxy) loadCachedSource(
 }
 
 // processFromSourceOrFetch makes the variant req asks for, from the cached
-// source when there is one and from a fetched source otherwise.
+// source when there is one and from a fetched source otherwise. It counts a
+// source cache miss when it fetches the source because the source has no row
+// in the cache or its cached file cannot be used, and a source cache hit
+// otherwise.
 //
 // A cached source last checked with upstream CacheTTL or more ago is checked
 // first: upstream is asked to send it only if it changed since. When it
@@ -362,6 +390,8 @@ func (p *Proxy) processFromSourceOrFetch(
 			p.log.Warn("failed to look up cached source, fetching", "error", err)
 		}
 
+		p.cache.IncrementSourceStats(false)
+
 		return p.fetchAndProcess(ctx, req, cacheKey)
 	}
 
@@ -375,16 +405,21 @@ func (p *Proxy) processFromSourceOrFetch(
 		case err != nil:
 			p.recordFailedCheck(ctx, req, err)
 		default:
+			p.cache.IncrementSourceStats(true)
+
 			return p.processFetched(ctx, req, cacheKey, fetched)
 		}
 	}
 
 	variant := p.renewVariant(ctx, cacheKey, cached)
 	if variant != nil {
+		p.cache.IncrementSourceStats(true)
+
 		return variant, nil
 	}
 
 	source, sourceSize, sourceFormat := p.loadCachedSource(ctx, req.Source)
+	p.cache.IncrementSourceStats(source != nil)
 
 	// Fetch from upstream if we don't have source data or it's empty
 	if source == nil {
@@ -581,36 +616,32 @@ type fetchedSource struct {
 // fetchSource fetches req's source from upstream and stores it in the cache.
 // A non-empty ifNoneMatch or ifModifiedSince asks upstream to send the source
 // only if it changed since; errSourceNotModified says it did not. It counts
-// the fetch with the bytes read from upstream, including when reading the
-// response or a later step fails. It fetches nothing while the source URL is
-// in the negative cache. The caller closes the returned response.
+// the fetch with the bytes read from upstream and its duration, including
+// when reading the response or a later step fails, and counts a fetch that
+// fails or whose response cannot be read as an upstream fetch error. It
+// fetches nothing while the source URL is in the negative cache. The caller
+// closes the returned response.
 func (p *Proxy) fetchSource(
 	ctx context.Context,
 	req *imagerequest.Request,
 	ifNoneMatch, ifModifiedSince string,
 ) (*fetchedSource, error) {
-	// Check negative cache - skip fetching for recently-failed URLs
-	negHit, err := p.cache.Failure(ctx, req.Source)
+	err := p.refuseNegativeCached(ctx, req)
 	if err != nil {
-		p.log.Warn("negative cache check failed", "error", err)
-	}
-
-	if negHit {
-		p.log.Debug("negative cache hit",
-			"host", req.Source.Host,
-			"path", req.Source.Path,
-		)
-
-		return nil, fmt.Errorf("%w: %w", httpfetcher.ErrUpstreamError, ErrNegativeCached)
+		return nil, err
 	}
 
 	// Fetch from upstream
 	p.log.Debug("fetching from upstream", "host", req.Source.Host,
 		"path", req.Source.Path, "query", req.Source.Query)
 
+	fetchStart := time.Now()
+
 	fetchResult, err := p.fetcher.Fetch(ctx, req.Source,
 		ifNoneMatch, ifModifiedSince)
 	if err != nil {
+		p.upstreamFetchErrors.Inc()
+
 		// Store negative cache for certain errors
 		if isNegativeCacheable(err) {
 			p.storeNegative(ctx, req)
@@ -634,9 +665,11 @@ func (p *Proxy) fetchSource(
 	fetchBytes := int64(len(sourceData))
 
 	// Counted also when the request context has ended meanwhile
-	p.incrementUpstreamFetch(fetchBytes)
+	p.incrementUpstreamFetch(fetchBytes, time.Since(fetchStart))
 
 	if err != nil {
+		p.upstreamFetchErrors.Inc()
+
 		_ = fetchResult.Content.Close()
 
 		return nil, fmt.Errorf("failed to read upstream response: %w", err)
@@ -677,6 +710,29 @@ func (p *Proxy) fetchSource(
 	}, nil
 }
 
+// refuseNegativeCached returns an error wrapping ErrNegativeCached while
+// req's source URL is in the negative cache, and nil otherwise. A failure to
+// read the negative cache is only logged, and returns nil.
+func (p *Proxy) refuseNegativeCached(
+	ctx context.Context, req *imagerequest.Request,
+) error {
+	negHit, err := p.cache.Failure(ctx, req.Source)
+	if err != nil {
+		p.log.Warn("negative cache check failed", "error", err)
+	}
+
+	if !negHit {
+		return nil
+	}
+
+	p.log.Debug("negative cache hit",
+		"host", req.Source.Host,
+		"path", req.Source.Path,
+	)
+
+	return fmt.Errorf("%w: %w", httpfetcher.ErrUpstreamError, ErrNegativeCached)
+}
+
 // fetchedSourceInfo returns what the cache keeps about a source upstream
 // just sent: fetched and checked now, with the ETag and Last-Modified
 // headers of fetchResult.
@@ -722,15 +778,16 @@ func (p *Proxy) logUpstreamFetch(
 	)
 }
 
-// incrementUpstreamFetch counts one upstream fetch that read fetchBytes bytes.
-// A fetch that read no bytes is not counted.
-func (p *Proxy) incrementUpstreamFetch(fetchBytes int64) {
+// incrementUpstreamFetch counts one upstream fetch that read fetchBytes bytes
+// and took duration. A fetch that read no bytes is not counted.
+func (p *Proxy) incrementUpstreamFetch(fetchBytes int64, duration time.Duration) {
 	if fetchBytes <= 0 {
 		return
 	}
 
 	p.upstreamFetches.Inc()
 	p.upstreamFetchBytes.Add(float64(fetchBytes))
+	p.upstreamFetchDurations.Observe(duration.Seconds())
 }
 
 // storeNegative stores a negative cache entry for req's source, whose fetch
@@ -772,8 +829,7 @@ func (p *Proxy) processAndStore(
 
 	// 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 := p.processor.Process(ctx, source, sourceFormat,
-		&req.Transform)
+	processResult, err := p.transform(ctx, source, sourceFormat, &req.Transform)
 	if errors.Is(err, context.DeadlineExceeded) {
 		return nil, fmt.Errorf("%w: %w", ErrProcessingTimedOut, err)
 	}
@@ -786,6 +842,7 @@ func (p *Proxy) processAndStore(
 
 	// Counted also when the request context has ended meanwhile
 	p.transforms.Inc()
+	p.transformDurations.Observe(processDuration.Seconds())
 
 	// Read processed content
 	processedData, err := io.ReadAll(processResult.Content)
@@ -838,6 +895,21 @@ func (p *Proxy) processAndStore(
 	}, nil
 }
 
+// transform has the image processor transform the image read from source
+// as requested says, and counts it in pixa_transforms_in_progress until the
+// processor returns or panics.
+func (p *Proxy) transform(
+	ctx context.Context,
+	source io.Reader,
+	sourceFormat imagerequest.Format,
+	requested *imagerequest.Transform,
+) (*imageprocessor.Result, error) {
+	p.transformsInProgress.Inc()
+	defer p.transformsInProgress.Dec()
+
+	return p.processor.Process(ctx, source, sourceFormat, requested)
+}
+
 // isNegativeCacheable returns true if the error should be cached.
 func isNegativeCacheable(err error) bool {
 	return errors.Is(err, httpfetcher.ErrUpstreamError)

internal/imageproxy/metrics_internal_test.go

@@ -0,0 +1,213 @@
+package imageproxy
+
+import (
+	"os"
+	"testing"
+	"time"
+
+	"sneak.berlin/go/pixa/internal/imageprocessor"
+	"sneak.berlin/go/pixa/internal/imagerequest"
+)
+
+// metricValues holds the source cache, upstream fetch and transform metrics
+// of a proxy and its cache. A histogram is given by its count of
+// observations.
+type metricValues struct {
+	sourceCacheHits   uint64
+	sourceCacheMisses uint64
+	fetchDurations    uint64
+	fetchErrors       uint64
+	transformDuration uint64
+	inProgress        float64
+}
+
+// readMetricValues reads the metrics of svc and its cache that
+// metricValues holds from their metrics registry.
+func readMetricValues(t *testing.T, svc *testProxy) metricValues {
+	t.Helper()
+
+	families, err := svc.registry.Gather()
+	if err != nil {
+		t.Fatalf("failed to gather the metrics: %v", err)
+	}
+
+	var values metricValues
+
+	for _, family := range families {
+		metric := family.GetMetric()[0]
+
+		switch family.GetName() {
+		case "pixa_source_cache_hits_total":
+			values.sourceCacheHits = uint64(metric.GetCounter().GetValue())
+		case "pixa_source_cache_misses_total":
+			values.sourceCacheMisses = uint64(metric.GetCounter().GetValue())
+		case "pixa_upstream_fetch_duration_seconds":
+			values.fetchDurations = metric.GetHistogram().GetSampleCount()
+		case "pixa_upstream_fetch_errors_total":
+			values.fetchErrors = uint64(metric.GetCounter().GetValue())
+		case "pixa_transform_duration_seconds":
+			values.transformDuration = metric.GetHistogram().GetSampleCount()
+		case "pixa_transforms_in_progress":
+			values.inProgress = metric.GetGauge().GetValue()
+		}
+	}
+
+	return values
+}
+
+// TestProxy_Get_CountsSourceCacheFetchesAndTransforms walks Get through a
+// miss that fetches the source, a hit, a miss that uses the cached source
+// and a miss whose source is not found upstream, checking the source cache,
+// upstream fetch and transform metrics after each.
+func TestProxy_Get_CountsSourceCacheFetchesAndTransforms(t *testing.T) {
+	t.Parallel()
+
+	svc, fixtures := setupTestProxy(t)
+
+	// want is source cache hits, source cache misses, fetch durations
+	// observed, fetch errors, transform durations observed, transforms in
+	// progress.
+	steps := []struct {
+		name    string
+		path    string
+		size    int
+		wantErr bool
+		want    metricValues
+	}{
+		{"miss that fetches the source", testPathPhoto, 50, false,
+			metricValues{0, 1, 1, 0, 1, 0}},
+		{"hit", testPathPhoto, 50, false,
+			metricValues{0, 1, 1, 0, 1, 0}},
+		{"miss that uses the cached source", testPathPhoto, 25, false,
+			metricValues{1, 1, 1, 0, 2, 0}},
+		{"miss whose source is not found", "/images/absent.jpg", 50, true,
+			metricValues{1, 2, 1, 1, 2, 0}},
+	}
+
+	for _, step := range steps {
+		resp, err := svc.Get(t.Context(), &imagerequest.Request{
+			Source: imagerequest.Source{
+				Host: fixtures.GoodHost,
+				Path: step.path,
+			},
+			Transform: imagerequest.Transform{
+				Size:    imagerequest.Size{Width: step.size, Height: step.size},
+				Format:  imagerequest.FormatJPEG,
+				Quality: 85,
+				FitMode: imagerequest.FitCover,
+			},
+		})
+		if (err != nil) != step.wantErr {
+			t.Fatalf("%s: Get() error = %v, want error %t", step.name, err, step.wantErr)
+		}
+
+		if err == nil {
+			_ = resp.Content.Close()
+		}
+
+		got := readMetricValues(t, svc)
+		t.Logf("after the %s: metrics = %+v", step.name, got)
+
+		if got != step.want {
+			t.Fatalf("after the %s: metrics = %+v, want %+v", step.name, got, step.want)
+		}
+	}
+}
+
+// TestProxy_Get_CountsMissingSourceFileAsSourceCacheMiss deletes the file of
+// a cached source but keeps its row. A request for a second variant of that
+// source must fetch the source again, and count a source cache miss, not a
+// hit.
+func TestProxy_Get_CountsMissingSourceFileAsSourceCacheMiss(t *testing.T) {
+	t.Parallel()
+
+	svc, fixtures := setupTestProxy(t)
+
+	// A first request caches the photo as a source.
+	resp, err := svc.Get(t.Context(), widthOnlyRequest(fixtures, 50))
+	if err != nil {
+		t.Fatalf("first Get() error = %v", err)
+	}
+
+	_ = resp.Content.Close()
+
+	source := widthOnlyRequest(fixtures, 50).Source
+
+	err = os.Remove(sourceFilePath(svc, source.Key()))
+	if err != nil {
+		t.Fatalf("failed to delete the cached source file: %v", err)
+	}
+
+	before := readMetricValues(t, svc)
+
+	resp, err = svc.Get(t.Context(), widthOnlyRequest(fixtures, 25))
+	if err != nil {
+		t.Fatalf("Get() of a second variant error = %v", err)
+	}
+
+	_ = resp.Content.Close()
+
+	after := readMetricValues(t, svc)
+	t.Logf("before the second variant: metrics = %+v; after: %+v", before, after)
+
+	if after.sourceCacheHits != before.sourceCacheHits ||
+		after.sourceCacheMisses != before.sourceCacheMisses+1 {
+		t.Errorf("source cache hits went from %d to %d and misses from %d to %d, "+
+			"want no new hit and one more miss", before.sourceCacheHits,
+			after.sourceCacheHits, before.sourceCacheMisses, after.sourceCacheMisses)
+	}
+}
+
+// TestProxy_Get_CountsTransformWaitingForSlotAsInProgress holds the only
+// processing slot and starts a request that must transform the photo. While
+// the request waits for the slot, pixa_transforms_in_progress must be 1; once
+// the request returns, 0.
+func TestProxy_Get_CountsTransformWaitingForSlotAsInProgress(t *testing.T) {
+	t.Parallel()
+
+	svc, fixtures := setupTestProxy(t)
+	svc.processor = imageprocessor.New(
+		imageprocessor.Params{MaxInputBytes: 50 << 20, MaxConcurrentProcessing: 1},
+	)
+
+	release := holdProcessingSlot(t, svc.processor)
+
+	result := startGet(t.Context(), svc, widthOnlyRequest(fixtures, 50))
+
+	// The request fetches the photo first, then waits for the slot.
+	deadline := time.Now().Add(5 * time.Second)
+	for readMetricValues(t, svc).inProgress != 1 && time.Now().Before(deadline) {
+		time.Sleep(10 * time.Millisecond)
+	}
+
+	waiting := readMetricValues(t, svc).inProgress
+	t.Logf("while the request waits for the slot: transforms in progress = %v",
+		waiting)
+
+	select {
+	case got := <-result:
+		t.Fatalf("Get() returned while the only processing slot was held, "+
+			"error = %v", got.err)
+	default:
+	}
+
+	if waiting != 1 {
+		t.Fatalf("transforms in progress = %v while the request waits for the "+
+			"slot, want 1", waiting)
+	}
+
+	release()
+
+	got := <-result
+	if got.err != nil {
+		t.Fatalf("Get() error = %v", got.err)
+	}
+
+	returned := readMetricValues(t, svc).inProgress
+	t.Logf("once the request returned: transforms in progress = %v", returned)
+
+	if returned != 0 {
+		t.Errorf("transforms in progress = %v once the request returned, want 0",
+			returned)
+	}
+}

internal/imageproxy/negative_cache_internal_test.go

@@ -82,15 +82,3 @@ func TestProxy_Get_ServesCachedVariantOfNegativeCachedURL(t *testing.T) {
 			err, ErrNegativeCached)
 	}
 }
-
-func TestProxy_Get_ReturnsErrorForNegativeCachedURL(t *testing.T) {
-	t.Parallel()
-
-	// This test verifies that Proxy.Get() checks the negative cache
-	// We can't easily test the full pipeline without vips, but we can
-	// verify the error type
-	err := ErrNegativeCached
-	if !errors.Is(err, ErrNegativeCached) {
-		t.Error("ErrNegativeCached should be identifiable with errors.Is")
-	}
-}

internal/imgcache/cache.go

@@ -111,10 +111,16 @@ type Cache struct {
 	pendingAccessTimesDone    chan struct{}
 	pendingAccessTimesCancel  context.CancelFunc
 
-	// The counts of cache hits and misses, made and registered by
-	// registerCounters (see counters.go)
-	cacheHits   prometheus.Counter
-	cacheMisses prometheus.Counter
+	// The cache's metrics, made and registered by registerMetrics (see
+	// metrics.go)
+	cacheHits         prometheus.Counter
+	cacheMisses       prometheus.Counter
+	sourceCacheHits   prometheus.Counter
+	sourceCacheMisses prometheus.Counter
+	usageBytes        prometheus.Gauge
+	maxBytes          prometheus.Gauge
+	evictions         prometheus.Counter
+	evictedBytes      prometheus.Counter
 
 	// reconciliationPageSize is the most rows one read of a content table
 	// returns in the reconciliation pass. NewCache sets it to
@@ -128,7 +134,7 @@ type Cache struct {
 	reconciliationReadTestHook func(rows int)
 }
 
-// NewCache creates a new cache instance and registers its counters on
+// NewCache creates a new cache instance and registers its metrics on
 // metricsRegistry. pixad passes Prometheus' default registry, the one
 // /metrics serves. It makes no database call.
 func NewCache(
@@ -157,7 +163,7 @@ func NewCache(
 		reconciliationPageSize: defaultReconciliationPageSize,
 	}
 
-	err := c.registerCounters(metricsRegistry)
+	err := c.registerMetrics(metricsRegistry)
 	if err != nil {
 		return nil, err
 	}
@@ -656,17 +662,6 @@ func (c *Cache) CleanExpired(ctx context.Context) error {
 	}
 }
 
-// IncrementStats counts a cache hit or miss. It only adds to the cache's
-// Prometheus counters in memory (see counters.go), so it never waits for the
-// database or fails.
-func (c *Cache) IncrementStats(hit bool) {
-	if hit {
-		c.cacheHits.Inc()
-	} else {
-		c.cacheMisses.Inc()
-	}
-}
-
 // touchVariant hands the access time of a variant served from the cache to
 // the goroutine StartPendingAccessTimeWrites starts, which writes it in its
 // next batch. It never waits: while maxPendingAccessTimes access times of

internal/imgcache/counters.go

@@ -1,31 +0,0 @@
-package imgcache
-
-import (
-	"fmt"
-
-	"github.com/prometheus/client_golang/prometheus"
-)
-
-// registerCounters makes the cache's counters and registers them on
-// metricsRegistry. The counters are kept in memory, so adding to one waits
-// for nothing and makes no database call. It fails when metricsRegistry
-// already holds counters of the same names.
-func (c *Cache) registerCounters(metricsRegistry prometheus.Registerer) error {
-	c.cacheHits = prometheus.NewCounter(prometheus.CounterOpts{
-		Name: "pixa_cache_hits_total",
-		Help: "Image requests served from the cache.",
-	})
-	c.cacheMisses = prometheus.NewCounter(prometheus.CounterOpts{
-		Name: "pixa_cache_misses_total",
-		Help: "Image requests not served from the cache.",
-	})
-
-	for _, counter := range []prometheus.Counter{c.cacheHits, c.cacheMisses} {
-		err := metricsRegistry.Register(counter)
-		if err != nil {
-			return fmt.Errorf("failed to register the cache's counters: %w", err)
-		}
-	}
-
-	return nil
-}

internal/imgcache/eviction.go

@@ -92,8 +92,9 @@ type evictionCandidate struct {
 }
 
 // EvictToLimit evicts least-recently-used cache entries until total
-// tracked usage is at or below the configured MaxBytes limit. It is a
-// no-op when the cache is disabled.
+// tracked usage is at or below the configured MaxBytes limit. It sets the
+// pixa_cache_usage_bytes gauge to each usage it reads. It is a no-op when
+// the cache is disabled.
 func (c *Cache) EvictToLimit(ctx context.Context) error {
 	if c.config.MaxBytes == 0 {
 		return nil
@@ -105,6 +106,8 @@ func (c *Cache) EvictToLimit(ctx context.Context) error {
 			return err
 		}
 
+		c.usageBytes.Set(float64(usage))
+
 		if usage <= c.config.MaxBytes {
 			return nil
 		}
@@ -345,37 +348,95 @@ func (c *Cache) sourceCandidates(ctx context.Context) ([]evictionCandidate, erro
 	return candidates, nil
 }
 
-// evictVariant removes one variant: accounting row first, then the
-// file, so the database never references a deleted file.
+// evictVariant removes one variant (see removeVariant) and counts the
+// eviction with the size its row recorded.
 func (c *Cache) evictVariant(
 	ctx context.Context, cacheKey imagerequest.VariantKey,
 ) error {
-	_, err := c.db.ExecContext(ctx,
-		`DELETE FROM variant_content WHERE cache_key = ?`, string(cacheKey))
-	if err != nil {
-		return fmt.Errorf("failed to delete variant accounting row: %w", err)
-	}
-
-	err = c.variants.Delete(string(cacheKey))
+	sizeBytes, err := c.removeVariant(ctx, cacheKey)
 	if err != nil {
 		return err
 	}
 
+	c.countEviction(sizeBytes)
+
 	return nil
 }
 
-// evictSourceBlob removes one source: its row first, then its file, as
-// evictVariant does for a variant. It holds no lock: a store of the same
-// source in between can leave the source's row with no file, which
-// Source treats as a miss.
-func (c *Cache) evictSourceBlob(ctx context.Context, key imagerequest.SourceKey) error {
-	_, err := c.db.ExecContext(ctx,
-		`DELETE FROM source_content WHERE source_key = ?`, string(key))
+// removeVariant removes one variant: accounting row first, then the
+// file, so the database never references a deleted file. It returns the
+// size the row recorded, or 0 when the variant had no row.
+func (c *Cache) removeVariant(
+	ctx context.Context, cacheKey imagerequest.VariantKey,
+) (int64, error) {
+	sizeBytes, err := c.deleteRowReturningSize(ctx,
+		`DELETE FROM variant_content WHERE cache_key = ? RETURNING size_bytes`,
+		string(cacheKey))
 	if err != nil {
-		return fmt.Errorf("failed to delete source content row: %w", err)
+		return 0, fmt.Errorf("failed to delete variant accounting row: %w", err)
 	}
 
-	return c.srcContent.Delete(string(key))
+	err = c.variants.Delete(string(cacheKey))
+	if err != nil {
+		return 0, err
+	}
+
+	return sizeBytes, nil
+}
+
+// evictSourceBlob removes one source (see removeSourceBlob) and counts the
+// eviction with the size its row recorded.
+func (c *Cache) evictSourceBlob(ctx context.Context, key imagerequest.SourceKey) error {
+	sizeBytes, err := c.removeSourceBlob(ctx, key)
+	if err != nil {
+		return err
+	}
+
+	c.countEviction(sizeBytes)
+
+	return nil
+}
+
+// removeSourceBlob removes one source: its row first, then its file, as
+// removeVariant does for a variant, and returns the size the row recorded,
+// or 0 when the source had no row. It holds no lock: a store of the same
+// source in between can leave the source's row with no file, which Source
+// treats as a miss.
+func (c *Cache) removeSourceBlob(
+	ctx context.Context, key imagerequest.SourceKey,
+) (int64, error) {
+	sizeBytes, err := c.deleteRowReturningSize(ctx,
+		`DELETE FROM source_content WHERE source_key = ? RETURNING size_bytes`,
+		string(key))
+	if err != nil {
+		return 0, fmt.Errorf("failed to delete source content row: %w", err)
+	}
+
+	err = c.srcContent.Delete(string(key))
+	if err != nil {
+		return 0, err
+	}
+
+	return sizeBytes, nil
+}
+
+// deleteRowReturningSize runs deleteQuery, which deletes the row of key and
+// returns its size_bytes, and returns that size, or 0 when there was no row.
+func (c *Cache) deleteRowReturningSize(
+	ctx context.Context, deleteQuery string, key string,
+) (int64, error) {
+	var sizeBytes int64
+
+	err := c.db.QueryRowContext(ctx, deleteQuery, key).Scan(&sizeBytes)
+	if errors.Is(err, sql.ErrNoRows) {
+		return 0, nil
+	}
+
+	if err != nil {
+		return 0, err
+	}
+
+	return sizeBytes, nil
 }
 
 // notifyWritePressure wakes the background evictor after a store, so
@@ -673,7 +734,9 @@ func (c *Cache) reconcileVariantFile(
 	c.log.Warn("removing damaged cached variant file", "path", path,
 		"file_bytes", info.Size(), "recorded_bytes", recordedSize)
 
-	return c.evictVariant(ctx, cacheKey)
+	_, err = c.removeVariant(ctx, cacheKey)
+
+	return err
 }
 
 // adoptVariantFile inserts an accounting row for a variant file that
@@ -835,7 +898,9 @@ func (c *Cache) reconcileSourceFile(
 	c.log.Warn("removing damaged cached source file", "path", path,
 		"file_bytes", info.Size(), "recorded_bytes", recordedSize)
 
-	return c.evictSourceBlob(ctx, key)
+	_, err = c.removeSourceBlob(ctx, key)
+
+	return err
 }
 
 // removeUntrackedSourceFile deletes a source blob file that has no

internal/imgcache/metrics.go

@@ -0,0 +1,88 @@
+package imgcache
+
+import (
+	"fmt"
+
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+// registerMetrics makes the cache's metrics and registers them on
+// metricsRegistry. The metrics are kept in memory, so updating one waits
+// for nothing and makes no database call. It fails when metricsRegistry
+// already holds metrics of the same names.
+func (c *Cache) registerMetrics(metricsRegistry prometheus.Registerer) error {
+	c.cacheHits = prometheus.NewCounter(prometheus.CounterOpts{
+		Name: "pixa_cache_hits_total",
+		Help: "Image requests served from the cache.",
+	})
+	c.cacheMisses = prometheus.NewCounter(prometheus.CounterOpts{
+		Name: "pixa_cache_misses_total",
+		Help: "Image requests not served from the cache.",
+	})
+	c.sourceCacheHits = prometheus.NewCounter(prometheus.CounterOpts{
+		Name: "pixa_source_cache_hits_total",
+		Help: "Variants made or checked whose source was in the cache.",
+	})
+	c.sourceCacheMisses = prometheus.NewCounter(prometheus.CounterOpts{
+		Name: "pixa_source_cache_misses_total",
+		Help: "Variants made or checked whose source was not in the cache.",
+	})
+	c.usageBytes = prometheus.NewGauge(prometheus.GaugeOpts{
+		Name: "pixa_cache_usage_bytes",
+		Help: "Bytes of sources and variants in the cache, as eviction last read them.",
+	})
+	c.maxBytes = prometheus.NewGauge(prometheus.GaugeOpts{
+		Name: "pixa_cache_max_bytes",
+		Help: "The disk cache limit in bytes, cache_max_bytes.",
+	})
+	c.evictions = prometheus.NewCounter(prometheus.CounterOpts{
+		Name: "pixa_cache_evictions_total",
+		Help: "Sources and variants removed by eviction.",
+	})
+	c.evictedBytes = prometheus.NewCounter(prometheus.CounterOpts{
+		Name: "pixa_cache_evicted_bytes_total",
+		Help: "Bytes of the sources and variants removed by eviction.",
+	})
+
+	c.maxBytes.Set(float64(c.config.MaxBytes))
+
+	for _, metric := range []prometheus.Collector{
+		c.cacheHits, c.cacheMisses, c.sourceCacheHits, c.sourceCacheMisses,
+		c.usageBytes, c.maxBytes, c.evictions, c.evictedBytes,
+	} {
+		err := metricsRegistry.Register(metric)
+		if err != nil {
+			return fmt.Errorf("failed to register the cache's metrics: %w", err)
+		}
+	}
+
+	return nil
+}
+
+// IncrementStats counts a cache hit or miss of an image request. It only
+// adds to the cache's counters in memory, so it never waits for the
+// database or fails.
+func (c *Cache) IncrementStats(hit bool) {
+	if hit {
+		c.cacheHits.Inc()
+	} else {
+		c.cacheMisses.Inc()
+	}
+}
+
+// IncrementSourceStats counts whether a variant being made or checked found
+// its source in the cache. Like IncrementStats, it never waits or fails.
+func (c *Cache) IncrementSourceStats(hit bool) {
+	if hit {
+		c.sourceCacheHits.Inc()
+	} else {
+		c.sourceCacheMisses.Inc()
+	}
+}
+
+// countEviction counts one source or variant of sizeBytes bytes removed by
+// eviction.
+func (c *Cache) countEviction(sizeBytes int64) {
+	c.evictions.Inc()
+	c.evictedBytes.Add(float64(sizeBytes))
+}

internal/imgcache/metrics_internal_test.go

@@ -0,0 +1,137 @@
+package imgcache
+
+import (
+	"bytes"
+	"testing"
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"sneak.berlin/go/pixa/internal/imagerequest"
+)
+
+// gatheredValue returns the value of the metric name on registry: a
+// counter's or a gauge's value.
+func gatheredValue(t *testing.T, registry *prometheus.Registry, name string) float64 {
+	t.Helper()
+
+	families, err := registry.Gather()
+	if err != nil {
+		t.Fatalf("failed to gather the metrics: %v", err)
+	}
+
+	for _, family := range families {
+		if family.GetName() != name {
+			continue
+		}
+
+		metric := family.GetMetric()[0]
+		if metric.GetGauge() != nil {
+			return metric.GetGauge().GetValue()
+		}
+
+		return metric.GetCounter().GetValue()
+	}
+
+	t.Fatalf("the metric %s is not on the registry", name)
+
+	return 0
+}
+
+// TestEvictToLimit_CountsEvictionsAndUsage stores four variants of 1000
+// bytes in a cache limited to 3000 bytes. EvictToLimit must count the one
+// eviction and its bytes, and set the usage and limit gauges.
+func TestEvictToLimit_CountsEvictionsAndUsage(t *testing.T) {
+	t.Parallel()
+
+	const limit = 3000
+
+	registry := prometheus.NewRegistry()
+
+	cache, err := NewCache(evictionTestDB(t),
+		Config{StateDir: t.TempDir(), MaxBytes: limit}, registry)
+	if err != nil {
+		t.Fatalf("NewCache() error = %v", err)
+	}
+
+	keys := []imagerequest.VariantKey{
+		testVariantKeyOne, testVariantKeyTwo,
+		testVariantKeyThree, testVariantKeyFour,
+	}
+
+	for i, key := range keys {
+		storeEvictionTestVariant(t, cache, key, bytes.Repeat([]byte{0x01}, 1000))
+		setVariantLastAccessed(t, cache, key,
+			time.Now().Add(-time.Duration(len(keys)-i)*time.Hour))
+	}
+
+	err = cache.EvictToLimit(t.Context())
+	if err != nil {
+		t.Fatalf("EvictToLimit() error = %v", err)
+	}
+
+	want := map[string]float64{
+		"pixa_cache_evictions_total":     1,
+		"pixa_cache_evicted_bytes_total": 1000,
+		"pixa_cache_usage_bytes":         3000,
+		"pixa_cache_max_bytes":           limit,
+	}
+
+	for name, value := range want {
+		got := gatheredValue(t, registry, name)
+		t.Logf("%s = %v", name, got)
+
+		if got != value {
+			t.Errorf("%s = %v, want %v", name, got, value)
+		}
+	}
+}
+
+// TestEvictNotCheckedRecently_CountsEvictions stores a source of 6 bytes and
+// a variant of 7 bytes last checked with upstream 31 days ago.
+// EvictNotCheckedRecently must count both evictions and their 13 bytes.
+func TestEvictNotCheckedRecently_CountsEvictions(t *testing.T) {
+	t.Parallel()
+
+	registry := prometheus.NewRegistry()
+
+	cache, err := NewCache(evictionTestDB(t),
+		Config{StateDir: t.TempDir(), MaxBytes: 1 << 30}, registry)
+	if err != nil {
+		t.Fatalf("NewCache() error = %v", err)
+	}
+
+	old := time.Now().Add(-31 * 24 * time.Hour)
+
+	_, err = cache.PutSource(t.Context(),
+		imagerequest.Source{Host: testHostCDN, Path: "/old.jpg"},
+		bytes.NewReader([]byte("source")),
+		SourceInfo{FetchedAt: old, CheckedAt: old})
+	if err != nil {
+		t.Fatalf("PutSource() error = %v", err)
+	}
+
+	err = cache.PutVariant(t.Context(), testVariantKeyOne,
+		SourceInfo{CheckedAt: old}, bytes.NewReader([]byte("variant")))
+	if err != nil {
+		t.Fatalf("PutVariant() error = %v", err)
+	}
+
+	err = cache.EvictNotCheckedRecently(t.Context())
+	if err != nil {
+		t.Fatalf("EvictNotCheckedRecently() error = %v", err)
+	}
+
+	want := map[string]float64{
+		"pixa_cache_evictions_total":     2,
+		"pixa_cache_evicted_bytes_total": 13,
+	}
+
+	for name, value := range want {
+		got := gatheredValue(t, registry, name)
+		t.Logf("%s = %v", name, got)
+
+		if got != value {
+			t.Errorf("%s = %v, want %v", name, got, value)
+		}
+	}
+}

internal/providers/providers.go

@@ -35,7 +35,7 @@ import (
 
 // Constructors returns the constructors of the parts this package builds,
 // for fx.Provide. The fx graph must also provide the prometheus.Registerer
-// the cache and the image service register their counters on.
+// the cache and the image service register their metrics on.
 func Constructors() []any {
 	return []any{
 		newKeys,

internal/templates/form_refused.html

@@ -0,0 +1,22 @@
+<!DOCTYPE html>
+<html lang="en">
+<head>
+    <meta charset="UTF-8">
+    <meta name="viewport" content="width=device-width, initial-scale=1.0">
+    <title>Pixa - Form Refused</title>
+    <link rel="stylesheet" href="/static/style.css">
+</head>
+<body class="login">
+    <div class="card">
+        <h1>Form Refused</h1>
+
+        <div class="error">
+            {{.Cause}}
+        </div>
+
+        <p>
+            <a href="/">Back to the start page</a>
+        </p>
+    </div>
+</body>
+</html>