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