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,9 +198,11 @@ 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 the same
+  `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
@@ -279,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,6 +30,15 @@ P2: security: per-origin rate limiting
 
 # Completed Steps
 
+- 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
@@ -38,17 +47,6 @@ P2: security: per-origin rate limiting
   and the query now have each `%` written as `%25` and each `:` as `%3A`; a path
   and query holding neither are signed and keyed as before. Signature
   Specification in `README.md` says so.
-- 2026-10-15 expired negative cache rows are removed on a schedule (closes
-  #244): the row of a failed fetch, which makes pixa answer 502 for that source
-  URL for 5 minutes, was deleted only when the same URL was requested again
-  after that, so a client asking for a new missing path each time added rows
-  that stayed for good. The eviction goroutine now calls `CleanExpired` at
-  startup and on each periodic tick, every 5 minutes in pixad, so a row stays at
-  most about 10 minutes. `CleanExpired` deletes at most 1000 rows per statement,
-  so a request waits behind 1000 deletions at most, however many rows have
-  expired. The goroutine runs with the disk cache disabled
-  (`cache_max_bytes: 0`) too, where it does nothing else, as the negative cache
-  is used either way.
 - 2026-10-15 the example config allowlists no host (closes #249): it allowlisted
   `github.com` and `user-images.githubusercontent.com`, where anyone can put an
   image, so a deployment set up as Getting Started says served those images to

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

@@ -124,8 +124,7 @@ func (s *Handlers) initImageService() error {
 	s.imgCache = cache
 
 	// Background eviction: startup reconciliation, then periodic and
-	// write-pressure passes, and the removal of expired negative cache
-	// rows, which is all it does when the disk cache is disabled.
+	// write-pressure passes. No-op when the disk cache is disabled.
 	cache.StartEviction(imgcache.DefaultEvictionInterval)
 
 	// Writes the counts requests could not write by their deadline

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

@@ -32,12 +32,6 @@ const httpStatusOK = 200
 // variant not among them is served as before, reading its .meta file.
 const metaCacheSize = 10000
 
-// cleanExpiredBatchSize is the most expired negative cache rows one
-// statement of CleanExpired deletes. Each batch is a statement of its
-// own, so a request waits behind one batch at most, however many rows
-// have expired.
-const cleanExpiredBatchSize = 1000
-
 // CacheConfig holds cache configuration.
 type CacheConfig struct {
 	StateDir    string
@@ -56,9 +50,8 @@ type CacheConfig struct {
 
 	// DisableDiskCache turns the disk cache off entirely: no cache
 	// directories are created, lookups always miss, stores are
-	// no-ops, and the eviction goroutine only removes the expired
-	// negative cache rows. The config layer sets this when the
-	// operator configures cache_max_bytes: 0.
+	// no-ops, and no eviction machinery runs. The config layer sets
+	// this when the operator configures cache_max_bytes: 0.
 	DisableDiskCache bool
 
 	// Logger receives accounting and eviction log output. A nil
@@ -489,27 +482,17 @@ func (c *Cache) GetSourceContent(
 	return c.srcContent.LoadWithSize(contentHash)
 }
 
-// CleanExpired removes the negative cache rows past their expiry, one
-// batch per statement, until none is left. Once ctx ends it starts no
-// further batch and returns ctx's error. The eviction goroutine calls it
-// at startup and on every periodic tick, so a row stays about
-// NegativeTTL plus one eviction interval, whether or not its URL is
-// requested again.
+// CleanExpired removes expired entries from the cache.
 func (c *Cache) CleanExpired(ctx context.Context) error {
-	for {
-		if ctx.Err() != nil {
-			return ctx.Err()
-		}
-
-		deleted, err := c.cleanExpiredBatch(ctx)
-		if err != nil {
-			return err
-		}
-
-		if deleted < cleanExpiredBatchSize {
-			return nil
-		}
+	// Clean expired negative cache entries
+	_, err := c.db.ExecContext(ctx, `
+		DELETE FROM negative_cache WHERE expires_at < CURRENT_TIMESTAMP
+	`)
+	if err != nil {
+		return fmt.Errorf("failed to clean negative cache: %w", err)
 	}
+
+	return nil
 }
 
 // Stats returns cache statistics.
@@ -773,27 +756,3 @@ func (c *Cache) checkNegativeCache(
 
 	return true, nil
 }
-
-// cleanExpiredBatch deletes up to cleanExpiredBatchSize negative cache
-// rows past their expiry in one statement, and returns how many it
-// deleted. DELETE ... LIMIT needs a SQLite build option, so the subquery
-// picks the rows.
-func (c *Cache) cleanExpiredBatch(ctx context.Context) (int64, error) {
-	result, err := c.db.ExecContext(ctx, `
-		DELETE FROM negative_cache WHERE id IN (
-			SELECT id FROM negative_cache
-			WHERE expires_at < CURRENT_TIMESTAMP
-			LIMIT ?
-		)
-	`, cleanExpiredBatchSize)
-	if err != nil {
-		return 0, fmt.Errorf("failed to clean negative cache: %w", err)
-	}
-
-	deleted, err := result.RowsAffected()
-	if err != nil {
-		return 0, fmt.Errorf("failed to count cleaned negative cache rows: %w", err)
-	}
-
-	return deleted, nil
-}

internal/imgcache/eviction.go

@@ -437,16 +437,14 @@ func (c *Cache) notifyWritePressure() {
 }
 
 // StartEviction launches the background eviction goroutine, which
-// reconciles the database accounting with the cache directories and
-// removes the expired negative cache rows at startup and again on every
-// periodic tick thereafter, and evicts to the configured limit on the
-// given periodic interval and on write-pressure notifications. On a
-// disabled cache it only removes the expired negative cache rows, as
-// the negative cache is used either way. It is a no-op when already
-// started. The goroutine outlives the caller, so it runs with its own
-// context, which StopEviction cancels.
+// reconciles the database accounting with the cache directories at
+// startup and again on every periodic tick thereafter, and evicts to
+// the configured limit on the given periodic interval and on
+// write-pressure notifications. It is a no-op on a disabled cache or
+// when already started. The goroutine outlives the caller, so it runs
+// with its own context, which StopEviction cancels.
 func (c *Cache) StartEviction(interval time.Duration) {
-	if c.evictionCancel != nil {
+	if c.disabled || c.evictionCancel != nil {
 		return
 	}
 
@@ -482,7 +480,6 @@ func (c *Cache) evictionLoop(ctx context.Context, interval time.Duration) {
 	defer close(c.evictionDone)
 
 	c.runReconciliationPass(ctx)
-	c.runCleanExpired(ctx)
 	c.runEvictionPass(ctx)
 
 	ticker := time.NewTicker(interval)
@@ -503,7 +500,6 @@ func (c *Cache) evictionLoop(ctx context.Context, interval time.Duration) {
 			// unaccounted for to one interval, on a process that is
 			// already running this loop regardless.
 			c.runReconciliationPass(ctx)
-			c.runCleanExpired(ctx)
 		case <-c.evictionPressure:
 		}
 
@@ -539,20 +535,6 @@ func (c *Cache) runReconciliationPass(ctx context.Context) {
 	}
 }
 
-// runCleanExpired runs CleanExpired, logging a failure instead of
-// propagating it (the loop must keep running). It does nothing once ctx
-// is cancelled.
-func (c *Cache) runCleanExpired(ctx context.Context) {
-	if ctx.Err() != nil {
-		return
-	}
-
-	err := c.CleanExpired(ctx)
-	if err != nil {
-		c.log.Warn("negative cache cleanup failed", "error", err)
-	}
-}
-
 // reconcileAccounting synchronizes the database size accounting with
 // the actual contents of the cache directories. It runs at startup and
 // again on every periodic eviction tick thereafter, off the request

internal/imgcache/negative_cache_internal_test.go

@@ -3,7 +3,6 @@ package imgcache
 import (
 	"context"
 	"errors"
-	"strconv"
 	"testing"
 	"time"
 )
@@ -95,242 +94,6 @@ func TestNegativeCache_Expired(t *testing.T) {
 	}
 }
 
-// TestEvictionLoopRemovesExpiredNegativeCacheRows stores a failed fetch
-// that expires a second later and starts the eviction loop with a short
-// interval: a later tick must remove its row although its URL is never
-// requested again, and must keep a row that has not expired. It runs
-// with the disk cache enabled and disabled, as the negative cache is
-// used either way.
-func TestEvictionLoopRemovesExpiredNegativeCacheRows(t *testing.T) {
-	t.Parallel()
-
-	tests := []struct {
-		name             string
-		disableDiskCache bool
-	}{
-		{name: "disk cache enabled", disableDiskCache: false},
-		{name: "disk cache disabled", disableDiskCache: true},
-	}
-
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			t.Parallel()
-
-			cache, err := NewCache(evictionTestDB(t), CacheConfig{
-				StateDir:         t.TempDir(),
-				NegativeTTL:      time.Second,
-				DisableDiskCache: tt.disableDiskCache,
-			})
-			if err != nil {
-				t.Fatalf("failed to create cache: %v", err)
-			}
-
-			expired := &ImageRequest{
-				SourceHost: testHostExample, SourcePath: "/gone.jpg",
-			}
-
-			err = cache.StoreNegative(t.Context(), expired, 404, "not found")
-			if err != nil {
-				t.Fatalf("StoreNegative failed: %v", err)
-			}
-
-			const notExpiredPath = "/later.jpg"
-
-			_, err = cache.db.ExecContext(t.Context(), `
-				INSERT INTO negative_cache
-					(source_host, source_path, status_code, expires_at)
-				VALUES (?, ?, 404, datetime('now', '+1 hour'))
-			`, testHostExample, notExpiredPath)
-			if err != nil {
-				t.Fatalf("failed to insert a row that has not expired: %v", err)
-			}
-
-			started := time.Now()
-
-			cache.StartEviction(100 * time.Millisecond)
-			defer func() { _ = cache.StopEviction(t.Context()) }()
-
-			for negativeCacheRowCount(t, cache, expired.SourcePath) > 0 {
-				if time.Since(started) > 10*time.Second {
-					t.Fatal("the expired row is still in negative_cache")
-				}
-
-				time.Sleep(50 * time.Millisecond)
-			}
-
-			t.Logf("the expired row was removed %s after the loop started",
-				time.Since(started))
-
-			if negativeCacheRowCount(t, cache, notExpiredPath) != 1 {
-				t.Error("the row that has not expired was removed")
-			}
-		})
-	}
-}
-
-// negativeCacheRowCount returns how many negative_cache rows hold
-// sourcePath.
-func negativeCacheRowCount(tb testing.TB, cache *Cache, sourcePath string) int {
-	tb.Helper()
-
-	var count int
-
-	err := cache.db.QueryRowContext(tb.Context(),
-		`SELECT COUNT(*) FROM negative_cache WHERE source_path = ?`,
-		sourcePath,
-	).Scan(&count)
-	if err != nil {
-		tb.Fatalf("failed to count negative_cache rows: %v", err)
-	}
-
-	return count
-}
-
-// TestCleanExpiredDeletesInBatches stores one expired negative cache row
-// more than one batch holds, and one row that has not expired. One
-// statement must delete one batch and no more, so a request waits behind
-// one batch at most; CleanExpired must then remove the expired row left
-// over and keep the row that has not expired.
-func TestCleanExpiredDeletesInBatches(t *testing.T) {
-	t.Parallel()
-
-	cache, err := NewCache(evictionTestDB(t), CacheConfig{StateDir: t.TempDir()})
-	if err != nil {
-		t.Fatalf("failed to create cache: %v", err)
-	}
-
-	ctx := t.Context()
-
-	insertExpiredNegativeCacheRows(t, cache, cleanExpiredBatchSize+1)
-
-	const notExpiredPath = "/later.jpg"
-
-	_, err = cache.db.ExecContext(ctx, `
-		INSERT INTO negative_cache
-			(source_host, source_path, status_code, expires_at)
-		VALUES (?, ?, 404, datetime('now', '+1 hour'))
-	`, testHostExample, notExpiredPath)
-	if err != nil {
-		t.Fatalf("failed to insert a row that has not expired: %v", err)
-	}
-
-	deleted, err := cache.cleanExpiredBatch(ctx)
-	if err != nil {
-		t.Fatalf("cleanExpiredBatch failed: %v", err)
-	}
-
-	t.Logf("one statement deleted %d of %d expired rows",
-		deleted, cleanExpiredBatchSize+1)
-
-	if deleted != cleanExpiredBatchSize {
-		t.Errorf("one statement deleted %d rows, want %d",
-			deleted, cleanExpiredBatchSize)
-	}
-
-	err = cache.CleanExpired(ctx)
-	if err != nil {
-		t.Fatalf("CleanExpired failed: %v", err)
-	}
-
-	if count := negativeCacheTableRowCount(t, cache); count != 1 {
-		t.Errorf("negative_cache holds %d rows after CleanExpired, want 1", count)
-	}
-
-	if negativeCacheRowCount(t, cache, notExpiredPath) != 1 {
-		t.Error("the row that has not expired was removed")
-	}
-}
-
-// TestCleanExpiredRemovesMoreThanOneBatch stores one expired negative
-// cache row more than one batch holds and calls CleanExpired once: it
-// must remove them all, so it fails if CleanExpired stops after its
-// first batch.
-func TestCleanExpiredRemovesMoreThanOneBatch(t *testing.T) {
-	t.Parallel()
-
-	cache, err := NewCache(evictionTestDB(t), CacheConfig{StateDir: t.TempDir()})
-	if err != nil {
-		t.Fatalf("failed to create cache: %v", err)
-	}
-
-	insertExpiredNegativeCacheRows(t, cache, cleanExpiredBatchSize+1)
-
-	before := negativeCacheTableRowCount(t, cache)
-
-	err = cache.CleanExpired(t.Context())
-	if err != nil {
-		t.Fatalf("CleanExpired failed: %v", err)
-	}
-
-	after := negativeCacheTableRowCount(t, cache)
-
-	t.Logf("CleanExpired removed %d of %d expired rows, %d per batch",
-		before-after, before, cleanExpiredBatchSize)
-
-	if after != 0 {
-		t.Errorf("negative_cache holds %d rows after CleanExpired, want 0", after)
-	}
-}
-
-// TestCleanExpiredStopsOnceContextEnds runs CleanExpired with a context
-// that has already ended: it must return the context's error and delete
-// no row.
-func TestCleanExpiredStopsOnceContextEnds(t *testing.T) {
-	t.Parallel()
-
-	cache, err := NewCache(evictionTestDB(t), CacheConfig{StateDir: t.TempDir()})
-	if err != nil {
-		t.Fatalf("failed to create cache: %v", err)
-	}
-
-	insertExpiredNegativeCacheRows(t, cache, 1)
-
-	ctx, cancel := context.WithCancel(t.Context())
-	cancel()
-
-	err = cache.CleanExpired(ctx)
-	if !errors.Is(err, context.Canceled) {
-		t.Errorf("CleanExpired() error = %v, want context.Canceled", err)
-	}
-
-	if count := negativeCacheTableRowCount(t, cache); count != 1 {
-		t.Errorf("negative_cache holds %d rows, want the expired row kept", count)
-	}
-}
-
-// insertExpiredNegativeCacheRows inserts count negative_cache rows that
-// expired an hour ago, each for a different source path.
-func insertExpiredNegativeCacheRows(t *testing.T, cache *Cache, count int) {
-	t.Helper()
-
-	for i := range count {
-		_, err := cache.db.ExecContext(t.Context(), `
-			INSERT INTO negative_cache
-				(source_host, source_path, status_code, expires_at)
-			VALUES (?, ?, 404, datetime('now', '-1 hour'))
-		`, testHostExample, "/expired/"+strconv.Itoa(i)+".jpg")
-		if err != nil {
-			t.Fatalf("failed to insert an expired row: %v", err)
-		}
-	}
-}
-
-// negativeCacheTableRowCount returns how many rows negative_cache holds.
-func negativeCacheTableRowCount(tb testing.TB, cache *Cache) int {
-	tb.Helper()
-
-	var count int
-
-	err := cache.db.QueryRowContext(tb.Context(),
-		`SELECT COUNT(*) FROM negative_cache`,
-	).Scan(&count)
-	if err != nil {
-		tb.Fatalf("failed to count negative_cache rows: %v", err)
-	}
-
-	return count
-}
-
 func TestService_Get_ReturnsErrorForNegativeCachedURL(t *testing.T) {
 	t.Parallel()
 

internal/imgcache/service.go

@@ -438,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)
@@ -490,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)
 	}
 
@@ -508,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 {
@@ -616,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.