internal/handlers/client_gone_internal_test.go

@@ -0,0 +1,177 @@
+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_ClientGoneWhileWaitingAnswers499 checks that both image
+// routes answer 499 to a request whose client goes away while it waits for an
+// image another request is making. 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_ClientGoneWhileWaitingAnswers499(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`)
+			}
+		})
+	}
+}