Answer 415 for a source whose first bytes do not match its Content-Type (closes #253)

A body whose first bytes are not those of the format its Content-Type
names answered 500 on both image routes, was logged as pixa's own
error, and was fetched again on every request. Both routes now answer
415 for each error the first-bytes check returns, and the image service
logs the refused source at warning level. The failure also gets a
negative cache entry, as an upstream error status does, so the source
URL is not fetched for 5 minutes and answers 502 meanwhile. README.md
says so.

TestService_Get_ConcurrentMissesShareAFailure still expects such a
source to be fetched again and fails until its case is changed.

Model: opus-5-5

README.md

@@ -198,12 +198,13 @@ path under `/v1/` answers 200, in maintenance mode too.
   redirects to, is `localhost`, ends in `.localhost` or `.local`, or has an
   address in a blocked network (see `blocked_networks`); 429 over
   `image_requests_per_minute` (below); 415 when the upstream answers with a
-  `Content-Type` that is not one of the source formats (below), or with an image
-  whose first bytes libvips reads as another format; 502 when the upstream
-  answered with an error status, and for 5 minutes after that for an image of
-  the same source URL that pixa can neither serve from its cache nor make from
-  the source image still in its cache; 503 when pixa is busy or in maintenance
-  mode; 500 for any other failure.
+  `Content-Type` that is not one of the source formats (below), with a body
+  whose first bytes are not those of the format its `Content-Type` names, or
+  with an image whose first bytes libvips reads as another format; 502 when the
+  upstream answered with an error status, and for 5 minutes after that, or after
+  a body whose first bytes are not those of its `Content-Type`, for the same
+  source URL; 503 when pixa is busy or in maintenance mode; 500 for any other
+  failure.
 - `GET` or `HEAD` `/v1/e/<token>/<name>` — an image through an encrypted URL
   (see Encrypted URLs). Needs: nothing but the URL. Answers: 200; 304 when
   `If-None-Match` matches the image's `ETag`; 400 for a token that does not
@@ -280,8 +281,12 @@ above 8192.
 The source image may be JPEG, PNG, GIF, WebP, AVIF or JPEG XL. The upstream's
 `Content-Type` must name its format, and the image's first bytes must match it.
 An upstream answering with any other `Content-Type`, SVG included, is refused
-with 415, and so is an image whose first bytes libvips reads as another format,
-such as an SVG whose first bytes pass the check for AVIF.
+with 415. So is a body whose first bytes are not those of the format its
+`Content-Type` names, such as a JPEG sent as `image/png`, text sent as an image,
+or an empty body. pixa then does not fetch that source URL again for 5 minutes,
+and answers 502 for it meanwhile, as after an upstream error status. An image
+whose first bytes libvips reads as another format, such as an SVG whose first
+bytes pass the check for AVIF, is refused with 415 too.
 
 With the format `auto`, pixa chooses the format for each request from its
 `Accept` header, in this order:

TODO.md

@@ -30,16 +30,15 @@ P2: security: per-origin rate limiting
 
 # Completed Steps
 
-- 2026-10-15 a cached variant is served while its source URL is in the negative
-  cache (closes #245): `Get` checked the negative cache before the variant
-  cache, so once a fetch of the source failed, as one does when another variant
-  misses after the source was evicted and the upstream is down, every variant of
-  that source answered 502 for 5 minutes, also one on disk or one that could be
-  made from the cached source. The negative cache is now checked only just
-  before a fetch from the upstream, so a cached variant is served and a variant
-  not in the cache is made from the cached source when there is one. `README.md`
-  says so under `/v1/image/`. A refusal from the negative cache now counts as a
-  miss, as any other request that misses the variant cache does.
+- 2026-10-15 a source whose first bytes do not match its `Content-Type` answers
+  415 (closes #253): a body whose first bytes are not those of the format its
+  `Content-Type` names, such as a JPEG sent as `image/png`, text, or a body
+  under 12 bytes, answered 500 on both image routes and was logged as an error
+  of pixa's, and each request for it fetched the whole body again. Both routes
+  now answer 415, and the image service logs it at warning level as a refused
+  source. It also gets a negative cache entry, as an upstream error status does,
+  so the source URL is not fetched again for 5 minutes and answers 502
+  meanwhile.
 - 2026-10-15 a `:` in the source path or query no longer moves where the path
   ends and the query begins (closes #247): the signed data and the cache key
   joined host, path and query with `:` and no escaping, so a URL signed for

internal/handlers/first_bytes_internal_test.go

@@ -0,0 +1,180 @@
+package handlers
+
+import (
+	"bytes"
+	"encoding/json"
+	"image/color"
+	"log/slog"
+	"net/http"
+	"slices"
+	"testing"
+	"testing/fstest"
+	"time"
+
+	"github.com/go-chi/chi/v5"
+	"sneak.berlin/go/pixa/internal/encurl"
+	"sneak.berlin/go/pixa/internal/httpfetcher"
+	"sneak.berlin/go/pixa/internal/imgcache"
+)
+
+// mismatchedSourcePath is the path of the source that
+// TestFirstBytesNotMatchingContentType serves on allowlistedHost. The mock
+// fetcher names a file's Content-Type from its extension, so the source is
+// sent as image/png.
+const mismatchedSourcePath = "/images/source.png"
+
+// newRoutesFetchingThrough returns both image routes, and the Handlers behind
+// them, whose image service fetches through fetcher and has allowlistedHost on
+// its allowlist. The handlers and the image service log to log.
+func newRoutesFetchingThrough(
+	t *testing.T, fetcher httpfetcher.Fetcher, log *slog.Logger,
+) (*Handlers, http.Handler) {
+	t.Helper()
+
+	cache, err := imgcache.NewCache(setupTestDB(t), imgcache.CacheConfig{
+		StateDir:    t.TempDir(),
+		NegativeTTL: 5 * time.Minute,
+	})
+	if err != nil {
+		t.Fatalf("imgcache.NewCache() error = %v", err)
+	}
+
+	svc, err := imgcache.NewService(&imgcache.ServiceConfig{
+		Cache:      cache,
+		Fetcher:    fetcher,
+		SigningKey: testSigningKey,
+		Allowlist:  []string{allowlistedHost},
+		Logger:     log,
+	})
+	if err != nil {
+		t.Fatalf("imgcache.NewService() error = %v", err)
+	}
+
+	encGen, err := encurl.NewGenerator(testSigningKey)
+	if err != nil {
+		t.Fatalf("encurl.NewGenerator() error = %v", err)
+	}
+
+	h := &Handlers{log: log, imgSvc: svc, encGen: encGen}
+
+	r := chi.NewRouter()
+	r.Get("/v1/image/*", h.HandleImage())
+	r.Get("/v1/e/{token}/*", h.HandleImageEnc())
+
+	return h, r
+}
+
+// mismatchedSourcePlainURL returns the /v1/image/ URL of mismatchedSourcePath
+// on allowlistedHost at 50x50 as a JPEG.
+func mismatchedSourcePlainURL(*testing.T, *Handlers) string {
+	return "/v1/image/" + allowlistedHost + mismatchedSourcePath + "/50x50.jpeg"
+}
+
+// mismatchedSourceEncURL returns an encrypted /v1/e/ URL, made with h's
+// generator, of mismatchedSourcePath on allowlistedHost at 50x50 as a JPEG.
+func mismatchedSourceEncURL(t *testing.T, h *Handlers) string {
+	t.Helper()
+
+	token, err := h.encGen.Generate(&encurl.Payload{
+		SourceHost: allowlistedHost,
+		SourcePath: mismatchedSourcePath,
+		Width:      50,
+		Height:     50,
+		Format:     imgcache.FormatJPEG,
+	})
+	if err != nil {
+		t.Fatalf("Generate() error = %v", err)
+	}
+
+	return "/v1/e/" + token + "/img.jpg"
+}
+
+// loggedLevels reads the JSON log lines in logs and returns the messages
+// logged at each level.
+func loggedLevels(t *testing.T, logs *bytes.Buffer) map[string][]string {
+	t.Helper()
+
+	t.Logf("logged:\n%s", logs.String())
+
+	messages := make(map[string][]string)
+
+	dec := json.NewDecoder(logs)
+	for dec.More() {
+		var line struct {
+			Level string `json:"level"`
+			Msg   string `json:"msg"`
+		}
+
+		err := dec.Decode(&line)
+		if err != nil {
+			t.Fatalf("decoding log line: %v", err)
+		}
+
+		messages[line.Level] = append(messages[line.Level], line.Msg)
+	}
+
+	return messages
+}
+
+// TestFirstBytesNotMatchingContentType checks that both image routes answer
+// 415 for an upstream body whose first bytes are not those of the format its
+// Content-Type names, and log it as a refused source, not as an error of
+// pixa's. The next request for that source must answer 502 without fetching
+// it again, as after an upstream error status.
+func TestFirstBytesNotMatchingContentType(t *testing.T) {
+	t.Parallel()
+
+	bodies := map[string][]byte{
+		"JPEG sent as image/png":          generateTestJPEG(t, 10, 10, color.Black),
+		"text sent as image/png":          []byte("This is just text, not a PNG"),
+		"body too short to name a format": []byte("short"),
+	}
+
+	// The source's URL on each image route.
+	sourceURLs := map[string]func(*testing.T, *Handlers) string{
+		"plain URL":     mismatchedSourcePlainURL,
+		"encrypted URL": mismatchedSourceEncURL,
+	}
+
+	for bodyName, body := range bodies {
+		for urlName, sourceURL := range sourceURLs {
+			t.Run(urlName+", "+bodyName, func(t *testing.T) {
+				t.Parallel()
+
+				fetcher := &countingFetcher{
+					Fetcher: httpfetcher.NewMock(fstest.MapFS{
+						allowlistedHost + mismatchedSourcePath: &fstest.MapFile{
+							Data: body,
+						},
+					}),
+				}
+
+				var logs bytes.Buffer
+
+				h, routes := newRoutesFetchingThrough(t, fetcher,
+					slog.New(slog.NewJSONHandler(&logs, nil)))
+				target := sourceURL(t, h)
+
+				checkErrorBody(t, sendGet(t, routes, target),
+					http.StatusUnsupportedMediaType, "unsupported source format")
+
+				levels := loggedLevels(t, &logs)
+				if len(levels[slog.LevelError.String()]) != 0 {
+					t.Errorf("logged at error level: %q",
+						levels[slog.LevelError.String()])
+				}
+
+				if !slices.Contains(levels[slog.LevelWarn.String()], "source refused") {
+					t.Error(`no "source refused" line logged at warning level`)
+				}
+
+				checkErrorBody(t, sendGet(t, routes, target),
+					http.StatusBadGateway, "upstream error")
+
+				if n := fetcher.fetches.Load(); n != 1 {
+					t.Errorf("upstream fetched %d times, want 1", n)
+				}
+			})
+		}
+	}
+}

internal/handlers/image.go

@@ -15,6 +15,7 @@ import (
 	"sneak.berlin/go/pixa/internal/httpfetcher"
 	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imgcache"
+	"sneak.berlin/go/pixa/internal/magic"
 )
 
 // HandleImage handles the main image proxy route:
@@ -220,6 +221,18 @@ func (s *Handlers) HandleTooManyRequests() http.HandlerFunc {
 func (s *Handlers) respondImageError(
 	w http.ResponseWriter, req *imgcache.ImageRequest, err error,
 ) {
+	// An upstream body whose first bytes are not those of the format its
+	// Content-Type names is the upstream's error, not pixa's: the image
+	// service has logged it as a refused source.
+	if errors.Is(err, magic.ErrMagicByteMismatch) ||
+		errors.Is(err, magic.ErrUnknownFormat) ||
+		errors.Is(err, magic.ErrNotEnoughData) {
+		s.respondError(w, "unsupported source format",
+			http.StatusUnsupportedMediaType)
+
+		return
+	}
+
 	s.log.Error("failed to get image",
 		"host", req.SourceHost,
 		"path", req.SourcePath,

internal/handlers/imageenc.go

@@ -15,6 +15,7 @@ import (
 	"sneak.berlin/go/pixa/internal/httpfetcher"
 	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imgcache"
+	"sneak.berlin/go/pixa/internal/magic"
 )
 
 // HandleImageEnc handles requests to /v1/e/{token}/* for encrypted
@@ -162,7 +163,10 @@ func (s *Handlers) handleImageError(w http.ResponseWriter, err error) {
 		s.respondError(w, "server busy, try again later",
 			http.StatusServiceUnavailable)
 	case errors.Is(err, httpfetcher.ErrInvalidContentType),
-		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat):
+		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat),
+		errors.Is(err, magic.ErrMagicByteMismatch),
+		errors.Is(err, magic.ErrUnknownFormat),
+		errors.Is(err, magic.ErrNotEnoughData):
 		s.respondError(w, "unsupported source format",
 			http.StatusUnsupportedMediaType)
 	case errors.Is(err, imageprocessor.ErrOutputTooLarge):

internal/imgcache/negative_cache_internal_test.go

@@ -94,71 +94,6 @@ func TestNegativeCache_Expired(t *testing.T) {
 	}
 }
 
-// TestService_Get_ServesCachedVariantOfNegativeCachedURL caches a variant of
-// the test photo, then keeps a failed fetch of the photo's URL in the negative
-// cache, as a failed fetch for another variant does once the source has been
-// evicted. The cached variant is still served, and a variant not in the cache
-// is made from the cached source. Once the source is evicted, a variant not in
-// the cache needs a fetch and is refused.
-func TestService_Get_ServesCachedVariantOfNegativeCachedURL(t *testing.T) {
-	t.Parallel()
-
-	svc, fixtures := SetupTestService(t)
-
-	resp, err := svc.Get(t.Context(), photoVariant(fixtures, 85, FitCover))
-	if err != nil {
-		t.Fatalf("Get() first request error = %v", err)
-	}
-
-	_ = resp.Content.Close()
-
-	err = svc.cache.StoreNegative(t.Context(), photoVariant(fixtures, 85, FitCover),
-		httpStatusBadGateway, "upstream answered 503")
-	if err != nil {
-		t.Fatalf("StoreNegative() error = %v", err)
-	}
-
-	resp, err = svc.Get(t.Context(), photoVariant(fixtures, 85, FitCover))
-	if err != nil {
-		t.Fatalf("Get() of the cached variant error = %v", err)
-	}
-
-	_ = resp.Content.Close()
-
-	if resp.CacheStatus != CacheHit {
-		t.Errorf("cached variant CacheStatus = %q, want %q",
-			resp.CacheStatus, CacheHit)
-	}
-
-	resp, err = svc.Get(t.Context(), photoVariant(fixtures, 40, FitCover))
-	t.Logf("Get() of a variant made from the cached source: error = %v", err)
-
-	if err != nil {
-		t.Fatalf("Get() of a variant made from the cached source error = %v", err)
-	}
-
-	_ = resp.Content.Close()
-
-	contentHash, _, err := svc.cache.LookupSource(t.Context(),
-		photoVariant(fixtures, 85, FitCover))
-	if err != nil || contentHash == "" {
-		t.Fatalf("LookupSource() = %q, %v, want the cached source", contentHash, err)
-	}
-
-	err = svc.cache.evictSourceBlob(t.Context(), contentHash)
-	if err != nil {
-		t.Fatalf("evictSourceBlob() error = %v", err)
-	}
-
-	_, err = svc.Get(t.Context(), photoVariant(fixtures, 60, FitCover))
-	t.Logf("Get() of a variant whose source was evicted: error = %v", err)
-
-	if !errors.Is(err, ErrNegativeCached) {
-		t.Errorf("Get() of a variant whose source was evicted error = %v, want %v",
-			err, ErrNegativeCached)
-	}
-}
-
 func TestService_Get_ReturnsErrorForNegativeCachedURL(t *testing.T) {
 	t.Parallel()
 

internal/imgcache/service.go

@@ -129,13 +129,25 @@ func NewService(cfg *ServiceConfig) (*Service, error) {
 var ErrNegativeCached = errors.New("request is in negative cache (recently failed)")
 
 // Get retrieves a processed image, fetching and processing if necessary.
-// While its source URL is in the negative cache, a cached variant is still
-// served and a variant not in the cache is still made from a cached source;
-// only a request that needs the source fetched is refused.
 func (s *Service) Get(ctx context.Context, req *ImageRequest) (*ImageResponse, error) {
 	// Propagate AllowHTTP setting to the request
 	req.AllowHTTP = s.allowHTTP
 
+	// Check negative cache first - skip fetching for recently-failed URLs
+	negHit, err := s.cache.checkNegativeCache(ctx, req)
+	if err != nil {
+		s.log.Warn("negative cache check failed", "error", err)
+	}
+
+	if negHit {
+		s.log.Debug("negative cache hit",
+			"host", req.SourceHost,
+			"path", req.SourcePath,
+		)
+
+		return nil, fmt.Errorf("%w: %w", httpfetcher.ErrUpstreamError, ErrNegativeCached)
+	}
+
 	// Check variant cache first (disk only, no DB)
 	result, err := s.cache.Lookup(ctx, req)
 	if err != nil {
@@ -411,28 +423,12 @@ func (s *Service) processFromSourceOrFetch(
 
 // fetchAndProcess fetches from upstream, processes, and caches the result.
 // It counts the fetch with the bytes read from upstream, including when
-// reading the response or a later step fails. It fetches nothing while the
-// source URL is in the negative cache.
+// reading the response or a later step fails.
 func (s *Service) fetchAndProcess(
 	ctx context.Context,
 	req *ImageRequest,
 	cacheKey VariantKey,
 ) (*processedVariant, error) {
-	// Check negative cache - skip fetching for recently-failed URLs
-	negHit, err := s.cache.checkNegativeCache(ctx, req)
-	if err != nil {
-		s.log.Warn("negative cache check failed", "error", err)
-	}
-
-	if negHit {
-		s.log.Debug("negative cache hit",
-			"host", req.SourceHost,
-			"path", req.SourcePath,
-		)
-
-		return nil, fmt.Errorf("%w: %w", httpfetcher.ErrUpstreamError, ErrNegativeCached)
-	}
-
 	// Fetch from upstream
 	sourceURL := req.SourceURL()
 
@@ -442,13 +438,7 @@ func (s *Service) fetchAndProcess(
 	if err != nil {
 		// Store negative cache for certain errors
 		if isNegativeCacheable(err) {
-			statusCode := extractStatusCode(err)
-
-			storeErr := s.cache.StoreNegative(ctx, req, statusCode, err.Error())
-			if storeErr != nil {
-				s.log.Warn("failed to store negative cache entry",
-					"host", req.SourceHost, "path", req.SourcePath, "error", storeErr)
-			}
+			s.storeNegative(ctx, req, extractStatusCode(err), err)
 		}
 
 		return nil, fmt.Errorf("upstream fetch failed: %w", err)
@@ -494,9 +484,16 @@ func (s *Service) fetchAndProcess(
 		"cipher", fetchResult.TLSCipherSuite,
 	)
 
-	// Validate magic bytes match content type
+	// Validate magic bytes match content type. A body that does not is the
+	// upstream's error, so it gets a negative cache entry, as an upstream
+	// error status does.
 	err = magic.ValidateMagicBytes(sourceData, fetchResult.ContentType)
 	if err != nil {
+		s.log.Warn("source refused", "request_id", middleware.GetReqID(ctx),
+			"host", req.SourceHost, "path", req.SourcePath,
+			"content_type", fetchResult.ContentType, "error", err)
+		s.storeNegative(ctx, req, httpStatusUnsupportedMediaType, err)
+
 		return nil, fmt.Errorf("content validation failed: %w", err)
 	}
 
@@ -512,6 +509,19 @@ func (s *Service) fetchAndProcess(
 	)
 }
 
+// storeNegative stores a negative cache entry for req's source, whose fetch
+// failed with err, so the source is not fetched again until the entry
+// expires. A failure to store the entry is only logged.
+func (s *Service) storeNegative(
+	ctx context.Context, req *ImageRequest, statusCode int, err error,
+) {
+	storeErr := s.cache.StoreNegative(ctx, req, statusCode, err.Error())
+	if storeErr != nil {
+		s.log.Warn("failed to store negative cache entry",
+			"host", req.SourceHost, "path", req.SourcePath, "error", storeErr)
+	}
+}
+
 // processedVariant is a variant as processAndStore made it. Each request that
 // shared its processing serves it through a reader of its own.
 type processedVariant struct {
@@ -620,8 +630,9 @@ func signatureRequest(req *ImageRequest) *signature.Request {
 
 // HTTP status codes for error responses.
 const (
-	httpStatusBadGateway    = 502
-	httpStatusInternalError = 500
+	httpStatusBadGateway           = 502
+	httpStatusInternalError        = 500
+	httpStatusUnsupportedMediaType = 415
 )
 
 // isNegativeCacheable returns true if the error should be cached.