Test that a client leaving while another request makes its image gets 499

On both image routes, a request waits for an image another request is
making, and its client goes away. The first test wants that request
answered 499 and logged once at info level. It fails on next, which
answers 500 and logs it at error level. The second test pins the 500
that a cancellation keeps while the request's context is live; it
passes on next. The fix follows in the next commit.

Model: opus-5-5

internal/handlers/client_gone_internal_test.go

@@ -0,0 +1,176 @@
+package handlers
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"slices"
+	"testing"
+	"time"
+
+	"github.com/go-chi/chi/v5/middleware"
+	"sneak.berlin/go/pixa/internal/httpfetcher"
+	"sneak.berlin/go/pixa/internal/imagerequest"
+)
+
+// heldFetcher sends on started when a fetch begins, and holds the fetch until
+// release is closed. It then fails the fetch as an upstream error.
+type heldFetcher struct {
+	started chan struct{}
+	release chan struct{}
+}
+
+// Fetch sends on f.started, waits for f.release to be closed, and returns
+// httpfetcher.ErrUpstreamError.
+func (f heldFetcher) Fetch(
+	context.Context, imagerequest.Source,
+) (*httpfetcher.FetchResult, error) {
+	f.started <- struct{}{}
+
+	<-f.release
+
+	return nil, httpfetcher.ErrUpstreamError
+}
+
+// readLogLines decodes the JSON log lines in logs.
+func readLogLines(t *testing.T, logs *bytes.Buffer) []map[string]any {
+	t.Helper()
+
+	t.Logf("logged:\n%s", logs.String())
+
+	var lines []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)
+		}
+
+		lines = append(lines, line)
+	}
+
+	return lines
+}
+
+// TestImageRoutes_ClientGoneAnswers499 checks that both image routes answer
+// 499 to a request whose client goes away while its image is being made. A
+// first request's fetch is held, so the image is being made, and a second
+// request for the same image waits for it until its client goes away. The
+// second request must be logged once at info level with its request ID and
+// the source host and path. Nothing may be logged at error level.
+func TestImageRoutes_ClientGoneAnswers499(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
+
+			fetcher := heldFetcher{started: make(chan struct{}), release: make(chan struct{})}
+			h, routes := newRoutesFetchingThrough(t, fetcher,
+				slog.New(slog.NewJSONHandler(&logs, nil)))
+			target := imageURL(t, h)
+
+			firstDone := make(chan struct{})
+
+			go func() {
+				defer close(firstDone)
+
+				sendGet(t, routes, target)
+			}()
+
+			<-fetcher.started
+
+			ctx, cancel := context.WithCancel(context.WithValue(t.Context(),
+				middleware.RequestIDKey, requestID))
+			rec := httptest.NewRecorder()
+			secondDone := make(chan struct{})
+
+			go func() {
+				defer close(secondDone)
+
+				routes.ServeHTTP(rec, httptest.NewRequestWithContext(
+					ctx, http.MethodGet, target, nil))
+			}()
+
+			// Give the second request time to start waiting for the first
+			// request's image. The fetch is still held, so the second request
+			// can end only because its client went away
+			time.Sleep(100 * time.Millisecond)
+			cancel()
+			<-secondDone
+
+			close(fetcher.release)
+			<-firstDone
+
+			if rec.Code != 499 {
+				t.Errorf("status = %d, want 499", rec.Code)
+			}
+
+			var clientGoneLines int
+
+			for _, line := range readLogLines(t, &logs) {
+				if line["level"] == slog.LevelError.String() {
+					t.Errorf("logged at error level: %v", line["msg"])
+				}
+
+				if line["level"] == slog.LevelInfo.String() &&
+					line["msg"] == "client went away before the image was ready" &&
+					line["request_id"] == requestID &&
+					line["host"] == signedHost &&
+					line["path"] == photoPath {
+					clientGoneLines++
+				}
+			}
+
+			if clientGoneLines != 1 {
+				t.Errorf("info line naming the request logged %d times, want 1",
+					clientGoneLines)
+			}
+		})
+	}
+}
+
+// TestImageRoutes_CanceledWithLiveRequestAnswers500 checks that both image
+// routes answer 500, logged as "failed to get image" at error level, for an
+// image service error that wraps context.Canceled while the request's own
+// context is live. Its client has not gone away, so the cancellation is
+// pixa's own failure.
+func TestImageRoutes_CanceledWithLiveRequestAnswers500(t *testing.T) {
+	t.Parallel()
+
+	for route, imageURL := range photoURLsByRoute() {
+		t.Run(route, func(t *testing.T) {
+			t.Parallel()
+
+			var logs bytes.Buffer
+
+			h, routes := newRoutesFetchingThrough(t,
+				failingFetcher{err: context.Canceled},
+				slog.New(slog.NewJSONHandler(&logs, nil)))
+
+			rec := sendGet(t, routes, imageURL(t, h))
+			if rec.Code != http.StatusInternalServerError {
+				t.Errorf("status = %d, want %d",
+					rec.Code, http.StatusInternalServerError)
+			}
+
+			if !slices.ContainsFunc(readLogLines(t, &logs),
+				func(line map[string]any) bool {
+					return line["level"] == slog.LevelError.String() &&
+						line["msg"] == "failed to get image"
+				}) {
+				t.Error(`no "failed to get image" line logged at error level`)
+			}
+		})
+	}
+}