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

@@ -200,9 +200,10 @@ path under `/v1/` answers 200, in maintenance mode too.
   `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
-  source URL; 503 when pixa is busy or in maintenance mode; 500 for any other
-  failure.
+  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
@@ -313,23 +314,9 @@ cache at once, they share one upstream fetch (or one read of the cached source)
 and one transcode: the first request does the work, and the others wait for its
 image or its error, holding no upstream connection or processing slot of their
 own. A waiting request stops waiting when its own client goes away. The work
-goes on for the others even if the first request's client goes away. The shared
-fetch sends the first request's ID upstream, and the lines logged for the fetch
-and the transcode carry that ID.
-
-A transcode whose request's `downstream_timeout` has ended (for a shared one,
-the first request's) stops when it gets its processing slot or before it begins
-encoding, and gives the slot back. libvips cannot stop an encode once it has
-begun, so an encode keeps its slot until it finishes, which can be after
-`downstream_timeout`. The limit of 8192 on each side of the source and of the
-output bounds how long that takes. With one libvips thread, as pixad runs it,
-encoding 8192x8192 random pixels takes up to about 1 second as JPEG, 15 as PNG,
-16 as GIF, 63 as WebP, 110 as AVIF and 96 as JPEG XL, the slowest of 8 or 16
-bits per sample, with or without an alpha channel. WebP, AVIF and JPEG XL are
-that slow only with an alpha channel: 8-bit RGB takes about 44, 53 and 28
-seconds. Decoding such a source adds up to about 11 seconds. A WebP, AVIF or
-JPEG XL encode can therefore hold its slot past the default `downstream_timeout`
-of 60 seconds.
+goes on for the others even if the first request's client goes away, until that
+request's `downstream_timeout` ends. The shared fetch sends the first request's
+ID upstream, and the lines logged for the fetch and the transcode carry that ID.
 
 The login form (`POST /`) is limited to 5 attempts per minute per client
 address, counting an IPv6 client by its /64; an attempt over the limit is

TODO.md

@@ -30,6 +30,16 @@ 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 `:` 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,21 +48,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 a transcode stops once its request's `downstream_timeout` has
-  ended, unless it has begun encoding (closes #243): the image processor looked
-  at its context only while it waited for a processing slot, so an image was
-  decoded and encoded, holding the slot, however long after its request's
-  deadline that took. `Process` now returns the context's error, and gives the
-  slot back, when the context has ended by the time it has the slot or before it
-  encodes. libvips cannot stop an encode once it has begun, so that encode keeps
-  its slot until it finishes; the limit of 8192 on each side of the source and
-  of the output bounds how long that takes. With one libvips thread, 8192x8192
-  random pixels take up to about 1 second to encode as JPEG, 15 as PNG, 16 as
-  GIF, 63 as WebP, 110 as AVIF and 96 as JPEG XL, the last three with an alpha
-  channel, plus up to about 11 seconds to decode the source; `README.md` gives
-  these times and no longer says the work stops when `downstream_timeout` ends.
-  The settings of the WebP, AVIF and JPEG XL encoders, which can hold a slot
-  past the default `downstream_timeout` of 60 seconds, are unchanged.
 - 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
@@ -516,11 +511,11 @@ P2: security: per-origin rate limiting
   cancellation but keeps its deadline, and the others wait for its image or
   error holding no upstream connection or processing slot, and stop waiting when
   their own context ends; the request doing the processing waits for it even
-  then, until it ends, which can be after its deadline; a request whose context
-  has already ended starts nothing; each request counts one miss, and the
-  processing counts its fetch and transcode once; a panic while processing is
-  reported to Sentry when `sentry_dsn` is set and becomes an error for every
-  waiting request instead of stopping pixad; documented in `README.md`.
+  then, up to its deadline; a request whose context has already ended starts
+  nothing; each request counts one miss, and the processing counts its fetch and
+  transcode once; a panic while processing is reported to Sentry when
+  `sentry_dsn` is set and becomes an error for every waiting request instead of
+  stopping pixad; documented in `README.md`.
 - 2026-09-29 only the image routes send CORS headers (closes #98): the CORS
   middleware, with the `access_control_allow_origin` origin, moved from the
   router root onto a `/v1` subrouter holding `/v1/image/` and `/v1/e/`, where it

internal/handlers/server_busy_internal_test.go

@@ -1,7 +1,6 @@
 package handlers
 
 import (
-	"context"
 	"fmt"
 	"log/slog"
 	"net/http"
@@ -48,39 +47,3 @@ func TestServerBusyAnswers503(t *testing.T) {
 		}
 	}
 }
-
-// TestProcessingTimedOutAnswers503 checks that both image routes answer 503
-// with the server busy error when the image service reports that processing
-// stopped at the deadline of the request doing it, wrapped as the service
-// wraps it. A request that waited for that processing gets this error while
-// its own deadline may have time left.
-func TestProcessingTimedOutAnswers503(t *testing.T) {
-	t.Parallel()
-
-	h := &Handlers{log: slog.New(slog.DiscardHandler)}
-	req := &imgcache.ImageRequest{SourceHost: "img.example.com", SourcePath: "/a.jpg"}
-	err := fmt.Errorf("%w: failed to encode: %w",
-		imgcache.ErrProcessingTimedOut, context.DeadlineExceeded)
-
-	plain := httptest.NewRecorder()
-	h.respondImageError(plain, req, err)
-
-	encrypted := httptest.NewRecorder()
-	h.handleImageError(encrypted, err)
-
-	for route, rec := range map[string]*httptest.ResponseRecorder{
-		"/v1/image/": plain, "/v1/e/": encrypted,
-	} {
-		t.Logf("%s: status = %d, body = %q", route, rec.Code, rec.Body.String())
-
-		if rec.Code != http.StatusServiceUnavailable {
-			t.Errorf("%s: status = %d, want %d",
-				route, rec.Code, http.StatusServiceUnavailable)
-		}
-
-		if !strings.Contains(rec.Body.String(), "server busy, try again later") {
-			t.Errorf("%s: body = %q, want the server busy error",
-				route, rec.Body.String())
-		}
-	}
-}

internal/imageprocessor/deadline_internal_test.go

@@ -1,118 +0,0 @@
-package imageprocessor
-
-import (
-	"bytes"
-	"context"
-	"errors"
-	"io"
-	"testing"
-	"time"
-)
-
-// readerAfterDeadline is a Process input whose first Read waits until done
-// is closed, so the deadline passes after Process has taken its slot and
-// before it encodes.
-type readerAfterDeadline struct {
-	data   *bytes.Reader
-	done   <-chan struct{}
-	waited bool
-}
-
-func (r *readerAfterDeadline) Read(p []byte) (int, error) {
-	if !r.waited {
-		r.waited = true
-
-		<-r.done
-	}
-
-	return r.data.Read(p)
-}
-
-// TestProcessStopsWhenDeadlinePassed checks that Process returns
-// context.DeadlineExceeded, and holds no slot afterwards, when its context's
-// deadline has passed before it starts or while it reads its input. libvips
-// cannot stop an encode once it has begun, so Process must not begin one for
-// a request that has ended.
-func TestProcessStopsWhenDeadlinePassed(t *testing.T) {
-	t.Parallel()
-
-	input := createTestJPEG(t, 50, 50)
-
-	t.Run("before Process starts", func(t *testing.T) {
-		t.Parallel()
-
-		ctx, cancel := context.WithDeadline(t.Context(),
-			time.Now().Add(-time.Second))
-		defer cancel()
-
-		checkProcessStopsAtDeadline(ctx, t, bytes.NewReader(input))
-	})
-
-	t.Run("while Process reads its input", func(t *testing.T) {
-		t.Parallel()
-
-		ctx, cancel := context.WithTimeout(t.Context(), 100*time.Millisecond)
-		defer cancel()
-
-		checkProcessStopsAtDeadline(ctx, t, &readerAfterDeadline{
-			data: bytes.NewReader(input), done: ctx.Done(),
-		})
-	})
-}
-
-// checkProcessStopsAtDeadline runs Process on input with ctx, whose deadline
-// has passed by the time Process could encode, and fails the test unless
-// Process returns context.DeadlineExceeded and gives its slot back.
-func checkProcessStopsAtDeadline(
-	ctx context.Context, t *testing.T, input io.Reader,
-) {
-	t.Helper()
-
-	proc := New(Params{MaxConcurrentProcessing: 1})
-
-	result, err := proc.Process(ctx, input, smallJPEGRequest())
-	if result != nil {
-		t.Logf("Process() made a %dx%d image after its deadline passed",
-			result.Width, result.Height)
-
-		_ = result.Content.Close()
-	}
-
-	t.Logf("Process() error = %v", err)
-
-	if !errors.Is(err, context.DeadlineExceeded) {
-		t.Errorf("Process() error = %v, want context.DeadlineExceeded", err)
-	}
-
-	if held := len(proc.processingSemaphore); held != 0 {
-		t.Errorf("%d slots still held after Process() returned", held)
-	}
-}
-
-// inputNotToBeRead is a Process input that fails the test when it is read.
-type inputNotToBeRead struct {
-	t *testing.T
-}
-
-func (r inputNotToBeRead) Read([]byte) (int, error) {
-	r.t.Error("Process read its input although its deadline had passed")
-
-	return 0, io.EOF
-}
-
-// TestProcessReadsNoInputOnceDeadlinePassed checks that Process, called with
-// a context whose deadline passed before it starts, gives its slot back
-// without reading its input. With a slot free, the select in acquireSlot
-// takes the slot or sees the ended context at random, so Process is called
-// many times.
-func TestProcessReadsNoInputOnceDeadlinePassed(t *testing.T) {
-	t.Parallel()
-
-	ctx, cancel := context.WithDeadline(t.Context(),
-		time.Now().Add(-time.Second))
-	defer cancel()
-
-	for range 100 {
-		checkProcessStopsAtDeadline(ctx, t, inputNotToBeRead{t: t})
-	}
-}

internal/imageprocessor/imageprocessor.go

@@ -208,9 +208,7 @@ func New(params Params) *ImageProcessor {
 // Process transforms an image according to the request. When
 // MaxConcurrentProcessing images are already being processed, it waits up
 // to ProcessingWaitTimeout for one to finish, then fails with
-// ErrTooManyImages. When ctx has ended once Process has a slot, or before it
-// encodes, it returns ctx's error and gives the slot back. libvips cannot stop
-// an encode once it has begun, so an encode keeps its slot until it finishes.
+// ErrTooManyImages.
 func (p *ImageProcessor) Process(
 	ctx context.Context,
 	input io.Reader,
@@ -292,7 +290,7 @@ func (p *ImageProcessor) Process(
 	}
 
 	// Encode to target format
-	output, err := p.encode(ctx, img, outputFormat, req.Quality)
+	output, err := p.encode(img, outputFormat, req.Quality)
 	if err != nil {
 		return nil, fmt.Errorf("failed to encode: %w", err)
 	}
@@ -419,28 +417,25 @@ func (p *ImageProcessor) WaitForProcessing(ctx context.Context) int {
 
 // acquireSlot takes a slot in processingSemaphore, waiting at most
 // processingWaitTimeout for one to free up, and returns the func that gives
-// it back. When ctx has ended by the time it has a slot, it gives the slot
-// back and returns ctx's error.
+// it back. A free slot is taken even when ctx has ended; only the wait for
+// one stops when ctx ends, as the rest of Process does not check ctx.
 func (p *ImageProcessor) acquireSlot(ctx context.Context) (func(), error) {
+	release := func() { <-p.processingSemaphore }
+
 	select {
 	case p.processingSemaphore <- struct{}{}:
+		return release, nil
+	default:
+	}
+
+	select {
+	case p.processingSemaphore <- struct{}{}:
+		return release, nil
 	case <-time.After(p.processingWaitTimeout):
 		return nil, ErrTooManyImages
 	case <-ctx.Done():
 		return nil, ctx.Err()
 	}
-
-	release := func() { <-p.processingSemaphore }
-
-	// select takes the slot even when ctx has ended at the same moment
-	err := ctx.Err()
-	if err != nil {
-		release()
-
-		return nil, err
-	}
-
-	return release, nil
 }
 
 // detectFormat returns the format string for a govips image type.
@@ -532,17 +527,10 @@ func (p *ImageProcessor) resize(
 
 const defaultQuality = 85
 
-// encode encodes an image to the specified format. libvips cannot stop an
-// encode once it has begun, so when ctx has ended encode returns ctx's error
-// without beginning one.
+// encode encodes an image to the specified format.
 func (p *ImageProcessor) encode(
-	ctx context.Context, img *vips.ImageRef, format Format, quality int,
+	img *vips.ImageRef, format Format, quality int,
 ) ([]byte, error) {
-	err := ctx.Err()
-	if err != nil {
-		return nil, err
-	}
-
 	if quality <= 0 {
 		quality = defaultQuality
 	}
@@ -552,7 +540,7 @@ func (p *ImageProcessor) encode(
 	// libvips' built-in profile; govips' own sRGB path variable is set on
 	// first use but read without a lock, so concurrent requests race on it.
 	if img.HasICCProfile() {
-		err = img.TransformICCProfileWithFallback("srgb", "srgb")
+		err := img.TransformICCProfileWithFallback("srgb", "srgb")
 		if err != nil {
 			return nil, fmt.Errorf("failed to convert to sRGB: %w", err)
 		}

internal/imgcache/concurrent_misses_internal_test.go

@@ -15,7 +15,6 @@ import (
 
 	"github.com/getsentry/sentry-go"
 	"sneak.berlin/go/pixa/internal/httpfetcher"
-	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/magic"
 )
 
@@ -436,47 +435,6 @@ func TestService_Get_ReturnsByItsDeadline(t *testing.T) {
 	}
 }
 
-// TestService_Get_WaiterGetsProcessingTimedOut has a request with no deadline
-// join the held fetch of a first request with a short one. With the only
-// processing slot held, the first request's transcode waits for it until the
-// first request's deadline ends, and stops then. The waiting request, whose
-// own context has not ended, must get ErrProcessingTimedOut, which the image
-// routes answer 503 as when pixa is busy.
-func TestService_Get_WaiterGetsProcessingTimedOut(t *testing.T) {
-	t.Parallel()
-
-	svc, fixtures, fetcher := setupHeldFetchService(t)
-	svc.processor = imageprocessor.New(
-		imageprocessor.Params{MaxConcurrentProcessing: 1},
-	)
-
-	holdProcessingSlot(t, svc.processor)
-
-	const firstTimeout = 500 * time.Millisecond
-
-	firstCtx, cancelFirst := context.WithTimeout(t.Context(), firstTimeout)
-	defer cancelFirst()
-
-	first := startGet(firstCtx, svc, photoVariant(fixtures, 85, FitCover))
-
-	<-fetcher.started
-
-	waiter := startGet(t.Context(), svc, photoVariant(fixtures, 85, FitCover))
-
-	time.Sleep(arrivalWait)
-	fetcher.releaseFetches()
-
-	t.Logf("first request: Get() error = %v", (<-first).err)
-
-	got := <-waiter
-	t.Logf("waiting request: Get() error = %v", got.err)
-
-	if !errors.Is(got.err, ErrProcessingTimedOut) {
-		t.Errorf("waiting request: Get() error = %v, want %v",
-			got.err, ErrProcessingTimedOut)
-	}
-}
-
 // panickingFetcher panics on every fetch.
 type panickingFetcher struct{}
 

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

@@ -128,32 +128,14 @@ func NewService(cfg *ServiceConfig) (*Service, error) {
 // ErrNegativeCached is returned when a URL is in the negative cache (recently failed).
 var ErrNegativeCached = errors.New("request is in negative cache (recently failed)")
 
-// ErrProcessingTimedOut is returned when processing an image stopped because
-// the downstream_timeout of the request doing it ended, to that request and to
-// every request that waited for its image.
-var ErrProcessingTimedOut = errors.New(
-	"image processing stopped at the deadline of the request doing it")
-
 // 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 {
@@ -429,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()