diff --git a/Source/AppScaffolding/LibationScaffolding.cs b/Source/AppScaffolding/LibationScaffolding.cs index 150828ed..4de3a839 100644 --- a/Source/AppScaffolding/LibationScaffolding.cs +++ b/Source/AppScaffolding/LibationScaffolding.cs @@ -269,6 +269,10 @@ public static class LibationScaffolding LogLevel_Fatal_Enabled = Log.Logger.IsFatalEnabled(), config.AutoScan, + // These silently exclude titles from every scan, so a log without them can't explain a missing book + config.ImportEpisodes, + config.ImportPlusTitles, + config.DownloadEpisodes, config.BetaOptIn, config.UseCoverAsFolderIcon, config.LibationFiles, diff --git a/Source/AudibleUtilities/ApiExtended.cs b/Source/AudibleUtilities/ApiExtended.cs index 0c0309c1..fbb3dabb 100644 --- a/Source/AudibleUtilities/ApiExtended.cs +++ b/Source/AudibleUtilities/ApiExtended.cs @@ -23,6 +23,10 @@ public class ApiExtended private const int MaxConcurrency = 10; private const int BatchSize = 50; + /// Extra attempts to re-request catalog products that Audible omitted from an otherwise successful response. + private const int MissingAsinRetries = 2; + /// Upper bound on how many dropped titles a single log entry will name. + private const int MaxLoggedTitles = 50; private ApiExtended(Api api) => Api = api; @@ -135,7 +139,12 @@ public class ApiExtended { Serilog.Log.Logger.Debug("Beginning library scan."); + //Read the import filters once so a settings change mid-scan can't produce a half-filtered library. + var importEpisodes = Configuration.Instance.ImportEpisodes; + var importPlusTitles = Configuration.Instance.ImportPlusTitles; + List items = new(); + int libraryItemCount = 0, episodeItemsExcluded = 0, plusTitlesExcluded = 0; var sw = Stopwatch.StartNew(); var totalTime = TimeSpan.Zero; using var semaphore = new SemaphoreSlim(MaxConcurrency); @@ -147,7 +156,9 @@ public class ApiExtended //Get relationship asins from episode-type items and write them to episodeChannel where they will be batched and queried. await foreach (var itemsBatch in Api.GetLibraryItemsPagesAsync(libraryOptions, BatchSize, semaphore)) { - if (Configuration.Instance.ImportEpisodes) + libraryItemCount += itemsBatch.Length; + + if (importEpisodes) { var episodes = itemsBatch.Where(i => i.IsEpisodes).ToList(); var series = itemsBatch.Where(i => i.IsSeriesParent).ToList(); @@ -170,11 +181,18 @@ public class ApiExtended items.AddRange(episodes); items.AddRange(series); } + else + episodeItemsExcluded += itemsBatch.Count(i => i.IsSeriesParent || i.IsEpisodes); + + var booksInBatch = itemsBatch.Where(i => !i.IsSeriesParent && !i.IsEpisodes).ToList(); + + if (!importPlusTitles) + { + var ownedInBatch = booksInBatch.Where(i => i.IsAyce is not true).ToList(); + plusTitlesExcluded += booksInBatch.Count - ownedInBatch.Count; + booksInBatch = ownedInBatch; + } - var booksInBatch - = itemsBatch - .Where(i => !i.IsSeriesParent && !i.IsEpisodes) - .Where(i => i.IsAyce is not true || Configuration.Instance.ImportPlusTitles); items.AddRange(booksInBatch); } @@ -204,14 +222,32 @@ public class ApiExtended SetSeries(parent, children); } - int orphansRemoved = items.RemoveAll(i => (i.IsEpisodes || i.IsSeriesParent) && i.Series is null); - if (orphansRemoved > 0) - Serilog.Log.Debug("{orphansRemoved} podcast orphans not imported", orphansRemoved); + //An episode whose series parent never made it into this scan can't be linked to a series, so it + //gets dropped. Name the casualties: without them a title silently vanishes from the library and + //there is nothing in the log to explain why. + var orphans = items.Where(isOrphan).Select(describe).Distinct().ToList(); + items.RemoveAll(isOrphan); + if (orphans.Count > 0) + Serilog.Log.Logger.Warning( + "{orphansRemoved} podcast episodes were not imported because their series parent was missing from this scan. {@DebugInfo}", + orphans.Count, + new { Orphans = orphans.Take(MaxLoggedTitles).ToList(), Truncated = orphans.Count > MaxLoggedTitles }); sw.Stop(); totalTime += sw.Elapsed; Serilog.Log.Logger.Information("Completed indexing series episodes after {elappsed_ms} ms.", sw.ElapsedMilliseconds); Serilog.Log.Logger.Information($"Completed library scan in {totalTime.TotalMilliseconds:F0} ms."); + Serilog.Log.Logger.Information("Library scan tally. {@DebugInfo}", new + { + LibraryItems = libraryItemCount, + EpisodesFetched = allEps.Count, + OrphanedEpisodesDropped = orphans.Count, + ImportEpisodes = importEpisodes, + EpisodeItemsExcluded = episodeItemsExcluded, + ImportPlusTitles = importPlusTitles, + PlusTitlesExcluded = plusTitlesExcluded, + ItemsToImport = items.Count + }); Array.ForEach(ISanitizer.GetAllSanitizers(), s => s.Sanitize(items)); var allExceptions = IValidator.GetAllValidators().SelectMany(v => v.Validate(items)).ToList(); @@ -219,6 +255,9 @@ public class ApiExtended throw new ImportValidationException(items, allExceptions); return items; + + static bool isOrphan(Item item) => (item.IsEpisodes || item.IsSeriesParent) && item.Series is null; + static string describe(Item item) => $"[{item.Asin}] {item.Title}"; } #region episodes and podcasts @@ -260,15 +299,27 @@ public class ApiExtended try { var sw = Stopwatch.StartNew(); - var items = await Api.GetCatalogProductsAsync(asins, CatalogOptions.ResponseGroupOptions.Rating | CatalogOptions.ResponseGroupOptions.Media - | CatalogOptions.ResponseGroupOptions.Relationships | CatalogOptions.ResponseGroupOptions.ProductDesc - | CatalogOptions.ResponseGroupOptions.Contributors | CatalogOptions.ResponseGroupOptions.ProvidedReview - | CatalogOptions.ResponseGroupOptions.ProductPlans | CatalogOptions.ResponseGroupOptions.Series - | CatalogOptions.ResponseGroupOptions.CategoryLadders | CatalogOptions.ResponseGroupOptions.ProductExtendedAttrs); + + //Audible sometimes omits products from a response that is otherwise successful. Those episodes + //would silently disappear from the library, so re-request them before accepting the loss. + var (items, missing) = await FetchRetryingMissingAsync( + asins, + getCatalogProductsAsync, + MissingAsinRetries, + attempt => Serilog.Log.Logger.Debug($"Batch {batchNum} Retry {attempt}: Re-fetching asins Audible did not return")); + sw.Stop(); Serilog.Log.Logger.Debug($"Batch {batchNum} End: Retrieved {items.Count} items in {sw.ElapsedMilliseconds} ms"); + if (missing.Count > 0) + Serilog.Log.Logger.Warning( + "Audible did not return {missingCount} of the {requestedCount} catalog products requested in batch {batchNum}. Those titles are missing from this scan. {@DebugInfo}", + missing.Count, + asins.Count, + batchNum, + new { MissingAsins = missing }); + return items; } catch (Exception ex) @@ -279,6 +330,52 @@ public class ApiExtended finally { semaphore.Release(); } } + private Task> getCatalogProductsAsync(List asins) + => Api.GetCatalogProductsAsync(asins, CatalogOptions.ResponseGroupOptions.Rating | CatalogOptions.ResponseGroupOptions.Media + | CatalogOptions.ResponseGroupOptions.Relationships | CatalogOptions.ResponseGroupOptions.ProductDesc + | CatalogOptions.ResponseGroupOptions.Contributors | CatalogOptions.ResponseGroupOptions.ProvidedReview + | CatalogOptions.ResponseGroupOptions.ProductPlans | CatalogOptions.ResponseGroupOptions.Series + | CatalogOptions.ResponseGroupOptions.CategoryLadders | CatalogOptions.ResponseGroupOptions.ProductExtendedAttrs); + + /// Requested asins for which holds no matching . + public static List GetMissingAsins(IEnumerable requested, IEnumerable received) + { + ArgumentValidator.EnsureNotNull(requested, nameof(requested)); + ArgumentValidator.EnsureNotNull(received, nameof(received)); + + var found = received.Select(i => i.Asin).OfType().ToHashSet(StringComparer.OrdinalIgnoreCase); + return requested.Where(a => !found.Contains(a)).ToList(); + } + + /// + /// Fetch , re-requesting any that fails to return. + /// Audible's catalog endpoint can answer 200 while quietly omitting products. + /// + /// Everything that was returned, plus the asins still unaccounted for after the last attempt. + public static async Task<(List Items, List Missing)> FetchRetryingMissingAsync( + List asins, + Func, Task>> fetch, + int maxRetries, + Action? onRetry = null) + { + ArgumentValidator.EnsureNotNull(asins, nameof(asins)); + ArgumentValidator.EnsureNotNull(fetch, nameof(fetch)); + + var items = await fetch(asins); + var missing = GetMissingAsins(asins, items); + + for (int attempt = 1; attempt <= maxRetries && missing.Count > 0; attempt++) + { + onRetry?.Invoke(attempt); + + var retriedItems = await fetch(missing); + items.AddRange(retriedItems); + missing = GetMissingAsins(missing, retriedItems); + } + + return (items, missing); + } + public static void SetSeries(Item parent, IEnumerable children) { ArgumentValidator.EnsureNotNull(parent, nameof(parent)); diff --git a/Source/_Tests/AudibleUtilities.Tests/ApiExtendedCatalogFetchTests.cs b/Source/_Tests/AudibleUtilities.Tests/ApiExtendedCatalogFetchTests.cs new file mode 100644 index 00000000..2725bb85 --- /dev/null +++ b/Source/_Tests/AudibleUtilities.Tests/ApiExtendedCatalogFetchTests.cs @@ -0,0 +1,158 @@ +using AudibleApi.Common; +using AudibleUtilities; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; + +namespace ApiExtendedCatalogFetchTests; + +/// +/// Audible's catalog endpoint can answer 200 while quietly omitting products. When that happened +/// the affected podcast episodes vanished from the library with nothing in the log (issue #1925). +/// +[TestClass] +public class GetMissingAsins +{ + private static Item item(string asin) => new() { Asin = asin }; + + [TestMethod] + public void nothing_missing_when_all_returned() + { + var missing = ApiExtended.GetMissingAsins(["A1", "A2", "A3"], [item("A1"), item("A2"), item("A3")]); + + Assert.AreEqual(0, missing.Count); + } + + [TestMethod] + public void reports_asins_the_response_omitted() + { + var missing = ApiExtended.GetMissingAsins(["A1", "A2", "A3"], [item("A1"), item("A3")]); + + CollectionAssert.AreEqual(new[] { "A2" }, missing); + } + + [TestMethod] + public void reports_every_asin_when_response_is_empty() + { + var missing = ApiExtended.GetMissingAsins(["A1", "A2"], []); + + CollectionAssert.AreEqual(new[] { "A1", "A2" }, missing); + } + + [TestMethod] + public void asin_comparison_ignores_case() + { + var missing = ApiExtended.GetMissingAsins(["a1"], [item("A1")]); + + Assert.AreEqual(0, missing.Count); + } + + [TestMethod] + public void items_without_an_asin_do_not_satisfy_a_request() + { + var missing = ApiExtended.GetMissingAsins(["A1"], [new Item()]); + + CollectionAssert.AreEqual(new[] { "A1" }, missing); + } + + [TestMethod] + public void extra_unrequested_items_are_ignored() + { + var missing = ApiExtended.GetMissingAsins(["A1"], [item("A1"), item("A9")]); + + Assert.AreEqual(0, missing.Count); + } +} + +[TestClass] +public class FetchRetryingMissingAsync +{ + private static Item item(string asin) => new() { Asin = asin }; + + /// Returns the requested asins minus , recording each request. + private static Func, Task>> fetcher(List> requests, params string[] omit) + => asins => + { + requests.Add([.. asins]); + return Task.FromResult(asins.Where(a => !omit.Contains(a)).Select(item).ToList()); + }; + + [TestMethod] + public async Task complete_response_is_not_retried() + { + var requests = new List>(); + + var (items, missing) = await ApiExtended.FetchRetryingMissingAsync(["A1", "A2"], fetcher(requests), maxRetries: 2); + + Assert.AreEqual(1, requests.Count); + Assert.AreEqual(2, items.Count); + Assert.AreEqual(0, missing.Count); + } + + [TestMethod] + public async Task omitted_asin_is_re_requested_on_its_own() + { + var requests = new List>(); + int call = 0; + + // Audible drops A2 from the first response, then returns it when asked again. + Task> fetch(List asins) + { + requests.Add([.. asins]); + var omit = call++ == 0 ? "A2" : null; + return Task.FromResult(asins.Where(a => a != omit).Select(item).ToList()); + } + + var (items, missing) = await ApiExtended.FetchRetryingMissingAsync(["A1", "A2", "A3"], fetch, maxRetries: 2); + + Assert.AreEqual(2, requests.Count); + CollectionAssert.AreEqual(new[] { "A2" }, requests[1]); + CollectionAssert.AreEquivalent(new[] { "A1", "A2", "A3" }, items.Select(i => i.Asin).ToList()); + Assert.AreEqual(0, missing.Count); + } + + [TestMethod] + public async Task persistently_omitted_asin_is_reported_after_the_retries_run_out() + { + var requests = new List>(); + + var (items, missing) = await ApiExtended.FetchRetryingMissingAsync(["A1", "A2"], fetcher(requests, "A2"), maxRetries: 2); + + Assert.AreEqual(3, requests.Count); + CollectionAssert.AreEqual(new[] { "A1" }, items.Select(i => i.Asin).ToList()); + CollectionAssert.AreEqual(new[] { "A2" }, missing); + } + + [TestMethod] + public async Task retries_can_be_disabled() + { + var requests = new List>(); + + var (_, missing) = await ApiExtended.FetchRetryingMissingAsync(["A1", "A2"], fetcher(requests, "A2"), maxRetries: 0); + + Assert.AreEqual(1, requests.Count); + CollectionAssert.AreEqual(new[] { "A2" }, missing); + } + + [TestMethod] + public async Task onRetry_reports_each_attempt_number() + { + var attempts = new List(); + + await ApiExtended.FetchRetryingMissingAsync(["A1"], fetcher([], "A1"), maxRetries: 2, attempts.Add); + + CollectionAssert.AreEqual(new[] { 1, 2 }, attempts); + } + + [TestMethod] + public async Task onRetry_is_not_called_for_a_complete_response() + { + var attempts = new List(); + + await ApiExtended.FetchRetryingMissingAsync(["A1"], fetcher([]), maxRetries: 2, attempts.Add); + + Assert.AreEqual(0, attempts.Count); + } +}