mirror of
https://github.com/navidrome/navidrome.git
synced 2026-08-31 07:30:32 +00:00
feat(artwork): prefix every log message and time the slow steps
Prefix: 22 messages still logged unprefixed, so a line from this package was indistinguishable from any other subsystem's. All 40 now carry "Artwork: ", matching Scanner:/API:/Watcher: -- which earns its place because DevLogSourceLine is off by default. Timing on what can actually be slow: total per acquisition (on every exit, failures included), the read that also covers the provider download, hashing, decode+blurhash, resize, drain batch, precache, prune, backfill, and the external agent call -- with the rate-limiter wait counted separately, since a throttled agent and a slow one look identical from the drain. Debug coverage for states that were previously silent: dedup hit vs decode, settling absent, serving a lower-priority source after an external failure, retry scheduling with attempts and budget left, giving up when the budget runs out, breaker open/close per agent, provisional read-through, dangling state rows, and the mtime mismatch that makes art appear to vanish. outcome gained a String() so it reads as a name.
This commit is contained in:
Deluan
parent
764bf55723
commit
e0f1acd1a2
@ -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
|
||||
}
|
||||
|
||||
@ -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
|
||||
|
||||
@ -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 {
|
||||
|
||||
@ -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
|
||||
}
|
||||
|
||||
@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
@ -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
|
||||
}
|
||||
|
||||
|
||||
@ -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 {
|
||||
|
||||
@ -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
|
||||
}
|
||||
|
||||
|
||||
@ -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()
|
||||
|
||||
@ -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)
|
||||
|
||||
@ -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
|
||||
}
|
||||
|
||||
|
||||
@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -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].
|
||||
|
||||
@ -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())
|
||||
})
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user