mirror of
https://github.com/navidrome/navidrome.git
synced 2026-10-10 19:37:08 +02:00
* fix(artwork): pause the artwork worker while a scan is running The artwork worker added in 0.64 writes to the database continuously, including while a scan runs. On slow storage the scanner holds the write lock for many seconds per folder, so the two writers keep timing each other out: artwork writes fail with "database is locked", and a single busy timeout on the scanner side aborts the whole scan. The worker now stops dispatching queue items while scanner.IsScanning reports true, including mid-batch, and resumes on the next poll after the scan ends. Artwork requests are unaffected, since they serve local art without the worker. * fix(db): run ANALYZE one index at a time so writers are not starved A full ANALYZE is a single write transaction, so every other write waits for it to finish and fails after the 15s busy timeout. On slow NAS storage it was measured taking over 26 minutes. The analysis now runs ANALYZE per index (per table for unindexed and WITHOUT ROWID tables), which produces the same sqlite_stat1 rows as a full ANALYZE, and pauses briefly between steps (up to 150ms, just above SQLite's longest busy-handler sleep) so waiting writers get the lock. * fix(scanner): ignore Synology @eaDir metadata folders Synology creates an @eaDir folder next to media files, holding one subfolder per file with generated thumbnails. The scanner and watcher treated them as regular folders, which on one reported library added tens of thousands of extra folders to every scan. * fix(db): analyze tables with only partial indexes as a whole A partial index does not record the table's row count, so a table whose only indexes are partial needs a table-level ANALYZE to get the sqlite_stat1 row a full ANALYZE would write. Navidrome's schema has no such table today, but the stepped analysis should match a full ANALYZE for any schema a future migration creates. * fix(scanner): retry busy folder saves and stop phase 1 on a fatal error On slow storage, a single SQLITE_BUSY while saving a folder aborted the whole scan, even when another writer held the lock only briefly. The folder save now runs as a retryable unit: on a busy error it waits (5s, 10s, 15s) and reruns the transaction, up to three times, before failing. Side effects that do not survive a rollback (the album ID map consumed by persistAlbum, the artwork queue items, the image-change record) are rebuilt per attempt or recorded only after a successful commit. When a folder save does fail, phase 1 used to keep walking the library and reading tags for every remaining folder, discarding the results, before reporting the error; a reporter saw 40 silent minutes. The walk now stops as soon as the save fails, and the walker honors cancellation instead of blocking on its channel. Because an early stop leaves folders unvisited, phase 1 no longer marks unvisited folders missing when the phase failed; the resumed scan handles them. * refactor(persistence): move busy retry into DataStore.WithTxRetry The scanner retried its folder save itself, which meant it had to know SQLite error codes. WithTxRetry now owns that policy: it reruns the block in a fresh transaction on SQLITE_BUSY, up to three times with growing delays, and runs it only once when already inside a transaction, since the outer transaction would still hold the lock. The block receives the context to use, and attempts that will be retried carry a marker so a busy statement in them is logged as a warning; only the final attempt logs errors. The scanner's inner error logs are folded into wrapped errors, so a recovered retry no longer prints error-level lines, and the folder path travels in the log context. * fix(persistence): join the enclosing transaction in a nested WithTxRetry Called on a store that is already inside a transaction, WithTxRetry went through WithTx, which opens a second, independent transaction on another connection. That transaction waits on the lock the outer one holds and fails with SQLITE_BUSY, and if it does succeed the outer transaction cannot roll it back. It now runs the block on the enclosing transaction, which owns the lock, the commit and the rollback. Found by a Codex (gpt-6-sol) review. * fix(scanner): retry the remaining scan writes on a busy database Every write step after phase 1 still aborted the whole scan on a single SQLITE_BUSY: phase 1 finalize, phase 2 moves and purge, phase 3 album saves and play count refreshes, the deferred playlist import flag, library ScanBegin, GC, the missing-artwork enqueue, tag counts, and the final library update. They now go through WithTxRetry. The phase 2 move had to be made rerun-safe first: it changed the target track's ID inside the transaction, so a rerun would have deleted the moved track itself, and it marked album annotations as handled even when the transaction rolled back. It now works on a copy per attempt and records the annotation reassignment only after a commit. Artist.RefreshStats is left alone: it updates artists in batches outside a transaction, and one transaction around all of them would hold the write lock for the whole refresh on slow storage. Phase 4 playlist imports go through the playlist service and are left for a follow-up. * fix(scanner): claim the album before moving its annotations The rerun-safe moveMatched checked processedAlbumAnnotations before its transaction and marked the album only after the commit. Phase 2 runs same-library and cross-library moves in separate pipeline stages, so two moves into one album could both pass the check; the second would reassign annotations again and overwrite the album's created_at. The album is now claimed under the lock before the transaction, as the old code effectively did, and the claim is released if the move fails so a later move can still reassign. Found by a Codex (gpt-6-sol) review. * fix(artwork): keep artwork housekeeping from writing during scans The artwork worker already pauses while a scan runs, but its housekeeping jobs did not: the hourly missing-artwork recheck (a bulk INSERT ... SELECT over albums and artists), the startup run of the same recheck, and the daily prune all kept competing with the scanner for the write lock. They now run through LockForMaintenance, like the scheduled DB analysis: they skip while a scan is running and keep a scan from starting until they finish. Skipping the recheck loses nothing, since each scan with changes queues missing artwork at its end. * refactor(scanner): log retried step errors once, from the caller Blocks passed to WithTxRetry still logged their own errors at error level on every attempt, so a busy error that a retry absorbed printed several error lines (GC printed three). They now return wrapped errors and the callers, which already log them, report the final outcome once. Also: drop a leftover variable in phase 1 finalize, check the walk context once, stop repeating the folder field that is already in the log context, stop shadowing finalize's err in phase 3, and format the WithTxRetry scope the same way as WithTx. * test(scanner): make the scanner suite's temp DB cleanup best effort Which DB file the process-wide DB handle opens depends on which spec touches it first. When the Scanner container wins the random order, its temp DB stays open until db.Close after RunSpecs, and on Windows removing the temp dir fails with 'being used by another process'. Ginkgo pins that on the container's last spec, which is now one of the busy-database specs. The sibling suites skip Windows for the same reason; this one now removes its temp dir on a best-effort basis instead, so it keeps running there.
350 lines
12 KiB
Go
350 lines
12 KiB
Go
package artwork
|
||
|
||
import (
|
||
"bytes"
|
||
"cmp"
|
||
"context"
|
||
"io"
|
||
"math"
|
||
"math/rand/v2"
|
||
"sync"
|
||
"time"
|
||
|
||
"github.com/navidrome/navidrome/conf"
|
||
"github.com/navidrome/navidrome/core/agents"
|
||
"github.com/navidrome/navidrome/core/auth"
|
||
"github.com/navidrome/navidrome/core/ffmpeg"
|
||
"github.com/navidrome/navidrome/log"
|
||
"github.com/navidrome/navidrome/model"
|
||
"github.com/navidrome/navidrome/server/events"
|
||
"github.com/navidrome/navidrome/utils/cache"
|
||
)
|
||
|
||
const (
|
||
workerPollInterval = 5 * time.Second
|
||
backoffBase = 5 * time.Second
|
||
// giveUpAfter bounds the retry budget from enqueue; past it the item settles and only an
|
||
// explicit reprocess retries it.
|
||
giveUpAfter = 12 * time.Hour
|
||
)
|
||
|
||
// drainPool drains one class of work with its own slot budget, so a blocking kind cannot
|
||
// occupy slots another kind needs.
|
||
type drainPool struct {
|
||
name string
|
||
kinds []string
|
||
concurrency int
|
||
}
|
||
|
||
// Worker drains the artwork queue: each external agent is rate-limited and circuit-broken
|
||
// independently, and pruneMu serializes prune against the store-write window.
|
||
type Worker struct {
|
||
proc *processor
|
||
cache cache.FileCache
|
||
ffmpeg ffmpeg.FFmpeg
|
||
broker events.Broker
|
||
pruneMu sync.RWMutex
|
||
pools []*drainPool
|
||
runCtx context.Context
|
||
paused func() bool
|
||
|
||
gatesMu sync.Mutex
|
||
gates map[string]*extGate
|
||
}
|
||
|
||
func NewWorker(ds model.DataStore, store *ImageStore, ag *agents.Agents, ffmpeg ffmpeg.FFmpeg, broker events.Broker, imgCache cache.FileCache) *Worker {
|
||
w := &Worker{
|
||
proc: &processor{ds: ds, store: store},
|
||
cache: imgCache,
|
||
ffmpeg: ffmpeg,
|
||
broker: broker,
|
||
pools: newDrainPools(),
|
||
runCtx: context.Background(),
|
||
paused: func() bool { return false },
|
||
gates: map[string]*extGate{},
|
||
}
|
||
w.proc.resolver = newResolver(ds, ag, ffmpeg, w.gate)
|
||
w.proc.pruneLock = w.pruneMu.RLocker()
|
||
return w
|
||
}
|
||
|
||
// newDrainPools splits the drain by what bounds it: gate() holds a slot while waiting for its
|
||
// rate-limit permit, so a sleeping lookup would crowd out a cover sitting on disk.
|
||
func newDrainPools() []*drainPool {
|
||
budget := conf.MaxOpenConns() // floored at 4, so both remainders below stay positive
|
||
local := min(max(1, conf.Server.DevArtworkWorkerConcurrency), budget-1)
|
||
// More external slots than the rate allows would only sleep in the limiter.
|
||
external := min(max(2, 2*conf.Server.DevArtworkExternalMaxRPS), budget-local)
|
||
return []*drainPool{
|
||
{name: "local", kinds: localDrainKinds, concurrency: local},
|
||
{name: "external", kinds: externalDrainKinds, concurrency: external},
|
||
}
|
||
}
|
||
|
||
// Kind is a proxy for cost: an album that reaches an external agent still costs a local slot.
|
||
var (
|
||
externalDrainKinds = []string{model.KindArtistArtwork.Prefix()}
|
||
localDrainKinds = []string{
|
||
model.KindAlbumArtwork.Prefix(),
|
||
model.KindPlaylistArtwork.Prefix(),
|
||
model.KindRadioArtwork.Prefix(),
|
||
model.KindMediaFileArtwork.Prefix(),
|
||
}
|
||
)
|
||
|
||
// PauseWhile holds off queue draining whenever paused reports true. Call it before Run.
|
||
func (w *Worker) PauseWhile(paused func() bool) {
|
||
w.paused = paused
|
||
}
|
||
|
||
// Run blocks draining the queue until ctx is cancelled.
|
||
func (w *Worker) Run(ctx context.Context) error {
|
||
w.runCtx = ctx
|
||
var wg sync.WaitGroup
|
||
for _, p := range w.pools {
|
||
wg.Go(func() { w.runPool(ctx, p) })
|
||
}
|
||
wg.Wait()
|
||
return nil
|
||
}
|
||
|
||
func (w *Worker) runPool(ctx context.Context, p *drainPool) {
|
||
ticker := time.NewTicker(workerPollInterval)
|
||
defer ticker.Stop()
|
||
for {
|
||
n, err := w.drain(ctx, p.concurrency, p.kinds...)
|
||
if err != nil && ctx.Err() == nil {
|
||
log.Warn(ctx, "Artwork: Worker drain failed", "pool", p.name, err)
|
||
}
|
||
if ctx.Err() != nil {
|
||
return
|
||
}
|
||
if n > 0 {
|
||
continue
|
||
}
|
||
select {
|
||
case <-ctx.Done():
|
||
return
|
||
case <-ticker.C:
|
||
}
|
||
}
|
||
}
|
||
|
||
// RunPrune runs prune under the worker's write lock, so no acquisition can place
|
||
// a file while orphans are being reclaimed. This is the only sanctioned prune path.
|
||
func (w *Worker) RunPrune(ctx context.Context) error {
|
||
w.pruneMu.Lock()
|
||
defer w.pruneMu.Unlock()
|
||
return prune(ctx, w.proc.ds, w.proc.store)
|
||
}
|
||
|
||
// ReconcileConfig records the artwork config fingerprint, or warns when it changed.
|
||
func (w *Worker) ReconcileConfig(ctx context.Context) error {
|
||
return ReconcileConfigFingerprint(ctx, w.proc.ds)
|
||
}
|
||
|
||
// EnqueueMissingAll requeues entities with no artwork state row: the safety net for anything
|
||
// a scan never enqueued.
|
||
func (w *Worker) EnqueueMissingAll(ctx context.Context) error {
|
||
return enqueueMissingAll(ctx, w.proc.ds)
|
||
}
|
||
|
||
func (w *Worker) drain(ctx context.Context, concurrency int, kinds ...string) (int, error) {
|
||
if w.paused() {
|
||
return 0, nil
|
||
}
|
||
// Dequeue well past the pool size so a slow external lookup never idles the other slots.
|
||
// DequeueBatch does not mark rows taken, so this is one query per pass, not per slot.
|
||
items, err := w.proc.ds.ArtworkQueue(ctx).DequeueBatch(max(16, 4*concurrency), kinds...)
|
||
if err != nil {
|
||
return 0, err
|
||
}
|
||
if len(items) == 0 {
|
||
return 0, nil
|
||
}
|
||
drainStart := time.Now()
|
||
// Private playlists need an admin identity; resolved per drain because the worker can
|
||
// start before any admin exists.
|
||
ctx = auth.WithAdminUser(ctx, w.proc.ds)
|
||
sem := make(chan struct{}, concurrency)
|
||
var wg sync.WaitGroup
|
||
var refreshMu sync.Mutex
|
||
var refresh []model.ArtworkQueueItem
|
||
for _, item := range items {
|
||
select {
|
||
case sem <- struct{}{}:
|
||
case <-ctx.Done():
|
||
}
|
||
// select picks randomly when both cases are ready, so re-check to never dispatch after cancellation.
|
||
if ctx.Err() != nil {
|
||
wg.Wait()
|
||
return len(items), nil //nolint:nilerr // a cancelled drain is a clean stop, not an error
|
||
}
|
||
if w.paused() {
|
||
break
|
||
}
|
||
wg.Go(func() {
|
||
defer func() { <-sem }()
|
||
out, got := w.process(ctx, item)
|
||
// Absent counts as a visible change too: clients must drop a previously-served
|
||
// immutable cover.
|
||
if out == outcomeFound || out == outcomeFoundStale || out == outcomeAbsent {
|
||
refreshMu.Lock()
|
||
refresh = append(refresh, item)
|
||
refreshMu.Unlock()
|
||
}
|
||
// Post-outcome: the queue row is already settled, so warming the cache can't
|
||
// block or alter queue ops.
|
||
if got != nil {
|
||
w.precache(ctx, got)
|
||
}
|
||
})
|
||
}
|
||
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
|
||
}
|
||
|
||
// artworkKindToResource maps a kind to its UI resource name; media_file maps to "song", so
|
||
// this can't derive from Kind.String().
|
||
var artworkKindToResource = map[model.Kind]string{
|
||
model.KindAlbumArtwork: "album",
|
||
model.KindArtistArtwork: "artist",
|
||
model.KindPlaylistArtwork: "playlist",
|
||
model.KindRadioArtwork: "radio",
|
||
model.KindMediaFileArtwork: "song",
|
||
}
|
||
|
||
// broadcastRefresh emits one coalesced RefreshResource for the batch, so UIs re-fetch the
|
||
// affected records and pick up the new coverArt id.
|
||
func (w *Worker) broadcastRefresh(ctx context.Context, found []model.ArtworkQueueItem) {
|
||
if len(found) == 0 {
|
||
return
|
||
}
|
||
event := &events.RefreshResource{}
|
||
byResource := map[string][]string{}
|
||
for _, it := range found {
|
||
kind, _ := model.ParseKind(it.ItemKind)
|
||
if res, ok := artworkKindToResource[kind]; ok {
|
||
byResource[res] = append(byResource[res], it.ItemID)
|
||
}
|
||
}
|
||
if len(byResource) == 0 {
|
||
return
|
||
}
|
||
for res, ids := range byResource {
|
||
event = event.With(res, ids...)
|
||
}
|
||
w.broker.SendBroadcastMessage(ctx, event)
|
||
}
|
||
|
||
func (w *Worker) process(ctx context.Context, item model.ArtworkQueueItem) (outcome, *acquired) {
|
||
item.ImageType = cmp.Or(item.ImageType, model.ImageTypePrimary)
|
||
trace := &ChainTrace{}
|
||
ctx = withTrace(ctx, trace)
|
||
out, got, retryIn := w.proc.acquire(ctx, item)
|
||
|
||
queue := w.proc.ds.ArtworkQueue(ctx)
|
||
switch out {
|
||
case outcomeFound, outcomeAbsent:
|
||
// A scan that re-enqueued this row mid-flight reset its retry_at, so the row survives
|
||
// here and the next drain re-resolves it.
|
||
if err := queue.DeleteIfUnchanged(item.ItemKind, item.ItemID, item.ImageType, item.RetryAt); err != nil {
|
||
log.Warn(ctx, "Artwork: Could not delete processed queue item", "kind", item.ItemKind, "id", item.ItemID, err)
|
||
}
|
||
case outcomeFoundStale, outcomeFailed:
|
||
retryAt := time.Now().Add(retryDelay(item.Attempts, retryIn))
|
||
encoded := trace.encode("")
|
||
if retryAt.Before(item.EnqueuedAt.Add(giveUpAfter)) {
|
||
// A mid-flight re-enqueue reset retry_at; stale backoff must not stomp its
|
||
// fresh, immediate eligibility.
|
||
if err := queue.MarkFailedIfUnchanged(item.ItemKind, item.ItemID, item.ImageType, item.RetryAt, retryAt, encoded); 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
|
||
}
|
||
// Art already being served is kept: exhaustion means unreachable, not removed.
|
||
settled := "kept previous state"
|
||
if out == outcomeFailed && settlesAbsentOnGiveUp(item.ItemKind) && !w.hasResolvedArtwork(ctx, item) {
|
||
writeAbsent(ctx, w.proc.ds.Artwork(ctx), item)
|
||
settled = "recorded absent"
|
||
}
|
||
// The queue row is about to go, taking the only record of the failure with it. This write is
|
||
// unconditional (not CAS-guarded) — safe only because the drain resolves each item serially.
|
||
w.recordGiveUp(ctx, item, encoded)
|
||
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)
|
||
}
|
||
}
|
||
return out, got
|
||
}
|
||
|
||
// recordGiveUp keeps the last failure on the state row after the queue row is deleted. An item
|
||
// that never resolved has no row to update, and creating one would settle it absent.
|
||
func (w *Worker) recordGiveUp(ctx context.Context, item model.ArtworkQueueItem, trace string) {
|
||
kind, ok := model.ParseKind(item.ItemKind)
|
||
if !ok {
|
||
return
|
||
}
|
||
if err := w.proc.ds.Artwork(ctx).PutLastFailure(kind, item.ItemID, item.ImageType, trace); err != nil {
|
||
log.Warn(ctx, "Artwork: Could not record the last failure", "kind", item.ItemKind, "id", item.ItemID, err)
|
||
}
|
||
}
|
||
|
||
func (w *Worker) hasResolvedArtwork(ctx context.Context, item model.ArtworkQueueItem) bool {
|
||
kind, ok := model.ParseKind(item.ItemKind)
|
||
if !ok {
|
||
return false
|
||
}
|
||
ia, err := w.proc.ds.Artwork(ctx).GetItemArtwork(kind, item.ItemID, item.ImageType)
|
||
return err == nil && ia.Hash != ""
|
||
}
|
||
|
||
// precache warms the resize cache at the UI cover size from the bytes just acquired, so the
|
||
// first UI request hits without re-reading the rows or the file.
|
||
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: square must match what the list surfaces request, or this
|
||
// warms a key nothing reads.
|
||
item := &resizedItem{
|
||
hash: got.ia.Hash,
|
||
size: conf.Server.UICoverArtSize,
|
||
square: true,
|
||
ffmpeg: w.ffmpeg,
|
||
open: func() (io.ReadCloser, error) { return io.NopCloser(bytes.NewReader(got.data)), nil },
|
||
}
|
||
stream, err := w.cache.Get(ctx, item)
|
||
if err != nil {
|
||
log.Debug(ctx, "Artwork: Precache failed", "kind", got.ia.ItemKind, "id", got.ia.ItemID, err)
|
||
return
|
||
}
|
||
_, _ = 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].
|
||
func backoffFor(attempts int, jitter float64) time.Duration {
|
||
d := min(float64(backoffBase)*math.Pow(4, float64(attempts)), float64(giveUpAfter))
|
||
return time.Duration(d * (1 + jitter))
|
||
}
|
||
|
||
func backoff(attempts int) time.Duration {
|
||
return backoffFor(attempts, rand.Float64()*0.8-0.4) //nolint:gosec // retry jitter, not security-sensitive
|
||
}
|
||
|
||
// retryDelay is how long a failed item waits: our backoff, unless the provider asked for longer.
|
||
func retryDelay(attempts int, hint time.Duration) time.Duration {
|
||
return max(backoff(attempts), hint)
|
||
}
|