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

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,

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)
+				}
+			}
+		})
+	}
+}

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)
+	}
+}