pixa/internal/imgcache/service.go

package imgcache

import (
	"bytes"
	"context"
	"errors"
	"fmt"
	"io"
	"log/slog"
	"runtime/debug"
	"time"

	"github.com/dustin/go-humanize"
	"github.com/getsentry/sentry-go"
	"github.com/go-chi/chi/v5/middleware"
	"golang.org/x/sync/singleflight"
	"sneak.berlin/go/pixa/internal/httpfetcher"
	"sneak.berlin/go/pixa/internal/imageprocessor"
	"sneak.berlin/go/pixa/internal/imagerequest"
	"sneak.berlin/go/pixa/internal/magic"
)

// Service orchestrates the cache, fetcher, and processor.
type Service struct {
	cache           *Cache
	fetcher         httpfetcher.Fetcher
	processor       *imageprocessor.ImageProcessor
	log             *slog.Logger
	maxResponseSize int64
	// variantsInProgress lets the requests that miss the same variant at the
	// same time share one fetch and one transcode.
	variantsInProgress singleflight.Group
}

// ServiceConfig holds configuration for the image service.
type ServiceConfig struct {
	// Cache is the cache instance
	Cache *Cache
	// Fetcher fetches source images from upstream hosts
	Fetcher httpfetcher.Fetcher
	// Processor converts and resizes the images
	Processor *imageprocessor.ImageProcessor
	// MaxResponseSize is the largest source accepted, in bytes; a cached
	// source larger than this is fetched again
	MaxResponseSize int64
	// Logger for logging
	Logger *slog.Logger
}

// errCacheRequired is returned when the service is built without a cache.
var errCacheRequired = errors.New("cache is required")

// NewService creates a new image service.
func NewService(cfg *ServiceConfig) (*Service, error) {
	if cfg.Cache == nil {
		return nil, errCacheRequired
	}

	log := cfg.Logger
	if log == nil {
		log = slog.Default()
	}

	// JPEG XL is the default output format, so pixad does not start
	// without it.
	err := imageprocessor.CheckJPEGXLSupport()
	if err != nil {
		return nil, err
	}

	return &Service{
		cache:           cfg.Cache,
		fetcher:         cfg.Fetcher,
		processor:       cfg.Processor,
		log:             log,
		maxResponseSize: cfg.MaxResponseSize,
	}, nil
}

// 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.
//
// A cache hit opens the variant file and makes no database call: its access
// time is handed to the goroutine that StartPendingAccessTimeWrites starts,
// without waiting for it, and its hit is counted in memory. 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 (s *Service) Get(
	ctx context.Context, req *imagerequest.Request,
) (*ImageResponse, error) {
	cacheKey := imagerequest.CacheKey(req)

	reader, size, contentType, err := s.cache.GetVariant(cacheKey)
	if err == nil {
		s.cache.touchVariant(cacheKey)
		s.cache.IncrementStats(true, 0)

		return &ImageResponse{
			Content:       reader,
			ContentLength: size,
			ContentType:   contentType,
			CacheStatus:   CacheHit,
			ETag:          formatETag(cacheKey),
		}, nil
	}

	if !errors.Is(err, ErrNotFound) {
		s.log.Warn("cached variant not served, making it again",
			"cache_key", cacheKey, "error", err)
	}

	// Cache miss - get the variant, processed once for all the requests that
	// miss it at the same time, then count this request's miss, also when it
	// failed or the request context has ended meanwhile
	response, err := s.processOrWait(ctx, req)

	s.cache.IncrementStats(false, 0)

	if err != nil {
		return nil, err
	}

	response.CacheStatus = CacheMiss

	return response, nil
}

// WaitForProcessing waits until no image is being processed, or until ctx
// ends, and returns how many images were still being processed then.
func (s *Service) WaitForProcessing(ctx context.Context) int {
	return s.processor.WaitForProcessing(ctx)
}

// errPanicked is returned when processing a variant panicked.
var errPanicked = errors.New("panic while processing image")

// processOrWait returns the variant req asks for. The first of the requests
// that miss a variant at the same time processes it, and singleflight hands
// its result, or its error, to the others: they fetch nothing, read no source
// and take no upstream connection or processing slot. The processing ignores
// the first request's cancellation, so the others are still served if that
// client goes away, but keeps its deadline.
func (s *Service) processOrWait(
	ctx context.Context, req *imagerequest.Request,
) (*ImageResponse, error) {
	// A request that has already ended starts no processing
	if ctx.Err() != nil {
		return nil, ctx.Err()
	}

	cacheKey := imagerequest.CacheKey(req)

	// Closed when this request's own function runs, which singleflight does
	// only when no other request is processing the variant
	processing := make(chan struct{})

	results := s.variantsInProgress.DoChan(string(cacheKey),
		func() (_ any, err error) {
			close(processing)

			// singleflight would raise a panic again in a goroutine of its
			// own, where no handler recovers it, and stop pixad. It is
			// reported through the Sentry hub that the Sentry middleware puts
			// on the request's context when sentry_dsn is set.
			defer func() {
				recovered := recover()
				if recovered != nil {
					s.log.Error("panic while processing image",
						"host", req.Source.Host, "path", req.Source.Path,
						"panic", recovered, "stack", string(debug.Stack()))

					if hub := sentry.GetHubFromContext(ctx); hub != nil {
						hub.RecoverWithContext(ctx, recovered)
					}

					err = fmt.Errorf("%w: %v", errPanicked, recovered)
				}
			}()

			processingCtx, cancel := withoutCancelKeepingDeadline(ctx)
			defer cancel()

			return s.processFromSourceOrFetch(processingCtx, req, cacheKey)
		})

	var result singleflight.Result

	select {
	case result = <-results:
	case <-ctx.Done():
		select {
		case <-processing:
			// This request is processing the variant: it waits for the
			// result, as every request did before misses were shared
			result = <-results
		default:
			// Another request is processing the variant, or this request's
			// function has not started yet; the processing goes on without it
			return nil, ctx.Err()
		}
	}

	if result.Err != nil {
		return nil, result.Err
	}

	variant, _ := result.Val.(*processedVariant)

	return &ImageResponse{
		Content:       io.NopCloser(bytes.NewReader(variant.data)),
		ContentLength: int64(len(variant.data)),
		ContentType:   variant.contentType,
		FetchedBytes:  variant.fetchedBytes,
		ETag:          formatETag(cacheKey),
	}, nil
}

// withoutCancelKeepingDeadline returns ctx without its cancellation but with
// its deadline, if it has one, and the func that releases the returned
// context.
func withoutCancelKeepingDeadline(
	ctx context.Context,
) (context.Context, context.CancelFunc) {
	deadline, hasDeadline := ctx.Deadline()
	if !hasDeadline {
		return context.WithoutCancel(ctx), func() {}
	}

	return context.WithDeadline(context.WithoutCancel(ctx), deadline)
}

// loadCachedSource opens source content from cache, without reading it, and
// returns it with its size; nil if the cached data is unavailable, empty or
// exceeds maxResponseSize.
func (s *Service) loadCachedSource(
	sourceKey imagerequest.SourceKey,
) (io.ReadCloser, int64) {
	reader, size, err := s.cache.GetSourceContent(sourceKey)
	if err != nil {
		s.log.Warn("failed to load cached source, fetching", "error", err)

		return nil, 0
	}

	if size > s.maxResponseSize {
		_ = reader.Close()

		s.log.Warn("cached source exceeds max response size, discarding",
			"source_key", sourceKey,
			"max_bytes", s.maxResponseSize,
		)

		return nil, 0
	}

	if size == 0 {
		_ = reader.Close()

		return nil, 0
	}

	return reader, size
}

// processFromSourceOrFetch processes an image, using cached source content
// if available.
func (s *Service) processFromSourceOrFetch(
	ctx context.Context,
	req *imagerequest.Request,
	cacheKey imagerequest.VariantKey,
) (*processedVariant, error) {
	// Check if we have cached source content
	sourceKey, err := s.cache.LookupSource(ctx, req)
	if err != nil {
		s.log.Warn("source lookup failed", "error", err)
	}

	var (
		source     io.ReadCloser
		sourceSize int64
	)

	if sourceKey != "" {
		s.log.Debug("using cached source", "source_key", sourceKey)
		source, sourceSize = s.loadCachedSource(sourceKey)
	}

	// Fetch from upstream if we don't have source data or it's empty
	if source == nil {
		return s.fetchAndProcess(ctx, req, cacheKey)
	}

	defer func() { _ = source.Close() }()

	// 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 s.processAndStore(ctx, req, cacheKey, source, 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.
func (s *Service) fetchAndProcess(
	ctx context.Context,
	req *imagerequest.Request,
	cacheKey imagerequest.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.Source.Host,
			"path", req.Source.Path,
		)

		return nil, fmt.Errorf("%w: %w", httpfetcher.ErrUpstreamError, ErrNegativeCached)
	}

	// Fetch from upstream
	s.log.Debug("fetching from upstream", "host", req.Source.Host,
		"path", req.Source.Path, "query", req.Source.Query)

	fetchResult, err := s.fetcher.Fetch(ctx, req.Source)
	if err != nil {
		// Store negative cache for certain errors
		if isNegativeCacheable(err) {
			s.storeNegative(ctx, req)
		}

		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() }()

	// Read and validate the source content
	sourceData, err := io.ReadAll(fetchResult.Content)
	fetchBytes := int64(len(sourceData))

	// Counted also when the request context has ended meanwhile
	s.cache.IncrementUpstreamFetch(fetchBytes)

	if err != nil {
		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
	s.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,
	)

	// 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.Source.Host, "path", req.Source.Path,
			"content_type", fetchResult.ContentType, "error", err)
		s.storeNegative(ctx, req)

		return nil, fmt.Errorf("content validation failed: %w", err)
	}

	// Store source content
	_, err = s.cache.StoreSource(ctx, req, bytes.NewReader(sourceData))
	if err != nil {
		s.log.Warn("failed to store source content", "error", err)
		// Continue even if caching fails
	}

	return s.processAndStore(
		ctx, req, cacheKey, bytes.NewReader(sourceData), fetchBytes,
	)
}

// storeNegative stores a negative cache entry for req's source, whose fetch
// failed, 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.Request) {
	err := s.cache.StoreNegative(ctx, req)
	if err != nil {
		s.log.Warn("failed to store negative cache entry",
			"host", req.Source.Host, "path", req.Source.Path, "error", err)
	}
}

// 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 {
	data         []byte
	contentType  string
	fetchedBytes int64
}

// processAndStore processes the image read from source and stores the
// result.
func (s *Service) processAndStore(
	ctx context.Context,
	req *imagerequest.Request,
	cacheKey imagerequest.VariantKey,
	source io.Reader,
	fetchBytes int64,
) (*processedVariant, error) {
	// Process the image
	processStart := time.Now()

	// ctx has the deadline of the request doing the processing, which can
	// end while a request waiting for its image has time left
	processResult, err := s.processor.Process(ctx, source, &req.Transform)
	if errors.Is(err, context.DeadlineExceeded) {
		return nil, fmt.Errorf("%w: %w", ErrProcessingTimedOut, err)
	}

	if err != nil {
		return nil, fmt.Errorf("image processing failed: %w", err)
	}

	processDuration := time.Since(processStart)

	// Counted also when the request context has ended meanwhile
	s.cache.IncrementTransformCount()

	// Read processed content
	processedData, err := io.ReadAll(processResult.Content)
	_ = processResult.Content.Close()

	if err != nil {
		return nil, fmt.Errorf("failed to read processed content: %w", err)
	}

	// Log conversion details
	outputSize := int64(len(processedData))

	var sizePercent float64
	if fetchBytes > 0 {
		//nolint:mnd // percentage calculation
		sizePercent = float64(outputSize) / float64(fetchBytes) * 100.0
	}

	s.log.Info("image converted",
		"request_id", middleware.GetReqID(ctx),
		"host", req.Source.Host,
		"path", req.Source.Path,
		"src_format", processResult.InputFormat,
		"dst_format", req.Transform.Format,
		"src_bytes", fetchBytes,
		"dst_bytes", outputSize,
		"src_dimensions", fmt.Sprintf("%dx%d",
			processResult.InputWidth, processResult.InputHeight),
		"dst_dimensions", fmt.Sprintf("%dx%d",
			processResult.Width, processResult.Height),
		"size_ratio", fmt.Sprintf("%.1f%%", sizePercent),
		"convert_ms", processDuration.Milliseconds(),
		"quality", req.Transform.Quality,
		"fit", req.Transform.FitMode,
	)

	// Store variant to cache
	err = s.cache.StoreVariant(ctx, cacheKey, bytes.NewReader(processedData))
	if err != nil {
		s.log.Warn("failed to store variant", "error", err)
		// Continue even if caching fails
	}

	return &processedVariant{
		data:         processedData,
		contentType:  processResult.ContentType,
		fetchedBytes: fetchBytes,
	}, nil
}

// isNegativeCacheable returns true if the error should be cached.
func isNegativeCacheable(err error) bool {
	return errors.Is(err, httpfetcher.ErrUpstreamError)
}

// 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 {
	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 + `"`
}