README.md

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

@@ -30,6 +30,36 @@ P2: security: per-origin rate limiting
 
 # Completed Steps
 
+- 2026-10-26 both image routes serve an image with one function, `serveImage`,
+  and answer its errors with one, `respondImageError` (closes #316).
+  `HandleImage` parses the path and verifies the signature, and `HandleImageEnc`
+  decrypts the token. Each then calls `serveImage`.
+    - `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
+      image". Each answer gets the same level on `/v1/image/` and on `/v1/e/`:
+        - 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.
+    - The debug line "failed to decrypt URL" is now "invalid encrypted URL". A
+      token that decrypts to a payload that does not decode also gets it.
+    - A failed write is logged once, as "failed to write response" at warn
+      level, since most often the client has gone away. 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/avif_too_large_internal_test.go

@@ -12,11 +12,11 @@ import (
 	"sneak.berlin/go/pixa/internal/imagerequest"
 )
 
-// TestAVIFOutputTooLargeAnswers400 checks that respondImageError and
-// handleImageError, which answer the errors of the two image routes, answer
-// 400 naming the AVIF pixel limit when the image processor refuses an AVIF
-// output above it, wrapped as the service wraps it. The request's source only
-// goes into a log line, so it is left empty.
+// TestAVIFOutputTooLargeAnswers400 checks that respondImageError, which
+// answers the errors of both image routes, answers 400 naming the AVIF pixel
+// limit when the image processor refuses an AVIF output above it, wrapped as
+// the service wraps it. The request's source only goes into a log line, so it
+// is left empty.
 func TestAVIFOutputTooLargeAnswers400(t *testing.T) {
 	t.Parallel()
 
@@ -25,25 +25,15 @@ func TestAVIFOutputTooLargeAnswers400(t *testing.T) {
 		imageprocessor.ErrAVIFOutputTooLarge)
 	wantBody := fmt.Sprintf("above %d pixels", imageprocessor.MaxAVIFOutputPixels)
 
-	plain := httptest.NewRecorder()
-	h.respondImageError(plain, &imagerequest.Request{}, err)
+	rec := httptest.NewRecorder()
+	h.respondImageError(rec, &imagerequest.Request{}, err)
+	t.Logf("status = %d, body = %q", rec.Code, rec.Body.String())
 
-	encrypted := httptest.NewRecorder()
-	h.handleImageError(encrypted, err)
+	if rec.Code != http.StatusBadRequest {
+		t.Errorf("status = %d, want %d", rec.Code, http.StatusBadRequest)
+	}
 
-	for name, rec := range map[string]*httptest.ResponseRecorder{
-		"respondImageError": plain, "handleImageError": encrypted,
-	} {
-		t.Logf("%s: status = %d, body = %q", name, rec.Code, rec.Body.String())
-
-		if rec.Code != http.StatusBadRequest {
-			t.Errorf("%s: status = %d, want %d",
-				name, rec.Code, http.StatusBadRequest)
-		}
-
-		if !strings.Contains(rec.Body.String(), wantBody) {
-			t.Errorf("%s: body = %q, want it to say %q",
-				name, rec.Body.String(), wantBody)
-		}
+	if !strings.Contains(rec.Body.String(), wantBody) {
+		t.Errorf("body = %q, want it to say %q", rec.Body.String(), wantBody)
 	}
 }

internal/handlers/image.go

@@ -46,30 +46,7 @@ func (s *Handlers) HandleImage() http.HandlerFunc {
 			return
 		}
 
-		// The signature covers the format auto, not the format chosen
-		format, ok := s.chooseAutoFormat(w, r, req.Transform.Format)
-		if !ok {
-			return
-		}
-
-		req.Transform.Format = format
-
-		// Get cache key for logging
-		cacheKey := imagerequest.CacheKey(req)
-
-		// Get the image (from cache or fetch/process)
-		startTime := time.Now()
-
-		resp, err := s.imgSvc.Get(r.Context(), req)
-		if err != nil {
-			s.respondImageError(w, req, err)
-
-			return
-		}
-
-		defer func() { _ = resp.Content.Close() }()
-
-		s.writeImageResponse(w, r, req, expires, resp, cacheKey, startTime)
+		s.serveImage(w, r, req, expires)
 	}
 }
 
@@ -213,8 +190,8 @@ func (s *Handlers) validateSignature(
 }
 
 // parseExpires reads the exp query parameter, a Unix time in seconds. An exp
-// missing from the URL gives the zero time, which the signature check takes
-// as no expiration. An exp in the URL that is not a whole number, an empty
+// missing from the URL gives the zero time, which the signature check refuses
+// as a missing exp. An exp in the URL that is not a whole number, an empty
 // one included, is an error naming exp and the value.
 func parseExpires(query url.Values) (time.Time, error) {
 	if !query.Has("exp") {
@@ -242,7 +219,11 @@ func (s *Handlers) HandleTooManyRequests() http.HandlerFunc {
 	}
 }
 
-// respondImageError maps image retrieval errors to HTTP responses.
+// 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
+// the other answers at warn level, since the client, the upstream or a full
+// limit caused them. The 415 for a source refused for its first bytes is not
+// logged here, because the image service logs it.
 func (s *Handlers) respondImageError(
 	w http.ResponseWriter, req *imagerequest.Request, err error,
 ) {
@@ -258,59 +239,53 @@ func (s *Handlers) respondImageError(
 		return
 	}
 
-	s.log.Error("failed to get image",
+	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)
+
+		return
+	}
+
+	s.log.Warn("failed to get image",
 		"host", req.Source.Host,
 		"path", req.Source.Path,
 		"error", err,
 	)
-
-	// Check for specific error types
-	if errors.Is(err, httpfetcher.ErrSSRFBlocked) {
-		s.respondError(w, "forbidden", http.StatusForbidden)
-
-		return
-	}
-
-	if errors.Is(err, httpfetcher.ErrUpstreamError) {
-		s.respondError(w, "upstream error", http.StatusBadGateway)
-
-		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)
+	s.respondError(w, message, status)
 }
 
 // cacheControl returns the Cache-Control header for an image served through a
@@ -367,14 +342,34 @@ func notModified(w http.ResponseWriter, r *http.Request, etag string) bool {
 	return true
 }
 
-// writeImageResponse writes headers and streams the image content,
-// handling conditional and HEAD requests. expires is the URL's expiry, which
-// ends the Cache-Control max-age.
-func (s *Handlers) writeImageResponse(
+// serveImage serves the image that req asks for. Both image routes call it
+// once they have the request and its URL's expiry, which ends the
+// Cache-Control max-age. It chooses the format for the format auto, answers
+// If-None-Match with 304 and HEAD with the headers only, and answers an error
+// of the image service with respondImageError.
+func (s *Handlers) serveImage(
 	w http.ResponseWriter, r *http.Request,
-	req *imagerequest.Request, expires time.Time, resp *imgcache.ImageResponse,
-	cacheKey imagerequest.VariantKey, startTime time.Time,
+	req *imagerequest.Request, expires time.Time,
 ) {
+	// The signature or the token covers the format auto, not the format chosen
+	format, ok := s.chooseAutoFormat(w, r, req.Transform.Format)
+	if !ok {
+		return
+	}
+
+	req.Transform.Format = format
+
+	startTime := time.Now()
+
+	resp, err := s.imgSvc.Get(r.Context(), req)
+	if err != nil {
+		s.respondImageError(w, req, err)
+
+		return
+	}
+
+	defer func() { _ = resp.Content.Close() }()
+
 	// Set response headers
 	w.Header().Set("Content-Type", resp.ContentType)
 
@@ -400,18 +395,28 @@ func (s *Handlers) writeImageResponse(
 	// Stream the response
 	w.WriteHeader(http.StatusOK)
 
+	// A failed write is most often a client that has gone away, not pixa's
+	// failure, so it is logged at warn level
 	servedBytes, err := io.Copy(w, resp.Content)
 	if err != nil {
-		s.log.Error("failed to write response",
+		s.log.Warn("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
 	duration := time.Since(startTime)
 	s.log.Info("image served",
 		"request_id", middleware.GetReqID(r.Context()),
-		"cache_key", cacheKey,
+		"cache_key", imagerequest.CacheKey(req),
+		"host", req.Source.Host,
+		"path", req.Source.Path,
 		"cache_status", resp.CacheStatus,
 		"duration_ms", duration.Milliseconds(),
 		"format", req.Transform.Format,

internal/handlers/image_errors_internal_test.go

@@ -1,18 +1,23 @@
 package handlers
 
 import (
+	"bytes"
+	"context"
 	"encoding/json"
 	"fmt"
 	"image/color"
+	"io"
 	"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"
@@ -414,3 +419,168 @@ func TestHandleImage_HashInSourcePathOrQuery_Returns400(t *testing.T) {
 		})
 	}
 }
+
+// failingFetcher answers every fetch with its error.
+type failingFetcher struct {
+	err error
+}
+
+// Fetch returns f's error.
+func (f failingFetcher) Fetch(
+	context.Context, imagerequest.Source,
+) (*httpfetcher.FetchResult, error) {
+	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
+// get image" at the same level: error for the 500 and warn for the others.
+// 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()
+
+	tests := []struct {
+		name       string
+		err        error
+		wantStatus int
+		wantLevel  slog.Level
+	}{
+		{"blocked upstream address", httpfetcher.ErrSSRFBlocked,
+			http.StatusForbidden, slog.LevelWarn},
+		{"upstream error status",
+			fmt.Errorf("%w: status 404", httpfetcher.ErrUpstreamError),
+			http.StatusBadGateway, slog.LevelWarn},
+		{"no response headers within the fetch timeout",
+			httpfetcher.ErrUpstreamTimeout, http.StatusGatewayTimeout,
+			slog.LevelWarn},
+		{"no free upstream connection", httpfetcher.ErrTooManyConnections,
+			http.StatusServiceUnavailable, slog.LevelWarn},
+		{"Content-Type not a source format",
+			fmt.Errorf("%w: image/svg+xml", httpfetcher.ErrInvalidContentType),
+			http.StatusUnsupportedMediaType, slog.LevelWarn},
+		{"any other failure", io.ErrUnexpectedEOF,
+			http.StatusInternalServerError, slog.LevelError},
+	}
+
+	for _, tt := range tests {
+		for route, imageURL := range photoURLsByRoute() {
+			t.Run(route+" "+tt.name, func(t *testing.T) {
+				t.Parallel()
+
+				var logs bytes.Buffer
+
+				h, routes := newRoutesFetchingThrough(t,
+					failingFetcher{err: tt.err},
+					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 warn 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.LevelWarn.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)
+				}
+			}
+		})
+	}
+}

internal/handlers/imageenc.go

@@ -2,21 +2,13 @@ package handlers
 
 import (
 	"errors"
-	"fmt"
-	"io"
 	"net/http"
-	"strconv"
 	"time"
 
 	"github.com/go-chi/chi/v5"
-	"github.com/go-chi/chi/v5/middleware"
 
 	"sneak.berlin/go/pixa/internal/encurl"
-	"sneak.berlin/go/pixa/internal/httpfetcher"
-	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imagerequest"
-	"sneak.berlin/go/pixa/internal/imgcache"
-	"sneak.berlin/go/pixa/internal/magic"
 )
 
 // HandleImageEnc handles requests to /v1/e/{token}/* for encrypted
@@ -28,83 +20,12 @@ func (s *Handlers) HandleImageEnc() http.HandlerFunc {
 			return
 		}
 
-		ctx := r.Context()
-		start := time.Now()
-
 		req, expires, ok := s.parseImageEncRequest(w, r)
 		if !ok {
 			return
 		}
 
-		format, ok := s.chooseAutoFormat(w, r, req.Transform.Format)
-		if !ok {
-			return
-		}
-
-		req.Transform.Format = format
-
-		// Log the request
-		s.log.Debug("encrypted image request",
-			"host", req.Source.Host,
-			"path", req.Source.Path,
-			"dimensions", fmt.Sprintf("%dx%d",
-				req.Transform.Size.Width, req.Transform.Size.Height),
-			"format", req.Transform.Format,
-		)
-
-		// Fetch and process the image (no signature validation
-		// needed - encrypted URL is trusted)
-		resp, err := s.imgSvc.Get(ctx, req)
-		if err != nil {
-			s.handleImageError(w, err)
-
-			return
-		}
-
-		defer func() { _ = resp.Content.Close() }()
-
-		// Set response headers
-		w.Header().Set("Content-Type", resp.ContentType)
-
-		if resp.ContentLength > 0 {
-			w.Header().Set("Content-Length", strconv.FormatInt(resp.ContentLength, 10))
-		}
-
-		// Cache headers: max-age ends at the URL's expiry
-		w.Header().Set("Cache-Control", cacheControl(expires))
-		w.Header().Set("X-Pixa-Cache", string(resp.CacheStatus))
-
-		if notModified(w, r, resp.ETag) {
-			return
-		}
-
-		// A HEAD request gets the headers only
-		if r.Method == http.MethodHead {
-			w.WriteHeader(http.StatusOK)
-
-			return
-		}
-
-		// Stream the response
-		written, err := io.Copy(w, resp.Content)
-		if err != nil {
-			s.log.Error("failed to write response", "error", err)
-
-			return
-		}
-
-		// Log completion
-		duration := time.Since(start)
-		s.log.Info("image served",
-			"request_id", middleware.GetReqID(ctx),
-			"cache_key", imagerequest.CacheKey(req),
-			"host", req.Source.Host,
-			"path", req.Source.Path,
-			"format", req.Transform.Format,
-			"cache_status", resp.CacheStatus,
-			"served_bytes", written,
-			"duration_ms", duration.Milliseconds(),
-		)
+		s.serveImage(w, r, req, expires)
 	}
 }
 
@@ -133,7 +54,7 @@ func (s *Handlers) parseImageEncRequest(
 			return nil, time.Time{}, false
 		}
 
-		s.log.Debug("failed to decrypt URL", "error", err)
+		s.log.Debug("invalid encrypted URL", "error", err)
 		s.respondError(w, "invalid encrypted URL", http.StatusBadRequest)
 
 		return nil, time.Time{}, false
@@ -141,8 +62,9 @@ func (s *Handlers) parseImageEncRequest(
 
 	// Apply the same dimension and fit-mode bounds as the plain image
 	// route: a sealed payload is trusted for its origin, not for staying
-	// within limits, so an over-limit size or unknown fit mode is a 400
-	// here rather than an out-of-memory or a 500 from the processor.
+	// within limits. This refuses an over-limit size before the source is
+	// fetched. An unknown fit mode is a 400 here rather than a 500 from the
+	// processor.
 	err = imagerequest.ValidateImageRequest(req)
 	if err != nil {
 		s.log.Debug("encrypted URL failed validation", "error", err)
@@ -154,38 +76,3 @@ func (s *Handlers) parseImageEncRequest(
 
 	return req, expires, true
 }
-
-// handleImageError converts image service errors to HTTP responses.
-func (s *Handlers) handleImageError(w http.ResponseWriter, err error) {
-	switch {
-	case errors.Is(err, httpfetcher.ErrSSRFBlocked):
-		s.respondError(w, "forbidden", http.StatusForbidden)
-	case errors.Is(err, httpfetcher.ErrUpstreamError):
-		s.respondError(w, "upstream error", http.StatusBadGateway)
-	case errors.Is(err, httpfetcher.ErrUpstreamTimeout):
-		s.respondError(w, "upstream timeout", http.StatusGatewayTimeout)
-	case errors.Is(err, httpfetcher.ErrTooManyConnections),
-		errors.Is(err, imageprocessor.ErrTooManyImages),
-		errors.Is(err, imgcache.ErrProcessingTimedOut):
-		s.respondError(w, "server busy, try again later",
-			http.StatusServiceUnavailable)
-	case errors.Is(err, httpfetcher.ErrInvalidContentType),
-		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat),
-		errors.Is(err, magic.ErrMagicByteMismatch),
-		errors.Is(err, magic.ErrUnknownFormat),
-		errors.Is(err, magic.ErrNotEnoughData):
-		s.respondError(w, "unsupported source format",
-			http.StatusUnsupportedMediaType)
-	case 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)
-	case 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)
-	default:
-		s.log.Error("image request failed", "error", err)
-		s.respondError(w, "internal error", http.StatusInternalServerError)
-	}
-}

internal/handlers/server_busy_internal_test.go

@@ -15,9 +15,10 @@ import (
 	"sneak.berlin/go/pixa/internal/imgcache"
 )
 
-// TestServerBusyAnswers503 checks that both image routes answer 503 with
-// a clear error when the image service gives up waiting for a free upstream
-// connection or processing slot, wrapped as the service wraps them.
+// TestServerBusyAnswers503 checks that respondImageError, which answers the
+// errors of both image routes, answers 503 with a clear error when the image
+// service gives up waiting for a free upstream connection or processing slot,
+// wrapped as the service wraps them.
 func TestServerBusyAnswers503(t *testing.T) {
 	t.Parallel()
 
@@ -30,35 +31,28 @@ func TestServerBusyAnswers503(t *testing.T) {
 		fmt.Errorf("upstream fetch failed: %w", httpfetcher.ErrTooManyConnections),
 		fmt.Errorf("image processing failed: %w", imageprocessor.ErrTooManyImages),
 	} {
-		plain := httptest.NewRecorder()
-		h.respondImageError(plain, req, err)
+		rec := httptest.NewRecorder()
+		h.respondImageError(rec, req, err)
 
-		encrypted := httptest.NewRecorder()
-		h.handleImageError(encrypted, err)
+		if rec.Code != http.StatusServiceUnavailable {
+			t.Errorf("for %v: status = %d, want %d",
+				err, rec.Code, http.StatusServiceUnavailable)
+		}
 
-		for route, rec := range map[string]*httptest.ResponseRecorder{
-			"/v1/image/": plain, "/v1/e/": encrypted,
-		} {
-			if rec.Code != http.StatusServiceUnavailable {
-				t.Errorf("%s for %v: status = %d, want %d",
-					route, err, rec.Code, http.StatusServiceUnavailable)
-			}
-
-			if !strings.Contains(rec.Body.String(), "server busy, try again later") {
-				t.Errorf("%s for %v: body = %q, want the server busy error",
-					route, err, rec.Body.String())
-			}
+		if !strings.Contains(rec.Body.String(), "server busy, try again later") {
+			t.Errorf("for %v: body = %q, want the server busy error",
+				err, rec.Body.String())
 		}
 	}
 }
 
-// TestProcessingTimedOutAnswers503 checks that respondImageError and
-// handleImageError, which answer the errors of the two image routes, answer
-// 503 with the server busy error when the image service reports that
-// processing stopped at the deadline of the request doing it, wrapped as the
-// service wraps it. A request that waited for that processing gets this error
-// while its own deadline may have time left. The request's source only goes
-// into a log line, so it is left empty.
+// TestProcessingTimedOutAnswers503 checks that respondImageError, which
+// answers the errors of both image routes, answers 503 with the server busy
+// error when the image service reports that processing stopped at the
+// deadline of the request doing it, wrapped as the service wraps it. A request
+// that waited for that processing gets this error while its own deadline may
+// have time left. The request's source only goes into a log line, so it is
+// left empty.
 func TestProcessingTimedOutAnswers503(t *testing.T) {
 	t.Parallel()
 
@@ -66,25 +60,15 @@ func TestProcessingTimedOutAnswers503(t *testing.T) {
 	err := fmt.Errorf("%w: failed to encode: %w",
 		imgcache.ErrProcessingTimedOut, context.DeadlineExceeded)
 
-	plain := httptest.NewRecorder()
-	h.respondImageError(plain, &imagerequest.Request{}, err)
+	rec := httptest.NewRecorder()
+	h.respondImageError(rec, &imagerequest.Request{}, err)
+	t.Logf("status = %d, body = %q", rec.Code, rec.Body.String())
 
-	encrypted := httptest.NewRecorder()
-	h.handleImageError(encrypted, err)
+	if rec.Code != http.StatusServiceUnavailable {
+		t.Errorf("status = %d, want %d", rec.Code, http.StatusServiceUnavailable)
+	}
 
-	for name, rec := range map[string]*httptest.ResponseRecorder{
-		"respondImageError": plain, "handleImageError": encrypted,
-	} {
-		t.Logf("%s: status = %d, body = %q", name, rec.Code, rec.Body.String())
-
-		if rec.Code != http.StatusServiceUnavailable {
-			t.Errorf("%s: status = %d, want %d",
-				name, rec.Code, http.StatusServiceUnavailable)
-		}
-
-		if !strings.Contains(rec.Body.String(), "server busy, try again later") {
-			t.Errorf("%s: body = %q, want the server busy error",
-				name, rec.Body.String())
-		}
+	if !strings.Contains(rec.Body.String(), "server busy, try again later") {
+		t.Errorf("body = %q, want the server busy error", rec.Body.String())
 	}
 }

internal/handlers/unsupported_source_internal_test.go

@@ -13,10 +13,11 @@ import (
 	"sneak.berlin/go/pixa/internal/imagerequest"
 )
 
-// TestUnsupportedSourceFormatAnswers415 checks that both image routes answer
-// 415 with a clear error when the upstream answers with a content type pixa
-// does not accept, such as SVG, and when orig is asked of a source in a
-// format the processor cannot name, wrapped as the service wraps them.
+// TestUnsupportedSourceFormatAnswers415 checks that respondImageError, which
+// answers the errors of both image routes, answers 415 with a clear error when
+// the upstream answers with a content type pixa does not accept, such as SVG,
+// and when orig is asked of a source in a format the processor cannot name,
+// wrapped as the service wraps them.
 func TestUnsupportedSourceFormatAnswers415(t *testing.T) {
 	t.Parallel()
 
@@ -31,26 +32,18 @@ func TestUnsupportedSourceFormatAnswers415(t *testing.T) {
 		fmt.Errorf("image processing failed: %w: unknown",
 			imageprocessor.ErrUnsupportedInputFormat),
 	} {
-		plain := httptest.NewRecorder()
-		h.respondImageError(plain, req, err)
+		rec := httptest.NewRecorder()
+		h.respondImageError(rec, req, err)
+		t.Logf("for %v: %d %s", err, rec.Code, rec.Body.String())
 
-		encrypted := httptest.NewRecorder()
-		h.handleImageError(encrypted, err)
+		if rec.Code != http.StatusUnsupportedMediaType {
+			t.Errorf("for %v: status = %d, want %d",
+				err, rec.Code, http.StatusUnsupportedMediaType)
+		}
 
-		for route, rec := range map[string]*httptest.ResponseRecorder{
-			"HandleImage": plain, "HandleImageEnc": encrypted,
-		} {
-			t.Logf("%s for %v: %d %s", route, err, rec.Code, rec.Body.String())
-
-			if rec.Code != http.StatusUnsupportedMediaType {
-				t.Errorf("%s for %v: status = %d, want %d",
-					route, err, rec.Code, http.StatusUnsupportedMediaType)
-			}
-
-			if !strings.Contains(rec.Body.String(), "unsupported source format") {
-				t.Errorf("%s for %v: body = %q, want the unsupported source format error",
-					route, err, rec.Body.String())
-			}
+		if !strings.Contains(rec.Body.String(), "unsupported source format") {
+			t.Errorf("for %v: body = %q, want the unsupported source format error",
+				err, rec.Body.String())
 		}
 	}
 }