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/. respondImageError logs a 500 at error level and every
other answer at warn. A failed write is logged once, with the request and the
bytes served. README.md lists each image route's answers as bullets. Tests send
the same errors through both routes.

Model: opus-5-5

README.md

@@ -248,32 +248,57 @@ 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; 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; 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; 400 for an `Accept` header that is not valid, and 406, 403, 415, 429,
-  502, 503, 504 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 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,11 +37,26 @@ 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.
-    - `/v1/e/` logs the image service's errors at error level, as `/v1/image/`
-      does. It logged only those 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, also after a failed write. The debug line "encrypted image
-      request" is gone.
+      both routes. The debug line "encrypted image request" is gone.
+    - A failed write is logged once, as "failed to write response" at error
+      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,7 +220,9 @@ func (s *Handlers) HandleTooManyRequests() http.HandlerFunc {
 }
 
 // respondImageError answers err, the image service's error for req, on both
-// image routes.
+// image routes. It logs a 500 at error level, as pixa's own failure. It logs
+// 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,
 ) {
@@ -236,65 +238,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.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)
+	s.respondError(w, message, status)
 }
 
 // cacheControl returns the Cache-Control header for an image served through a
@@ -407,8 +397,14 @@ 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,6 +1,7 @@
 package handlers
 
 import (
+	"bytes"
 	"context"
 	"encoding/json"
 	"fmt"
@@ -9,12 +10,14 @@ 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"
@@ -429,9 +432,20 @@ 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. Each request gets routes of
-// its own, so no request finds another's failed fetch in the negative cache.
+// 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()
 
@@ -439,43 +453,134 @@ func TestImageRoutes_SameErrorAnswers(t *testing.T) {
 		name       string
 		err        error
 		wantStatus int
+		wantLevel  slog.Level
 	}{
 		{"blocked upstream address", httpfetcher.ErrSSRFBlocked,
-			http.StatusForbidden},
+			http.StatusForbidden, slog.LevelWarn},
 		{"upstream error status",
 			fmt.Errorf("%w: status 404", httpfetcher.ErrUpstreamError),
-			http.StatusBadGateway},
+			http.StatusBadGateway, slog.LevelWarn},
 		{"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},
+			http.StatusServiceUnavailable, slog.LevelWarn},
 		{"Content-Type not a source format",
 			fmt.Errorf("%w: image/svg+xml", httpfetcher.ErrInvalidContentType),
-			http.StatusUnsupportedMediaType},
+			http.StatusUnsupportedMediaType, slog.LevelWarn},
 		{"any other failure", io.ErrUnexpectedEOF,
-			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,
+			http.StatusInternalServerError, slog.LevelError},
 	}
 
 	for _, tt := range tests {
-		for route, imageURL := range imageURLs {
+		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.DiscardHandler))
+					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 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)
+				}
+			}
+		})
+	}
+}