Serve both image routes with one function and one error mapping (closes #316)

HandleImage parses the path and verifies the signature, and HandleImageEnc
decrypts the token. Each then calls serveImage, which chooses the format for
auto, gets the image and serves it: the headers, ETag and 304, HEAD, the copy
and the log line. respondImageError answers the image service's errors on both
routes, and handleImageError is gone. /v1/image/ now answers 504 when the
upstream sends no response headers within upstream_fetch_timeout, as README.md
documented for /v1/e/. /v1/e/ now logs these errors at error level, as
/v1/image/ does. README.md's route tables list 504 for /v1/image/. A new test
sends the same upstream fetch errors through both routes.

Model: opus-5-5

README.md

@@ -248,57 +248,32 @@ path under `/v1/` answers 200, in maintenance mode too.
 - `GET` or `HEAD` `/v1/image/<host>/<path>/<size>.<format>`, or
   `/v1/image/<host>/<path>/<size>` with no format — an image, fetched, resized
   and converted (below). Needs: a signature, unless the host is allowlisted (see
-  Source Hosts). Answers:
+  Source Hosts). Answers: 200; 304 when `If-None-Match` matches the image's
-    - 200 with the image.
+  `ETag`; 400 for a URL or parameter that is not valid, or for the format `auto`
-    - 304 when `If-None-Match` matches the image's `ETag`.
+  an `Accept` header that is not valid; 406 for the format `auto` when `Accept`
-    - 400 for a URL or parameter that is not valid.
+  allows none of the formats it chooses from; 401 for a missing or wrong
-    - 400 when the format is `auto` and the `Accept` header is not valid.
+  signature, a missing `exp` or an `exp` in the past; 403 when the request's
-    - 406 when the format is `auto` and `Accept` allows none of the formats it
+  `Referer` names a host in `referer_blocklist`, checked before the signature,
-      chooses from.
+  the cache and the upstream fetch; 403 when the upstream host, or a host it
-    - 401 for a missing or wrong signature.
+  redirects to, is `localhost`, ends in `.localhost` or `.local`, or has an
-    - 401 for a missing `exp`.
+  address in a blocked network (see `blocked_networks`); 429 over
-    - 401 for an `exp` in the past.
+  `image_requests_per_minute` (below); 415 when the upstream answers with a
-    - 403 when the request's `Referer` names a host in `referer_blocklist`,
+  `Content-Type` that is not one of the source formats (below), with a body
-      checked before the signature, the cache and the upstream fetch.
+  whose first bytes are not those of the format its `Content-Type` names, or
-    - 403 when the upstream host, or a host it redirects to, is `localhost` or
+  with an image whose first bytes libvips reads as another format; 502 when the
-      ends in `.localhost` or `.local`.
+  upstream answered with an error status, and for 5 minutes after that, or after
-    - 403 when the upstream host, or a host it redirects to, has an address in a
+  a body whose first bytes are not those of its `Content-Type`, for an image of
-      blocked network (see `blocked_networks`).
+  the same source URL that pixa can neither serve from its cache nor make from
-    - 429 over `image_requests_per_minute` (below).
+  the source image still in its cache; 503 when pixa is busy or in maintenance
-    - 415 when the upstream answers with a `Content-Type` that is not one of the
+  mode; 504 when the upstream has not sent its response headers within
-      source formats (below).
+  `upstream_fetch_timeout`, but 500 when that time runs out while the image
-    - 415 when the upstream sends a body whose first bytes are not those of the
+  itself is still arriving; 500 for any other failure.
-      format its `Content-Type` names.
-    - 415 when the upstream sends an image whose first bytes libvips reads as
-      another format.
-    - 502 when the upstream answers with an error status.
-    - 502 for 5 minutes after that for the same source URL, when pixa has
-      neither the image nor its source image in its cache.
-    - 502 likewise for 5 minutes after a body whose first bytes are not those of
-      its `Content-Type`.
-    - 503 when pixa is busy.
-    - 503 when pixa is in maintenance mode.
-    - 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.
-    - 500 for any other failure.
 - `GET` or `HEAD` `/v1/e/<token>/<name>` — an image through an encrypted URL
-  (see Encrypted URLs). Needs: nothing but the URL. Answers:
+  (see Encrypted URLs). Needs: nothing but the URL. Answers: 200; 304 when
-    - 200 with the image.
+  `If-None-Match` matches the image's `ETag`; 400 for a token that does not
-    - 304 when `If-None-Match` matches the image's `ETag`.
+  decrypt, or that asks for a size or fit that is not valid; 410 once it has
-    - 400 for a token that does not decrypt.
+  expired; 400 for an `Accept` header that is not valid, and 406, 403, 415, 429,
-    - 400 for a token that asks for a size or fit that is not valid.
+  502, 503, 504 and 500, as for `/v1/image/`.
-    - 410 once the token has expired.
-    - 400 for an `Accept` header that is not valid.
-    - These answers, for the same causes as on `/v1/image/`:
-        - 406
-        - 403
-        - 415
-        - 429
-        - 502
-        - 503
-        - 504
-        - 500
 - `GET /robots.txt` — asks every crawler to stay away (`Disallow: /`). Needs:
   nothing. Answers: 200.
 - `GET /.well-known/healthcheck.json` — JSON with `status` (`ok`), `now`,

TODO.md

@@ -37,26 +37,11 @@ P2: security: per-origin rate limiting
     - `handleImageError`, the encrypted route's own mapping, is gone.
     - `/v1/image/` answers 504 when the upstream has not sent its response
       headers within `upstream_fetch_timeout`, as `/v1/e/` did. It answered 500.
-    - `respondImageError` logs the image service's errors as "failed to get
+    - `/v1/e/` logs the image service's errors at error level, as `/v1/image/`
-      image". Each answer gets the same level on `/v1/image/` and on `/v1/e/`:
+      does. It logged only those it answered 500.
-        - 500: error, as pixa's own failure
-        - 400: warn
-        - 403: warn
-        - 415: warn
-        - 502: warn
-        - 503: warn
-        - 504: warn
-    - Before, `/v1/image/` logged all of these answers at error level. `/v1/e/`
-      logged only its 500, as "image request failed", without the host and the
-      path.
-    - `respondImageError` does not log the 415 for a body refused for its first
-      bytes, on either route. The image service logs it as "source refused", at
-      warn level.
     - The "image served" line carries the host, the path and `fetched_bytes` on
-      both routes. The debug line "encrypted image request" is gone.
+      both routes, also after a failed write. The debug line "encrypted image
-    - A failed write is logged once, as "failed to write response" at error
+      request" is gone.
-      level. It carries the `request_id`, the host, the path, `served_bytes` and
-      the error, and is not also logged as "image served".
 - 2026-10-26 every key derived from the signing key is derived in one place
   (closes #315): `seal.DeriveKeys` returns them as one `seal.Keys`, with their
   salts declared beside it. `internal/providers` calls it once at startup. Each

internal/handlers/image.go

@@ -220,9 +220,7 @@ func (s *Handlers) HandleTooManyRequests() http.HandlerFunc {
 }
 
 // respondImageError answers err, the image service's error for req, on both
-// image routes. It logs a 500 at error level, as pixa's own failure. It logs
+// image routes.
-// every other answer at warn level, since the client, the upstream or a full
-// limit caused it.
 func (s *Handlers) respondImageError(
 	w http.ResponseWriter, req *imagerequest.Request, err error,
 ) {
@@ -238,53 +236,65 @@ func (s *Handlers) respondImageError(
 		return
 	}
 
-	var (
-		status  int
-		message string
-	)
-
-	switch {
-	case errors.Is(err, httpfetcher.ErrSSRFBlocked):
-		status, message = http.StatusForbidden, "forbidden"
-	case errors.Is(err, httpfetcher.ErrUpstreamError):
-		status, message = http.StatusBadGateway, "upstream error"
-	case errors.Is(err, httpfetcher.ErrUpstreamTimeout):
-		status, message = http.StatusGatewayTimeout, "upstream timeout"
-	case errors.Is(err, httpfetcher.ErrTooManyConnections),
-		errors.Is(err, imageprocessor.ErrTooManyImages),
-		errors.Is(err, imgcache.ErrProcessingTimedOut):
-		status = http.StatusServiceUnavailable
-		message = "server busy, try again later"
-	case errors.Is(err, httpfetcher.ErrInvalidContentType),
-		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat):
-		status = http.StatusUnsupportedMediaType
-		message = "unsupported source format"
-	case errors.Is(err, imageprocessor.ErrOutputTooLarge):
-		status = http.StatusBadRequest
-		message = fmt.Sprintf("size too large for the source: the side "+
-			"computed from its proportions is above %d",
-			imageprocessor.MaxOutputDimension)
-	case errors.Is(err, imageprocessor.ErrAVIFOutputTooLarge):
-		status = http.StatusBadRequest
-		message = fmt.Sprintf("size too large for AVIF: the output "+
-			"would be above %d pixels", imageprocessor.MaxAVIFOutputPixels)
-	default:
 	s.log.Error("failed to get image",
 		"host", req.Source.Host,
 		"path", req.Source.Path,
 		"error", err,
 	)
-		s.respondError(w, "internal error", http.StatusInternalServerError)
+
+	// Check for specific error types
+	if errors.Is(err, httpfetcher.ErrSSRFBlocked) {
+		s.respondError(w, "forbidden", http.StatusForbidden)
 
 		return
 	}
 
-	s.log.Warn("failed to get image",
+	if errors.Is(err, httpfetcher.ErrUpstreamError) {
-		"host", req.Source.Host,
+		s.respondError(w, "upstream error", http.StatusBadGateway)
-		"path", req.Source.Path,
+
-		"error", err,
+		return
-	)
+	}
-	s.respondError(w, message, status)
+
+	if errors.Is(err, httpfetcher.ErrUpstreamTimeout) {
+		s.respondError(w, "upstream timeout", http.StatusGatewayTimeout)
+
+		return
+	}
+
+	if errors.Is(err, httpfetcher.ErrTooManyConnections) ||
+		errors.Is(err, imageprocessor.ErrTooManyImages) ||
+		errors.Is(err, imgcache.ErrProcessingTimedOut) {
+		s.respondError(w, "server busy, try again later",
+			http.StatusServiceUnavailable)
+
+		return
+	}
+
+	if errors.Is(err, httpfetcher.ErrInvalidContentType) ||
+		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat) {
+		s.respondError(w, "unsupported source format",
+			http.StatusUnsupportedMediaType)
+
+		return
+	}
+
+	if errors.Is(err, imageprocessor.ErrOutputTooLarge) {
+		s.respondError(w, fmt.Sprintf("size too large for the source: the side "+
+			"computed from its proportions is above %d",
+			imageprocessor.MaxOutputDimension), http.StatusBadRequest)
+
+		return
+	}
+
+	if errors.Is(err, imageprocessor.ErrAVIFOutputTooLarge) {
+		s.respondError(w, fmt.Sprintf("size too large for AVIF: the output "+
+			"would be above %d pixels", imageprocessor.MaxAVIFOutputPixels),
+			http.StatusBadRequest)
+
+		return
+	}
+
+	s.respondError(w, "internal error", http.StatusInternalServerError)
 }
 
 // cacheControl returns the Cache-Control header for an image served through a
@@ -397,14 +407,8 @@ func (s *Handlers) serveImage(
 	servedBytes, err := io.Copy(w, resp.Content)
 	if err != nil {
 		s.log.Error("failed to write response",
-			"request_id", middleware.GetReqID(r.Context()),
-			"host", req.Source.Host,
-			"path", req.Source.Path,
-			"served_bytes", servedBytes,
 			"error", err,
 		)
-
-		return
 	}
 
 	// Log cache status and timing after serving

internal/handlers/image_errors_internal_test.go

@@ -1,7 +1,6 @@
 package handlers
 
 import (
-	"bytes"
 	"context"
 	"encoding/json"
 	"fmt"
@@ -10,14 +9,12 @@ import (
 	"log/slog"
 	"net/http"
 	"net/http/httptest"
-	"slices"
 	"strings"
 	"testing"
 	"testing/fstest"
 	"time"
 
 	"github.com/go-chi/chi/v5"
-	"github.com/go-chi/chi/v5/middleware"
 	"github.com/prometheus/client_golang/prometheus"
 	"sneak.berlin/go/pixa/internal/allowlist"
 	"sneak.berlin/go/pixa/internal/httpfetcher"
@@ -432,20 +429,9 @@ func (f failingFetcher) Fetch(
 	return nil, f.err
 }
 
-// photoURLsByRoute returns, for each image route, the function that makes the
-// URL of the JPEG at photoPath on signedHost on that route.
-func photoURLsByRoute() map[string]func(*testing.T, *Handlers) string {
-	return map[string]func(*testing.T, *Handlers) string{
-		"/v1/image/": signedPhotoURL,
-		"/v1/e/":     encPhotoURL,
-	}
-}
-
 // TestImageRoutes_SameErrorAnswers checks that both image routes answer each
-// upstream fetch error below with the same status. They log it as "failed to
+// upstream fetch error below with the same status. Each request gets routes of
-// get image" at the same level: error for the 500 and warn for the others.
+// its own, so no request finds another's failed fetch in the negative cache.
-// Each request gets routes of its own, so no request finds another's failed
-// fetch in the negative cache.
 func TestImageRoutes_SameErrorAnswers(t *testing.T) {
 	t.Parallel()
 
@@ -453,134 +439,43 @@ func TestImageRoutes_SameErrorAnswers(t *testing.T) {
 		name       string
 		err        error
 		wantStatus int
-		wantLevel  slog.Level
 	}{
 		{"blocked upstream address", httpfetcher.ErrSSRFBlocked,
-			http.StatusForbidden, slog.LevelWarn},
+			http.StatusForbidden},
 		{"upstream error status",
 			fmt.Errorf("%w: status 404", httpfetcher.ErrUpstreamError),
-			http.StatusBadGateway, slog.LevelWarn},
+			http.StatusBadGateway},
 		{"no response headers within the fetch timeout",
-			httpfetcher.ErrUpstreamTimeout, http.StatusGatewayTimeout,
+			httpfetcher.ErrUpstreamTimeout, http.StatusGatewayTimeout},
-			slog.LevelWarn},
 		{"no free upstream connection", httpfetcher.ErrTooManyConnections,
-			http.StatusServiceUnavailable, slog.LevelWarn},
+			http.StatusServiceUnavailable},
 		{"Content-Type not a source format",
 			fmt.Errorf("%w: image/svg+xml", httpfetcher.ErrInvalidContentType),
-			http.StatusUnsupportedMediaType, slog.LevelWarn},
+			http.StatusUnsupportedMediaType},
 		{"any other failure", io.ErrUnexpectedEOF,
-			http.StatusInternalServerError, slog.LevelError},
+			http.StatusInternalServerError},
+	}
+
+	// The URL of the JPEG at photoPath on signedHost on each image route.
+	imageURLs := map[string]func(*testing.T, *Handlers) string{
+		"/v1/image/": signedPhotoURL,
+		"/v1/e/":     encPhotoURL,
 	}
 
 	for _, tt := range tests {
-		for route, imageURL := range photoURLsByRoute() {
+		for route, imageURL := range imageURLs {
 			t.Run(route+" "+tt.name, func(t *testing.T) {
 				t.Parallel()
 
-				var logs bytes.Buffer
-
 				h, routes := newRoutesFetchingThrough(t,
-					failingFetcher{err: tt.err},
+					failingFetcher{err: tt.err}, slog.New(slog.DiscardHandler))
-					slog.New(slog.NewJSONHandler(&logs, nil)))
 
 				rec := sendGet(t, routes, imageURL(t, h))
 				if rec.Code != tt.wantStatus {
 					t.Errorf("status = %d, want %d: %s",
 						rec.Code, tt.wantStatus, rec.Body)
 				}
-
-				levels := loggedLevels(t, &logs)
-				if !slices.Contains(levels[tt.wantLevel.String()],
-					"failed to get image") {
-					t.Errorf(`no "failed to get image" line logged at level %s`,
-						tt.wantLevel)
-				}
-
-				if tt.wantLevel != slog.LevelError &&
-					len(levels[slog.LevelError.String()]) != 0 {
-					t.Errorf("logged at error level: %q",
-						levels[slog.LevelError.String()])
-				}
 			})
 		}
 	}
 }
-
-// failingResponseWriter is a response writer whose Write always fails, as when
-// the client has gone away.
-type failingResponseWriter struct {
-	*httptest.ResponseRecorder
-}
-
-// Write writes nothing and returns io.ErrClosedPipe.
-func (failingResponseWriter) Write([]byte) (int, error) {
-	return 0, io.ErrClosedPipe
-}
-
-// TestImageRoutes_FailedWriteLoggedOnce checks that both image routes log a
-// failed write of the image once, at error level, with the request's ID, the
-// source host and path, the bytes served and the error. Neither may also log
-// the image as served.
-func TestImageRoutes_FailedWriteLoggedOnce(t *testing.T) {
-	t.Parallel()
-
-	const requestID = "test-request-id"
-
-	for route, imageURL := range photoURLsByRoute() {
-		t.Run(route, func(t *testing.T) {
-			t.Parallel()
-
-			var logs bytes.Buffer
-
-			h, srv := newSignedHostServer(t,
-				slog.New(slog.NewJSONHandler(&logs, nil)))
-
-			ctx := context.WithValue(t.Context(),
-				middleware.RequestIDKey, requestID)
-			srv.ServeHTTP(failingResponseWriter{httptest.NewRecorder()},
-				httptest.NewRequestWithContext(
-					ctx, http.MethodGet, imageURL(t, h), nil))
-
-			t.Logf("logged:\n%s", logs.String())
-
-			var failedWrites []map[string]any
-
-			dec := json.NewDecoder(&logs)
-			for dec.More() {
-				var line map[string]any
-
-				err := dec.Decode(&line)
-				if err != nil {
-					t.Fatalf("decoding log line: %v", err)
-				}
-
-				switch line["msg"] {
-				case "image served":
-					t.Error(`"image served" logged after a failed write`)
-				case "failed to write response":
-					failedWrites = append(failedWrites, line)
-				}
-			}
-
-			if len(failedWrites) != 1 {
-				t.Fatalf(`"failed to write response" logged %d times, want 1`,
-					len(failedWrites))
-			}
-
-			want := map[string]any{
-				"level":        slog.LevelError.String(),
-				"request_id":   requestID,
-				"host":         signedHost,
-				"path":         photoPath,
-				"served_bytes": float64(0),
-				"error":        io.ErrClosedPipe.Error(),
-			}
-
-			for key, wantValue := range want {
-				if got := failedWrites[0][key]; got != wantValue {
-					t.Errorf("%s = %v, want %v", key, got, wantValue)
-				}
-			}
-		})
-	}
-}