diff --git a/README.md b/README.md index 5268bc1..0973975 100644 --- a/README.md +++ b/README.md @@ -310,6 +310,7 @@ path under `/v1/` answers 200, in maintenance mode too. - 403 when the upstream host, or a host it redirects to, has an address in a blocked network (see `blocked_networks`). - 429 over `image_requests_per_minute` (below). + - 499 when the client goes away before the image is ready. - 415 when the upstream answers with a `Content-Type` that is not one of the source formats (below). - 415 when the upstream sends a body whose first bytes are not those of the @@ -341,6 +342,7 @@ path under `/v1/` answers 200, in maintenance mode too. - 403 - 415 - 429 + - 499 - 502 - 503 - 504 diff --git a/TODO.md b/TODO.md index 92228e4..b12e97b 100644 --- a/TODO.md +++ b/TODO.md @@ -30,6 +30,16 @@ P2: security: per-origin rate limiting # Completed Steps +- 2026-10-26 on both image routes, a request whose client went away before its + image was ready is answered 499 and logged at info level (closes #339). It was + answered 500 and logged at error level, as pixa's own failure. + - The line is "client went away before the image was ready". It carries the + `request_id`, the host and the path. + - The 499 has no body, since nobody reads it. + - `serveImage` answers it before calling `respondImageError`, which cannot + see the request's context. + - An error wrapping `context.Canceled` while the request's context is live + is still answered 500 and logged at error level. - 2026-10-26 `README.md`'s Design section starts with a Concepts list (closes #321). Each concept gets one sentence, under the name the code gives it. - Storage calls the transformed images variants, in shorter sentences. diff --git a/internal/handlers/client_gone_internal_test.go b/internal/handlers/client_gone_internal_test.go new file mode 100644 index 0000000..554beff --- /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 != statusClientClosedRequest { + t.Errorf("status = %d, want %d", rec.Code, statusClientClosedRequest) + } + + 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`) + } + }) + } +} diff --git a/internal/handlers/image.go b/internal/handlers/image.go index 68c2fee..7c1c468 100644 --- a/internal/handlers/image.go +++ b/internal/handlers/image.go @@ -1,6 +1,7 @@ package handlers import ( + "context" "errors" "fmt" "io" @@ -19,6 +20,11 @@ import ( "sneak.berlin/go/pixa/internal/magic" ) +// statusClientClosedRequest is the status nginx calls "client closed +// request". The image routes answer it to a request whose client went away +// before its image was ready. Nobody reads it; it is for logs and metrics. +const statusClientClosedRequest = 499 + // HandleImage handles the main image proxy route: // /v1/image///x., or with no format // /v1/image///x @@ -345,8 +351,9 @@ func notModified(w http.ResponseWriter, r *http.Request, etag string) bool { // serveImage serves the image that req asks for. Both image routes call it // once they have the request and its URL's expiry, which ends the // Cache-Control max-age. It chooses the format for the format auto, answers -// If-None-Match with 304 and HEAD with the headers only, and answers an error -// of the image service with respondImageError. +// If-None-Match with 304 and HEAD with the headers only. It answers 499 when +// the client went away before the image was ready, and any other error of +// the image service with respondImageError. func (s *Handlers) serveImage( w http.ResponseWriter, r *http.Request, req *imagerequest.Request, expires time.Time, @@ -362,6 +369,21 @@ func (s *Handlers) serveImage( startTime := time.Now() resp, err := s.imgSvc.Get(r.Context(), req) + + // The client went away before its image was ready, which is not pixa's + // failure. A cancellation while the request's context is live is pixa's, + // and respondImageError answers it 500. + if errors.Is(err, context.Canceled) && r.Context().Err() != nil { + s.log.Info("client went away before the image was ready", + "request_id", middleware.GetReqID(r.Context()), + "host", req.Source.Host, + "path", req.Source.Path, + ) + w.WriteHeader(statusClientClosedRequest) + + return + } + if err != nil { s.respondImageError(w, req, err)