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. 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 the other answers at warn. The image service
alone logs a source refused for its first bytes. A failed write is logged once,
at warn, 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 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)
+				}
+			}
+		})
+	}
+}