diff --git a/internal/handlers/client_gone_internal_test.go b/internal/handlers/client_gone_internal_test.go new file mode 100644 index 0000000..0323d7a --- /dev/null +++ b/internal/handlers/client_gone_internal_test.go @@ -0,0 +1,173 @@ +package handlers + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "slices" + "testing" + + "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)) + }() + + // The fetch is still held, so the second request can end only + // because its client went away + 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`) + } + }) + } +}