Check cached sources with upstream after the cache TTL (closes #69)

A cached source and its variants were served until eviction, so a
changed image at the same URL was never picked up.

After 24 hours a request checks the source with upstream, sending its
stored ETag and Last-Modified. A 304 renews the source with no download
or conversion. New bytes replace the source, and older variants are
converted again. A failed check serves the cached image and puts the
URL in the negative cache. This includes the full fetch made for a
variant whose source was evicted. Images not checked for 30 days are
evicted.

A variant file's modification time is its source's check time, so a
hit still makes no database call.

Model: opus-5-5

internal/imageproxy/imageproxy.go

@@ -10,6 +10,7 @@ import (
 	"fmt"
 	"io"
 	"log/slog"
+	"net/http"
 	"runtime/debug"
 	"time"
 
@@ -157,7 +158,9 @@ const (
 //
 // A cache hit opens the variant file and makes no database call: the cache
 // hands its access time to the goroutine that writes access times, without
-// waiting for it, and its hit is counted in memory. A variant file that
+// waiting for it, and its hit is counted in memory. A variant whose source
+// was last checked with upstream CacheTTL or more ago is a miss, which checks
+// the source first (see processFromSourceOrFetch). A variant file that
 // cannot be served, such as one whose first bytes are not those of an output
 // format, is a miss, and the variant is made again.
 func (p *Proxy) Get(
@@ -178,7 +181,7 @@ func (p *Proxy) Get(
 		}, nil
 	}
 
-	if !errors.Is(err, imgcache.ErrNotFound) {
+	if !errors.Is(err, imgcache.ErrNotFound) && !errors.Is(err, imgcache.ErrStale) {
 		p.log.Warn("cached variant not served, making it again",
 			"cache_key", cacheKey, "error", err)
 	}
@@ -337,13 +340,50 @@ func (p *Proxy) loadCachedSource(
 	return reader, size, format
 }
 
-// processFromSourceOrFetch processes an image, using cached source content
-// if available.
+// processFromSourceOrFetch makes the variant req asks for, from the cached
+// source when there is one and from a fetched source otherwise.
+//
+// A cached source last checked with upstream CacheTTL or more ago is checked
+// first: upstream is asked to send it only if it changed since. When it
+// changed, the new bytes replace the cached source and the variant is made
+// from them. When it did not change, or the check fails, the cached source
+// is used: the variant's cached file is served again if it was made from the
+// cached source's bytes, and otherwise the variant is made from them. When
+// the source is not cached, a failed fetch still serves the variant's cached
+// file (see fetchAndProcess).
 func (p *Proxy) processFromSourceOrFetch(
 	ctx context.Context,
 	req *imagerequest.Request,
 	cacheKey imagerequest.VariantKey,
 ) (*processedVariant, error) {
+	cached, err := p.cache.LookupSource(ctx, req.Source)
+	if err != nil {
+		if !errors.Is(err, imgcache.ErrNotFound) {
+			p.log.Warn("failed to look up cached source, fetching", "error", err)
+		}
+
+		return p.fetchAndProcess(ctx, req, cacheKey)
+	}
+
+	if p.cache.Stale(cached.CheckedAt) {
+		fetched, err := p.fetchSource(ctx, req, cached.ETag, cached.LastModified)
+
+		switch {
+		case errors.Is(err, errSourceNotModified):
+			cached.CheckedAt = time.Now().UTC()
+			p.renewSource(ctx, req.Source, cached.CheckedAt)
+		case err != nil:
+			p.recordFailedCheck(ctx, req, err)
+		default:
+			return p.processFetched(ctx, req, cacheKey, fetched)
+		}
+	}
+
+	variant := p.renewVariant(ctx, cacheKey, cached)
+	if variant != nil {
+		return variant, nil
+	}
+
 	source, sourceSize, sourceFormat := p.loadCachedSource(ctx, req.Source)
 
 	// Fetch from upstream if we don't have source data or it's empty
@@ -356,18 +396,168 @@ func (p *Proxy) processFromSourceOrFetch(
 	// Process using cached source; nothing was fetched from upstream. The
 	// image processor reads the source only once it has a processing slot,
 	// so a request waiting for one holds none of it in memory.
-	return p.processAndStore(ctx, req, cacheKey, source, sourceFormat, sourceSize)
+	return p.processAndStore(ctx, req, cacheKey, cached.CheckedAt,
+		source, sourceFormat, sourceSize)
 }
 
-// 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.
+// recordFailedCheck logs a failed check of req's source with upstream, after
+// which the image is still served from the cache. It puts the source URL in
+// the negative cache, whatever the failure, a timeout included, so upstream
+// is asked at most once per NegativeTTL while it fails, however often the
+// image is served. A failure that was a negative cache hit records nothing.
+func (p *Proxy) recordFailedCheck(
+	ctx context.Context, req *imagerequest.Request, err error,
+) {
+	if errors.Is(err, ErrNegativeCached) {
+		return
+	}
+
+	p.log.Warn("checking source with upstream failed, serving from the cache",
+		"request_id", middleware.GetReqID(ctx),
+		"host", req.Source.Host, "path", req.Source.Path, "error", err)
+	p.storeNegative(ctx, req)
+}
+
+// renewSource records that upstream answered at checkedAt that src's cached
+// source had not changed. A failure to record it is only logged: the source
+// is then checked again on its next use.
+func (p *Proxy) renewSource(
+	ctx context.Context, src imagerequest.Source, checkedAt time.Time,
+) {
+	err := p.cache.RenewSource(ctx, src, checkedAt)
+	if err != nil {
+		p.log.Warn("failed to renew cached source", "source_key", src.Key(),
+			"error", err)
+	}
+}
+
+// renewVariant returns the cached variant of cacheKey when it was made from
+// the bytes of the cached source that source describes, and renews it to
+// source.CheckedAt (see imgcache.Cache.RenewVariant). It returns nil when
+// there is no such variant or it cannot be read.
+func (p *Proxy) renewVariant(
+	ctx context.Context, cacheKey imagerequest.VariantKey,
+	source imgcache.SourceInfo,
+) *processedVariant {
+	reader, _, contentType, err := p.cache.RenewVariant(ctx, cacheKey, source)
+	if err != nil {
+		if !errors.Is(err, imgcache.ErrNotFound) {
+			p.log.Warn("cached variant not renewed, making it again",
+				"cache_key", cacheKey, "error", err)
+		}
+
+		return nil
+	}
+
+	return p.readCachedVariant(cacheKey, reader, contentType)
+}
+
+// cachedVariantIgnoringTTL returns the cached variant of cacheKey whatever
+// its age. It returns nil when the variant is not cached or cannot be read.
+func (p *Proxy) cachedVariantIgnoringTTL(
+	cacheKey imagerequest.VariantKey,
+) *processedVariant {
+	reader, _, contentType, err := p.cache.VariantIgnoringTTL(cacheKey)
+	if err != nil {
+		if !errors.Is(err, imgcache.ErrNotFound) {
+			p.log.Warn("cached variant not served", "cache_key", cacheKey,
+				"error", err)
+		}
+
+		return nil
+	}
+
+	return p.readCachedVariant(cacheKey, reader, contentType)
+}
+
+// readCachedVariant reads the cached variant of cacheKey that reader opened,
+// whose content type is contentType, and closes reader. It returns nil when
+// the variant cannot be read.
+func (p *Proxy) readCachedVariant(
+	cacheKey imagerequest.VariantKey, reader io.ReadCloser, contentType string,
+) *processedVariant {
+	defer func() { _ = reader.Close() }()
+
+	data, err := io.ReadAll(reader)
+	if err != nil {
+		p.log.Warn("failed to read cached variant", "cache_key", cacheKey,
+			"error", err)
+
+		return nil
+	}
+
+	return &processedVariant{data: data, contentType: contentType}
+}
+
+// fetchAndProcess fetches the source from upstream, stores it, and makes
+// and stores the variant from it. When the fetch fails while the variant is
+// still cached, as it can be after eviction removed its source, the cached
+// variant is served whatever its age, and the failure is recorded as a failed
+// check (see recordFailedCheck).
 func (p *Proxy) fetchAndProcess(
 	ctx context.Context,
 	req *imagerequest.Request,
 	cacheKey imagerequest.VariantKey,
 ) (*processedVariant, error) {
+	fetched, err := p.fetchSource(ctx, req, "", "")
+	if err != nil {
+		variant := p.cachedVariantIgnoringTTL(cacheKey)
+		if variant == nil {
+			return nil, err
+		}
+
+		p.recordFailedCheck(ctx, req, err)
+
+		return variant, nil
+	}
+
+	return p.processFetched(ctx, req, cacheKey, fetched)
+}
+
+// processFetched makes and stores the variant from the source fetchSource
+// fetched, then closes the fetch's response.
+func (p *Proxy) processFetched(
+	ctx context.Context,
+	req *imagerequest.Request,
+	cacheKey imagerequest.VariantKey,
+	fetched *fetchedSource,
+) (*processedVariant, error) {
+	// Closing the response frees the upstream connection. It is closed only
+	// after processing, so the fetcher's connection limit also bounds the
+	// fetched sources held in memory while their requests wait for a
+	// processing slot.
+	defer func() { _ = fetched.response.Close() }()
+
+	return p.processAndStore(ctx, req, cacheKey, fetched.info.CheckedAt,
+		bytes.NewReader(fetched.data), fetched.format, int64(len(fetched.data)))
+}
+
+// errSourceNotModified is returned by fetchSource when upstream answers 304
+// Not Modified: the cached source has not changed.
+var errSourceNotModified = errors.New("upstream source not modified")
+
+// fetchedSource is a source fetchSource fetched and stored in the cache.
+type fetchedSource struct {
+	data   []byte
+	format imagerequest.Format
+	// info is what the cache keeps about the source
+	info imgcache.SourceInfo
+	// response is the fetch's response, still open; closing it frees the
+	// upstream connection
+	response io.Closer
+}
+
+// fetchSource fetches req's source from upstream and stores it in the cache.
+// A non-empty ifNoneMatch or ifModifiedSince asks upstream to send the source
+// only if it changed since; errSourceNotModified says it did not. 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. The caller closes the returned response.
+func (p *Proxy) fetchSource(
+	ctx context.Context,
+	req *imagerequest.Request,
+	ifNoneMatch, ifModifiedSince string,
+) (*fetchedSource, error) {
 	// Check negative cache - skip fetching for recently-failed URLs
 	negHit, err := p.cache.Failure(ctx, req.Source)
 	if err != nil {
@@ -387,7 +577,8 @@ func (p *Proxy) fetchAndProcess(
 	p.log.Debug("fetching from upstream", "host", req.Source.Host,
 		"path", req.Source.Path, "query", req.Source.Query)
 
-	fetchResult, err := p.fetcher.Fetch(ctx, req.Source)
+	fetchResult, err := p.fetcher.Fetch(ctx, req.Source,
+		ifNoneMatch, ifModifiedSince)
 	if err != nil {
 		// Store negative cache for certain errors
 		if isNegativeCacheable(err) {
@@ -397,11 +588,15 @@ func (p *Proxy) fetchAndProcess(
 		return nil, fmt.Errorf("upstream fetch failed: %w", err)
 	}
 
-	// Closing the body frees the upstream connection. It is closed only
-	// after processing, so the fetcher's connection limit also bounds the
-	// fetched sources held in memory while their requests wait for a
-	// processing slot.
-	defer func() { _ = fetchResult.Content.Close() }()
+	if fetchResult.StatusCode == http.StatusNotModified {
+		_ = fetchResult.Content.Close()
+
+		p.log.Info("upstream source not modified",
+			"request_id", middleware.GetReqID(ctx), "host", req.Source.Host,
+			"path", req.Source.Path, "fetch_ms", fetchResult.FetchDurationMs)
+
+		return nil, errSourceNotModified
+	}
 
 	// Read and validate the source content
 	sourceData, err := io.ReadAll(fetchResult.Content)
@@ -411,31 +606,12 @@ func (p *Proxy) fetchAndProcess(
 	p.incrementUpstreamFetch(fetchBytes)
 
 	if err != nil {
+		_ = fetchResult.Content.Close()
+
 		return nil, fmt.Errorf("failed to read upstream response: %w", err)
 	}
 
-	// Calculate download bitrate
-	var downloadRate string
-
-	if fetchResult.FetchDurationMs > 0 {
-		seconds := float64(fetchResult.FetchDurationMs) / 1000.0 //nolint:mnd // ms to seconds
-		bitsPerSecond := float64(fetchBytes*8) / seconds         //nolint:mnd // bytes to bits
-		downloadRate = humanize.SI(bitsPerSecond, "bps")
-	}
-
-	// Log upstream fetch details
-	p.log.Info("upstream fetched",
-		"request_id", middleware.GetReqID(ctx),
-		"host", req.Source.Host,
-		"path", req.Source.Path,
-		"bytes", fetchBytes,
-		"fetch_ms", fetchResult.FetchDurationMs,
-		"rate", downloadRate,
-		"remote_addr", fetchResult.RemoteAddr,
-		"http", fetchResult.HTTPVersion,
-		"tls", fetchResult.TLSVersion,
-		"cipher", fetchResult.TLSCipherSuite,
-	)
+	p.logUpstreamFetch(ctx, req, fetchResult, fetchBytes)
 
 	// The source's format, detected from its first bytes, which must match
 	// its content type. A body that does not is the upstream's error, so it
@@ -448,18 +624,70 @@ func (p *Proxy) fetchAndProcess(
 			"content_type", fetchResult.ContentType, "error", err)
 		p.storeNegative(ctx, req)
 
+		_ = fetchResult.Content.Close()
+
 		return nil, fmt.Errorf("content validation failed: %w", err)
 	}
 
+	info := fetchedSourceInfo(fetchResult)
+
 	// Store source content
-	_, err = p.cache.PutSource(ctx, req.Source, bytes.NewReader(sourceData))
+	_, err = p.cache.PutSource(ctx, req.Source, bytes.NewReader(sourceData), info)
 	if err != nil {
 		p.log.Warn("failed to store source content", "error", err)
 		// Continue even if caching fails
 	}
 
-	return p.processAndStore(
-		ctx, req, cacheKey, bytes.NewReader(sourceData), sourceFormat, fetchBytes,
+	return &fetchedSource{
+		data:     sourceData,
+		format:   sourceFormat,
+		info:     info,
+		response: fetchResult.Content,
+	}, nil
+}
+
+// fetchedSourceInfo returns what the cache keeps about a source upstream
+// just sent: fetched and checked now, with the ETag and Last-Modified
+// headers of fetchResult.
+func fetchedSourceInfo(fetchResult *httpfetcher.FetchResult) imgcache.SourceInfo {
+	now := time.Now().UTC()
+	upstreamHeaders := http.Header(fetchResult.Headers)
+
+	return imgcache.SourceInfo{
+		FetchedAt:    now,
+		CheckedAt:    now,
+		ETag:         upstreamHeaders.Get("ETag"),
+		LastModified: upstreamHeaders.Get("Last-Modified"),
+	}
+}
+
+// logUpstreamFetch logs a fetch of req's source that read fetchBytes bytes,
+// with its download rate and connection details.
+func (p *Proxy) logUpstreamFetch(
+	ctx context.Context,
+	req *imagerequest.Request,
+	fetchResult *httpfetcher.FetchResult,
+	fetchBytes int64,
+) {
+	var downloadRate string
+
+	if fetchResult.FetchDurationMs > 0 {
+		seconds := float64(fetchResult.FetchDurationMs) / 1000.0 //nolint:mnd // ms to seconds
+		bitsPerSecond := float64(fetchBytes*8) / seconds         //nolint:mnd // bytes to bits
+		downloadRate = humanize.SI(bitsPerSecond, "bps")
+	}
+
+	p.log.Info("upstream fetched",
+		"request_id", middleware.GetReqID(ctx),
+		"host", req.Source.Host,
+		"path", req.Source.Path,
+		"bytes", fetchBytes,
+		"fetch_ms", fetchResult.FetchDurationMs,
+		"rate", downloadRate,
+		"remote_addr", fetchResult.RemoteAddr,
+		"http", fetchResult.HTTPVersion,
+		"tls", fetchResult.TLSVersion,
+		"cipher", fetchResult.TLSCipherSuite,
 	)
 }
 
@@ -494,11 +722,13 @@ type processedVariant struct {
 }
 
 // processAndStore processes the image read from source, which is in
-// sourceFormat, and stores the result.
+// sourceFormat, and stores the result. sourceCheckedAt is when the source
+// was last checked with upstream (see imgcache.Cache.PutVariant).
 func (p *Proxy) processAndStore(
 	ctx context.Context,
 	req *imagerequest.Request,
 	cacheKey imagerequest.VariantKey,
+	sourceCheckedAt time.Time,
 	source io.Reader,
 	sourceFormat imagerequest.Format,
 	fetchBytes int64,
@@ -559,7 +789,8 @@ func (p *Proxy) processAndStore(
 	)
 
 	// Store variant to cache
-	err = p.cache.PutVariant(ctx, cacheKey, bytes.NewReader(processedData))
+	err = p.cache.PutVariant(ctx, cacheKey, sourceCheckedAt,
+		bytes.NewReader(processedData))
 	if err != nil {
 		p.log.Warn("failed to store variant", "error", err)
 		// Continue even if caching fails