Return and pass on request IDs, and give /v1/e/ ETag, 304 and HEAD (closes #84)

Every response carries X-Request-Id, the upstream fetch sends it, and
the "upstream fetched", "image converted" and "image served" lines log
it as request_id. pixa's own RequestID middleware keeps a request's own
ID only when it is at most 64 letters, digits, '-', '_' or '.', and
otherwise makes a random one with crypto/rand, so nothing a client
chooses freely and nothing about the host reaches upstream. /v1/e/ now
sets ETag, answers a matching If-None-Match with 304 and is routed for
HEAD, through notModified, which both image handlers call. No Vary is
added: go-chi/cors already sends Vary: Origin.

Model: opus-5-5

internal/handlers/image.go

@@ -10,6 +10,7 @@ import (
 	"time"
 
 	"github.com/go-chi/chi/v5"
+	"github.com/go-chi/chi/v5/middleware"
 	"sneak.berlin/go/pixa/internal/encurl"
 	"sneak.berlin/go/pixa/internal/httpfetcher"
 	"sneak.berlin/go/pixa/internal/imageprocessor"
@@ -247,6 +248,25 @@ func cacheControl(expires time.Time) string {
 	return fmt.Sprintf("public, max-age=%d, immutable", int64(maxAge/time.Second))
 }
 
+// notModified sets the ETag header to etag and, when the request's
+// If-None-Match is that ETag, answers 304 Not Modified. It reports whether it
+// answered. An empty etag sets no header and never answers.
+func notModified(w http.ResponseWriter, r *http.Request, etag string) bool {
+	if etag == "" {
+		return false
+	}
+
+	w.Header().Set("ETag", etag)
+
+	if r.Header.Get("If-None-Match") != etag {
+		return false
+	}
+
+	w.WriteHeader(http.StatusNotModified)
+
+	return true
+}
+
 // writeImageResponse writes headers and streams the image content,
 // handling conditional and HEAD requests.
 func (s *Handlers) writeImageResponse(
@@ -265,17 +285,8 @@ func (s *Handlers) writeImageResponse(
 	w.Header().Set("Cache-Control", cacheControl(req.Expires))
 	w.Header().Set("X-Pixa-Cache", string(resp.CacheStatus))
 
-	if resp.ETag != "" {
-		w.Header().Set("ETag", resp.ETag)
-
-		// Check for conditional request (If-None-Match)
-		if ifNoneMatch := r.Header.Get("If-None-Match"); ifNoneMatch != "" {
-			if ifNoneMatch == resp.ETag {
-				w.WriteHeader(http.StatusNotModified)
-
-				return
-			}
-		}
+	if notModified(w, r, resp.ETag) {
+		return
 	}
 
 	// Handle HEAD request - return headers only
@@ -298,6 +309,7 @@ func (s *Handlers) writeImageResponse(
 	// Log cache status and timing after serving
 	duration := time.Since(startTime)
 	s.log.Info("image served",
+		"request_id", middleware.GetReqID(r.Context()),
 		"cache_key", cacheKey,
 		"cache_status", resp.CacheStatus,
 		"duration_ms", duration.Milliseconds(),

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/imageenc.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/go-chi/chi/v5"
+	"github.com/go-chi/chi/v5/middleware"
 
 	"sneak.berlin/go/pixa/internal/encurl"
 	"sneak.berlin/go/pixa/internal/httpfetcher"
@@ -24,43 +25,8 @@ func (s *Handlers) HandleImageEnc() http.HandlerFunc {
 		ctx := r.Context()
 		start := time.Now()
 
-		// Extract token from URL
-		token := chi.URLParam(r, "token")
-		if token == "" {
-			s.respondError(w, "missing token", http.StatusBadRequest)
-
-			return
-		}
-
-		// Decrypt and validate the payload
-		payload, err := s.encGen.Parse(token)
-		if err != nil {
-			if errors.Is(err, encurl.ErrExpired) {
-				s.log.Debug("encrypted URL expired", "error", err)
-				s.respondError(w, "URL has expired", http.StatusGone)
-
-				return
-			}
-
-			s.log.Debug("failed to decrypt URL", "error", err)
-			s.respondError(w, "invalid encrypted URL", http.StatusBadRequest)
-
-			return
-		}
-
-		// Convert payload to ImageRequest
-		req := payload.ToImageRequest()
-
-		// Apply the same dimension and fit-mode bounds as the plain image
-		// route: a sealed payload is trusted for its origin, not for staying
-		// within limits, so an over-limit size or unknown fit mode is a 400
-		// here rather than an out-of-memory or a 500 from the processor.
-		err = imgcache.ValidateImageRequest(req)
-		if err != nil {
-			s.log.Debug("encrypted URL failed validation", "error", err)
-			s.respondError(w, "invalid encrypted URL: "+err.Error(),
-				http.StatusBadRequest)
-
+		req, ok := s.parseImageEncRequest(w, r)
+		if !ok {
 			return
 		}
 
@@ -94,6 +60,17 @@ func (s *Handlers) HandleImageEnc() http.HandlerFunc {
 		w.Header().Set("Cache-Control", cacheControl(req.Expires))
 		w.Header().Set("X-Pixa-Cache", string(resp.CacheStatus))
 
+		if notModified(w, r, resp.ETag) {
+			return
+		}
+
+		// A HEAD request gets the headers only
+		if r.Method == http.MethodHead {
+			w.WriteHeader(http.StatusOK)
+
+			return
+		}
+
 		// Stream the response
 		written, err := io.Copy(w, resp.Content)
 		if err != nil {
@@ -105,6 +82,7 @@ func (s *Handlers) HandleImageEnc() http.HandlerFunc {
 		// Log completion
 		duration := time.Since(start)
 		s.log.Info("image served",
+			"request_id", middleware.GetReqID(ctx),
 			"cache_key", imgcache.CacheKey(req),
 			"host", req.SourceHost,
 			"path", req.SourcePath,
@@ -116,6 +94,56 @@ func (s *Handlers) HandleImageEnc() http.HandlerFunc {
 	}
 }
 
+// parseImageEncRequest decrypts the token of an encrypted image URL into an
+// ImageRequest and checks it. On a token that is missing, does not decrypt,
+// has expired or asks for something not valid, it writes an error response
+// and returns false.
+func (s *Handlers) parseImageEncRequest(
+	w http.ResponseWriter, r *http.Request,
+) (*imgcache.ImageRequest, bool) {
+	// Extract token from URL
+	token := chi.URLParam(r, "token")
+	if token == "" {
+		s.respondError(w, "missing token", http.StatusBadRequest)
+
+		return nil, false
+	}
+
+	// Decrypt and validate the payload
+	payload, err := s.encGen.Parse(token)
+	if err != nil {
+		if errors.Is(err, encurl.ErrExpired) {
+			s.log.Debug("encrypted URL expired", "error", err)
+			s.respondError(w, "URL has expired", http.StatusGone)
+
+			return nil, false
+		}
+
+		s.log.Debug("failed to decrypt URL", "error", err)
+		s.respondError(w, "invalid encrypted URL", http.StatusBadRequest)
+
+		return nil, false
+	}
+
+	// Convert payload to ImageRequest
+	req := payload.ToImageRequest()
+
+	// Apply the same dimension and fit-mode bounds as the plain image
+	// route: a sealed payload is trusted for its origin, not for staying
+	// within limits, so an over-limit size or unknown fit mode is a 400
+	// here rather than an out-of-memory or a 500 from the processor.
+	err = imgcache.ValidateImageRequest(req)
+	if err != nil {
+		s.log.Debug("encrypted URL failed validation", "error", err)
+		s.respondError(w, "invalid encrypted URL: "+err.Error(),
+			http.StatusBadRequest)
+
+		return nil, false
+	}
+
+	return req, true
+}
+
 // handleImageError converts image service errors to HTTP responses.
 func (s *Handlers) handleImageError(w http.ResponseWriter, err error) {
 	switch {

internal/handlers/imageenc_internal_test.go

@@ -96,3 +96,70 @@ func TestHandleImageEnc_InvalidFitMode_Returns400(t *testing.T) {
 		t.Fatalf("status = %d, want %d", rec.Code, http.StatusBadRequest)
 	}
 }
+
+// TestHandleImageEnc_IfNoneMatch_Returns304 verifies that an image served
+// through an encrypted URL carries an ETag, and that a request whose
+// If-None-Match is that ETag is answered 304 Not Modified with no body.
+func TestHandleImageEnc_IfNoneMatch_Returns304(t *testing.T) {
+	t.Parallel()
+
+	h, srv := newSignedHostServer(t, slog.New(slog.DiscardHandler))
+	target := encPhotoURL(t, h)
+
+	rec := httptest.NewRecorder()
+	srv.ServeHTTP(rec, httptest.NewRequestWithContext(
+		t.Context(), http.MethodGet, target, nil))
+
+	etag := rec.Header().Get("ETag")
+	t.Logf("GET: %d, ETag %q", rec.Code, etag)
+
+	if rec.Code != http.StatusOK || etag == "" {
+		t.Fatalf("GET: status = %d, ETag = %q, want %d and an ETag",
+			rec.Code, etag, http.StatusOK)
+	}
+
+	req := httptest.NewRequestWithContext(t.Context(), http.MethodGet, target, nil)
+	req.Header.Set("If-None-Match", etag)
+
+	rec = httptest.NewRecorder()
+	srv.ServeHTTP(rec, req)
+	t.Logf("GET with If-None-Match: %d, %d body bytes", rec.Code, rec.Body.Len())
+
+	if rec.Code != http.StatusNotModified || rec.Body.Len() != 0 {
+		t.Errorf("status = %d with %d body bytes, want %d with none",
+			rec.Code, rec.Body.Len(), http.StatusNotModified)
+	}
+}
+
+// TestHandleImageEnc_HEAD_ReturnsHeadersOnly verifies that HEAD on an
+// encrypted URL is answered 200 with the headers GET sends and no body.
+func TestHandleImageEnc_HEAD_ReturnsHeadersOnly(t *testing.T) {
+	t.Parallel()
+
+	h, _ := newSignedHostServer(t, slog.New(slog.DiscardHandler))
+
+	r := chi.NewRouter()
+	r.Head("/v1/e/{token}/*", h.HandleImageEnc())
+
+	rec := httptest.NewRecorder()
+	r.ServeHTTP(rec, httptest.NewRequestWithContext(
+		t.Context(), http.MethodHead, encPhotoURL(t, h), nil))
+	t.Logf("HEAD: %d, headers %v, %d body bytes",
+		rec.Code, rec.Header(), rec.Body.Len())
+
+	if rec.Code != http.StatusOK {
+		t.Fatalf("status = %d, want %d", rec.Code, http.StatusOK)
+	}
+
+	for _, name := range []string{
+		"Content-Type", "Content-Length", "Cache-Control", "ETag",
+	} {
+		if rec.Header().Get(name) == "" {
+			t.Errorf("HEAD response has no %s", name)
+		}
+	}
+
+	if rec.Body.Len() != 0 {
+		t.Errorf("HEAD response body has %d bytes, want none", rec.Body.Len())
+	}
+}

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