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`.
 
@@ -1174,7 +1216,7 @@ Each item below is one setting, named by its config key:
     - `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 cache size limit, `cache_max_bytes`
+    - `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

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

@@ -366,8 +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. It counts
-// whether the source was in the cache.
+// 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
@@ -393,8 +395,6 @@ func (p *Proxy) processFromSourceOrFetch(
 		return p.fetchAndProcess(ctx, req, cacheKey)
 	}
 
-	p.cache.IncrementSourceStats(true)
-
 	if p.cache.Stale(cached.CheckedAt) {
 		fetched, err := p.fetchSource(ctx, req, cached.ETag, cached.LastModified)
 
@@ -405,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 {

internal/imageproxy/metrics_internal_test.go

@@ -1,14 +1,17 @@
 package imageproxy
 
 import (
+	"os"
 	"testing"
+	"time"
 
+	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imagerequest"
 )
 
-// metricValues holds the metrics of a proxy and its cache that
-// TestProxy_Get_CountsSourceCacheFetchesAndTransforms checks. A histogram
-// is given by its count of observations.
+// 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
@@ -110,3 +113,101 @@ func TestProxy_Get_CountsSourceCacheFetchesAndTransforms(t *testing.T) {
 		}
 	}
 }
+
+// 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/metrics.go

@@ -33,7 +33,7 @@ func (c *Cache) registerMetrics(metricsRegistry prometheus.Registerer) error {
 	})
 	c.maxBytes = prometheus.NewGauge(prometheus.GaugeOpts{
 		Name: "pixa_cache_max_bytes",
-		Help: "The cache size limit in bytes, cache_max_bytes.",
+		Help: "The disk cache limit in bytes, cache_max_bytes.",
 	})
 	c.evictions = prometheus.NewCounter(prometheus.CounterOpts{
 		Name: "pixa_cache_evictions_total",

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>