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

Cached images were served until eviction, so upstream changes were
missed.

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

Variant rows keep the source's ETag and Last-Modified for checking a
variant of an evicted source.

A variant file's modification time is its source's check time when it
was made or renewed. Hits read it without a database call. The ETag
includes it, so new bytes get a new ETag.

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(
@@ -165,20 +168,20 @@ func (p *Proxy) Get(
 ) (*ImageResponse, error) {
 	cacheKey := imagerequest.CacheKey(req)
 
-	reader, size, contentType, err := p.cache.Variant(cacheKey)
+	cached, err := p.cache.Variant(cacheKey)
 	if err == nil {
 		p.cache.IncrementStats(true)
 
 		return &ImageResponse{
-			Content:       reader,
-			ContentLength: size,
-			ContentType:   contentType,
+			Content:       cached.Content,
+			ContentLength: cached.Size,
+			ContentType:   cached.ContentType,
 			CacheStatus:   CacheHit,
-			ETag:          formatETag(cacheKey),
+			ETag:          formatETag(cacheKey, cached.CheckedAt),
 		}, 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)
 	}
@@ -285,7 +288,7 @@ func (p *Proxy) processOrWait(
 		ContentLength: int64(len(variant.data)),
 		ContentType:   variant.contentType,
 		FetchedBytes:  variant.fetchedBytes,
-		ETag:          formatETag(cacheKey),
+		ETag:          formatETag(cacheKey, variant.checkedAt),
 	}, nil
 }
 
@@ -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 but the variant is, the variant is checked with
+// upstream the same way (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,199 @@ 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, 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 {
+	cached, 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, cached)
+}
+
+// cachedVariantIgnoringTTL returns the cached variant of cacheKey whatever
+// its age, with what its row keeps about the source bytes it was made from
+// (see imgcache.Cache.LookupVariant). It returns nil when the variant is not
+// cached or cannot be read. The SourceInfo is empty when the variant is not
+// returned, or its row is missing or cannot be read.
+func (p *Proxy) cachedVariantIgnoringTTL(
+	ctx context.Context, cacheKey imagerequest.VariantKey,
+) (*processedVariant, imgcache.SourceInfo) {
+	cached, 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, imgcache.SourceInfo{}
+	}
+
+	variant := p.readCachedVariant(cacheKey, cached)
+	if variant == nil {
+		return nil, imgcache.SourceInfo{}
+	}
+
+	madeFrom, err := p.cache.LookupVariant(ctx, cacheKey)
+	if err != nil && !errors.Is(err, imgcache.ErrNotFound) {
+		p.log.Warn("failed to look up cached variant", "cache_key", cacheKey,
+			"error", err)
+	}
+
+	return variant, madeFrom
+}
+
+// readCachedVariant reads the cached variant of cacheKey from its opened file,
+// and closes the file. It returns nil when the variant cannot be read.
+func (p *Proxy) readCachedVariant(
+	cacheKey imagerequest.VariantKey, file imgcache.VariantFile,
+) *processedVariant {
+	defer func() { _ = file.Content.Close() }()
+
+	data, err := io.ReadAll(file.Content)
+	if err != nil {
+		p.log.Warn("failed to read cached variant", "cache_key", cacheKey,
+			"error", err)
+
+		return nil
+	}
+
+	return &processedVariant{
+		data:        data,
+		contentType: file.ContentType,
+		checkedAt:   file.CheckedAt,
+	}
+}
+
+// fetchAndProcess fetches the source from upstream, stores it, and makes
+// and stores the variant from it.
+//
+// The variant can still be cached after eviction removed its source. The
+// fetch then sends the ETag and Last-Modified of the source bytes the variant
+// was made from, so upstream sends the source only if it changed since. When
+// it did not change, the cached variant is renewed and served, with no
+// download and no conversion. When the fetch fails, 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) {
+	variant, madeFrom := p.cachedVariantIgnoringTTL(ctx, cacheKey)
+
+	fetched, err := p.fetchSource(ctx, req, madeFrom.ETag, madeFrom.LastModified)
+
+	switch {
+	case err == nil:
+		return p.processFetched(ctx, req, cacheKey, fetched)
+	case variant == nil:
+		return nil, err
+	case errors.Is(err, errSourceNotModified):
+		variant.checkedAt = time.Now().UTC()
+
+		err = p.cache.SetVariantCheckedAt(ctx, cacheKey, variant.checkedAt)
+		if err != nil {
+			p.log.Warn("failed to renew cached variant", "cache_key", cacheKey,
+				"error", err)
+		}
+	default:
+		p.recordFailedCheck(ctx, req, err)
+	}
+
+	return variant, nil
+}
+
+// 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,
+		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 +608,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 +619,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 +637,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 +655,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,
 	)
 }
 
@@ -491,14 +750,19 @@ type processedVariant struct {
 	data         []byte
 	contentType  string
 	fetchedBytes int64
+	// checkedAt is its source's check time when the variant was made or last
+	// renewed, which its cached file has as its modification time
+	checkedAt time.Time
 }
 
 // processAndStore processes the image read from source, which is in
-// sourceFormat, and stores the result.
+// sourceFormat, and stores the result. sourceInfo describes the source's
+// bytes, and is stored with the variant (see imgcache.Cache.PutVariant).
 func (p *Proxy) processAndStore(
 	ctx context.Context,
 	req *imagerequest.Request,
 	cacheKey imagerequest.VariantKey,
+	sourceInfo imgcache.SourceInfo,
 	source io.Reader,
 	sourceFormat imagerequest.Format,
 	fetchBytes int64,
@@ -559,7 +823,8 @@ func (p *Proxy) processAndStore(
 	)
 
 	// Store variant to cache
-	err = p.cache.PutVariant(ctx, cacheKey, bytes.NewReader(processedData))
+	err = p.cache.PutVariant(ctx, cacheKey, sourceInfo,
+		bytes.NewReader(processedData))
 	if err != nil {
 		p.log.Warn("failed to store variant", "error", err)
 		// Continue even if caching fails
@@ -569,6 +834,7 @@ func (p *Proxy) processAndStore(
 		data:         processedData,
 		contentType:  processResult.ContentType,
 		fetchedBytes: fetchBytes,
+		checkedAt:    sourceInfo.CheckedAt,
 	}, nil
 }
 
@@ -580,13 +846,16 @@ func isNegativeCacheable(err error) bool {
 // etagHashLength is the number of hash characters to use for ETags.
 const etagHashLength = 16
 
-// formatETag formats a VariantKey as a quoted ETag value.
-func formatETag(key imagerequest.VariantKey) string {
+// formatETag returns the quoted ETag of the variant of key: the first
+// etagHashLength characters of key, then checkedAt in Unix nanoseconds.
+// checkedAt is its source's check time when the variant was made or last
+// renewed, so a variant made again from new source bytes gets another ETag.
+func formatETag(key imagerequest.VariantKey, checkedAt time.Time) string {
 	hash := string(key)
 	// Use first 16 characters of hash for a shorter but still unique ETag
 	if len(hash) > etagHashLength {
 		hash = hash[:etagHashLength]
 	}
 
-	return `"` + hash + `"`
+	return fmt.Sprintf(`"%s-%d"`, hash, checkedAt.UnixNano())
 }