From e00bf374cb259746cc29aa4ca5e923cbc9b21e12 Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Sun, 4 Oct 2026 08:34:04 +0000 Subject: [PATCH] Test that the upstream fetch and image log lines carry the request ID A fetch must send the ID of the request it serves as X-Request-Id, and the "upstream fetched", "image converted" and "image served" lines must carry it as request_id, through either image route. newSignedHostServer takes the logger its handlers and image service write to; its existing callers pass a discarding one. Model: opus-5-5 --- .../image_cache_control_internal_test.go | 13 +- internal/handlers/request_id_internal_test.go | 131 ++++++++++++++++++ .../httpfetcher/request_id_internal_test.go | 50 +++++++ 3 files changed, 189 insertions(+), 5 deletions(-) create mode 100644 internal/handlers/request_id_internal_test.go create mode 100644 internal/httpfetcher/request_id_internal_test.go diff --git a/internal/handlers/image_cache_control_internal_test.go b/internal/handlers/image_cache_control_internal_test.go index bb6a6b9..7845df5 100644 --- a/internal/handlers/image_cache_control_internal_test.go +++ b/internal/handlers/image_cache_control_internal_test.go @@ -23,8 +23,10 @@ const photoPath = "/images/photo.jpg" // newSignedHostServer returns a router for both image routes, and the Handlers // behind it, whose fetcher serves a JPEG at photoPath on signedHost. signedHost // is not on the allowlist, so a /v1/image/ URL for it is served only with a -// valid signature. -func newSignedHostServer(t *testing.T) (*Handlers, http.Handler) { +// valid signature. The handlers and the image service log to log. +func newSignedHostServer( + t *testing.T, log *slog.Logger, +) (*Handlers, http.Handler) { t.Helper() cache, err := imgcache.NewCache(setupTestDB(t), imgcache.CacheConfig{ @@ -44,6 +46,7 @@ func newSignedHostServer(t *testing.T) (*Handlers, http.Handler) { signedHost + photoPath: &fstest.MapFile{Data: jpegData}, }), SigningKey: testSigningKey, + Logger: log, }) if err != nil { t.Fatalf("imgcache.NewService() error = %v", err) @@ -55,7 +58,7 @@ func newSignedHostServer(t *testing.T) (*Handlers, http.Handler) { } h := &Handlers{ - log: slog.New(slog.DiscardHandler), + log: log, imgSvc: svc, encGen: encGen, } @@ -103,7 +106,7 @@ func getMaxAge(t *testing.T, srv http.Handler, target string) int { func TestHandleImage_SignedURL_MaxAgeEndsAtExp(t *testing.T) { t.Parallel() - h, srv := newSignedHostServer(t) + h, srv := newSignedHostServer(t, slog.New(slog.DiscardHandler)) signedURL, err := h.imgSvc.GenerateSignedURL("", &imgcache.ImageRequest{ SourceHost: signedHost, @@ -179,7 +182,7 @@ func TestHandleImageEnc_MaxAge(t *testing.T) { t.Run(tt.name, func(t *testing.T) { t.Parallel() - h, srv := newSignedHostServer(t) + h, srv := newSignedHostServer(t, slog.New(slog.DiscardHandler)) token, err := h.encGen.Generate(&encurl.Payload{ SourceHost: signedHost, diff --git a/internal/handlers/request_id_internal_test.go b/internal/handlers/request_id_internal_test.go new file mode 100644 index 0000000..d26a2f6 --- /dev/null +++ b/internal/handlers/request_id_internal_test.go @@ -0,0 +1,131 @@ +package handlers + +import ( + "bytes" + "context" + "encoding/json" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/go-chi/chi/v5/middleware" + + "sneak.berlin/go/pixa/internal/encurl" + "sneak.berlin/go/pixa/internal/imgcache" +) + +// signedPhotoURL returns a signed /v1/image/ URL, valid for a minute, for the +// JPEG at photoPath on signedHost at 50x50, made with h's image service. +func signedPhotoURL(t *testing.T, h *Handlers) string { + t.Helper() + + signedURL, err := h.imgSvc.GenerateSignedURL("", &imgcache.ImageRequest{ + SourceHost: signedHost, + SourcePath: photoPath, + Size: imgcache.Size{Width: 50, Height: 50}, + Format: imgcache.FormatJPEG, + }, time.Minute) + if err != nil { + t.Fatalf("GenerateSignedURL() error = %v", err) + } + + return signedURL +} + +// encPhotoURL returns an encrypted /v1/e/ URL, which never expires, for the +// JPEG at photoPath on signedHost at 50x50, made with h's generator. +func encPhotoURL(t *testing.T, h *Handlers) string { + t.Helper() + + token, err := h.encGen.Generate(&encurl.Payload{ + SourceHost: signedHost, + SourcePath: photoPath, + Width: 50, + Height: 50, + Format: imgcache.FormatJPEG, + }) + if err != nil { + t.Fatalf("Generate() error = %v", err) + } + + return "/v1/e/" + token + "/img.jpg" +} + +// requestIDByMessage reads the JSON log lines in logs and returns the +// request_id of each line, by its message. +func requestIDByMessage(t *testing.T, logs io.Reader) map[string]string { + t.Helper() + + logged := make(map[string]string) + + 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) + } + + msg, _ := line["msg"].(string) + requestID, _ := line["request_id"].(string) + logged[msg] = requestID + } + + return logged +} + +// TestImageLogLinesCarryRequestID verifies that the lines logged when an image +// is fetched, converted and served through either image route carry the +// request's ID as request_id, as the request log line does, so they can be +// found from it. +func TestImageLogLinesCarryRequestID(t *testing.T) { + t.Parallel() + + const requestID = "test-request-id" + + imageURLs := map[string]func(*testing.T, *Handlers) string{ + "/v1/image/": signedPhotoURL, + "/v1/e/": encPhotoURL, + } + + for route, imageURL := range imageURLs { + t.Run(route, func(t *testing.T) { + t.Parallel() + + var logs bytes.Buffer + + h, srv := newSignedHostServer(t, + slog.New(slog.NewJSONHandler(&logs, nil))) + + ctx := context.WithValue(t.Context(), + middleware.RequestIDKey, requestID) + rec := httptest.NewRecorder() + srv.ServeHTTP(rec, httptest.NewRequestWithContext( + ctx, http.MethodGet, imageURL(t, h), nil)) + + if rec.Code != http.StatusOK { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusOK) + } + + t.Logf("logged:\n%s", logs.String()) + + logged := requestIDByMessage(t, &logs) + + for _, msg := range []string{ + "upstream fetched", "image converted", "image served", + } { + got, ok := logged[msg] + if !ok { + t.Errorf("no %q line logged", msg) + } else if got != requestID { + t.Errorf("%q line has request_id %q, want %q", + msg, got, requestID) + } + } + }) + } +} diff --git a/internal/httpfetcher/request_id_internal_test.go b/internal/httpfetcher/request_id_internal_test.go new file mode 100644 index 0000000..374bdbb --- /dev/null +++ b/internal/httpfetcher/request_id_internal_test.go @@ -0,0 +1,50 @@ +package httpfetcher + +import ( + "context" + "io" + "net/http" + "net/http/httptest" + "testing" + + "github.com/go-chi/chi/v5/middleware" +) + +// TestFetchSendsRequestID verifies that a fetch sends the ID of the request +// it serves, which chi's RequestID middleware stores in the request context, +// to the upstream host as X-Request-Id, so the fetch can be found in that +// host's logs. +func TestFetchSendsRequestID(t *testing.T) { + t.Parallel() + + const requestID = "test-request-id" + + received := make(chan string, 1) + + srv := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + received <- r.Header.Get("X-Request-Id") + + w.Header().Set("Content-Type", contentTypeJPEG) + _, _ = io.WriteString(w, imagePayload) + })) + t.Cleanup(srv.Close) + + f, _ := newServerFetcher(t, srv, nil) + + ctx := context.WithValue(testContext(t), middleware.RequestIDKey, requestID) + + res, err := f.Fetch(ctx, upstreamURL("/image")) + if err != nil { + t.Fatalf("Fetch() error = %v", err) + } + + _ = res.Content.Close() + + got := <-received + t.Logf("upstream received X-Request-Id %q", got) + + if got != requestID { + t.Errorf("upstream X-Request-Id = %q, want %q", got, requestID) + } +}