bugfix #1925: stop library scans from silently dropping titles

Audible's catalog endpoint can answer 200 while omitting products from the
response. getProductsAsync returned whatever came back, so any podcast episode
Audible skipped simply vanished from the scan. The reporter's log shows this:
across 1117 consecutive scans of an unchanged 440-item library, the post-scan
item total drifted between 2147 and 2151.

Re-request the omitted asins before accepting the loss, and warn with the asins
that are still unaccounted for afterwards.

The rest of the scan's exclusions were equally invisible at the default log
level, which is why the reporter found nothing in the log about the missing
book:
- episodes dropped for having no series parent were logged at Debug, without
  identifying them. Warn instead, and name them.
- titles excluded by ImportEpisodes / ImportPlusTitles were not logged at all.
  Tally them, and record both settings in the startup state block.

Read the two import filters once per scan so a settings change mid-scan can't
produce a half-filtered library.

Co-authored-by: rmcrackan <rmcrackan@gmail.com>

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,

Source/AudibleUtilities/ApiExtended.cs

@@ -23,6 +23,10 @@ public class ApiExtended
 
 	private const int MaxConcurrency = 10;
 	private const int BatchSize = 50;
+	/// <summary>Extra attempts to re-request catalog products that Audible omitted from an otherwise successful response.</summary>
+	private const int MissingAsinRetries = 2;
+	/// <summary>Upper bound on how many dropped titles a single log entry will name.</summary>
+	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<Item> 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<List<Item>> getCatalogProductsAsync(List<string> 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);
+
+	/// <summary>Requested asins for which <paramref name="received"/> holds no matching <see cref="Item"/>.</summary>
+	public static List<string> GetMissingAsins(IEnumerable<string> requested, IEnumerable<Item> received)
+	{
+		ArgumentValidator.EnsureNotNull(requested, nameof(requested));
+		ArgumentValidator.EnsureNotNull(received, nameof(received));
+
+		var found = received.Select(i => i.Asin).OfType<string>().ToHashSet(StringComparer.OrdinalIgnoreCase);
+		return requested.Where(a => !found.Contains(a)).ToList();
+	}
+
+	/// <summary>
+	/// Fetch <paramref name="asins"/>, re-requesting any that <paramref name="fetch"/> fails to return.
+	/// Audible's catalog endpoint can answer 200 while quietly omitting products.
+	/// </summary>
+	/// <returns>Everything that was returned, plus the asins still unaccounted for after the last attempt.</returns>
+	public static async Task<(List<Item> Items, List<string> Missing)> FetchRetryingMissingAsync(
+		List<string> asins,
+		Func<List<string>, Task<List<Item>>> fetch,
+		int maxRetries,
+		Action<int>? 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<Item> children)
 	{
 		ArgumentValidator.EnsureNotNull(parent, nameof(parent));

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;
+
+/// <summary>
+/// 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).
+/// </summary>
+[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 };
+
+	/// <summary>Returns the requested asins minus <paramref name="omit"/>, recording each request.</summary>
+	private static Func<List<string>, Task<List<Item>>> fetcher(List<List<string>> 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<List<string>>();
+
+		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<List<string>>();
+		int call = 0;
+
+		// Audible drops A2 from the first response, then returns it when asked again.
+		Task<List<Item>> fetch(List<string> 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<List<string>>();
+
+		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<List<string>>();
+
+		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<int>();
+
+		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<int>();
+
+		await ApiExtended.FetchRetryingMissingAsync(["A1"], fetcher([]), maxRetries: 2, attempts.Add);
+
+		Assert.AreEqual(0, attempts.Count);
+	}
+}