Answer 499 to a client that goes away while waiting for an image (closes #339) #341
@@ -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
|
||||||
|
|||||||
@@ -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`)
|
||||||
|
}
|
||||||
|
})
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -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)
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user