diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index aae9320..5feea07 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -22,6 +22,51 @@ not submit anything, so there is no `submit` command. If you want to contribute timing you know, do it on [theintrodb.org](https://theintrodb.org), which is where contributions are made. +## "read the Plex library: ... timeout or cancel" + +The request that reads a library section did not come back inside +`plex.timeout_s` (20 seconds by default). + +The library read is paged, the first request included, so no single request asks +Plex to build a response proportional to the size of the section. On a build +older than that fix the first request was unpaged, and Plex answered it by +assembling the whole section at once — which on a section of tens of thousands +of episodes outlives any sensible timeout. Raising `plex.timeout_s` was the +workaround then: + +```toml +[plex] +timeout_s = 120 +``` + +It still works as a workaround, but it is no longer the fix, and it is worth +checking that the failing request is the section read before reaching for it: a +timeout on `/library/metadata/` is a different problem. + +`/identity` answering — which is what `setup` and `config check` report as `plex +server ok` — proves only that the URL reaches a Plex server. It is +unauthenticated, so it says nothing about the token, and it is a small answer, so +it says nothing about whether a library-sized one can be served. A rejected token +answers 401 immediately rather than timing out. + +## "could not read the shows behind the episodes; they keep their own ids" + +The run could not read the show behind each episode out of the Plex database, so +every episode keeps the provider id in its own row. That id is the episode's, and +TheIntroDB is asked for an episode by series id, so those lookups answer "media +not found" — the run spends its allowance on questions that cannot succeed, and +no TV markers are written. It is one WARN line and no other symptom, which is why +it is worth reading. + +The known cause was a library larger than SQLite's bound-parameter limit: the +walk bound one parameter per episode in a single statement, and above 32,766 +(`SQLITE_MAX_VARIABLE_NUMBER`) the statement failed outright with `too many SQL +variables`. The walk is chunked now, so a library of any size reads. + +The other causes are ordinary: no read access to the database, or episodes whose +show rows carry no provider ids. Check what `plex-sync library` prints for the +ids an item would be looked up with. + ## "no-provider-id" The item has no TMDb, IMDb or Tvdb id, so there is nothing to look it up by. diff --git a/internal/plexapi/client.go b/internal/plexapi/client.go index 009c8f2..c162a2b 100644 --- a/internal/plexapi/client.go +++ b/internal/plexapi/client.go @@ -242,8 +242,15 @@ func (c *Client) Items(ctx context.Context, sectionKeys []int) ([]model.LibraryI return out, nil } -// sectionItems reads one section, following Plex's container paging when the -// server reports more items than the first answer carried. +// sectionItems reads one section, a page at a time. +// +// Every request carries the container headers, the first one included. Plex +// answers an unpaged /all with the whole section, and on a library of tens of +// thousands of episodes that single answer is the request that never finishes: +// the server is still assembling it when the client's timeout expires, which +// surfaces as "timeout or cancel" on a library that is perfectly healthy. The +// first request is therefore bounded like every other one, so nothing ever asks +// Plex to build a response proportional to the library. func (c *Client) sectionItems(ctx context.Context, key, metadataType int, kind model.Kind) ([]model.LibraryItem, error) { path := "/library/sections/" + strconv.Itoa(key) + "/all" query := url.Values{ @@ -251,14 +258,9 @@ func (c *Client) sectionItems(ctx context.Context, key, metadataType int, kind m "includeGuids": {"1"}, } - ctr, err := c.container(ctx, path, query, nil) - if err != nil { - return nil, err - } - out := parseItems(*ctr, kind) - total := ctr.MediaContainer.Total.Int() - - for start := len(out); total > 0 && start < total; { + var out []model.LibraryItem + seen := make(map[int]bool) + for start := 0; ; { extra := map[string]string{ "X-Plex-Container-Start": strconv.Itoa(start), "X-Plex-Container-Size": strconv.Itoa(ItemWindow), @@ -268,11 +270,34 @@ func (c *Client) sectionItems(ctx context.Context, key, metadataType int, kind m return out, err } batch := parseItems(*page, kind) - if len(batch) == 0 { + + added := 0 + for _, it := range batch { + if seen[it.RatingKey] { + continue + } + seen[it.RatingKey] = true + out = append(out, it) + added++ + } + // A page with nothing new on it is a server repeating itself, which is + // what a server that ignores the offset would do forever. It is also + // what the walk ends on when the server reports no total: every + // iteration either adds an item or stops, and the library is finite, so + // the walk terminates without a page size to count against. + if added == 0 { break } - out = append(out, batch...) start += len(batch) + + // When the server reports a total, it is the only thing that says the + // walk is over. The page size deliberately is not: a server that caps + // its answer below the size asked for would otherwise end the walk on + // its first page and silently return a fraction of the library, which + // is worse than the timeout this paging exists to avoid. + if total := page.MediaContainer.Total.Int(); total > 0 && start >= total { + break + } } return out, nil } diff --git a/internal/plexapi/client_test.go b/internal/plexapi/client_test.go index ea4f0f3..55484ea 100644 --- a/internal/plexapi/client_test.go +++ b/internal/plexapi/client_test.go @@ -527,6 +527,197 @@ func TestItemsPaging(t *testing.T) { } } +// TestItemsFirstRequestIsPaged pins the fix for a library that times out before +// it is read: an unpaged /all makes Plex assemble the whole section, and on a +// section of tens of thousands of episodes that answer outlives the client's +// timeout. The fake below behaves the way a real server does — it answers an +// unpaged request slowly and a paged one immediately — so the old code fails +// here with "timeout or cancel" and this one does not. +func TestItemsFirstRequestIsPaged(t *testing.T) { + t.Parallel() + const total = 500 + + handler := func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/library/sections/7/all" { + writeJSON(w, http.StatusOK, + `{"MediaContainer":{"size":1,"Directory":[{"key":"7","title":"TV","type":"show"}]}}`) + return + } + raw := r.Header.Get("X-Plex-Container-Size") + if raw == "" { + // Unpaged: Plex builds the entire section, which is the request + // that never returns in time on a large library. + time.Sleep(2 * time.Second) + writeJSON(w, http.StatusOK, sectionPage(0, total, total)) + return + } + start, _ := strconv.Atoi(r.Header.Get("X-Plex-Container-Start")) + size, _ := strconv.Atoi(raw) + if size <= 0 { + size = ItemWindow + } + writeJSON(w, http.StatusOK, sectionPage(start, size, total)) + } + + f := newFake(t, handler) + hc := httpclient.New(300*time.Millisecond, false, UserAgent) + t.Cleanup(hc.Close) + c := NewClient(config.Plex{URL: f.srv.URL, Token: fakeToken}, hc) + + items, err := c.Items(context.Background(), nil) + if err != nil { + t.Fatalf("Items: %v (the first request was not paged)", err) + } + if len(items) != total { + t.Fatalf("Items = %d entries, want %d", len(items), total) + } + for i, it := range items { + if it.RatingKey != 900+i { + t.Fatalf("items[%d].RatingKey = %d, want %d", i, it.RatingKey, 900+i) + } + } +} + +// TestItemsPagingWithoutTotal covers a server that reports no total, which is +// the one case where the page size is the only thing that says the walk is over. +func TestItemsPagingWithoutTotal(t *testing.T) { + t.Parallel() + const total = ItemWindow + 7 + + handler := func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/library/sections/7/all" { + writeJSON(w, http.StatusOK, + `{"MediaContainer":{"size":1,"Directory":[{"key":"7","title":"TV","type":"show"}]}}`) + return + } + start, _ := strconv.Atoi(r.Header.Get("X-Plex-Container-Start")) + size, _ := strconv.Atoi(r.Header.Get("X-Plex-Container-Size")) + if size <= 0 { + size = ItemWindow + } + writeJSON(w, http.StatusOK, sectionPageNoTotal(start, size, total)) + } + + f := newFake(t, handler) + c := f.client(t) + + items, err := c.Items(context.Background(), nil) + if err != nil { + t.Fatalf("Items: %v", err) + } + if len(items) != total { + t.Fatalf("Items = %d entries, want %d", len(items), total) + } +} + +// TestItemsPagingServerThatCapsThePage covers a server that answers with fewer +// items than the size asked for and reports no total. The page size must not end +// the walk: doing so would return a fraction of the library and look like a +// successful read, which is worse than the timeout the paging exists to avoid. +func TestItemsPagingServerThatCapsThePage(t *testing.T) { + t.Parallel() + const ( + total = 7 + server = 2 // what this server will hand over per request + ) + + handler := func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/library/sections/7/all" { + writeJSON(w, http.StatusOK, + `{"MediaContainer":{"size":1,"Directory":[{"key":"7","title":"TV","type":"show"}]}}`) + return + } + start, _ := strconv.Atoi(r.Header.Get("X-Plex-Container-Start")) + writeJSON(w, http.StatusOK, sectionPageNoTotal(start, server, total)) + } + + f := newFake(t, handler) + c := f.client(t) + + items, err := c.Items(context.Background(), nil) + if err != nil { + t.Fatalf("Items: %v", err) + } + if len(items) != total { + t.Fatalf("Items = %d entries, want %d: a capped page ended the walk early", len(items), total) + } + for i, it := range items { + if it.RatingKey != 900+i { + t.Fatalf("items[%d].RatingKey = %d, want %d", i, it.RatingKey, 900+i) + } + } +} + +// TestItemsServerThatIgnoresPaging terminates and does not duplicate when the +// server answers every request with the whole section, which is what a server +// with no container support looks like. +func TestItemsServerThatIgnoresPaging(t *testing.T) { + t.Parallel() + const total = 3 + + handler := func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/library/sections/7/all" { + writeJSON(w, http.StatusOK, + `{"MediaContainer":{"size":1,"Directory":[{"key":"7","title":"TV","type":"show"}]}}`) + return + } + writeJSON(w, http.StatusOK, sectionPage(0, total, total)) + } + + f := newFake(t, handler) + c := f.client(t) + + items, err := c.Items(context.Background(), nil) + if err != nil { + t.Fatalf("Items: %v", err) + } + if len(items) != total { + t.Fatalf("Items = %d entries, want %d with no duplicates", len(items), total) + } +} + +// sectionPage renders a page of a section that reports its total. +func sectionPage(start, size, total int) string { + if start < 0 || start > total { + start = total + } + end := start + size + if end > total { + end = total + } + return page(start, end, total, true) +} + +// sectionPageNoTotal renders a page from a server that reports no total. +func sectionPageNoTotal(start, size, total int) string { + if start < 0 || start > total { + start = total + } + end := start + size + if end > total { + end = total + } + return page(start, end, total, false) +} + +func page(start, end, total int, withTotal bool) string { + var sb strings.Builder + sb.WriteString(`{"MediaContainer":{"size":`) + fmt.Fprintf(&sb, "%d", end-start) + if withTotal { + fmt.Fprintf(&sb, `,"total":%d`, total) + } + sb.WriteString(`,"Metadata":[`) + for i := start; i < end; i++ { + if i > start { + sb.WriteString(",") + } + fmt.Fprintf(&sb, `{"ratingKey":%d,"type":"movie","title":"Movie %d"}`, 900+i, i) + } + sb.WriteString(`]}}`) + return sb.String() +} + func TestChapters(t *testing.T) { t.Parallel() f := newFake(t, plexHandler) diff --git a/internal/plexdb/showids.go b/internal/plexdb/showids.go index 97f0526..9a8ba8b 100644 --- a/internal/plexdb/showids.go +++ b/internal/plexdb/showids.go @@ -7,6 +7,17 @@ import ( "strings" ) +// showIDChunk is how many episode keys go into one statement. +// +// SQLite refuses a statement carrying more bound parameters than +// SQLITE_MAX_VARIABLE_NUMBER, which has been 32,766 since 3.32, and a TV +// library can hold more episodes than that. The whole query then fails, the +// caller treats that as non-fatal, and every episode silently keeps its own id +// instead of the show's -- a key TheIntroDB can never match, so the run spends +// its allowance on lookups that cannot succeed. Chunking keeps the +// one-query-per-library shape and never reaches the limit. +const showIDChunk = 5000 + // ShowProviderIDs returns the provider id tags of the show each of these // episodes belongs to. // @@ -21,15 +32,48 @@ import ( // // The walk is episode -> season -> show because that is the shape Plex stores: // the episode's parent is its season, and the season's parent is the show. It is -// done in one query for a whole library rather than a request per episode. +// done in a handful of queries for a whole library rather than a request per +// episode. func (d *DB) ShowProviderIDs(ctx context.Context, episodeKeys []int64) (map[int64][]string, error) { if len(episodeKeys) == 0 { return nil, nil } + keys := uniqueKeys(episodeKeys) - placeholders := make([]string, 0, len(episodeKeys)) - args := make([]any, 0, len(episodeKeys)) - for _, key := range episodeKeys { + out := map[int64][]string{} + for start := 0; start < len(keys); start += showIDChunk { + end := start + showIDChunk + if end > len(keys) { + end = len(keys) + } + if err := d.showProviderIDsChunk(ctx, keys[start:end], len(keys), out); err != nil { + return nil, err + } + } + return out, nil +} + +// uniqueKeys drops repeats, so an episode named twice cannot be reported twice +// and a key cannot be queried in two different chunks. +func uniqueKeys(keys []int64) []int64 { + seen := make(map[int64]bool, len(keys)) + out := make([]int64, 0, len(keys)) + for _, key := range keys { + if seen[key] { + continue + } + seen[key] = true + out = append(out, key) + } + return out +} + +// showProviderIDsChunk runs one chunk of the walk and adds its rows to out. +// total is the size of the whole request, which is what the error reports. +func (d *DB) showProviderIDsChunk(ctx context.Context, keys []int64, total int, out map[int64][]string) error { + placeholders := make([]string, 0, len(keys)) + args := make([]any, 0, len(keys)) + for _, key := range keys { placeholders = append(placeholders, "?") args = append(args, key) } @@ -46,23 +90,22 @@ func (d *DB) ShowProviderIDs(ctx context.Context, episodeKeys []int64) (map[int6 ORDER BY episode.id`, append(args, TagTypeProviderID)...) if err != nil { - return nil, fmt.Errorf("plexdb: read the shows for %d episode(s): %w", len(episodeKeys), err) + return fmt.Errorf("plexdb: read the shows for %d episode(s): %w", total, err) } defer func() { _ = rows.Close() }() - out := map[int64][]string{} for rows.Next() { var key int64 var tag string if err := rows.Scan(&key, &tag); err != nil { - return nil, fmt.Errorf("plexdb: read the shows for %d episode(s): %w", len(episodeKeys), err) + return fmt.Errorf("plexdb: read the shows for %d episode(s): %w", total, err) } out[key] = append(out[key], tag) } if err := rows.Err(); err != nil { - return nil, fmt.Errorf("plexdb: read the shows for %d episode(s): %w", len(episodeKeys), err) + return fmt.Errorf("plexdb: read the shows for %d episode(s): %w", total, err) } - return out, nil + return nil } // IsEpisodeKey reports whether a rating key looks like an episode, by asking the diff --git a/internal/plexdb/showids_test.go b/internal/plexdb/showids_test.go new file mode 100644 index 0000000..befa8b2 --- /dev/null +++ b/internal/plexdb/showids_test.go @@ -0,0 +1,158 @@ +package plexdb + +import ( + "context" + "testing" +) + +// TestShowProviderIDsLargeLibrary covers a TV library bigger than SQLite's bound +// parameter limit. +// +// The walk binds one parameter per episode, and SQLITE_MAX_VARIABLE_NUMBER has +// been 32,766 since SQLite 3.32. Above that the whole statement fails, the +// caller treats the failure as non-fatal, and every episode keeps its own +// provider id -- an id TheIntroDB cannot match, so the run spends its allowance +// on lookups that cannot succeed and writes no markers. The library below is +// deliberately over the limit. +func TestShowProviderIDsLargeLibrary(t *testing.T) { + t.Parallel() + + const episodes = 40_000 + const ( + showID = int64(900001) + seasonID = int64(900002) + ) + + f := newFixture(t) + + tmdbTag := f.addTag(TagTypeProviderID, "tmdb://236235") + imdbTag := f.addTag(TagTypeProviderID, "imdb://tt1489211") + + f.exec(`INSERT INTO metadata_items + (id, metadata_type, parent_id, library_section_id, "index", title, duration, added_at, updated_at, guid) +VALUES (?, 2, NULL, 2, 1, 'The Gentlemen', 0, 1700000000, 1700000000, NULL)`, showID) + f.exec(`INSERT INTO metadata_items + (id, metadata_type, parent_id, library_section_id, "index", title, duration, added_at, updated_at, guid) +VALUES (?, 3, ?, 2, 2, 'Season 2', 0, 1700000000, 1700000000, NULL)`, seasonID, showID) + f.exec(`INSERT INTO taggings (metadata_item_id, tag_id, "index", created_at) +VALUES (?, ?, 1, 1700000000)`, showID, tmdbTag) + f.exec(`INSERT INTO taggings (metadata_item_id, tag_id, "index", created_at) +VALUES (?, ?, 2, 1700000000)`, showID, imdbTag) + + keys := make([]int64, 0, episodes) + tx, err := f.db.BeginTx(context.Background(), nil) + if err != nil { + t.Fatalf("begin: %v", err) + } + stmt, err := tx.Prepare(`INSERT INTO metadata_items + (id, metadata_type, parent_id, library_section_id, "index", title, duration, added_at, updated_at, guid) +VALUES (?, 4, ?, 2, ?, 'Episode', 0, 1700000000, 1700000000, NULL)`) + if err != nil { + t.Fatalf("prepare: %v", err) + } + defer func() { _ = stmt.Close() }() + for i := 1; i <= episodes; i++ { + key := int64(i) + if _, err := stmt.Exec(key, seasonID, i); err != nil { + t.Fatalf("insert episode %d: %v", i, err) + } + keys = append(keys, key) + } + if err := stmt.Close(); err != nil { + t.Fatalf("close statement: %v", err) + } + if err := tx.Commit(); err != nil { + t.Fatalf("commit: %v", err) + } + + db := f.open() + got, err := db.ShowProviderIDs(context.Background(), keys) + if err != nil { + t.Fatalf("ShowProviderIDs over %d episodes: %v", episodes, err) + } + if len(got) != episodes { + t.Fatalf("ShowProviderIDs returned %d episodes, want %d", len(got), episodes) + } + for _, key := range keys { + tags := got[key] + if len(tags) != 2 { + t.Fatalf("episode %d carries %d tags, want the show's 2", key, len(tags)) + } + if tags[0] != "tmdb://236235" || tags[1] != "imdb://tt1489211" { + t.Fatalf("episode %d tags = %v, want the show's provider ids", key, tags) + } + } +} + +// TestShowProviderIDsChunkBoundary checks the join between two chunks, and that a +// key named twice is not reported twice. +// +// The library is one key longer than a chunk, so the last key is read by a second +// statement than the first, and the repeat is appended after a whole chunk-sized +// group so deduplication is what keeps it out of the second one. A shorter +// library would put every key in the same statement and prove nothing about +// either. +func TestShowProviderIDsChunkBoundary(t *testing.T) { + t.Parallel() + + const ( + showID = int64(900001) + seasonID = int64(900002) + ) + + f := newFixture(t) + tag := f.addTag(TagTypeProviderID, "tmdb://1911") + + f.exec(`INSERT INTO metadata_items + (id, metadata_type, parent_id, library_section_id, "index", title, duration, added_at, updated_at, guid) +VALUES (?, 2, NULL, 2, 1, 'Game of Thrones', 0, 1700000000, 1700000000, NULL)`, showID) + f.exec(`INSERT INTO metadata_items + (id, metadata_type, parent_id, library_section_id, "index", title, duration, added_at, updated_at, guid) +VALUES (?, 3, ?, 2, 1, 'Season 1', 0, 1700000000, 1700000000, NULL)`, seasonID, showID) + f.exec(`INSERT INTO taggings (metadata_item_id, tag_id, "index", created_at) +VALUES (?, ?, 1, 1700000000)`, showID, tag) + + // One chunk and one more, so the walk has to join two statements. + distinct := showIDChunk + 1 + keys := make([]int64, 0, distinct+1) + tx, err := f.db.BeginTx(context.Background(), nil) + if err != nil { + t.Fatalf("begin: %v", err) + } + stmt, err := tx.Prepare(`INSERT INTO metadata_items + (id, metadata_type, parent_id, library_section_id, "index", title, duration, added_at, updated_at, guid) +VALUES (?, 4, ?, 2, 1, 'Episode', 0, 1700000000, 1700000000, NULL)`) + if err != nil { + t.Fatalf("prepare: %v", err) + } + defer func() { _ = stmt.Close() }() + for i := 1; i <= distinct; i++ { + key := int64(i) + if _, err := stmt.Exec(key, seasonID); err != nil { + t.Fatalf("insert episode %d: %v", i, err) + } + keys = append(keys, key) + } + if err := stmt.Close(); err != nil { + t.Fatalf("close statement: %v", err) + } + if err := tx.Commit(); err != nil { + t.Fatalf("commit: %v", err) + } + // The first key again, after a whole chunk of others. + keys = append(keys, 1) + + db := f.open() + got, err := db.ShowProviderIDs(context.Background(), keys) + if err != nil { + t.Fatalf("ShowProviderIDs: %v", err) + } + if len(got) != distinct { + t.Fatalf("ShowProviderIDs returned %d episodes, want %d", len(got), distinct) + } + for _, key := range keys { + if tags := got[key]; len(tags) != 1 || tags[0] != "tmdb://1911" { + t.Fatalf("episode %d tags = %v, want the show's id once", key, tags) + } + } +}