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

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 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)
+				}
+			}
+		})
+	}
+}