From 3d3c3ed60186deb95461cd80b052e564fb9d2055 Mon Sep 17 00:00:00 2001 From: Daniel Barrientos Anariba <69573860+danielbanariba@users.noreply.github.com> Date: Thu, 20 Aug 2026 06:53:11 -0600 Subject: [PATCH 01/13] ci: lint with the golangci-lint version the Makefile declares (#5994) * ci: lint with the golangci-lint version the Makefile declares The workflow asked for `version: latest` while the Makefile pins `GOLANGCI_LINT_VERSION ?= v2.12.0`, so `make lint` and CI ran different linters. golangci-lint v2.13.0 started reporting G404 on three existing `rand.Shuffle` calls, which turned every PR red without a line of Go changing. Read the version from the Makefile instead of resolving `latest`, so the two stay in step and a new release cannot break unchanged code. * chore: re-run CI --- .github/workflows/pipeline.yml | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/.github/workflows/pipeline.yml b/.github/workflows/pipeline.yml index 8e6e8126a..b91c19505 100644 --- a/.github/workflows/pipeline.yml +++ b/.github/workflows/pipeline.yml @@ -68,10 +68,16 @@ jobs: with: go-version-file: go.mod + # Keep CI on the same version `make lint` installs, so a clean local run + # cannot turn red in CI just because a new golangci-lint was released. + - name: Resolve golangci-lint version + id: golangci-version + run: echo "version=$(grep '^GOLANGCI_LINT_VERSION' Makefile | cut -d ' ' -f 3)" >> "$GITHUB_OUTPUT" + - name: golangci-lint uses: golangci/golangci-lint-action@v9 with: - version: latest + version: ${{ steps.golangci-version.outputs.version }} problem-matchers: true args: --timeout 2m From fc1c1366dcfb18c6ac885fe271d04ec6fede8c2e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Thu, 20 Aug 2026 09:04:09 -0400 Subject: [PATCH 02/13] fix(cli): write `pls -p` playlist output to stdout (#5996) The export path used the `println` builtin, which writes to stderr, so `navidrome pls -p X > playlist.m3u8` produced an empty file while the M3U body was interleaved with the startup logs on stderr. `println` also appended a newline that `ToM3U8` already provides, so the piped output had a stray trailing blank line that `-o file` did not. Both destinations are now byte-identical. The stdout/file choice moved into a `writePlaylist` helper shared by `pls -p` and `pls export -p`, which both had the same bug. It takes the destination as an `io.Writer`, matching the existing convention in cmd/artwork.go. --- cmd/pls.go | 17 ++++++++++------- cmd/pls_test.go | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 45 insertions(+), 7 deletions(-) create mode 100644 cmd/pls_test.go diff --git a/cmd/pls.go b/cmd/pls.go index 184ca6fe7..93b411483 100644 --- a/cmd/pls.go +++ b/cmd/pls.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "io" "os" "path/filepath" "strconv" @@ -141,14 +142,16 @@ func findPlaylist(ctx context.Context, ds model.DataStore, nameOrID string) *mod func runExporter(ctx context.Context) { ds, ctx := getAdminContext(ctx) playlist := findPlaylist(ctx, ds, playlistID) - pls := playlist.ToM3U8() - if outputFile == "-" || outputFile == "" { - println(pls) + writePlaylist(playlist.ToM3U8(), os.Stdout, outputFile) +} + +func writePlaylist(m3u string, out io.Writer, file string) { + if file == "" || file == "-" { + fmt.Fprint(out, m3u) return } - err := os.WriteFile(outputFile, []byte(pls), 0600) - if err != nil { - log.Fatal("Error writing to the output file", "file", outputFile, err) + if err := os.WriteFile(file, []byte(m3u), 0600); err != nil { + log.Fatal("Error writing to the output file", "file", file, err) } } @@ -157,7 +160,7 @@ func runExport(ctx context.Context) { if playlistID != "" && outputFile == "" { playlist := findPlaylist(ctx, ds, playlistID) - println(playlist.ToM3U8()) + writePlaylist(playlist.ToM3U8(), os.Stdout, outputFile) return } diff --git a/cmd/pls_test.go b/cmd/pls_test.go new file mode 100644 index 000000000..f3e8c7edd --- /dev/null +++ b/cmd/pls_test.go @@ -0,0 +1,35 @@ +package cmd + +import ( + "fmt" + "os" + "path/filepath" + "strings" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +var _ = Describe("writePlaylist", func() { + const m3u = "#EXTM3U\n#PLAYLIST:DJ Wave\n#EXTINF:364,Bel Canto - Dreaming Girl\n" + plsFile := filepath.Join(os.TempDir(), fmt.Sprintf("navidrome-pls-%d.m3u8", os.Getpid())) + + BeforeEach(func() { + DeferCleanup(func() { _ = os.Remove(plsFile) }) + }) + + DescribeTable("writes the playlist to exactly one destination", + func(file, wantStream, wantFile string) { + var out strings.Builder + + writePlaylist(m3u, &out, file) + + written, _ := os.ReadFile(plsFile) + Expect(out.String()).To(Equal(wantStream)) + Expect(string(written)).To(Equal(wantFile)) + }, + Entry("no file name writes to the stream", "", m3u, ""), + Entry("a dash writes to the stream", "-", m3u, ""), + Entry("a path writes to the file", plsFile, "", m3u), + ) +}) From 17db7d40770bb30edffc675323e4329a9303288a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Thu, 20 Aug 2026 10:02:04 -0400 Subject: [PATCH 03/13] ci: pull base images through mirror.gcr.io instead of ECR Public (#5997) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CI builds were failing at random with: buildx failed with: toomanyrequests: Rate exceeded The 429 comes from public.ecr.aws, not Docker Hub. AWS caps unauthenticated ECR Public pulls at 1 per second per source IP (authenticated: 10/s). The build matrix starts 11 jobs at once and each resolves 4 base images, so roughly 44 anonymous pulls land in a couple of seconds — from GitHub runner IPs that are shared with every other GitHub customer. Measured against public.ecr.aws with an anonymous token, 60 requests at concurrency 30 returned 31x 429 in 0.48s. The same probe against mirror.gcr.io (Google's Docker Hub pull-through cache) returned zero errors: 750 manifest requests up to ~141 req/s, plus 120 layer blob requests at concurrency 60. Google publishes no rate limit for it, so this is measured headroom, not a contract — but it is roughly 10x the pipeline's peak rate, and cached pulls do not count against Docker Hub's limits either. Authenticating to ECR Public was the alternative. It was rejected because 10 pulls/s is still under the ~44-pull burst, it needs an AWS account plus a secret, and secrets never reach fork pull requests — so forks would keep failing. The mirror fixes forks too. Verified buildkit honours the mirror block by routing a build through a local logging registry: all 6 requests (manifests and blobs) hit the mirror, none went to Docker Hub directly. Confirmed mirror.gcr.io answers 200 for buildkit's "?ns=docker.io" query form on all four images, for both GET and HEAD. Confirmed buildkit falls back to Docker Hub when the mirror is unreachable — the build still succeeds, but the resolve takes ~30s instead of ~0.3s, so a mirror outage means slow builds, not broken ones. The existing Docker Hub login covers that fallback on main-repo runs. msitools.dockerfile is only used by the local `make docker-msi` target, but is switched over too so no ECR Public reference is left behind. --- .github/actions/prepare-docker/action.yml | 5 +++++ Dockerfile | 10 +++++----- release/wix/msitools.dockerfile | 2 +- 3 files changed, 11 insertions(+), 6 deletions(-) diff --git a/.github/actions/prepare-docker/action.yml b/.github/actions/prepare-docker/action.yml index b8cde4aaf..6cb54dbdb 100644 --- a/.github/actions/prepare-docker/action.yml +++ b/.github/actions/prepare-docker/action.yml @@ -68,6 +68,11 @@ runs: - name: Set up Docker Buildx id: buildx uses: docker/setup-buildx-action@v4 + with: + # Runner IPs are shared, so anonymous base image pulls get rate-limited. + buildkitd-config-inline: | + [registry."docker.io"] + mirrors = ["mirror.gcr.io"] - name: Extract metadata for Docker image id: meta diff --git a/Dockerfile b/Dockerfile index df5df52ab..847c19bf7 100644 --- a/Dockerfile +++ b/Dockerfile @@ -2,7 +2,7 @@ FROM --platform=$BUILDPLATFORM ghcr.io/crazy-max/osxcross:14.5-debian AS osxcros ######################################################################################################################## ### Build xx (original image: tonistiigi/xx) -FROM --platform=$BUILDPLATFORM public.ecr.aws/docker/library/alpine:3.20 AS xx-build +FROM --platform=$BUILDPLATFORM alpine:3.20 AS xx-build # v1.9.0 ENV XX_VERSION=a5592eab7a57895e8d385394ff12241bc65ecd50 @@ -26,7 +26,7 @@ COPY --from=xx-build /out/ /usr/bin/ ######################################################################################################################## ### Build Navidrome UI -FROM --platform=$BUILDPLATFORM public.ecr.aws/docker/library/node:lts-alpine AS ui +FROM --platform=$BUILDPLATFORM node:lts-alpine AS ui WORKDIR /app # Install node dependencies @@ -43,7 +43,7 @@ COPY --from=ui /build /build ######################################################################################################################## ### Build Navidrome binary for Docker image (dynamic musl, enables native libwebp via dlopen) -FROM --platform=$BUILDPLATFORM public.ecr.aws/docker/library/golang:1.26-alpine AS build-alpine +FROM --platform=$BUILDPLATFORM golang:1.26-alpine AS build-alpine COPY --from=xx / / ARG TARGETPLATFORM @@ -85,7 +85,7 @@ EOT ######################################################################################################################## ### Build Navidrome binary for standalone distribution (static glibc, cross-compiled) -FROM --platform=$BUILDPLATFORM public.ecr.aws/docker/library/golang:1.26-trixie AS base +FROM --platform=$BUILDPLATFORM golang:1.26-trixie AS base RUN apt-get update && apt-get install -y clang lld COPY --from=xx / / WORKDIR /workspace @@ -154,7 +154,7 @@ COPY --from=build /out / ######################################################################################################################## ### Build Final Image -FROM public.ecr.aws/docker/library/alpine:3.20 AS final +FROM alpine:3.20 AS final LABEL maintainer="deluan@navidrome.org" LABEL org.opencontainers.image.source="https://github.com/navidrome/navidrome" diff --git a/release/wix/msitools.dockerfile b/release/wix/msitools.dockerfile index 38364eb47..90249c1ce 100644 --- a/release/wix/msitools.dockerfile +++ b/release/wix/msitools.dockerfile @@ -1,3 +1,3 @@ -FROM public.ecr.aws/docker/library/alpine +FROM alpine RUN apk update && apk add jq msitools WORKDIR /workspace \ No newline at end of file From 0a55cc8cafdde9ab92aa0a207507dc2165ff1caf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Thu, 20 Aug 2026 22:48:26 -0400 Subject: [PATCH 04/13] docs(plugins): document how a metadata agent signals "not found" (#6001) A MetadataAgent plugin reports "I have no data for this item" by returning an empty response with a nil error. Any error it returns instead is treated as a plugin fault and retried with backoff. That rule was not documented anywhere, so an author naturally returns an error for a missing item, and Navidrome then retries every item the plugin's source does not cover. This is not hypothetical: the artist-nfo-metadata plugin returned an error for every artist without an artist.nfo, which kept those artists in the artwork retry queue for hours and tripped the artwork circuit breaker for the plugin as a whole. Document the rule on the capability interface, which ndpgen copies into the Go PDK, and in the MetadataAgent section of the plugin README. --- plugins/README.md | 8 ++++++++ plugins/capabilities/metadata_agent.go | 3 +++ plugins/pdk/go/metadata/metadata.go | 3 +++ plugins/pdk/go/metadata/metadata_stub.go | 3 +++ 4 files changed, 17 insertions(+) diff --git a/plugins/README.md b/plugins/README.md index b04e12bd9..7042b8c45 100644 --- a/plugins/README.md +++ b/plugins/README.md @@ -174,6 +174,14 @@ Capabilities define what your plugin can do. They're automatically detected base Provides artist and album metadata. All methods are **optional** — implement only the ones your data source supports. +> **Returning "not found".** When you have no data for an item, return an empty response and no +> error. In the Go PDK that is `return nil, nil`. Navidrome reads it as a definitive "not found" +> and stops asking. +> +> Return an error only when the plugin itself failed, such as an unreachable API or a broken host +> call. Navidrome retries failed calls with backoff. A plugin that errors on "no data" makes +> Navidrome retry every item it has no data for. + | Function | Input | Output | Description | |-----------------------------------|----------------------------|----------------------------------|--------------------------| | `nd_get_artist_mbid` | `{id, name}` | `{mbid}` | Get MusicBrainz ID | diff --git a/plugins/capabilities/metadata_agent.go b/plugins/capabilities/metadata_agent.go index f856562c6..72cb1622f 100644 --- a/plugins/capabilities/metadata_agent.go +++ b/plugins/capabilities/metadata_agent.go @@ -9,6 +9,9 @@ import "github.com/navidrome/navidrome/plugins/types" // Plugins implementing this capability can choose which methods to implement. // Each method is optional - plugins only need to provide the functionality they support. // +// To say "no data for this item", return a nil response and a nil error. Return an error only when +// the plugin itself failed, because Navidrome retries failed calls with backoff. +// //nd:capability name=metadata type MetadataAgent interface { // GetArtistMBID retrieves the MusicBrainz ID for an artist. diff --git a/plugins/pdk/go/metadata/metadata.go b/plugins/pdk/go/metadata/metadata.go index c561c2893..bb0ae9620 100644 --- a/plugins/pdk/go/metadata/metadata.go +++ b/plugins/pdk/go/metadata/metadata.go @@ -186,6 +186,9 @@ type TopSongsResponse struct { // // Plugins implementing this capability can choose which methods to implement. // Each method is optional - plugins only need to provide the functionality they support. +// +// To say "no data for this item", return a nil response and a nil error. Return an error only when +// the plugin itself failed, because Navidrome retries failed calls with backoff. type Metadata interface{} // ArtistMBIDProvider provides the GetArtistMBID function. diff --git a/plugins/pdk/go/metadata/metadata_stub.go b/plugins/pdk/go/metadata/metadata_stub.go index e72cca103..572eba4da 100644 --- a/plugins/pdk/go/metadata/metadata_stub.go +++ b/plugins/pdk/go/metadata/metadata_stub.go @@ -184,6 +184,9 @@ type TopSongsResponse struct { // // Plugins implementing this capability can choose which methods to implement. // Each method is optional - plugins only need to provide the functionality they support. +// +// To say "no data for this item", return a nil response and a nil error. Return an error only when +// the plugin itself failed, because Navidrome retries failed calls with backoff. type Metadata interface{} // ArtistMBIDProvider provides the GetArtistMBID function. From c26f6f9e981dcdbf14a86120bcda5e3d0a3e74a4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Fri, 21 Aug 2026 10:24:01 -0400 Subject: [PATCH 05/13] feat(artwork): store the resolution trace so `artwork explain` works offline (#5980) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat(artwork): record the resolution trace so explain works without --live The worker never attached a ChainTrace, so `artwork explain` had to re-walk the priority chain at CLI time. That reconstruction could disagree with what actually happened, and without --live it could not report the external tier at all. The worker now traces every acquisition and stores it. `explain` reads the stored trace by default and reports when it was recorded; --live re-walks and calls the agents. Disc artwork keeps no row, so it always walks live. A chain trace alone would have explained almost nothing about failures: six of the seven ways an item can fail happen after the chain has already picked a winner. The trace now covers those stages too, and has somewhere to live when they fail: the retrying queue row carries the last failure, and the state row keeps it in last_failure once the retry budget is spent and the queue row is deleted. Measured on a copy of a 682MB / 43.6k-item library: +9.7MB (+1.4%). No row crosses the WITHOUT ROWID overflow threshold, so list hydration is unchanged; only full scans of item_artwork, which no request performs, read more pages. * test(artwork): pin the give-up ordering that keeps a failure for unresolved items recordGiveUp updates an existing row, and for a kind with a recheck path that row is only created moments earlier by the absent settle. Recording before the settle would lose the failure for every item that never resolved, with nothing to catch it. * refactor(artwork): tighten the trace code after review Four fixes worth taking: The doc comments on ChainTrace and chainState.trace still said the worker never attaches a trace and resolution stays allocation-free — the exact invariant this branch reverses. explain's report field meant both "the chain shown was walked just now" and "go out for real", and was being passed to loadPluginAgents, which --live documents as the only thing that may open external connections. Renamed to `walked` and restored explainLive as the sole input to that decision. A stored Detail is an error string on the failure paths, with no bound. The measured "no row reaches the WITHOUT ROWID overflow limit" only holds while it is bounded, so cap it at 200 runes. offlineGate was a factory returning a constant closure; make it a plain gateFunc like its sibling passthroughGate. Collapse five copies of the age-a-queue-row loop in the worker tests into one helper. * refactor(artwork): drop the offline explain walk, now that traces are stored `artwork explain` reported the external tier without calling it, so a diagnostic could not add load to a provider already rate-limiting us. Reading the stored trace answers that better: it reports what the agents actually returned, not what would be tried. Nothing could reach the offline gate any more. It was installed only for a walk with --live unset, which now happens for disc artwork alone, and disc rejects the external candidate before any gate call. That made the gate, its sentinel error, the would-try outcome and two of explain's verdicts unreachable. Removes offlineGate, errOfflineSkipped, OutcomeWouldTry, the NewTracingResolver live parameter and the CreateArtworkResolver argument threaded through wire. Verified against a copy of a real library: disc artwork with "external" first in DiscArtPriority and external services enabled still records the skip and issues no agent call. * fix(artwork): make explain's no-network guarantee structural, not incidental Serving falls back disc -> album and track -> disc -> album. The resolver layer explain uses has no such fallback today, so dropping the offline gate did not leak. But the guarantee rested on which chains happen to lack an external tier, and the serving layer already shows the fallback shape someone could mirror. Without --live the tracing resolver is now built with no agents at all, so no chain and no fallback added later can reach a provider. That is stronger than the gate it replaces, which only intercepted the call. The test pins it against exactly that regression: with the guard removed and the serving fallback mirrored into resolveDisc, it fails. * refactor(artwork): trim the trace plumbing EncodeTrace was exported for nobody: only this package writes traces, and cmd reads them. It becomes a ChainTrace method, which also drops the copy Steps made for a caller that only wanted to serialize. explain's report carried queuedSteps and failureSteps, both pure functions of the queue and state rows already in the struct, which let a test set the two out of step with each other. formatExplain derives them, as it already does for every other display value. The trace row format and its tabwriter empty-cell rule lived in two places, and the "nothing was ever recorded" predicate in three. * fix(artwork): clear the queue trace on a fresh re-enqueue Enqueue's conflict clause reset attempts to 0 but left the new trace column, so after a scan or refresh re-enqueued a previously-failed item artwork explain showed "Attempts: 0" next to the prior lifecycle's "Last attempt failed" trace. Clear trace in Enqueue (a fresh lifecycle has no last attempt); EnqueuePreservingBackoff still keeps it. * fix(artwork): treat a processing-stage error as indeterminate in explain A read/hash/decode/store failure records an OutcomeError step and writes an absent row, but explainResult only mapped external errors and unreadable candidates to indeterminate, so the default verdict read "not resolved" — presenting a processing failure as a definitive miss. The worker retries these exactly as it retries an unreadable candidate, so classify any OutcomeError as indeterminate too. * fix(artwork): record a trace step when a chainless resolver faults Playlist and radio resolvers walk no priority chain, so a fault (unreadable upload/sidecar, or an m3u fetch error with no grid) returned localError/extError without recording any trace step. The attempt then encoded [], leaving artwork explain with an empty "Last attempt failed" and "Gave up after". Record a fallback step in the faulted-no-image branch when nothing else did, and carry the source label through resolveLocalFile so the step can name it. * fix(artwork): trace the m3u failure at its source, not via the empty guard A playlist's grid sampling records album-chain steps into the shared trace, so the processor's empty-trace fallback no longer fires when the m3u remote image fetch failed — the error that forced the retry was omitted from explain. Record it where it happens, in resolvePlaylist's external step, as external:m3u. * test(artwork): skip the chainless-fault spec on Windows The spec provokes an open fault with a non-directory parent, but Windows maps that to a not-exist error, so localError is never set and the item resolves absent instead of failed. The sibling failed-on-unreadable-upload spec skips Windows for the same class of reason. * fix(artwork): don't label an absent empty-chain row as pre-tracing explain reported "resolved before traces were recorded" for any stored row with an empty chain, but an empty CoverArtPriority records a real, empty [] chain and resolves absent. A recorded resolution that finds an image always records its winning candidate, so only a row with a hash and no chain predates tracing; split on the hash and report an absent empty chain plainly instead. * fix(db): retimestamp the artwork trace migration after rebase master merged a 2026-08-18 migration, so the original 2026-08-16 timestamp is now older than the newest on the base branch and Goose would silently skip it on an already-upgraded database. Bumped past it; the SQL is unchanged. * fix(artwork): keep the m3u error detail in the trace The m3u trace step recorded OutcomeError with no detail because resolveExternalStep collapsed the gate's error to a bool, so explain showed only "external:m3u error -" and could not tell a timeout from an HTTP error or an open breaker. Return the error (normalizing not-found to nil so it stays a definitive miss, not a failure) and store its message as the step detail; encodeSteps already bounds it. * docs(artwork): note the give-up write relies on serial draining recordGiveUp writes last_failure unconditionally; that is only correct because the drain resolves each item serially, so no concurrent success can store artwork between the write and the queue delete. Record the invariant at the call site. --- cmd/artwork.go | 108 ++++++++--- cmd/artwork_test.go | 108 +++++++---- core/artwork/agent_images.go | 6 +- core/artwork/artwork.go | 13 +- core/artwork/processor.go | 21 ++- core/artwork/processor_test.go | 29 +++ core/artwork/resolve.go | 26 ++- core/artwork/resolve_test.go | 31 ++++ core/artwork/trace.go | 107 ++++++++--- core/artwork/trace_test.go | 170 +++++++++++------- core/artwork/worker.go | 20 ++- core/artwork/worker_test.go | 95 ++++++++-- ...260819204637_add_artwork_trace_columns.sql | 9 + model/artwork.go | 10 +- persistence/artwork_queue_repository.go | 11 +- persistence/artwork_queue_repository_test.go | 27 ++- persistence/artwork_repository.go | 10 ++ persistence/artwork_repository_test.go | 45 +++++ tests/mock_artwork_queue_repo.go | 3 +- tests/mock_artwork_repo.go | 14 ++ 20 files changed, 662 insertions(+), 201 deletions(-) create mode 100644 db/migrations/20260819204637_add_artwork_trace_columns.sql diff --git a/cmd/artwork.go b/cmd/artwork.go index aeaec0e43..63f0d0917 100644 --- a/cmd/artwork.go +++ b/cmd/artwork.go @@ -36,8 +36,9 @@ var ( func init() { artworkExplainCmd.Flags().BoolVar(&explainLive, "live", false, - "perform real external lookups instead of reporting what would be tried; "+ - "also initializes plugin agents, which may open external connections") + "walk the chain again now, performing real external lookups, instead of reporting the "+ + "stored trace of the last resolution; also initializes plugin agents, which may open "+ + "external connections") artworkReprocessCmd.Flags().StringSliceVar(&reprocessKinds, "kind", nil, "kinds to reprocess ("+kindPrefixes(artwork.RecheckKinds)+"); repeatable") artworkReprocessCmd.Flags().StringSliceVar(&reprocessSources, "source", nil, @@ -640,10 +641,6 @@ func explainResult(source string, steps []artwork.TraceStep) string { if s.Outcome == artwork.OutcomeHit { break } - if s.Outcome == artwork.OutcomeWouldTry { - return "resolved from " + source + - " (offline: a higher-priority external candidate was not tried; re-run with --live)" - } // An external winner discards the earlier error, so the resolver settles it with no retry. if s.Outcome == artwork.OutcomeError && strings.HasPrefix(s.Candidate, artwork.ExternalPrefix) && !strings.HasPrefix(source, artwork.ExternalPrefix) { @@ -655,14 +652,12 @@ func explainResult(source string, steps []artwork.TraceStep) string { } for _, s := range steps { switch { - case s.Outcome == artwork.OutcomeWouldTry: - return "indeterminate (external agents not called; re-run with --live)" case s.Outcome == artwork.OutcomeError && strings.HasPrefix(s.Candidate, artwork.ExternalPrefix): return "indeterminate (an external lookup failed; the item may resolve on a later attempt)" - // The worker treats an unreadable local candidate exactly as it treats a failed external one: - // it retries instead of settling absent, so the verdict must not read as a clean miss. - case s.Outcome == artwork.OutcomeUnreadable: - return "indeterminate (a candidate exists but could not be read; the worker retries rather than settling absent)" + // A stage error or an unreadable candidate means a source was found but not processed; the + // worker retries rather than settling absent, so neither reads as a clean miss. + case s.Outcome == artwork.OutcomeError, s.Outcome == artwork.OutcomeUnreadable: + return "indeterminate (a candidate was found but could not be processed; the worker retries rather than settling absent)" } } return "not resolved" @@ -684,22 +679,55 @@ func explainConfig(kind model.Kind) (name, value string) { } type explainReport struct { - kind model.Kind - id string - name string - stored *model.ItemArtwork - queued *model.ArtworkQueueItem - agents string + kind model.Kind + id string + name string + stored *model.ItemArtwork + queued *model.ArtworkQueueItem + agents string + // steps is the chain walk: recorded when the item was resolved, or performed just now when walked. steps []artwork.TraceStep source string + walked bool resolveErr error } +// explainChainOrigin says whether the operator is reading history or a walk performed just now, +// since the two can disagree after a config change. +func explainChainOrigin(rep explainReport) string { + if rep.walked { + return "walked now" + } + if rep.stored != nil { + return "recorded " + formatTime(rep.stored.AttemptedAt) + } + return "not recorded" +} + +// writeSteps prints the trace rows. An empty last cell would end tabwriter's column block and +// break the alignment, so a missing detail is rendered as a dash. +func writeSteps(w io.Writer, indent string, steps []artwork.TraceStep) { + for _, s := range steps { + fmt.Fprintf(w, "%s%s\t%s\t%s\n", indent, s.Candidate, s.Outcome, cmp.Or(s.Detail, "-")) + } +} + +// writeStepTable prints a secondary trace, and nothing at all when there is none to show. +func writeStepTable(w io.Writer, title string, steps []artwork.TraceStep) { + if len(steps) == 0 { + return + } + // No tab on the title: it closes the preceding column block, so these rows align among themselves. + fmt.Fprintf(w, " %s:\n", title) + writeSteps(w, " ", steps) +} + func formatExplain(rep explainReport) string { var sb strings.Builder w := newTabWriter(&sb) explainable := artwork.Explainable(rep.kind) stateful := artwork.KeepsState(rep.kind) + unrecorded := !rep.walked && rep.stored == nil fmt.Fprintln(w, "Item") fmt.Fprintf(w, " Kind:\t%s (%s)\n", rep.kind, rep.kind.Prefix()) @@ -732,6 +760,12 @@ func formatExplain(rep explainReport) string { fmt.Fprintf(w, " Attempts:\t%d\n", rep.queued.Attempts) fmt.Fprintf(w, " Retry at:\t%s\n", formatTime(rep.queued.RetryAt)) } + if rep.queued != nil { + writeStepTable(w, "Last attempt failed", artwork.DecodeTrace(rep.queued.Trace, "")) + } + if rep.stored != nil { + writeStepTable(w, "Gave up after", artwork.DecodeTrace(rep.stored.LastFailure, "")) + } fmt.Fprintln(w, "\nConfig") if setting, value := explainConfig(rep.kind); setting == "" { @@ -743,15 +777,22 @@ func formatExplain(rep explainReport) string { } } - fmt.Fprintln(w, "\nChain") - if !explainable { + fmt.Fprintf(w, "\nChain (%s)\n", explainChainOrigin(rep)) + switch { + case !explainable: fmt.Fprintf(w, " (%s artwork does not walk a priority chain)\n", rep.kind) - } else { + case unrecorded: + fmt.Fprintln(w, " (no resolution recorded yet; re-run with --live to walk the chain now)") + case !rep.walked && len(rep.steps) == 0 && rep.stored.Hash != "": + // A stored image with no chain can only predate trace recording: a recorded resolution that + // found an image always records its winning candidate. + fmt.Fprintln(w, " (this item was resolved before traces were recorded; re-run with --live)") + case !rep.walked && len(rep.steps) == 0: + // Absent with no chain: an empty priority list walked nothing, or a pre-tracing absent row. + fmt.Fprintln(w, " (no candidates were recorded; re-run with --live to walk the chain now)") + default: fmt.Fprintln(w, " CANDIDATE\tOUTCOME\tDETAIL") - for _, s := range rep.steps { - // A row with an empty last cell would end tabwriter's column block, breaking alignment. - fmt.Fprintf(w, " %s\t%s\t%s\n", s.Candidate, s.Outcome, cmp.Or(s.Detail, "-")) - } + writeSteps(w, " ", rep.steps) } fmt.Fprintln(w, "\nResult") @@ -760,6 +801,8 @@ func formatExplain(rep explainReport) string { fmt.Fprintf(w, " resolution failed: %s\n", rep.resolveErr) case !explainable: fmt.Fprintln(w, " not evaluated (no chain was walked; see Stored above)") + case unrecorded: + fmt.Fprintln(w, " not evaluated (nothing recorded; re-run with --live to walk the chain now)") default: fmt.Fprintf(w, " %s\n", explainResult(rep.source, rep.steps)) } @@ -807,6 +850,8 @@ func runExplain(ctx context.Context, args []string) { } } + // Disc artwork keeps no row, so it has no stored trace and can only be explained by walking now. + rep.walked = explainLive || !artwork.KeepsState(kind) if artwork.Explainable(kind) { // Only artist and album reach an agent, and the load must precede the resolver, which reads // the same manager. @@ -815,11 +860,16 @@ func runExplain(ctx context.Context, args []string) { defer func() { _ = mgr.Stop() }() rep.agents = explainAgents(conf.Server.Agents, availableImageAgents(ds, mgr, kind)) } - trace := &artwork.ChainTrace{} - rep.source, rep.resolveErr = CreateArtworkResolver(trace, explainLive).Resolve(ctx, kind, id) - rep.steps = trace.Steps() + switch { + case rep.walked: + trace := &artwork.ChainTrace{} + rep.source, rep.resolveErr = CreateArtworkResolver(trace, explainLive).Resolve(ctx, kind, id) + rep.steps = trace.Steps() + case rep.stored != nil: + rep.steps = artwork.DecodeTrace(rep.stored.Trace, rep.stored.SourcePath) + rep.source = rep.stored.Source + } } - fmt.Print(formatExplain(rep)) // The steps taken before a failed walk are the diagnosis, so report them before exiting. if rep.resolveErr != nil { diff --git a/cmd/artwork_test.go b/cmd/artwork_test.go index 8b50ba775..38a1b79cb 100644 --- a/cmd/artwork_test.go +++ b/cmd/artwork_test.go @@ -145,6 +145,15 @@ var _ = Describe("explainResult", func() { "the worker retries an unreadable candidate instead of settling absent, so this is not a clean miss") }) + It("reports indeterminate when a processing stage errored after a candidate was found", func() { + steps := []artwork.TraceStep{ + {Candidate: "cover.*", Outcome: "hit", Detail: "/music/cover.jpg"}, + {Candidate: "store", Outcome: "error", Detail: "disk full"}, + } + Expect(explainResult("", steps)).To(ContainSubstring("indeterminate"), + "a stage error is a processing failure the worker retries, not a definitive miss") + }) + It("does not qualify a hit that an earlier unreadable candidate preceded", func() { // chainState.try stamps only the external error onto a hit and drops the local one, so the // worker settles this as found; warning about it would be a false alarm. @@ -164,34 +173,6 @@ var _ = Describe("explainResult", func() { "a failed network call is not evidence that the item has no artwork") }) - It("qualifies a win a skipped higher-priority external candidate could have taken", func() { - steps := []artwork.TraceStep{ - {Candidate: "external:deezer", Outcome: "would-try"}, - {Candidate: "artist.*", Outcome: "hit", Detail: "/music/artist.jpg"}, - } - res := explainResult("artist.*", steps) - Expect(res).To(ContainSubstring("resolved from artist.*")) - Expect(res).To(ContainSubstring("--live"), - "offline, the winner is only the winner because the external tier was skipped") - }) - - It("does not qualify a win that no skipped candidate outranked", func() { - steps := []artwork.TraceStep{ - {Candidate: "artist.*", Outcome: "hit"}, - {Candidate: "external:deezer", Outcome: "would-try"}, - } - Expect(explainResult("artist.*", steps)).To(Equal("resolved from artist.*")) - }) - - It("reports indeterminate when external agents were never called", func() { - steps := []artwork.TraceStep{ - {Candidate: "artist.*", Outcome: "miss"}, - {Candidate: "external:deezer", Outcome: "would-try"}, - } - Expect(explainResult("", steps)).To(ContainSubstring("indeterminate"), - "an offline run must not claim an item is unresolvable when external agents were skipped") - }) - It("qualifies a win a failed higher-priority external lookup could have taken", func() { steps := []artwork.TraceStep{ {Candidate: "external:deezer", Outcome: "error", Detail: "context deadline exceeded"}, @@ -252,9 +233,10 @@ var _ = Describe("formatExplain", func() { id: "ar-1", name: "Radiohead", agents: "lastfm,spotify", + walked: true, steps: []artwork.TraceStep{ {Candidate: "upload", Outcome: "skipped", Detail: "no uploaded image"}, - {Candidate: "external:deezer", Outcome: "would-try"}, + {Candidate: "external:deezer", Outcome: "error", Detail: "context deadline exceeded"}, }, source: "", } @@ -267,7 +249,6 @@ var _ = Describe("formatExplain", func() { Expect(out).To(ContainSubstring("ArtistArtPriority")) Expect(out).To(ContainSubstring("lastfm,spotify")) Expect(out).To(ContainSubstring("external:deezer")) - Expect(out).To(ContainSubstring("would-try")) Expect(out).To(ContainSubstring("indeterminate")) }) @@ -304,7 +285,7 @@ var _ = Describe("formatExplain", func() { out := formatExplain(rep) Expect(out).To(ContainSubstring("resolution failed: no such directory")) Expect(out).ToNot(ContainSubstring("indeterminate")) - Expect(out).To(ContainSubstring("would-try"), "the steps taken before the failure still print") + Expect(out).To(ContainSubstring("external:deezer"), "the steps taken before the failure still print") }) It("says a kind that does not walk a chain has no chain, without an empty table", func() { @@ -329,6 +310,7 @@ var _ = Describe("formatExplain", func() { kind: model.KindDiscArtwork, id: "al-1:2", name: "OK Computer (disc 2)", steps: []artwork.TraceStep{{Candidate: "cover.jpg", Outcome: "hit", Detail: "/music/cover.jpg"}}, source: "folder", + walked: true, } out := formatExplain(rep) @@ -341,10 +323,74 @@ var _ = Describe("formatExplain", func() { Expect(out).To(ContainSubstring("resolved from folder")) }) + Context("stored traces", func() { + BeforeEach(func() { + rep.walked = false + rep.steps = nil + }) + + It("labels a recorded chain with when it was recorded, not as a walk done now", func() { + attempted := time.Date(2026, 8, 13, 10, 0, 0, 0, time.UTC) + rep.stored = &model.ItemArtwork{Source: "folder", Hash: "abc", AttemptedAt: attempted} + rep.steps = []artwork.TraceStep{{Candidate: "artist.*", Outcome: "hit", Detail: "/music/artist.jpg"}} + rep.source = "folder" + + out := formatExplain(rep) + Expect(out).To(ContainSubstring("Chain (recorded 2026-08-13T10:00:00Z)")) + Expect(out).To(ContainSubstring("/music/artist.jpg")) + Expect(out).To(ContainSubstring("resolved from folder")) + }) + + It("says so when the item has never been resolved", func() { + out := formatExplain(rep) + Expect(out).To(ContainSubstring("no resolution recorded yet")) + Expect(out).To(ContainSubstring("--live")) + Expect(out).ToNot(ContainSubstring("not resolved"), + "nothing was recorded, which is not the same as resolving to nothing") + }) + + It("distinguishes a row written before traces existed from one with an empty chain", func() { + rep.stored = &model.ItemArtwork{Source: "folder", Hash: "abc", AttemptedAt: time.Now()} + + Expect(formatExplain(rep)).To(ContainSubstring("resolved before traces were recorded")) + }) + + It("does not call an absent row with an empty recorded chain a pre-tracing row", func() { + // An empty priority list records a real but empty chain and resolves absent; that is not a + // legacy row, so it must not be reported as resolved before tracing existed. + rep.stored = &model.ItemArtwork{Source: "", Hash: "", AttemptedAt: time.Now()} + + out := formatExplain(rep) + Expect(out).ToNot(ContainSubstring("resolved before traces were recorded")) + Expect(out).To(ContainSubstring("no candidates were recorded")) + Expect(out).To(ContainSubstring("not resolved"), "the Result still reports the absence plainly") + }) + + It("prints why the last attempt failed and why it gave up", func() { + rep.queued = &model.ArtworkQueueItem{Priority: model.ArtworkPriorityScan, Attempts: 3, + Trace: `[{"c":"decode","o":"error","d":"bad header"}]`} + rep.stored = &model.ItemArtwork{Source: "folder", Hash: "abc", AttemptedAt: time.Now(), + LastFailure: `[{"c":"read","o":"error","d":"i/o timeout"}]`} + + out := formatExplain(rep) + Expect(out).To(ContainSubstring("Last attempt failed")) + Expect(out).To(ContainSubstring("bad header")) + Expect(out).To(ContainSubstring("Gave up after")) + Expect(out).To(ContainSubstring("i/o timeout")) + }) + + It("omits the failure tables when there is no failure to report", func() { + out := formatExplain(rep) + Expect(out).ToNot(ContainSubstring("Last attempt failed")) + Expect(out).ToNot(ContainSubstring("Gave up after")) + }) + }) + It("reports the setting that governs media file artwork", func() { conf.Server.EnableMediaFileCoverArt = false rep = explainReport{ kind: model.KindMediaFileArtwork, id: "mf-1", name: "Airbag", + walked: true, steps: []artwork.TraceStep{ {Candidate: "embedded", Outcome: "skipped", Detail: "EnableMediaFileCoverArt is off"}, }, diff --git a/core/artwork/agent_images.go b/core/artwork/agent_images.go index a6f746959..95596dabc 100644 --- a/core/artwork/agent_images.go +++ b/core/artwork/agent_images.go @@ -58,7 +58,7 @@ func fetchArtistImage(ctx context.Context, ag *agents.Agents, gate gateFunc, ar return nil, "", false } for _, a := range imageAgents { - reader, _, err := gate(a.Name, func() (io.ReadCloser, string, error) { + reader, path, err := gate(a.Name, func() (io.ReadCloser, string, error) { imgs, err := a.Retriever.GetArtistImages(ctx, ar.ID, name, ar.MbzArtistID) if err != nil { return nil, "", err @@ -69,6 +69,7 @@ func fetchArtistImage(ctx context.Context, ag *agents.Agents, gate gateFunc, ar } return fromURL(ctx, u) }) + recordAgent(ctx, a.Name, reader, path, err) if reader != nil { return reader, a.Name, false } @@ -90,7 +91,7 @@ func fetchAlbumImage(ctx context.Context, ag *agents.Agents, gate gateFunc, al m return nil, "", false } for _, a := range imageAgents { - reader, _, err := gate(a.Name, func() (io.ReadCloser, string, error) { + reader, path, err := gate(a.Name, func() (io.ReadCloser, string, error) { imgs, err := a.Retriever.GetAlbumImages(ctx, name, artist, al.MbzAlbumID) if err != nil { return nil, "", err @@ -101,6 +102,7 @@ func fetchAlbumImage(ctx context.Context, ag *agents.Agents, gate gateFunc, al m } return fromURL(ctx, u) }) + recordAgent(ctx, a.Name, reader, path, err) if reader != nil { return reader, a.Name, false } diff --git a/core/artwork/artwork.go b/core/artwork/artwork.go index 7edc80e99..e8458a0f9 100644 --- a/core/artwork/artwork.go +++ b/core/artwork/artwork.go @@ -393,16 +393,15 @@ type TracingResolver struct { trace *ChainTrace } -// NewTracingResolver builds a TracingResolver that records its priority-chain walk. With live -// false the external tier is reported but never called. +// NewTracingResolver builds a TracingResolver that records its priority-chain walk. Without live +// it gets no agents at all, so neither a chain nor any fallback added later can reach a provider; +// with it, one item is at most one call per agent, so the rate limiter and breaker are bypassed. func NewTracingResolver(ds model.DataStore, ag *agents.Agents, ffm ffmpeg.FFmpeg, t *ChainTrace, live bool) *TracingResolver { - gate := offlineGate(t) + inner := newLocalResolver(ds, ffm) if live { - // A diagnostic must show the provider's real answer, and one item is at most one call - // per agent, so --live deliberately bypasses the rate limiter and circuit breaker. - gate = tracingGate(t, passthroughGate) + inner = newResolver(ds, ag, ffm, passthroughGate) } - return &TracingResolver{inner: newResolver(ds, ag, ffm, gate), trace: t} + return &TracingResolver{inner: inner, trace: t} } // Resolve walks kind's sources for id, recording the walk, and reports the winning source diff --git a/core/artwork/processor.go b/core/artwork/processor.go index 4d38ced95..fdb28189a 100644 --- a/core/artwork/processor.go +++ b/core/artwork/processor.go @@ -2,6 +2,7 @@ package artwork import ( "bytes" + "cmp" "context" "encoding/base64" "errors" @@ -89,12 +90,21 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o res, err := p.resolver.resolve(ctx, item) if err != nil { + traceStage(ctx, "resolve", err) log.Warn(ctx, "Artwork: Could not resolve item", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } if res.reader == nil { if res.extError || res.localError { // A fault is not a definitive "no image": never settle absent, keep serving old state. + // A chainless resolver (playlist/radio) records no step, so leave a fallback or explain is blank. + if t := traceFrom(ctx); len(t.Steps()) == 0 { + outcome := OutcomeError + if res.localError { + outcome = OutcomeUnreadable + } + t.add(TraceStep{Candidate: cmp.Or(res.source, "source"), Outcome: outcome}) + } 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 @@ -106,6 +116,7 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o readStart := time.Now() data, err := readCapped(res.reader) if err != nil { + traceStage(ctx, "read", err) log.Warn(ctx, "Artwork: Failed to read resolved image", "kind", item.ItemKind, "id", item.ItemID, "source", res.source, err) return outcomeFailed, nil } @@ -115,6 +126,7 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o hashStart := time.Now() hash, err := hashImage(bytes.NewReader(data)) if err != nil { + traceStage(ctx, "hash", err) log.Warn(ctx, "Artwork: Failed to hash image", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } @@ -138,19 +150,22 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o art, err = undecodedArtwork(hash), nil } if err != nil { + traceStage(ctx, "decode", err) 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, "width", art.Width, "height", art.Height, "mime", art.Mime, "elapsed", time.Since(decodeStart)) default: + traceStage(ctx, "lookup", err) log.Warn(ctx, "Artwork: Failed to look up image hash", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } art.SizeBytes = int64(len(data)) - ia, err := p.persist(repo, item, art, res, data) + ia, err := p.persist(ctx, repo, item, art, res, data) if err != nil { + traceStage(ctx, "store", err) log.Warn(ctx, "Artwork: Failed to persist resolved image", "kind", item.ItemKind, "id", item.ItemID, err) return outcomeFailed, nil } @@ -165,7 +180,7 @@ func (p *processor) acquire(ctx context.Context, item model.ArtworkQueueItem) (o // persist places the bytes and commits the rows referencing them, excluding Prune for that // window only so a slow resolution can never hold it off. -func (p *processor) persist(repo model.ArtworkRepository, item model.ArtworkQueueItem, +func (p *processor) persist(ctx context.Context, repo model.ArtworkRepository, item model.ArtworkQueueItem, art *model.Artwork, res resolution, data []byte, ) (*model.ItemArtwork, error) { if p.pruneLock != nil { @@ -188,6 +203,7 @@ func (p *processor) persist(repo model.ArtworkRepository, item model.ArtworkQueu SourcePath: sourcePath, RefMtime: refMtime, AttemptedAt: time.Now(), + Trace: traceFrom(ctx).encode(sourcePath), } // PutItemArtwork stamps UpdatedAt on ia, so the returned struct matches the persisted row. if err := repo.PutItemArtwork(ia); err != nil { @@ -203,6 +219,7 @@ func writeAbsent(ctx context.Context, repo model.ArtworkRepository, item model.A ItemID: item.ItemID, ImageType: item.ImageType, AttemptedAt: time.Now(), + Trace: traceFrom(ctx).encode(""), }) if err != nil { log.Warn(ctx, "Artwork: Failed to persist absent state", "kind", item.ItemKind, "id", item.ItemID, err) diff --git a/core/artwork/processor_test.go b/core/artwork/processor_test.go index 1ada8415d..0ca5a308e 100644 --- a/core/artwork/processor_test.go +++ b/core/artwork/processor_test.go @@ -229,6 +229,35 @@ var _ = Describe("processor.acquire", func() { Expect(err).To(MatchError(model.ErrNotFound), "an unreadable upload must not be recorded as absent") }) + // Playlist/radio resolvers walk no chain, so a fault records no step; without a fallback, + // explain would show a give-up with an empty "Gave up after" table. + It("chainless fault: records a fallback trace step naming the faulted source", func() { + if runtime.GOOS == "windows" { + // os.Open under a non-directory maps to a not-exist error on Windows, so no localError. + Skip("cannot provoke an open fault via a non-directory parent on Windows") + } + radioRepo := tests.CreateMockedRadioRepo() + radioRepo.Data = map[string]*model.Radio{} + ds.MockedRadio = radioRepo + dir := GinkgoT().TempDir() + conf.Server.DataFolder = conf.NewDir(dir) + upload := model.UploadedImagePath(consts.EntityRadio, "ra-tr.jpg") + // A plain file where the upload's parent should be makes os.Open fault with ENOTDIR, + // deterministically and regardless of the test user's privileges. + Expect(os.MkdirAll(filepath.Dir(filepath.Dir(upload)), 0o755)).To(Succeed()) + Expect(os.WriteFile(filepath.Dir(upload), []byte("x"), 0o600)).To(Succeed()) + radioRepo.Data["ra-tr"] = &model.Radio{ID: "ra-tr", Name: "Station", UploadedImage: "ra-tr.jpg"} + + trace := &ChainTrace{} + out, _ := proc.acquire(withTrace(ctx, trace), model.ArtworkQueueItem{ItemKind: "ra", ItemID: "ra-tr"}) + Expect(out).To(Equal(outcomeFailed)) + + steps := trace.Steps() + Expect(steps).To(HaveLen(1), "a radio fault must leave one step so explain is not blank") + Expect(steps[0].Candidate).To(Equal("upload")) + Expect(steps[0].Outcome).To(Equal(OutcomeUnreadable)) + }) + It("failed-on-extError: leaves the item's state untouched", func() { conf.Server.CoverArtPriority = "external" ds.MockedAlbum.(*tests.MockAlbumRepo).SetData(model.Albums{ diff --git a/core/artwork/resolve.go b/core/artwork/resolve.go index d25f76460..f42beb9f1 100644 --- a/core/artwork/resolve.go +++ b/core/artwork/resolve.go @@ -37,7 +37,7 @@ type resolution struct { // transient external failure still retries; localErr is dropped, as the scanner re-lists changes. type chainState struct { extErr, localErr bool - trace *ChainTrace // nil unless the CLI asked for a trace + trace *ChainTrace // nil only where no caller attached one } // try stamps the accumulated external failure onto a hit, and records the miss otherwise. @@ -354,10 +354,13 @@ func (r *resolver) resolvePlaylist(ctx context.Context, playlistID string) (reso } if remoteImg != nil && conf.Server.EnableM3UExternalAlbumArt { sf := func() (io.ReadCloser, string, error) { return fromURL(ctx, remoteImg) } - if res, ok, isErr := resolveExternalStep(r.ext.gate, "m3u", sf); ok { + if res, ok, err := resolveExternalStep(r.ext.gate, "m3u", sf); ok { return res, nil - } else if isErr { + } else if err != nil { extErr = true + // Record it here with its detail: once album sampling adds its own steps, the processor's + // empty-trace fallback no longer fires, and the error that forced the retry would be lost. + traceFrom(ctx).add(TraceStep{Candidate: ExternalPrefix + "m3u", Outcome: OutcomeError, Detail: err.Error()}) } } @@ -461,14 +464,17 @@ func (r *resolver) resolveDisc(ctx context.Context, id string) (resolution, erro return dr.selectImage(ctx, r.ffmpeg, conf.Server.DiscArtPriority, &chain) } -// resolveExternalStep runs a single external sourceFunc through the named gate. extErr excludes -// a not-found, which is a definitive "no" rather than a failure. -func resolveExternalStep(gate gateFunc, name string, sf sourceFunc) (res resolution, ok bool, extErr bool) { +// resolveExternalStep runs a single external sourceFunc through the named gate. A not-found is a +// definitive "no", returned as (_, false, nil); any other error is a failure the caller records. +func resolveExternalStep(gate gateFunc, name string, sf sourceFunc) (resolution, bool, error) { r, path, err := gate(name, sf) if r != nil { - return resolution{reader: r, source: externalCandidate, sourcePath: path}, true, false + return resolution{reader: r, source: externalCandidate, sourcePath: path}, true, nil } - return resolution{}, false, err != nil && !errors.Is(err, model.ErrNotFound) + if errors.Is(err, model.ErrNotFound) { + return resolution{}, false, nil + } + return resolution{}, false, err } // classifyPlaylistImage splits a playlist ExternalImageURL into a local filesystem path or a @@ -561,7 +567,9 @@ func resolveLocalFile(path, source string) (resolution, bool) { } f, err := os.Open(path) if err != nil { - return resolution{localError: !errors.Is(err, fs.ErrNotExist)}, false + // Carry the source label even on a fault, so a resolver with no chain (playlist/radio) can + // still name what faulted in the trace. + return resolution{source: source, localError: !errors.Is(err, fs.ErrNotExist)}, false } return resolution{reader: f, source: source, sourcePath: path, refMtime: mtimeOf(path)}, true } diff --git a/core/artwork/resolve_test.go b/core/artwork/resolve_test.go index 8b4c11c8c..236e76b9b 100644 --- a/core/artwork/resolve_test.go +++ b/core/artwork/resolve_test.go @@ -520,6 +520,37 @@ var _ = Describe("resolveItem", func() { Expect(gatedNames).To(Equal([]string{"m3u"}), "the playlist URL fetch is gated under \"m3u\"") }) + It("records the m3u failure in the trace even when album sampling adds its own steps", func() { + conf.Server.EnableM3UExternalAlbumArt = true + folderRepo.result = nil // the sampled album yields no tile, so the m3u failure is what forced the retry + + plRepo := tests.CreateMockPlaylistRepo() + plRepo.SetData(model.Playlists{{ID: "plm3u", Name: "Playlist", ExternalImageURL: "http://example.com/cover.jpg"}}) + plRepo.TracksRepo = &tests.MockPlaylistTrackRepo{AlbumIDs: []string{"t1"}} + ds.MockedPlaylist = plRepo + + gate := func(string, func() (io.ReadCloser, string, error)) (io.ReadCloser, string, error) { + return nil, "", errors.New("network down") + } + + trace := &ChainTrace{} + res, err := newResolver(ds, ag, ffm, gate).resolve(withTrace(ctx, trace), + model.ArtworkQueueItem{ItemKind: "pl", ItemID: "plm3u"}) + Expect(err).ToNot(HaveOccurred()) + Expect(res.extError).To(BeTrue()) + + steps := trace.Steps() + var m3u *TraceStep + for i := range steps { + if steps[i].Candidate == ExternalPrefix+"m3u" && steps[i].Outcome == OutcomeError { + m3u = &steps[i] + } + } + Expect(m3u).ToNot(BeNil(), "the m3u fetch error must be traced at its source, not left to the empty-trace fallback") + Expect(m3u.Detail).To(Equal("network down"), + "the trace must carry the underlying error so explain can tell a timeout from an HTTP error") + }) + It("treats a missing local ExternalImageURL as a definitive miss, not extError", func() { folderRepo.result = nil // no grid tiles, so the local-file miss is what surfaces diff --git a/core/artwork/trace.go b/core/artwork/trace.go index 5d02fa4ff..bca2f2c7d 100644 --- a/core/artwork/trace.go +++ b/core/artwork/trace.go @@ -2,10 +2,12 @@ package artwork import ( "context" - "errors" + "encoding/json" "io" "slices" "sync" + + "github.com/navidrome/navidrome/utils/str" ) // Outcome is what the priority chain observed for one candidate; the CLI renders and branches on these. @@ -16,7 +18,6 @@ const ( OutcomeMiss Outcome = "miss" OutcomeUnreadable Outcome = "unreadable" OutcomeSkipped Outcome = "skipped" - OutcomeWouldTry Outcome = "would-try" OutcomeError Outcome = "error" ) @@ -34,8 +35,8 @@ type TraceStep struct { Detail string } -// ChainTrace collects the walk of a single resolution. The artwork worker never attaches -// one; only the CLI does, so resolution stays allocation-free in the hot path. +// ChainTrace collects the walk of a single resolution: the worker attaches one per queue +// item so it can be stored, and the CLI attaches one per explain. type ChainTrace struct { mu sync.Mutex steps []TraceStep @@ -59,6 +60,65 @@ func (t *ChainTrace) Steps() []TraceStep { return slices.Clone(t.steps) } +// maxTraceDetail bounds a stored Detail, which on the failure paths is an error string of +// unknown length. Past ~1kB a row spills to an overflow page, slowing every scan of the table. +const maxTraceDetail = 200 + +// storedStep is the persisted shape of a TraceStep. The keys are single letters because a trace +// is written for every item, and the encoded length is repeated across the whole library. +type storedStep struct { + C string `json:"c"` + O Outcome `json:"o"` + D string `json:"d,omitempty"` +} + +// encode serializes the trace for storage, without the copy Steps would make for a caller +// that only wants to write it. +func (t *ChainTrace) encode(sourcePath string) string { + if t == nil { + return encodeSteps(nil, sourcePath) + } + t.mu.Lock() + defer t.mu.Unlock() + return encodeSteps(t.steps, sourcePath) +} + +// encodeSteps writes the stored form. A hit's Detail is the winning source's path, which the +// same row already stores as source_path, so it is dropped and DecodeTrace puts it back. +func encodeSteps(steps []TraceStep, sourcePath string) string { + out := make([]storedStep, 0, len(steps)) + for _, s := range steps { + d := s.Detail + if s.Outcome == OutcomeHit && d == sourcePath { + d = "" + } + out = append(out, storedStep{C: s.Candidate, O: s.Outcome, D: str.TruncateRunes(d, maxTraceDetail, "...")}) + } + b, _ := json.Marshal(out) // []storedStep is all strings, so this cannot fail + return string(b) +} + +// DecodeTrace reverses the stored form. A trace that will not parse is reported as no trace at all, +// since a diagnostic command must not fail on a bad row. +func DecodeTrace(encoded, sourcePath string) []TraceStep { + if encoded == "" { + return nil + } + var stored []storedStep + if err := json.Unmarshal([]byte(encoded), &stored); err != nil { + return nil + } + steps := make([]TraceStep, 0, len(stored)) + for _, s := range stored { + d := s.D + if d == "" && s.O == OutcomeHit { + d = sourcePath + } + steps = append(steps, TraceStep{Candidate: s.C, Outcome: s.O, Detail: d}) + } + return steps +} + type traceCtxKey struct{} func withTrace(ctx context.Context, t *ChainTrace) context.Context { @@ -70,30 +130,23 @@ func traceFrom(ctx context.Context) *ChainTrace { return t } -var errOfflineSkipped = errors.New("artwork: external lookup skipped (offline)") - -// tracingGate records each external agent's outcome without changing what the gate returns. -func tracingGate(t *ChainTrace, inner gateFunc) gateFunc { - return func(name string, f func() (io.ReadCloser, string, error)) (io.ReadCloser, string, error) { - r, path, err := inner(name, f) - candidate := ExternalPrefix + name - switch { - case r != nil: - t.add(TraceStep{Candidate: candidate, Outcome: OutcomeHit, Detail: path}) - case isTransientExternal(err): - t.add(TraceStep{Candidate: candidate, Outcome: OutcomeError, Detail: err.Error()}) - default: - t.add(TraceStep{Candidate: candidate, Outcome: OutcomeMiss}) - } - return r, path, err +// recordAgent files what one external agent answered. The agent loops call this rather than a +// gate wrapper, because only they hold the context that carries the trace. +func recordAgent(ctx context.Context, name string, r io.ReadCloser, path string, err error) { + t := traceFrom(ctx) + candidate := ExternalPrefix + name + switch { + case r != nil: + t.add(TraceStep{Candidate: candidate, Outcome: OutcomeHit, Detail: path}) + case isTransientExternal(err): + t.add(TraceStep{Candidate: candidate, Outcome: OutcomeError, Detail: err.Error()}) + default: + t.add(TraceStep{Candidate: candidate, Outcome: OutcomeMiss}) } } -// offlineGate reports which agents would be asked without asking them, so a diagnostic -// command cannot add load to a provider that is already rate-limiting us. -func offlineGate(t *ChainTrace) gateFunc { - return func(name string, _ func() (io.ReadCloser, string, error)) (io.ReadCloser, string, error) { - t.add(TraceStep{Candidate: ExternalPrefix + name, Outcome: OutcomeWouldTry}) - return nil, "", errOfflineSkipped - } +// traceStage records a failure from the stages that run after the priority chain has already +// picked a winner: most ways an item can fail are here, not in the chain walk. +func traceStage(ctx context.Context, stage string, err error) { + traceFrom(ctx).add(TraceStep{Candidate: stage, Outcome: OutcomeError, Detail: err.Error()}) } diff --git a/core/artwork/trace_test.go b/core/artwork/trace_test.go index 5a54c9e91..a16347457 100644 --- a/core/artwork/trace_test.go +++ b/core/artwork/trace_test.go @@ -24,13 +24,63 @@ var _ = Describe("trace vocabulary", func() { // what `artwork explain` tells an operator, so it must be made deliberately. It("pins the wire values the CLI reads", func() { Expect([]Outcome{ - OutcomeHit, OutcomeMiss, OutcomeUnreadable, OutcomeSkipped, OutcomeWouldTry, OutcomeError, - }).To(Equal([]Outcome{"hit", "miss", "unreadable", "skipped", "would-try", "error"})) + OutcomeHit, OutcomeMiss, OutcomeUnreadable, OutcomeSkipped, OutcomeError, + }).To(Equal([]Outcome{"hit", "miss", "unreadable", "skipped", "error"})) Expect(externalCandidate).To(Equal("external")) Expect(ExternalPrefix).To(Equal("external:")) }) }) +var _ = Describe("encodeSteps/DecodeTrace", func() { + It("round-trips a trace", func() { + steps := []TraceStep{ + {Candidate: "cover.png", Outcome: OutcomeMiss}, + {Candidate: "cover.*", Outcome: OutcomeHit, Detail: "/music/a/cover.jpg"}, + } + Expect(DecodeTrace(encodeSteps(steps, ""), "")).To(Equal(steps)) + }) + + It("encodes an empty trace as an empty JSON array", func() { + Expect(encodeSteps(nil, "")).To(Equal("[]")) + Expect(DecodeTrace("[]", "")).To(BeEmpty()) + }) + + It("tolerates a row written before the column existed", func() { + Expect(DecodeTrace("", "")).To(BeEmpty()) + }) + + // The hit detail repeats source_path byte for byte, and that column is on the same row. + It("drops a hit detail that repeats sourcePath, and restores it on read", func() { + path := "/music/artist/album/cover.jpg" + steps := []TraceStep{{Candidate: "cover.*", Outcome: OutcomeHit, Detail: path}} + encoded := encodeSteps(steps, path) + Expect(encoded).NotTo(ContainSubstring(path)) + Expect(DecodeTrace(encoded, path)).To(Equal(steps)) + }) + + It("keeps a detail that differs from sourcePath", func() { + steps := []TraceStep{{Candidate: "external:deezer", Outcome: OutcomeHit, Detail: "https://cdn/x.jpg"}} + Expect(DecodeTrace(encodeSteps(steps, "/music/a/cover.jpg"), "/music/a/cover.jpg")).To(Equal(steps)) + }) + + // A row past ~1kB spills to an overflow page on these WITHOUT ROWID tables, which would + // slow every scan; Detail is an error string on the failure paths, so it needs a bound. + It("bounds a detail so one long error cannot inflate the row", func() { + steps := []TraceStep{{Candidate: "decode", Outcome: OutcomeError, Detail: strings.Repeat("x", 5000)}} + + got := DecodeTrace(encodeSteps(steps, ""), "") + + Expect(len(got[0].Detail)).To(BeNumerically("<=", 210)) + Expect(got[0].Detail).To(HaveSuffix("...")) + Expect(got[0].Candidate).To(Equal("decode"), "truncating the detail must not disturb the step") + }) + + It("only restores sourcePath onto a detail-less hit", func() { + steps := []TraceStep{{Candidate: "cover.*", Outcome: OutcomeMiss}} + Expect(DecodeTrace(encodeSteps(steps, "/music/a/cover.jpg"), "/music/a/cover.jpg")).To(Equal(steps)) + }) +}) + var _ = Describe("chainTrace", func() { It("returns nil when no trace is attached", func() { Expect(traceFrom(context.Background())).To(BeNil()) @@ -113,63 +163,41 @@ var _ = Describe("chainState tracing", func() { }) }) -var _ = Describe("external gate tracing", func() { - hit := func() (io.ReadCloser, string, error) { - return io.NopCloser(strings.NewReader("x")), "http://img", nil - } - miss := func() (io.ReadCloser, string, error) { return nil, "", agents.ErrNotFound } - boom := func() (io.ReadCloser, string, error) { return nil, "", errors.New("returned status 429") } +var _ = Describe("external agent tracing", func() { + var ( + t *ChainTrace + ctx context.Context + body io.ReadCloser + ) + BeforeEach(func() { + t = &ChainTrace{} + ctx = withTrace(context.Background(), t) + body = io.NopCloser(strings.NewReader("x")) + }) It("records a hit with the image path", func() { - t := &ChainTrace{} - g := tracingGate(t, passthroughGate) - - r, _, err := g("deezer", hit) - - Expect(err).ToNot(HaveOccurred()) - Expect(r).ToNot(BeNil()) + recordAgent(ctx, "deezer", body, "http://img", nil) Expect(t.Steps()).To(Equal([]TraceStep{ {Candidate: "external:deezer", Outcome: OutcomeHit, Detail: "http://img"}, })) }) It("records a miss for a not-found", func() { - t := &ChainTrace{} - _, _, _ = tracingGate(t, passthroughGate)("deezer", miss) + recordAgent(ctx, "deezer", nil, "", agents.ErrNotFound) Expect(t.Steps()[0].Outcome).To(Equal(OutcomeMiss)) }) It("records a miss for a model not-found", func() { - t := &ChainTrace{} - notFound := func() (io.ReadCloser, string, error) { return nil, "", model.ErrNotFound } - _, _, _ = tracingGate(t, passthroughGate)("deezer", notFound) + recordAgent(ctx, "deezer", nil, "", model.ErrNotFound) Expect(t.Steps()[0].Outcome).To(Equal(OutcomeMiss), "both not-found flavours are definitive answers, not faults") }) It("records an error with its reason", func() { - t := &ChainTrace{} - _, _, _ = tracingGate(t, passthroughGate)("apple-music", boom) + recordAgent(ctx, "apple-music", nil, "", errors.New("returned status 429")) Expect(t.Steps()[0].Outcome).To(Equal(OutcomeError)) Expect(t.Steps()[0].Detail).To(ContainSubstring("429")) }) - - It("never calls the agent in offline mode", func() { - t := &ChainTrace{} - called := false - counting := func() (io.ReadCloser, string, error) { - called = true - return hit() - } - - _, _, err := offlineGate(t)("deezer", counting) - - Expect(called).To(BeFalse(), "offline mode must not perform external requests") - Expect(err).To(MatchError(errOfflineSkipped)) - Expect(t.Steps()).To(Equal([]TraceStep{ - {Candidate: "external:deezer", Outcome: OutcomeWouldTry}, - })) - }) }) var _ = Describe("resolveAlbum tracing", func() { @@ -409,51 +437,51 @@ var _ = Describe("NewTracingResolver", func() { t = &ChainTrace{} }) - Context("offline", func() { + Context("resolving", func() { var fake *fakeImageAgent BeforeEach(func() { - fake = &fakeImageAgent{name: "offline-probe"} + // Misses, so the chain falls through to the local tier and both are traced. + fake = &fakeImageAgent{name: "probe", err: agents.ErrNotFound} albumRepo.SetData(model.Albums{{ ID: "al1", Name: "Album", EmbedArtPath: "tests/fixtures/artist/an-album/test.mp3", FolderIDs: []string{"f1"}, }}) artistRepo.SetData(model.Artists{{ID: "ar1", Name: "Artist"}}) }) - It("reports the external tier without asking any agent", func() { - source, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, false).Resolve(context.Background(), model.KindAlbumArtwork, "al1") + It("asks the agents and records what each answered", func() { + source, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindAlbumArtwork, "al1") Expect(err).ToNot(HaveOccurred()) Expect(source).To(Equal("embedded")) - Expect(fake.albumCalls).To(BeZero(), "offline mode must not add load to an external provider") - Expect(t.Steps()).To(ContainElement(TraceStep{Candidate: "external:offline-probe", Outcome: OutcomeWouldTry})) + Expect(fake.albumCalls).To(Equal(1)) + Expect(t.Steps()).To(ContainElement(TraceStep{Candidate: "external:probe", Outcome: OutcomeMiss})) }) It("records the local chain steps too", func() { - _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, false).Resolve(context.Background(), model.KindAlbumArtwork, "al1") + _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindAlbumArtwork, "al1") Expect(err).ToNot(HaveOccurred()) last := t.Steps()[len(t.Steps())-1] - Expect(last.Candidate).To(Equal("embedded"), "the local chain must be traced, not just the external gate") + Expect(last.Candidate).To(Equal("embedded"), "the local chain must be traced, not just the external tier") Expect(last.Outcome).To(Equal(OutcomeHit)) }) It("never persists artwork state", func() { - _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, false).Resolve(context.Background(), model.KindAlbumArtwork, "al1") + _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindAlbumArtwork, "al1") Expect(err).ToNot(HaveOccurred()) Expect(artworkRepo.ItemData).To(BeEmpty(), - "an offline resolution carries extError, which must never be recorded as a real provider failure") + "explain is read-only; a diagnostic walk must never become the stored answer") Expect(queueRepo.Data).To(BeEmpty()) }) It("resolves an artist without persisting anything", func() { - source, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, false).Resolve(context.Background(), model.KindArtistArtwork, "ar1") + source, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindArtistArtwork, "ar1") Expect(err).ToNot(HaveOccurred()) Expect(source).To(BeEmpty()) - Expect(fake.artistCalls).To(BeZero()) - Expect(t.Steps()).To(ContainElement(TraceStep{Candidate: "external:offline-probe", Outcome: OutcomeWouldTry})) + Expect(fake.artistCalls).To(Equal(1)) Expect(artworkRepo.ItemData).To(BeEmpty()) Expect(queueRepo.Data).To(BeEmpty()) }) @@ -465,31 +493,39 @@ var _ = Describe("NewTracingResolver", func() { ID: "al2", Name: "Album", EmbedArtPath: "tests/fixtures/artist/an-album/no-such-file.mp3", FolderIDs: []string{"f1"}, }}) - source, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, false).Resolve(context.Background(), model.KindAlbumArtwork, "al2") + source, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindAlbumArtwork, "al2") Expect(err).ToNot(HaveOccurred()) Expect(source).To(Equal("embedded")) Expect(ffm.IsClosed()).To(BeTrue(), "nothing downstream closes it, so a leak is one file handle per invocation") }) + // Serving falls back disc -> album and track -> disc -> album. The resolver does not, but + // if it ever did, an explain without --live would start calling providers uninvited. + It("cannot reach a provider without live, whatever the chain does", func() { + conf.Server.DiscArtPriority = "external, cover.*" + conf.Server.CoverArtPriority = "external, cover.*" + conf.Server.EnableMediaFileCoverArt = true + mfRepo := tests.CreateMockMediaFileRepo() + mfRepo.SetData(model.MediaFiles{{ID: "mf1", LibraryID: 0, HasCoverArt: true, + Path: "tests/fixtures/artist/an-album/test.mp3"}}) + ds.MockedMediaFile = mfRepo + offline := NewTracingResolver(ds, imageAgents(fake), ffm, t, false) + + _, err := offline.Resolve(context.Background(), model.KindDiscArtwork, "al1:1") + Expect(err).ToNot(HaveOccurred()) + _, err = offline.Resolve(context.Background(), model.KindMediaFileArtwork, "mf1") + Expect(err).ToNot(HaveOccurred()) + + Expect(fake.albumCalls).To(BeZero()) + Expect(fake.artistCalls).To(BeZero()) + }) + It("propagates a lookup error", func() { - _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, false).Resolve(context.Background(), model.KindAlbumArtwork, "nope") + _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindAlbumArtwork, "nope") Expect(err).To(MatchError(model.ErrNotFound)) }) }) - - It("asks the agents when live is true", func() { - fake := &fakeImageAgent{name: "live-probe", err: agents.ErrNotFound} - albumRepo.SetData(model.Albums{{ - ID: "al1", Name: "Album", EmbedArtPath: "tests/fixtures/artist/an-album/test.mp3", FolderIDs: []string{"f1"}, - }}) - - _, err := NewTracingResolver(ds, imageAgents(fake), ffm, t, true).Resolve(context.Background(), model.KindAlbumArtwork, "al1") - - Expect(err).ToNot(HaveOccurred()) - Expect(fake.albumCalls).To(Equal(1)) - Expect(t.Steps()).To(ContainElement(TraceStep{Candidate: "external:live-probe", Outcome: OutcomeMiss})) - }) }) var _ = Describe("resolveDisc tracing", func() { diff --git a/core/artwork/worker.go b/core/artwork/worker.go index be8495305..6271e54bf 100644 --- a/core/artwork/worker.go +++ b/core/artwork/worker.go @@ -235,6 +235,8 @@ func (w *Worker) broadcastRefresh(ctx context.Context, found []model.ArtworkQueu 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 := w.proc.acquire(ctx, item) queue := w.proc.ds.ArtworkQueue(ctx) @@ -247,10 +249,11 @@ func (w *Worker) process(ctx context.Context, item model.ArtworkQueueItem) (outc } case outcomeFoundStale, outcomeFailed: retryAt := time.Now().Add(backoff(item.Attempts)) + 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); err != nil { + 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, @@ -265,6 +268,9 @@ func (w *Worker) process(ctx context.Context, item model.ArtworkQueueItem) (outc 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 { @@ -274,6 +280,18 @@ func (w *Worker) process(ctx context.Context, item model.ArtworkQueueItem) (outc 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 { diff --git a/core/artwork/worker_test.go b/core/artwork/worker_test.go index 53b6a43b2..248e400e1 100644 --- a/core/artwork/worker_test.go +++ b/core/artwork/worker_test.go @@ -95,6 +95,17 @@ func (f *fakeEventBroker) getEvents() []events.Event { var _ events.Broker = (*fakeEventBroker)(nil) +// expireQueued ages a row past the retry budget, so the next drain settles it instead of retrying. +func expireQueued(q *tests.MockArtworkQueueRepo, id string) { + GinkgoHelper() + for k, v := range q.Data { + if v.ItemID == id { + v.EnqueuedAt = time.Now().Add(-(giveUpAfter + time.Hour)) + q.Data[k] = v + } + } +} + func findQueued(q *tests.MockArtworkQueueRepo, kind, id string) *model.ArtworkQueueItem { for _, it := range q.Data { if it.ItemKind == kind && it.ItemID == id { @@ -318,12 +329,7 @@ var _ = Describe("Worker", func() { w = NewWorker(ds, store, ag, ffm, broker, imgCache) Expect(queueRepo.Enqueue(model.ArtworkQueueItem{ItemKind: "al", ItemID: "al9"})).To(Succeed()) // Age the row past the retry budget. - for k, v := range queueRepo.Data { - if v.ItemID == "al9" { - v.EnqueuedAt = time.Now().Add(-(giveUpAfter + time.Hour)) - queueRepo.Data[k] = v - } - } + expireQueued(queueRepo, "al9") n, err := w.drain(ctx, 1) Expect(err).ToNot(HaveOccurred()) @@ -345,12 +351,7 @@ var _ = Describe("Worker", func() { imageAgents(&fakeImageAgent{name: "failAgent", err: errors.New("agent timed out")}) w = NewWorker(ds, store, ag, ffm, broker, imgCache) Expect(queueRepo.Enqueue(model.ArtworkQueueItem{ItemKind: "al", ItemID: "al10"})).To(Succeed()) - for k, v := range queueRepo.Data { - if v.ItemID == "al10" { - v.EnqueuedAt = time.Now().Add(-(giveUpAfter + time.Hour)) - queueRepo.Data[k] = v - } - } + expireQueued(queueRepo, "al10") n, err := w.drain(ctx, 1) Expect(err).ToNot(HaveOccurred()) @@ -362,6 +363,67 @@ var _ = Describe("Worker", func() { Expect(ia.Hash).To(Equal("cafebabe"), "a persistent outage must not discard served art") }) + It("records on the queue row why the last attempt failed", func() { + conf.Server.CoverArtPriority = "external" + ds.MockedAlbum.(*tests.MockAlbumRepo).SetData(model.Albums{{ID: "al11", Name: "Album"}}) + imageAgents(&fakeImageAgent{name: "failAgent", err: errors.New("agent timed out")}) + w = NewWorker(ds, store, ag, ffm, broker, imgCache) + Expect(queueRepo.Enqueue(model.ArtworkQueueItem{ItemKind: "al", ItemID: "al11"})).To(Succeed()) + + _, err := w.drain(ctx, 1) + Expect(err).ToNot(HaveOccurred()) + + it := findQueued(queueRepo, "al", "al11") + Expect(it).ToNot(BeNil()) + Expect(DecodeTrace(it.Trace, "")).To(ContainElement(SatisfyAll( + HaveField("Candidate", "external:failAgent"), + HaveField("Outcome", OutcomeError), + HaveField("Detail", ContainSubstring("agent timed out")), + )), "a retrying row must say why it is retrying") + }) + + // The give-up path settles absent before recording, so the row exists by the time the + // failure is written. Recording first would silently lose it for every unresolved item. + It("keeps the failure for an item that never resolved at all", func() { + conf.Server.CoverArtPriority = "external" + ds.MockedAlbum.(*tests.MockAlbumRepo).SetData(model.Albums{{ID: "al13", Name: "Album"}}) + imageAgents(&fakeImageAgent{name: "failAgent", err: errors.New("agent timed out")}) + w = NewWorker(ds, store, ag, ffm, broker, imgCache) + Expect(queueRepo.Enqueue(model.ArtworkQueueItem{ItemKind: "al", ItemID: "al13"})).To(Succeed()) + expireQueued(queueRepo, "al13") + + _, err := w.drain(ctx, 1) + Expect(err).ToNot(HaveOccurred()) + + ia, err := artRepo.GetItemArtwork(model.KindAlbumArtwork, "al13", model.ImageTypePrimary) + Expect(err).ToNot(HaveOccurred(), "settling absent must create the row the failure is written to") + Expect(ia.Hash).To(BeEmpty()) + Expect(DecodeTrace(ia.LastFailure, "")).ToNot(BeEmpty()) + }) + + It("keeps the failure on the state row after the queue row is deleted", func() { + conf.Server.CoverArtPriority = "external" + ds.MockedAlbum.(*tests.MockAlbumRepo).SetData(model.Albums{{ID: "al12", Name: "Album"}}) + Expect(artRepo.PutItemArtwork(&model.ItemArtwork{ + ItemKind: "al", ItemID: "al12", ImageType: model.ImageTypePrimary, + Hash: "cafebabe", Source: "external:lastfm", + })).To(Succeed()) + imageAgents(&fakeImageAgent{name: "failAgent", err: errors.New("agent timed out")}) + w = NewWorker(ds, store, ag, ffm, broker, imgCache) + Expect(queueRepo.Enqueue(model.ArtworkQueueItem{ItemKind: "al", ItemID: "al12"})).To(Succeed()) + expireQueued(queueRepo, "al12") + + _, err := w.drain(ctx, 1) + Expect(err).ToNot(HaveOccurred()) + + Expect(findQueued(queueRepo, "al", "al12")).To(BeNil()) + ia, err := artRepo.GetItemArtwork(model.KindAlbumArtwork, "al12", model.ImageTypePrimary) + Expect(err).ToNot(HaveOccurred()) + Expect(DecodeTrace(ia.LastFailure, "")).ToNot(BeEmpty(), + "the queue row is gone, so this is the only remaining record of the failure") + Expect(ia.Hash).To(Equal("cafebabe"), "recording the failure must not disturb the served art") + }) + // Media files are excluded from RecheckKinds, so an absent row here would never be // revisited: a transient read error would look permanent. It("does not settle absent on exhaustion for a kind with no recheck path", func() { @@ -371,12 +433,7 @@ var _ = Describe("Worker", func() { {ID: "mfX", LibraryID: 0, Path: "tests/fixtures/artist/an-album/gone.mp3", HasCoverArt: true}, }) Expect(queueRepo.Enqueue(model.ArtworkQueueItem{ItemKind: "mf", ItemID: "mfX"})).To(Succeed()) - for k, v := range queueRepo.Data { - if v.ItemID == "mfX" { - v.EnqueuedAt = time.Now().Add(-(giveUpAfter + time.Hour)) - queueRepo.Data[k] = v - } - } + expireQueued(queueRepo, "mfX") n, err := w.drain(ctx, 1) Expect(err).ToNot(HaveOccurred()) @@ -386,6 +443,8 @@ var _ = Describe("Worker", func() { _, err = artRepo.GetItemArtwork(model.KindMediaFileArtwork, "mfX", model.ImageTypePrimary) Expect(err).To(MatchError(model.ErrNotFound), "no row leaves the track unresolved, so a later view can still recover it") + // Known gap: with no row and no absent settle, there is nowhere to keep the failure. + // Creating one here would write an empty hash, which every reader treats as absent. }) It("resolves a private playlist under an admin context instead of failing forever", func() { diff --git a/db/migrations/20260819204637_add_artwork_trace_columns.sql b/db/migrations/20260819204637_add_artwork_trace_columns.sql new file mode 100644 index 000000000..90fbf9725 --- /dev/null +++ b/db/migrations/20260819204637_add_artwork_trace_columns.sql @@ -0,0 +1,9 @@ +-- +goose Up +ALTER TABLE item_artwork ADD COLUMN trace jsonb NOT NULL DEFAULT '[]'; +ALTER TABLE item_artwork ADD COLUMN last_failure jsonb NOT NULL DEFAULT '[]'; +ALTER TABLE artwork_queue ADD COLUMN trace jsonb NOT NULL DEFAULT '[]'; + +-- +goose Down +ALTER TABLE artwork_queue DROP COLUMN trace; +ALTER TABLE item_artwork DROP COLUMN last_failure; +ALTER TABLE item_artwork DROP COLUMN trace; diff --git a/model/artwork.go b/model/artwork.go index ea724265a..6107e9ffa 100644 --- a/model/artwork.go +++ b/model/artwork.go @@ -51,6 +51,10 @@ type ItemArtwork struct { SourcePath string `structs:"source_path"` // RefMtime is SourcePath's mtime (unix-nanoseconds) at resolution; 0 when there is no SourcePath. RefMtime int64 `structs:"ref_mtime"` + // Trace is the encoded walk that produced this state; LastFailure is the walk of the attempt + // that exhausted the retry budget. Both are JSON, read back with artwork.DecodeTrace. + Trace string `structs:"trace"` + LastFailure string `structs:"last_failure"` // Nullable in the schema, but every insert must set them: these non-pointer fields cannot scan NULL. AttemptedAt time.Time `structs:"attempted_at"` UpdatedAt time.Time `structs:"updated_at"` @@ -91,6 +95,8 @@ type ArtworkQueueItem struct { Attempts int `structs:"attempts"` RetryAt time.Time `structs:"retry_at"` EnqueuedAt time.Time `structs:"enqueued_at"` + // Trace is why the last attempt failed. Only Get reads it; the drain projects it away. + Trace string `structs:"trace"` } // Queue priorities: higher drains first. @@ -109,6 +115,8 @@ type ArtworkRepository interface { PurgeOrphans(createdBefore time.Time) (int64, error) GetItemArtwork(kind Kind, id, imageType string) (*ItemArtwork, error) PutItemArtwork(ia *ItemArtwork) error + // PutLastFailure records the trace of the attempt that exhausted the retry budget. + PutLastFailure(kind Kind, id, imageType, trace string) error DeleteForItems(kind Kind, ids []string) error // GetInfoForItems hydrates a page in one batched query. GetInfoForItems(kind Kind, ids []string) (map[string]ItemArtworkInfo, error) @@ -145,7 +153,7 @@ type ArtworkQueueRepository interface { DequeueBatch(n int, kinds ...string) ([]ArtworkQueueItem, error) // MarkFailedIfUnchanged applies the failure backoff only while retry_at still matches // seenRetryAt, so a concurrent re-enqueue keeps its fresh eligibility. - MarkFailedIfUnchanged(kind, id, imageType string, seenRetryAt, retryAt time.Time) error + MarkFailedIfUnchanged(kind, id, imageType string, seenRetryAt, retryAt time.Time, trace string) error // DeleteIfUnchanged deletes only while retry_at still matches, sparing a concurrent re-enqueue. DeleteIfUnchanged(kind, id, imageType string, retryAt time.Time) error Count() (int64, error) diff --git a/persistence/artwork_queue_repository.go b/persistence/artwork_queue_repository.go index 1ff754dc3..ba9fb6f1a 100644 --- a/persistence/artwork_queue_repository.go +++ b/persistence/artwork_queue_repository.go @@ -18,6 +18,7 @@ import ( const enqueueChunkSize = 100 // Every insert writes these, in this order; the INSERT..SELECT forms must project them to match. +// DequeueBatch also selects exactly these, to leave the drain's rows free of the trace it never reads. var enqueueColumns = []string{"item_kind", "item_id", "image_type", "priority", "attempts", "retry_at", "enqueued_at"} type artworkQueueRepository struct { @@ -42,11 +43,12 @@ func (r *artworkQueueRepository) Get(kind model.Kind, id, imageType string) (*mo return &res, nil } -// Enqueue also resets enqueued_at, so a fresh request does not inherit an old row's spent retry budget. +// Enqueue starts a fresh lifecycle: it resets enqueued_at (so a fresh request does not inherit an old +// row's spent retry budget) and clears trace (so explain does not show a prior failure at attempts 0). func (r *artworkQueueRepository) Enqueue(items ...model.ArtworkQueueItem) error { return r.enqueue(`ON CONFLICT (item_kind, item_id, image_type) DO UPDATE SET priority = MAX(priority, excluded.priority), retry_at = excluded.retry_at, - attempts = 0, enqueued_at = excluded.enqueued_at`, items) + attempts = 0, enqueued_at = excluded.enqueued_at, trace = '[]'`, items) } func (r *artworkQueueRepository) EnqueuePreservingBackoff(items ...model.ArtworkQueueItem) error { @@ -159,7 +161,7 @@ func (r *artworkQueueRepository) enqueue(conflict string, items []model.ArtworkQ } func (r *artworkQueueRepository) DequeueBatch(n int, kinds ...string) ([]model.ArtworkQueueItem, error) { - sel := Select("*").From(r.tableName). + sel := Select(enqueueColumns...).From(r.tableName). Where(LtOrEq{"retry_at": time.Now()}). OrderBy("priority DESC", "enqueued_at ASC"). Limit(uint64(n)) @@ -171,10 +173,11 @@ func (r *artworkQueueRepository) DequeueBatch(n int, kinds ...string) ([]model.A return res, err } -func (r *artworkQueueRepository) MarkFailedIfUnchanged(kind, id, imageType string, seenRetryAt, retryAt time.Time) error { +func (r *artworkQueueRepository) MarkFailedIfUnchanged(kind, id, imageType string, seenRetryAt, retryAt time.Time, trace string) error { upd := Update(r.tableName). Set("attempts", Expr("attempts + 1")). Set("retry_at", retryAt). + Set("trace", trace). Where(Eq{"item_kind": kind, "item_id": id, "image_type": imageType, "retry_at": seenRetryAt}) _, err := r.executeSQL(upd) return err diff --git a/persistence/artwork_queue_repository_test.go b/persistence/artwork_queue_repository_test.go index d11d89a1f..84f3e2986 100644 --- a/persistence/artwork_queue_repository_test.go +++ b/persistence/artwork_queue_repository_test.go @@ -127,19 +127,42 @@ var _ = Describe("ArtworkQueueRepository", func() { Expect(repo.Enqueue(item("al", "m1", model.ArtworkPriorityScan))).To(Succeed()) future := time.Now().Add(48 * time.Hour) - Expect(repo.MarkFailedIfUnchanged("al", "m1", model.ImageTypePrimary, original, future)).To(Succeed()) + Expect(repo.MarkFailedIfUnchanged("al", "m1", model.ImageTypePrimary, original, future, "[]")).To(Succeed()) got, _ = repo.DequeueBatch(10) Expect(got).To(HaveLen(1), "the fresh re-enqueue stays immediately eligible") Expect(got[0].Attempts).To(BeZero(), "re-enqueue clears attempts, and the stale failure must not bump them") current := got[0].RetryAt - Expect(repo.MarkFailedIfUnchanged("al", "m1", model.ImageTypePrimary, current, future)).To(Succeed()) + Expect(repo.MarkFailedIfUnchanged("al", "m1", model.ImageTypePrimary, current, future, `[{"c":"read","o":"error"}]`)).To(Succeed()) got, _ = repo.DequeueBatch(10) Expect(got).To(BeEmpty(), "backed-off row is hidden until the future retry_at") all, _ := repo.Count() Expect(all).To(Equal(int64(1))) }) + It("Enqueue clears a prior lifecycle's failure trace; EnqueuePreservingBackoff keeps it", func() { + // Fail an attempt so the queue row carries a failure trace. + Expect(repo.Enqueue(item("al", "t1", model.ArtworkPriorityScan))).To(Succeed()) + backOff("al", "t1", time.Now().Add(-time.Hour)) + got, _ := repo.DequeueBatch(10) + Expect(got).To(HaveLen(1)) + future := time.Now().Add(48 * time.Hour) + Expect(repo.MarkFailedIfUnchanged("al", "t1", model.ImageTypePrimary, got[0].RetryAt, future, `[{"c":"read","o":"error"}]`)).To(Succeed()) + + // A continuation of the same lifecycle must retain the trace. + Expect(repo.EnqueuePreservingBackoff(item("al", "t1", model.ArtworkPriorityBump))).To(Succeed()) + kept, err := repo.Get(model.KindAlbumArtwork, "t1", model.ImageTypePrimary) + Expect(err).ToNot(HaveOccurred()) + Expect(kept.Trace).To(Equal(`[{"c":"read","o":"error"}]`)) + + // A fresh Enqueue resets attempts to 0, so the stale failure trace must be cleared with it. + Expect(repo.Enqueue(item("al", "t1", model.ArtworkPriorityScan))).To(Succeed()) + fresh, err := repo.Get(model.KindAlbumArtwork, "t1", model.ImageTypePrimary) + Expect(err).ToNot(HaveOccurred()) + Expect(fresh.Attempts).To(BeZero()) + Expect(fresh.Trace).To(Equal("[]"), "a fresh lifecycle has no last-attempt trace") + }) + It("Enqueue restarts the retry budget an existing row had spent", func() { Expect(repo.Enqueue(item("al", "e1", model.ArtworkPriorityScan))).To(Succeed()) backOff("al", "e1", time.Now().Add(-time.Hour)) diff --git a/persistence/artwork_repository.go b/persistence/artwork_repository.go index 22662b575..89eb1d415 100644 --- a/persistence/artwork_repository.go +++ b/persistence/artwork_repository.go @@ -134,11 +134,21 @@ func (r *artworkRepository) PutItemArtwork(ia *model.ItemArtwork) error { } ins := Insert(itemArtworkTable).SetMap(values).Suffix(`ON CONFLICT (item_kind, item_id, image_type) DO UPDATE SET hash=excluded.hash, source=excluded.source, source_path=excluded.source_path, ref_mtime=excluded.ref_mtime, + trace=excluded.trace, last_failure=excluded.last_failure, attempted_at=excluded.attempted_at, updated_at=excluded.updated_at`) _, err = r.items.executeSQL(ins) return err } +// PutLastFailure records why an item exhausted its retry budget. It only updates an existing row: +// inserting one would write an empty hash, which the rest of the system reads as a settled absent. +func (r *artworkRepository) PutLastFailure(kind model.Kind, id, imageType, trace string) error { + upd := Update(itemArtworkTable).Set("last_failure", trace). + Where(Eq{"item_kind": kind.Prefix(), "item_id": id, "image_type": imageType}) + _, err := r.items.executeSQL(upd) + return err +} + func (r *artworkRepository) DeleteForItems(kind model.Kind, ids []string) error { for chunk := range slices.Chunk(ids, artworkBatchSize) { if err := r.items.delete(Eq{"item_kind": kind.Prefix(), "item_id": chunk}); err != nil { diff --git a/persistence/artwork_repository_test.go b/persistence/artwork_repository_test.go index 683dc2d0f..a9687f76b 100644 --- a/persistence/artwork_repository_test.go +++ b/persistence/artwork_repository_test.go @@ -28,6 +28,51 @@ var _ = Describe("ArtworkRepository", func() { repo = NewArtworkRepository(context.Background(), GetDBXBuilder()) }) + Context("resolution traces", func() { + const traceJSON = `[{"c":"cover.*","o":"hit"}]` + + It("round-trips the trace with the state row", func() { + Expect(repo.PutItemArtwork(&model.ItemArtwork{ItemKind: "al", ItemID: "t1", + ImageType: model.ImageTypePrimary, Hash: "h1", Trace: traceJSON})).To(Succeed()) + + got, err := repo.GetItemArtwork(model.KindAlbumArtwork, "t1", model.ImageTypePrimary) + Expect(err).ToNot(HaveOccurred()) + Expect(got.Trace).To(Equal(traceJSON)) + Expect(got.LastFailure).To(BeEmpty()) + }) + + It("replaces the trace when the item is resolved again", func() { + Expect(repo.PutItemArtwork(&model.ItemArtwork{ItemKind: "al", ItemID: "t2", + ImageType: model.ImageTypePrimary, Trace: traceJSON})).To(Succeed()) + Expect(repo.PutItemArtwork(&model.ItemArtwork{ItemKind: "al", ItemID: "t2", + ImageType: model.ImageTypePrimary, Trace: `[{"c":"embedded","o":"hit"}]`})).To(Succeed()) + + got, _ := repo.GetItemArtwork(model.KindAlbumArtwork, "t2", model.ImageTypePrimary) + Expect(got.Trace).To(Equal(`[{"c":"embedded","o":"hit"}]`)) + }) + + It("records a last failure on an existing row", func() { + Expect(repo.PutItemArtwork(&model.ItemArtwork{ItemKind: "al", ItemID: "t3", + ImageType: model.ImageTypePrimary, Hash: "h3"})).To(Succeed()) + + Expect(repo.PutLastFailure(model.KindAlbumArtwork, "t3", model.ImageTypePrimary, + `[{"c":"decode","o":"error"}]`)).To(Succeed()) + + got, _ := repo.GetItemArtwork(model.KindAlbumArtwork, "t3", model.ImageTypePrimary) + Expect(got.LastFailure).To(Equal(`[{"c":"decode","o":"error"}]`)) + Expect(got.Hash).To(Equal("h3"), "recording a failure must not disturb the served artwork") + }) + + // Inserting here would write hash='', which every reader treats as a settled absent. + It("never creates a row for an item that has no state", func() { + Expect(repo.PutLastFailure(model.KindAlbumArtwork, "ghost", model.ImageTypePrimary, + `[{"c":"decode","o":"error"}]`)).To(Succeed()) + + _, err := repo.GetItemArtwork(model.KindAlbumArtwork, "ghost", model.ImageTypePrimary) + Expect(err).To(MatchError(model.ErrNotFound)) + }) + }) + Context("image identity", func() { It("stores and retrieves an artwork by hash", func() { a := &model.Artwork{Hash: "abc123", Mime: "image/jpeg", Width: 500, Height: 500, SizeBytes: 1234, BlurHash: "LKO2?U%2Tw=w"} diff --git a/tests/mock_artwork_queue_repo.go b/tests/mock_artwork_queue_repo.go index c8e915daa..f8f57e8d9 100644 --- a/tests/mock_artwork_queue_repo.go +++ b/tests/mock_artwork_queue_repo.go @@ -118,7 +118,7 @@ func (m *MockArtworkQueueRepo) DequeueBatch(n int, kinds ...string) ([]model.Art return res, nil } -func (m *MockArtworkQueueRepo) MarkFailedIfUnchanged(kind, id, imageType string, seenRetryAt, retryAt time.Time) error { +func (m *MockArtworkQueueRepo) MarkFailedIfUnchanged(kind, id, imageType string, seenRetryAt, retryAt time.Time, trace string) error { m.mu.Lock() defer m.mu.Unlock() if m.Err != nil { @@ -128,6 +128,7 @@ func (m *MockArtworkQueueRepo) MarkFailedIfUnchanged(kind, id, imageType string, if it, ok := m.Data[k]; ok && it.RetryAt.Equal(seenRetryAt) { it.Attempts++ it.RetryAt = retryAt + it.Trace = trace m.Data[k] = it } return nil diff --git a/tests/mock_artwork_repo.go b/tests/mock_artwork_repo.go index 2ace0daba..5d76a0169 100644 --- a/tests/mock_artwork_repo.go +++ b/tests/mock_artwork_repo.go @@ -122,6 +122,20 @@ func (m *MockArtworkRepo) GetItemArtwork(kind model.Kind, id, imageType string) return nil, model.ErrNotFound } +func (m *MockArtworkRepo) PutLastFailure(kind model.Kind, id, imageType, trace string) error { + m.mu.Lock() + defer m.mu.Unlock() + if m.Err != nil { + return m.Err + } + key := iaKey(kind.Prefix(), id, imageType) + if ia, ok := m.ItemData[key]; ok { + ia.LastFailure = trace + m.ItemData[key] = ia + } + return nil +} + func (m *MockArtworkRepo) PutItemArtwork(ia *model.ItemArtwork) error { m.mu.Lock() defer m.mu.Unlock() From ffc68e29dbf53baf11ea6ae06d225a2ddea64e78 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Fri, 21 Aug 2026 14:03:59 -0400 Subject: [PATCH 06/13] feat(cli): add `artwork cancel` to call off queued artwork work (#6006) * feat(cli): add `artwork cancel` to call off queued artwork work A bulk backfill had no off switch. Changing an artwork setting bumps the config fingerprint, which enqueues every entity in the library, and the only way to stop it was to turn agents off -- which changes the fingerprint again and enqueues a second full backfill. The escape hatch was the trap. `artwork cancel` deletes pending queue rows selected by --kind and/or --priority, with the --dry-run/confirm/-y flow `reprocess` already uses. Cancelling by priority is the point: it drops a runaway backfill while leaving the bump-priority rows an operator queued by hand. It only touches the queue. Resolved artwork and the item_artwork state behind `artwork explain` are left alone, and the trace of why a cancelled item last failed goes with its row. Preserving that trace would mean writing it to last_failure, which `explain` prints under "Gave up after" -- reporting a cancellation as an exhausted retry budget. The help text says the trace is discarded instead. Two limits the help text states, because neither is guessable: work already dequeued is not interrupted, and an item with no artwork state yet can be queued again by the hourly missing-artwork recheck. Cancel calls off queued work; it does not stop the worker. --kind validates against RefreshableKinds, not the RecheckKinds `reprocess` uses: the queue holds media file rows, so --all has to reach them. PurgeQueued follows the repository's naming rule -- it finds its own rows and reports how many went -- and ignores retry_at, since a row still backing off is pending work. The preview reuses CountByKindAndPriority rather than adding a counter. reprocessConfirm became confirmUnlessYes(yes, in, verb) now that two commands prompt. * refactor(cli): share the artwork queue filter between the preview and the delete Follow-up cleanup on the previous commit; no change to what the command does, apart from --all, noted below. The "which rows does cancel touch" predicate was written three times: once as SQL in PurgeQueued, once in Go in cmd's matchingQueueStats, and once more in the mock. The preview and the delete could therefore drift, and the mock would keep the tests green while they did. persistence now has one artworkQueueFilter, shared by PurgeQueued and a new CountQueued, and cmd does no filtering at all. That also makes the preview cheaper. It counted the whole queue and filtered in Go, so `artwork cancel --kind al` scanned every row of every kind to print a handful. CountQueued pushes the filter into SQL, which the drain index serves as a range seek. CountByKindAndPriority is gone: it is CountQueued(nil, nil). --all now selects with an empty filter instead of enumerating RefreshableKinds. It is what the flag help already claimed, and the enumeration was narrower than its own documentation -- a queue row whose item_kind this build does not know survived `--all` with no flag combination able to remove it. It also restores SQLite's truncate path: measured with EXPLAIN QUERY PLAN, a bare DELETE plans to nothing, while `WHERE (1=1)` -- which an empty squirrel And renders -- plans to a full index scan. A test pins the filter's emptiness so that cannot regress silently. Also folded together three copies of the parse-and-dedup loop (parseAll), two copies of the queue-stats table (printQueueStats, now shared with `artwork status`), two copies of the stat sum (queueTotal), and four copies of the kind-to-prefix mapping (model.KindPrefixes). The PurgeQueued specs became one DescribeTable that asserts count and delete agree on every selection. * docs(cli): say when `artwork cancel` evaluates its selection The help text covered the two limits that surprise an operator after the fact, but not the one that bites during the prompt: the count is a preview, and the filters run again on confirm. A scan or a manual refresh landing in between is cancelled without ever appearing in the table the operator agreed to. Deleting only the previewed rows was considered and rejected. The exposure is one item re-resolving on next view instead of immediately: clearing an item's artwork state is what every recovery path selects on, so a lost Bump row from artwork.Refresh comes back at the same priority via provisional() on the next request, and otherwise within the hour via EnqueueAllMissing. Buying a guarantee against that costs the truncate path on --all, the flag that exists for a 29k-item backfill. * refactor(cli): share one set of flag targets across the artwork subcommands reprocess and cancel each declared their own kinds/all/dry-run/yes variables, but cobra only ever parses the one subcommand being run, so the two sets could never hold values at the same time. backup.go already binds one backupDir across two subcommands and one force across two more; this follows that. Ten package-level variables become six. Each command keeps its own help string and its own valid-kind list, so --kind still reports RecheckKinds for reprocess and RefreshableKinds for cancel, and --source and --priority stay registered only on the command that has them. The priority lookup table is now knownPriorities, freeing the artworkPriorities name for the flag. The new name also reads better against priorityName's fallback for a value it does not know. --- cmd/artwork.go | 223 +++++++++++++++---- cmd/artwork_test.go | 168 +++++++++++++- model/artwork.go | 7 +- model/artwork_id.go | 7 + persistence/artwork_queue_repository.go | 40 +++- persistence/artwork_queue_repository_test.go | 71 +++++- tests/mock_artwork_queue_repo.go | 29 ++- 7 files changed, 479 insertions(+), 66 deletions(-) diff --git a/cmd/artwork.go b/cmd/artwork.go index 63f0d0917..b193abeaf 100644 --- a/cmd/artwork.go +++ b/cmd/artwork.go @@ -26,12 +26,14 @@ import ( var explainLive bool +// Only one subcommand runs per invocation, so reprocess and cancel bind the same flag targets. var ( - reprocessKinds []string - reprocessSources []string - reprocessAll bool - reprocessDryRun bool - reprocessYes bool + artworkKinds []string + artworkSources []string + artworkPriorities []string + artworkAll bool + artworkDryRun bool + artworkYes bool ) func init() { @@ -39,17 +41,26 @@ func init() { "walk the chain again now, performing real external lookups, instead of reporting the "+ "stored trace of the last resolution; also initializes plugin agents, which may open "+ "external connections") - artworkReprocessCmd.Flags().StringSliceVar(&reprocessKinds, "kind", nil, + artworkReprocessCmd.Flags().StringSliceVar(&artworkKinds, "kind", nil, "kinds to reprocess ("+kindPrefixes(artwork.RecheckKinds)+"); repeatable") - artworkReprocessCmd.Flags().StringSliceVar(&reprocessSources, "source", nil, + artworkReprocessCmd.Flags().StringSliceVar(&artworkSources, "source", nil, "only items currently resolved from these sources (e.g. folder, external:deezer, absent)") - artworkReprocessCmd.Flags().BoolVar(&reprocessAll, "all", false, "reprocess every kind") - artworkReprocessCmd.Flags().BoolVar(&reprocessDryRun, "dry-run", false, + artworkReprocessCmd.Flags().BoolVar(&artworkAll, "all", false, "reprocess every kind") + artworkReprocessCmd.Flags().BoolVar(&artworkDryRun, "dry-run", false, "report what would be queued and exit without queueing") - artworkReprocessCmd.Flags().BoolVarP(&reprocessYes, "yes", "y", false, "skip the confirmation prompt") + artworkReprocessCmd.Flags().BoolVarP(&artworkYes, "yes", "y", false, "skip the confirmation prompt") + artworkCancelCmd.Flags().StringSliceVar(&artworkKinds, "kind", nil, + "kinds to cancel ("+kindPrefixes(artwork.RefreshableKinds)+"); repeatable") + artworkCancelCmd.Flags().StringSliceVar(&artworkPriorities, "priority", nil, + "only rows queued at these priorities ("+priorityNames()+"); repeatable") + artworkCancelCmd.Flags().BoolVar(&artworkAll, "all", false, "cancel every kind at every priority") + artworkCancelCmd.Flags().BoolVar(&artworkDryRun, "dry-run", false, + "report what would be cancelled and exit without cancelling") + artworkCancelCmd.Flags().BoolVarP(&artworkYes, "yes", "y", false, "skip the confirmation prompt") artworkCmd.AddCommand(artworkExplainCmd) artworkCmd.AddCommand(artworkRefreshCmd) artworkCmd.AddCommand(artworkReprocessCmd) + artworkCmd.AddCommand(artworkCancelCmd) artworkCmd.AddCommand(artworkStatusCmd) rootCmd.AddCommand(artworkCmd) } @@ -93,6 +104,22 @@ var artworkReprocessCmd = &cobra.Command{ }, } +var artworkCancelCmd = &cobra.Command{ + Use: "cancel", + Short: "Cancel pending artwork work in bulk, by kind and/or queue priority", + Long: "Cancel pending artwork work in bulk, by kind and/or queue priority.\n\n" + + "Only the queue is touched: resolved artwork and the state behind `artwork explain` are\n" + + "left alone, and the trace of why a cancelled item last failed goes with its queue row.\n\n" + + "Work already picked up is not interrupted, and an item with no artwork yet can be\n" + + "queued again by the hourly re-check. The selection is applied again when you confirm,\n" + + "so anything queued after the preview is cancelled too. Use it to call off a bulk\n" + + "backfill, not to stop the worker.", + Args: cobra.NoArgs, + Run: func(cmd *cobra.Command, args []string) { + runCancel(cmd.Context()) + }, +} + var artworkStatusCmd = &cobra.Command{ Use: "status", Short: "Report the artwork queue, where artwork resolves from, and the backfill state", @@ -133,9 +160,11 @@ type statusReport struct { current string } -func (r statusReport) queueTotal() int64 { +func (r statusReport) queueTotal() int64 { return queueTotal(r.queue) } + +func queueTotal(stats []model.ArtworkQueueStat) int64 { var n int64 - for _, s := range r.queue { + for _, s := range stats { n += s.Count } return n @@ -155,7 +184,7 @@ func collectStatus(ctx context.Context, ds model.DataStore) (statusReport, error q := ds.ArtworkQueue(ctx) var rep statusReport var err error - if rep.queue, err = q.CountByKindAndPriority(); err != nil { + if rep.queue, err = q.CountQueued(nil, nil); err != nil { return rep, fmt.Errorf("breaking the artwork queue down by kind: %w", err) } @@ -195,11 +224,7 @@ func formatStatus(rep statusReport) string { if len(rep.queue) == 0 { fmt.Fprintln(w, " (empty)") } else { - fmt.Fprintln(w, " KIND\tPRIORITY\tITEMS") - for _, s := range rep.queue { - fmt.Fprintf(w, " %s\t%s\t%d\n", kindName(s.ItemKind), priorityName(s.Priority), s.Count) - } - fmt.Fprintf(w, " TOTAL\t\t%d\n", rep.queueTotal()) + printQueueStats(w, rep.queue, rep.queueTotal(), "ITEMS", " ") } fmt.Fprintln(w, "\nSources") @@ -246,6 +271,15 @@ func backfillState(rep statusReport) string { return "up to date" } +// printQueueStats writes the shared queue breakdown; the caller owns the tab writer and flushes it. +func printQueueStats(w io.Writer, stats []model.ArtworkQueueStat, total int64, countHeader, indent string) { + fmt.Fprintf(w, "%sKIND\tPRIORITY\t%s\n", indent, countHeader) + for _, s := range stats { + fmt.Fprintf(w, "%s%s\t%s\t%d\n", indent, kindName(s.ItemKind), priorityName(s.Priority), s.Count) + } + fmt.Fprintf(w, "%sTOTAL\t\t%d\n", indent, total) +} + func kindName(prefix string) string { if k, ok := model.ParseKind(prefix); ok { return k.String() @@ -253,22 +287,44 @@ func kindName(prefix string) string { return prefix } +type artworkPriority struct { + name string + value int +} + +// knownPriorities is the one listing behind both the name and the parse, so they cannot drift. +var knownPriorities = []artworkPriority{ + {"bump", model.ArtworkPriorityBump}, + {"scan", model.ArtworkPriorityScan}, + {"backfill", model.ArtworkPriorityBackfill}, + {"recheck", model.ArtworkPriorityRecheck}, +} + +// priorityName falls back to the number: a row written by a newer version still has to print. func priorityName(p int) string { - switch p { - case model.ArtworkPriorityRecheck: - return "recheck" - case model.ArtworkPriorityBackfill: - return "backfill" - case model.ArtworkPriorityScan: - return "scan" - case model.ArtworkPriorityBump: - return "bump" + for _, ap := range knownPriorities { + if ap.value == p { + return ap.name + } } return strconv.Itoa(p) } +func priorityNames() string { + return strings.Join(slice.Map(knownPriorities, func(ap artworkPriority) string { return ap.name }), ", ") +} + +func parseArtworkPriority(s string) (int, error) { + for _, ap := range knownPriorities { + if ap.name == s { + return ap.value, nil + } + } + return 0, fmt.Errorf("invalid priority %q, expected one of: %s", s, priorityNames()) +} + func runReprocess(ctx context.Context) { - kinds, err := selectedKinds(reprocessKinds, reprocessSources, reprocessAll) + kinds, err := selectedKinds(artworkKinds, artworkSources, artworkAll) if err != nil { log.Fatal(ctx, err) } @@ -285,8 +341,8 @@ func runReprocess(ctx context.Context) { imageAgents = imageAgentCount(ds, mgr) } - if err := reprocessArtwork(ctx, ds, kinds, repositorySources(reprocessSources), imageAgents, - reprocessDryRun, reprocessConfirm(reprocessYes, os.Stdin), os.Stdout); err != nil { + if err := reprocessArtwork(ctx, ds, kinds, repositorySources(artworkSources), imageAgents, + artworkDryRun, confirmUnlessYes(artworkYes, os.Stdin, "re-resolve"), os.Stdout); err != nil { log.Fatal(ctx, err) } } @@ -299,16 +355,9 @@ func selectedKinds(kinds, sources []string, all bool) ([]model.Kind, error) { if len(kinds) == 0 { return nil, fmt.Errorf("no selector given: pass --kind, --source or --all") } - out := make([]model.Kind, 0, len(kinds)) - for _, k := range kinds { - kind, err := parseArtworkKind(k, artwork.RecheckKinds) - if err != nil { - return nil, err - } - out = append(out, kind) - } - // A repeated kind would be counted twice, overstating the cost the operator confirms. - return slice.Unique(out), nil + return parseAll(kinds, func(s string) (model.Kind, error) { + return parseArtworkKind(s, artwork.RecheckKinds) + }) } // absentSource is how the stored empty source — resolved, no image — is spelled on the CLI. @@ -327,11 +376,11 @@ func displaySource(s string) string { return cmp.Or(s, absentSource) } type confirmFunc func(out io.Writer, total, external int64) bool -func reprocessConfirm(yes bool, in io.Reader) confirmFunc { +func confirmUnlessYes(yes bool, in io.Reader, verb string) confirmFunc { if yes { return func(io.Writer, int64, int64) bool { return true } } - return promptConfirm(in) + return promptConfirm(in, verb) } // externalEstimate claims no bound: a local hit ends the walk before any agent is asked, and the @@ -379,13 +428,13 @@ func configuredAgents() []string { return names } -func promptConfirm(in io.Reader) confirmFunc { +func promptConfirm(in io.Reader, verb string) confirmFunc { return func(out io.Writer, total, external int64) bool { var cost string if external > 0 { cost = fmt.Sprintf(" %s", externalLookupLine(external)) } - fmt.Fprintf(out, "\nThis will re-resolve %d items.%s Continue? [y/N] ", total, cost) + fmt.Fprintf(out, "\nThis will %s %d items.%s Continue? [y/N] ", verb, total, cost) var answer string if _, err := fmt.Fscanln(in, &answer); err != nil { return false @@ -477,6 +526,90 @@ func reprocessArtwork(ctx context.Context, ds model.DataStore, kinds []model.Kin return nil } +func runCancel(ctx context.Context) { + kinds, priorities, err := cancelSelection(artworkKinds, artworkPriorities, artworkAll) + if err != nil { + log.Fatal(ctx, err) + } + + defer db.Init(ctx)() + ds, ctx := getAdminContext(ctx) + + if err := cancelArtwork(ctx, ds, kinds, priorities, artworkDryRun, + confirmUnlessYes(artworkYes, os.Stdin, "cancel"), os.Stdout); err != nil { + log.Fatal(ctx, err) + } +} + +// cancelSelection leaves --all as the empty filter the repository reads as "every one", so a row +// whose kind this build does not know still gets cancelled. +func cancelSelection(kinds, priorities []string, all bool) ([]model.Kind, []int, error) { + if all { + return nil, nil, nil + } + if len(kinds) == 0 && len(priorities) == 0 { + return nil, nil, fmt.Errorf("no selector given: pass --kind, --priority or --all") + } + // RefreshableKinds, not RecheckKinds: media files are queued, so --kind must reach them. + outKinds, err := parseAll(kinds, func(s string) (model.Kind, error) { + return parseArtworkKind(s, artwork.RefreshableKinds) + }) + if err != nil { + return nil, nil, err + } + outPriorities, err := parseAll(priorities, parseArtworkPriority) + if err != nil { + return nil, nil, err + } + return outKinds, outPriorities, nil +} + +// parseAll drops repeats: a doubled selector would overstate the total the operator confirms. +func parseAll[T comparable](values []string, parse func(string) (T, error)) ([]T, error) { + out := make([]T, 0, len(values)) + for _, v := range values { + parsed, err := parse(v) + if err != nil { + return nil, err + } + out = append(out, parsed) + } + return slice.Unique(out), nil +} + +func cancelArtwork(ctx context.Context, ds model.DataStore, kinds []model.Kind, priorities []int, + dryRun bool, confirm confirmFunc, out io.Writer) error { + q := ds.ArtworkQueue(ctx) + matched, err := q.CountQueued(kinds, priorities) + if err != nil { + return fmt.Errorf("counting queued artwork: %w", err) + } + total := queueTotal(matched) + w := newTabWriter(out) + printQueueStats(w, matched, total, "MATCHED", "") + w.Flush() + + switch { + case total == 0: + fmt.Fprintln(out, "\nNothing matches this selection.") + return nil + case dryRun: + fmt.Fprintln(out, "\nDry run: nothing was cancelled.") + return nil + case !confirm(out, total, 0): + fmt.Fprintln(out, "Aborted: nothing was cancelled.") + return nil + } + + cancelled, err := q.PurgeQueued(kinds, priorities) + if err != nil { + return fmt.Errorf("cancelling queued artwork: %w", err) + } + // Count and delete are separate statements, so a drain in between makes these two differ. + fmt.Fprintf(out, "Cancelled %d of %d matched items.\n", cancelled, total) + return nil +} + // printReprocessPreview also states the external estimate, which --dry-run must show because it // skips the prompt that would otherwise carry it. func printReprocessPreview(out io.Writer, kinds []model.Kind, matched []int64, total, external int64, sources []string) { @@ -542,7 +675,7 @@ var explainKinds = []model.Kind{ } func kindPrefixes(kinds []model.Kind) string { - return strings.Join(slice.Map(kinds, func(k model.Kind) string { return k.Prefix() }), ", ") + return strings.Join(model.KindPrefixes(kinds), ", ") } func parseArtworkKind(s string, valid []model.Kind) (model.Kind, error) { diff --git a/cmd/artwork_test.go b/cmd/artwork_test.go index 38a1b79cb..1d2bdae73 100644 --- a/cmd/artwork_test.go +++ b/cmd/artwork_test.go @@ -549,36 +549,36 @@ var _ = Describe("promptConfirm", func() { BeforeEach(func() { out.Reset() }) It("states the external cost and accepts an explicit yes", func() { - Expect(promptConfirm(strings.NewReader("y\n"))(&out, 42, 7)).To(BeTrue()) + Expect(promptConfirm(strings.NewReader("y\n"), "re-resolve")(&out, 42, 7)).To(BeTrue()) Expect(out.String()).To(ContainSubstring("re-resolve 42 items")) Expect(out.String()).To(ContainSubstring("External lookups: ~7 estimated")) }) It("defaults to no on anything else", func() { - Expect(promptConfirm(strings.NewReader("\n"))(&out, 1, 1)).To(BeFalse()) - Expect(promptConfirm(strings.NewReader("nope\n"))(&out, 1, 1)).To(BeFalse()) - Expect(promptConfirm(strings.NewReader(""))(&out, 1, 1)).To(BeFalse()) + Expect(promptConfirm(strings.NewReader("\n"), "re-resolve")(&out, 1, 1)).To(BeFalse()) + Expect(promptConfirm(strings.NewReader("nope\n"), "re-resolve")(&out, 1, 1)).To(BeFalse()) + Expect(promptConfirm(strings.NewReader(""), "re-resolve")(&out, 1, 1)).To(BeFalse()) }) It("drops the external clause when no lookup will be made", func() { - Expect(promptConfirm(strings.NewReader("y\n"))(&out, 3, 0)).To(BeTrue()) - Expect(out.String()).To(ContainSubstring("re-resolve 3 items.")) + Expect(promptConfirm(strings.NewReader("y\n"), "cancel")(&out, 3, 0)).To(BeTrue()) + Expect(out.String()).To(ContainSubstring("cancel 3 items.")) Expect(out.String()).ToNot(ContainSubstring("External lookups")) }) }) -var _ = Describe("reprocessConfirm", func() { +var _ = Describe("confirmUnlessYes", func() { var out strings.Builder BeforeEach(func() { out.Reset() }) It("prompts when --yes was not given", func() { - Expect(reprocessConfirm(false, strings.NewReader("n\n"))(&out, 5, 5)).To(BeFalse()) + Expect(confirmUnlessYes(false, strings.NewReader("n\n"), "re-resolve")(&out, 5, 5)).To(BeFalse()) Expect(out.String()).To(ContainSubstring("Continue?")) }) It("bypasses the prompt only for --yes", func() { - Expect(reprocessConfirm(true, strings.NewReader(""))(&out, 5, 5)).To(BeTrue()) + Expect(confirmUnlessYes(true, strings.NewReader(""), "re-resolve")(&out, 5, 5)).To(BeTrue()) Expect(out.String()).To(BeEmpty(), "--yes must not print a prompt it never reads") }) }) @@ -1059,3 +1059,153 @@ var _ = Describe("configuredAgents", func() { Expect(configuredAgents()).To(BeEmpty()) }) }) + +var _ = Describe("parseArtworkPriority", func() { + It("accepts every name status prints", func() { + for _, p := range []int{model.ArtworkPriorityRecheck, model.ArtworkPriorityBackfill, + model.ArtworkPriorityScan, model.ArtworkPriorityBump} { + Expect(parseArtworkPriority(priorityName(p))).To(Equal(p)) + } + }) + + It("rejects an unknown name and lists the valid ones", func() { + _, err := parseArtworkPriority("urgent") + Expect(err).To(MatchError(ContainSubstring(`invalid priority "urgent"`))) + Expect(err).To(MatchError(ContainSubstring("backfill"))) + }) + + // Accepting the raw numbers would make the help text a lie and let a typo like 11 select nothing. + It("rejects the numeric form", func() { + _, err := parseArtworkPriority("10") + Expect(err).To(HaveOccurred()) + }) +}) + +var _ = Describe("artwork cancel selection", func() { + It("errors when no selector is given", func() { + _, _, err := cancelSelection(nil, nil, false) + Expect(err).To(MatchError(ContainSubstring("no selector given"))) + }) + + // Empty, not an enumeration of the known kinds: --all must also take a queue row whose kind + // this build does not recognise. + It("selects with no filter at all for --all", func() { + kinds, priorities, err := cancelSelection(nil, nil, true) + Expect(err).ToNot(HaveOccurred()) + Expect(kinds).To(BeEmpty()) + Expect(priorities).To(BeEmpty()) + }) + + // The queue holds media file rows, so --all must reach them. + It("accepts media file artwork, which reprocess does not", func() { + kinds, _, err := cancelSelection([]string{"mf"}, nil, false) + Expect(err).ToNot(HaveOccurred()) + Expect(kinds).To(Equal([]model.Kind{model.KindMediaFileArtwork})) + }) + + It("treats a priority filter on its own as a complete selection", func() { + kinds, priorities, err := cancelSelection(nil, []string{"backfill"}, false) + Expect(err).ToNot(HaveOccurred()) + Expect(kinds).To(BeEmpty(), "no kind filter means every kind") + Expect(priorities).To(Equal([]int{model.ArtworkPriorityBackfill})) + }) + + It("returns only the named kinds and priorities", func() { + kinds, priorities, err := cancelSelection([]string{"ar", "al"}, []string{"backfill", "scan"}, false) + Expect(err).ToNot(HaveOccurred()) + Expect(kinds).To(Equal([]model.Kind{model.KindArtistArtwork, model.KindAlbumArtwork})) + Expect(priorities).To(Equal([]int{model.ArtworkPriorityBackfill, model.ArtworkPriorityScan})) + }) + + It("counts a repeated kind and a repeated priority once", func() { + kinds, priorities, err := cancelSelection([]string{"ar", "ar"}, []string{"bump", "bump"}, false) + Expect(err).ToNot(HaveOccurred()) + Expect(kinds).To(HaveLen(1)) + Expect(priorities).To(HaveLen(1)) + }) + + It("rejects an unknown kind", func() { + _, _, err := cancelSelection([]string{"zz"}, nil, false) + Expect(err).To(MatchError(ContainSubstring(`invalid kind "zz"`))) + }) + + It("rejects a kind that is never queued", func() { + _, _, err := cancelSelection([]string{"dc"}, nil, false) + Expect(err).To(MatchError(ContainSubstring("invalid kind"))) + }) + + It("rejects an unknown priority", func() { + _, _, err := cancelSelection(nil, []string{"urgent"}, false) + Expect(err).To(MatchError(ContainSubstring("invalid priority"))) + }) +}) + +var _ = Describe("cancelArtwork", func() { + var ds *tests.MockDataStore + var queue *tests.MockArtworkQueueRepo + var out strings.Builder + ctx := context.Background() + accept := func(io.Writer, int64, int64) bool { return true } + decline := func(io.Writer, int64, int64) bool { return false } + + BeforeEach(func() { + ds = &tests.MockDataStore{} + queue = ds.ArtworkQueue(ctx).(*tests.MockArtworkQueueRepo) + out.Reset() + Expect(queue.Enqueue( + model.ArtworkQueueItem{ItemKind: "ar", ItemID: "ar-1", ImageType: model.ImageTypePrimary, + Priority: model.ArtworkPriorityBackfill}, + model.ArtworkQueueItem{ItemKind: "ar", ItemID: "ar-2", ImageType: model.ImageTypePrimary, + Priority: model.ArtworkPriorityBump}, + model.ArtworkQueueItem{ItemKind: "al", ItemID: "al-1", ImageType: model.ImageTypePrimary, + Priority: model.ArtworkPriorityBackfill}, + )).To(Succeed()) + }) + + It("previews the per-kind breakdown and cancels nothing on a dry run", func() { + Expect(cancelArtwork(ctx, ds, []model.Kind{model.KindArtistArtwork}, nil, true, accept, &out)).To(Succeed()) + + Expect(out.String()).To(ContainSubstring("artist")) + Expect(out.String()).To(ContainSubstring("backfill")) + Expect(out.String()).To(ContainSubstring("TOTAL")) + Expect(out.String()).To(ContainSubstring("Dry run")) + Expect(queue.Count()).To(BeNumerically("==", 3)) + }) + + It("cancels nothing when the operator declines", func() { + Expect(cancelArtwork(ctx, ds, nil, nil, false, decline, &out)).To(Succeed()) + + Expect(out.String()).To(ContainSubstring("Aborted")) + Expect(queue.Count()).To(BeNumerically("==", 3)) + }) + + It("deletes the selected rows and leaves the rest queued", func() { + Expect(cancelArtwork(ctx, ds, nil, []int{model.ArtworkPriorityBackfill}, false, accept, &out)).To(Succeed()) + + Expect(queue.Count()).To(BeNumerically("==", 1)) + _, err := queue.Get(model.KindArtistArtwork, "ar-2", model.ImageTypePrimary) + Expect(err).ToNot(HaveOccurred(), "a non-matching priority must stay queued") + Expect(out.String()).To(ContainSubstring("Cancelled 2 of 2 matched items.")) + }) + + It("cancels every kind and priority when neither filter is given", func() { + Expect(cancelArtwork(ctx, ds, nil, nil, false, accept, &out)).To(Succeed()) + Expect(queue.Count()).To(BeZero()) + }) + + It("stops at a selection that matches nothing instead of prompting", func() { + refuse := func(io.Writer, int64, int64) bool { + Fail("must not prompt when nothing matches") + return false + } + Expect(cancelArtwork(ctx, ds, []model.Kind{model.KindPlaylistArtwork}, nil, false, refuse, &out)).To(Succeed()) + + Expect(out.String()).To(ContainSubstring("Nothing matches this selection.")) + Expect(queue.Count()).To(BeNumerically("==", 3)) + }) + + It("reports a queue read failure instead of reporting nothing to cancel", func() { + queue.Err = errors.New("read failed") + Expect(cancelArtwork(ctx, ds, nil, nil, false, accept, &out)).To(MatchError(ContainSubstring("read failed"))) + }) +}) diff --git a/model/artwork.go b/model/artwork.go index 6107e9ffa..b484b0500 100644 --- a/model/artwork.go +++ b/model/artwork.go @@ -157,13 +157,16 @@ type ArtworkQueueRepository interface { // DeleteIfUnchanged deletes only while retry_at still matches, sparing a concurrent re-enqueue. DeleteIfUnchanged(kind, id, imageType string, retryAt time.Time) error Count() (int64, error) - // CountByKindAndPriority reports the pending queue rows grouped by kind and priority. - CountByKindAndPriority() ([]ArtworkQueueStat, error) + // CountQueued reports the pending rows matching the kinds and priorities, grouped by both; + // an empty filter means every one. + CountQueued(kinds []Kind, priorities []int) ([]ArtworkQueueStat, error) // CountAbsent reports the absent states of a kind, and how many of those EnqueueStaleAbsent // would pick up at the given cutoff. CountAbsent(kind Kind, attemptedBefore time.Time) (ArtworkAbsentStat, error) // PurgeDangling removes queue rows whose entity no longer exists. PurgeDangling() (int64, error) + // PurgeQueued removes pending rows matching the kinds and priorities; an empty filter means every one. + PurgeQueued(kinds []Kind, priorities []int) (int64, error) } type ArtworkQueueStat struct { diff --git a/model/artwork_id.go b/model/artwork_id.go index 634a6442f..e827e935a 100644 --- a/model/artwork_id.go +++ b/model/artwork_id.go @@ -6,6 +6,8 @@ import ( "strconv" "strings" "time" + + "github.com/navidrome/navidrome/utils/slice" ) type Kind struct { @@ -40,6 +42,11 @@ var artworkKindMap = map[string]Kind{ KindRadioArtwork.prefix: KindRadioArtwork, } +// KindPrefixes leaves the typed Kind domain for the item_kind column, or for a help string. +func KindPrefixes(kinds []Kind) []string { + return slice.Map(kinds, func(k Kind) string { return k.prefix }) +} + // ParseKind resolves an item_kind prefix (e.g. "al") to its Kind, reporting whether it was known. // Use it at string boundaries — URL params, the item_kind column — to enter the typed Kind domain. func ParseKind(prefix string) (Kind, bool) { diff --git a/persistence/artwork_queue_repository.go b/persistence/artwork_queue_repository.go index ba9fb6f1a..5db122a8b 100644 --- a/persistence/artwork_queue_repository.go +++ b/persistence/artwork_queue_repository.go @@ -191,19 +191,45 @@ func (r *artworkQueueRepository) PurgeDangling() (int64, error) { return purgeDangling(r.sqlRepository) } +// artworkQueueFilter returns no conditions for an empty filter, so an unfiltered DELETE keeps +// SQLite's truncate path. It ignores retry_at: a backing-off row is pending work too. +func artworkQueueFilter(kinds []model.Kind, priorities []int) And { + var f And + if len(kinds) > 0 { + f = append(f, Eq{"item_kind": model.KindPrefixes(kinds)}) + } + if len(priorities) > 0 { + f = append(f, Eq{"priority": priorities}) + } + return f +} + +// CountQueued shares its filter with PurgeQueued, so a preview cannot count rows the delete misses. +func (r *artworkQueueRepository) CountQueued(kinds []model.Kind, priorities []int) ([]model.ArtworkQueueStat, error) { + sel := Select("item_kind", "priority", "count(*) as count").From(r.tableName). + GroupBy("item_kind", "priority").OrderBy("item_kind", "priority desc") + if f := artworkQueueFilter(kinds, priorities); len(f) > 0 { + sel = sel.Where(f) + } + var res []model.ArtworkQueueStat + err := r.queryAll(sel, &res) + return res, err +} + +func (r *artworkQueueRepository) PurgeQueued(kinds []model.Kind, priorities []int) (int64, error) { + del := Delete(r.tableName) + if f := artworkQueueFilter(kinds, priorities); len(f) > 0 { + del = del.Where(f) + } + return r.executeSQL(del) +} + func (r *artworkQueueRepository) Count() (int64, error) { var res struct{ Count int64 } err := r.queryOne(Select("count(*) as count").From(r.tableName), &res) return res.Count, err } -func (r *artworkQueueRepository) CountByKindAndPriority() ([]model.ArtworkQueueStat, error) { - var res []model.ArtworkQueueStat - err := r.queryAll(Select("item_kind", "priority", "count(*) as count").From(r.tableName). - GroupBy("item_kind", "priority").OrderBy("item_kind", "priority desc"), &res) - return res, err -} - // CountAbsent matches EnqueueStaleAbsent on hash, so the stale count is what a recheck would queue. func (r *artworkQueueRepository) CountAbsent(kind model.Kind, attemptedBefore time.Time) (model.ArtworkAbsentStat, error) { var res model.ArtworkAbsentStat diff --git a/persistence/artwork_queue_repository_test.go b/persistence/artwork_queue_repository_test.go index 84f3e2986..35eebdd6d 100644 --- a/persistence/artwork_queue_repository_test.go +++ b/persistence/artwork_queue_repository_test.go @@ -411,7 +411,7 @@ var _ = Describe("ArtworkQueueRepository", func() { Expect(repo.Enqueue(item("ar", "a3", model.ArtworkPriorityBump))).To(Succeed()) Expect(repo.Enqueue(item("al", "b1", model.ArtworkPriorityScan))).To(Succeed()) - Expect(repo.CountByKindAndPriority()).To(ConsistOf( + Expect(repo.CountQueued(nil, nil)).To(ConsistOf( model.ArtworkQueueStat{ItemKind: "ar", Priority: model.ArtworkPriorityBackfill, Count: 2}, model.ArtworkQueueStat{ItemKind: "ar", Priority: model.ArtworkPriorityBump, Count: 1}, model.ArtworkQueueStat{ItemKind: "al", Priority: model.ArtworkPriorityScan, Count: 1}, @@ -419,7 +419,7 @@ var _ = Describe("ArtworkQueueRepository", func() { }) It("reports an empty queue as no rows", func() { - Expect(repo.CountByKindAndPriority()).To(BeEmpty()) + Expect(repo.CountQueued(nil, nil)).To(BeEmpty()) }) It("counts absent states and how many are due for recheck", func() { @@ -442,4 +442,71 @@ var _ = Describe("ArtworkQueueRepository", func() { Expect(repo.CountAbsent(model.KindRadioArtwork, time.Now())).To(Equal(model.ArtworkAbsentStat{})) }) }) + + Describe("PurgeQueued", func() { + queuedIDs := func() []string { + GinkgoHelper() + got, err := repo.DequeueBatch(100) + Expect(err).ToNot(HaveOccurred()) + return slice.Map(got, func(it model.ArtworkQueueItem) string { return it.ItemID }) + } + + BeforeEach(func() { + Expect(repo.Enqueue( + item("ar", "ar-backfill", model.ArtworkPriorityBackfill), + item("ar", "ar-bump", model.ArtworkPriorityBump), + item("al", "al-backfill", model.ArtworkPriorityBackfill), + item("mf", "mf-scan", model.ArtworkPriorityScan), + )).To(Succeed()) + }) + + // CountQueued feeds the preview and PurgeQueued does the delete; they share one filter, so + // every selection must count exactly what it deletes. + DescribeTable("selects the same rows to count and to delete", + func(kinds []model.Kind, priorities []int, deleted int, remaining []string) { + counted, err := repo.CountQueued(kinds, priorities) + Expect(err).ToNot(HaveOccurred()) + var total int64 + for _, s := range counted { + total += s.Count + } + Expect(total).To(BeNumerically("==", deleted), "the preview must match the delete") + + Expect(repo.PurgeQueued(kinds, priorities)).To(BeNumerically("==", deleted)) + Expect(queuedIDs()).To(ConsistOf(remaining)) + }, + Entry("only the given kinds", []model.Kind{model.KindArtistArtwork}, nil, + 2, []string{"al-backfill", "mf-scan"}), + Entry("only the given priorities", nil, []int{model.ArtworkPriorityBackfill}, + 2, []string{"ar-bump", "mf-scan"}), + Entry("the intersection of both", []model.Kind{model.KindArtistArtwork}, []int{model.ArtworkPriorityBackfill}, + 1, []string{"ar-bump", "al-backfill", "mf-scan"}), + Entry("everything, when neither filter is given", nil, nil, + 4, []string{}), + Entry("several kinds and priorities at once", + []model.Kind{model.KindArtistArtwork, model.KindMediaFileArtwork}, + []int{model.ArtworkPriorityBackfill, model.ArtworkPriorityScan}, + 2, []string{"ar-bump", "al-backfill"}), + Entry("nothing, leaving the queue alone", []model.Kind{model.KindPlaylistArtwork}, nil, + 0, []string{"ar-backfill", "ar-bump", "al-backfill", "mf-scan"}), + ) + + It("deletes a row that is still backing off", func() { + backOff("ar", "ar-bump", time.Now().Add(time.Hour)) + + Expect(repo.PurgeQueued([]model.Kind{model.KindArtistArtwork}, nil)).To(BeNumerically("==", 2)) + Expect(repo.Get(model.KindArtistArtwork, "ar-bump", model.ImageTypePrimary)). + Error().To(MatchError(model.ErrNotFound)) + }) + + // A WHERE clause, even one that matches everything, costs SQLite its truncate optimization + // and turns `artwork cancel --all` into a full scan of the queue. + It("adds no conditions at all for an empty filter", func() { + Expect(artworkQueueFilter(nil, nil)).To(BeEmpty()) + Expect(artworkQueueFilter([]model.Kind{model.KindArtistArtwork}, nil)).To(HaveLen(1)) + Expect(artworkQueueFilter(nil, []int{model.ArtworkPriorityBump})).To(HaveLen(1)) + Expect(artworkQueueFilter([]model.Kind{model.KindArtistArtwork}, []int{model.ArtworkPriorityBump})). + To(HaveLen(2)) + }) + }) }) diff --git a/tests/mock_artwork_queue_repo.go b/tests/mock_artwork_queue_repo.go index f8f57e8d9..70f7084ff 100644 --- a/tests/mock_artwork_queue_repo.go +++ b/tests/mock_artwork_queue_repo.go @@ -167,6 +167,30 @@ func (m *MockArtworkQueueRepo) PurgeDangling() (int64, error) { return purged, nil } +// queueFilterMatches mirrors artworkQueueFilter, so the mock cannot let a preview and a delete disagree. +func queueFilterMatches(it model.ArtworkQueueItem, kinds []model.Kind, priorities []int) bool { + prefixes := model.KindPrefixes(kinds) + return (len(prefixes) == 0 || slices.Contains(prefixes, it.ItemKind)) && + (len(priorities) == 0 || slices.Contains(priorities, it.Priority)) +} + +func (m *MockArtworkQueueRepo) PurgeQueued(kinds []model.Kind, priorities []int) (int64, error) { + m.mu.Lock() + defer m.mu.Unlock() + if m.Err != nil { + return 0, m.Err + } + var purged int64 + for k, it := range m.Data { + if !queueFilterMatches(it, kinds, priorities) { + continue + } + delete(m.Data, k) + purged++ + } + return purged, nil +} + func (m *MockArtworkQueueRepo) Count() (int64, error) { m.mu.Lock() defer m.mu.Unlock() @@ -176,7 +200,7 @@ func (m *MockArtworkQueueRepo) Count() (int64, error) { return int64(len(m.Data)), nil } -func (m *MockArtworkQueueRepo) CountByKindAndPriority() ([]model.ArtworkQueueStat, error) { +func (m *MockArtworkQueueRepo) CountQueued(kinds []model.Kind, priorities []int) ([]model.ArtworkQueueStat, error) { m.mu.Lock() defer m.mu.Unlock() if m.Err != nil { @@ -184,6 +208,9 @@ func (m *MockArtworkQueueRepo) CountByKindAndPriority() ([]model.ArtworkQueueSta } var res []model.ArtworkQueueStat for _, it := range m.Data { + if !queueFilterMatches(it, kinds, priorities) { + continue + } i := slices.IndexFunc(res, func(s model.ArtworkQueueStat) bool { return s.ItemKind == it.ItemKind && s.Priority == it.Priority }) From 07b6411c0bc3ff0c2aafe8c8cfac4d00f2a6ddcd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Fri, 21 Aug 2026 15:23:07 -0400 Subject: [PATCH 07/13] perf(artwork): cap the stale-absent recheck at 100 items per kind per hour (#6007) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat(artwork): drip the stale-absent recheck instead of bursting it daily Each hourly housekeeping tick now re-queues at most 100 absent states per kind, oldest attempts first, instead of everything older than 24h at once. External agents see a flat ~100 requests/hour per agent instead of hourly bursts of ~2,000, and the effective recheck interval self-scales with the size of the absent pool (~4 days at 10k absent artists) while small libraries keep the 24h floor. * feat(artwork): trust an absent artwork state for a week before rechecking With the recheck now dripped at 100 items per kind per hour, the 24h floor only governed small libraries, where the drip cap never binds; they still re-asked every agent daily. A 7-day floor cuts that cost 7x and, for large libraries, becomes the binding limit over the drip cycle (~5.7k calls/day instead of ~9.6k at 10k absent artists). Among comparable servers, this is still the second-most-eager recheck: gonic retries misses every 30 days, Jellyfin and Funkwhale never do. * refactor(artwork): state the drip's backpressure contract where it bites Review follow-ups: the recheck limit deliberately caps the *selection*, not the insertions — already-queued rows use up budget, so a stalled drain admits no new work instead of building a recovery burst. Say so in the interface doc, mirror it in the mock by truncating the sorted candidates (matching the SQL's LIMIT-before-ON CONFLICT), and teach `artwork status` and the worker doc the post-drip wording. Also pin the one cmd fixture that still assumed a 24h recheck window. --- cmd/artwork.go | 3 ++- cmd/artwork_test.go | 7 ++++--- core/artwork/housekeeping.go | 8 ++++++-- core/artwork/housekeeping_test.go | 19 +++++++++++++++++-- core/artwork/worker.go | 3 ++- model/artwork.go | 9 +++++---- persistence/artwork_queue_repository.go | 9 +++++---- persistence/artwork_queue_repository_test.go | 19 ++++++++++++++++++- tests/mock_artwork_queue_repo.go | 16 +++++++++++----- 9 files changed, 70 insertions(+), 23 deletions(-) diff --git a/cmd/artwork.go b/cmd/artwork.go index b193abeaf..01de071bb 100644 --- a/cmd/artwork.go +++ b/cmd/artwork.go @@ -238,7 +238,8 @@ func formatStatus(rep statusReport) string { for _, a := range rep.absent { fmt.Fprintf(w, " %s\t%d\t%d\n", a.kind, a.Total, a.Stale) } - fmt.Fprintf(w, " (rechecked once the last attempt is older than %gh)\n", artwork.StaleAbsentAge.Hours()) + fmt.Fprintf(w, " (eligible once the last attempt is older than %gh; re-queued %d per kind per hour, oldest first)\n", + artwork.StaleAbsentAge.Hours(), artwork.StaleAbsentRecheckBatch) fmt.Fprintln(w, "\nBackfill") fmt.Fprintf(w, " State:\t%s\n", backfillState(rep)) diff --git a/cmd/artwork_test.go b/cmd/artwork_test.go index 1d2bdae73..cc63ed86f 100644 --- a/cmd/artwork_test.go +++ b/cmd/artwork_test.go @@ -818,7 +818,7 @@ var _ = Describe("collectStatus", func() { ImageType: model.ImageTypePrimary, Source: source, Hash: hash, AttemptedAt: attempted})).To(Succeed()) } put(model.KindArtistArtwork, "ar-1", "external:deezer", "h1", time.Now()) - put(model.KindArtistArtwork, "ar-2", "", "", time.Now().Add(-48*time.Hour)) + put(model.KindArtistArtwork, "ar-2", "", "", time.Now().Add(-artwork.StaleAbsentAge-time.Hour)) put(model.KindArtistArtwork, "ar-3", "", "", time.Now()) put(model.KindAlbumArtwork, "al-1", "folder", "h2", time.Now()) Expect(queue.Enqueue(model.ArtworkQueueItem{ItemKind: "ar", ItemID: "ar-9", @@ -909,8 +909,9 @@ var _ = Describe("formatStatus", func() { Expect(absent).To(MatchRegexp(`artist\s+2\s+1`)) }) - It("states the recheck window the absent counts are bucketed against", func() { - Expect(formatStatus(rep)).To(ContainSubstring("24h")) + It("states the recheck window and the drip rate the absent counts are bucketed against", func() { + Expect(formatStatus(rep)).To(ContainSubstring("168h")) + Expect(formatStatus(rep)).To(ContainSubstring("100 per kind per hour")) }) It("leads with the queued backlog, which is the finding, not with the fingerprint verdict", func() { diff --git a/core/artwork/housekeeping.go b/core/artwork/housekeeping.go index f2996d044..fed5757c8 100644 --- a/core/artwork/housekeeping.go +++ b/core/artwork/housekeeping.go @@ -18,7 +18,11 @@ import ( ) // StaleAbsentAge is how long an absent state is trusted before a recheck retries it. -const StaleAbsentAge = 24 * time.Hour +const StaleAbsentAge = 7 * 24 * time.Hour + +// StaleAbsentRecheckBatch caps how many absent states each hourly tick re-queues per kind, +// oldest first, so external agents see a flat drip instead of a daily burst. +const StaleAbsentRecheckBatch = 100 // RecheckKinds omits media files: they resolve embedded-only, at scan or on view. var RecheckKinds = []model.Kind{ @@ -125,7 +129,7 @@ func enqueueStaleAbsentAll(ctx context.Context, ds model.DataStore) error { cutoff := time.Now().Add(-StaleAbsentAge) queue := ds.ArtworkQueue(ctx) for _, kind := range RecheckKinds { - if _, err := queue.EnqueueStaleAbsent(kind, cutoff); err != nil { + if _, err := queue.EnqueueStaleAbsent(kind, cutoff, StaleAbsentRecheckBatch); err != nil { return err } } diff --git a/core/artwork/housekeeping_test.go b/core/artwork/housekeeping_test.go index 4ea15ab04..4f229bff8 100644 --- a/core/artwork/housekeeping_test.go +++ b/core/artwork/housekeeping_test.go @@ -2,6 +2,7 @@ package artwork import ( "context" + "fmt" "slices" "time" @@ -235,8 +236,8 @@ var _ = Describe("Housekeeping", func() { }) It("enqueues only absent entries older than the recheck window, across all kinds", func() { - old := time.Now().Add(-48 * time.Hour) - recent := time.Now().Add(-time.Hour) + old := time.Now().Add(-StaleAbsentAge - time.Hour) + recent := time.Now().Add(-StaleAbsentAge + time.Hour) artRepo.ItemData["ar-stale"] = model.ItemArtwork{ItemKind: "ar", ItemID: "ar1", ImageType: model.ImageTypePrimary, Hash: "", AttemptedAt: old} artRepo.ItemData["al-stale"] = model.ItemArtwork{ItemKind: "al", ItemID: "al1", ImageType: model.ImageTypePrimary, Hash: "", AttemptedAt: old} @@ -259,6 +260,20 @@ var _ = Describe("Housekeeping", func() { Expect(findQueued(queueRepo.MockArtworkQueueRepo, "ar", "ar2")).To(BeNil()) Expect(findQueued(queueRepo.MockArtworkQueueRepo, "al", "al2")).To(BeNil()) }) + + It("caps each tick at the recheck batch, oldest attempts first", func() { + for i := range StaleAbsentRecheckBatch + 1 { + id := fmt.Sprintf("ar%d", i) + artRepo.ItemData[id] = model.ItemArtwork{ItemKind: "ar", ItemID: id, ImageType: model.ImageTypePrimary, + Hash: "", AttemptedAt: time.Now().Add(-StaleAbsentAge - time.Duration(i+1)*time.Minute)} + } + + Expect(enqueueStaleAbsentAll(ctx, ds)).To(Succeed()) + + Expect(queueRepo.Data).To(HaveLen(StaleAbsentRecheckBatch)) + // ar0 has the newest attempted_at of the cohort, so it is the one left out. + Expect(findQueued(queueRepo.MockArtworkQueueRepo, "ar", "ar0")).To(BeNil()) + }) }) Describe("EnqueueMissingAll", func() { diff --git a/core/artwork/worker.go b/core/artwork/worker.go index 6271e54bf..0f947f6d7 100644 --- a/core/artwork/worker.go +++ b/core/artwork/worker.go @@ -137,7 +137,8 @@ func (w *Worker) Backfill(ctx context.Context) (bool, error) { return backfill(ctx, w.proc.ds) } -// EnqueueStaleAbsentAll requeues known-absent entries older than StaleAbsentAge. +// EnqueueStaleAbsentAll requeues known-absent entries older than StaleAbsentAge, at most +// StaleAbsentRecheckBatch per kind, oldest first. func (w *Worker) EnqueueStaleAbsentAll(ctx context.Context) error { return enqueueStaleAbsentAll(ctx, w.proc.ds) } diff --git a/model/artwork.go b/model/artwork.go index b484b0500..3c0df209b 100644 --- a/model/artwork.go +++ b/model/artwork.go @@ -134,8 +134,9 @@ type ArtworkQueueRepository interface { // EnqueuePreservingBackoff upserts like Enqueue but preserves an existing row's retry_at, so a // request-triggered read-through never resets a failed resolution's backoff. EnqueuePreservingBackoff(items ...ArtworkQueueItem) error - // EnqueueStaleAbsent inserts queue rows (priority Recheck) for absent states older than cutoff. - EnqueueStaleAbsent(kind Kind, attemptedBefore time.Time) (int64, error) + // EnqueueStaleAbsent inserts queue rows (priority Recheck) for absent states older than cutoff, oldest + // first; limit caps the selection, so already-queued rows use up budget (backpressure when the drain stalls). + EnqueueStaleAbsent(kind Kind, attemptedBefore time.Time, limit int) (int64, error) // EnqueueAllMissing inserts queue rows for all entities with no item_artwork row, at the given priority. EnqueueAllMissing(kind Kind, priority int) (int64, error) // EnqueueIfMissing inserts only for items with no item_artwork row yet. @@ -160,8 +161,8 @@ type ArtworkQueueRepository interface { // CountQueued reports the pending rows matching the kinds and priorities, grouped by both; // an empty filter means every one. CountQueued(kinds []Kind, priorities []int) ([]ArtworkQueueStat, error) - // CountAbsent reports the absent states of a kind, and how many of those EnqueueStaleAbsent - // would pick up at the given cutoff. + // CountAbsent reports the absent states of a kind, and how many are past the given cutoff, + // eligible for EnqueueStaleAbsent (which drains them limit rows per call). CountAbsent(kind Kind, attemptedBefore time.Time) (ArtworkAbsentStat, error) // PurgeDangling removes queue rows whose entity no longer exists. PurgeDangling() (int64, error) diff --git a/persistence/artwork_queue_repository.go b/persistence/artwork_queue_repository.go index 5db122a8b..1c0077fc7 100644 --- a/persistence/artwork_queue_repository.go +++ b/persistence/artwork_queue_repository.go @@ -56,11 +56,12 @@ func (r *artworkQueueRepository) EnqueuePreservingBackoff(items ...model.Artwork priority = MAX(priority, excluded.priority)`, items) } -func (r *artworkQueueRepository) EnqueueStaleAbsent(kind model.Kind, attemptedBefore time.Time) (int64, error) { +func (r *artworkQueueRepository) EnqueueStaleAbsent(kind model.Kind, attemptedBefore time.Time, limit int) (int64, error) { now := time.Now() return r.insertIfNotQueued("", `SELECT item_kind, item_id, image_type, ?, 0, ?, ? - FROM `+itemArtworkTable+` WHERE item_kind = ? AND hash = '' AND attempted_at < ?`, - model.ArtworkPriorityRecheck, now, now, kind.Prefix(), attemptedBefore) + FROM `+itemArtworkTable+` WHERE item_kind = ? AND hash = '' AND attempted_at < ? + ORDER BY attempted_at LIMIT ?`, + model.ArtworkPriorityRecheck, now, now, kind.Prefix(), attemptedBefore, limit) } func (r *artworkQueueRepository) EnqueueAllMissing(kind model.Kind, priority int) (int64, error) { @@ -230,7 +231,7 @@ func (r *artworkQueueRepository) Count() (int64, error) { return res.Count, err } -// CountAbsent matches EnqueueStaleAbsent on hash, so the stale count is what a recheck would queue. +// CountAbsent matches EnqueueStaleAbsent on hash, so the stale count is the pool a recheck drains from. func (r *artworkQueueRepository) CountAbsent(kind model.Kind, attemptedBefore time.Time) (model.ArtworkAbsentStat, error) { var res model.ArtworkAbsentStat err := r.queryOne(Select("count(*) as total"). diff --git a/persistence/artwork_queue_repository_test.go b/persistence/artwork_queue_repository_test.go index 35eebdd6d..1673a5b0e 100644 --- a/persistence/artwork_queue_repository_test.go +++ b/persistence/artwork_queue_repository_test.go @@ -244,7 +244,7 @@ var _ = Describe("ArtworkQueueRepository", func() { Expect(awRepo.PutItemArtwork(&model.ItemArtwork{ItemKind: "ar", ItemID: "fresh1", ImageType: model.ImageTypePrimary, Hash: "", AttemptedAt: time.Now()})).To(Succeed()) Expect(awRepo.PutItemArtwork(&model.ItemArtwork{ItemKind: "ar", ItemID: "found1", ImageType: model.ImageTypePrimary, Hash: "hX", AttemptedAt: old})).To(Succeed()) - n, err := repo.EnqueueStaleAbsent(model.KindArtistArtwork, time.Now().Add(-24*time.Hour)) + n, err := repo.EnqueueStaleAbsent(model.KindArtistArtwork, time.Now().Add(-24*time.Hour), 100) Expect(err).ToNot(HaveOccurred()) Expect(n).To(Equal(int64(1))) @@ -255,6 +255,23 @@ var _ = Describe("ArtworkQueueRepository", func() { Expect(items[0].Priority).To(Equal(model.ArtworkPriorityRecheck)) }) + It("enqueues only the oldest stale absent states up to the limit", func() { + awRepo := NewArtworkRepository(context.Background(), GetDBXBuilder()) + now := time.Now() + Expect(awRepo.PutItemArtwork(&model.ItemArtwork{ItemKind: "ar", ItemID: "oldest", ImageType: model.ImageTypePrimary, Hash: "", AttemptedAt: now.Add(-72 * time.Hour)})).To(Succeed()) + Expect(awRepo.PutItemArtwork(&model.ItemArtwork{ItemKind: "ar", ItemID: "older", ImageType: model.ImageTypePrimary, Hash: "", AttemptedAt: now.Add(-60 * time.Hour)})).To(Succeed()) + Expect(awRepo.PutItemArtwork(&model.ItemArtwork{ItemKind: "ar", ItemID: "old", ImageType: model.ImageTypePrimary, Hash: "", AttemptedAt: now.Add(-48 * time.Hour)})).To(Succeed()) + + n, err := repo.EnqueueStaleAbsent(model.KindArtistArtwork, now.Add(-24*time.Hour), 2) + Expect(err).ToNot(HaveOccurred()) + Expect(n).To(Equal(int64(2))) + + items, err := repo.DequeueBatch(10) + Expect(err).ToNot(HaveOccurred()) + ids := slice.Map(items, func(it model.ArtworkQueueItem) string { return it.ItemID }) + Expect(ids).To(ConsistOf("oldest", "older")) + }) + It("enqueues entities that have no item_artwork row at all", func() { awRepo := NewArtworkRepository(context.Background(), GetDBXBuilder()) Expect(awRepo.PutItemArtwork(&model.ItemArtwork{ItemKind: "al", ItemID: albumSgtPeppers.ID, ImageType: model.ImageTypePrimary, Hash: "hX", AttemptedAt: time.Now()})).To(Succeed()) diff --git a/tests/mock_artwork_queue_repo.go b/tests/mock_artwork_queue_repo.go index 70f7084ff..51ddf4b61 100644 --- a/tests/mock_artwork_queue_repo.go +++ b/tests/mock_artwork_queue_repo.go @@ -272,18 +272,24 @@ func (m *MockArtworkQueueRepo) EnqueuePreservingBackoff(items ...model.ArtworkQu return nil } -func (m *MockArtworkQueueRepo) EnqueueStaleAbsent(kind model.Kind, attemptedBefore time.Time) (int64, error) { +func (m *MockArtworkQueueRepo) EnqueueStaleAbsent(kind model.Kind, attemptedBefore time.Time, limit int) (int64, error) { m.mu.Lock() defer m.mu.Unlock() if m.Err != nil || m.ItemArtworkSource == nil { return 0, m.Err } + var stale []model.ItemArtwork + for _, ia := range m.ItemArtworkSource.ItemData { + if ia.ItemKind == kind.Prefix() && ia.Hash == "" && ia.AttemptedAt.Before(attemptedBefore) { + stale = append(stale, ia) + } + } + slices.SortFunc(stale, func(a, b model.ItemArtwork) int { return a.AttemptedAt.Compare(b.AttemptedAt) }) + // The limit caps the selection, like the SQL's LIMIT before ON CONFLICT: queued rows use up budget. + stale = stale[:min(limit, len(stale))] now := time.Now() var inserted int64 - for _, ia := range m.ItemArtworkSource.ItemData { - if ia.ItemKind != kind.Prefix() || ia.Hash != "" || !ia.AttemptedAt.Before(attemptedBefore) { - continue - } + for _, ia := range stale { k := iaKey(ia.ItemKind, ia.ItemID, ia.ImageType) if _, ok := m.Data[k]; ok { // DO NOTHING: never touch existing queue rows continue From 295886cb9a432d375afa796ed8a32db0775464af Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Fri, 21 Aug 2026 20:27:42 -0400 Subject: [PATCH 08/13] feat(artwork): report what a config-fingerprint backfill enqueued (#6010) * feat(artwork): report what a config-fingerprint backfill enqueued A backfill re-resolves every entity, and on a large library that is tens of thousands of external agent calls. It announced itself with a single line carrying nothing but an elapsed time, so the size of the job was invisible until the request volume showed up hours later. Log the item count, the per-kind breakdown, and a ceiling on the external lookups the queued work can cost. The ceiling reuses ExternalLookupsPerItem, the same estimator behind the `artwork reprocess` preview, so the two agree on what an item can cost. backfill now returns a summary instead of a bare bool, which keeps the counts assertable without capturing log output. Worker.Backfill keeps its (bool, error) signature, so its caller is unchanged, and it reads the agent count off its own resolver. * refactor(artwork): share the image-agent count and take it lazily Counting image agents was written twice, once in the CLI for the `artwork reprocess` preview and again as a resolver method for the backfill log. Two copies of "which agents count as image agents" can drift, and the CLI estimate and the server log would then disagree silently. Move the derivation next to the type it builds, as NewImageAgentCount, and call it from both. The resolver method goes away with it: hanging the census on the resolver forced two nil guards that its only caller could never trigger, because Worker always builds a resolver with agents. The Worker keeps the *agents.Agents it is already handed instead of reaching through the processor and resolver to find it. Pass the count as a func. Building the agent list constructs every enabled agent (each one an HTTP client and a cache goroutine) only to take its length, and a backfill returns early on an unchanged fingerprint, which is what happens on nearly every restart. * docs(artwork): say what the backfill lookup estimate does not bound The comment called the number a ceiling, which the CLI comment on the same estimate already contradicts: externalEstimate "claims no bound". Both are right about the local-source case and only one of them mentions that a retried item asks its agents again. --- cmd/artwork.go | 7 +----- core/artwork/housekeeping.go | 35 ++++++++++++++++++++------- core/artwork/housekeeping_test.go | 39 ++++++++++++++++++++++++------- core/artwork/resolve.go | 9 +++++++ core/artwork/worker.go | 7 ++++-- 5 files changed, 73 insertions(+), 24 deletions(-) diff --git a/cmd/artwork.go b/cmd/artwork.go index 01de071bb..8b9e28f0e 100644 --- a/cmd/artwork.go +++ b/cmd/artwork.go @@ -339,7 +339,7 @@ func runReprocess(ctx context.Context) { if needsImageAgents(kinds) { mgr := loadPluginAgents(ctx, false) defer func() { _ = mgr.Stop() }() - imageAgents = imageAgentCount(ds, mgr) + imageAgents = artwork.NewImageAgentCount(agents.GetAgents(ds, mgr)) } if err := reprocessArtwork(ctx, ds, kinds, repositorySources(artworkSources), imageAgents, @@ -397,11 +397,6 @@ func externalLookupLine(n int64) string { return fmt.Sprintf("External lookups: %s.", externalEstimate(n)) } -func imageAgentCount(ds model.DataStore, mgr *plugins.Manager) artwork.ImageAgentCount { - ag := agents.GetAgents(ds, mgr) - return artwork.ImageAgentCount{Artist: len(ag.ArtistImageAgents()), Album: len(ag.AlbumImageAgents())} -} - // loadPluginAgents loads the plugins named in Agents, so the CLI resolves through the same agents a // running server would. A load failure is reported, not fatal: the built-in agents still answer. func loadPluginAgents(ctx context.Context, runInit bool) *plugins.Manager { diff --git a/core/artwork/housekeeping.go b/core/artwork/housekeeping.go index fed5757c8..9456a5584 100644 --- a/core/artwork/housekeeping.go +++ b/core/artwork/housekeeping.go @@ -72,18 +72,27 @@ func ConfigFingerprint() string { return fmt.Sprintf("%016x", xxh3.Hash([]byte(raw))) } +// backfillSummary is what a backfill enqueued. MaxExternalLookups is an upper estimate for one +// attempt per item, not a bound: a local hit ends the walk, and a retry asks the agents again. +type backfillSummary struct { + Ran bool + PerKind map[string]int64 + Items int64 + MaxExternalLookups int64 +} + // backfill enqueues artwork resolution for every entity when the config fingerprint changed. -func backfill(ctx context.Context, ds model.DataStore) (bool, error) { +func backfill(ctx context.Context, ds model.DataStore, agentCount func() ImageAgentCount) (backfillSummary, error) { start := time.Now() ctx = auth.WithAdminUser(ctx, ds) current := ConfigFingerprint() props := ds.Property(ctx) stored, err := props.DefaultGet(consts.ArtConfFingerprintPropertyKey, "") if err != nil { - return false, err + return backfillSummary{}, err } if stored == current { - return false, nil + return backfillSummary{}, nil } // Artists first: few entities, most external-dependent, so they get a queue headstart. @@ -96,21 +105,31 @@ func backfill(ctx context.Context, ds model.DataStore) (bool, error) { {model.KindPlaylistArtwork, func() ([]string, error) { return ds.Playlist(ctx).GetAllIDs() }}, {model.KindRadioArtwork, func() ([]string, error) { return ds.Radio(ctx).GetAllIDs() }}, } + // Counted here, not by the caller: building the agent list constructs every enabled agent, and + // an unchanged fingerprint returns above without ever needing the number. + agents := agentCount() + summary := backfillSummary{Ran: true, PerKind: map[string]int64{}} for _, k := range kinds { ids, err := k.fetch() if err != nil { - return false, err + return backfillSummary{}, err } if err := enqueueBackfillKind(ctx, ds, k.kind, ids); err != nil { - return false, err + return backfillSummary{}, err } + n := int64(len(ids)) + summary.PerKind[k.kind.Prefix()] = n + summary.Items += n + summary.MaxExternalLookups += n * ExternalLookupsPerItem(k.kind, agents) } if err := props.Put(consts.ArtConfFingerprintPropertyKey, current); err != nil { - return false, err + return backfillSummary{}, err } - log.Info(ctx, "Artwork: Config fingerprint changed, backfill enqueued", "elapsed", time.Since(start)) - return true, nil + log.Info(ctx, "Artwork: Config fingerprint changed, backfill enqueued", "items", summary.Items, + "byKind", summary.PerKind, "maxExternalLookups", summary.MaxExternalLookups, + "elapsed", time.Since(start)) + return summary, nil } func enqueueBackfillKind(ctx context.Context, ds model.DataStore, kind model.Kind, ids []string) error { diff --git a/core/artwork/housekeeping_test.go b/core/artwork/housekeeping_test.go index 4f229bff8..7aecd2760 100644 --- a/core/artwork/housekeeping_test.go +++ b/core/artwork/housekeeping_test.go @@ -39,6 +39,8 @@ func adminUserRepo() *tests.MockedUserRepo { return repo } +func noAgents() ImageAgentCount { return ImageAgentCount{} } + // orderTrackingQueueRepo records the item kind of each Enqueue call, so tests can // assert phase ordering (artists-first) that same-priority timestamps can't guarantee. type orderTrackingQueueRepo struct { @@ -164,9 +166,14 @@ var _ = Describe("Housekeeping", func() { seedEntities() Expect(propRepo.Put(consts.ArtConfFingerprintPropertyKey, ConfigFingerprint())).To(Succeed()) - did, err := backfill(ctx, ds) + counted := false + s, err := backfill(ctx, ds, func() ImageAgentCount { + counted = true + return ImageAgentCount{Artist: 3, Album: 2} + }) Expect(err).ToNot(HaveOccurred()) - Expect(did).To(BeFalse()) + Expect(s).To(Equal(backfillSummary{})) + Expect(counted).To(BeFalse(), "building the agent list constructs every agent; an unchanged fingerprint must not pay for it") count, err := queueRepo.Count() Expect(err).ToNot(HaveOccurred()) @@ -176,9 +183,9 @@ var _ = Describe("Housekeeping", func() { It("runs the backfill when no fingerprint was ever stored", func() { seedEntities() - did, err := backfill(ctx, ds) + s, err := backfill(ctx, ds, noAgents) Expect(err).ToNot(HaveOccurred()) - Expect(did).To(BeTrue()) + Expect(s.Ran).To(BeTrue()) count, err := queueRepo.Count() Expect(err).ToNot(HaveOccurred()) @@ -197,9 +204,9 @@ var _ = Describe("Housekeeping", func() { tracks: &tests.MockPlaylistTrackRepo{}, } - did, err := backfill(ctx, vds) + s, err := backfill(ctx, vds, noAgents) Expect(err).ToNot(HaveOccurred()) - Expect(did).To(BeTrue()) + Expect(s.Ran).To(BeTrue()) Expect(findQueued(queueRepo.MockArtworkQueueRepo, "pl", "plPrivate")).ToNot(BeNil()) }) @@ -207,9 +214,9 @@ var _ = Describe("Housekeeping", func() { seedEntities() Expect(propRepo.Put(consts.ArtConfFingerprintPropertyKey, "stale-fingerprint")).To(Succeed()) - did, err := backfill(ctx, ds) + s, err := backfill(ctx, ds, noAgents) Expect(err).ToNot(HaveOccurred()) - Expect(did).To(BeTrue()) + Expect(s.Ran).To(BeTrue()) Expect(queueRepo.callKinds).ToNot(BeEmpty()) firstOther := slices.IndexFunc(queueRepo.callKinds, func(k string) bool { return k != "ar" }) @@ -224,6 +231,22 @@ var _ = Describe("Housekeeping", func() { Expect(it.ItemKind).To(BeElementOf("ar", "al", "pl", "ra")) } }) + + It("reports what it enqueued, per kind and as an external-lookup ceiling", func() { + conf.Server.ArtistArtPriority = "artist.*, external" + conf.Server.CoverArtPriority = "cover.*, external" + conf.Server.EnableM3UExternalAlbumArt = false + seedEntities() + + s, err := backfill(ctx, ds, func() ImageAgentCount { return ImageAgentCount{Artist: 3, Album: 2} }) + Expect(err).ToNot(HaveOccurred()) + Expect(s.Ran).To(BeTrue()) + + Expect(s.PerKind).To(Equal(map[string]int64{"ar": 2, "al": 1, "pl": 1, "ra": 1})) + Expect(s.Items).To(Equal(int64(5))) + // 2 artists x 3 agents, 1 album x 2, 1 playlist grid x 2, and radios never fetch. + Expect(s.MaxExternalLookups).To(Equal(int64(6 + 2 + PlaylistGridSamples*2))) + }) }) Describe("EnqueueStaleAbsentAll", func() { diff --git a/core/artwork/resolve.go b/core/artwork/resolve.go index f42beb9f1..6663679fa 100644 --- a/core/artwork/resolve.go +++ b/core/artwork/resolve.go @@ -137,6 +137,15 @@ func MayFetchExternal(kind model.Kind) bool { // ImageAgentCount is how many enabled agents provide artist and album images. type ImageAgentCount struct{ Artist, Album int } +// NewImageAgentCount counts what an external step would consult, so an estimate and the gate that +// guards it cannot disagree about which agents exist. +func NewImageAgentCount(ag *agents.Agents) ImageAgentCount { + if ag == nil { + return ImageAgentCount{} + } + return ImageAgentCount{Artist: len(ag.ArtistImageAgents()), Album: len(ag.AlbumImageAgents())} +} + // ExternalLookupsPerItem reports what resolving one item of this kind can cost: every image agent is // tried, and a zero count still bills one, so agents the caller cannot see never read as free. func ExternalLookupsPerItem(kind model.Kind, agents ImageAgentCount) int64 { diff --git a/core/artwork/worker.go b/core/artwork/worker.go index 0f947f6d7..0358708c0 100644 --- a/core/artwork/worker.go +++ b/core/artwork/worker.go @@ -40,6 +40,7 @@ type drainPool struct { // independently, and pruneMu serializes prune against the store-write window. type Worker struct { proc *processor + agents *agents.Agents cache cache.FileCache ffmpeg ffmpeg.FFmpeg broker events.Broker @@ -54,6 +55,7 @@ type Worker struct { 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}, + agents: ag, cache: imgCache, ffmpeg: ffmpeg, broker: broker, @@ -132,9 +134,10 @@ func (w *Worker) RunPrune(ctx context.Context) error { } // Backfill enqueues every entity for re-resolution when the artwork config fingerprint changed, -// artists first. It reports whether anything was enqueued. +// artists first. It reports whether the backfill ran. func (w *Worker) Backfill(ctx context.Context) (bool, error) { - return backfill(ctx, w.proc.ds) + s, err := backfill(ctx, w.proc.ds, func() ImageAgentCount { return NewImageAgentCount(w.agents) }) + return s.Ran, err } // EnqueueStaleAbsentAll requeues known-absent entries older than StaleAbsentAge, at most From 59810c3d59af724f46c73fd8add72ec5cde1776e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Sat, 22 Aug 2026 20:36:24 -0400 Subject: [PATCH 09/13] feat(jellyfin): non-expiring, audience-scoped tokens revocable by password change (#6013) * feat(auth): add per-user token_epoch column and bump method * feat(auth): add aud and ep claims, omitted when zero * feat(auth): add CreateAPIToken for non-expiring, audience-scoped tokens * feat(auth): add CheckClaims for epoch and audience validation * feat(jellyfin): issue non-expiring, jellyfin-scoped access tokens * fix(subsonic): reject API-scoped and revoked tokens on the jwt path * fix(server): reject API-scoped and revoked tokens on the native API * fix(server): pin the token-subject guard and stop leaking test config Adds a regression spec for the DevAutoLogin/ExtAuth guard in tokenAllowed, switches its comparison to case-insensitive to match the user lookup's own COLLATE NOCASE semantics, and restores Subsonic JWT test config after each spec instead of leaking SessionTimeout. * feat(request): add a token epoch holder for handler-to-middleware signalling * refactor(server): write the refreshed JWT header after the handler runs * feat(auth): revoke all tokens for a user when their password changes * fix(server): restore Unwrap on the JWT refresh writer so SSE write deadlines apply * test(auth): pin that non-session tokens reject API access tokens * test(jellyfin): pin token scoping and epoch revocation end to end Exercises auth.CreateAPIToken and CheckClaims against the real Jellyfin router and SQLite DB: the minted token has no exp and is aud-scoped to jellyfin, and bumping token_epoch through the real UserRepository revokes an already-issued token on the next protected request. * test(nativeapi): pin the token-epoch handoff through a real password-change request Drive a self password change through the real Authenticator/JWTRefresher chain and a real SQLite-backed userRepository, so the epoch handoff between Put and the refreshed-token writer is verified end to end, not as two separately-tested halves. Also fix tokenAllowed to read the enriched ctx it was given instead of r.Context(), so its warning log carries the username. * refactor(server): drop tokenAllowed's now-unused request parameter Finding-2 already moved every use to ctx; r was dead weight. Also note in the new nativeapi test why it must stay the package's only real-DB spec: db.Db() is a process-wide singleton its cleanup closes for good. * refactor(auth): remove duplication in claim decoding and token minting * refactor(auth): group aud with the standard JWT claims * refactor(auth): read aud with the standard-claim accessor pattern * fix(log): redact every api_key spelling the Jellyfin API accepts * fix(auth): bind session tokens to the user id, not just the username * fix(auth): return the token epoch from the same atomic increment * fix(auth): bump the token epoch in the same statement as the password write * chore(auth): trim comments to the why-only budget --- adapters/lastfm/auth_router_test.go | 9 + core/auth/auth.go | 59 ++++++- core/auth/auth_test.go | 109 ++++++++++++ core/auth/claims.go | 32 +++- core/auth/claims_test.go | 40 +++++ core/stream/token_test.go | 10 ++ .../20260822062750_add_user_token_epoch.sql | 7 + log/log.go | 5 +- log/log_test.go | 11 ++ model/request/request.go | 49 +++++- model/request/request_suite_test.go | 17 ++ model/request/request_test.go | 40 +++++ model/user.go | 2 + persistence/user_repository.go | 35 +++- persistence/user_repository_test.go | 157 ++++++++++++++++++ server/auth.go | 94 +++++++++-- server/auth_test.go | 135 +++++++++++++++ server/jellyfin/README.md | 2 + server/jellyfin/auth.go | 2 +- server/jellyfin/e2e/auth_test.go | 37 +++++ server/jellyfin/middlewares.go | 4 + server/jellyfin/middlewares_test.go | 46 +++++ .../user_password_token_refresh_test.go | 80 +++++++++ server/subsonic/middlewares.go | 4 +- server/subsonic/middlewares_test.go | 31 ++++ 25 files changed, 971 insertions(+), 46 deletions(-) create mode 100644 db/migrations/20260822062750_add_user_token_epoch.sql create mode 100644 model/request/request_suite_test.go create mode 100644 model/request/request_test.go create mode 100644 server/nativeapi/user_password_token_refresh_test.go diff --git a/adapters/lastfm/auth_router_test.go b/adapters/lastfm/auth_router_test.go index 4cbbd4298..1f65c059e 100644 --- a/adapters/lastfm/auth_router_test.go +++ b/adapters/lastfm/auth_router_test.go @@ -214,5 +214,14 @@ var _ = Describe("auth_router", func() { _, err = verifyLinkToken(nonExpiringToken) Expect(err).To(MatchError("link token missing expiration")) }) + + It("rejects a Jellyfin access token", func() { + usr := &model.User{ID: "u1", UserName: "johndoe"} + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + + _, err = verifyLinkToken(tokenStr) + Expect(err).To(HaveOccurred()) + }) }) }) diff --git a/core/auth/auth.go b/core/auth/auth.go index b1e2667bd..b36bb2696 100644 --- a/core/auth/auth.go +++ b/core/auth/auth.go @@ -4,6 +4,8 @@ import ( "cmp" "context" "crypto/sha256" + "errors" + "slices" "sync" "time" @@ -26,6 +28,13 @@ var ( PublicTokenAuth *jwtauth.JWTAuth ) +// Audiences a session token can be scoped to. A token with no audience is accepted anywhere. +const ( + AudienceJellyfin = "jellyfin" + AudienceSubsonic = "subsonic" + AudienceNative = "native" +) + // Init creates the JWTAuth objects from the secrets stored in the DB. // Missing or undecryptable secrets are regenerated and stored. func Init(ds model.DataStore) { @@ -66,15 +75,20 @@ func CreateExpiringPublicToken(exp time.Time, claims Claims) (string, error) { return token, err } -func CreateToken(u *model.User) (string, error) { - claims := Claims{ +func userClaims(u *model.User, audience []string) Claims { + return Claims{ Issuer: consts.JWTIssuer, Subject: u.UserName, IssuedAt: time.Now(), UserID: u.ID, IsAdmin: u.IsAdmin, + Epoch: u.TokenEpoch, + Audience: audience, } - token, _, err := TokenAuth.Encode(claims.ToMap()) +} + +func CreateToken(u *model.User) (string, error) { + token, _, err := TokenAuth.Encode(userClaims(u, nil).ToMap()) if err != nil { return "", err } @@ -82,10 +96,20 @@ func CreateToken(u *model.User) (string, error) { return TouchToken(token) } +// CreateAPIToken mints a non-expiring token scoped to one API, matching how Jellyfin +// clients expect tokens to behave. Revocation is by token epoch, not expiry. +func CreateAPIToken(u *model.User, audience string) (string, error) { + _, token, err := TokenAuth.Encode(userClaims(u, []string{audience}).ToMap()) + return token, err +} + func TouchToken(token jwt.Token) (string, error) { - claims := ClaimsFromToken(token). - WithExpiresAt(time.Now().UTC().Add(conf.Server.SessionTimeout)) - _, newToken, err := TokenAuth.Encode(claims.ToMap()) + return TouchClaims(ClaimsFromToken(token)) +} + +func TouchClaims(c Claims) (string, error) { + c = c.WithExpiresAt(time.Now().UTC().Add(conf.Server.SessionTimeout)) + _, newToken, err := TokenAuth.Encode(c.ToMap()) return newToken, err } @@ -106,6 +130,29 @@ func ValidatePublic(tokenStr string) (Claims, error) { return ClaimsFromToken(token), nil } +var ( + ErrTokenRevoked = errors.New("token revoked") + ErrWrongAudience = errors.New("token not valid for this API") + ErrWrongUser = errors.New("token issued for a different user") +) + +// CheckClaims gates a session token against the user it names. Callers must have already +// verified the signature; this adds revocation and API scoping on top. +func CheckClaims(c Claims, usr model.User, audience string) error { + // Usernames can be reused: deleting a user and recreating the name yields a new random id + // at epoch 0, which an old token would otherwise match. + if c.UserID != "" && c.UserID != usr.ID { + return ErrWrongUser + } + if c.Epoch != usr.TokenEpoch { + return ErrTokenRevoked + } + if len(c.Audience) > 0 && !slices.Contains(c.Audience, audience) { + return ErrWrongAudience + } + return nil +} + func WithAdminUser(ctx context.Context, ds model.DataStore) context.Context { u, err := ds.User(ctx).FindFirstAdmin() if err != nil { diff --git a/core/auth/auth_test.go b/core/auth/auth_test.go index e5cbb2352..c86dcd08c 100644 --- a/core/auth/auth_test.go +++ b/core/auth/auth_test.go @@ -151,4 +151,113 @@ var _ = Describe("Auth", func() { Expect(decodedClaims.ExpiresAt.Sub(yesterday)).To(BeNumerically(">=", oneDay)) }) }) + + Describe("CreateAPIToken", func() { + var usr *model.User + + BeforeEach(func() { + usr = &model.User{ID: "123", UserName: "johndoe", TokenEpoch: 4} + }) + + It("does not expire", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + + claims, err := auth.Validate(tokenStr) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.ExpiresAt.IsZero()).To(BeTrue()) + }) + + It("carries the audience and the user's epoch", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + + claims, err := auth.Validate(tokenStr) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.Audience).To(Equal([]string{"jellyfin"})) + Expect(claims.Epoch).To(Equal(4)) + Expect(claims.Subject).To(Equal("johndoe")) + Expect(claims.UserID).To(Equal("123")) + }) + }) + + Describe("CreateToken with an epoch", func() { + It("carries the epoch and still expires", func() { + usr := &model.User{ID: "123", UserName: "johndoe", TokenEpoch: 9} + tokenStr, err := auth.CreateToken(usr) + Expect(err).ToNot(HaveOccurred()) + + claims, err := auth.Validate(tokenStr) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.Epoch).To(Equal(9)) + Expect(claims.Audience).To(BeEmpty()) + Expect(claims.ExpiresAt).To(BeTemporally(">", time.Now())) + }) + }) + + Describe("TouchClaims", func() { + It("preserves custom claims and refreshes the expiry", func() { + tokenStr, err := auth.TouchClaims(auth.Claims{Subject: "johndoe", UserID: "123", Epoch: 5}) + Expect(err).ToNot(HaveOccurred()) + + claims, err := auth.Validate(tokenStr) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.Epoch).To(Equal(5)) + Expect(claims.Subject).To(Equal("johndoe")) + Expect(claims.ExpiresAt).To(BeTemporally(">", time.Now())) + }) + }) + + Describe("CheckClaims", func() { + usr := model.User{ID: "123", UserName: "johndoe", TokenEpoch: 2} + + It("accepts a matching epoch and audience", func() { + c := auth.Claims{Epoch: 2, Audience: []string{auth.AudienceJellyfin}} + Expect(auth.CheckClaims(c, usr, auth.AudienceJellyfin)).To(Succeed()) + }) + + It("accepts a token with no audience on any API", func() { + c := auth.Claims{Epoch: 2} + Expect(auth.CheckClaims(c, usr, auth.AudienceNative)).To(Succeed()) + Expect(auth.CheckClaims(c, usr, auth.AudienceJellyfin)).To(Succeed()) + Expect(auth.CheckClaims(c, usr, auth.AudienceSubsonic)).To(Succeed()) + }) + + It("rejects a stale epoch", func() { + c := auth.Claims{Epoch: 1, Audience: []string{auth.AudienceJellyfin}} + Expect(auth.CheckClaims(c, usr, auth.AudienceJellyfin)).To(MatchError(auth.ErrTokenRevoked)) + }) + + It("rejects a token minted for another API", func() { + c := auth.Claims{Epoch: 2, Audience: []string{auth.AudienceJellyfin}} + Expect(auth.CheckClaims(c, usr, auth.AudienceNative)).To(MatchError(auth.ErrWrongAudience)) + Expect(auth.CheckClaims(c, usr, auth.AudienceSubsonic)).To(MatchError(auth.ErrWrongAudience)) + }) + + It("accepts a multi-audience token that includes this API", func() { + c := auth.Claims{Epoch: 2, Audience: []string{"other", auth.AudienceNative}} + Expect(auth.CheckClaims(c, usr, auth.AudienceNative)).To(Succeed()) + }) + + It("accepts a pre-upgrade token against a never-bumped user", func() { + fresh := model.User{ID: "456", UserName: "newbie"} + Expect(auth.CheckClaims(auth.Claims{}, fresh, auth.AudienceNative)).To(Succeed()) + }) + + It("accepts a token whose user id matches", func() { + c := auth.Claims{UserID: "123", Epoch: 2} + Expect(auth.CheckClaims(c, usr, auth.AudienceNative)).To(Succeed()) + }) + + It("rejects a token for a deleted user recreated under the same name", func() { + recreated := model.User{ID: "new-random-id", UserName: "johndoe"} + c := auth.Claims{UserID: "123", Audience: []string{auth.AudienceJellyfin}} + Expect(auth.CheckClaims(c, recreated, auth.AudienceJellyfin)).To(MatchError(auth.ErrWrongUser)) + }) + + It("accepts a token that carries no user id", func() { + fresh := model.User{ID: "456", UserName: "newbie"} + Expect(auth.CheckClaims(auth.Claims{}, fresh, auth.AudienceNative)).To(Succeed()) + }) + }) }) diff --git a/core/auth/claims.go b/core/auth/claims.go index c7e6f02fe..42f7e4f2f 100644 --- a/core/auth/claims.go +++ b/core/auth/claims.go @@ -11,7 +11,8 @@ import ( type Claims struct { // Standard JWT claims Issuer string - Subject string // username for session tokens + Subject string // username for session tokens + Audience []string // which API may accept this token; empty means any IssuedAt time.Time ExpiresAt time.Time @@ -22,6 +23,7 @@ type Claims struct { Format string // "f" - audio format BitRate int // "b" - audio bitrate ShareID string // "sid" - share ID for share stream tokens + Epoch int // "ep" - the user's token_epoch at mint time } // ToMap converts Claims to a map[string]any for use with TokenAuth.Encode(). @@ -34,6 +36,9 @@ func (c Claims) ToMap() map[string]any { if c.Subject != "" { m[jwt.SubjectKey] = c.Subject } + if len(c.Audience) > 0 { + m[jwt.AudienceKey] = c.Audience + } if !c.IssuedAt.IsZero() { m[jwt.IssuedAtKey] = c.IssuedAt.UTC().Unix() } @@ -58,6 +63,9 @@ func (c Claims) ToMap() map[string]any { if c.ShareID != "" { m["sid"] = c.ShareID } + if c.Epoch != 0 { + m["ep"] = c.Epoch + } return m } @@ -73,6 +81,7 @@ func ClaimsFromToken(token jwt.Token) Claims { c.Subject, _ = token.Subject() c.IssuedAt, _ = token.IssuedAt() c.ExpiresAt, _ = token.Expiration() + c.Audience, _ = token.Audience() var uid string if err := token.Get("uid", &uid); err == nil { @@ -90,15 +99,24 @@ func ClaimsFromToken(token jwt.Token) Claims { if err := token.Get("f", &f); err == nil { c.Format = f } - if err := token.Get("b", &c.BitRate); err != nil { - var bf float64 - if err := token.Get("b", &bf); err == nil { - c.BitRate = int(bf) - } - } + c.BitRate = intClaim(token, "b") var sid string if err := token.Get("sid", &sid); err == nil { c.ShareID = sid } + c.Epoch = intClaim(token, "ep") return c } + +// intClaim reads a numeric claim, which a parsed token may decode as either int or float64. +func intClaim(token jwt.Token, key string) int { + var i int + if err := token.Get(key, &i); err == nil { + return i + } + var f float64 + if err := token.Get(key, &f); err == nil { + return int(f) + } + return 0 +} diff --git a/core/auth/claims_test.go b/core/auth/claims_test.go index 8820fd295..69d054031 100644 --- a/core/auth/claims_test.go +++ b/core/auth/claims_test.go @@ -105,4 +105,44 @@ var _ = Describe("Claims", func() { }) }) + Describe("Audience and Epoch claims", func() { + It("omits both when zero", func() { + m := auth.Claims{ID: "artwork-id"}.ToMap() + Expect(m).ToNot(HaveKey("aud")) + Expect(m).ToNot(HaveKey("ep")) + }) + + It("includes them when set", func() { + m := auth.Claims{Subject: "u", Epoch: 3, Audience: []string{"jellyfin"}}.ToMap() + Expect(m).To(HaveKeyWithValue("ep", 3)) + Expect(m).To(HaveKeyWithValue("aud", []string{"jellyfin"})) + }) + + It("round-trips through a signed token", func() { + tokenAuth := jwtauth.New("HS256", []byte("test-secret"), nil) + _, tokenStr, err := tokenAuth.Encode(auth.Claims{ + Subject: "u", Epoch: 7, Audience: []string{"jellyfin"}, + }.ToMap()) + Expect(err).ToNot(HaveOccurred()) + + token, err := jwtauth.VerifyToken(tokenAuth, tokenStr) + Expect(err).ToNot(HaveOccurred()) + claims := auth.ClaimsFromToken(token) + Expect(claims.Epoch).To(Equal(7)) + Expect(claims.Audience).To(Equal([]string{"jellyfin"})) + }) + + It("reads a token that has neither claim", func() { + tokenAuth := jwtauth.New("HS256", []byte("test-secret"), nil) + _, tokenStr, err := tokenAuth.Encode(auth.Claims{Subject: "u"}.ToMap()) + Expect(err).ToNot(HaveOccurred()) + + token, err := jwtauth.VerifyToken(tokenAuth, tokenStr) + Expect(err).ToNot(HaveOccurred()) + claims := auth.ClaimsFromToken(token) + Expect(claims.Epoch).To(BeZero()) + Expect(claims.Audience).To(BeEmpty()) + }) + }) + }) diff --git a/core/stream/token_test.go b/core/stream/token_test.go index 7409a7532..4f0d8066c 100644 --- a/core/stream/token_test.go +++ b/core/stream/token_test.go @@ -232,6 +232,16 @@ var _ = Describe("Token", func() { _, err := svc.ResolveRequestFromToken(ctx, token, mf, 0) Expect(err).To(MatchError(ErrTokenStale)) }) + + It("rejects a Jellyfin access token", func() { + mf := &model.MediaFile{ID: "song-1", UpdatedAt: sourceTime} + usr := &model.User{ID: "u1", UserName: "johndoe"} + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + + _, err = svc.ResolveRequestFromToken(ctx, tokenStr, mf, 0) + Expect(err).To(MatchError(ErrTokenInvalid)) + }) }) Describe("paramsFromToken", func() { diff --git a/db/migrations/20260822062750_add_user_token_epoch.sql b/db/migrations/20260822062750_add_user_token_epoch.sql new file mode 100644 index 000000000..bd37ddeb4 --- /dev/null +++ b/db/migrations/20260822062750_add_user_token_epoch.sql @@ -0,0 +1,7 @@ +-- +goose Up + +ALTER TABLE user ADD COLUMN token_epoch INTEGER NOT NULL DEFAULT 0; + +-- +goose Down + +ALTER TABLE user DROP COLUMN token_epoch; diff --git a/log/log.go b/log/log.go index 1c4ee3b4b..f7977c0fa 100644 --- a/log/log.go +++ b/log/log.go @@ -47,8 +47,9 @@ var redacted = &Hook{ // External services query params. Values can be JWTs (dots, dashes), so match everything up // to the next query separator or whitespace, not just word chars. A [\w]+ class would stop - // at a JWT's first '.' and leak its payload and signature. - "([^\\w]api_key=)[^&\\s]+", + // at a JWT's first '.' and leak its payload and signature. Case-insensitive with an + // optional underscore: the API accepts api_key, apikey and ApiKey alike. + "(?i)([^\\w]api_?key=)[^&\\s]+", }, } diff --git a/log/log_test.go b/log/log_test.go index 7b6ecfc32..f0e2e0eae 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -264,5 +264,16 @@ var _ = Describe("Logger", func() { msg := "/jellyfin/Audio/abc/universal?static=true&api_key=eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJhZG1pbiJ9.c2ln-X_1&other=1" Expect(Redact(msg)).To(Equal("/jellyfin/Audio/abc/universal?static=true&api_key=[REDACTED]&other=1")) }) + + DescribeTable("redacts every api_key spelling the Jellyfin API accepts", + func(param string) { + msg := "/jellyfin/Audio/abc/File?" + param + "=SECRET&other=1" + Expect(Redact(msg)).To(Equal("/jellyfin/Audio/abc/File?" + param + "=[REDACTED]&other=1")) + }, + Entry("api_key", "api_key"), + Entry("apikey", "apikey"), + Entry("ApiKey", "ApiKey"), + Entry("APIKEY", "APIKEY"), + ) }) }) diff --git a/model/request/request.go b/model/request/request.go index 8d7919298..2b1cfb9ef 100644 --- a/model/request/request.go +++ b/model/request/request.go @@ -2,6 +2,7 @@ package request import ( "context" + "sync/atomic" "github.com/navidrome/navidrome/model" ) @@ -9,15 +10,16 @@ import ( type contextKey string const ( - User = contextKey("user") - Username = contextKey("username") - Client = contextKey("client") - Version = contextKey("version") - Player = contextKey("player") - Transcoding = contextKey("transcoding") - ClientUniqueId = contextKey("clientUniqueId") - ReverseProxyIp = contextKey("reverseProxyIp") - InternalAuth = contextKey("internalAuth") // Used for internal API calls, e.g., from the plugins + User = contextKey("user") + Username = contextKey("username") + Client = contextKey("client") + Version = contextKey("version") + Player = contextKey("player") + Transcoding = contextKey("transcoding") + ClientUniqueId = contextKey("clientUniqueId") + ReverseProxyIp = contextKey("reverseProxyIp") + InternalAuth = contextKey("internalAuth") // Used for internal API calls, e.g., from the plugins + TokenEpochHolder = contextKey("tokenEpochHolder") ) var allKeys = []contextKey{ @@ -125,3 +127,32 @@ func AddValues(ctx, requestCtx context.Context) context.Context { } return ctx } + +type tokenEpochHolder struct { + value atomic.Int64 +} + +// WithTokenEpochHolder installs a slot a handler can use to report a bumped token epoch +// back to middleware that has already returned from the handler's perspective. +func WithTokenEpochHolder(ctx context.Context) context.Context { + h := &tokenEpochHolder{} + h.value.Store(-1) + return context.WithValue(ctx, TokenEpochHolder, h) +} + +func SetTokenEpoch(ctx context.Context, epoch int) { + if h, ok := ctx.Value(TokenEpochHolder).(*tokenEpochHolder); ok { + h.value.Store(int64(epoch)) + } +} + +func TokenEpochFrom(ctx context.Context) (int, bool) { + h, ok := ctx.Value(TokenEpochHolder).(*tokenEpochHolder) + if !ok { + return 0, false + } + if v := h.value.Load(); v >= 0 { + return int(v), true + } + return 0, false +} diff --git a/model/request/request_suite_test.go b/model/request/request_suite_test.go new file mode 100644 index 000000000..643ca76d7 --- /dev/null +++ b/model/request/request_suite_test.go @@ -0,0 +1,17 @@ +package request + +import ( + "testing" + + "github.com/navidrome/navidrome/log" + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +// tests.Init is not used here: the tests package imports model/request, so importing it +// back would create an import cycle. +func TestRequest(t *testing.T) { + log.SetLevel(log.LevelFatal) + RegisterFailHandler(Fail) + RunSpecs(t, "Request Suite") +} diff --git a/model/request/request_test.go b/model/request/request_test.go new file mode 100644 index 000000000..ef9af8231 --- /dev/null +++ b/model/request/request_test.go @@ -0,0 +1,40 @@ +package request + +import ( + "context" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +var _ = Describe("Token epoch holder", func() { + It("reports nothing when unset", func() { + ctx := WithTokenEpochHolder(context.TODO()) + _, ok := TokenEpochFrom(ctx) + Expect(ok).To(BeFalse()) + }) + + It("round-trips a value set by the handler", func() { + ctx := WithTokenEpochHolder(context.TODO()) + SetTokenEpoch(ctx, 7) + + epoch, ok := TokenEpochFrom(ctx) + Expect(ok).To(BeTrue()) + Expect(epoch).To(Equal(7)) + }) + + It("survives being wrapped in a derived context", func() { + ctx := WithTokenEpochHolder(context.TODO()) + SetTokenEpoch(context.WithValue(ctx, contextKey("unrelated"), 1), 3) + + epoch, ok := TokenEpochFrom(ctx) + Expect(ok).To(BeTrue()) + Expect(epoch).To(Equal(3)) + }) + + It("is a no-op with no holder installed", func() { + Expect(func() { SetTokenEpoch(context.TODO(), 5) }).ToNot(Panic()) + _, ok := TokenEpochFrom(context.TODO()) + Expect(ok).To(BeFalse()) + }) +}) diff --git a/model/user.go b/model/user.go index b6f792c9a..37bdca33d 100644 --- a/model/user.go +++ b/model/user.go @@ -22,6 +22,8 @@ type User struct { // This is only available on the backend, and it is never sent over the wire Password string `structs:"-" json:"-"` + // Bumped on password change to invalidate every issued token for this user. + TokenEpoch int `structs:"-" json:"-"` // This is used to set or change a password when calling Put. If it is empty, the password is not changed. // It is received from the UI with the name "password" NewPassword string `structs:"password,omitempty" json:"password,omitempty"` //nolint:gosec diff --git a/persistence/user_repository.go b/persistence/user_repository.go index 3c030a640..9de37876b 100644 --- a/persistence/user_repository.go +++ b/persistence/user_repository.go @@ -18,6 +18,7 @@ import ( "github.com/navidrome/navidrome/model" "github.com/navidrome/navidrome/model/criteria" "github.com/navidrome/navidrome/model/id" + "github.com/navidrome/navidrome/model/request" "github.com/navidrome/navidrome/utils" "github.com/navidrome/navidrome/utils/slice" "github.com/pocketbase/dbx" @@ -126,14 +127,30 @@ func (r *userRepository) Put(u *model.User) error { } delete(values, "current_password") - // Save/update the user + // The epoch bump rides the password UPDATE: as two statements they can interleave with a + // concurrent change and leave a session valid that the other change should have revoked. update := Update(r.tableName).Where(Eq{"id": u.ID}).SetMap(values) - count, err := r.executeSQL(update) - if err != nil { - return err + var isNewUser bool + var epoch int + if u.NewPassword != "" { + var res struct{ TokenEpoch int } + err = r.queryOne(update.Set("token_epoch", Expr("token_epoch + 1")). + Suffix("RETURNING token_epoch"), &res) + switch { + case errors.Is(err, model.ErrNotFound): + isNewUser = true + case err != nil: + return err + default: + epoch = res.TokenEpoch + } + } else { + count, err := r.executeSQL(update) + if err != nil { + return err + } + isNewUser = count == 0 } - - isNewUser := count == 0 if isNewUser { values["created_at"] = time.Now() insert := Insert(r.tableName).SetMap(values) @@ -163,6 +180,12 @@ func (r *userRepository) Put(u *model.User) error { } } + // Only the caller's own token can be refreshed in-flight; an admin resetting another + // user must keep their own epoch. + if u.NewPassword != "" && !isNewUser && loggedUser(r.ctx).ID == u.ID { + request.SetTokenEpoch(r.ctx, epoch) + } + return nil } diff --git a/persistence/user_repository_test.go b/persistence/user_repository_test.go index ec417c193..dc519d0a1 100644 --- a/persistence/user_repository_test.go +++ b/persistence/user_repository_test.go @@ -4,6 +4,7 @@ import ( "context" "errors" "slices" + "sync" "github.com/Masterminds/squirrel" "github.com/deluan/rest" @@ -13,6 +14,7 @@ import ( "github.com/navidrome/navidrome/model/id" "github.com/navidrome/navidrome/model/request" "github.com/navidrome/navidrome/tests" + "github.com/navidrome/navidrome/utils/slice" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" ) @@ -683,4 +685,159 @@ var _ = Describe("UserRepository", func() { Expect(query).To(ContainSubstring("user.id = {:p0}")) }) }) + + Describe("token epoch", func() { + var repo model.UserRepository + var usr model.User + + newUser := func() model.User { + uid := id.NewRandom() + // user_name is unique; suffix it so each It gets its own row in the shared suite DB. + return model.User{ID: uid, UserName: "epoch-user-" + uid, Name: "Epoch", NewPassword: "hunter2"} + } + + BeforeEach(func() { + ctx := log.NewContext(context.TODO()) + ctx = request.WithUser(ctx, model.User{ID: "userid", IsAdmin: true}) + repo = NewUserRepository(ctx, GetDBXBuilder()) + usr = newUser() + Expect(repo.Put(&usr)).To(Succeed()) + }) + + It("starts at zero for a new user", func() { + got, err := repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(0)) + }) + + It("increments once per password change", func() { + usr.NewPassword = "second" + Expect(repo.Put(&usr)).To(Succeed()) + got, err := repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(1)) + + usr.NewPassword = "third" + Expect(repo.Put(&usr)).To(Succeed()) + got, err = repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(2)) + }) + + It("leaves the epoch alone when the password is untouched", func() { + usr.NewPassword = "" + usr.Name = "Renamed" + Expect(repo.Put(&usr)).To(Succeed()) + + got, err := repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(0)) + Expect(got.Name).To(Equal("Renamed")) + }) + + It("never signals the same epoch to two concurrent password changes", func() { + // Each writer's epoch must be the one its own UPDATE produced. + const callers = 4 + var mu sync.Mutex + var signalled []int + var wg sync.WaitGroup + for range callers { + wg.Go(func() { + ctx := log.NewContext(context.TODO()) + ctx = request.WithUser(ctx, model.User{ID: usr.ID}) + ctx = request.WithTokenEpochHolder(ctx) + own := NewUserRepository(ctx, GetDBXBuilder()) + + u := usr + u.NewPassword = "concurrent" + if err := own.Put(&u); err != nil { + return // the shared in-memory test DB can raise SQLITE_LOCKED + } + epoch, ok := request.TokenEpochFrom(ctx) + if !ok { + return + } + mu.Lock() + defer mu.Unlock() + signalled = append(signalled, epoch) + }) + } + wg.Wait() + + Expect(signalled).To(HaveLen(len(slice.Unique(signalled))), + "an epoch was signalled to more than one writer: %v", signalled) + }) + }) + + Describe("Put and the token epoch", func() { + newRepo := func(actingUserID string) model.UserRepository { + ctx := log.NewContext(context.TODO()) + ctx = request.WithUser(ctx, model.User{ID: actingUserID, IsAdmin: true}) + ctx = request.WithTokenEpochHolder(ctx) + return NewUserRepository(ctx, GetDBXBuilder()) + } + + It("does not bump when creating a user", func() { + repo := newRepo("admin") + usr := model.User{ID: id.NewRandom(), UserName: "fresh", NewPassword: "pw1"} + Expect(repo.Put(&usr)).To(Succeed()) + + got, err := repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(0)) + }) + + It("bumps when the password changes", func() { + repo := newRepo("admin") + usr := model.User{ID: id.NewRandom(), UserName: "changer", NewPassword: "pw1"} + Expect(repo.Put(&usr)).To(Succeed()) + + usr.NewPassword = "pw2" + Expect(repo.Put(&usr)).To(Succeed()) + + got, err := repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(1)) + }) + + It("does not bump on an edit that leaves the password alone", func() { + repo := newRepo("admin") + usr := model.User{ID: id.NewRandom(), UserName: "renamer", NewPassword: "pw1"} + Expect(repo.Put(&usr)).To(Succeed()) + + usr.NewPassword = "" + usr.Name = "New Display Name" + Expect(repo.Put(&usr)).To(Succeed()) + + got, err := repo.Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(got.TokenEpoch).To(Equal(0)) + }) + + It("signals the new epoch when a user changes their own password", func() { + userID := id.NewRandom() + repo := newRepo(userID) + usr := model.User{ID: userID, UserName: "self", NewPassword: "pw1"} + Expect(repo.Put(&usr)).To(Succeed()) + + usr.NewPassword = "pw2" + Expect(repo.Put(&usr)).To(Succeed()) + + epoch, ok := request.TokenEpochFrom(repo.(*userRepository).ctx) + Expect(ok).To(BeTrue()) + Expect(epoch).To(Equal(1)) + }) + + It("does not signal when an admin changes someone else's password", func() { + repo := newRepo("some-admin") + usr := model.User{ID: id.NewRandom(), UserName: "other", NewPassword: "pw1"} + Expect(repo.Put(&usr)).To(Succeed()) + + usr.NewPassword = "pw2" + Expect(repo.Put(&usr)).To(Succeed()) + + _, ok := request.TokenEpochFrom(repo.(*userRepository).ctx) + Expect(ok).To(BeFalse()) + }) + }) }) diff --git a/server/auth.go b/server/auth.go index 6a25f1406..37a318a83 100644 --- a/server/auth.go +++ b/server/auth.go @@ -12,10 +12,12 @@ import ( "net/http" "slices" "strings" + "sync" "time" "github.com/deluan/rest" "github.com/go-chi/jwtauth/v5" + "github.com/lestrrat-go/jwx/v3/jwt" "github.com/navidrome/navidrome/conf" "github.com/navidrome/navidrome/consts" "github.com/navidrome/navidrome/core/auth" @@ -260,7 +262,7 @@ func Authenticator(ds model.DataStore) func(next http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { ctx, err := authenticateRequest(ds, r, UsernameFromConfig, UsernameFromToken, UsernameFromExtAuthHeader) - if err != nil { + if err != nil || !tokenAllowed(ctx) { _ = rest.RespondWithError(w, http.StatusUnauthorized, "Not authenticated") return } @@ -270,24 +272,88 @@ func Authenticator(ds model.DataStore) func(next http.Handler) http.Handler { } } -// JWTRefresher updates the expiry date of the received JWT token, and add the new one to the Authorization Header +// tokenAllowed re-checks a JWT that actually identifies the resolved user. Header and +// config auth carry no token, so they short-circuit to true. +func tokenAllowed(ctx context.Context) bool { + token, _, err := jwtauth.FromContext(ctx) + if err != nil || token == nil { + return true + } + usr, ok := request.UserFrom(ctx) + if !ok { + return true + } + claims := auth.ClaimsFromToken(token) + if !strings.EqualFold(claims.Subject, usr.UserName) { + return true + } + if err := auth.CheckClaims(claims, usr, auth.AudienceNative); err != nil { + log.Warn(ctx, "Native API: rejected token", "user", claims.Subject, err) + return false + } + return true +} + +// refreshingWriter defers the refreshed-token header until the handler's first write, so an +// epoch the handler bumped reaches the token the client stores. +type refreshingWriter struct { + http.ResponseWriter + ctx context.Context + token jwt.Token + once sync.Once +} + +func (w *refreshingWriter) setToken() { + w.once.Do(func() { + claims := auth.ClaimsFromToken(w.token) + if epoch, ok := request.TokenEpochFrom(w.ctx); ok { + claims.Epoch = epoch + } + newToken, err := auth.TouchClaims(claims) + if err != nil { + log.Error(w.ctx, "Could not sign new token", err) + return + } + w.Header().Set(consts.UIAuthorizationHeader, newToken) + }) +} + +func (w *refreshingWriter) WriteHeader(code int) { + w.setToken() + w.ResponseWriter.WriteHeader(code) +} + +func (w *refreshingWriter) Write(b []byte) (int, error) { + w.setToken() + return w.ResponseWriter.Write(b) +} + +// Flush keeps the SSE events route working through the wrap. +func (w *refreshingWriter) Flush() { + w.setToken() + if f, ok := w.ResponseWriter.(http.Flusher); ok { + f.Flush() + } +} + +// Unwrap lets capability lookups, such as SSE's write deadline, see past this wrap. +func (w *refreshingWriter) Unwrap() http.ResponseWriter { + return w.ResponseWriter +} + +// JWTRefresher updates the expiry date of the received JWT token, and adds the new one to +// the Authorization Header. func JWTRefresher(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - ctx := r.Context() - token, _, err := jwtauth.FromContext(ctx) - if err != nil { + token, _, err := jwtauth.FromContext(r.Context()) + if err != nil || token == nil { next.ServeHTTP(w, r) return } - newTokenString, err := auth.TouchToken(token) - if err != nil { - log.Error(r, "Could not sign new token", err) - _ = rest.RespondWithError(w, http.StatusUnauthorized, "Not authenticated") - return - } - - w.Header().Set(consts.UIAuthorizationHeader, newTokenString) - next.ServeHTTP(w, r) + ctx := request.WithTokenEpochHolder(r.Context()) + rw := &refreshingWriter{ResponseWriter: w, ctx: ctx, token: token} + next.ServeHTTP(rw, r.WithContext(ctx)) + rw.setToken() }) } diff --git a/server/auth_test.go b/server/auth_test.go index f6af6f0d6..e021c82a8 100644 --- a/server/auth_test.go +++ b/server/auth_test.go @@ -12,6 +12,7 @@ import ( "time" "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/conf/configtest" "github.com/navidrome/navidrome/consts" "github.com/navidrome/navidrome/core/auth" "github.com/navidrome/navidrome/model" @@ -342,4 +343,138 @@ var _ = Describe("Auth", func() { Expect(u.IsAdmin).To(BeFalse()) }) }) + + Describe("Authenticator token gating", func() { + var ds *tests.MockDataStore + var usr *model.User + + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + conf.Server.SessionTimeout = time.Hour + ds = &tests.MockDataStore{} + auth.Init(ds) + ur := ds.User(context.TODO()).(*tests.MockedUserRepo) + usr = &model.User{ID: "u1", UserName: "johndoe", NewPassword: "pw", TokenEpoch: 2} + Expect(ur.Put(usr)).To(Succeed()) + }) + + serve := func(token string) *httptest.ResponseRecorder { + r := httptest.NewRequest("GET", "/api/song", nil) + r.Header.Set(consts.UIAuthorizationHeader, "Bearer "+token) + w := httptest.NewRecorder() + handler := JWTVerifier(Authenticator(ds)(http.HandlerFunc( + func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }, + ))) + handler.ServeHTTP(w, r) + return w + } + + It("accepts a current session token", func() { + tokenStr, err := auth.CreateToken(usr) + Expect(err).ToNot(HaveOccurred()) + Expect(serve(tokenStr).Code).To(Equal(http.StatusOK)) + }) + + It("rejects a jellyfin-scoped token", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + Expect(serve(tokenStr).Code).To(Equal(http.StatusUnauthorized)) + }) + + It("rejects a token with a stale epoch", func() { + tokenStr, err := auth.CreateToken(usr) + Expect(err).ToNot(HaveOccurred()) + usr.TokenEpoch = 3 + Expect(serve(tokenStr).Code).To(Equal(http.StatusUnauthorized)) + }) + + It("ignores a stray token for someone else when config auto-login resolves the user", func() { + conf.Server.DevAutoLoginUsername = usr.UserName + tokenStr, err := auth.CreateToken(&model.User{UserName: "someone-else"}) + Expect(err).ToNot(HaveOccurred()) + Expect(serve(tokenStr).Code).To(Equal(http.StatusOK)) + }) + + It("rejects a stale-epoch token whose subject differs only in case from the resolved user", func() { + tokenStr, err := auth.CreateToken(&model.User{UserName: strings.ToUpper(usr.UserName), TokenEpoch: usr.TokenEpoch}) + Expect(err).ToNot(HaveOccurred()) + usr.TokenEpoch = 5 + Expect(serve(tokenStr).Code).To(Equal(http.StatusUnauthorized)) + }) + }) + + Describe("JWTRefresher", func() { + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + // TouchClaims reads this; left at zero every refreshed token is born expired. + conf.Server.SessionTimeout = time.Hour + auth.Init(&tests.MockDataStore{}) + }) + + serveWith := func(handler http.HandlerFunc) *httptest.ResponseRecorder { + usr := model.User{ID: "u1", UserName: "johndoe", TokenEpoch: 1} + tokenStr, err := auth.CreateToken(&usr) + Expect(err).ToNot(HaveOccurred()) + + r := httptest.NewRequest("GET", "/api/song", nil) + r.Header.Set(consts.UIAuthorizationHeader, "Bearer "+tokenStr) + w := httptest.NewRecorder() + JWTVerifier(JWTRefresher(handler)).ServeHTTP(w, r) + return w + } + + It("writes a refreshed token when the handler writes a body", func() { + w := serveWith(func(w http.ResponseWriter, _ *http.Request) { + _, _ = w.Write([]byte("ok")) + }) + Expect(w.Header().Get(consts.UIAuthorizationHeader)).ToNot(BeEmpty()) + }) + + It("writes a refreshed token when the handler writes no body", func() { + w := serveWith(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusNoContent) + }) + Expect(w.Header().Get(consts.UIAuthorizationHeader)).ToNot(BeEmpty()) + }) + + It("picks up an epoch the handler reported", func() { + w := serveWith(func(w http.ResponseWriter, r *http.Request) { + request.SetTokenEpoch(r.Context(), 42) + w.WriteHeader(http.StatusOK) + }) + + claims, err := auth.Validate(w.Header().Get(consts.UIAuthorizationHeader)) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.Epoch).To(Equal(42)) + }) + + It("keeps the original epoch when the handler reports nothing", func() { + w := serveWith(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + claims, err := auth.Validate(w.Header().Get(consts.UIAuthorizationHeader)) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.Epoch).To(Equal(1)) + }) + + It("propagates Flush to the underlying ResponseWriter", func() { + w := serveWith(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + w.(http.Flusher).Flush() + }) + Expect(w.Flushed).To(BeTrue()) + }) + + It("exposes the underlying ResponseWriter via Unwrap, for http.ResponseController lookups", func() { + var unwrapped http.ResponseWriter + w := serveWith(func(w http.ResponseWriter, _ *http.Request) { + u, ok := w.(interface{ Unwrap() http.ResponseWriter }) + Expect(ok).To(BeTrue()) + unwrapped = u.Unwrap() + w.WriteHeader(http.StatusOK) + }) + Expect(unwrapped).To(BeIdenticalTo(w)) + }) + }) }) diff --git a/server/jellyfin/README.md b/server/jellyfin/README.md index dc3219dfa..15b56a499 100644 --- a/server/jellyfin/README.md +++ b/server/jellyfin/README.md @@ -58,6 +58,8 @@ query param — all forms are accepted, matching what different clients do). `/auth/login` (`AuthRequestLimit`/`AuthWindowLength`), since it's an unauthenticated brute-force surface. +Access tokens do not expire, matching real Jellyfin. They are revoked by a password change, which bumps the user's token epoch. + ### Public user list (login picker) `GET /Users/Public` lets a client render a login user-picker (tap a user, then just type the diff --git a/server/jellyfin/auth.go b/server/jellyfin/auth.go index 062ac6458..e7070d341 100644 --- a/server/jellyfin/auth.go +++ b/server/jellyfin/auth.go @@ -36,7 +36,7 @@ func (api *Router) authenticateByName(w http.ResponseWriter, r *http.Request) { log.Error(ctx, "Jellyfin API: could not update last login date", "username", body.Username, err) } - token, err := auth.CreateToken(usr) + token, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) if err != nil { api.internalError(w, r, err) return diff --git a/server/jellyfin/e2e/auth_test.go b/server/jellyfin/e2e/auth_test.go index 806b0e5e7..156e79ce9 100644 --- a/server/jellyfin/e2e/auth_test.go +++ b/server/jellyfin/e2e/auth_test.go @@ -6,6 +6,7 @@ import ( "github.com/navidrome/navidrome/conf" "github.com/navidrome/navidrome/conf/configtest" + "github.com/navidrome/navidrome/core/auth" "github.com/navidrome/navidrome/server/jellyfin/dto" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" @@ -61,6 +62,42 @@ var _ = Describe("Authentication", func() { It("rejects a malformed body", func() { Expect(rawReq("POST", "/Users/AuthenticateByName", "not json").Code).To(Equal(http.StatusBadRequest)) }) + + It("mints a non-expiring token scoped to the Jellyfin audience", func() { + w := authenticate("admin", "password") + var res dto.AuthenticationResult + parseInto(w, &res) + + claims, err := auth.Validate(res.AccessToken) + Expect(err).ToNot(HaveOccurred()) + Expect(claims.ExpiresAt.IsZero()).To(BeTrue()) + Expect(claims.Audience).To(Equal([]string{"jellyfin"})) + Expect(claims.Subject).To(Equal("admin")) + }) + + It("revokes an already-issued token when the user's epoch is bumped", func() { + w := authenticate("admin", "password") + var res dto.AuthenticationResult + parseInto(w, &res) + + r := httptest.NewRequest("GET", "/Users/Me", nil) + r.Header.Set("X-Emby-Token", res.AccessToken) + pw := httptest.NewRecorder() + router.ServeHTTP(pw, r) + Expect(pw.Code).To(Equal(http.StatusOK)) + + // A real password change through the repository, which is what revokes in production. + admin, err := ds.User(ctx).Get(testID("admin-1")) + Expect(err).ToNot(HaveOccurred()) + admin.NewPassword = "rotated" + Expect(ds.User(ctx).Put(admin)).To(Succeed()) + + r = httptest.NewRequest("GET", "/Users/Me", nil) + r.Header.Set("X-Emby-Token", res.AccessToken) + pw = httptest.NewRecorder() + router.ServeHTTP(pw, r) + Expect(pw.Code).To(Equal(http.StatusUnauthorized)) + }) }) Describe("GET /Users/Public", func() { diff --git a/server/jellyfin/middlewares.go b/server/jellyfin/middlewares.go index c90f9c088..0ae4f6071 100644 --- a/server/jellyfin/middlewares.go +++ b/server/jellyfin/middlewares.go @@ -167,6 +167,10 @@ func (api *Router) userFromToken(r *http.Request) (model.User, bool) { log.Warn(r.Context(), "Jellyfin API: token subject not found", "user", claims.Subject, err) return model.User{}, false } + if err := auth.CheckClaims(claims, *usr, auth.AudienceJellyfin); err != nil { + log.Warn(r.Context(), "Jellyfin API: rejected token", "user", claims.Subject, err) + return model.User{}, false + } return *usr, true } diff --git a/server/jellyfin/middlewares_test.go b/server/jellyfin/middlewares_test.go index b17b9a4ec..a3b88799b 100644 --- a/server/jellyfin/middlewares_test.go +++ b/server/jellyfin/middlewares_test.go @@ -95,6 +95,52 @@ var _ = Describe("authenticate middleware", func() { api.authenticate(next).ServeHTTP(w, r) Expect(w.Code).To(Equal(http.StatusUnauthorized)) }) + + Context("token scoping and revocation", func() { + var usr *model.User + + BeforeEach(func() { + ur := ds.User(context.Background()).(*tests.MockedUserRepo) + usr = &model.User{ID: testID("u2"), UserName: "bob", NewPassword: "secret", TokenEpoch: 3} + Expect(ur.Put(usr)).To(Succeed()) + }) + + serve := func(token string) *httptest.ResponseRecorder { + next := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }) + w := httptest.NewRecorder() + r := httptest.NewRequest("GET", "/Items", nil) + r.Header.Set("X-Emby-Token", token) + api.authenticate(next).ServeHTTP(w, r) + return w + } + + It("accepts a jellyfin-scoped token with the current epoch", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + Expect(serve(tokenStr).Code).To(Equal(http.StatusOK)) + }) + + It("rejects a token whose epoch is stale", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + usr.TokenEpoch = 4 + Expect(serve(tokenStr).Code).To(Equal(http.StatusUnauthorized)) + }) + + It("rejects a token minted for another API", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceNative) + Expect(err).ToNot(HaveOccurred()) + Expect(serve(tokenStr).Code).To(Equal(http.StatusUnauthorized)) + }) + + It("still accepts an unscoped session token", func() { + tokenStr, err := auth.CreateToken(usr) + Expect(err).ToNot(HaveOccurred()) + Expect(serve(tokenStr).Code).To(Equal(http.StatusOK)) + }) + }) }) var _ = Describe("withPlayer middleware", func() { diff --git a/server/nativeapi/user_password_token_refresh_test.go b/server/nativeapi/user_password_token_refresh_test.go new file mode 100644 index 000000000..32f4b13cb --- /dev/null +++ b/server/nativeapi/user_password_token_refresh_test.go @@ -0,0 +1,80 @@ +package nativeapi + +import ( + "bytes" + "context" + "encoding/json" + "net/http" + "net/http/httptest" + "path/filepath" + "time" + + "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/conf/configtest" + "github.com/navidrome/navidrome/consts" + "github.com/navidrome/navidrome/core" + "github.com/navidrome/navidrome/core/auth" + "github.com/navidrome/navidrome/db" + "github.com/navidrome/navidrome/model" + "github.com/navidrome/navidrome/persistence" + "github.com/navidrome/navidrome/server" + "github.com/navidrome/navidrome/tests" + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +type noopPluginUnloader struct{} + +func (noopPluginUnloader) UnloadDisabledPlugins(context.Context) {} + +// Pins that the token-epoch handoff survives a real request through the real middleware chain. +var _ = Describe("PUT /user/{id}: token refresh on self password change", func() { + var ds model.DataStore + var router http.Handler + + BeforeEach(func() { + // db.Db() is a process-wide singleton that this DeferCleanup closes for the whole binary; keep this the only real-DB spec in this package. + DeferCleanup(configtest.SetupConfig()) + conf.Server.EnableUserEditing = true + conf.Server.EnableSharing = false + conf.Server.SessionTimeout = time.Hour + conf.Server.DbPath = filepath.Join(GinkgoT().TempDir(), "nativeapi-user-refresh.db") + "?_journal_mode=WAL" + DeferCleanup(db.Init(GinkgoT().Context())) + + ds = &tests.MockDataStore{RealDS: persistence.New(db.Db())} + auth.Init(ds) + + userService := core.NewUser(ds, noopPluginUnloader{}) + nativeRouter := New(ds, nil, nil, nil, tests.NewMockLibraryService(), userService, nil, nil, nil) + router = server.JWTVerifier(nativeRouter) + }) + + It("carries the bumped epoch in the refreshed token, not the epoch the token was minted with", func() { + usr := model.User{UserName: "selfchanger", Name: "Self Changer", NewPassword: "old-password"} + Expect(ds.User(GinkgoT().Context()).Put(&usr)).To(Succeed()) + + token, err := auth.CreateToken(&usr) + Expect(err).ToNot(HaveOccurred()) + + body, _ := json.Marshal(map[string]any{ + "userName": usr.UserName, + "name": usr.Name, + "currentPassword": "old-password", + "password": "new-password", + }) + req := createAuthenticatedRequest(http.MethodPut, "/user/"+usr.ID, bytes.NewBuffer(body), token) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + Expect(w.Code).To(Equal(http.StatusOK), w.Body.String()) + + refreshed := w.Header().Get(consts.UIAuthorizationHeader) + Expect(refreshed).ToNot(BeEmpty()) + claims, err := auth.Validate(refreshed) + Expect(err).ToNot(HaveOccurred()) + + reloaded, err := ds.User(GinkgoT().Context()).Get(usr.ID) + Expect(err).ToNot(HaveOccurred()) + Expect(reloaded.TokenEpoch).To(Equal(1)) + Expect(claims.Epoch).To(Equal(reloaded.TokenEpoch)) + }) +}) diff --git a/server/subsonic/middlewares.go b/server/subsonic/middlewares.go index 837852d18..6dfa2263f 100644 --- a/server/subsonic/middlewares.go +++ b/server/subsonic/middlewares.go @@ -178,7 +178,9 @@ func validateCredentials(user *model.User, pass, token, salt, jwt string) error switch { case jwt != "": claims, err := auth.Validate(jwt) - valid = err == nil && claims.Subject == user.UserName + valid = err == nil && + claims.Subject == user.UserName && + auth.CheckClaims(claims, *user, auth.AudienceSubsonic) == nil case pass != "": if strings.HasPrefix(pass, "enc:") { if dec, err := hex.DecodeString(pass[4:]); err == nil { diff --git a/server/subsonic/middlewares_test.go b/server/subsonic/middlewares_test.go index 3f8c07a56..cb34b92e7 100644 --- a/server/subsonic/middlewares_test.go +++ b/server/subsonic/middlewares_test.go @@ -470,6 +470,7 @@ var _ = Describe("Middlewares", func() { var validToken string BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) conf.Server.SessionTimeout = time.Minute auth.Init(ds) @@ -499,6 +500,36 @@ var _ = Describe("Middlewares", func() { Expect(err).To(MatchError(model.ErrInvalidAuth)) }) }) + + Context("JWT credentials", func() { + var usr *model.User + + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + conf.Server.SessionTimeout = time.Minute + auth.Init(ds) + usr = &model.User{ID: "u1", UserName: "johndoe", TokenEpoch: 1} + }) + + It("accepts an unscoped session token", func() { + tokenStr, err := auth.CreateToken(usr) + Expect(err).ToNot(HaveOccurred()) + Expect(validateCredentials(usr, "", "", "", tokenStr)).To(Succeed()) + }) + + It("rejects a jellyfin-scoped token", func() { + tokenStr, err := auth.CreateAPIToken(usr, auth.AudienceJellyfin) + Expect(err).ToNot(HaveOccurred()) + Expect(validateCredentials(usr, "", "", "", tokenStr)).To(MatchError(model.ErrInvalidAuth)) + }) + + It("rejects a token with a stale epoch", func() { + tokenStr, err := auth.CreateToken(usr) + Expect(err).ToNot(HaveOccurred()) + usr.TokenEpoch = 2 + Expect(validateCredentials(usr, "", "", "", tokenStr)).To(MatchError(model.ErrInvalidAuth)) + }) + }) }) }) From 3cb9850872f45a2cee0ca540b7c8d141c631f222 Mon Sep 17 00:00:00 2001 From: Deluan Date: Sat, 22 Aug 2026 21:38:54 -0400 Subject: [PATCH 10/13] feat(artwork): extend stale absent age to 30 days and update test formatting Signed-off-by: Deluan --- cmd/artwork_test.go | 3 ++- core/artwork/housekeeping.go | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/cmd/artwork_test.go b/cmd/artwork_test.go index cc63ed86f..f17206aaa 100644 --- a/cmd/artwork_test.go +++ b/cmd/artwork_test.go @@ -3,6 +3,7 @@ package cmd import ( "context" "errors" + "fmt" "io" "strings" "time" @@ -910,7 +911,7 @@ var _ = Describe("formatStatus", func() { }) It("states the recheck window and the drip rate the absent counts are bucketed against", func() { - Expect(formatStatus(rep)).To(ContainSubstring("168h")) + Expect(formatStatus(rep)).To(ContainSubstring(fmt.Sprintf("%gh", artwork.StaleAbsentAge.Hours()))) Expect(formatStatus(rep)).To(ContainSubstring("100 per kind per hour")) }) diff --git a/core/artwork/housekeeping.go b/core/artwork/housekeeping.go index 9456a5584..ce98e2a03 100644 --- a/core/artwork/housekeeping.go +++ b/core/artwork/housekeeping.go @@ -18,7 +18,7 @@ import ( ) // StaleAbsentAge is how long an absent state is trusted before a recheck retries it. -const StaleAbsentAge = 7 * 24 * time.Hour +const StaleAbsentAge = 30 * 24 * time.Hour // StaleAbsentRecheckBatch caps how many absent states each hourly tick re-queues per kind, // oldest first, so external agents see a flat drip instead of a daily burst. From fc9d93d22ac7e175223a48e0a84a6e5fe7c24c42 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Sat, 22 Aug 2026 22:02:25 -0400 Subject: [PATCH 11/13] fix(plugins): read the loaded plugin from a local, not the shared map (#6014) Plugins load concurrently through an errgroup. loadPluginWithConfig wrote m.plugins under m.mu but read it back unlocked to pass to callPluginInit, so one goroutine's write raced another's read. Caught by -race on master (run 32608293134): all 640 specs passed, the job failed only on the race. Capture the pointer while holding the lock and use the local. Holding m.mu across callPluginInit would be wrong, since that runs arbitrary plugin code. --- plugins/manager_loader.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/plugins/manager_loader.go b/plugins/manager_loader.go index e5e3dbfc0..46da56396 100644 --- a/plugins/manager_loader.go +++ b/plugins/manager_loader.go @@ -434,8 +434,7 @@ func (m *Manager) loadPluginWithConfig(p *model.Plugin) error { return fmt.Errorf("manifest validation: %w", err) } - m.mu.Lock() - m.plugins[p.ID] = &plugin{ + loadedPlugin := &plugin{ name: p.ID, path: p.Path, manifest: pkg.Manifest, @@ -449,13 +448,16 @@ func (m *Manager) loadPluginWithConfig(p *model.Plugin) error { fsConfig: fsConfig, lyricsSem: make(chan struct{}, maxConcurrentLyricsCalls), } + m.mu.Lock() + m.plugins[p.ID] = loadedPlugin m.mu.Unlock() loaded = true // Init is the plugin's first chance to run arbitrary code: open sockets, create task queues, // schedule work. Only a caller that already intends to reach the network asks for it. + // Use the local: loads run concurrently, so reading the map back here would race the writes. if m.transient == nil || m.transient.runInit { - callPluginInit(ctx, m.plugins[p.ID]) + callPluginInit(ctx, loadedPlugin) } return nil From 3e55886195bb125f5c1fda1a1ded39f319e96662 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Sun, 23 Aug 2026 14:31:37 -0400 Subject: [PATCH 12/13] feat: add optional natural sort order for names and titles (#6015) * feat: add optional natural sort order for names and titles Album, artist, song and playlist lists sort with a plain text comparison, so names containing numbers come out as "Foo 1, Foo 10, Foo 2" instead of "Foo 1, Foo 2, Foo 10" (issue #4554). Adds an EnableNaturalSorting option, default off, that switches those sorts to a NATSORT collation registered on every connection and backed by natural.CompareFold. natural.Compare gained an ASCII case-folding variant because it replaces 'collate nocase': sort_* columns hold raw tag values, so without folding they would order uppercase before lowercase. Applying the collation only inside mapSortOrder would have missed the default configuration entirely, since that mapper runs only when PreferSortTags is on. setSortMappings now also rewrites the order_* columns when natural sorting is enabled on its own. Sorts over plain text columns that are not order_* columns (playlist.name, album.name, media_file.title, playlist_tracks title) are wrapped explicitly, and qualified with their table because 'user' is joined and also has a 'name' column. The option defaults to off because the collation cannot use the existing indexes: measured on a synthetic 110k album library, the first page of an album-by-name listing goes from 0.03ms to 14ms. Indexing the expression was rejected outright - an index declared with a custom collation makes the whole database unreadable to any tool that does not register it, including the sqlite3 CLI, which fails even on 'select count(*)' and 'pragma integrity_check'. * refactor: fold the two sort-order mappers into one mapSortOrder and mapNaturalOrder shared the same regex and loop, differing only in the expression they substituted, and setSortMappings picked between them with a two-case switch. mapSortOrder now selects the column shape itself and defers to collatedSort for the collation, so the 'collate' clause is emitted in one place and the caller only has to decide whether any mapping is needed at all. The mapper tests were three near-identical cases that each hard-coded one flag combination; they are now a DescribeTable covering all four combinations of PreferSortTags and EnableNaturalSorting, which the previous set did not. The album sorting specs collapse the same way. Behavior is unchanged. * fix: leave plain sort columns alone when natural sorting is off collatedSort wrapped its column unconditionally, so the tiebreakers added for plain text columns picked up 'collate nocase' even with EnableNaturalSorting off. media_file.title, the playlist_tracks alias of it, and user.user_name are all declared without a collation, so a default install would have silently switched those tiebreaks from binary to case-insensitive ordering. Only playlist.name was already NOCASE and genuinely unaffected. The helper is now naturalSort and returns the column untouched unless the option is on, so the default path keeps the collation each column was declared with. sortCollation had a single remaining caller and folded into mapSortOrder. Tests: the CompareFold table body was a verbatim copy of the Compare one, so both now go through one expectOrder helper, and the album sorting specs inline two single-use closures. * fix(natural): defer the leading-zero tie-break to keep ordering transitive Compare applied the padding difference between numerically equal digit runs only when one side ended at the digit boundary, and ignored it mid-string. That made the relation intransitive: CompareFold("1","1a") < 0 and CompareFold("1a","01a") == 0, yet CompareFold("1","01a") > 0. SQLite requires a collating function to be transitive and leaves ORDER BY undefined otherwise, so registering this as NATSORT was not safe. Reproduced with the real driver on three artist names that occur in practice - "3", "3 doors down" and "03 greedo" - where paging one row at a time returned "03 greedo" twice and dropped "3" entirely. The padding difference is now carried as a tie-break that is applied only when the strings are otherwise equal, which restores transitivity while keeping the documented intent (a01 < a1, a0 < a00). Three existing entries changed: each asserted that two distinct strings compare equal, which was the same defect seen from the other side. Found by the Codex review on #6015. --- conf/configuration.go | 2 + db/db.go | 10 ++- persistence/album_repository.go | 2 +- persistence/album_repository_test.go | 39 +++++++++ persistence/helpers.go | 29 +++++-- persistence/helpers_test.go | 55 ++++++++++--- persistence/mediafile_repository.go | 2 +- persistence/playlist_repository.go | 3 +- persistence/playlist_repository_test.go | 35 ++++++++ persistence/playlist_track_repository.go | 2 +- persistence/sql_base_repository.go | 5 +- utils/natural/natural.go | 51 ++++++++---- utils/natural/natural_test.go | 100 ++++++++++++++++++++--- 13 files changed, 284 insertions(+), 51 deletions(-) diff --git a/conf/configuration.go b/conf/configuration.go index fbbaaf252..df22e4ae2 100644 --- a/conf/configuration.go +++ b/conf/configuration.go @@ -73,6 +73,7 @@ type configOptions struct { Matcher matcherOptions `json:",omitzero"` RecentlyAddedByModTime bool PreferSortTags bool + EnableNaturalSorting bool IgnoredArticles string IndexGroups string FFmpegPath string @@ -973,6 +974,7 @@ func setViperDefaults() { viper.SetDefault("matcher.fuzzythreshold", 85) viper.SetDefault("recentlyaddedbymodtime", false) viper.SetDefault("prefersorttags", false) + viper.SetDefault("enablenaturalsorting", false) viper.SetDefault("ignoredarticles", "The El La Los Las Le Les Os As O A") viper.SetDefault("indexgroups", "A B C D E F G H I J K L M N O P Q R S T U V W X-Z(XYZ) [Unknown]([)") viper.SetDefault("ffmpegpath", "") diff --git a/db/db.go b/db/db.go index 11a05b456..a325dd3f5 100644 --- a/db/db.go +++ b/db/db.go @@ -13,10 +13,15 @@ import ( _ "github.com/navidrome/navidrome/db/migrations" "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/utils/hasher" + "github.com/navidrome/navidrome/utils/natural" "github.com/navidrome/navidrome/utils/singleton" "github.com/pressly/goose/v3" ) +// NaturalCollation sorts embedded numbers by value. It is registered on every +// connection, but only referenced when conf.Server.EnableNaturalSorting is on. +const NaturalCollation = "NATSORT" + var ( Dialect = "sqlite3" Driver = Dialect + "_custom" @@ -32,7 +37,10 @@ func Db() *sql.DB { return singleton.GetInstance(func() *sql.DB { sql.Register(Driver, &sqlite3.SQLiteDriver{ ConnectHook: func(conn *sqlite3.SQLiteConn) error { - return conn.RegisterFunc("SEEDEDRAND", hasher.HashFunc(), false) + if err := conn.RegisterFunc("SEEDEDRAND", hasher.HashFunc(), false); err != nil { + return err + } + return conn.RegisterCollation(NaturalCollation, natural.CompareFold) }, }) Path = conf.Server.DbPath diff --git a/persistence/album_repository.go b/persistence/album_repository.go index 5d7aad22e..7ac875a51 100644 --- a/persistence/album_repository.go +++ b/persistence/album_repository.go @@ -113,7 +113,7 @@ func NewAlbumRepository(ctx context.Context, db dbx.Builder) model.AlbumReposito "artist": "compilation, order_album_artist_name, order_album_name", "album_artist": "compilation, order_album_artist_name, order_album_name", // TODO Rename this to just year (or date) - "max_year": "coalesce(nullif(original_date,''), cast(max_year as text)), release_date, name", + "max_year": "coalesce(nullif(original_date,''), cast(max_year as text)), release_date, " + naturalSort("album.name"), "random": "random", "recently_added": recentlyAddedSort(), "starred_at": "starred, starred_at", diff --git a/persistence/album_repository_test.go b/persistence/album_repository_test.go index f6768768d..0fb680cff 100644 --- a/persistence/album_repository_test.go +++ b/persistence/album_repository_test.go @@ -10,6 +10,7 @@ import ( "github.com/Masterminds/squirrel" "github.com/deluan/rest" "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/conf/configtest" "github.com/navidrome/navidrome/consts" "github.com/navidrome/navidrome/model" "github.com/navidrome/navidrome/model/id" @@ -38,6 +39,44 @@ var _ = Describe("AlbumRepository", func() { albumRepo = NewAlbumRepository(ctx, GetDBXBuilder()).(*albumRepository) }) + Describe("natural sorting", func() { + var ids []string + + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + ids = nil + for _, n := range []string{"foo 1", "foo 10", "foo 2", "foo 20", "foo 3"} { + aid := "nat-" + n + ids = append(ids, aid) + Expect(albumRepo.Put(&model.Album{ + ID: aid, LibraryID: 1, Name: n, OrderAlbumName: n, + })).To(Succeed()) + } + DeferCleanup(func() { + _, _ = albumRepo.executeSQL(squirrel.Delete("album").Where(squirrel.Eq{"id": ids})) + }) + }) + + DescribeTable("sorts albums by name", + func(naturalSorting, preferSortTags bool, expected []string) { + conf.Server.EnableNaturalSorting = naturalSorting + conf.Server.PreferSortTags = preferSortTags + albumRepo = NewAlbumRepository(ctx, GetDBXBuilder()).(*albumRepository) + albums, err := albumRepo.GetAll(model.QueryOptions{ + Sort: "name", Filters: squirrel.Eq{"album.id": ids}, + }) + Expect(err).ToNot(HaveOccurred()) + Expect(slice.Map(albums, func(a model.Album) string { return a.Name })).To(Equal(expected)) + }, + Entry("lexicographically by default", false, false, + []string{"foo 1", "foo 10", "foo 2", "foo 20", "foo 3"}), + Entry("by number value when natural sorting is enabled", true, false, + []string{"foo 1", "foo 2", "foo 3", "foo 10", "foo 20"}), + Entry("by number value with sort tags preferred too", true, true, + []string{"foo 1", "foo 2", "foo 3", "foo 10", "foo 20"}), + ) + }) + Describe("Get", func() { var Get = func(id string) (*model.Album, error) { album, err := albumRepo.Get(id) diff --git a/persistence/helpers.go b/persistence/helpers.go index fd6a9a4cd..1da31cf02 100644 --- a/persistence/helpers.go +++ b/persistence/helpers.go @@ -9,6 +9,8 @@ import ( "github.com/Masterminds/squirrel" "github.com/fatih/structs" + "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/db" ) type PostMapper interface { @@ -82,11 +84,28 @@ func (e existsCond) ToSql() (string, []any, error) { var sortOrderRegex = regexp.MustCompile(`order_([a-z_]+)`) -// Convert the order_* columns to an expression using sort_* columns. Example: -// sort_album_name -> (coalesce(nullif(sort_album_name,”),order_album_name) collate nocase) +// naturalSort makes a plain text column sort numbers by value, leaving it alone +// otherwise so it keeps its declared collation. Parens guard buildSortOrder's space split. +func naturalSort(col string) string { + if !conf.Server.EnableNaturalSorting { + return col + } + return fmt.Sprintf("(%s collate %s)", col, db.NaturalCollation) +} + +// Convert the order_* columns to a collated sort expression, falling back to the +// sort_* column when those are preferred. Example: +// order_album_name -> (coalesce(nullif(sort_album_name,”),order_album_name) collate nocase) // It finds order column names anywhere in the substring func mapSortOrder(tableName, order string) string { - order = strings.ToLower(order) - repl := fmt.Sprintf("(coalesce(nullif(%[1]s.sort_$1,''),%[1]s.order_$1) collate nocase)", tableName) - return sortOrderRegex.ReplaceAllString(order, repl) + col := tableName + ".order_$1" + if conf.Server.PreferSortTags { + col = fmt.Sprintf("coalesce(nullif(%[1]s.sort_$1,''),%[1]s.order_$1)", tableName) + } + collation := "nocase" + if conf.Server.EnableNaturalSorting { + collation = db.NaturalCollation + } + repl := fmt.Sprintf("(%s collate %s)", col, collation) + return sortOrderRegex.ReplaceAllString(strings.ToLower(order), repl) } diff --git a/persistence/helpers_test.go b/persistence/helpers_test.go index 85893ef55..3019609f3 100644 --- a/persistence/helpers_test.go +++ b/persistence/helpers_test.go @@ -4,6 +4,8 @@ import ( "time" "github.com/Masterminds/squirrel" + "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/conf/configtest" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" ) @@ -85,22 +87,51 @@ var _ = Describe("Helpers", func() { }) Describe("mapSortOrder", func() { + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + }) + It("does not change the sort string if there are no order columns", func() { - sort := "album_name asc" - mapped := mapSortOrder("album", sort) - Expect(mapped).To(Equal(sort)) - }) - It("changes order columns to sort expression", func() { - sort := "ORDER_ALBUM_NAME asc" - mapped := mapSortOrder("album", sort) - Expect(mapped).To(Equal(`(coalesce(nullif(album.sort_album_name,''),album.order_album_name)` + - ` collate nocase) asc`)) + Expect(mapSortOrder("album", "album_name asc")).To(Equal("album_name asc")) }) + + DescribeTable("maps order columns to a collated expression", + func(preferSortTags, naturalSorting bool, expected string) { + conf.Server.PreferSortTags = preferSortTags + conf.Server.EnableNaturalSorting = naturalSorting + Expect(mapSortOrder("album", "ORDER_ALBUM_NAME asc")).To(Equal(expected)) + }, + Entry("qualified column", false, false, + "(album.order_album_name collate nocase) asc"), + Entry("natural collation", false, true, + "(album.order_album_name collate NATSORT) asc"), + Entry("sort tags preferred", true, false, + `(coalesce(nullif(album.sort_album_name,''),album.order_album_name) collate nocase) asc`), + Entry("sort tags preferred, natural collation", true, true, + `(coalesce(nullif(album.sort_album_name,''),album.order_album_name) collate NATSORT) asc`), + ) + It("changes multiple order columns to sort expressions", func() { + conf.Server.PreferSortTags = true sort := "compilation, order_title asc, order_album_artist_name desc, year desc" - mapped := mapSortOrder("album", sort) - Expect(mapped).To(Equal(`compilation, (coalesce(nullif(album.sort_title,''),album.order_title) collate nocase) asc,` + - ` (coalesce(nullif(album.sort_album_artist_name,''),album.order_album_artist_name) collate nocase) desc, year desc`)) + Expect(mapSortOrder("album", sort)).To(Equal( + `compilation, (coalesce(nullif(album.sort_title,''),album.order_title) collate nocase) asc,` + + ` (coalesce(nullif(album.sort_album_artist_name,''),album.order_album_artist_name) collate nocase) desc, year desc`)) + }) + }) + + Describe("naturalSort", func() { + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + }) + + It("leaves the column alone by default, keeping its declared collation", func() { + Expect(naturalSort("media_file.title")).To(Equal("media_file.title")) + }) + + It("applies the natural collation when enabled", func() { + conf.Server.EnableNaturalSorting = true + Expect(naturalSort("media_file.title")).To(Equal("(media_file.title collate NATSORT)")) }) }) }) diff --git a/persistence/mediafile_repository.go b/persistence/mediafile_repository.go index 8146cba2f..320b95ef2 100644 --- a/persistence/mediafile_repository.go +++ b/persistence/mediafile_repository.go @@ -86,7 +86,7 @@ func NewMediaFileRepository(ctx context.Context, db dbx.Builder) model.MediaFile "title": "order_title", "artist": "order_artist_name, order_album_name, release_date, disc_number, track_number", "album_artist": "order_album_artist_name, order_album_name, release_date, disc_number, track_number", - "album": "order_album_name, album_id, disc_number, track_number, order_artist_name, title", + "album": "order_album_name, album_id, disc_number, track_number, order_artist_name, " + naturalSort("media_file.title"), "random": "random", "created_at": "media_file.created_at", "recently_added": mediaFileRecentlyAddedSort(), diff --git a/persistence/playlist_repository.go b/persistence/playlist_repository.go index cf54c6d5a..505f23440 100644 --- a/persistence/playlist_repository.go +++ b/persistence/playlist_repository.go @@ -60,7 +60,8 @@ func NewPlaylistRepository(ctx context.Context, db dbx.Builder) model.PlaylistRe "starred": annotationBoolFilter("starred"), }) r.setSortMappings(map[string]string{ - "owner_name": "owner_name", + "name": naturalSort("playlist.name"), + "owner_name": naturalSort("owner_name"), }) return r } diff --git a/persistence/playlist_repository_test.go b/persistence/playlist_repository_test.go index 9697e6fff..f60b4e7ca 100644 --- a/persistence/playlist_repository_test.go +++ b/persistence/playlist_repository_test.go @@ -5,6 +5,8 @@ import ( "github.com/Masterminds/squirrel" "github.com/deluan/rest" + "github.com/navidrome/navidrome/conf" + "github.com/navidrome/navidrome/conf/configtest" "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" "github.com/navidrome/navidrome/model/criteria" @@ -24,6 +26,39 @@ var _ = Describe("PlaylistRepository", func() { repo = NewPlaylistRepository(ctx, GetDBXBuilder()) }) + Describe("natural sorting", func() { + var ids []string + + BeforeEach(func() { + DeferCleanup(configtest.SetupConfig()) + conf.Server.EnableNaturalSorting = true + ctx := log.NewContext(GinkgoT().Context()) + ctx = request.WithUser(ctx, model.User{ID: "userid", UserName: "userid", IsAdmin: true}) + repo = NewPlaylistRepository(ctx, GetDBXBuilder()) + + ids = nil + for _, n := range []string{"mix 1", "mix 10", "mix 2"} { + pls := model.Playlist{Name: n, OwnerID: "userid"} + Expect(repo.Put(&pls)).To(Succeed()) + ids = append(ids, pls.ID) + } + DeferCleanup(func() { + for _, id := range ids { + _ = repo.Delete(id) + } + }) + }) + + It("sorts playlist names by number value", func() { + all, err := repo.GetAll(model.QueryOptions{ + Sort: "name", Filters: squirrel.Eq{"playlist.id": ids}, + }) + Expect(err).ToNot(HaveOccurred()) + Expect(slice.Map(all, func(p model.Playlist) string { return p.Name })).To( + Equal([]string{"mix 1", "mix 2", "mix 10"})) + }) + }) + Describe("Count", func() { It("returns the number of playlists in the DB", func() { Expect(repo.CountAll()).To(Equal(int64(2))) diff --git a/persistence/playlist_track_repository.go b/persistence/playlist_track_repository.go index a5e1975fd..cf1b8f3fa 100644 --- a/persistence/playlist_track_repository.go +++ b/persistence/playlist_track_repository.go @@ -56,7 +56,7 @@ func (r *playlistRepository) Tracks(playlistId string, refreshSmartPlaylist bool "id": "playlist_tracks.id", "artist": "order_artist_name", "album_artist": "order_album_artist_name", - "album": "order_album_name, album_id, disc_number, track_number, order_artist_name, title", + "album": "order_album_name, album_id, disc_number, track_number, order_artist_name, " + naturalSort("f.title"), "title": "order_title", "random": "random()", // To make sure these fields will be whitelisted diff --git a/persistence/sql_base_repository.go b/persistence/sql_base_repository.go index d4cf9b456..f49e1bc4f 100644 --- a/persistence/sql_base_repository.go +++ b/persistence/sql_base_repository.go @@ -113,10 +113,9 @@ func (r *sqlRepository) setSortMappings(mappings map[string]string, tableName .. if len(tableName) > 0 { tn = tableName[0] } - if conf.Server.PreferSortTags { + if conf.Server.PreferSortTags || conf.Server.EnableNaturalSorting { for k, v := range mappings { - v = mapSortOrder(tn, v) - mappings[k] = v + mappings[k] = mapSortOrder(tn, v) } } r.sortMappings = mappings diff --git a/utils/natural/natural.go b/utils/natural/natural.go index fa0800e1d..d8ddcc405 100644 --- a/utils/natural/natural.go +++ b/utils/natural/natural.go @@ -10,15 +10,32 @@ import "strings" // or a positive value if a > b using natural sort ordering. // // When two numeric segments are numerically equal (e.g. "01" vs "1"), -// comparison continues with the remaining suffixes. If one or both -// strings end at the digit boundary, the raw strings are compared -// lexically, which makes leading zeros significant as a tie-breaker -// (e.g. "a01" < "a1", "a0" < "a00"). +// comparison continues with the remaining suffixes, and the padding +// difference is kept as a final tie-breaker that only decides strings +// that are otherwise equal (e.g. "a01" < "a1", "a0" < "a00"). Deferring +// it that way is what keeps the ordering transitive, which SQLite +// requires of a collating function. func Compare(a, b string) int { + return compare(a, b, false) +} + +// CompareFold is Compare with ASCII case folding, matching SQLite's NOCASE +// collation: only A-Z fold, bytes >= 0x80 are compared as-is. +func CompareFold(a, b string) int { + return compare(a, b, true) +} + +func compare(a, b string, fold bool) int { ia, ib := 0, 0 + // Set when two runs are numerically equal but differently padded. Applying it + // immediately would break transitivity, so it only decides otherwise-equal strings. + padTie := 0 for ia < len(a) && ib < len(b) { ca, cb := a[ia], b[ib] da, db := isDigit(ca), isDigit(cb) + if fold { + ca, cb = lower(ca), lower(cb) + } switch { case da && db: @@ -35,17 +52,11 @@ func Compare(a, b string) int { if c := compareNumbers(a[ia:endA], b[ib:endB]); c != 0 { return c } - - // Numerically equal. If both sides have trailing data, continue - // comparing after the digit runs. Otherwise fall through to - // lexical comparison of the full remaining strings (which makes - // leading-zero differences significant as a tie-breaker). - if endA < len(a) && endB < len(b) { - ia = endA - ib = endB - continue + if t := strings.Compare(a[ia:endA], b[ib:endB]); t != 0 { + padTie = t } - return strings.Compare(a[ia:], b[ib:]) + ia = endA + ib = endB case da != db: return int(ca) - int(cb) default: @@ -56,7 +67,10 @@ func Compare(a, b string) int { ib++ } } - return (len(a) - ia) - (len(b) - ib) + if c := (len(a) - ia) - (len(b) - ib); c != 0 { + return c + } + return padTie } // compareNumbers compares two digit strings numerically. @@ -96,3 +110,10 @@ func stripZeros(s string) string { func isDigit(c byte) bool { return c >= '0' && c <= '9' } + +func lower(c byte) byte { + if c >= 'A' && c <= 'Z' { + return c + 'a' - 'A' + } + return c +} diff --git a/utils/natural/natural_test.go b/utils/natural/natural_test.go index 825a944c0..534885d40 100644 --- a/utils/natural/natural_test.go +++ b/utils/natural/natural_test.go @@ -13,17 +13,23 @@ func TestNatural(t *testing.T) { RunSpecs(t, "Natural Suite") } +// expectOrder asserts the sign of cmp(a, b) matches expected. +func expectOrder(cmp func(string, string) int, a, b string, expected int) { + result := cmp(a, b) + switch { + case expected < 0: + ExpectWithOffset(1, result).To(BeNumerically("<", 0), "expected %q < %q", a, b) + case expected > 0: + ExpectWithOffset(1, result).To(BeNumerically(">", 0), "expected %q > %q", a, b) + default: + ExpectWithOffset(1, result).To(Equal(0), "expected %q == %q", a, b) + } +} + var _ = Describe("Compare", func() { DescribeTable("returns correct ordering", func(a, b string, expected int) { - result := natural.Compare(a, b) - if expected < 0 { - Expect(result).To(BeNumerically("<", 0), "expected %q < %q", a, b) - } else if expected > 0 { - Expect(result).To(BeNumerically(">", 0), "expected %q > %q", a, b) - } else { - Expect(result).To(Equal(0), "expected %q == %q", a, b) - } + expectOrder(natural.Compare, a, b, expected) }, // Basic string ordering Entry("a < b", "a", "b", -1), @@ -67,7 +73,9 @@ var _ = Describe("Compare", func() { Entry("a00b00 < a0b1", "a00b00", "a0b1", -1), Entry("a00b00 > a0b0", "a00b00", "a0b0", 1), Entry("a00b01 > a0b00", "a00b01", "a0b00", 1), - Entry("a00b00 == a0b00", "a00b00", "a0b00", 0), + // Distinct strings must not compare equal: the padding difference in the first + // run decides once everything else matches. + Entry("a00b00 > a0b00", "a00b00", "a0b00", 1), // Leading zeros at end of string — lexical tie-break Entry("file01 < file1", "file01", "file1", -1), @@ -109,8 +117,78 @@ var _ = Describe("Compare", func() { Entry("large: equal", "a100000000000000000000", "a100000000000000000000", 0), Entry("large: leading zeros with trailing data", - "a00000000000000000000001x", "a1x", 0), + "a00000000000000000000001x", "a1x", -1), Entry("large: leading zeros with trailing data (2)", - "a099999999999999999999x", "a99999999999999999999x", 0), + "a099999999999999999999x", "a99999999999999999999x", -1), ) }) + +var _ = Describe("CompareFold", func() { + DescribeTable("orders case-insensitively", + func(a, b string, expected int) { + expectOrder(natural.CompareFold, a, b, expected) + }, + Entry("numbers compare numerically", "foo 2", "foo 10", -1), + Entry("numbers compare numerically, reversed", "foo 10", "foo 2", 1), + Entry("case is ignored", "apple 2", "Banana 10", -1), + Entry("case is ignored, reversed", "Banana 10", "apple 2", 1), + Entry("same word, different case, is equal", "ABC", "abc", 0), + Entry("case ignored while comparing numbers", "Vol 2", "vol 10", -1), + Entry("uppercase digits boundary", "Track9", "track10", -1), + Entry("empty vs empty", "", "", 0), + Entry("empty sorts first", "", "a", -1), + Entry("non-ASCII is left untouched", "café 2", "café 10", -1), + ) + + // SQLite requires a collating function to be transitive; if it is not, the behavior of + // ORDER BY is undefined and paginated queries can drop or duplicate rows. + It("is transitive, as a SQLite collation requires", func() { + var corpus []string + var build func(prefix string, depth int) + build = func(prefix string, depth int) { + if prefix != "" { + corpus = append(corpus, prefix) + } + if depth == 0 { + return + } + for _, c := range []string{"0", "1", "a"} { + build(prefix+c, depth-1) + } + } + build("", 3) + + sign := func(n int) int { + switch { + case n < 0: + return -1 + case n > 0: + return 1 + } + return 0 + } + for _, a := range corpus { + for _, b := range corpus { + ab := sign(natural.CompareFold(a, b)) + for _, c := range corpus { + bc := sign(natural.CompareFold(b, c)) + ac := sign(natural.CompareFold(a, c)) + if ab == 0 && bc == 0 { + Expect(ac).To(Equal(0), "%q==%q and %q==%q but %q vs %q is %d", a, b, b, c, a, c, ac) + } + if ab < 0 && bc < 0 { + Expect(ac).To(BeNumerically("<", 0), "%q<%q<%q but %q vs %q is %d", a, b, c, a, c, ac) + } + } + } + } + }) + + It("matches Compare when both sides are already lowercase", func() { + pairs := [][2]string{{"foo 2", "foo 10"}, {"a01", "a1"}, {"a", "aa"}, {"vol 3", "vol 3"}} + for _, p := range pairs { + Expect(natural.CompareFold(p[0], p[1])).To(Equal(natural.Compare(p[0], p[1])), + "CompareFold(%q,%q) should match Compare", p[0], p[1]) + } + }) +}) From 82b9a44a1f0ee94682f759086579df3a9ec4330e Mon Sep 17 00:00:00 2001 From: Deluan Date: Sun, 23 Aug 2026 15:24:44 -0400 Subject: [PATCH 13/13] fix(log): redact sensitive auth headers from request logs The trace-level request log dumps all headers as a JSON blob, but the redaction hook only had query-param patterns, so Authorization, X-Emby-Token, X-MediaBrowser-Token and X-Nd-Authorization leaked their tokens in plaintext. Add one pattern that blanks those header value arrays at the log sink. --- log/log.go | 4 ++++ log/log_test.go | 18 +++++++++++++++++- 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/log/log.go b/log/log.go index f7977c0fa..10cfb17b5 100644 --- a/log/log.go +++ b/log/log.go @@ -50,6 +50,10 @@ var redacted = &Hook{ // at a JWT's first '.' and leak its payload and signature. Case-insensitive with an // optional underscore: the API accepts api_key, apikey and ApiKey alike. "(?i)([^\\w]api_?key=)[^&\\s]+", + + // Sensitive request headers, logged as a JSON blob at trace level and never matched by the + // query-param patterns above. Blank the whole value array; values may hold escaped quotes. + `(?i)("(?:Authorization|X-Emby-Token|X-MediaBrowser-Token|X-Nd-Authorization)":\[")[^\]]*("\])`, }, } diff --git a/log/log_test.go b/log/log_test.go index f0e2e0eae..82207c672 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -2,7 +2,9 @@ package log import ( "context" + "encoding/json" "errors" + "net/http" "net/http/httptest" "testing" "time" @@ -92,7 +94,7 @@ var _ = Describe("Logger", func() { SetLogSourceLine(true) Error("A crash happened") // NOTE: This assertion breaks if the line number above changes - Expect(hook.LastEntry().Data[" source"]).To(ContainSubstring("/log/log_test.go:93")) + Expect(hook.LastEntry().Data[" source"]).To(ContainSubstring("/log/log_test.go:95")) Expect(hook.LastEntry().Message).To(Equal("A crash happened")) }) @@ -275,5 +277,19 @@ var _ = Describe("Logger", func() { Entry("ApiKey", "ApiKey"), Entry("APIKEY", "APIKEY"), ) + + It("redacts sensitive request headers in a logged header blob", func() { + h := http.Header{ + "Authorization": {`MediaBrowser Client="Finamp", Token="jwt-secret"`}, + "X-Emby-Token": {"emby-secret"}, + "X-Mediabrowser-Token": {"mb-secret"}, + "X-Nd-Authorization": {"Bearer nd-secret"}, + "User-Agent": {"Finamp/1.0"}, + } + blob, _ := json.Marshal(h) + got := Redact(string(blob)) + Expect(got).ToNot(ContainSubstring("secret")) + Expect(got).To(ContainSubstring(`"User-Agent":["Finamp/1.0"]`)) + }) }) })