navidrome/scanner/phase_2_missing_tracks.go
Deluan Quintão ee6dd1bc03
fix(scanner): stop DB lock starvation during scans on slow storage (#6201)
* 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.
2026-09-23 17:04:50 -04:00

381 lines
13 KiB
Go

package scanner
import (
"context"
"errors"
"fmt"
"sync"
"sync/atomic"
ppl "github.com/google/go-pipeline/pkg/pipeline"
"github.com/navidrome/navidrome/conf"
"github.com/navidrome/navidrome/consts"
"github.com/navidrome/navidrome/log"
"github.com/navidrome/navidrome/model"
)
type missingTracks struct {
lib model.Library
pid string
missing model.MediaFiles
matched model.MediaFiles
}
// phaseMissingTracks is responsible for processing missing media files during the scan process.
// It identifies media files that are marked as missing and attempts to find matching files that
// may have been moved or renamed. This phase helps in maintaining the integrity of the media
// library by ensuring that moved or renamed files are correctly updated in the database.
//
// The phaseMissingTracks phase performs the following steps:
// 1. Loads all libraries and their missing media files from the database.
// 2. For each library, it sorts the missing files by their PID (persistent identifier).
// 3. Groups missing and matched files by their PID and processes them to find exact or equivalent matches.
// 4. Updates the database with the new locations of the matched files and removes the old entries.
// 5. Logs the results and finalizes the phase by reporting the total number of matched files.
type phaseMissingTracks struct {
ctx context.Context
ds model.DataStore
totalMatched atomic.Uint32
state *scanState
processedAlbumAnnotations map[string]bool // Track processed album annotation reassignments
annotationMutex sync.RWMutex // Protects processedAlbumAnnotations
}
func createPhaseMissingTracks(ctx context.Context, state *scanState, ds model.DataStore) *phaseMissingTracks {
return &phaseMissingTracks{
ctx: ctx,
ds: ds,
state: state,
processedAlbumAnnotations: make(map[string]bool),
}
}
func (p *phaseMissingTracks) description() string {
return "Process missing files, checking for moves"
}
func (p *phaseMissingTracks) producer() ppl.Producer[*missingTracks] {
return ppl.NewProducer(p.produce, ppl.Name("load missing tracks from db"))
}
func (p *phaseMissingTracks) produce(put func(tracks *missingTracks)) error {
count := 0
var putIfMatched = func(mt missingTracks) {
if mt.pid != "" && len(mt.missing) > 0 {
log.Trace(p.ctx, "Scanner: Found missing tracks", "pid", mt.pid, "missing", "title", mt.missing[0].Title,
len(mt.missing), "matched", len(mt.matched), "lib", mt.lib.Name,
)
count++
put(&mt)
}
}
for _, lib := range p.state.libraries {
log.Debug(p.ctx, "Scanner: Checking missing tracks", "libraryId", lib.ID, "libraryName", lib.Name)
cursor, err := p.ds.MediaFile(p.ctx).GetMissingAndMatching(lib.ID)
if err != nil {
return fmt.Errorf("loading missing tracks for library %s: %w", lib.Name, err)
}
// Group missing and matched tracks by PID
mt := missingTracks{lib: lib}
for mf, err := range cursor {
if err != nil {
return fmt.Errorf("loading missing tracks for library %s: %w", lib.Name, err)
}
if mt.pid != mf.PID {
putIfMatched(mt)
mt.pid = mf.PID
mt.missing = nil
mt.matched = nil
}
if mf.Missing {
mt.missing = append(mt.missing, mf)
} else {
mt.matched = append(mt.matched, mf)
}
}
putIfMatched(mt)
if count == 0 {
log.Debug(p.ctx, "Scanner: No potential moves found", "libraryId", lib.ID, "libraryName", lib.Name)
} else {
log.Debug(p.ctx, "Scanner: Found potential moves", "libraryId", lib.ID, "count", count)
}
}
return nil
}
func (p *phaseMissingTracks) stages() []ppl.Stage[*missingTracks] {
return []ppl.Stage[*missingTracks]{
ppl.NewStage(p.processMissingTracks, ppl.Name("process missing tracks")),
ppl.NewStage(p.processCrossLibraryMoves, ppl.Name("process cross-library moves")),
}
}
func (p *phaseMissingTracks) processMissingTracks(in *missingTracks) (*missingTracks, error) {
hasMatches := false
// Track which matched entries have already been consumed, so each matched track
// is only used once. Without this, the same matched track could be paired with
// multiple missing tracks, creating duplicate records with the same path.
usedMatched := make(map[string]bool, len(in.matched))
for _, ms := range in.missing {
var exactMatch model.MediaFile
var equivalentMatch model.MediaFile
// Identify exact and equivalent matches
for _, mt := range in.matched {
if usedMatched[mt.ID] {
continue
}
if ms.Equals(mt) {
exactMatch = mt
break // Prioritize exact match
}
if ms.IsEquivalent(mt) {
equivalentMatch = mt
}
}
// Use the exact match if found
if exactMatch.ID != "" {
log.Debug(p.ctx, "Scanner: Found missing track in a new place", "missing", ms.Path, "movedTo", exactMatch.Path, "lib", in.lib.Name)
err := p.moveMatched(exactMatch, ms)
if err != nil {
log.Error(p.ctx, "Scanner: Error moving matched track", "missing", ms.Path, "movedTo", exactMatch.Path, "lib", in.lib.Name, err)
return nil, err
}
usedMatched[exactMatch.ID] = true
p.totalMatched.Add(1)
hasMatches = true
continue
}
// If there is only one missing and one matched track, consider them equivalent (same PID)
if len(in.missing) == 1 && len(in.matched) == 1 && !usedMatched[in.matched[0].ID] {
singleMatch := in.matched[0]
log.Debug(p.ctx, "Scanner: Found track with same persistent ID in a new place", "missing", ms.Path, "movedTo", singleMatch.Path, "lib", in.lib.Name)
err := p.moveMatched(singleMatch, ms)
if err != nil {
log.Error(p.ctx, "Scanner: Error updating matched track", "missing", ms.Path, "movedTo", singleMatch.Path, "lib", in.lib.Name, err)
return nil, err
}
usedMatched[singleMatch.ID] = true
p.totalMatched.Add(1)
hasMatches = true
continue
}
// Use the equivalent match if no other better match was found
if equivalentMatch.ID != "" {
log.Debug(p.ctx, "Scanner: Found missing track with same base path", "missing", ms.Path, "movedTo", equivalentMatch.Path, "lib", in.lib.Name)
err := p.moveMatched(equivalentMatch, ms)
if err != nil {
log.Error(p.ctx, "Scanner: Error updating matched track", "missing", ms.Path, "movedTo", equivalentMatch.Path, "lib", in.lib.Name, err)
return nil, err
}
usedMatched[equivalentMatch.ID] = true
p.totalMatched.Add(1)
hasMatches = true
}
}
// If any matches were found in this missingTracks group, return nil
// This signals the next stage to skip processing this group
if hasMatches {
return nil, nil
}
// If no matches found, pass through to next stage
return in, nil
}
// processCrossLibraryMoves processes files that weren't matched within their library
// and attempts to find matches in other libraries
func (p *phaseMissingTracks) processCrossLibraryMoves(in *missingTracks) (*missingTracks, error) {
// Skip if input is nil (meaning previous stage found matches)
if in == nil {
return nil, nil
}
// Skip cross-library move detection when only one library is configured
// since there are no other libraries to search in.
if p.state.totalLibraryCount == 1 {
log.Debug(p.ctx, "Scanner: Skipping cross-library move detection (single library)")
return in, nil
}
log.Debug(p.ctx, "Scanner: Processing cross-library moves", "pid", in.pid, "missing", len(in.missing), "lib", in.lib.Name)
for _, missing := range in.missing {
found, err := p.findCrossLibraryMatch(missing)
if err != nil {
log.Error(p.ctx, "Scanner: Error searching for cross-library matches", "missing", missing.Path, "lib", in.lib.Name, err)
continue
}
if found.ID != "" {
log.Debug(p.ctx, "Scanner: Found cross-library moved track", "missing", missing.Path, "movedTo", found.Path, "fromLib", in.lib.Name, "toLib", found.LibraryName)
err := p.moveMatched(found, missing)
if err != nil {
log.Error(p.ctx, "Scanner: Error moving cross-library track", "missing", missing.Path, "movedTo", found.Path, err)
continue
}
p.totalMatched.Add(1)
}
}
return in, nil
}
// findCrossLibraryMatch searches for a missing file in other libraries using two-tier matching
func (p *phaseMissingTracks) findCrossLibraryMatch(missing model.MediaFile) (model.MediaFile, error) {
// First tier: Search by MusicBrainz Track ID if available
if missing.MbzReleaseTrackID != "" {
matches, err := p.ds.MediaFile(p.ctx).FindRecentFilesByMBZTrackID(missing, missing.CreatedAt)
if err != nil {
log.Error(p.ctx, "Scanner: Error searching for recent files by MBZ Track ID", "mbzTrackID", missing.MbzReleaseTrackID, err)
} else {
// Apply the same matching logic as within-library matching
for _, match := range matches {
if missing.Equals(match) {
return match, nil // Exact match found
}
}
// If only one match and it's equivalent, use it
if len(matches) == 1 && missing.IsEquivalent(matches[0]) {
return matches[0], nil
}
}
}
// Second tier: Search by intrinsic properties (title, size, suffix, etc.)
matches, err := p.ds.MediaFile(p.ctx).FindRecentFilesByProperties(missing, missing.CreatedAt)
if err != nil {
log.Error(p.ctx, "Scanner: Error searching for recent files by properties", "missing", missing.Path, err)
return model.MediaFile{}, err
}
// Apply the same matching logic as within-library matching
for _, match := range matches {
if missing.Equals(match) {
return match, nil // Exact match found
}
}
// If only one match and it's equivalent, use it
if len(matches) == 1 && missing.IsEquivalent(matches[0]) {
return matches[0], nil
}
return model.MediaFile{}, nil
}
func (p *phaseMissingTracks) moveMatched(target, missing model.MediaFile) error {
oldAlbumID := missing.AlbumID
newAlbumID := target.AlbumID
// Use newAlbumID as key since we only care about avoiding duplicate reassignments to the same target.
// Claimed before the transaction so a concurrent move skips it, and released if the move fails.
reassignAlbum := oldAlbumID != newAlbumID
if reassignAlbum {
p.annotationMutex.Lock()
reassignAlbum = !p.processedAlbumAnnotations[newAlbumID]
p.processedAlbumAnnotations[newAlbumID] = true
p.annotationMutex.Unlock()
if !reassignAlbum {
log.Trace(p.ctx, "Scanner: Skipping album annotation reassignment", "from", oldAlbumID, "to", newAlbumID)
}
}
err := p.ds.WithTxRetry(p.ctx, func(ctx context.Context, tx model.DataStore) error {
// A rerun must start from the original target, not the one the rolled-back attempt changed
moved := target
// Preserve the original created_at from the missing file, so moved tracks
// don't appear in "Recently Added"
moved.CreatedAt = missing.CreatedAt
// Update the target media file with the missing file's ID. This effectively "moves" the track
// to the new location while keeping its annotations and references intact.
moved.ID = missing.ID
if err := tx.MediaFile(ctx).Put(&moved); err != nil {
return fmt.Errorf("update matched track: %w", err)
}
// Discard the new mediafile row (the one that was moved to)
if err := tx.MediaFile(ctx).Delete(target.ID); err != nil {
return fmt.Errorf("delete discarded track: %w", err)
}
if reassignAlbum {
// Reassign direct album annotations (starred, rating)
log.Debug(ctx, "Scanner: Reassigning album annotations", "from", oldAlbumID, "to", newAlbumID)
if err := tx.Album(ctx).ReassignAnnotation(oldAlbumID, newAlbumID); err != nil {
log.Warn(ctx, "Scanner: Could not reassign album annotations", "from", oldAlbumID, "to", newAlbumID, err)
}
// Keep created_at field from previous instance of the album, so moved albums
// don't appear in "Recently Added"
if err := tx.Album(ctx).CopyAttributes(oldAlbumID, newAlbumID, "created_at"); err != nil {
if !errors.Is(err, model.ErrNotFound) {
log.Warn(ctx, "Scanner: Could not copy album created_at", "from", oldAlbumID, "to", newAlbumID, err)
}
}
// Note: RefreshPlayCounts will be called in later phases, so we don't need to call it here
}
return nil
}, "scanner: move matched track")
if err != nil {
if reassignAlbum {
p.annotationMutex.Lock()
delete(p.processedAlbumAnnotations, newAlbumID)
p.annotationMutex.Unlock()
}
return err
}
p.state.changesDetected.Store(true)
return nil
}
func (p *phaseMissingTracks) finalize(err error) error {
matched := p.totalMatched.Load()
if matched > 0 {
log.Info(p.ctx, "Scanner: Found moved files", "total", matched, err)
}
if err != nil {
return err
}
// Check if we should purge missing items
if conf.Server.Scanner.PurgeMissing == consts.PurgeMissingAlways || (conf.Server.Scanner.PurgeMissing == consts.PurgeMissingFull && p.state.fullScan) {
if err = p.purgeMissing(); err != nil {
log.Error(p.ctx, "Scanner: Error purging missing items", err)
}
}
return err
}
func (p *phaseMissingTracks) purgeMissing() error {
var deletedCount int64
err := p.ds.WithTxRetry(p.ctx, func(ctx context.Context, tx model.DataStore) error {
var err error
deletedCount, err = tx.MediaFile(ctx).DeleteAllMissing()
return err
}, "scanner: purge missing")
if err != nil {
return fmt.Errorf("error deleting missing files: %w", err)
}
if deletedCount > 0 {
log.Info(p.ctx, "Scanner: Purged missing items from the database", "mediaFiles", deletedCount)
// Set changesDetected to true so that garbage collection will run at the end of the scan process
p.state.changesDetected.Store(true)
} else {
log.Debug(p.ctx, "Scanner: No missing items to purge")
}
return nil
}
var _ phase[*missingTracks] = (*phaseMissingTracks)(nil)