diff --git a/core/artwork/artwork.go b/core/artwork/artwork.go index 6e3f54185..c293129c3 100644 --- a/core/artwork/artwork.go +++ b/core/artwork/artwork.go @@ -184,6 +184,8 @@ func openOriginal(ia *model.ItemArtwork, mime string, store *ImageStore) (io.Rea } if ia.RefMtime != 0 && info.ModTime().UnixNano() != ia.RefMtime { f.Close() + log.Debug("Artwork: Backing file changed since resolution", "path", ia.SourcePath, + "hash", ia.Hash, "resolvedMtime", ia.RefMtime, "currentMtime", info.ModTime().UnixNano()) return nil, errStaleSource } return f, nil @@ -196,6 +198,8 @@ func openOriginal(ia *model.ItemArtwork, mime string, store *ImageStore) (io.Rea return nil, err } if info.ModTime().UnixNano() != ia.RefMtime { + log.Debug("Artwork: Source file changed since resolution", "path", ia.SourcePath, + "hash", ia.Hash, "resolvedMtime", ia.RefMtime, "currentMtime", info.ModTime().UnixNano()) return nil, errStaleSource } } @@ -211,6 +215,8 @@ func (s *service) provisional(ctx context.Context, artID model.ArtworkID, size i return nil, err } s.enqueue(ctx, artID, model.ArtworkPriorityBump) + log.Debug(ctx, "Artwork: Provisional read-through, no state row yet", "artID", artID, + "source", res.source, "hit", res.reader != nil) return s.serveResolution(ctx, res, size, square) } @@ -322,6 +328,7 @@ func (s *service) serveDisc(ctx context.Context, artID model.ArtworkID, size int // dangling enqueues a re-resolution at Scan priority and reports the artwork as // unavailable, leaving the state row untouched. func (s *service) dangling(ctx context.Context, artID model.ArtworkID) (*Image, error) { + log.Debug(ctx, "Artwork: State row points at bytes we cannot serve, re-resolving", "artID", artID) s.enqueue(ctx, artID, model.ArtworkPriorityScan) return nil, ErrUnavailable } diff --git a/core/artwork/disc.go b/core/artwork/disc.go index 4344bf3e6..84d4543b3 100644 --- a/core/artwork/disc.go +++ b/core/artwork/disc.go @@ -152,7 +152,7 @@ func (d *discArtworkReader) fromDiscSubtitle(ctx context.Context, subtitle strin } f, err := d.lib.FS.Open(file) if err != nil { - log.Warn(ctx, "Could not open disc art file", "file", file, err) + log.Warn(ctx, "Artwork: Could not open disc art file", "file", file, err) continue } return f, file, nil @@ -210,7 +210,7 @@ func (d *discArtworkReader) fromExternalFile(ctx context.Context, pattern string name := strings.ToLower(path.Base(file)) match, err := filepath.Match(pattern, name) if err != nil { - log.Warn(ctx, "Error matching disc art file to pattern", "pattern", pattern, "file", file) + log.Warn(ctx, "Artwork: Error matching disc art file to pattern", "pattern", pattern, "file", file) continue } if !match { @@ -224,7 +224,7 @@ func (d *discArtworkReader) fromExternalFile(ctx context.Context, pattern string } f, err := d.lib.FS.Open(file) if err != nil { - log.Warn(ctx, "Could not open disc art file", "file", file, err) + log.Warn(ctx, "Artwork: Could not open disc art file", "file", file, err) continue } return f, file, nil @@ -240,7 +240,7 @@ func (d *discArtworkReader) fromExternalFile(ctx context.Context, pattern string for _, file := range fallbacks { f, err := d.lib.FS.Open(file) if err != nil { - log.Warn(ctx, "Could not open disc art file", "file", file, err) + log.Warn(ctx, "Artwork: Could not open disc art file", "file", file, err) continue } return f, file, nil diff --git a/core/artwork/folders_album.go b/core/artwork/folders_album.go index d5abee2ee..84099db6f 100644 --- a/core/artwork/folders_album.go +++ b/core/artwork/folders_album.go @@ -79,7 +79,7 @@ func albumRootParent(ctx context.Context, ds model.DataStore, folders []model.Fo } parent, err := ds.Folder(ctx).Get(commonParentID) if errors.Is(err, model.ErrNotFound) { - log.Warn(ctx, "Parent folder not found for album cover art lookup", "parentID", commonParentID) + log.Warn(ctx, "Artwork: Parent folder not found for album cover art lookup", "parentID", commonParentID) return nil, nil } if err != nil { diff --git a/core/artwork/folders_artist.go b/core/artwork/folders_artist.go index ec80a3fca..e411cdf9b 100644 --- a/core/artwork/folders_artist.go +++ b/core/artwork/folders_artist.go @@ -66,14 +66,14 @@ func fromArtistFolder(ctx context.Context, libFS fs.FS, libPath, artistFolder, p // messages so callers see absolute-looking paths consistent with the rest of // the artwork pipeline. func findImageInFolder(ctx context.Context, libFS fs.FS, relFolder, absFolder, pattern string) (io.ReadCloser, string, error) { - log.Trace(ctx, "Looking for artist image", "pattern", pattern, "folder", absFolder) + log.Trace(ctx, "Artwork: Looking for artist image", "pattern", pattern, "folder", absFolder) globPattern := pattern if relFolder != "." { globPattern = path.Join(escapeGlobLiteral(relFolder), pattern) } matches, err := fs.Glob(libFS, globPattern) if err != nil { - log.Warn(ctx, "Error matching artist image pattern", "pattern", pattern, "folder", absFolder, err) + log.Warn(ctx, "Artwork: Error matching artist image pattern", "pattern", pattern, "folder", absFolder, err) return nil, "", err } @@ -94,7 +94,7 @@ func findImageInFolder(ctx context.Context, libFS fs.FS, relFolder, absFolder, p for _, p := range imagePaths { f, err := libFS.Open(p) if err != nil { - log.Warn(ctx, "Could not open cover art file", "file", p, err) + log.Warn(ctx, "Artwork: Could not open cover art file", "file", p, err) openErr = fmt.Errorf("%w: %s: %w", errSourceUnreadable, p, err) continue } @@ -138,13 +138,13 @@ func loadArtistFolder(ctx context.Context, ds model.DataStore, albums model.Albu libPath := core.AbsolutePath(ctx, ds, libID, "") folderID := model.FolderID(model.Library{ID: libID, Path: libPath}, folderPath) - log.Trace(ctx, "Calculating artist folder details", "folderPath", folderPath, "folderID", folderID, + log.Trace(ctx, "Artwork: Calculating artist folder details", "folderPath", folderPath, "folderID", folderID, "libPath", libPath, "libID", libID, "albumPaths", paths) // Get the last update time for the folder folders, err := ds.Folder(ctx).GetAll(model.QueryOptions{Filters: squirrel.Eq{"folder.id": folderID, "missing": false}}) if err != nil || len(folders) == 0 { - log.Warn(ctx, "Could not find folder for artist", "folderPath", folderPath, "id", folderID, + log.Warn(ctx, "Artwork: Could not find folder for artist", "folderPath", folderPath, "id", folderID, "libPath", libPath, "libID", libID, err) return "", time.Time{}, err } diff --git a/core/artwork/gate.go b/core/artwork/gate.go index 0d7cf15df..68c281284 100644 --- a/core/artwork/gate.go +++ b/core/artwork/gate.go @@ -8,6 +8,7 @@ import ( "github.com/navidrome/navidrome/conf" "github.com/navidrome/navidrome/core/agents" + "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" "golang.org/x/time/rate" ) @@ -45,13 +46,20 @@ type extGate struct { func (w *Worker) gate(name string, f func() (io.ReadCloser, string, error)) (io.ReadCloser, string, error) { g := w.gateFor(name) if !g.breaker.allow() { + log.Debug(w.runCtx, "Artwork: Skipping agent, circuit breaker open", "agent", name) return nil, "", errBreakerOpen } + // Waiting for the rate-limit permit is counted separately: a slow agent and a throttled one + // look identical from the drain, but only one of them is the provider's fault. + waitStart := time.Now() if err := g.limiter.Wait(w.runCtx); err != nil { return nil, "", err } + callStart := time.Now() r, path, err := f() - g.breaker.record(err) + g.breaker.record(name, err) + log.Trace(w.runCtx, "Artwork: External agent call", "agent", name, "hit", r != nil, + "limiterWait", callStart.Sub(waitStart), "elapsed", time.Since(callStart), err) return r, path, err } @@ -96,17 +104,22 @@ func (b *breaker) allow() bool { return false } -func (b *breaker) record(err error) { +func (b *breaker) record(name string, err error) { b.mu.Lock() defer b.mu.Unlock() // A not-found (from either package) is a definitive answer, not a fault; only real // errors trip the breaker. Must stay consistent with isTransientExternal. if err == nil || errors.Is(err, model.ErrNotFound) || errors.Is(err, agents.ErrNotFound) { + if b.failures >= breakerThreshold { + log.Info("Artwork: Circuit breaker closed for agent", "agent", name) + } b.failures = 0 return } b.failures++ if b.failures == breakerThreshold { b.openedAt = time.Now() + log.Warn("Artwork: Circuit breaker opened for agent", "agent", name, + "consecutiveFailures", b.failures, "probeAfter", breakerProbeAfter, err) } } diff --git a/core/artwork/housekeeping.go b/core/artwork/housekeeping.go index fb7c9de4c..f5da3d0cc 100644 --- a/core/artwork/housekeeping.go +++ b/core/artwork/housekeeping.go @@ -48,6 +48,7 @@ func fingerprint() string { // backfill enqueues artwork resolution for every entity when the config fingerprint changed // (or was never stored), artists first so those pages resolve before the larger backlog. func backfill(ctx context.Context, ds model.DataStore) (bool, error) { + start := time.Now() ctx = auth.WithAdminUser(ctx, ds) current := fingerprint() props := ds.Property(ctx) @@ -82,7 +83,7 @@ func backfill(ctx context.Context, ds model.DataStore) (bool, error) { if err := props.Put(consts.ArtConfFingerprintPropertyKey, current); err != nil { return false, err } - log.Info(ctx, "Artwork: Config fingerprint changed, backfill enqueued") + log.Info(ctx, "Artwork: Config fingerprint changed, backfill enqueued", "elapsed", time.Since(start)) return true, nil } diff --git a/core/artwork/playlist_cover.go b/core/artwork/playlist_cover.go index fa5b09033..43047a6c6 100644 --- a/core/artwork/playlist_cover.go +++ b/core/artwork/playlist_cover.go @@ -30,7 +30,7 @@ func findPlaylistSidecarPath(ctx context.Context, plsPath string) string { entries, err := os.ReadDir(dir) if err != nil { - log.Warn(ctx, "Could not read directory for playlist sidecar", "dir", dir, err) + log.Warn(ctx, "Artwork: Could not read directory for playlist sidecar", "dir", dir, err) return "" } for _, entry := range entries { diff --git a/core/artwork/processor.go b/core/artwork/processor.go index 784921ec2..369600b13 100644 --- a/core/artwork/processor.go +++ b/core/artwork/processor.go @@ -31,6 +31,19 @@ const ( outcomeFailed ) +func (o outcome) String() string { + switch o { + case outcomeFound: + return "found" + case outcomeFoundStale: + return "foundStale" + case outcomeAbsent: + return "absent" + default: + return "failed" + } +} + // thumbnailSize is the max dimension fed to blurhash. const thumbnailSize = 128 @@ -61,8 +74,15 @@ type processor struct { // acquire resolves one queue item end to end: find an image, hash/decode/ // blurhash it, place its bytes, and persist the resulting state. -func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (outcome, *acquired) { +func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (out outcome, got *acquired) { repo := p.ds.Artwork(ctx) + // Timed on every exit, failures included: an item that is slow is usually one that failed + // slowly, and the outcome alone doesn't say whether the cost was the network or the decode. + start := time.Now() + defer func() { + log.Debug(ctx, "Artwork: Acquisition finished", "kind", item.ItemKind, "id", item.ItemID, + "outcome", out, "elapsed", time.Since(start)) + }() res, err := p.resolver.resolve(ctx, item) if err != nil { @@ -73,35 +93,48 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o if res.extError || res.localError { // A source errored/timed out rather than answering "no image": never settle on // absent, keep serving old state. + log.Debug(ctx, "Artwork: No image, but a source faulted; keeping previous state", + "kind", item.ItemKind, "id", item.ItemID, "extError", res.extError, "localError", res.localError) return outcomeFailed, nil } return writeAbsent(ctx, repo, item), nil } defer res.reader.Close() + // Times the download too: res.reader is the provider's response body for external sources. + readStart := time.Now() data, err := readCapped(res.reader) if err != nil { log.Warn(ctx, "Artwork: Failed to read resolved image", "kind", item.ItemKind, "id", item.ItemID, "source", res.source, err) return outcomeFailed, nil } - log.Debug(ctx, "Artwork: Read resolved image", "kind", item.ItemKind, "id", item.ItemID, "source", res.source, "bytes", len(data)) + log.Debug(ctx, "Artwork: Read resolved image", "kind", item.ItemKind, "id", item.ItemID, + "source", res.source, "bytes", len(data), "elapsed", time.Since(readStart)) + hashStart := time.Now() hash, err := hashImage(bytes.NewReader(data)) if err != nil { log.Warn(ctx, "Artwork: Failed to hash image", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } + log.Trace(ctx, "Artwork: Hashed image", "kind", item.ItemKind, "id", item.ItemID, + "hash", hash, "bytes", len(data), "elapsed", time.Since(hashStart)) art, err := repo.GetImage(hash) switch { case err == nil: // Dedup hit: identical bytes already known, reuse dims/mime/blurhash. + log.Debug(ctx, "Artwork: Reusing a known image, skipping decode", "kind", item.ItemKind, + "id", item.ItemID, "hash", hash) case errors.Is(err, model.ErrNotFound): + decodeStart := time.Now() art, err = decodeArtwork(ctx, hash, data) if err != nil { log.Warn(ctx, "Artwork: Failed to decode resolved image", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } + log.Debug(ctx, "Artwork: Decoded new image", "kind", item.ItemKind, "id", item.ItemID, "hash", hash, + "dims", fmt.Sprintf("%dx%d", art.Width, art.Height), "mime", art.Mime, "elapsed", time.Since(decodeStart)) default: log.Warn(ctx, "Artwork: Failed to look up image hash", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil @@ -113,8 +146,11 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o log.Warn(ctx, "Artwork: Failed to persist resolved image", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } - got := &acquired{ia: ia, mime: art.Mime, data: data} + got = &acquired{ia: ia, mime: art.Mime, data: data} if res.extError { + // Served, but a higher-priority external source errored: the pick may improve on retry. + log.Debug(ctx, "Artwork: Serving a lower-priority source after an external failure", + "kind", item.ItemKind, "id", item.ItemID, "source", res.source) return outcomeFoundStale, got } return outcomeFound, got @@ -166,6 +202,8 @@ func writeAbsent(ctx context.Context, repo model.ArtworkRepository, item model.A log.Warn(ctx, "Artwork: Failed to persist absent state", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed } + log.Debug(ctx, "Artwork: Settled absent, every source answered definitively", + "kind", item.ItemKind, "id", item.ItemID) return outcomeAbsent } diff --git a/core/artwork/prune.go b/core/artwork/prune.go index 265eb8262..88ef0177a 100644 --- a/core/artwork/prune.go +++ b/core/artwork/prune.go @@ -12,6 +12,8 @@ import ( const pruneMinAge = time.Hour func prune(ctx context.Context, ds model.DataStore, store *ImageStore) error { + start := time.Now() + defer func() { log.Debug(ctx, "Artwork: Prune finished", "elapsed", time.Since(start)) }() repo := ds.Artwork(ctx) purged, err := repo.PurgeDanglingItemArtwork() diff --git a/core/artwork/resize.go b/core/artwork/resize.go index e213cf5d0..58c8a2796 100644 --- a/core/artwork/resize.go +++ b/core/artwork/resize.go @@ -10,6 +10,7 @@ import ( "image/png" "io" "sync" + "time" "github.com/gen2brain/webp" "github.com/navidrome/navidrome/conf" @@ -27,9 +28,9 @@ func init() { // "nodynamic" tag (see Dockerfile), which makes webp.Dynamic() report an // error here and forces the safe WASM path. if err := webp.Dynamic(); err != nil { - log.Debug("Using WASM WebP encoder/decoder", "reason", err) + log.Debug("Artwork: Using WASM WebP encoder/decoder", "reason", err) } else { - log.Debug("Using native libwebp for WebP encoding/decoding") + log.Debug("Artwork: Using native libwebp for WebP encoding/decoding") } }) } @@ -43,6 +44,11 @@ var bufPool = sync.Pool{ // resizeImageData resizes raw image bytes to fit size, preserving animation where // possible. A nil reader means the image was already within bounds (no resize needed). func resizeImageData(ctx context.Context, ffm ffmpeg.FFmpeg, data []byte, size int, square bool) (io.Reader, int, error) { + start := time.Now() + defer func() { + log.Trace(ctx, "Artwork: Resized image", "bytes", len(data), "size", size, "square", square, + "elapsed", time.Since(start)) + }() // Preserve animation for animated images if isAnimatedGIF(data) { if ffm.IsAvailable() { @@ -51,7 +57,7 @@ func resizeImageData(ctx context.Context, ffm ffmpeg.FFmpeg, data []byte, size i if err == nil { return r, 0, nil } - log.Warn(ctx, "Could not convert animated GIF, falling back to static", err) + log.Warn(ctx, "Artwork: Could not convert animated GIF, falling back to static", err) } } else if isAnimatedWebP(data) || isAnimatedPNG(data) { // Animated WebP/APNG: return original as-is (ffmpeg can't re-encode these) diff --git a/core/artwork/sources.go b/core/artwork/sources.go index 4706db712..b2cd5be44 100644 --- a/core/artwork/sources.go +++ b/core/artwork/sources.go @@ -35,11 +35,11 @@ func selectImageReader(ctx context.Context, artID model.ArtworkID, extractFuncs start := time.Now() r, path, err := f() if r != nil { - msg := fmt.Sprintf("Found %s artwork", artID.Kind) + msg := fmt.Sprintf("Artwork: Found %s artwork", artID.Kind) log.Debug(ctx, msg, "artID", artID, "path", path, "source", f, "elapsed", time.Since(start)) return r, path, nil } - log.Trace(ctx, "Failed trying to extract artwork", "artID", artID, "source", f, "elapsed", time.Since(start), err) + log.Trace(ctx, "Artwork: Failed trying to extract artwork", "artID", artID, "source", f, "elapsed", time.Since(start), err) } return nil, "", fmt.Errorf("could not get `%s` cover art for %s: %w", artID.Kind, artID, ErrUnavailable) } @@ -63,7 +63,7 @@ func fromExternalFile(ctx context.Context, libFS fs.FS, files []string, pattern _, name := filepath.Split(file) match, err := filepath.Match(pattern, strings.ToLower(name)) if err != nil { - log.Warn(ctx, "Error matching cover art file to pattern", "pattern", pattern, "file", file) + log.Warn(ctx, "Artwork: Error matching cover art file to pattern", "pattern", pattern, "file", file) continue } if !match { @@ -71,7 +71,7 @@ func fromExternalFile(ctx context.Context, libFS fs.FS, files []string, pattern } f, err := libFS.Open(file) if err != nil { - log.Warn(ctx, "Could not open cover art file", "file", file, err) + log.Warn(ctx, "Artwork: Could not open cover art file", "file", file, err) openErr = fmt.Errorf("%w: %s: %w", errSourceUnreadable, file, err) continue } @@ -135,12 +135,12 @@ func findBestImageIndex(ctx context.Context, images []taglib.ImageDesc, path str for _, regex := range picTypeRegexes { for i, img := range images { if regex.MatchString(img.Type) { - log.Trace(ctx, "Found embedded image", "type", img.Type, "path", path) + log.Trace(ctx, "Artwork: Found embedded image", "type", img.Type, "path", path) return i } } } - log.Trace(ctx, "Could not find a front image. Getting the first one", "type", images[0].Type, "path", path) + log.Trace(ctx, "Artwork: Could not find a front image. Getting the first one", "type", images[0].Type, "path", path) return 0 } diff --git a/core/artwork/uploader.go b/core/artwork/uploader.go index 47c701d9b..2c3c380dd 100644 --- a/core/artwork/uploader.go +++ b/core/artwork/uploader.go @@ -62,7 +62,7 @@ func (s *uploader) SetImage(ctx context.Context, entityType string, entityID str // Remove old image if it exists if oldPath != "" { if err := os.Remove(oldPath); err != nil && !os.IsNotExist(err) { - log.Warn(ctx, "Failed to remove old image", "path", oldPath, err) + log.Warn(ctx, "Artwork: Failed to remove old image", "path", oldPath, err) } } @@ -87,7 +87,7 @@ func (s *uploader) EnqueueArtwork(ctx context.Context, entityType, id string) { return } if err := Refresh(ctx, s.ds, kind, id); err != nil { - log.Warn(ctx, "Could not refresh artwork after upload", "kind", kind, "id", id, err) + log.Warn(ctx, "Artwork: Could not refresh artwork after upload", "kind", kind, "id", id, err) } } diff --git a/core/artwork/worker.go b/core/artwork/worker.go index e3034ef3b..1e0a33444 100644 --- a/core/artwork/worker.go +++ b/core/artwork/worker.go @@ -188,6 +188,7 @@ func (w *Worker) drain(ctx context.Context, concurrency int, kinds ...string) (i if len(items) == 0 { return 0, nil } + drainStart := time.Now() // Resolved only once there is work, and per drain rather than per item: the worker needs an // admin identity for private playlists, and can start before any admin exists. ctx = auth.WithAdminUser(ctx, w.proc.ds) @@ -222,6 +223,8 @@ func (w *Worker) drain(ctx context.Context, concurrency int, kinds ...string) (i } wg.Wait() w.broadcastRefresh(ctx, refresh) + log.Debug(ctx, "Artwork: Drained a batch", "kinds", kinds, "items", len(items), + "refreshed", len(refresh), "concurrency", concurrency, "elapsed", time.Since(drainStart)) return len(items), nil } @@ -280,15 +283,22 @@ func (w *Worker) process(ctx context.Context, item model.ArtworkQueueItem) (outc if err := queue.MarkFailedIfUnchanged(item.ItemKind, item.ItemID, item.ImageType, item.RetryAt, retryAt); err != nil { log.Warn(ctx, "Artwork: Could not reschedule failed queue item", "kind", item.ItemKind, "id", item.ItemID, err) } + log.Debug(ctx, "Artwork: Rescheduled item", "kind", item.ItemKind, "id", item.ItemID, + "outcome", out, "attempts", item.Attempts+1, "retryIn", time.Until(retryAt), + "budgetLeft", time.Until(item.EnqueuedAt.Add(giveUpAfter))) break } // Retry budget exhausted: stop retrying. Absent is only recoverable where a periodic // recheck will revisit it, so kinds without one keep no row at all; and art already // being served is kept, since exhaustion means the source stayed unreachable rather // than that the entity lost its cover. + settled := "kept previous state" if out == outcomeFailed && hasRecheckPath(item.ItemKind) && !w.hasResolvedArtwork(ctx, item) { writeAbsent(ctx, w.proc.ds.Artwork(ctx), item) + settled = "recorded absent" } + log.Info(ctx, "Artwork: Retry budget exhausted, giving up", "kind", item.ItemKind, "id", item.ItemID, + "outcome", out, "attempts", item.Attempts+1, "budget", giveUpAfter, "settled", settled) if err := queue.DeleteIfUnchanged(item.ItemKind, item.ItemID, item.ImageType, item.RetryAt); err != nil { log.Warn(ctx, "Artwork: Could not remove exhausted queue item", "kind", item.ItemKind, "id", item.ItemID, err) } @@ -313,6 +323,7 @@ func (w *Worker) precache(ctx context.Context, got *acquired) { if !conf.Server.EnableArtworkPrecache || w.cache == nil || w.cache.Disabled(ctx) { return } + precacheStart := time.Now() // Same key as the serving path (hash/size/square); only the source of the bytes differs. // square matches what the list surfaces request, otherwise this warms a key nothing reads. item := &resizedItem{ @@ -329,6 +340,8 @@ func (w *Worker) precache(ctx context.Context, got *acquired) { } _, _ = io.Copy(io.Discard, stream) _ = stream.Close() + log.Trace(ctx, "Artwork: Precached UI size", "kind", got.ia.ItemKind, "id", got.ia.ItemID, + "size", conf.Server.UICoverArtSize, "elapsed", time.Since(precacheStart)) } // backoffFor returns min(5s×4^n, giveUpAfter) scaled by (1+jitter), with jitter in [-0.4, 0.4]. diff --git a/core/artwork/worker_timing_test.go b/core/artwork/worker_timing_test.go index dbaed0a84..9b64fc53a 100644 --- a/core/artwork/worker_timing_test.go +++ b/core/artwork/worker_timing_test.go @@ -20,7 +20,7 @@ func TestArtworkBreakerHalfOpen(t *testing.T) { b := newBreaker() for range breakerThreshold { - b.record(errors.New("boom")) + b.record("agentA", errors.New("boom")) } g.Expect(b.allow()).To(BeFalse(), "breaker opens after consecutive errors") @@ -31,11 +31,11 @@ func TestArtworkBreakerHalfOpen(t *testing.T) { g.Expect(b.allow()).To(BeTrue(), "half-open: one probe is granted") g.Expect(b.allow()).To(BeFalse(), "only a single probe per interval") - b.record(errors.New("boom")) // probe fails -> stay open + b.record("agentA", errors.New("boom")) // probe fails -> stay open time.Sleep(breakerProbeAfter) g.Expect(b.allow()).To(BeTrue(), "another probe after the next interval") - b.record(nil) // probe succeeds -> close + b.record("agentA", nil) // probe succeeds -> close g.Expect(b.allow()).To(BeTrue(), "closed breaker admits freely") g.Expect(b.allow()).To(BeTrue()) })