Answer 499 to a client that goes away while waiting for an image (closes #339) #341

Merged
clawbot merged 2 commits from issue-339-client-gone into next 2026-10-27 00:49:37 +01:00
4 changed files with 215 additions and 1 deletions
+3
View File
@@ -310,6 +310,8 @@ 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 - 403 when the upstream host, or a host it redirects to, has an address in a
blocked network (see `blocked_networks`). blocked network (see `blocked_networks`).
- 429 over `image_requests_per_minute` (below). - 429 over `image_requests_per_minute` (below).
- 499, with no body, when the client goes away before its image is ready,
unless its request is the one making the image (below).
- 415 when the upstream answers with a `Content-Type` that is not one of the - 415 when the upstream answers with a `Content-Type` that is not one of the
source formats (below). source formats (below).
- 415 when the upstream sends a body whose first bytes are not those of the - 415 when the upstream sends a body whose first bytes are not those of the
@@ -341,6 +343,7 @@ path under `/v1/` answers 200, in maintenance mode too.
- 403 - 403
- 415 - 415
- 429 - 429
- 499, with no body
- 502 - 502
- 503 - 503
- 504 - 504
+11
View File
@@ -30,6 +30,17 @@ P2: security: per-origin rate limiting
# Completed Steps # Completed Steps
- 2026-10-26 on both image routes, a request is answered 499 and logged at info
level when its client goes away before its image is ready, unless it is the
request making the image (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 - 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. #321). Each concept gets one sentence, under the name the code gives it.
- Storage calls the transformed images variants, in shorter sentences. - Storage calls the transformed images variants, in shorter sentences.
@@ -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`)
}
})
}
}
+24 -1
View File
@@ -1,6 +1,7 @@
package handlers package handlers
import ( import (
"context"
"errors" "errors"
"fmt" "fmt"
"io" "io"
@@ -19,6 +20,12 @@ import (
"sneak.berlin/go/pixa/internal/magic" "sneak.berlin/go/pixa/internal/magic"
) )
// statusClientClosedRequest is the status nginx calls "client closed
// request". The image routes answer it when the client goes away before its
// image is ready, unless its request is the one making the image. Nobody reads
// it; it is for logs and metrics.
const statusClientClosedRequest = 499
// HandleImage handles the main image proxy route: // HandleImage handles the main image proxy route:
// /v1/image/<host>/<path>/<width>x<height>.<format>, or with no format // /v1/image/<host>/<path>/<width>x<height>.<format>, or with no format
// /v1/image/<host>/<path>/<width>x<height> // /v1/image/<host>/<path>/<width>x<height>
@@ -345,7 +352,8 @@ func notModified(w http.ResponseWriter, r *http.Request, etag string) bool {
// serveImage serves the image that req asks for. Both image routes call it // 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 // 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 // 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 // If-None-Match with 304 and HEAD with the headers only. It answers 499 when
// the image service stopped because the client went away, and any other error
// of the image service with respondImageError. // of the image service with respondImageError.
func (s *Handlers) serveImage( func (s *Handlers) serveImage(
w http.ResponseWriter, r *http.Request, w http.ResponseWriter, r *http.Request,
@@ -362,6 +370,21 @@ func (s *Handlers) serveImage(
startTime := time.Now() startTime := time.Now()
resp, err := s.imgSvc.Get(r.Context(), req) 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 { if err != nil {
s.respondImageError(w, req, err) s.respondImageError(w, req, err)