Check the negative cache only before a fetch from the upstream (closes #245)

The check moves from Get to the start of fetchAndProcess, so a variant
not in the cache is still made from a cached source while the URL is in
the negative cache. A refusal now counts as a miss.

Model: opus-5-5

README.md

@@ -198,13 +198,12 @@ 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), 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.
+  `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.
 - `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
@@ -281,12 +280,8 @@ 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. 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 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 the format `auto`, pixa chooses the format for each request from its
 `Accept` header, in this order:

TODO.md

@@ -30,15 +30,16 @@ 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 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 `:` 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

@@ -1,180 +0,0 @@
-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,7 +15,6 @@ 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:
@@ -221,18 +220,6 @@ 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,7 +15,6 @@ 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
@@ -163,10 +162,7 @@ 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, magic.ErrMagicByteMismatch),
-		errors.Is(err, magic.ErrUnknownFormat),
-		errors.Is(err, magic.ErrNotEnoughData):
+		errors.Is(err, imageprocessor.ErrUnsupportedInputFormat):
 		s.respondError(w, "unsupported source format",
 			http.StatusUnsupportedMediaType)
 	case errors.Is(err, imageprocessor.ErrOutputTooLarge):

internal/imgcache/negative_cache_internal_test.go

@@ -94,6 +94,71 @@ 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,25 +129,13 @@ 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 {
@@ -423,12 +411,28 @@ 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.
+// reading the response or a later step fails. It fetches nothing while the
+// source URL is in the negative cache.
 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()
 
@@ -438,7 +442,13 @@ func (s *Service) fetchAndProcess(
 	if err != nil {
 		// Store negative cache for certain errors
 		if isNegativeCacheable(err) {
-			s.storeNegative(ctx, req, extractStatusCode(err), 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)
+			}
 		}
 
 		return nil, fmt.Errorf("upstream fetch failed: %w", err)
@@ -484,16 +494,9 @@ func (s *Service) fetchAndProcess(
 		"cipher", fetchResult.TLSCipherSuite,
 	)
 
-	// 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.
+	// Validate magic bytes match content type
 	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)
 	}
 
@@ -509,19 +512,6 @@ 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 {
@@ -630,9 +620,8 @@ func signatureRequest(req *ImageRequest) *signature.Request {
 
 // HTTP status codes for error responses.
 const (
-	httpStatusBadGateway           = 502
-	httpStatusInternalError        = 500
-	httpStatusUnsupportedMediaType = 415
+	httpStatusBadGateway    = 502
+	httpStatusInternalError = 500
 )
 
 // isNegativeCacheable returns true if the error should be cached.