From 4d8075927ff229a05816b7274c6abba858a4803e Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 16:03:27 +0000 Subject: [PATCH 01/14] fix(logging): roll the log on size, not only on the calendar month The default Serilog config set rollingInterval only, so Serilog's own defaults applied: no size-based roll and a 1 GB ceiling after which the sink silently stops writing. A busy install (many accounts scanned several times an hour) reaches tens of MB in a month, past the point where the log can be attached to a bug report. Add fileSizeLimitBytes, rollOnFileSizeLimit and retainedFileCountLimit to the default File sink, and fill in whichever of the three an existing Settings.json is missing so installs that already have a Serilog section benefit too. Only absent keys are written, so a hand-tuned config is left alone. Co-authored-by: rmcrackan --- .../Configuration.Logging.cs | 86 +++++++++++++++---- .../SerilogConfigurationTests.cs | 65 ++++++++++++++ docs/installation/docker.md | 22 ++++- 3 files changed, 155 insertions(+), 18 deletions(-) diff --git a/Source/LibationFileManager/Configuration.Logging.cs b/Source/LibationFileManager/Configuration.Logging.cs index 67bf2242..0c39e014 100644 --- a/Source/LibationFileManager/Configuration.Logging.cs +++ b/Source/LibationFileManager/Configuration.Logging.cs @@ -22,7 +22,19 @@ public partial class Configuration public bool SerilogInitialized { get; private set; } /// - /// Create default Serilog config if missing, and migrate legacy ZipFile sink to File. + /// Size at which the log rolls to a new file. Deliberately well under GitHub's 25 MB attachment limit so + /// the current log can always be attached to a bug report. + /// + public const long LogFileSizeLimitBytes = 10 * 1024 * 1024; + + /// + /// How many log files to keep. With this caps the logs at about 200 MB. + /// + public const int LogRetainedFileCountLimit = 20; + + /// + /// Create default Serilog config if missing, and bring an existing one up to date: migrate the legacy + /// ZipFile sink to File, attach , and add size-based rolling. /// Must run before / . /// public void EnsureSerilogConfig() @@ -43,6 +55,8 @@ public partial class Configuration fileSinkArgs["hooks"] = hooks; fileChanged = true; } + + fileChanged |= AddSizeRollingArgs(fileSinkArgs); } if (fileChanged) @@ -62,22 +76,7 @@ public partial class Configuration new JObject { { "Name", "File" }, - { "Args", - new JObject - { - // for this sink to work, a path must be provided. we override this below - { "path", Path.Combine(LibationFiles.Location, "Log.log") }, - { "rollingInterval", "Month" }, - // Serilog template formatting examples - // - default: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}" - // output example: 2019-11-26 08:48:40.224 -05:00 [DBG] Begin Libation - // - with class and method info: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] (at {Caller}) {Message:lj}{NewLine}{Exception}"; - // output example: 2019-11-26 08:48:40.224 -05:00 [DBG] (at LibationWinForms.Program.init()) Begin Libation - // {Properties:j} needed for expanded exception logging - { "outputTemplate", "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] (at {Caller}) {Message:lj}{NewLine}{Exception} {Properties:j}" }, - { "hooks", typeof(FileSinkHook).AssemblyQualifiedName }, // for FileSinkHook - } - } + { "Args", CreateDefaultFileSinkArgs() } } } }, @@ -88,6 +87,59 @@ public partial class Configuration SetNonString(serilogObj, "Serilog"); } + private JObject CreateDefaultFileSinkArgs() + { + var args = new JObject + { + // for this sink to work, a path must be provided. we override this below + { "path", Path.Combine(LibationFiles.Location, "Log.log") }, + { "rollingInterval", "Month" }, + // Serilog template formatting examples + // - default: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}" + // output example: 2019-11-26 08:48:40.224 -05:00 [DBG] Begin Libation + // - with class and method info: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] (at {Caller}) {Message:lj}{NewLine}{Exception}"; + // output example: 2019-11-26 08:48:40.224 -05:00 [DBG] (at LibationWinForms.Program.init()) Begin Libation + // {Properties:j} needed for expanded exception logging + { "outputTemplate", "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] (at {Caller}) {Message:lj}{NewLine}{Exception} {Properties:j}" }, + { "hooks", typeof(FileSinkHook).AssemblyQualifiedName }, // for FileSinkHook + }; + + AddSizeRollingArgs(args); + return args; + } + + /// + /// Adds the size-based rolling arguments a monthly rolling interval does not provide on its own. + /// + /// Without these, Serilog's own defaults apply: one file per month, no size roll, and a 1 GB ceiling + /// after which the sink silently stops writing. A busy install (many accounts, a scan every hour) can + /// reach tens of MB in a month, past the point where the log can be attached to a bug report. + /// + /// + /// Only absent keys are filled in, so a hand-tuned config is left alone. + /// + /// + /// True when something was added. + private static bool AddSizeRollingArgs(JObject fileSinkArgs) + { + var changed = false; + + changed |= AddIfMissing("fileSizeLimitBytes", LogFileSizeLimitBytes); + changed |= AddIfMissing("rollOnFileSizeLimit", true); + changed |= AddIfMissing("retainedFileCountLimit", LogRetainedFileCountLimit); + + return changed; + + bool AddIfMissing(string name, JToken value) + { + if (fileSinkArgs[name] is not null) + return false; + + fileSinkArgs[name] = value; + return true; + } + } + public void ConfigureLogging() { ValidateSerilogConfiguration(); diff --git a/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs b/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs index 94ce9204..ed269b85 100644 --- a/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs +++ b/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs @@ -84,6 +84,71 @@ public class SerilogConfigurationTests config.ValidateSerilogConfiguration(); } + [TestMethod] + public void EnsureSerilogConfig_default_rolls_the_log_on_size() + { + var config = Configuration.CreateMockInstance(); + + config.EnsureSerilogConfig(); + + var args = (JObject)((JObject)config.GetObject("Serilog")!).SelectToken("$.WriteTo[0].Args")!; + Assert.AreEqual(Configuration.LogFileSizeLimitBytes, args["fileSizeLimitBytes"]!.Value()); + Assert.IsTrue(args["rollOnFileSizeLimit"]!.Value()); + Assert.AreEqual(Configuration.LogRetainedFileCountLimit, args["retainedFileCountLimit"]!.Value()); + + config.ValidateSerilogConfiguration(); + } + + [TestMethod] + public void EnsureSerilogConfig_adds_size_rolling_to_an_existing_config() + { + // Existing installs kept the pre-13.7.9 default: monthly rolling only, which let a single + // month's log grow past the point where it can be attached to a bug report. + var config = Configuration.CreateMockInstance(); + config.SetNonString(CreateSerilog("File"), "Serilog"); + + config.EnsureSerilogConfig(); + + var args = (JObject)((JObject)config.GetObject("Serilog")!).SelectToken("$.WriteTo[0].Args")!; + Assert.AreEqual(Configuration.LogFileSizeLimitBytes, args["fileSizeLimitBytes"]!.Value()); + Assert.IsTrue(args["rollOnFileSizeLimit"]!.Value()); + Assert.AreEqual(Configuration.LogRetainedFileCountLimit, args["retainedFileCountLimit"]!.Value()); + // the migration must not disturb what the user already had + Assert.AreEqual("Month", args["rollingInterval"]!.Value()); + } + + [TestMethod] + public void EnsureSerilogConfig_keeps_hand_tuned_size_rolling_args() + { + var config = Configuration.CreateMockInstance(); + var serilog = CreateSerilog("File"); + var existingArgs = (JObject)serilog.SelectToken("$.WriteTo[0].Args")!; + existingArgs["fileSizeLimitBytes"] = 1234; + existingArgs["rollOnFileSizeLimit"] = false; + existingArgs["retainedFileCountLimit"] = 3; + config.SetNonString(serilog, "Serilog"); + + config.EnsureSerilogConfig(); + + var args = (JObject)((JObject)config.GetObject("Serilog")!).SelectToken("$.WriteTo[0].Args")!; + Assert.AreEqual(1234, args["fileSizeLimitBytes"]!.Value()); + Assert.IsFalse(args["rollOnFileSizeLimit"]!.Value()); + Assert.AreEqual(3, args["retainedFileCountLimit"]!.Value()); + } + + [TestMethod] + public void EnsureSerilogConfig_leaves_a_non_File_sink_alone() + { + var config = Configuration.CreateMockInstance(); + config.SetNonString(CreateSerilog("Console"), "Serilog"); + + config.EnsureSerilogConfig(); + + var args = (JObject)((JObject)config.GetObject("Serilog")!).SelectToken("$.WriteTo[0].Args")!; + Assert.IsNull(args["fileSizeLimitBytes"]); + Assert.IsNull(args["rollOnFileSizeLimit"]); + } + [TestMethod] public void Validate_rejects_invalid_MinimumLevel() { diff --git a/docs/installation/docker.md b/docs/installation/docker.md index 63d6cb18..d6f1431b 100644 --- a/docs/installation/docker.md +++ b/docs/installation/docker.md @@ -153,7 +153,7 @@ The docker image supports an optional database mount location defined by `LIBATI LibationCli already writes a `LogYYYYMM.log` file (rolling monthly) using the same logging setup as the desktop apps — no extra configuration is required to generate it. However, in the docker image the log is written to an internal path (`/config-internal`) that isn't persisted or mounted by any of the examples above, so it disappears when the container is removed. To keep it around, use one of the following: - **Mount the internal config path**, e.g. add `-v /opt/libation/logs:/config-internal` to your `docker run` command. Note that this directory also holds the staged copies of `AccountsSettings.json`/`Settings.json` and the database symlink, which are regenerated from `/config`/`/db` on every container start. -- **Point the log file at an already-mounted directory** by adding a `Serilog` section to your `Settings.json` (in your `/config` volume) with a `File` sink `path` pointing somewhere persisted, such as `/data/Log.log`. If `Settings.json` already contains a `Serilog` section, Libation uses it as-is instead of generating its own default: +- **Point the log file at an already-mounted directory** by adding a `Serilog` section to your `Settings.json` (in your `/config` volume) with a `File` sink `path` pointing somewhere persisted, such as `/data/Log.log`. Libation uses an existing `Serilog` section as-is apart from filling in the size-rolling arguments described below when they are missing: ```json "Serilog": { @@ -164,6 +164,9 @@ LibationCli already writes a `LogYYYYMM.log` file (rolling monthly) using the sa "Args": { "path": "/data/Log.log", "rollingInterval": "Month", + "fileSizeLimitBytes": 10485760, + "rollOnFileSizeLimit": true, + "retainedFileCountLimit": 20, "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] (at {Caller}) {Message:lj}{NewLine}{Exception} {Properties:j}", "hooks": "LibationFileManager.FileSinkHook, LibationFileManager, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null" } @@ -180,6 +183,23 @@ LibationCli already writes a `LogYYYYMM.log` file (rolling monthly) using the sa } ``` +### Log size + +The log rolls on **both** the calendar month and file size: a new file is started every 10 MB +(`Log202608.log`, `Log202608_001.log`, ...) and the 20 newest files are kept, so the logs stay +around 200 MB at most and any single file is small enough to attach to a bug report. + +A frequent cron schedule and many accounts is what makes this matter: every run logs a startup +block and every account's library scan logs a line per page of results, so several runs an hour +across a dozen-plus accounts produces several MB a day. `rollingInterval` alone does not bound +that — before this was the default, a single month's log could reach tens of MB, and Serilog's own +1 GB ceiling would eventually stop it logging altogether until the month rolled over. + +To change any of it, set `fileSizeLimitBytes`, `rollOnFileSizeLimit` or `retainedFileCountLimit` +yourself in `Settings.json`; Libation only fills in the ones you leave out. Lowering +`MinimumLevel` is not an option (`Information` is the lowest that still records what a bug report +needs), but a smaller `retainedFileCountLimit` bounds total disk use. + ## Getting Help As mentioned above: docker is not officially supported. I'm adding this at the bottom of the page for anyone serious enough to have read this far. If you've tried everything above and would still like help, you can open an [issue](https://github.com/rmcrackan/Libation/issues). Please include `[docker]` in the title. There are also some docker folks who have offered occasional assistance who you can tag within your issue: `@ducamagnifico` , `@wtanksleyjr` , `@CLHatch` , `@oxivanisher`. From 824ff10dd99ff22e1cca0ceff1f3d4a783a8f101 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 16:13:17 +0000 Subject: [PATCH 02/14] fix(download): stop asking Audible for a license it just refused A license denial left no trace: BookStatus stayed NotLiberated, so every liberate run asked again. Only the GUI's bad-book dialog could mark a title Error, and license denials take their own path and never reach that dialog, so a headless install had no way at all to stop the retries. A cron schedule then re-requested the same refused licenses every run and printed the same warning block for each one, which is both wasted API traffic and the log noise reported in issue #1947. Record the refusal instead, with a wait that doubles per consecutive failure: one day for an eligibility denial (up to 30), six hours for a title Audible has no audio for yet such as an unreleased preorder (up to 7 days), one hour when the denial names GenericError, which the GUI already reads as an outage (up to 12). Nothing is permanent - every kind is attempted again on its own. Only failures attributable to Audible are recorded. A dropped connection, a decrypt error or a full disk keeps being retried on the next run as before. Naming a title, --force, and setting a download status all clear the record: asking for a title explicitly overrides the wait. Co-authored-by: rmcrackan --- .../ApplicationServices/DeferredDownload.cs | 107 ++++ .../DownloadAttemptFailureStore.cs | 176 ++++++ .../DownloadRetryBackoff.cs | 50 ++ Source/ApplicationServices/LibraryCommands.cs | 15 + ...446_AddDownloadAttemptFailures.Designer.cs | 578 ++++++++++++++++++ ...260816160446_AddDownloadAttemptFailures.cs | 47 ++ .../LibationContextModelSnapshot.cs | 39 ++ ...439_AddDownloadAttemptFailures.Designer.cs | 557 +++++++++++++++++ ...260816160439_AddDownloadAttemptFailures.cs | 46 ++ .../LibationContextModelSnapshot.cs | 37 ++ .../DownloadAttemptFailureConfig.cs | 16 + .../EfClasses/DownloadAttemptFailure.cs | 98 +++ Source/DataLayer/LibationContext.cs | 2 + Source/FileLiberator/DownloadDecryptBook.cs | 2 + .../DownloadFailureClassifier.cs | 88 +++ Source/FileLiberator/Processable.cs | 45 +- Source/LibationCli/Options/LiberateOptions.cs | 8 + .../Options/_ProcessableOptionsBase.cs | 59 +- .../ProcessQueue/BackupRequest.cs | 54 +- .../ProcessQueue/ProcessQueueViewModel.cs | 7 +- 20 files changed, 2019 insertions(+), 12 deletions(-) create mode 100644 Source/ApplicationServices/DeferredDownload.cs create mode 100644 Source/ApplicationServices/DownloadAttemptFailureStore.cs create mode 100644 Source/ApplicationServices/DownloadRetryBackoff.cs create mode 100644 Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.Designer.cs create mode 100644 Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.cs create mode 100644 Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.Designer.cs create mode 100644 Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.cs create mode 100644 Source/DataLayer/Configurations/DownloadAttemptFailureConfig.cs create mode 100644 Source/DataLayer/EfClasses/DownloadAttemptFailure.cs create mode 100644 Source/FileLiberator/DownloadFailureClassifier.cs diff --git a/Source/ApplicationServices/DeferredDownload.cs b/Source/ApplicationServices/DeferredDownload.cs new file mode 100644 index 00000000..72499978 --- /dev/null +++ b/Source/ApplicationServices/DeferredDownload.cs @@ -0,0 +1,107 @@ +using DataLayer; +using Dinah.Core; +using System; +using System.Collections.Generic; +using System.Linq; + +namespace ApplicationServices; + +/// One title Libation is waiting on before attempting it again, and why. +public sealed record DeferredDownload( + string Account, + string AudibleProductId, + DownloadFailureKind Kind, + int ConsecutiveFailures, + DateTimeOffset LastFailedAt, + DateTimeOffset RetryAfter, + string? Reason) +{ + /// The label used in the log, the CLI summary and the GUI's skipped-titles breakdown. + public string KindLabel => Kind switch + { + DownloadFailureKind.LicenseDenied => "Audible denied a download license", + DownloadFailureKind.AssetUnavailable => "Audible has no downloadable audio yet", + DownloadFailureKind.ServiceInterruption => "A possible Audible service interruption", + _ => "A previous failure" + }; +} + +/// +/// The titles a bulk or automatic download run should leave alone for now, looked up by library book. +/// +/// Read once per run: a run that takes hours must not have its own failures start suppressing the titles +/// still ahead of it in the same pass. +/// +/// +public sealed class DownloadDeferrals +{ + /// No title is deferred. Used by targeted and forced runs, which must attempt what was asked. + public static DownloadDeferrals None { get; } = new([]); + + private readonly Dictionary<(string Account, string AudibleProductId), DeferredDownload> byBook; + + private DownloadDeferrals(IEnumerable deferred) + => byBook = deferred.ToDictionary(d => (d.Account, d.AudibleProductId)); + + public static DownloadDeferrals Create(IEnumerable deferred) => new(deferred); + + /// Reads the store. Never throws: a failure here must not stop a download run. + public static DownloadDeferrals Load(DateTimeOffset now) + => Create(DownloadAttemptFailureStore.GetDeferred(now)); + + public int Count => byBook.Count; + public bool Any => byBook.Count > 0; + + public DeferredDownload? Find(LibraryBook libraryBook) + => libraryBook.Account is { } account + && byBook.TryGetValue((account, libraryBook.Book.AudibleProductId), out var deferred) + ? deferred + : null; + + public bool IsDeferred(LibraryBook libraryBook) => Find(libraryBook) is not null; +} + +/// What to tell the user about titles a run held back, instead of the full warning per title per run. +public static class DeferredDownloadUserMessage +{ + /// + /// A compact breakdown for the log, eg: + /// "Audible denied a download license: 3, Audible has no downloadable audio yet: 1". + /// + public static string BuildLogBreakdown(IEnumerable deferred) + { + var breakdown = string.Join(", ", GroupByKind(deferred).Select(g => $"{g.First().KindLabel}: {g.Count()}")); + return breakdown is "" ? "none" : breakdown; + } + + /// + /// The lines a CLI run prints in place of a full warning per title. Says how many were held back, why, + /// when the soonest will be attempted again, and how to override. + /// + public static IEnumerable BuildCliSkippedLines(IReadOnlyCollection skipped, DateTimeOffset now) + { + if (skipped.Count == 0) + yield break; + + yield return $"Skipped {"title".PluralizeWithCount(skipped.Count)} that recently failed to download. Libation will try again by itself."; + + foreach (var group in GroupByKind(skipped)) + yield return $" {group.First().KindLabel}: {group.Count()} (next attempt {DescribeWhen(group.Min(d => d.RetryAfter), now)})"; + + yield return " To try one now: libationcli liberate . For all of them: libationcli liberate --force."; + } + + /// "in about 3 hours" / "in about 12 days (9/14/2026)" - a summary should not need a clock to read. + public static string DescribeWhen(DateTimeOffset when, DateTimeOffset now) + { + var wait = when - now; + + return wait <= TimeSpan.Zero ? "on the next run" + : wait < TimeSpan.FromHours(1) ? $"in about {"minute".PluralizeWithCount(Math.Max(1, (int)wait.TotalMinutes))}" + : wait < TimeSpan.FromDays(1) ? $"in about {"hour".PluralizeWithCount((int)Math.Round(wait.TotalHours))}" + : $"in about {"day".PluralizeWithCount((int)Math.Round(wait.TotalDays))} ({when.ToLocalTime():d})"; + } + + private static IEnumerable> GroupByKind(IEnumerable deferred) + => deferred.GroupBy(d => d.Kind).OrderBy(g => g.Key); +} diff --git a/Source/ApplicationServices/DownloadAttemptFailureStore.cs b/Source/ApplicationServices/DownloadAttemptFailureStore.cs new file mode 100644 index 00000000..1679c7cd --- /dev/null +++ b/Source/ApplicationServices/DownloadAttemptFailureStore.cs @@ -0,0 +1,176 @@ +using DataLayer; +using Dinah.Core; +using Microsoft.EntityFrameworkCore; +using System; +using System.Collections.Generic; +using System.Linq; + +namespace ApplicationServices; + +/// +/// Reads and writes the record of refused download attempts that keeps a scheduled run from asking Audible +/// for the same license every time. +/// +/// Every method swallows its own errors. This is bookkeeping that makes downloading quieter; it must never +/// be the reason a download fails, and a broken query must leave downloading exactly as it was before this +/// existed. +/// +/// +public static class DownloadAttemptFailureStore +{ + /// + /// Records a failed attempt, extending the wait before the title is attempted again. A failure of a + /// different kind than last time restarts the count: Audible changed its mind about why, so the previous + /// wait no longer describes the situation. + /// + public static void Record(LibraryBook libraryBook, DownloadFailureKind kind, string? reason, DateTimeOffset? failedAt = null) + { + ArgumentNullException.ThrowIfNull(libraryBook); + + if (string.IsNullOrWhiteSpace(libraryBook.Account) || string.IsNullOrWhiteSpace(libraryBook.Book.AudibleProductId)) + return; + + try + { + var when = failedAt ?? DateTimeOffset.Now; + var account = libraryBook.Account; + var productId = libraryBook.Book.AudibleProductId; + + using var context = DbContexts.GetContext(); + var existing = context.DownloadAttemptFailures + .SingleOrDefault(f => f.Account == account && f.AudibleProductId == productId); + + var consecutiveFailures = existing is null || existing.Kind != kind ? 1 : existing.ConsecutiveFailures + 1; + var retryAfter = DownloadRetryBackoff.GetRetryAfter(kind, consecutiveFailures, when); + + if (existing is null) + context.DownloadAttemptFailures.Add(new DownloadAttemptFailure(productId, account, kind, consecutiveFailures, when, retryAfter, Truncate(reason))); + else + existing.Record(kind, consecutiveFailures, when, retryAfter, Truncate(reason)); + + context.SaveChanges(); + + Serilog.Log.Logger.Information( + "Not attempting {audibleProductId} again until {retryAfter}. {@DebugInfo}", + productId, + retryAfter.ToLocalTime(), + new { Title = libraryBook.Book.TitleWithSubtitle, Account = account.ToMask(), kind, consecutiveFailures, reason }); + } + catch (Exception ex) + { + Serilog.Log.Logger.Error( + ex, + "Failed to record a refused download attempt. The title will be attempted again on the next run. {@DebugInfo}", + new { libraryBook.Book.AudibleProductId, Title = libraryBook.Book.TitleWithSubtitle, kind }); + } + } + + /// + /// Forgets any record for this title, so it is attempted again at the next opportunity. Called when a + /// download succeeds and when the user asks for the title explicitly. + /// + public static void Clear(LibraryBook libraryBook) + { + ArgumentNullException.ThrowIfNull(libraryBook); + Clear(libraryBook.Account, libraryBook.Book.AudibleProductId); + } + + public static void Clear(string? account, string? audibleProductId) + { + if (string.IsNullOrWhiteSpace(account) || string.IsNullOrWhiteSpace(audibleProductId)) + return; + + try + { + using var context = DbContexts.GetContext(); + + // ExecuteDelete rather than a load-then-remove so the common case (nothing recorded) is one + // statement. Called after every successful download. + var deleted = context.DownloadAttemptFailures + .Where(f => f.Account == account && f.AudibleProductId == audibleProductId) + .ExecuteDelete(); + + if (deleted > 0) + Serilog.Log.Logger.Debug("Cleared the recorded download failure for {audibleProductId}", audibleProductId); + } + catch (Exception ex) + { + Serilog.Log.Logger.Error(ex, "Failed to clear the recorded download failure for {audibleProductId}", audibleProductId); + } + } + + /// Titles whose wait has not elapsed. Empty when the query fails, so downloading carries on. + public static IReadOnlyList GetDeferred(DateTimeOffset now) + { + try + { + var ticks = now.UtcTicks; + + using var context = DbContexts.GetContext(); + return Project(context.DownloadAttemptFailures.AsNoTracking().Where(f => f.RetryAfterUtcTicks > ticks)); + } + catch (Exception ex) + { + // Failing open is the safer default: a broken query must not stop titles from being downloaded. + Serilog.Log.Logger.Error(ex, "Failed to read recorded download failures. Treating every title as ready to attempt."); + return []; + } + } + + /// The current wait for one title, or null when it is ready to be attempted. Null when the query fails. + public static DeferredDownload? Find(LibraryBook libraryBook, DateTimeOffset now) + { + ArgumentNullException.ThrowIfNull(libraryBook); + + var account = libraryBook.Account; + var productId = libraryBook.Book.AudibleProductId; + + if (string.IsNullOrWhiteSpace(account) || string.IsNullOrWhiteSpace(productId)) + return null; + + try + { + var ticks = now.UtcTicks; + + using var context = DbContexts.GetContext(); + return Project( + context.DownloadAttemptFailures + .AsNoTracking() + .Where(f => f.Account == account && f.AudibleProductId == productId && f.RetryAfterUtcTicks > ticks)) + .FirstOrDefault(); + } + catch (Exception ex) + { + Serilog.Log.Logger.Error(ex, "Failed to read the recorded download failure for {audibleProductId}", productId); + return null; + } + } + + private static List Project(IQueryable query) + => query + // Materialise the columns first: the record's constructor is not translatable to SQL. + .Select(f => new + { + f.Account, + f.AudibleProductId, + f.Kind, + f.ConsecutiveFailures, + f.LastFailedAtUtcTicks, + f.RetryAfterUtcTicks, + f.Reason + }) + .ToList() + .Select(f => new DeferredDownload( + f.Account, + f.AudibleProductId, + f.Kind, + f.ConsecutiveFailures, + new DateTimeOffset(f.LastFailedAtUtcTicks, TimeSpan.Zero), + new DateTimeOffset(f.RetryAfterUtcTicks, TimeSpan.Zero), + f.Reason)) + .ToList(); + + /// Audible's messages can run long; the full text is already in the log. + private static string? Truncate(string? reason) + => reason is null || reason.Length <= 400 ? reason : reason[..400]; +} diff --git a/Source/ApplicationServices/DownloadRetryBackoff.cs b/Source/ApplicationServices/DownloadRetryBackoff.cs new file mode 100644 index 00000000..c561e7e2 --- /dev/null +++ b/Source/ApplicationServices/DownloadRetryBackoff.cs @@ -0,0 +1,50 @@ +using DataLayer; +using System; +using System.Collections.Generic; + +namespace ApplicationServices; + +/// +/// How long to leave a title alone after a download attempt Audible refused, so a scheduled run stops asking +/// for the same license every time. +/// +/// The wait doubles with each failure in a row, up to a cap, and every kind of failure has a finite cap: a +/// title held back is always attempted again eventually. Audible never distinguishes "you will never have +/// rights to this" from "not right now", so nothing here may be permanent. +/// +/// +public static class DownloadRetryBackoff +{ + private static readonly Dictionary schedule = new() + { + // An eligibility refusal changes only when the account or the catalog changes. A day matches the + // advice Libation already gives for a Plus title ("try again in 1 to 2 days"), which is the most + // common refusal that clears by itself. + [DownloadFailureKind.LicenseDenied] = (TimeSpan.FromDays(1), TimeSpan.FromDays(30)), + + // A preorder becomes downloadable on its release date, which nobody can predict from the error, so + // keep checking within a week. + [DownloadFailureKind.AssetUnavailable] = (TimeSpan.FromHours(6), TimeSpan.FromDays(7)), + + // Short: an outage that has passed should not delay a title any longer than it has to. + [DownloadFailureKind.ServiceInterruption] = (TimeSpan.FromHours(1), TimeSpan.FromHours(12)), + }; + + /// How long to wait after the th failure in a row. + public static TimeSpan GetWait(DownloadFailureKind kind, int consecutiveFailures) + { + var (first, max) = schedule.TryGetValue(kind, out var found) + ? found + : schedule[DownloadFailureKind.ServiceInterruption]; + + // Doubling in ticks would overflow long before the cap matters, so count the doublings first. + var doublings = Math.Clamp(consecutiveFailures - 1, 0, 30); + var wait = first * Math.Pow(2, doublings); + + return wait > max ? max : wait; + } + + /// When a title becomes eligible for another automatic attempt. + public static DateTimeOffset GetRetryAfter(DownloadFailureKind kind, int consecutiveFailures, DateTimeOffset failedAt) + => failedAt + GetWait(kind, consecutiveFailures); +} diff --git a/Source/ApplicationServices/LibraryCommands.cs b/Source/ApplicationServices/LibraryCommands.cs index bfa51a1c..40e69016 100644 --- a/Source/ApplicationServices/LibraryCommands.cs +++ b/Source/ApplicationServices/LibraryCommands.cs @@ -579,13 +579,19 @@ public static class LibraryCommands return 0; int qtyChanges; + var statusChanged = new List(); using (var context = DbContexts.GetContext()) { // Entry() instead of Attach() due to possible stack overflow with large tables foreach (var book in nonNullBooks) { + var statusBefore = book.Book.UserDefinedItem.BookStatus; + action?.Invoke(book.Book.UserDefinedItem); + if (book.Book.UserDefinedItem.BookStatus != statusBefore) + statusChanged.Add(book); + var udiEntity = context.Entry(book.Book.UserDefinedItem); udiEntity.State = Microsoft.EntityFrameworkCore.EntityState.Modified; @@ -596,7 +602,16 @@ public static class LibraryCommands qtyChanges = context.SaveChanges(); } if (qtyChanges > 0) + { + // Changing a title's download status is the user saying they want a different outcome for it, + // so drop any wait Libation was observing before attempting it again. Compared against the + // previous value rather than acting on every call: editing tags or a rating must not quietly + // put a title Audible just refused back into the next scheduled run. + foreach (var book in statusChanged) + DownloadAttemptFailureStore.Clear(book); + BookUserDefinedItemCommitted?.Invoke(null, nonNullBooks); + } return qtyChanges; } diff --git a/Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.Designer.cs b/Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.Designer.cs new file mode 100644 index 00000000..0eaaf6d6 --- /dev/null +++ b/Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.Designer.cs @@ -0,0 +1,578 @@ +// +using System; +using DataLayer; +using Microsoft.EntityFrameworkCore; +using Microsoft.EntityFrameworkCore.Infrastructure; +using Microsoft.EntityFrameworkCore.Migrations; +using Microsoft.EntityFrameworkCore.Storage.ValueConversion; +using Npgsql.EntityFrameworkCore.PostgreSQL.Metadata; + +#nullable disable + +namespace DataLayer.Postgres.Migrations +{ + [DbContext(typeof(LibationContext))] + [Migration("20260816160446_AddDownloadAttemptFailures")] + partial class AddDownloadAttemptFailures + { + /// + protected override void BuildTargetModel(ModelBuilder modelBuilder) + { +#pragma warning disable 612, 618 + modelBuilder + .HasAnnotation("ProductVersion", "10.0.7") + .HasAnnotation("Relational:MaxIdentifierLength", 63); + + NpgsqlModelBuilderExtensions.UseIdentityByDefaultColumns(modelBuilder); + + modelBuilder.Entity("CategoryCategoryLadder", b => + { + b.Property("_categoriesCategoryId") + .HasColumnType("integer"); + + b.Property("_categoryLaddersCategoryLadderId") + .HasColumnType("integer"); + + b.HasKey("_categoriesCategoryId", "_categoryLaddersCategoryLadderId"); + + b.HasIndex("_categoryLaddersCategoryLadderId"); + + b.ToTable("CategoryCategoryLadder"); + }); + + modelBuilder.Entity("DataLayer.Book", b => + { + b.Property("BookId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("BookId")); + + b.Property("AudibleProductId") + .IsRequired() + .HasColumnType("text"); + + b.Property("ContentType") + .HasColumnType("integer"); + + b.Property("DatePublished") + .HasColumnType("timestamp without time zone"); + + b.Property("Description") + .IsRequired() + .HasColumnType("text"); + + b.Property("IsAbridged") + .HasColumnType("boolean"); + + b.Property("IsSpatial") + .HasColumnType("boolean"); + + b.Property("Language") + .HasColumnType("text"); + + b.Property("LengthInMinutes") + .HasColumnType("integer"); + + b.Property("Locale") + .IsRequired() + .HasColumnType("text"); + + b.Property("PictureId") + .HasColumnType("text"); + + b.Property("PictureLarge") + .HasColumnType("text"); + + b.Property("Subtitle") + .IsRequired() + .HasColumnType("text"); + + b.Property("Title") + .IsRequired() + .HasColumnType("text"); + + b.HasKey("BookId"); + + b.HasIndex("AudibleProductId"); + + b.ToTable("Books"); + }); + + modelBuilder.Entity("DataLayer.BookCategory", b => + { + b.Property("BookId") + .HasColumnType("integer"); + + b.Property("CategoryLadderId") + .HasColumnType("integer"); + + b.HasKey("BookId", "CategoryLadderId"); + + b.HasIndex("BookId"); + + b.HasIndex("CategoryLadderId"); + + b.ToTable("BookCategory"); + }); + + modelBuilder.Entity("DataLayer.BookContributor", b => + { + b.Property("BookId") + .HasColumnType("integer"); + + b.Property("ContributorId") + .HasColumnType("integer"); + + b.Property("Role") + .HasColumnType("integer"); + + b.Property("Order") + .HasColumnType("smallint"); + + b.HasKey("BookId", "ContributorId", "Role"); + + b.HasIndex("BookId"); + + b.HasIndex("ContributorId"); + + b.ToTable("BookContributor"); + }); + + modelBuilder.Entity("DataLayer.Category", b => + { + b.Property("CategoryId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("CategoryId")); + + b.Property("AudibleCategoryId") + .IsRequired() + .HasColumnType("text"); + + b.Property("Name") + .IsRequired() + .HasColumnType("text"); + + b.HasKey("CategoryId"); + + b.HasIndex("AudibleCategoryId"); + + b.ToTable("Categories"); + }); + + modelBuilder.Entity("DataLayer.CategoryLadder", b => + { + b.Property("CategoryLadderId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("CategoryLadderId")); + + b.HasKey("CategoryLadderId"); + + b.ToTable("CategoryLadders"); + }); + + modelBuilder.Entity("DataLayer.Contributor", b => + { + b.Property("ContributorId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("ContributorId")); + + b.Property("AudibleContributorId") + .HasColumnType("text"); + + b.Property("Name") + .IsRequired() + .HasColumnType("text"); + + b.HasKey("ContributorId"); + + b.HasIndex("Name"); + + b.ToTable("Contributors"); + + b.HasData( + new + { + ContributorId = -1, + Name = "" + }); + }); + + modelBuilder.Entity("DataLayer.DownloadAttemptFailure", b => + { + b.Property("DownloadAttemptFailureId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("DownloadAttemptFailureId")); + + b.Property("Account") + .IsRequired() + .HasColumnType("text"); + + b.Property("AudibleProductId") + .IsRequired() + .HasColumnType("text"); + + b.Property("ConsecutiveFailures") + .HasColumnType("integer"); + + b.Property("Kind") + .HasColumnType("integer"); + + b.Property("LastFailedAtUtcTicks") + .HasColumnType("bigint"); + + b.Property("Reason") + .HasColumnType("text"); + + b.Property("RetryAfterUtcTicks") + .HasColumnType("bigint"); + + b.HasKey("DownloadAttemptFailureId"); + + b.HasIndex("Account", "AudibleProductId") + .IsUnique(); + + b.ToTable("DownloadAttemptFailures"); + }); + + modelBuilder.Entity("DataLayer.DownloadHistory", b => + { + b.Property("DownloadHistoryId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("DownloadHistoryId")); + + b.Property("AudibleProductId") + .HasColumnType("text"); + + b.Property("Bytes") + .HasColumnType("bigint"); + + b.Property("CompletedAtUtcTicks") + .HasColumnType("bigint"); + + b.Property("IsAudiblePlus") + .HasColumnType("boolean"); + + b.HasKey("DownloadHistoryId"); + + b.HasIndex("CompletedAtUtcTicks"); + + b.ToTable("DownloadHistory"); + }); + + modelBuilder.Entity("DataLayer.LibraryBook", b => + { + b.Property("BookId") + .HasColumnType("integer"); + + b.Property("AbsentFromLastScan") + .HasColumnType("boolean"); + + b.Property("Account") + .IsRequired() + .HasColumnType("text"); + + b.Property("DateAdded") + .HasColumnType("timestamp without time zone"); + + b.Property("IncludedUntil") + .HasColumnType("timestamp without time zone"); + + b.Property("IsAudiblePlus") + .HasColumnType("boolean"); + + b.Property("IsDeleted") + .HasColumnType("boolean"); + + b.HasKey("BookId"); + + b.ToTable("LibraryBooks"); + }); + + modelBuilder.Entity("DataLayer.Series", b => + { + b.Property("SeriesId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("SeriesId")); + + b.Property("AudibleSeriesId") + .IsRequired() + .HasColumnType("text"); + + b.Property("Name") + .HasColumnType("text"); + + b.HasKey("SeriesId"); + + b.HasIndex("AudibleSeriesId"); + + b.ToTable("Series"); + }); + + modelBuilder.Entity("DataLayer.SeriesBook", b => + { + b.Property("SeriesId") + .HasColumnType("integer"); + + b.Property("BookId") + .HasColumnType("integer"); + + b.Property("Order") + .HasColumnType("text"); + + b.HasKey("SeriesId", "BookId"); + + b.HasIndex("BookId"); + + b.HasIndex("SeriesId"); + + b.ToTable("SeriesBook"); + }); + + modelBuilder.Entity("CategoryCategoryLadder", b => + { + b.HasOne("DataLayer.Category", null) + .WithMany() + .HasForeignKey("_categoriesCategoryId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.CategoryLadder", null) + .WithMany() + .HasForeignKey("_categoryLaddersCategoryLadderId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + }); + + modelBuilder.Entity("DataLayer.Book", b => + { + b.OwnsOne("DataLayer.Rating", "Rating", b1 => + { + b1.Property("BookId") + .HasColumnType("integer"); + + b1.Property("OverallRating") + .HasColumnType("real"); + + b1.Property("PerformanceRating") + .HasColumnType("real"); + + b1.Property("StoryRating") + .HasColumnType("real"); + + b1.HasKey("BookId"); + + b1.ToTable("Books"); + + b1.WithOwner() + .HasForeignKey("BookId"); + }); + + b.OwnsMany("DataLayer.Supplement", "Supplements", b1 => + { + b1.Property("SupplementId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b1.Property("SupplementId")); + + b1.Property("BookId") + .HasColumnType("integer"); + + b1.Property("Url") + .IsRequired() + .HasColumnType("text"); + + b1.HasKey("SupplementId"); + + b1.HasIndex("BookId"); + + b1.ToTable("Supplement"); + + b1.WithOwner("Book") + .HasForeignKey("BookId"); + + b1.Navigation("Book"); + }); + + b.OwnsOne("DataLayer.UserDefinedItem", "UserDefinedItem", b1 => + { + b1.Property("BookId") + .HasColumnType("integer"); + + b1.Property("BookStatus") + .HasColumnType("integer"); + + b1.Property("IsFinished") + .HasColumnType("boolean"); + + b1.Property("LastDownloaded") + .HasColumnType("timestamp without time zone"); + + b1.Property("LastDownloadedFileVersion") + .HasColumnType("text"); + + b1.Property("LastDownloadedFormat") + .HasColumnType("bigint"); + + b1.Property("LastDownloadedVersion") + .HasColumnType("text"); + + b1.Property("PdfStatus") + .HasColumnType("integer"); + + b1.Property("Tags") + .IsRequired() + .HasColumnType("text"); + + b1.HasKey("BookId"); + + b1.ToTable("UserDefinedItem", (string)null); + + b1.WithOwner("Book") + .HasForeignKey("BookId"); + + b1.OwnsOne("DataLayer.Rating", "Rating", b2 => + { + b2.Property("UserDefinedItemBookId") + .HasColumnType("integer"); + + b2.Property("OverallRating") + .HasColumnType("real"); + + b2.Property("PerformanceRating") + .HasColumnType("real"); + + b2.Property("StoryRating") + .HasColumnType("real"); + + b2.HasKey("UserDefinedItemBookId"); + + b2.ToTable("UserDefinedItem"); + + b2.WithOwner() + .HasForeignKey("UserDefinedItemBookId"); + }); + + b1.Navigation("Book"); + + b1.Navigation("Rating") + .IsRequired(); + }); + + b.Navigation("Rating") + .IsRequired(); + + b.Navigation("Supplements"); + + b.Navigation("UserDefinedItem") + .IsRequired(); + }); + + modelBuilder.Entity("DataLayer.BookCategory", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithMany("CategoriesLink") + .HasForeignKey("BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.CategoryLadder", "CategoryLadder") + .WithMany("BooksLink") + .HasForeignKey("CategoryLadderId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + + b.Navigation("CategoryLadder"); + }); + + modelBuilder.Entity("DataLayer.BookContributor", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithMany("ContributorsLink") + .HasForeignKey("BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.Contributor", "Contributor") + .WithMany("BooksLink") + .HasForeignKey("ContributorId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + + b.Navigation("Contributor"); + }); + + modelBuilder.Entity("DataLayer.LibraryBook", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithOne() + .HasForeignKey("DataLayer.LibraryBook", "BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + }); + + modelBuilder.Entity("DataLayer.SeriesBook", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithMany("SeriesLink") + .HasForeignKey("BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.Series", "Series") + .WithMany("BooksLink") + .HasForeignKey("SeriesId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + + b.Navigation("Series"); + }); + + modelBuilder.Entity("DataLayer.Book", b => + { + b.Navigation("CategoriesLink"); + + b.Navigation("ContributorsLink"); + + b.Navigation("SeriesLink"); + }); + + modelBuilder.Entity("DataLayer.CategoryLadder", b => + { + b.Navigation("BooksLink"); + }); + + modelBuilder.Entity("DataLayer.Contributor", b => + { + b.Navigation("BooksLink"); + }); + + modelBuilder.Entity("DataLayer.Series", b => + { + b.Navigation("BooksLink"); + }); +#pragma warning restore 612, 618 + } + } +} diff --git a/Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.cs b/Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.cs new file mode 100644 index 00000000..63e0eabe --- /dev/null +++ b/Source/DataLayer.Postgres/Migrations/20260816160446_AddDownloadAttemptFailures.cs @@ -0,0 +1,47 @@ +using Microsoft.EntityFrameworkCore.Migrations; +using Npgsql.EntityFrameworkCore.PostgreSQL.Metadata; + +#nullable disable + +namespace DataLayer.Postgres.Migrations +{ + /// + public partial class AddDownloadAttemptFailures : Migration + { + /// + protected override void Up(MigrationBuilder migrationBuilder) + { + migrationBuilder.CreateTable( + name: "DownloadAttemptFailures", + columns: table => new + { + DownloadAttemptFailureId = table.Column(type: "integer", nullable: false) + .Annotation("Npgsql:ValueGenerationStrategy", NpgsqlValueGenerationStrategy.IdentityByDefaultColumn), + AudibleProductId = table.Column(type: "text", nullable: false), + Account = table.Column(type: "text", nullable: false), + Kind = table.Column(type: "integer", nullable: false), + ConsecutiveFailures = table.Column(type: "integer", nullable: false), + LastFailedAtUtcTicks = table.Column(type: "bigint", nullable: false), + RetryAfterUtcTicks = table.Column(type: "bigint", nullable: false), + Reason = table.Column(type: "text", nullable: true) + }, + constraints: table => + { + table.PrimaryKey("PK_DownloadAttemptFailures", x => x.DownloadAttemptFailureId); + }); + + migrationBuilder.CreateIndex( + name: "IX_DownloadAttemptFailures_Account_AudibleProductId", + table: "DownloadAttemptFailures", + columns: new[] { "Account", "AudibleProductId" }, + unique: true); + } + + /// + protected override void Down(MigrationBuilder migrationBuilder) + { + migrationBuilder.DropTable( + name: "DownloadAttemptFailures"); + } + } +} diff --git a/Source/DataLayer.Postgres/Migrations/LibationContextModelSnapshot.cs b/Source/DataLayer.Postgres/Migrations/LibationContextModelSnapshot.cs index 1e4cffb9..59e0e8ce 100644 --- a/Source/DataLayer.Postgres/Migrations/LibationContextModelSnapshot.cs +++ b/Source/DataLayer.Postgres/Migrations/LibationContextModelSnapshot.cs @@ -201,6 +201,45 @@ namespace DataLayer.Postgres.Migrations }); }); + modelBuilder.Entity("DataLayer.DownloadAttemptFailure", b => + { + b.Property("DownloadAttemptFailureId") + .ValueGeneratedOnAdd() + .HasColumnType("integer"); + + NpgsqlPropertyBuilderExtensions.UseIdentityByDefaultColumn(b.Property("DownloadAttemptFailureId")); + + b.Property("Account") + .IsRequired() + .HasColumnType("text"); + + b.Property("AudibleProductId") + .IsRequired() + .HasColumnType("text"); + + b.Property("ConsecutiveFailures") + .HasColumnType("integer"); + + b.Property("Kind") + .HasColumnType("integer"); + + b.Property("LastFailedAtUtcTicks") + .HasColumnType("bigint"); + + b.Property("Reason") + .HasColumnType("text"); + + b.Property("RetryAfterUtcTicks") + .HasColumnType("bigint"); + + b.HasKey("DownloadAttemptFailureId"); + + b.HasIndex("Account", "AudibleProductId") + .IsUnique(); + + b.ToTable("DownloadAttemptFailures"); + }); + modelBuilder.Entity("DataLayer.DownloadHistory", b => { b.Property("DownloadHistoryId") diff --git a/Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.Designer.cs b/Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.Designer.cs new file mode 100644 index 00000000..35a9fda5 --- /dev/null +++ b/Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.Designer.cs @@ -0,0 +1,557 @@ +// +using System; +using DataLayer; +using Microsoft.EntityFrameworkCore; +using Microsoft.EntityFrameworkCore.Infrastructure; +using Microsoft.EntityFrameworkCore.Migrations; +using Microsoft.EntityFrameworkCore.Storage.ValueConversion; + +#nullable disable + +namespace DataLayer.Migrations +{ + [DbContext(typeof(LibationContext))] + [Migration("20260816160439_AddDownloadAttemptFailures")] + partial class AddDownloadAttemptFailures + { + /// + protected override void BuildTargetModel(ModelBuilder modelBuilder) + { +#pragma warning disable 612, 618 + modelBuilder.HasAnnotation("ProductVersion", "10.0.7"); + + modelBuilder.Entity("CategoryCategoryLadder", b => + { + b.Property("_categoriesCategoryId") + .HasColumnType("INTEGER"); + + b.Property("_categoryLaddersCategoryLadderId") + .HasColumnType("INTEGER"); + + b.HasKey("_categoriesCategoryId", "_categoryLaddersCategoryLadderId"); + + b.HasIndex("_categoryLaddersCategoryLadderId"); + + b.ToTable("CategoryCategoryLadder"); + }); + + modelBuilder.Entity("DataLayer.Book", b => + { + b.Property("BookId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("AudibleProductId") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("ContentType") + .HasColumnType("INTEGER"); + + b.Property("DatePublished") + .HasColumnType("TEXT"); + + b.Property("Description") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("IsAbridged") + .HasColumnType("INTEGER"); + + b.Property("IsSpatial") + .HasColumnType("INTEGER"); + + b.Property("Language") + .HasColumnType("TEXT"); + + b.Property("LengthInMinutes") + .HasColumnType("INTEGER"); + + b.Property("Locale") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("PictureId") + .HasColumnType("TEXT"); + + b.Property("PictureLarge") + .HasColumnType("TEXT"); + + b.Property("Subtitle") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("Title") + .IsRequired() + .HasColumnType("TEXT"); + + b.HasKey("BookId"); + + b.HasIndex("AudibleProductId"); + + b.ToTable("Books"); + }); + + modelBuilder.Entity("DataLayer.BookCategory", b => + { + b.Property("BookId") + .HasColumnType("INTEGER"); + + b.Property("CategoryLadderId") + .HasColumnType("INTEGER"); + + b.HasKey("BookId", "CategoryLadderId"); + + b.HasIndex("BookId"); + + b.HasIndex("CategoryLadderId"); + + b.ToTable("BookCategory"); + }); + + modelBuilder.Entity("DataLayer.BookContributor", b => + { + b.Property("BookId") + .HasColumnType("INTEGER"); + + b.Property("ContributorId") + .HasColumnType("INTEGER"); + + b.Property("Role") + .HasColumnType("INTEGER"); + + b.Property("Order") + .HasColumnType("INTEGER"); + + b.HasKey("BookId", "ContributorId", "Role"); + + b.HasIndex("BookId"); + + b.HasIndex("ContributorId"); + + b.ToTable("BookContributor"); + }); + + modelBuilder.Entity("DataLayer.Category", b => + { + b.Property("CategoryId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("AudibleCategoryId") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("Name") + .IsRequired() + .HasColumnType("TEXT"); + + b.HasKey("CategoryId"); + + b.HasIndex("AudibleCategoryId"); + + b.ToTable("Categories"); + }); + + modelBuilder.Entity("DataLayer.CategoryLadder", b => + { + b.Property("CategoryLadderId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.HasKey("CategoryLadderId"); + + b.ToTable("CategoryLadders"); + }); + + modelBuilder.Entity("DataLayer.Contributor", b => + { + b.Property("ContributorId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("AudibleContributorId") + .HasColumnType("TEXT"); + + b.Property("Name") + .IsRequired() + .HasColumnType("TEXT"); + + b.HasKey("ContributorId"); + + b.HasIndex("Name"); + + b.ToTable("Contributors"); + + b.HasData( + new + { + ContributorId = -1, + Name = "" + }); + }); + + modelBuilder.Entity("DataLayer.DownloadAttemptFailure", b => + { + b.Property("DownloadAttemptFailureId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("Account") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("AudibleProductId") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("ConsecutiveFailures") + .HasColumnType("INTEGER"); + + b.Property("Kind") + .HasColumnType("INTEGER"); + + b.Property("LastFailedAtUtcTicks") + .HasColumnType("INTEGER"); + + b.Property("Reason") + .HasColumnType("TEXT"); + + b.Property("RetryAfterUtcTicks") + .HasColumnType("INTEGER"); + + b.HasKey("DownloadAttemptFailureId"); + + b.HasIndex("Account", "AudibleProductId") + .IsUnique(); + + b.ToTable("DownloadAttemptFailures"); + }); + + modelBuilder.Entity("DataLayer.DownloadHistory", b => + { + b.Property("DownloadHistoryId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("AudibleProductId") + .HasColumnType("TEXT"); + + b.Property("Bytes") + .HasColumnType("INTEGER"); + + b.Property("CompletedAtUtcTicks") + .HasColumnType("INTEGER"); + + b.Property("IsAudiblePlus") + .HasColumnType("INTEGER"); + + b.HasKey("DownloadHistoryId"); + + b.HasIndex("CompletedAtUtcTicks"); + + b.ToTable("DownloadHistory"); + }); + + modelBuilder.Entity("DataLayer.LibraryBook", b => + { + b.Property("BookId") + .HasColumnType("INTEGER"); + + b.Property("AbsentFromLastScan") + .HasColumnType("INTEGER"); + + b.Property("Account") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("DateAdded") + .HasColumnType("TEXT"); + + b.Property("IncludedUntil") + .HasColumnType("TEXT"); + + b.Property("IsAudiblePlus") + .HasColumnType("INTEGER"); + + b.Property("IsDeleted") + .HasColumnType("INTEGER"); + + b.HasKey("BookId"); + + b.ToTable("LibraryBooks"); + }); + + modelBuilder.Entity("DataLayer.Series", b => + { + b.Property("SeriesId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("AudibleSeriesId") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("Name") + .HasColumnType("TEXT"); + + b.HasKey("SeriesId"); + + b.HasIndex("AudibleSeriesId"); + + b.ToTable("Series"); + }); + + modelBuilder.Entity("DataLayer.SeriesBook", b => + { + b.Property("SeriesId") + .HasColumnType("INTEGER"); + + b.Property("BookId") + .HasColumnType("INTEGER"); + + b.Property("Order") + .HasColumnType("TEXT"); + + b.HasKey("SeriesId", "BookId"); + + b.HasIndex("BookId"); + + b.HasIndex("SeriesId"); + + b.ToTable("SeriesBook"); + }); + + modelBuilder.Entity("CategoryCategoryLadder", b => + { + b.HasOne("DataLayer.Category", null) + .WithMany() + .HasForeignKey("_categoriesCategoryId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.CategoryLadder", null) + .WithMany() + .HasForeignKey("_categoryLaddersCategoryLadderId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + }); + + modelBuilder.Entity("DataLayer.Book", b => + { + b.OwnsOne("DataLayer.Rating", "Rating", b1 => + { + b1.Property("BookId") + .HasColumnType("INTEGER"); + + b1.Property("OverallRating") + .HasColumnType("REAL"); + + b1.Property("PerformanceRating") + .HasColumnType("REAL"); + + b1.Property("StoryRating") + .HasColumnType("REAL"); + + b1.HasKey("BookId"); + + b1.ToTable("Books"); + + b1.WithOwner() + .HasForeignKey("BookId"); + }); + + b.OwnsMany("DataLayer.Supplement", "Supplements", b1 => + { + b1.Property("SupplementId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b1.Property("BookId") + .HasColumnType("INTEGER"); + + b1.Property("Url") + .IsRequired() + .HasColumnType("TEXT"); + + b1.HasKey("SupplementId"); + + b1.HasIndex("BookId"); + + b1.ToTable("Supplement"); + + b1.WithOwner("Book") + .HasForeignKey("BookId"); + + b1.Navigation("Book"); + }); + + b.OwnsOne("DataLayer.UserDefinedItem", "UserDefinedItem", b1 => + { + b1.Property("BookId") + .HasColumnType("INTEGER"); + + b1.Property("BookStatus") + .HasColumnType("INTEGER"); + + b1.Property("IsFinished") + .HasColumnType("INTEGER"); + + b1.Property("LastDownloaded") + .HasColumnType("TEXT"); + + b1.Property("LastDownloadedFileVersion") + .HasColumnType("TEXT"); + + b1.Property("LastDownloadedFormat") + .HasColumnType("INTEGER"); + + b1.Property("LastDownloadedVersion") + .HasColumnType("TEXT"); + + b1.Property("PdfStatus") + .HasColumnType("INTEGER"); + + b1.Property("Tags") + .IsRequired() + .HasColumnType("TEXT"); + + b1.HasKey("BookId"); + + b1.ToTable("UserDefinedItem", (string)null); + + b1.WithOwner("Book") + .HasForeignKey("BookId"); + + b1.OwnsOne("DataLayer.Rating", "Rating", b2 => + { + b2.Property("UserDefinedItemBookId") + .HasColumnType("INTEGER"); + + b2.Property("OverallRating") + .HasColumnType("REAL"); + + b2.Property("PerformanceRating") + .HasColumnType("REAL"); + + b2.Property("StoryRating") + .HasColumnType("REAL"); + + b2.HasKey("UserDefinedItemBookId"); + + b2.ToTable("UserDefinedItem"); + + b2.WithOwner() + .HasForeignKey("UserDefinedItemBookId"); + }); + + b1.Navigation("Book"); + + b1.Navigation("Rating") + .IsRequired(); + }); + + b.Navigation("Rating") + .IsRequired(); + + b.Navigation("Supplements"); + + b.Navigation("UserDefinedItem") + .IsRequired(); + }); + + modelBuilder.Entity("DataLayer.BookCategory", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithMany("CategoriesLink") + .HasForeignKey("BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.CategoryLadder", "CategoryLadder") + .WithMany("BooksLink") + .HasForeignKey("CategoryLadderId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + + b.Navigation("CategoryLadder"); + }); + + modelBuilder.Entity("DataLayer.BookContributor", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithMany("ContributorsLink") + .HasForeignKey("BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.Contributor", "Contributor") + .WithMany("BooksLink") + .HasForeignKey("ContributorId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + + b.Navigation("Contributor"); + }); + + modelBuilder.Entity("DataLayer.LibraryBook", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithOne() + .HasForeignKey("DataLayer.LibraryBook", "BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + }); + + modelBuilder.Entity("DataLayer.SeriesBook", b => + { + b.HasOne("DataLayer.Book", "Book") + .WithMany("SeriesLink") + .HasForeignKey("BookId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.HasOne("DataLayer.Series", "Series") + .WithMany("BooksLink") + .HasForeignKey("SeriesId") + .OnDelete(DeleteBehavior.Cascade) + .IsRequired(); + + b.Navigation("Book"); + + b.Navigation("Series"); + }); + + modelBuilder.Entity("DataLayer.Book", b => + { + b.Navigation("CategoriesLink"); + + b.Navigation("ContributorsLink"); + + b.Navigation("SeriesLink"); + }); + + modelBuilder.Entity("DataLayer.CategoryLadder", b => + { + b.Navigation("BooksLink"); + }); + + modelBuilder.Entity("DataLayer.Contributor", b => + { + b.Navigation("BooksLink"); + }); + + modelBuilder.Entity("DataLayer.Series", b => + { + b.Navigation("BooksLink"); + }); +#pragma warning restore 612, 618 + } + } +} diff --git a/Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.cs b/Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.cs new file mode 100644 index 00000000..69eca2ba --- /dev/null +++ b/Source/DataLayer.Sqlite/Migrations/20260816160439_AddDownloadAttemptFailures.cs @@ -0,0 +1,46 @@ +using Microsoft.EntityFrameworkCore.Migrations; + +#nullable disable + +namespace DataLayer.Migrations +{ + /// + public partial class AddDownloadAttemptFailures : Migration + { + /// + protected override void Up(MigrationBuilder migrationBuilder) + { + migrationBuilder.CreateTable( + name: "DownloadAttemptFailures", + columns: table => new + { + DownloadAttemptFailureId = table.Column(type: "INTEGER", nullable: false) + .Annotation("Sqlite:Autoincrement", true), + AudibleProductId = table.Column(type: "TEXT", nullable: false), + Account = table.Column(type: "TEXT", nullable: false), + Kind = table.Column(type: "INTEGER", nullable: false), + ConsecutiveFailures = table.Column(type: "INTEGER", nullable: false), + LastFailedAtUtcTicks = table.Column(type: "INTEGER", nullable: false), + RetryAfterUtcTicks = table.Column(type: "INTEGER", nullable: false), + Reason = table.Column(type: "TEXT", nullable: true) + }, + constraints: table => + { + table.PrimaryKey("PK_DownloadAttemptFailures", x => x.DownloadAttemptFailureId); + }); + + migrationBuilder.CreateIndex( + name: "IX_DownloadAttemptFailures_Account_AudibleProductId", + table: "DownloadAttemptFailures", + columns: new[] { "Account", "AudibleProductId" }, + unique: true); + } + + /// + protected override void Down(MigrationBuilder migrationBuilder) + { + migrationBuilder.DropTable( + name: "DownloadAttemptFailures"); + } + } +} diff --git a/Source/DataLayer.Sqlite/Migrations/LibationContextModelSnapshot.cs b/Source/DataLayer.Sqlite/Migrations/LibationContextModelSnapshot.cs index 4a5c84d4..3787d1bf 100644 --- a/Source/DataLayer.Sqlite/Migrations/LibationContextModelSnapshot.cs +++ b/Source/DataLayer.Sqlite/Migrations/LibationContextModelSnapshot.cs @@ -188,6 +188,43 @@ namespace DataLayer.Migrations }); }); + modelBuilder.Entity("DataLayer.DownloadAttemptFailure", b => + { + b.Property("DownloadAttemptFailureId") + .ValueGeneratedOnAdd() + .HasColumnType("INTEGER"); + + b.Property("Account") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("AudibleProductId") + .IsRequired() + .HasColumnType("TEXT"); + + b.Property("ConsecutiveFailures") + .HasColumnType("INTEGER"); + + b.Property("Kind") + .HasColumnType("INTEGER"); + + b.Property("LastFailedAtUtcTicks") + .HasColumnType("INTEGER"); + + b.Property("Reason") + .HasColumnType("TEXT"); + + b.Property("RetryAfterUtcTicks") + .HasColumnType("INTEGER"); + + b.HasKey("DownloadAttemptFailureId"); + + b.HasIndex("Account", "AudibleProductId") + .IsUnique(); + + b.ToTable("DownloadAttemptFailures"); + }); + modelBuilder.Entity("DataLayer.DownloadHistory", b => { b.Property("DownloadHistoryId") diff --git a/Source/DataLayer/Configurations/DownloadAttemptFailureConfig.cs b/Source/DataLayer/Configurations/DownloadAttemptFailureConfig.cs new file mode 100644 index 00000000..b4ceb100 --- /dev/null +++ b/Source/DataLayer/Configurations/DownloadAttemptFailureConfig.cs @@ -0,0 +1,16 @@ +using Microsoft.EntityFrameworkCore; +using Microsoft.EntityFrameworkCore.Metadata.Builders; + +namespace DataLayer.Configurations; + +internal class DownloadAttemptFailureConfig : IEntityTypeConfiguration +{ + public void Configure(EntityTypeBuilder entity) + { + entity.HasKey(f => f.DownloadAttemptFailureId); + + // One row per title per account, upserted on each failure: the point is to remember the latest + // verdict, not to accumulate a history. + entity.HasIndex(f => new { f.Account, f.AudibleProductId }).IsUnique(); + } +} diff --git a/Source/DataLayer/EfClasses/DownloadAttemptFailure.cs b/Source/DataLayer/EfClasses/DownloadAttemptFailure.cs new file mode 100644 index 00000000..a9d7ec77 --- /dev/null +++ b/Source/DataLayer/EfClasses/DownloadAttemptFailure.cs @@ -0,0 +1,98 @@ +using System; + +namespace DataLayer; + +/// +/// Why a download attempt failed, coarse enough to choose how long to wait before trying again. +/// Persisted as an int; do not renumber. +/// +public enum DownloadFailureKind +{ + /// + /// Audible refused a content license and named an eligibility reason: the title is not owned, is not in + /// the Plus catalog, or the account is not entitled to it. Changes only when the account or the catalog + /// changes, so this is worth waiting a long time on. + /// + LicenseDenied = 0, + + /// + /// Audible accepted the request but has no downloadable asset, as for a preorder that has not been + /// released. Expected to start working by itself once the title is published. + /// + AssetUnavailable = 1, + + /// + /// Looks like a service interruption or throttling rather than a decision about this title. Retried soon. + /// + ServiceInterruption = 2, +} + +/// +/// The most recent failed attempt to download one title, so that a title Audible has just refused is not +/// requested again on every run. One row per (account, title): the same ASIN can be refused on one account +/// and downloadable on another. +/// +/// Nothing here is permanent. always names a time, so a title held back +/// because of an outage, throttling or an unreleased preorder starts being attempted again on its own. +/// +/// +/// The database is deliberately the home for this instead of a file under LibationFiles: in Docker, +/// LibationFiles is a throwaway directory inside the container and only the database is on a volume, so a +/// file-based record would forget every failure on each container start - exactly the case this fixes. +/// +/// +public class DownloadAttemptFailure +{ + internal int DownloadAttemptFailureId { get; private set; } + + public string AudibleProductId { get; private set; } + + /// The the attempt was made with. + public string Account { get; private set; } + + public DownloadFailureKind Kind { get; private set; } + + /// Failures in a row without an intervening success. Drives how long the next wait is. + public int ConsecutiveFailures { get; private set; } + + /// + /// UTC ticks rather than a DateTime so range queries mean the same thing on SQLite and PostgreSQL. + /// Local time is for display only. + /// + public long LastFailedAtUtcTicks { get; private set; } + + /// When this title becomes eligible for another automatic attempt, in UTC ticks. + public long RetryAfterUtcTicks { get; private set; } + + /// One line from Audible, kept so the user can be told why without re-requesting a license. + public string? Reason { get; private set; } + + public DateTimeOffset LastFailedAt => new(LastFailedAtUtcTicks, TimeSpan.Zero); + public DateTimeOffset RetryAfter => new(RetryAfterUtcTicks, TimeSpan.Zero); + + private DownloadAttemptFailure() + { + // for EF + AudibleProductId = null!; + Account = null!; + } + + public DownloadAttemptFailure(string audibleProductId, string account, DownloadFailureKind kind, int consecutiveFailures, DateTimeOffset lastFailedAt, DateTimeOffset retryAfter, string? reason) + { + AudibleProductId = audibleProductId; + Account = account; + Record(kind, consecutiveFailures, lastFailedAt, retryAfter, reason); + } + + public void Record(DownloadFailureKind kind, int consecutiveFailures, DateTimeOffset lastFailedAt, DateTimeOffset retryAfter, string? reason) + { + Kind = kind; + ConsecutiveFailures = consecutiveFailures; + LastFailedAtUtcTicks = lastFailedAt.UtcTicks; + RetryAfterUtcTicks = retryAfter.UtcTicks; + Reason = reason; + } + + public override string ToString() + => $"{AudibleProductId} {Kind} x{ConsecutiveFailures}, retry after {RetryAfter.ToLocalTime()}"; +} diff --git a/Source/DataLayer/LibationContext.cs b/Source/DataLayer/LibationContext.cs index 795c26d6..2d88f246 100644 --- a/Source/DataLayer/LibationContext.cs +++ b/Source/DataLayer/LibationContext.cs @@ -27,6 +27,7 @@ public class LibationContext : DbContext, INotifyDisposed public DbSet Categories { get; private set; } public DbSet CategoryLadders { get; private set; } public DbSet DownloadHistory { get; private set; } + public DbSet DownloadAttemptFailures { get; private set; } public event EventHandler? ObjectDisposed; public override void Dispose() @@ -58,6 +59,7 @@ public class LibationContext : DbContext, INotifyDisposed modelBuilder.ApplyConfiguration(new CategoryLadderConfig()); modelBuilder.ApplyConfiguration(new BookCategoryConfig()); modelBuilder.ApplyConfiguration(new DownloadHistoryConfig()); + modelBuilder.ApplyConfiguration(new DownloadAttemptFailureConfig()); // views are now supported via "keyless entity types" (instead of "entity types" or the prev "query types"): // https://docs.microsoft.com/en-us/ef/core/modeling/keyless-entity-types diff --git a/Source/FileLiberator/DownloadDecryptBook.cs b/Source/FileLiberator/DownloadDecryptBook.cs index 56cd007f..4e6bedae 100644 --- a/Source/FileLiberator/DownloadDecryptBook.cs +++ b/Source/FileLiberator/DownloadDecryptBook.cs @@ -28,6 +28,8 @@ public class DownloadDecryptBook : AudioDecodable, IProcessable !libraryBook.Book.AudioExists; + protected override bool RecordsAttemptFailures => true; + public override async Task CancelAsync() { if (abDownloader is not null) await abDownloader.CancelAsync(); diff --git a/Source/FileLiberator/DownloadFailureClassifier.cs b/Source/FileLiberator/DownloadFailureClassifier.cs new file mode 100644 index 00000000..cacd2a68 --- /dev/null +++ b/Source/FileLiberator/DownloadFailureClassifier.cs @@ -0,0 +1,88 @@ +using AudibleApi; +using AudibleApi.Common; +using DataLayer; +using System; +using System.Collections.Generic; +using System.Diagnostics.CodeAnalysis; +using System.Linq; + +namespace FileLiberator; + +/// What Libation understood about a failed download attempt, and how long to wait because of it. +public sealed record DownloadFailureDiagnosis(DownloadFailureKind Kind, string Reason); + +/// +/// Recognises the download failures that mean "asking again right now will fail the same way": Audible +/// refusing a license, and Audible having no audio to deliver. +/// +/// Only failures recognised here are recorded and waited on. Everything else - a dropped connection, a +/// decrypt error, a full disk - keeps the long-standing behaviour of being retried on the next run, because +/// there is no reason to believe the next attempt fails for the same reason. +/// +/// +public static class DownloadFailureClassifier +{ + /// + /// Substring in Audible's Sable error when no audio asset exists for the title, which is what an + /// unreleased preorder looks like. Shared with , + /// which pairs it with an error code to spot a much narrower case. + /// + private const string NoAudioAssetMarker = "acr:null"; + + public static bool TryClassify(Exception ex, [NotNullWhen(true)] out DownloadFailureDiagnosis? diagnosis) + { + diagnosis = Classify(ex); + return diagnosis is not null; + } + + public static DownloadFailureDiagnosis? Classify(Exception? ex) + => ex switch + { + null => null, + ContentLicenseDeniedException denied => ClassifyLicenseDenial(denied), + ApiErrorException api => ClassifyApiError(api), + // A rethrown Widevine failure arrives wrapped by whichever step gave up on it. + _ => Classify(ex.InnerException) + }; + + /// + /// Audible attaches a rejection reason per validation type. GenericError is Audible declining to + /// say why, which in practice means an outage or throttling rather than a decision about the title; the + /// GUI already treats it that way when it offers guidance. Anything else names an eligibility problem + /// with the account or the title, which will not change within the hour. + /// + private static DownloadFailureDiagnosis ClassifyLicenseDenial(ContentLicenseDeniedException ex) + { + LicenseDenialReason?[] reasons = [ex.Ownership, ex.AYCL, ex.Membership, ex.Client]; + + var looksLikeOutage + = ex.AYCL?.RejectionReason is null or RejectionReason.GenericError + || reasons.Any(r => r?.RejectionReason is RejectionReason.GenericError); + + return new DownloadFailureDiagnosis( + looksLikeOutage ? DownloadFailureKind.ServiceInterruption : DownloadFailureKind.LicenseDenied, + BuildLicenseDenialReason(reasons) ?? ex.Message); + } + + /// The most specific message Audible gave, prefixed with which check it failed. + private static string? BuildLicenseDenialReason(IEnumerable reasons) + => reasons + .Where(r => !string.IsNullOrWhiteSpace(r?.Message)) + .Select(r => r!.ValidationType is { Length: > 0 } type ? $"{type}: {r.Message}" : r.Message) + .FirstOrDefault(); + + /// + /// A license request that fails with no content reference (acr:null) means Audible has nothing to + /// deliver for this title yet, which is what a preorder that has not been released looks like. + /// + private static DownloadFailureDiagnosis? ClassifyApiError(ApiErrorException ex) + { + if (ex.RequestUri?.Contains("/licenserequest", StringComparison.OrdinalIgnoreCase) is not true + || ex.JsonMessage?.Contains(NoAudioAssetMarker, StringComparison.Ordinal) is not true) + return null; + + return new DownloadFailureDiagnosis( + DownloadFailureKind.AssetUnavailable, + "Audible returned no audio for this title. An unreleased preorder looks like this; so does a title Audible has not finished preparing."); + } +} diff --git a/Source/FileLiberator/Processable.cs b/Source/FileLiberator/Processable.cs index 813029ab..22ad9dae 100644 --- a/Source/FileLiberator/Processable.cs +++ b/Source/FileLiberator/Processable.cs @@ -1,4 +1,5 @@ -using DataLayer; +using ApplicationServices; +using DataLayer; using Dinah.Core; using Dinah.Core.ErrorHandling; using Dinah.Core.Net.Http; @@ -42,6 +43,13 @@ public abstract class Processable /// True == success public abstract Task ProcessAsync(LibraryBook libraryBook); + /// + /// Whether a refusal from Audible during this step should be remembered, so a scheduled run stops asking + /// for the same license every time. Only the audiobook download does: it is the request Audible refuses, + /// and the record gates that same request. + /// + protected virtual bool RecordsAttemptFailures => false; + // when used in foreach: stateful. deferred execution public IEnumerable GetValidLibraryBooks(IEnumerable library) => library.Where(libraryBook => @@ -62,15 +70,42 @@ public abstract class Processable Account = libraryBook.Account?.ToMask() ?? "[empty]" }); - var status - = (await ProcessAsync(libraryBook)) - ?? new StatusHandler { "Processable should never return a null status" }; + StatusHandler status; + try + { + status + = (await ProcessAsync(libraryBook)) + ?? new StatusHandler { "Processable should never return a null status" }; + } + catch (Exception ex) + { + RecordAttemptFailure(libraryBook, ex); + throw; + } + finally + { + GC.Collect(GC.MaxGeneration, GCCollectionMode.Aggressive, true, true); + } - GC.Collect(GC.MaxGeneration, GCCollectionMode.Aggressive, true, true); + if (status.IsSuccess && RecordsAttemptFailures) + DownloadAttemptFailureStore.Clear(libraryBook); return status; } + /// + /// Recorded here rather than in each host so the CLI, the GUI queue and anything added later all remember + /// a refusal the same way. Failures Libation cannot attribute to Audible are left unrecorded and keep + /// being retried on the next run. + /// + private void RecordAttemptFailure(LibraryBook libraryBook, Exception ex) + { + if (!RecordsAttemptFailures || !DownloadFailureClassifier.TryClassify(ex, out var diagnosis)) + return; + + DownloadAttemptFailureStore.Record(libraryBook, diagnosis.Kind, diagnosis.Reason); + } + public async Task TryProcessAsync(LibraryBook libraryBook) => Validate(libraryBook) ? await ProcessAsync(libraryBook) diff --git a/Source/LibationCli/Options/LiberateOptions.cs b/Source/LibationCli/Options/LiberateOptions.cs index a78cd163..93551735 100644 --- a/Source/LibationCli/Options/LiberateOptions.cs +++ b/Source/LibationCli/Options/LiberateOptions.cs @@ -49,6 +49,9 @@ public class LiberateOptions : ProcessableOptionsBase #endregion + // --force means "attempt everything", which includes the titles Audible recently refused. + protected override bool HonorsDeferredRetries => !Force; + protected override async Task ProcessAsync() { if (!RunDownloadLimit.TryCreate(LimitBooks, LimitMB, LimitGB, PdfOnly, out runLimit, out var limitError)) @@ -174,6 +177,11 @@ public class LiberateOptions : ProcessableOptionsBase { lb.Book.UserDefinedItem.BookStatus = LiberatedStatus.NotLiberated; lb.Book.UserDefinedItem.SetPdfStatus(LiberatedStatus.NotLiberated); + + // The status above is set on an untracked copy, so the central clear in updateUserDefinedItem + // never sees it. Asking for this title is the user overriding any wait Libation was observing, + // and the wait must restart from the beginning if the attempt fails again. + DownloadAttemptFailureStore.Clear(lb); } } diff --git a/Source/LibationCli/Options/_ProcessableOptionsBase.cs b/Source/LibationCli/Options/_ProcessableOptionsBase.cs index 16c95904..6d65c219 100644 --- a/Source/LibationCli/Options/_ProcessableOptionsBase.cs +++ b/Source/LibationCli/Options/_ProcessableOptionsBase.cs @@ -84,9 +84,16 @@ public abstract class ProcessableOptionsBase : OptionsBase /// How much this run may download before it stops, or null for a verb without a per-run limit. protected virtual RunDownloadLimit? RunLimit => null; + /// + /// Whether this run should leave alone the titles Audible recently refused. False for a run that names + /// its titles or passes --force: an explicit request is always attempted. + /// + protected virtual bool HonorsDeferredRetries => false; + protected async Task RunAsync(Processable Processable, Action? config = null, Action? notFound = null) { var skippedForDailyLimit = 0; + var deferredThisRun = new List(); var runLimitReached = false; // Needs no guard against pdf or convert runs, unlike the daily limit below: the tracker counts only @@ -114,14 +121,42 @@ public abstract class ProcessableOptionsBase : OptionsBase } else { + // Read once, before the first book: a run that spends hours downloading must not start skipping + // titles because of failures it recorded itself a moment ago. + var deferrals = HonorsDeferredRetries && Processable is DownloadDecryptBook + ? DownloadDeferrals.Load(DateTimeOffset.Now) + : DownloadDeferrals.None; + var libraryBooks = DbContexts.GetLibrary_Flat_NoTracking(); foreach (var lb in Processable.GetValidLibraryBooks(libraryBooks)) { + if (deferrals.Find(lb) is DeferredDownload deferred) + { + deferredThisRun.Add(deferred); + Serilog.Log.Logger.Information( + "Not attempting {libraryBook} yet. {@DebugInfo}", + lb.LogFriendly(), + new { deferred.Kind, deferred.ConsecutiveFailures, deferred.Reason, RetryAfter = deferred.RetryAfter.ToLocalTime() }); + continue; + } + if (!await ProcessOrStopAsync(lb, false)) break; } } + if (deferredThisRun.Count > 0) + { + var now = DateTimeOffset.Now; + foreach (var line in DeferredDownloadUserMessage.BuildCliSkippedLines(deferredThisRun, now)) + Console.WriteLine(line); + + Serilog.Log.Logger.Information( + "Skipped {deferredCount} titles that recently failed to download. Skipped: {skipped}", + deferredThisRun.Count, + DeferredDownloadUserMessage.BuildLogBreakdown(deferredThisRun)); + } + if (skippedForDailyLimit > 0) { var summary = DailyDownloadLimitUserMessage.BuildCliSkippedSummary(skippedForDailyLimit); @@ -219,18 +254,40 @@ public abstract class ProcessableOptionsBase : OptionsBase { Console.Error.WriteLine(WidevineRecommendation.BuildLogSummary(libraryBook.Book.TitleWithSubtitle)); Serilog.Log.Logger.Error(ex, "ADRM license unavailable (Sable acr:null) {@DebugInfo}", new { Book = libraryBook.LogFriendly() }); + ReportNextAttempt(libraryBook); } catch (ContentLicenseDeniedException clEx) { foreach (var line in ContentLicenseDeniedCliSummary.Lines(clEx)) Console.Error.WriteLine(line); Serilog.Log.Logger.Error(clEx, "Content license denied {@DebugInfo}", new { Book = libraryBook.LogFriendly() }); + ReportNextAttempt(libraryBook); } catch (Exception ex) { - var msg = "Error processing book. Skipping. This book will be tried again on next attempt. For options of skipping or marking as error, retry with main Libation app."; + var msg = "Error processing book. Skipping. For options of skipping or marking as error, retry with main Libation app."; Console.Error.WriteLine(msg + ". See log for more details."); Serilog.Log.Logger.Error(ex, $"{msg} {{@DebugInfo}}", new { Book = libraryBook.LogFriendly() }); + + if (!ReportNextAttempt(libraryBook)) + Console.Error.WriteLine("This book will be tried again on next attempt."); } } + + /// + /// Says when a title Libation has decided to wait on will be attempted again, so a scheduled run explains + /// its own silence on the next several runs rather than appearing to have forgotten the title. + /// + /// True when the title is being waited on. + private static bool ReportNextAttempt(LibraryBook libraryBook) + { + var now = DateTimeOffset.Now; + if (DownloadAttemptFailureStore.Find(libraryBook, now) is not DeferredDownload deferred) + return false; + + Console.Error.WriteLine( + $"Not attempting this title again {DeferredDownloadUserMessage.DescribeWhen(deferred.RetryAfter, now)}. " + + "To try it sooner, name it: libationcli liberate " + libraryBook.Book.AudibleProductId); + return true; + } } diff --git a/Source/LibationUiBase/ProcessQueue/BackupRequest.cs b/Source/LibationUiBase/ProcessQueue/BackupRequest.cs index 4cb663df..e164e998 100644 --- a/Source/LibationUiBase/ProcessQueue/BackupRequest.cs +++ b/Source/LibationUiBase/ProcessQueue/BackupRequest.cs @@ -1,5 +1,7 @@ +using ApplicationServices; using DataLayer; using Dinah.Core; +using System; using System.Collections.Generic; using System.Linq; using System.Text; @@ -20,8 +22,9 @@ internal sealed class BackupRequest public static readonly SkipReason AlreadyDownloaded = new("Already downloaded"); public static readonly SkipReason PreviousError = new("Previously failed to download", "set the download status to 'Not Downloaded' to try again"); public static readonly SkipReason AbsentFromLastScan = new("Absent from your last library scan", "run Scan, or `libationcli scan`, then try again"); + public static readonly SkipReason WaitingToRetry = new("Waiting before trying again after a recent failure", "download the title on its own to try it now"); - public static readonly SkipReason[] All = [AlreadyDownloaded, PreviousError, AbsentFromLastScan]; + public static readonly SkipReason[] All = [AlreadyDownloaded, PreviousError, AbsentFromLastScan, WaitingToRetry]; } /// The titles the caller asked to back up, including the ones that cannot be queued. @@ -30,32 +33,49 @@ internal sealed class BackupRequest public int SkippedCount => RequestedCount - Queueable.Length; public int Skipped(SkipReason reason) => skipped.GetValueOrDefault(reason); + /// The titles left out because Libation is waiting before attempting them again. + public IReadOnlyList Deferred { get; } + private readonly Dictionary skipped; - private BackupRequest(int requestedCount, LibraryBook[] queueable, Dictionary skipped) + private BackupRequest(int requestedCount, LibraryBook[] queueable, Dictionary skipped, IReadOnlyList deferred) { RequestedCount = requestedCount; Queueable = queueable; this.skipped = skipped; + Deferred = deferred; } - public static BackupRequest Create(IEnumerable libraryBooks) + /// + /// The titles to leave alone for now. Pass for a request the user + /// made about specific titles, which must always be attempted. + /// + public static BackupRequest Create(IEnumerable libraryBooks, DownloadDeferrals? deferrals = null) { + deferrals ??= DownloadDeferrals.None; + var requestedCount = 0; var queueable = new List(); var skipped = new Dictionary(); + var deferred = new List(); foreach (var libraryBook in libraryBooks) { requestedCount++; - if (GetSkipReason(libraryBook) is not SkipReason reason) + // A title needing only its PDF is never waited on: the audiobook download is what Audible refused. + if (libraryBook.NeedsBookDownload && deferrals.Find(libraryBook) is DeferredDownload waiting) + { + deferred.Add(waiting); + skipped[SkipReason.WaitingToRetry] = skipped.GetValueOrDefault(SkipReason.WaitingToRetry) + 1; + } + else if (GetSkipReason(libraryBook) is not SkipReason reason) queueable.Add(libraryBook); else skipped[reason] = skipped.GetValueOrDefault(reason) + 1; } - return new BackupRequest(requestedCount, [.. queueable], skipped); + return new BackupRequest(requestedCount, [.. queueable], skipped, deferred); } /// Null when the title can be queued. Absent outranks status: Downloadable is false either way. @@ -89,6 +109,30 @@ internal sealed class BackupRequest foreach (var (reason, count) in Breakdown()) sb.AppendLine($"{reason.Label}: {count}{(reason.Advice is "" ? "" : $" ({reason.Advice})")}"); + if (Deferred.Count > 0) + { + sb.AppendLine(); + sb.AppendLine(BuildDeferredDetail(DateTimeOffset.Now)); + } + + return sb.ToString().TrimEnd(); + } + + /// + /// What Audible said about the waited-on titles and when they come back. Without this the dialog reports a + /// wait with no way to find out its cause short of reading the log. + /// + public string BuildDeferredDetail(DateTimeOffset now) + { + var sb = new StringBuilder(); + sb.AppendLine("Why Libation is waiting:"); + + foreach (var group in Deferred.GroupBy(d => d.Kind).OrderBy(g => g.Key)) + { + sb.AppendLine($"- {group.First().KindLabel} ({"title".PluralizeWithCount(group.Count())}). " + + $"Next attempt {DeferredDownloadUserMessage.DescribeWhen(group.Min(d => d.RetryAfter), now)}."); + } + return sb.ToString().TrimEnd(); } diff --git a/Source/LibationUiBase/ProcessQueue/ProcessQueueViewModel.cs b/Source/LibationUiBase/ProcessQueue/ProcessQueueViewModel.cs index 52a65e1d..40ff26fc 100644 --- a/Source/LibationUiBase/ProcessQueue/ProcessQueueViewModel.cs +++ b/Source/LibationUiBase/ProcessQueue/ProcessQueueViewModel.cs @@ -241,7 +241,9 @@ public class ProcessQueueViewModel : ReactiveObject } else { - var request = BackupRequest.Create(libraryBooks); + // Titles Audible recently refused are left out of a multi-book request but never out of a + // single-title one: picking one title is the user overriding the wait. + var request = BackupRequest.Create(libraryBooks, DownloadDeferrals.Load(DateTimeOffset.Now)); if (request.Queueable.Length == 0) { @@ -269,6 +271,9 @@ public class ProcessQueueViewModel : ReactiveObject request.RequestedCount, request.BuildSkippedLogSummary()); + if (request.Deferred.Count > 0) + AddQueueLogEntry(request.BuildDeferredDetail(DateTimeOffset.Now)); + // May no-op when free space is unknown (common on UNC); see DiskSpaceBackupPreflight. if (!await DiskSpaceBackupPreflight.ConfirmBulkBackupAsync(request.Queueable.Length, config, backupQueueAlreadyRunning: Running)) return false; From 854cb280a006e235f64a4056b072e0ec71307422 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 16:23:34 +0000 Subject: [PATCH 03/14] test: cover the retry backoff, the store and the failure classifier The classifier's inputs are the actual denials from the log attached to issue #1947: owned titles on an inactive account, a Plus title no longer in the catalog, and an unreleased preorder Audible has no audio for. The backoff tests also caught a real overflow: first * 2^n exceeds a TimeSpan long before the cap matters. Co-authored-by: rmcrackan --- .../DownloadRetryBackoff.cs | 9 +- .../DownloadFailureClassifier.cs | 14 +- Source/LibationCli/Options/LiberateOptions.cs | 2 +- .../Options/_ProcessableOptionsBase.cs | 2 +- .../DeferredDownloadUserMessageTests.cs | 80 ++++++ .../DownloadAttemptFailureStoreTests.cs | 256 ++++++++++++++++++ .../DownloadRetryBackoffTests.cs | 72 +++++ .../DownloadFailureClassifierTests.cs | 166 ++++++++++++ .../DeferredRetryOptionsTests.cs | 45 +++ .../BackupRequestTests.cs | 97 +++++++ 10 files changed, 732 insertions(+), 11 deletions(-) create mode 100644 Source/_Tests/ApplicationServices.Tests/DeferredDownloadUserMessageTests.cs create mode 100644 Source/_Tests/ApplicationServices.Tests/DownloadAttemptFailureStoreTests.cs create mode 100644 Source/_Tests/ApplicationServices.Tests/DownloadRetryBackoffTests.cs create mode 100644 Source/_Tests/FileLiberator.Tests/DownloadFailureClassifierTests.cs create mode 100644 Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs diff --git a/Source/ApplicationServices/DownloadRetryBackoff.cs b/Source/ApplicationServices/DownloadRetryBackoff.cs index c561e7e2..986c563e 100644 --- a/Source/ApplicationServices/DownloadRetryBackoff.cs +++ b/Source/ApplicationServices/DownloadRetryBackoff.cs @@ -37,9 +37,12 @@ public static class DownloadRetryBackoff ? found : schedule[DownloadFailureKind.ServiceInterruption]; - // Doubling in ticks would overflow long before the cap matters, so count the doublings first. - var doublings = Math.Clamp(consecutiveFailures - 1, 0, 30); - var wait = first * Math.Pow(2, doublings); + // Doubled one step at a time and stopped at the cap: first * 2^n overflows a TimeSpan long before a + // plausible failure count, let alone the absurd ones a corrupt row could hold. + var doublings = Math.Max(0, consecutiveFailures - 1); + var wait = first; + for (var i = 0; i < doublings && wait < max; i++) + wait += wait; return wait > max ? max : wait; } diff --git a/Source/FileLiberator/DownloadFailureClassifier.cs b/Source/FileLiberator/DownloadFailureClassifier.cs index cacd2a68..c58bd643 100644 --- a/Source/FileLiberator/DownloadFailureClassifier.cs +++ b/Source/FileLiberator/DownloadFailureClassifier.cs @@ -46,18 +46,20 @@ public static class DownloadFailureClassifier }; /// - /// Audible attaches a rejection reason per validation type. GenericError is Audible declining to - /// say why, which in practice means an outage or throttling rather than a decision about the title; the - /// GUI already treats it that way when it offers guidance. Anything else names an eligibility problem - /// with the account or the title, which will not change within the hour. + /// Audible attaches a rejection reason per validation type it ran. GenericError is Audible + /// declining to say why, which in practice means an outage or throttling rather than a decision about the + /// title; the GUI already reads it that way when it chooses which guidance to offer. Anything else names + /// an eligibility problem with the account or the title, which will not change within the hour. Saying + /// nothing at all is also treated as an outage: a refusal with no stated reason is not a settled one. /// private static DownloadFailureDiagnosis ClassifyLicenseDenial(ContentLicenseDeniedException ex) { LicenseDenialReason?[] reasons = [ex.Ownership, ex.AYCL, ex.Membership, ex.Client]; + var stated = reasons.Where(r => !string.IsNullOrWhiteSpace(r?.RejectionReason)).ToArray(); var looksLikeOutage - = ex.AYCL?.RejectionReason is null or RejectionReason.GenericError - || reasons.Any(r => r?.RejectionReason is RejectionReason.GenericError); + = stated.Length == 0 + || stated.Any(r => r!.RejectionReason is RejectionReason.GenericError); return new DownloadFailureDiagnosis( looksLikeOutage ? DownloadFailureKind.ServiceInterruption : DownloadFailureKind.LicenseDenied, diff --git a/Source/LibationCli/Options/LiberateOptions.cs b/Source/LibationCli/Options/LiberateOptions.cs index 93551735..27be2daa 100644 --- a/Source/LibationCli/Options/LiberateOptions.cs +++ b/Source/LibationCli/Options/LiberateOptions.cs @@ -50,7 +50,7 @@ public class LiberateOptions : ProcessableOptionsBase #endregion // --force means "attempt everything", which includes the titles Audible recently refused. - protected override bool HonorsDeferredRetries => !Force; + internal override bool HonorsDeferredRetries => !Force; protected override async Task ProcessAsync() { diff --git a/Source/LibationCli/Options/_ProcessableOptionsBase.cs b/Source/LibationCli/Options/_ProcessableOptionsBase.cs index 6d65c219..9947deb1 100644 --- a/Source/LibationCli/Options/_ProcessableOptionsBase.cs +++ b/Source/LibationCli/Options/_ProcessableOptionsBase.cs @@ -88,7 +88,7 @@ public abstract class ProcessableOptionsBase : OptionsBase /// Whether this run should leave alone the titles Audible recently refused. False for a run that names /// its titles or passes --force: an explicit request is always attempted. /// - protected virtual bool HonorsDeferredRetries => false; + internal virtual bool HonorsDeferredRetries => false; protected async Task RunAsync(Processable Processable, Action? config = null, Action? notFound = null) { diff --git a/Source/_Tests/ApplicationServices.Tests/DeferredDownloadUserMessageTests.cs b/Source/_Tests/ApplicationServices.Tests/DeferredDownloadUserMessageTests.cs new file mode 100644 index 00000000..2717f5c2 --- /dev/null +++ b/Source/_Tests/ApplicationServices.Tests/DeferredDownloadUserMessageTests.cs @@ -0,0 +1,80 @@ +using ApplicationServices; +using DataLayer; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.Linq; + +namespace DeferredDownloadUserMessageTests; + +[TestClass] +public class DeferredDownloadUserMessageTests +{ + private static readonly DateTimeOffset Now = new(2026, 8, 16, 3, 7, 0, TimeSpan.Zero); + + private static DeferredDownload Deferred(DownloadFailureKind kind, TimeSpan untilRetry, string asin = "ASIN") + => new("account", asin, kind, ConsecutiveFailures: 1, LastFailedAt: Now, RetryAfter: Now + untilRetry, Reason: null); + + [TestMethod] + public void Nothing_is_said_when_no_title_was_held_back() + => Assert.AreEqual(0, DeferredDownloadUserMessage.BuildCliSkippedLines([], Now).Count()); + + [TestMethod] + public void The_cli_summary_replaces_a_warning_per_title_with_a_count_per_reason() + { + var skipped = new[] + { + Deferred(DownloadFailureKind.LicenseDenied, TimeSpan.FromDays(3), "A"), + Deferred(DownloadFailureKind.LicenseDenied, TimeSpan.FromDays(1), "B"), + Deferred(DownloadFailureKind.AssetUnavailable, TimeSpan.FromHours(6), "C"), + }; + + var lines = DeferredDownloadUserMessage.BuildCliSkippedLines(skipped, Now).ToList(); + + Assert.AreEqual("Skipped 3 titles that recently failed to download. Libation will try again by itself.", lines[0]); + // The soonest of each group, so the summary says when something will actually happen. + StringAssert.Contains(lines[1], "Audible denied a download license: 2 (next attempt in about 1 day"); + StringAssert.Contains(lines[2], "Audible has no downloadable audio yet: 1 (next attempt in about 6 hours)"); + StringAssert.Contains(lines[3], "libationcli liberate --force"); + } + + [TestMethod] + public void One_title_is_counted_in_the_singular() + { + var lines = DeferredDownloadUserMessage.BuildCliSkippedLines([Deferred(DownloadFailureKind.LicenseDenied, TimeSpan.FromDays(1))], Now).ToList(); + + StringAssert.Contains(lines[0], "Skipped 1 title that recently"); + } + + [TestMethod] + public void The_log_breakdown_is_compact() + { + var breakdown = DeferredDownloadUserMessage.BuildLogBreakdown([ + Deferred(DownloadFailureKind.LicenseDenied, TimeSpan.FromDays(1), "A"), + Deferred(DownloadFailureKind.LicenseDenied, TimeSpan.FromDays(1), "B"), + Deferred(DownloadFailureKind.ServiceInterruption, TimeSpan.FromHours(1), "C")]); + + Assert.AreEqual("Audible denied a download license: 2, A possible Audible service interruption: 1", breakdown); + } + + [TestMethod] + public void The_log_breakdown_of_nothing_is_none() + => Assert.AreEqual("none", DeferredDownloadUserMessage.BuildLogBreakdown([])); + + [TestMethod] + [DataRow(0, "on the next run")] + [DataRow(-90, "on the next run")] + [DataRow(1, "in about 1 minute")] + [DataRow(45, "in about 45 minutes")] + [DataRow(90, "in about 2 hours")] + [DataRow(60 * 20, "in about 20 hours")] + [DataRow(60 * 24, "in about 1 day")] + [DataRow(60 * 24 * 3, "in about 3 days")] + public void When_a_title_comes_back_is_described_without_needing_a_clock(int minutes, string expected) + => StringAssert.StartsWith(DeferredDownloadUserMessage.DescribeWhen(Now.AddMinutes(minutes), Now), expected); + + [TestMethod] + public void A_wait_of_days_also_names_the_date() + => StringAssert.Contains( + DeferredDownloadUserMessage.DescribeWhen(Now.AddDays(30), Now), + Now.AddDays(30).ToLocalTime().ToString("d")); +} diff --git a/Source/_Tests/ApplicationServices.Tests/DownloadAttemptFailureStoreTests.cs b/Source/_Tests/ApplicationServices.Tests/DownloadAttemptFailureStoreTests.cs new file mode 100644 index 00000000..1134e14f --- /dev/null +++ b/Source/_Tests/ApplicationServices.Tests/DownloadAttemptFailureStoreTests.cs @@ -0,0 +1,256 @@ +using ApplicationServices; +using AssertionHelper; +using DataLayer; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.IO; +using System.Linq; +using System.Threading.Tasks; + +namespace DownloadAttemptFailureStoreTests; + +/// +/// Exercises the record of refused downloads against a real SQLite database in a temp directory, which also +/// proves the new migration applies to a fresh database and that the store's queries work on the shipping +/// provider. +/// +[TestClass] +[DoNotParallelize] +public class DownloadAttemptFailureStoreTests +{ + private string tempLibationFiles = string.Empty; + + [TestInitialize] + public void Initialize() + { + tempLibationFiles = Path.Combine(Path.GetTempPath(), $"libation-attempt-failure-tests-{Guid.NewGuid():N}"); + Directory.CreateDirectory(tempLibationFiles); + + // A fresh Configuration resolves LibationFiles from this variable, so the database lands in the temp dir. + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, tempLibationFiles); + Configuration.CreateMockInstance(); + } + + [TestCleanup] + public void Cleanup() + { + Configuration.RestoreSingletonInstance(); + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, null); + + try + { + Directory.Delete(tempLibationFiles, recursive: true); + } + catch (IOException) + { + // A leftover temp directory is not worth failing a test over. + } + } + + private static LibraryBook Book(string title = "Refused Title", string account = "someone@email.co") + => MockLibraryBook.CreateBook(title: title, account: account, bookStatus: LiberatedStatus.NotLiberated); + + [TestMethod] + public void Round_trips_a_refusal_through_a_real_database() + { + var book = Book(); + var failedAt = DateTimeOffset.Now.AddMinutes(-5); + + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "Ownership: not owned", failedAt); + + var deferred = DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now); + + deferred.Count.Should().Be(1); + deferred[0].AudibleProductId.Should().Be(book.Book.AudibleProductId); + deferred[0].Account.Should().Be(book.Account); + Assert.AreEqual(DownloadFailureKind.LicenseDenied, deferred[0].Kind); + deferred[0].ConsecutiveFailures.Should().Be(1); + deferred[0].Reason.Should().Be("Ownership: not owned"); + Assert.AreEqual(failedAt.UtcTicks, deferred[0].LastFailedAt.UtcTicks); + Assert.AreEqual(failedAt.AddDays(1).UtcTicks, deferred[0].RetryAfter.UtcTicks); + + File.Exists(Path.Combine(tempLibationFiles, "LibationContext.db")).Should().BeTrue(); + } + + [TestMethod] + public void Repeated_refusals_of_the_same_kind_push_the_next_attempt_further_out() + { + var book = Book(); + var now = DateTimeOffset.Now; + + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope", now.AddDays(-8)); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope", now.AddDays(-4)); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope", now); + + var deferred = DownloadAttemptFailureStore.GetDeferred(now); + + // One row per title, not a history. + deferred.Count.Should().Be(1); + deferred[0].ConsecutiveFailures.Should().Be(3); + Assert.AreEqual(now.AddDays(4).UtcTicks, deferred[0].RetryAfter.UtcTicks); + } + + [TestMethod] + public void A_refusal_for_a_different_reason_restarts_the_wait() + { + var book = Book(); + var now = DateTimeOffset.Now; + + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope", now.AddDays(-10)); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope", now.AddDays(-5)); + // Audible now says something different, so the wait built up for the old reason no longer applies. + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.ServiceInterruption, "outage", now); + + var deferred = DownloadAttemptFailureStore.GetDeferred(now); + + Assert.AreEqual(DownloadFailureKind.ServiceInterruption, deferred[0].Kind); + deferred[0].ConsecutiveFailures.Should().Be(1); + Assert.AreEqual(now.AddHours(1).UtcTicks, deferred[0].RetryAfter.UtcTicks); + } + + [TestMethod] + public void The_same_title_on_two_accounts_is_tracked_separately() + { + // Refused on one account says nothing about whether another account can download it. + var refused = MockLibraryBook.CreateBook(title: "Shared", account: "a@email.co"); + var allowed = MockLibraryBook.CreateBook(title: "Shared", account: "b@email.co"); + refused.Book.AudibleProductId.Should().Be(allowed.Book.AudibleProductId); + + DownloadAttemptFailureStore.Record(refused, DownloadFailureKind.LicenseDenied, "nope"); + + var deferrals = DownloadDeferrals.Load(DateTimeOffset.Now); + + deferrals.IsDeferred(refused).Should().BeTrue(); + deferrals.IsDeferred(allowed).Should().BeFalse(); + } + + [TestMethod] + public void A_title_is_ready_again_once_its_wait_has_elapsed() + { + var book = Book(); + var failedAt = DateTimeOffset.Now.AddDays(-2); + + // One day's wait, two days ago. + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope", failedAt); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now).Count.Should().Be(0); + DownloadAttemptFailureStore.Find(book, DateTimeOffset.Now).Should().BeNull(); + // The row stays so the next failure continues the count rather than restarting the schedule. + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope"); + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now)[0].ConsecutiveFailures.Should().Be(2); + } + + [TestMethod] + public void Clear_forgets_a_title() + { + var book = Book(); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope"); + + DownloadAttemptFailureStore.Clear(book); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now).Count.Should().Be(0); + // And the count starts over, so an explicit retry does not inherit a long wait. + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope"); + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now)[0].ConsecutiveFailures.Should().Be(1); + } + + [TestMethod] + public void Clear_leaves_other_titles_alone() + { + var kept = Book("Kept"); + var cleared = Book("Cleared"); + DownloadAttemptFailureStore.Record(kept, DownloadFailureKind.LicenseDenied, "nope"); + DownloadAttemptFailureStore.Record(cleared, DownloadFailureKind.LicenseDenied, "nope"); + + DownloadAttemptFailureStore.Clear(cleared); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now) + .Select(d => d.AudibleProductId) + .Should().BeEquivalentTo([kept.Book.AudibleProductId]); + } + + [TestMethod] + public void Clearing_a_title_that_was_never_recorded_is_harmless() + { + DownloadAttemptFailureStore.Clear(Book()); + DownloadAttemptFailureStore.Clear(null, null); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now).Count.Should().Be(0); + } + + [TestMethod] + public void Find_returns_only_the_named_title() + { + var deferred = Book("Deferred"); + var other = Book("Other"); + DownloadAttemptFailureStore.Record(deferred, DownloadFailureKind.AssetUnavailable, "preorder"); + + Assert.AreEqual(DownloadFailureKind.AssetUnavailable, DownloadAttemptFailureStore.Find(deferred, DateTimeOffset.Now)!.Kind); + DownloadAttemptFailureStore.Find(other, DateTimeOffset.Now).Should().BeNull(); + } + + [TestMethod] + public void An_overlong_reason_is_stored_truncated() + { + var book = Book(); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, new string('x', 5000)); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now)[0].Reason!.Length.Should().Be(400); + } + + /// Puts a title in the library so the real update path can be exercised against it. + private static LibraryBook InsertBook(string title, LiberatedStatus bookStatus = LiberatedStatus.Liberated) + { + var libraryBook = MockLibraryBook.CreateBook(title: title, bookStatus: bookStatus); + + using (var context = DbContexts.GetContext()) + { + context.LibraryBooks.Add(new LibraryBook(libraryBook.Book, libraryBook.DateAdded, libraryBook.Account)); + context.SaveChanges(); + } + + return DbContexts.GetLibraryBook_Flat_NoTracking(libraryBook.Book.AudibleProductId)!; + } + + [TestMethod] + public async Task Changing_a_titles_download_status_clears_the_record() + { + // Setting a title to Not Downloaded is the user saying they want it tried again. + var book = InsertBook("Refused Then Reset"); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope"); + + await book.UpdateBookStatusAsync(LiberatedStatus.NotLiberated); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now).Count.Should().Be(0); + } + + [TestMethod] + public async Task Editing_tags_does_not_clear_the_record() + { + // Otherwise any grid edit would quietly put a refused title back into the next scheduled run. + var book = InsertBook("Refused Then Tagged", LiberatedStatus.NotLiberated); + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope"); + + await book.UpdateTagsAsync("favourite"); + + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now).Count.Should().Be(1); + } + + [TestMethod] + public void A_broken_database_leaves_downloading_exactly_as_it_was() + { + // This is bookkeeping to make downloading quieter. It must never be the reason a download stops. + Configuration.Instance.PostgresqlConnectionString + = "Host=127.0.0.1;Port=1;Database=nope;Username=nobody;Password=nothing;Timeout=1;Command Timeout=1"; + + var book = Book(); + + DownloadAttemptFailureStore.Record(book, DownloadFailureKind.LicenseDenied, "nope"); + DownloadAttemptFailureStore.Clear(book); + + // A failed read defers nothing, so every title is attempted. + DownloadAttemptFailureStore.GetDeferred(DateTimeOffset.Now).Count.Should().Be(0); + DownloadAttemptFailureStore.Find(book, DateTimeOffset.Now).Should().BeNull(); + } +} diff --git a/Source/_Tests/ApplicationServices.Tests/DownloadRetryBackoffTests.cs b/Source/_Tests/ApplicationServices.Tests/DownloadRetryBackoffTests.cs new file mode 100644 index 00000000..3358dfdd --- /dev/null +++ b/Source/_Tests/ApplicationServices.Tests/DownloadRetryBackoffTests.cs @@ -0,0 +1,72 @@ +using ApplicationServices; +using AssertionHelper; +using DataLayer; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.Linq; + +namespace DownloadRetryBackoffTests; + +[TestClass] +public class DownloadRetryBackoffTests +{ + [TestMethod] + [DataRow(DownloadFailureKind.LicenseDenied, 1, 24)] + [DataRow(DownloadFailureKind.LicenseDenied, 2, 48)] + [DataRow(DownloadFailureKind.LicenseDenied, 3, 96)] + [DataRow(DownloadFailureKind.AssetUnavailable, 1, 6)] + [DataRow(DownloadFailureKind.AssetUnavailable, 2, 12)] + [DataRow(DownloadFailureKind.ServiceInterruption, 1, 1)] + [DataRow(DownloadFailureKind.ServiceInterruption, 2, 2)] + public void Wait_doubles_with_each_consecutive_failure(DownloadFailureKind kind, int consecutiveFailures, int expectedHours) + => DownloadRetryBackoff.GetWait(kind, consecutiveFailures).Should().Be(TimeSpan.FromHours(expectedHours)); + + [TestMethod] + [DataRow(DownloadFailureKind.LicenseDenied, 30)] + [DataRow(DownloadFailureKind.AssetUnavailable, 7)] + public void Wait_is_capped(DownloadFailureKind kind, int capDays) + { + // Deliberately absurd counts: the cap must hold rather than overflow. + foreach (var failures in new[] { 20, 100, int.MaxValue }) + DownloadRetryBackoff.GetWait(kind, failures).Should().Be(TimeSpan.FromDays(capDays)); + } + + [TestMethod] + public void A_possible_outage_is_never_waited_on_for_more_than_half_a_day() + => DownloadRetryBackoff.GetWait(DownloadFailureKind.ServiceInterruption, int.MaxValue) + .Should().Be(TimeSpan.FromHours(12)); + + [TestMethod] + public void Every_kind_is_attempted_again_eventually() + { + // Nothing here may be permanent: Audible never distinguishes "never" from "not now". + foreach (var kind in Enum.GetValues()) + Assert.IsTrue(DownloadRetryBackoff.GetWait(kind, int.MaxValue) <= TimeSpan.FromDays(30), $"{kind} is waited on forever"); + } + + [TestMethod] + public void A_first_failure_is_never_waited_on_for_less_than_an_hour() + { + // A shorter wait would leave an hourly cron re-requesting the same refused license every run. + foreach (var kind in Enum.GetValues()) + Assert.IsTrue(DownloadRetryBackoff.GetWait(kind, 1) >= TimeSpan.FromHours(1), $"{kind} is retried too soon"); + } + + [TestMethod] + public void A_count_of_zero_or_less_is_treated_as_the_first_failure() + { + var first = DownloadRetryBackoff.GetWait(DownloadFailureKind.LicenseDenied, 1); + + DownloadRetryBackoff.GetWait(DownloadFailureKind.LicenseDenied, 0).Should().Be(first); + DownloadRetryBackoff.GetWait(DownloadFailureKind.LicenseDenied, -5).Should().Be(first); + } + + [TestMethod] + public void RetryAfter_is_the_wait_added_to_when_the_attempt_failed() + { + var failedAt = new DateTimeOffset(2026, 8, 16, 3, 7, 0, TimeSpan.Zero); + + DownloadRetryBackoff.GetRetryAfter(DownloadFailureKind.LicenseDenied, 1, failedAt) + .Should().Be(failedAt.AddDays(1)); + } +} diff --git a/Source/_Tests/FileLiberator.Tests/DownloadFailureClassifierTests.cs b/Source/_Tests/FileLiberator.Tests/DownloadFailureClassifierTests.cs new file mode 100644 index 00000000..34a26457 --- /dev/null +++ b/Source/_Tests/FileLiberator.Tests/DownloadFailureClassifierTests.cs @@ -0,0 +1,166 @@ +using AudibleApi; +using AudibleApi.Common; +using DataLayer; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using Newtonsoft.Json.Linq; +using System; +using System.IO; +using System.Net.Http; + +namespace FileLiberator.Tests; + +/// +/// The inputs here are taken from the log attached to issue #1947: a Plus preorder Audible had no audio for, +/// and owned titles on an inactive account that Audible refused a license for. +/// +[TestClass] +public class DownloadFailureClassifierTests +{ + private const string LicenseRequestUri = "https://api.audible.com/1.0/content/B002V5B8OY/licenserequest"; + + /// The preorder failure: a license request that comes back with no content reference. + private const string NoAudioAssetJson = """ + {"http_response_code":"NotFound","response":"{\"message\":\"Unable to retrieve asset details from Sable(ACRInfos), for marketplaceId:AF2M0KC94RCEA, asin:B0H956N76W, acr:null, skuLite:OR_ORIG_003592, version:LATEST, aaaClientId:urn:cdo:AudibleApiExternalRouterService:Prod:Default\"}"} + """; + + private static ContentLicenseDeniedException Denied(params (string ValidationType, string RejectionReason, string Message)[] reasons) + { + var license = new ContentLicense + { + Asin = "B002V5B8OY", + StatusCode = "Denied", + LicenseDenialReasons = [.. Array.ConvertAll(reasons, r => new LicenseDenialReason + { + ValidationType = r.ValidationType, + RejectionReason = r.RejectionReason, + Message = r.Message + })] + }; + + return new ContentLicenseDeniedException(new Uri(LicenseRequestUri), license); + } + + private static ApiErrorException ApiError(string requestUri, string json) + => new(requestUri, JObject.Parse(json), "License response not \"OK\""); + + [TestMethod] + public void An_eligibility_refusal_is_a_license_denial() + { + // Verbatim from the issue's log: an owned title on an account that is no longer active. + var ex = Denied( + ("Membership", RejectionReason.RequesterEligibility, "Customer is not part of any plans"), + ("Ownership", RejectionReason.RequesterEligibility, "Ownership: No Ownership information returned by DAOQS for customer [x] and for asin [B002V5B8OY]."), + ("Client", RejectionReason.RequesterEligibility, "does not has access to asin[B002V5B8OY]."), + ("AYCL", RejectionReason.ContentEligibility, "Asin: [B002V5B8OY] is not eligible for AYCL")); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.LicenseDenied, diagnosis.Kind); + // The reason names which check failed, so the log and the UI can say why without another request. + StringAssert.StartsWith(diagnosis.Reason, "Ownership: "); + } + + [TestMethod] + public void A_Plus_title_no_longer_in_the_catalog_is_a_license_denial() + { + var ex = Denied( + ("Ownership", RejectionReason.RequesterEligibility, "No matching DAO benefit found"), + ("AYCL", RejectionReason.ContentEligibility, "Asin: [B0D5JLT7YG] is not eligible for AYCL")); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.LicenseDenied, diagnosis.Kind); + } + + [TestMethod] + public void An_ownership_refusal_alone_is_a_license_denial() + { + // Audible does not always run every check. One stated eligibility refusal is still a refusal, and an + // hourly schedule must not keep asking about it. + var ex = Denied(("Ownership", RejectionReason.RequesterEligibility, "not owned")); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.LicenseDenied, diagnosis.Kind); + } + + [TestMethod] + public void GenericError_is_read_as_a_possible_service_interruption() + { + // Matches the judgement the GUI queue already makes when it offers guidance for this failure. + var ex = Denied(("AYCL", RejectionReason.GenericError, "Something went wrong")); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.ServiceInterruption, diagnosis.Kind); + } + + [TestMethod] + public void GenericError_on_any_check_is_read_as_a_possible_service_interruption() + { + var ex = Denied( + ("Ownership", RejectionReason.GenericError, "Something went wrong"), + ("AYCL", RejectionReason.ContentEligibility, "Asin is not eligible for AYCL")); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.ServiceInterruption, diagnosis.Kind); + } + + [TestMethod] + public void A_denial_with_no_reasons_at_all_is_not_treated_as_settled() + { + var ex = Denied(); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.ServiceInterruption, diagnosis.Kind); + Assert.AreEqual(ex.Message, diagnosis.Reason); + } + + [TestMethod] + public void A_license_request_with_no_content_reference_means_there_is_no_audio_yet() + { + var ex = ApiError(LicenseRequestUri, NoAudioAssetJson); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.AssetUnavailable, diagnosis.Kind); + StringAssert.Contains(diagnosis.Reason, "preorder"); + } + + [TestMethod] + public void An_acr_null_error_from_another_endpoint_is_not_classified() + { + // Only the license request tells us whether audio exists to download. + var ex = ApiError("https://api.audible.com/1.0/content/B0H956N76W/metadata", NoAudioAssetJson); + + Assert.IsFalse(DownloadFailureClassifier.TryClassify(ex, out _)); + } + + [TestMethod] + public void An_ordinary_api_error_is_not_classified() + { + var ex = ApiError(LicenseRequestUri, """{"message":"Internal server error"}"""); + + Assert.IsFalse(DownloadFailureClassifier.TryClassify(ex, out _)); + } + + [TestMethod] + public void Failures_that_are_nothing_to_do_with_Audible_keep_being_retried_every_run() + { + // Nothing here suggests the next attempt fails the same way, so these must not be waited on. + Assert.IsFalse(DownloadFailureClassifier.TryClassify(new IOException("There is not enough space on the disk."), out _)); + Assert.IsFalse(DownloadFailureClassifier.TryClassify(new HttpRequestException("Connection reset"), out _)); + Assert.IsFalse(DownloadFailureClassifier.TryClassify(new OperationCanceledException(), out _)); + Assert.IsFalse(DownloadFailureClassifier.TryClassify(new InvalidDataException("Widevine license response is null."), out _)); + } + + [TestMethod] + public void A_wrapped_denial_is_still_recognised() + { + // The Widevine path rethrows through whichever step gave up on it. + var inner = Denied(("Ownership", RejectionReason.RequesterEligibility, "not owned")); + var ex = new InvalidOperationException("Failed to request a Widevine license.", inner); + + Assert.IsTrue(DownloadFailureClassifier.TryClassify(ex, out var diagnosis)); + Assert.AreEqual(DownloadFailureKind.LicenseDenied, diagnosis.Kind); + } + + [TestMethod] + public void Classifying_null_is_harmless() + => Assert.IsNull(DownloadFailureClassifier.Classify(null)); +} diff --git a/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs b/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs new file mode 100644 index 00000000..d5b71ddb --- /dev/null +++ b/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs @@ -0,0 +1,45 @@ +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System.IO; + +namespace LibationCli.Tests; + +/// +/// Which liberate runs leave alone the titles Audible recently refused. A run that says what it wants +/// downloaded must always attempt it. +/// +[TestClass] +public class DeferredRetryOptionsTests +{ + private static OptionsBase? Parse(params string[] args) + { + using var error = new StringWriter(); + return Program.ParseInvocation(args, error).Result?.Value as OptionsBase; + } + + [TestMethod] + public void A_plain_liberate_run_waits_on_the_titles_Audible_refused() + => Assert.IsTrue(((ProcessableOptionsBase)Parse("liberate")!).HonorsDeferredRetries); + + [TestMethod] + [DataRow("--force")] + [DataRow("-f")] + public void Force_attempts_them_anyway(string force) + => Assert.IsFalse(((ProcessableOptionsBase)Parse("liberate", force)!).HonorsDeferredRetries); + + [TestMethod] + public void A_pdf_only_run_is_never_held_back() + { + // The audiobook download is what Audible refused; a --pdf run makes a different request entirely, and + // RunAsync only consults the record for a DownloadDecryptBook. + var options = (LiberateOptions)Parse("liberate", "--pdf")!; + + Assert.IsTrue(options.PdfOnly); + } + + [TestMethod] + public void Other_processable_verbs_do_not_consult_the_record() + { + // convert-to-mp3 and the like never request a license, so there is nothing for them to wait on. + Assert.IsFalse(((ProcessableOptionsBase)Parse("convert")!).HonorsDeferredRetries); + } +} diff --git a/Source/_Tests/LibationUiBase.Tests/BackupRequestTests.cs b/Source/_Tests/LibationUiBase.Tests/BackupRequestTests.cs index b36365f3..4b2490c3 100644 --- a/Source/_Tests/LibationUiBase.Tests/BackupRequestTests.cs +++ b/Source/_Tests/LibationUiBase.Tests/BackupRequestTests.cs @@ -1,3 +1,4 @@ +using ApplicationServices; using DataLayer; using LibationUiBase.ProcessQueue; @@ -110,4 +111,100 @@ public class BackupRequestTests Assert.AreEqual("already downloaded: 2, absent from your last library scan: 1", request.BuildSkippedLogSummary()); } + + private static DownloadDeferrals Deferring( + LibraryBook libraryBook, + DownloadFailureKind kind = DownloadFailureKind.LicenseDenied, + int hoursUntilRetry = 20) + => DownloadDeferrals.Create([ + new DeferredDownload( + libraryBook.Account, + libraryBook.Book.AudibleProductId, + kind, + ConsecutiveFailures: 1, + LastFailedAt: DateTimeOffset.Now, + RetryAfter: DateTimeOffset.Now.AddHours(hoursUntilRetry), + Reason: "Ownership: not owned")]); + + [TestMethod] + public void a_title_being_waited_on_is_not_queued() + { + var waiting = LibraryBook("REFUSED"); + + var request = BackupRequest.Create([waiting, LibraryBook("NEW")], Deferring(waiting)); + + CollectionAssert.AreEqual(new[] { "NEW" }, request.Queueable.Select(lb => lb.Book.AudibleProductId).ToList()); + Assert.AreEqual(1, request.Skipped(BackupRequest.SkipReason.WaitingToRetry)); + Assert.AreEqual(1, request.Deferred.Count); + } + + [TestMethod] + public void no_title_is_waited_on_when_no_deferrals_are_supplied() + { + // The default is what a request about specific titles passes: an explicit ask is always attempted. + var waiting = LibraryBook("REFUSED"); + + var request = BackupRequest.Create([waiting]); + + Assert.AreEqual(1, request.Queueable.Length); + Assert.AreEqual(0, request.Deferred.Count); + } + + [TestMethod] + public void a_title_needing_only_its_pdf_is_never_waited_on() + { + // The audiobook download is what Audible refused; the PDF is a different request. + var pdfOnly = MockLibraryBook + .CreateBook(title: "PDFONLY", bookStatus: LiberatedStatus.Liberated) + .WithPdfStatus(LiberatedStatus.NotLiberated); + + var request = BackupRequest.Create([pdfOnly], Deferring(pdfOnly)); + + Assert.AreEqual(1, request.Queueable.Length); + Assert.AreEqual(0, request.Deferred.Count); + } + + [TestMethod] + public void an_already_downloaded_title_is_reported_as_such_rather_than_as_waiting() + { + var done = LibraryBook("DONE", LiberatedStatus.Liberated); + + var request = BackupRequest.Create([done], Deferring(done)); + + Assert.AreEqual(1, request.Skipped(BackupRequest.SkipReason.AlreadyDownloaded)); + Assert.AreEqual(0, request.Skipped(BackupRequest.SkipReason.WaitingToRetry)); + } + + [TestMethod] + public void nothing_queued_body_says_why_libation_is_waiting_and_for_how_long() + { + var waiting = LibraryBook("REFUSED"); + + var request = BackupRequest.Create([waiting], Deferring(waiting)); + var body = request.BuildNothingQueuedBody(); + + StringAssert.Contains(body, "Waiting before trying again after a recent failure: 1"); + StringAssert.Contains(body, "download the title on its own to try it now"); + StringAssert.Contains(body, "Audible denied a download license (1 title)"); + StringAssert.Contains(body, "Next attempt in about 20 hours"); + } + + [TestMethod] + public void the_waiting_detail_groups_titles_by_reason() + { + var refused = LibraryBook("REFUSED"); + var preorder = LibraryBook("PREORDER"); + var now = DateTimeOffset.Now; + + var request = BackupRequest.Create( + [refused, preorder], + DownloadDeferrals.Create([ + new DeferredDownload(refused.Account, "REFUSED", DownloadFailureKind.LicenseDenied, 2, now, now.AddDays(3), null), + new DeferredDownload(preorder.Account, "PREORDER", DownloadFailureKind.AssetUnavailable, 1, now, now.AddHours(6), null)])); + + var detail = request.BuildDeferredDetail(now); + + StringAssert.Contains(detail, "Audible denied a download license (1 title). Next attempt in about 3 days"); + StringAssert.Contains(detail, "Audible has no downloadable audio yet (1 title). Next attempt in about 6 hours"); + } } From 252decb3adfd6b27b630b64a966bb9ec60dbd4f2 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 16:30:23 +0000 Subject: [PATCH 04/14] test(logging): prove the log actually rolls on size Asserting on the generated JSON alone would pass just as happily with a misspelled sink argument, which Serilog ignores in silence - and silently not rolling is the bug. These build a real logger from Libation's own config and write until it rolls, including a test that pins the old unbounded behaviour so a future change to the defaults cannot quietly restore it. Co-authored-by: rmcrackan --- .../ApplicationServices/DeferredDownload.cs | 15 +- .../AttemptFailureRecordingTests.cs | 190 ++++++++++++++++++ .../DeferredRetryReportingTests.cs | 142 +++++++++++++ .../LogRolloverTests.cs | 161 +++++++++++++++ 4 files changed, 504 insertions(+), 4 deletions(-) create mode 100644 Source/_Tests/FileLiberator.Tests/AttemptFailureRecordingTests.cs create mode 100644 Source/_Tests/LibationCli.Tests/DeferredRetryReportingTests.cs create mode 100644 Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs diff --git a/Source/ApplicationServices/DeferredDownload.cs b/Source/ApplicationServices/DeferredDownload.cs index 72499978..25a86feb 100644 --- a/Source/ApplicationServices/DeferredDownload.cs +++ b/Source/ApplicationServices/DeferredDownload.cs @@ -96,10 +96,17 @@ public static class DeferredDownloadUserMessage { var wait = when - now; - return wait <= TimeSpan.Zero ? "on the next run" - : wait < TimeSpan.FromHours(1) ? $"in about {"minute".PluralizeWithCount(Math.Max(1, (int)wait.TotalMinutes))}" - : wait < TimeSpan.FromDays(1) ? $"in about {"hour".PluralizeWithCount((int)Math.Round(wait.TotalHours))}" - : $"in about {"day".PluralizeWithCount((int)Math.Round(wait.TotalDays))} ({when.ToLocalTime():d})"; + if (wait <= TimeSpan.Zero) + return "on the next run"; + if (wait < TimeSpan.FromHours(1)) + return $"in about {"minute".PluralizeWithCount(Math.Max(1, (int)wait.TotalMinutes))}"; + + // Rounded first, so a wait of exactly one day does not read as 24 hours or 23, depending on how long + // the run took to reach this line. + var hours = (int)Math.Round(wait.TotalHours); + return hours < 24 + ? $"in about {"hour".PluralizeWithCount(hours)}" + : $"in about {"day".PluralizeWithCount((int)Math.Round(hours / 24d))} ({when.ToLocalTime():d})"; } private static IEnumerable> GroupByKind(IEnumerable deferred) diff --git a/Source/_Tests/FileLiberator.Tests/AttemptFailureRecordingTests.cs b/Source/_Tests/FileLiberator.Tests/AttemptFailureRecordingTests.cs new file mode 100644 index 00000000..f613c6c6 --- /dev/null +++ b/Source/_Tests/FileLiberator.Tests/AttemptFailureRecordingTests.cs @@ -0,0 +1,190 @@ +using ApplicationServices; +using AudibleApi; +using AudibleApi.Common; +using DataLayer; +using Dinah.Core.ErrorHandling; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.IO; +using System.Threading.Tasks; + +namespace FileLiberator.Tests; + +/// +/// The whole chain from a thrown refusal to a title being left alone, against a real SQLite database. Recording +/// lives in rather than in each host, so this is what proves the CLI and the GUI +/// queue both get it. +/// +[TestClass] +[DoNotParallelize] +public class AttemptFailureRecordingTests +{ + private string tempLibationFiles = string.Empty; + + [TestInitialize] + public void Initialize() + { + tempLibationFiles = Path.Combine(Path.GetTempPath(), $"libation-attempt-recording-tests-{Guid.NewGuid():N}"); + Directory.CreateDirectory(tempLibationFiles); + + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, tempLibationFiles); + Configuration.CreateMockInstance(); + } + + [TestCleanup] + public void Cleanup() + { + Configuration.RestoreSingletonInstance(); + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, null); + + try + { + Directory.Delete(tempLibationFiles, recursive: true); + } + catch (IOException) + { + // A leftover temp directory is not worth failing a test over. + } + } + + /// Stands in for the audiobook download: the step whose refusals are remembered. + private sealed class FakeDownload : Processable + { + public override string Name => nameof(FakeDownload); + public Exception? Throw { get; init; } + protected override bool RecordsAttemptFailures => true; + + public override bool Validate(LibraryBook libraryBook) => true; + + public override Task ProcessAsync(LibraryBook libraryBook) + => Throw is null ? Task.FromResult(new StatusHandler()) : throw Throw; + } + + /// Stands in for the PDF or mp3 steps, which never request an audiobook license. + private sealed class FakeOtherStep : Processable + { + public override string Name => nameof(FakeOtherStep); + public Exception? Throw { get; init; } + + public override bool Validate(LibraryBook libraryBook) => true; + + public override Task ProcessAsync(LibraryBook libraryBook) + => Throw is null ? Task.FromResult(new StatusHandler()) : throw Throw; + } + + private static ContentLicenseDeniedException Denied() + => new( + new Uri("https://api.audible.com/1.0/content/B002V5B8OY/licenserequest"), + new ContentLicense + { + Asin = "B002V5B8OY", + StatusCode = "Denied", + LicenseDenialReasons = + [ + new LicenseDenialReason + { + ValidationType = "Ownership", + RejectionReason = RejectionReason.RequesterEligibility, + Message = "Ownership: No Ownership information returned by DAOQS" + } + ] + }); + + private static LibraryBook Book(string title = "Refused Title") + => MockLibraryBook.CreateBook(title: title, bookStatus: LiberatedStatus.NotLiberated); + + private static DeferredDownload? Deferred(LibraryBook libraryBook) + => DownloadAttemptFailureStore.Find(libraryBook, DateTimeOffset.Now); + + [TestMethod] + public async Task A_refused_download_is_remembered_and_the_title_left_alone() + { + var book = Book(); + var processable = new FakeDownload { Configuration = Configuration.Instance, Throw = Denied() }; + + // The exception still reaches the caller: recording must not change how a failure is reported. + await Assert.ThrowsExactlyAsync(() => processable.ProcessSingleAsync(book, validate: true)); + + var deferred = Deferred(book); + Assert.IsNotNull(deferred); + Assert.AreEqual(DownloadFailureKind.LicenseDenied, deferred.Kind); + Assert.AreEqual(1, deferred.ConsecutiveFailures); + StringAssert.StartsWith(deferred.Reason, "Ownership: "); + } + + [TestMethod] + public async Task Each_further_refusal_pushes_the_next_attempt_further_out() + { + var book = Book(); + var processable = new FakeDownload { Configuration = Configuration.Instance, Throw = Denied() }; + + for (var i = 0; i < 3; i++) + await Assert.ThrowsExactlyAsync(() => processable.ProcessSingleAsync(book, validate: true)); + + Assert.AreEqual(3, Deferred(book)!.ConsecutiveFailures); + } + + [TestMethod] + public async Task A_successful_download_forgets_the_refusal() + { + var book = Book(); + await Assert.ThrowsExactlyAsync( + () => new FakeDownload { Configuration = Configuration.Instance, Throw = Denied() }.ProcessSingleAsync(book, validate: true)); + Assert.IsNotNull(Deferred(book)); + + var status = await new FakeDownload { Configuration = Configuration.Instance }.ProcessSingleAsync(book, validate: true); + + Assert.IsTrue(status.IsSuccess); + Assert.IsNull(Deferred(book)); + } + + [TestMethod] + public async Task A_failure_that_is_nothing_to_do_with_Audible_is_not_remembered() + { + // Keeps the long-standing behaviour: retried on the next run, because nothing says it will fail again. + var book = Book(); + var processable = new FakeDownload + { + Configuration = Configuration.Instance, + Throw = new IOException("There is not enough space on the disk.") + }; + + await Assert.ThrowsExactlyAsync(() => processable.ProcessSingleAsync(book, validate: true)); + + Assert.IsNull(Deferred(book)); + } + + [TestMethod] + public async Task A_step_other_than_the_audiobook_download_records_nothing() + { + // A PDF download hits the same license endpoint, but the wait gates the audiobook request, so letting + // the PDF write to the same record would hold back a title whose audio was never refused. + var book = Book(); + var processable = new FakeOtherStep { Configuration = Configuration.Instance, Throw = Denied() }; + + await Assert.ThrowsExactlyAsync(() => processable.ProcessSingleAsync(book, validate: true)); + + Assert.IsNull(Deferred(book)); + } + + [TestMethod] + public async Task A_step_that_fails_validation_records_nothing() + { + var book = Book(); + var processable = new NeverValid { Configuration = Configuration.Instance }; + + var status = await processable.ProcessSingleAsync(book, validate: true); + + Assert.IsFalse(status.IsSuccess); + Assert.IsNull(Deferred(book)); + } + + private sealed class NeverValid : Processable + { + public override string Name => nameof(NeverValid); + protected override bool RecordsAttemptFailures => true; + public override bool Validate(LibraryBook libraryBook) => false; + public override Task ProcessAsync(LibraryBook libraryBook) => throw new InvalidOperationException("must not run"); + } +} diff --git a/Source/_Tests/LibationCli.Tests/DeferredRetryReportingTests.cs b/Source/_Tests/LibationCli.Tests/DeferredRetryReportingTests.cs new file mode 100644 index 00000000..bf383c8a --- /dev/null +++ b/Source/_Tests/LibationCli.Tests/DeferredRetryReportingTests.cs @@ -0,0 +1,142 @@ +using ApplicationServices; +using AudibleApi; +using AudibleApi.Common; +using DataLayer; +using Dinah.Core.ErrorHandling; +using FileLiberator; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.IO; +using System.Threading.Tasks; + +namespace LibationCli.Tests; + +/// +/// What a scheduled run prints when Audible refuses a title. The user in issue #1947 runs from cron, so the +/// console output is the only place they find out that Libation has decided to wait rather than forgotten the +/// title. +/// +[TestClass] +[DoNotParallelize] +public class DeferredRetryReportingTests +{ + private string tempLibationFiles = string.Empty; + + [TestInitialize] + public void Initialize() + { + tempLibationFiles = Path.Combine(Path.GetTempPath(), $"libation-cli-deferred-tests-{Guid.NewGuid():N}"); + Directory.CreateDirectory(tempLibationFiles); + + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, tempLibationFiles); + Configuration.CreateMockInstance(); + } + + [TestCleanup] + public void Cleanup() + { + Configuration.RestoreSingletonInstance(); + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, null); + + try + { + Directory.Delete(tempLibationFiles, recursive: true); + } + catch (IOException) + { + // A leftover temp directory is not worth failing a test over. + } + } + + /// Exposes the shared per-book failure handling without running a real download. + private sealed class TestableRun : ProcessableOptionsBase + { + protected override Task ProcessAsync() => throw new NotSupportedException(); + + public Task ReportAsync(Processable processable, LibraryBook libraryBook) + => ProcessOneAsync(processable, libraryBook, validate: false); + } + + private sealed class RefusedDownload : Processable + { + public override string Name => nameof(RefusedDownload); + public required Exception Throw { get; init; } + protected override bool RecordsAttemptFailures => true; + public override bool Validate(LibraryBook libraryBook) => true; + public override Task ProcessAsync(LibraryBook libraryBook) => throw Throw; + } + + private static ContentLicenseDeniedException Denied() + => new( + new Uri("https://api.audible.com/1.0/content/B002V5B8OY/licenserequest"), + new ContentLicense + { + Asin = "B002V5B8OY", + StatusCode = "Denied", + LicenseDenialReasons = + [ + new LicenseDenialReason + { + ValidationType = "Ownership", + RejectionReason = RejectionReason.RequesterEligibility, + Message = "Ownership: No Ownership information returned by DAOQS" + } + ] + }); + + private async Task RunAndCaptureStdErrAsync(Exception thrown, LibraryBook libraryBook) + { + var original = Console.Error; + using var captured = new StringWriter(); + Console.SetError(captured); + try + { + await new TestableRun().ReportAsync( + new RefusedDownload { Configuration = Configuration.Instance, Throw = thrown }, + libraryBook); + } + finally + { + Console.SetError(original); + } + return captured.ToString(); + } + + private static LibraryBook Book(string title = "Refused Title") + => MockLibraryBook.CreateBook(title: title, bookStatus: LiberatedStatus.NotLiberated); + + [TestMethod] + public async Task A_refusal_says_when_the_title_will_be_attempted_again() + { + var book = Book(); + + var output = await RunAndCaptureStdErrAsync(Denied(), book); + + // The existing per-title detail is still printed the once... + StringAssert.Contains(output, "Audible denied a content license"); + StringAssert.Contains(output, "Ownership: No Ownership information returned by DAOQS"); + // ...followed by the reason the next several runs will say nothing about this title. + StringAssert.Contains(output, "Not attempting this title again in about 1 day"); + StringAssert.Contains(output, $"libationcli liberate {book.Book.AudibleProductId}"); + } + + [TestMethod] + public async Task A_failure_nothing_to_do_with_Audible_still_promises_the_next_run() + { + var output = await RunAndCaptureStdErrAsync(new IOException("Connection reset"), Book()); + + StringAssert.Contains(output, "This book will be tried again on next attempt."); + Assert.IsFalse(output.Contains("Not attempting this title again"), output); + } + + [TestMethod] + public async Task A_refusal_no_longer_claims_the_next_run_will_try_again() + { + // The old message said "will be tried again on next attempt" for every failure, which was untrue for + // the ones now waited on. + var output = await RunAndCaptureStdErrAsync(Denied(), Book()); + + Assert.IsFalse(output.Contains("tried again on next attempt"), output); + } +} diff --git a/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs b/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs new file mode 100644 index 00000000..91feb715 --- /dev/null +++ b/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs @@ -0,0 +1,161 @@ +using AssertionHelper; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using Newtonsoft.Json.Linq; +using Serilog; +using System; +using System.IO; +using System.Linq; + +namespace SerilogConfigurationTests; + +/// +/// Builds a real Serilog logger from the config Libation generates and writes until it rolls. Asserting on the +/// JSON alone would pass just as happily with a misspelled argument name, which Serilog ignores in silence - +/// and silently not rolling is the bug being fixed. +/// +[TestClass] +[DoNotParallelize] +public class LogRolloverTests +{ + private string tempDir = string.Empty; + private ILogger originalLogger = Serilog.Log.Logger; + + [TestInitialize] + public void Initialize() + { + originalLogger = Serilog.Log.Logger; + tempDir = Path.Combine(Path.GetTempPath(), $"libation-log-rollover-tests-{Guid.NewGuid():N}"); + Directory.CreateDirectory(tempDir); + } + + [TestCleanup] + public void Cleanup() + { + Serilog.Log.CloseAndFlush(); + Serilog.Log.Logger = originalLogger; + Configuration.RestoreSingletonInstance(); + + try + { + Directory.Delete(tempDir, recursive: true); + } + catch (IOException) + { + // A leftover temp directory is not worth failing a test over. + } + } + + /// The pre-13.7.9 default: a monthly rolling interval and nothing about size. + private JObject LegacySerilogConfig(long? fileSizeLimitBytes = null) + { + var args = new JObject + { + ["path"] = Path.Combine(tempDir, "Log.log"), + ["rollingInterval"] = "Month", + ["outputTemplate"] = "{Message:lj}{NewLine}" + }; + + if (fileSizeLimitBytes is not null) + args["fileSizeLimitBytes"] = fileSizeLimitBytes; + + return new JObject + { + ["MinimumLevel"] = "Information", + ["WriteTo"] = new JArray { new JObject { ["Name"] = "File", ["Args"] = args } } + }; + } + + private string[] LogFiles() => [.. Directory.GetFiles(tempDir, "Log*.log").Order()]; + + [TestMethod] + public void An_existing_config_is_migrated_and_then_actually_rolls_on_size() + { + var config = Configuration.CreateMockInstance(); + // A small limit so the test writes kilobytes rather than tens of megabytes. Libation's own default + // value is asserted in SerilogConfigurationTests; what matters here is that Serilog obeys it. + config.SetNonString(LegacySerilogConfig(fileSizeLimitBytes: 4096), "Serilog"); + + config.EnsureSerilogConfig(); + config.ConfigureLogging(); + + var line = new string('x', 512); + for (var i = 0; i < 40; i++) + Serilog.Log.Logger.Information(line); + Serilog.Log.CloseAndFlush(); + + var files = LogFiles(); + Assert.IsTrue(files.Length > 1, $"expected the log to roll, found {files.Length} file(s)"); + foreach (var file in files) + Assert.IsTrue(new FileInfo(file).Length < 8192, $"{Path.GetFileName(file)} grew past the size limit"); + } + + [TestMethod] + public void The_generated_default_rolls_on_size_too() + { + var config = Configuration.CreateMockInstance(); + config.EnsureSerilogConfig(); + + var args = (JObject)((JObject)config.GetObject("Serilog")!).SelectToken("$.WriteTo[0].Args")!; + + // Serilog ignores an argument it does not recognise, so the names have to match the sink exactly. + args["fileSizeLimitBytes"] = 4096; + args["path"] = Path.Combine(tempDir, "Log.log"); + args["outputTemplate"] = "{Message:lj}{NewLine}"; + config.SetNonString((JObject)config.GetObject("Serilog")!, "Serilog"); + + config.ConfigureLogging(); + + var line = new string('x', 512); + for (var i = 0; i < 40; i++) + Serilog.Log.Logger.Information(line); + Serilog.Log.CloseAndFlush(); + + var files = LogFiles(); + Assert.IsTrue(files.Length > 1, $"expected the log to roll, found {files.Length} file(s)"); + } + + [TestMethod] + public void Without_size_rolling_a_single_file_grows_unbounded() + { + // The behaviour being fixed, pinned so a future change to the defaults cannot quietly restore it. + var config = Configuration.CreateMockInstance(); + var serilog = LegacySerilogConfig(fileSizeLimitBytes: 4096); + var args = (JObject)serilog.SelectToken("$.WriteTo[0].Args")!; + args["outputTemplate"] = "{Message:lj}{NewLine}"; + args["rollOnFileSizeLimit"] = false; + config.SetNonString(serilog, "Serilog"); + + config.EnsureSerilogConfig(); + config.ConfigureLogging(); + + var line = new string('x', 512); + for (var i = 0; i < 40; i++) + Serilog.Log.Logger.Information(line); + Serilog.Log.CloseAndFlush(); + + // One file, and Serilog stopped writing at the limit rather than starting a new one. + LogFiles().Length.Should().Be(1); + } + + [TestMethod] + public void Old_log_files_beyond_the_retained_count_are_deleted() + { + var config = Configuration.CreateMockInstance(); + var serilog = LegacySerilogConfig(fileSizeLimitBytes: 4096); + var args = (JObject)serilog.SelectToken("$.WriteTo[0].Args")!; + args["outputTemplate"] = "{Message:lj}{NewLine}"; + args["retainedFileCountLimit"] = 2; + config.SetNonString(serilog, "Serilog"); + + config.EnsureSerilogConfig(); + config.ConfigureLogging(); + + var line = new string('x', 512); + for (var i = 0; i < 100; i++) + Serilog.Log.Logger.Information(line); + Serilog.Log.CloseAndFlush(); + + LogFiles().Length.Should().Be(2); + } +} From 69c4f9f0d144d305ef24f56ebe9e114e970a5a0e Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 16:32:24 +0000 Subject: [PATCH 05/14] docs: document waiting before retrying a refused download Adds a Features page covering the wait schedule, what clears it, and what the CLI and app show, plus cross-links from the CLI reference, the daily download limit page and troubleshooting. Troubleshooting also gains an entry for a log too large to attach to a bug report, which is how the reporter in issue #1947 found this. Co-authored-by: rmcrackan --- .vitepress/config.js | 4 + docs/advanced/command-line-interface.md | 4 + docs/advanced/troubleshoot.md | 19 ++++- docs/features/daily-download-limit.md | 4 + docs/features/retrying-refused-downloads.md | 82 +++++++++++++++++++++ 5 files changed, 112 insertions(+), 1 deletion(-) create mode 100644 docs/features/retrying-refused-downloads.md diff --git a/.vitepress/config.js b/.vitepress/config.js index 03836c4b..bbb59d24 100644 --- a/.vitepress/config.js +++ b/.vitepress/config.js @@ -99,6 +99,10 @@ export default defineConfig({ link: "/docs/features/daily-download-limit", }, { text: "Naming Templates", link: "/docs/features/naming-templates" }, + { + text: "Retrying Refused Downloads", + link: "/docs/features/retrying-refused-downloads", + }, { text: "Searching & Filtering", link: "/docs/features/searching-and-filtering", diff --git a/docs/advanced/command-line-interface.md b/docs/advanced/command-line-interface.md index 0b8c93c6..db31a1d3 100644 --- a/docs/advanced/command-line-interface.md +++ b/docs/advanced/command-line-interface.md @@ -158,6 +158,8 @@ libationcli liberate If Audiobookshelf auto-upload is enabled in Settings, `liberate` also uploads each liberated book after download/decrypt (and PDF). See [Audiobookshelf Auto-Upload](/docs/features/audiobookshelf). The separate `convert` command does not upload. To upload books that were already liberated, use [`abs upload`](#upload-already-liberated-books-to-audiobookshelf). +Titles Audible has recently refused a license for are left out of the run and reported as one summary, rather than being requested again every time. This matters most for a scheduled run. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads); naming an ASIN or passing `--force` overrides it. + ## Upload Already-Liberated Books to Audiobookshelf Auto-upload only runs at the moment a book is liberated. Use `abs upload` to send books liberated earlier, using the files already on disk. Nothing is re-downloaded. @@ -206,6 +208,8 @@ libationcli liberate --force libationcli liberate -f ``` +`--force` also attempts the titles Audible recently refused, which a plain run leaves alone. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads). + ## Limit How Much One Run Downloads A large library can take a long time and a lot of disk to liberate in one go. These options stop a run once it has downloaded a given amount, leaving the rest for the next run: diff --git a/docs/advanced/troubleshoot.md b/docs/advanced/troubleshoot.md index fe392588..33f1f209 100644 --- a/docs/advanced/troubleshoot.md +++ b/docs/advanced/troubleshoot.md @@ -6,7 +6,7 @@ **Common causes:** - `TokenStorageMethod` mistyped (canonical values are `Encrypted` and `Plaintext` - casing variants like `PlainText` are accepted, but unknown spellings are not) -- `Serilog.WriteTo` missing, empty, or malformed (not an array of objects with `Name`). Hand-edited custom sink names are allowed; legacy `ZipFile` is migrated to `File` automatically +- `Serilog.WriteTo` missing, empty, or malformed (not an array of objects with `Name`). Hand-edited custom sink names are allowed; legacy `ZipFile` is migrated to `File` automatically, and a `File` sink missing the size-rolling arguments has them filled in - `Serilog.MinimumLevel` set to a value that is not a Serilog level **Fix:** Edit `Settings.json` in your Libation Files directory to a valid value and restart. Do not delete the whole file unless it is corrupt JSON. @@ -187,5 +187,22 @@ These errors come from Audible refusing to grant a download license. Common caus 1. **Temporary Audible outage or Plus throttling** -- wait 24 to 48 hours and try again. See the [FAQ](/docs/frequently-asked-questions). 2. **Title requires Widevine** -- some Plus titles no longer download as AAXC; enable **Use Widevine DRM** in Settings and re-add your account if prompted. See [issue #1580](https://github.com/rmcrackan/Libation/issues/1580). 3. **Spatial / Dolby Atmos requested (older Libation versions)** -- Audible now requires Widevine L1 for many spatial titles. Libation 13.1.3+ no longer offers spatial download. See [Spatial Audio & DRM](/docs/advanced/spatial-audio). +4. **You no longer have rights to the title** -- it was returned, it left the Plus catalog, or the account that owned it is no longer active. Check the title in the Audible app or website. + +After a refusal Libation waits before asking about that title again, so you see the explanation once rather than on every run. It attempts the title again by itself; to try it sooner, name it (`libationcli liberate `) or set its download status to Not Downloaded. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads). Attach your log file when opening a GitHub issue. + +## The log file is too large to attach to a bug report + +From 13.7.9 the log rolls every 10 MB as well as every month, keeping the 20 newest files, so the current +`LogYYYYMM.log` is always small enough to upload. Existing installs pick this up on the next start: Libation +fills in the size-rolling settings your `Settings.json` is missing without touching anything you set yourself. + +Before that, `rollingInterval: "Month"` was the only rolling rule, so one file grew for the whole month -- +tens of MB for an install with several accounts scanned on a frequent schedule, and Serilog's own 1 GB +ceiling would eventually stop it logging at all until the month rolled over. + +If a single file is still too large for what you need, lower `fileSizeLimitBytes` (and, for total disk use, +`retainedFileCountLimit`) in the `File` sink's `Args` in `Settings.json`. See [Docker - +Logging](/docs/installation/docker#logging) for the full sink configuration. diff --git a/docs/features/daily-download-limit.md b/docs/features/daily-download-limit.md index f63d9d67..bc342ab8 100644 --- a/docs/features/daily-download-limit.md +++ b/docs/features/daily-download-limit.md @@ -71,3 +71,7 @@ Containers have no settings dialog, so add the keys to the `Settings.json` you m `DailyDownloadLimit` accepts `NoLimit`, `PlusOnly` or `AllBooks`, and `DailyDownloadLimitUnit` accepts `Books`, `MB` or `GB`. Download counts are kept in Libation's database, so they survive container restarts as long as your database is on a mounted volume, as it is in the standard setup. A container that liberates on a schedule combines well with a limit: each run downloads what it may and stops, and the next run continues where it left off. + +## When a license is denied anyway + +If Audible refuses a license despite the limit, Libation waits before asking about that title again instead of re-requesting it on every run. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads). diff --git a/docs/features/retrying-refused-downloads.md b/docs/features/retrying-refused-downloads.md new file mode 100644 index 00000000..c515dde3 --- /dev/null +++ b/docs/features/retrying-refused-downloads.md @@ -0,0 +1,82 @@ +# Retrying titles Audible refuses + +Some titles in your library cannot be downloaded right now. Audible refuses a content license for a title +you no longer own, for a Plus title that has left the catalog, or for an account that is no longer active. +Others fail because Audible has no audio to send yet, which is what a preorder looks like before its release +date. + +Libation remembers these refusals and waits before asking again. There is nothing to turn on and nothing to +configure. + +## Why it matters + +Without this, a title Audible had just refused was requested again on the very next run. For a scheduled +`libationcli liberate` — a cron job or the Docker image's own loop — that meant re-requesting the same +refused licenses every run, forever: pointless traffic to Audible, which itself risks throttling, and a +console and log full of the same warning for the same titles. + +## How long Libation waits + +The wait starts short and doubles with each refusal in a row. Nothing is ever permanent: every kind of +failure is attempted again on its own, because Audible never tells us the difference between "you will never +have rights to this" and "not right now". + +| What happened | First wait | Longest wait | +|---------------|-----------|--------------| +| Audible refused a license and named an eligibility reason: not owned, not in the Plus catalog, account not entitled | 1 day | 30 days | +| Audible has no downloadable audio for the title, as for an unreleased preorder | 6 hours | 7 days | +| Audible refused but would not say why, which usually means an outage or throttling | 1 hour | 12 hours | + +A refusal for a *different* reason than last time starts the count over: Audible changed its mind about why, +so the wait built up for the old reason no longer describes the situation. + +Failures that are nothing to do with Audible — a dropped connection, a decrypt error, a full disk — are not +waited on at all. They keep being retried on the next run, because nothing about them suggests the next +attempt fails the same way. + +## Asking for a title anyway + +Any of these overrides the wait, and clears it so the schedule starts from the beginning if the attempt fails +again: + +- `libationcli liberate ` — naming a title always attempts it. +- `libationcli liberate --force` — attempts everything, including the refused titles. +- In the app, selecting a single title and downloading it. +- Setting a title's download status to **Not Downloaded** (grid context menu, book details, or + `libationcli set-status`). +- A successful download, which forgets the title's history entirely. + +## What you see + +**On the command line**, one summary per run instead of a warning block per title: + +``` +Skipped 4 titles that recently failed to download. Libation will try again by itself. + Audible denied a download license: 3 (next attempt in about 20 hours) + Audible has no downloadable audio yet: 1 (next attempt in about 2 hours) + To try one now: libationcli liberate . For all of them: libationcli liberate --force. +``` + +The run that first hits a refusal still prints Audible's full explanation for that title, and then says when +the title will be attempted again, so a schedule that goes quiet about a title explains itself rather than +appearing to have forgotten it. + +**In the app**, a multi-title download leaves waited-on titles out of the queue and reports them under +"Waiting before trying again after a recent failure", with what Audible said and when each comes back. A +single-title download is never held back. + +`--pdf` runs are never held back either: the refusal is about the audiobook, and a PDF is a different +request. + +## Relationship to marking a book as an error + +This is separate from the app's Abort / Retry / **Ignore** prompt. Choosing Ignore sets a title's download +status to Error, which stops Libation attempting it until you change the status back yourself. That is a +decision you make; the wait described here is automatic, temporary, and needs nothing from you. + +## Where it is stored + +In Libation's database, alongside the record backing the [daily download +limit](/docs/features/daily-download-limit). The database rather than a file in the Libation Files directory, +because in Docker that directory lives inside the container and only the database is on a volume — a +file-based record would forget every refusal on each container start, which is exactly the case this fixes. From 178715499fce16dd68098211906baa33c1470511 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 16:35:41 +0000 Subject: [PATCH 06/14] refactor: keep the deferral gating and its messaging in one place each Fold the pdf-only exclusion into HonorsDeferredRetries instead of also checking the processable type in the run loop, split the user-facing message building into its own file next to the store, and leave GC.Collect on the success path where it was. Co-authored-by: rmcrackan --- .../ApplicationServices/DeferredDownload.cs | 52 ---------------- .../DeferredDownloadUserMessage.cs | 59 +++++++++++++++++++ Source/FileLiberator/Processable.cs | 6 +- Source/LibationCli/Options/LiberateOptions.cs | 8 ++- .../Options/_ProcessableOptionsBase.cs | 4 +- .../DeferredRetryOptionsTests.cs | 11 ++-- 6 files changed, 73 insertions(+), 67 deletions(-) create mode 100644 Source/ApplicationServices/DeferredDownloadUserMessage.cs diff --git a/Source/ApplicationServices/DeferredDownload.cs b/Source/ApplicationServices/DeferredDownload.cs index 25a86feb..8c6adb2e 100644 --- a/Source/ApplicationServices/DeferredDownload.cs +++ b/Source/ApplicationServices/DeferredDownload.cs @@ -60,55 +60,3 @@ public sealed class DownloadDeferrals public bool IsDeferred(LibraryBook libraryBook) => Find(libraryBook) is not null; } - -/// What to tell the user about titles a run held back, instead of the full warning per title per run. -public static class DeferredDownloadUserMessage -{ - /// - /// A compact breakdown for the log, eg: - /// "Audible denied a download license: 3, Audible has no downloadable audio yet: 1". - /// - public static string BuildLogBreakdown(IEnumerable deferred) - { - var breakdown = string.Join(", ", GroupByKind(deferred).Select(g => $"{g.First().KindLabel}: {g.Count()}")); - return breakdown is "" ? "none" : breakdown; - } - - /// - /// The lines a CLI run prints in place of a full warning per title. Says how many were held back, why, - /// when the soonest will be attempted again, and how to override. - /// - public static IEnumerable BuildCliSkippedLines(IReadOnlyCollection skipped, DateTimeOffset now) - { - if (skipped.Count == 0) - yield break; - - yield return $"Skipped {"title".PluralizeWithCount(skipped.Count)} that recently failed to download. Libation will try again by itself."; - - foreach (var group in GroupByKind(skipped)) - yield return $" {group.First().KindLabel}: {group.Count()} (next attempt {DescribeWhen(group.Min(d => d.RetryAfter), now)})"; - - yield return " To try one now: libationcli liberate . For all of them: libationcli liberate --force."; - } - - /// "in about 3 hours" / "in about 12 days (9/14/2026)" - a summary should not need a clock to read. - public static string DescribeWhen(DateTimeOffset when, DateTimeOffset now) - { - var wait = when - now; - - if (wait <= TimeSpan.Zero) - return "on the next run"; - if (wait < TimeSpan.FromHours(1)) - return $"in about {"minute".PluralizeWithCount(Math.Max(1, (int)wait.TotalMinutes))}"; - - // Rounded first, so a wait of exactly one day does not read as 24 hours or 23, depending on how long - // the run took to reach this line. - var hours = (int)Math.Round(wait.TotalHours); - return hours < 24 - ? $"in about {"hour".PluralizeWithCount(hours)}" - : $"in about {"day".PluralizeWithCount((int)Math.Round(hours / 24d))} ({when.ToLocalTime():d})"; - } - - private static IEnumerable> GroupByKind(IEnumerable deferred) - => deferred.GroupBy(d => d.Kind).OrderBy(g => g.Key); -} diff --git a/Source/ApplicationServices/DeferredDownloadUserMessage.cs b/Source/ApplicationServices/DeferredDownloadUserMessage.cs new file mode 100644 index 00000000..9b88310f --- /dev/null +++ b/Source/ApplicationServices/DeferredDownloadUserMessage.cs @@ -0,0 +1,59 @@ +using DataLayer; +using Dinah.Core; +using System; +using System.Collections.Generic; +using System.Linq; + +namespace ApplicationServices; + +/// What to tell the user about titles a run held back, instead of the full warning per title per run. +public static class DeferredDownloadUserMessage +{ + /// + /// A compact breakdown for the log, eg: + /// "Audible denied a download license: 3, Audible has no downloadable audio yet: 1". + /// + public static string BuildLogBreakdown(IEnumerable deferred) + { + var breakdown = string.Join(", ", GroupByKind(deferred).Select(g => $"{g.First().KindLabel}: {g.Count()}")); + return breakdown is "" ? "none" : breakdown; + } + + /// + /// The lines a CLI run prints in place of a full warning per title. Says how many were held back, why, + /// when the soonest will be attempted again, and how to override. + /// + public static IEnumerable BuildCliSkippedLines(IReadOnlyCollection skipped, DateTimeOffset now) + { + if (skipped.Count == 0) + yield break; + + yield return $"Skipped {"title".PluralizeWithCount(skipped.Count)} that recently failed to download. Libation will try again by itself."; + + foreach (var group in GroupByKind(skipped)) + yield return $" {group.First().KindLabel}: {group.Count()} (next attempt {DescribeWhen(group.Min(d => d.RetryAfter), now)})"; + + yield return " To try one now: libationcli liberate . For all of them: libationcli liberate --force."; + } + + /// "in about 3 hours" / "in about 12 days (9/14/2026)" - a summary should not need a clock to read. + public static string DescribeWhen(DateTimeOffset when, DateTimeOffset now) + { + var wait = when - now; + + if (wait <= TimeSpan.Zero) + return "on the next run"; + if (wait < TimeSpan.FromHours(1)) + return $"in about {"minute".PluralizeWithCount(Math.Max(1, (int)wait.TotalMinutes))}"; + + // Rounded to hours first, so a wait of exactly one day does not read as 23 or 24 hours depending on + // how long the run took to reach this line. + var hours = (int)Math.Round(wait.TotalHours); + return hours < 24 + ? $"in about {"hour".PluralizeWithCount(hours)}" + : $"in about {"day".PluralizeWithCount((int)Math.Round(hours / 24d))} ({when.ToLocalTime():d})"; + } + + private static IEnumerable> GroupByKind(IEnumerable deferred) + => deferred.GroupBy(d => d.Kind).OrderBy(g => g.Key); +} diff --git a/Source/FileLiberator/Processable.cs b/Source/FileLiberator/Processable.cs index 22ad9dae..2e55d344 100644 --- a/Source/FileLiberator/Processable.cs +++ b/Source/FileLiberator/Processable.cs @@ -82,10 +82,8 @@ public abstract class Processable RecordAttemptFailure(libraryBook, ex); throw; } - finally - { - GC.Collect(GC.MaxGeneration, GCCollectionMode.Aggressive, true, true); - } + + GC.Collect(GC.MaxGeneration, GCCollectionMode.Aggressive, true, true); if (status.IsSuccess && RecordsAttemptFailures) DownloadAttemptFailureStore.Clear(libraryBook); diff --git a/Source/LibationCli/Options/LiberateOptions.cs b/Source/LibationCli/Options/LiberateOptions.cs index 27be2daa..22711063 100644 --- a/Source/LibationCli/Options/LiberateOptions.cs +++ b/Source/LibationCli/Options/LiberateOptions.cs @@ -49,8 +49,12 @@ public class LiberateOptions : ProcessableOptionsBase #endregion - // --force means "attempt everything", which includes the titles Audible recently refused. - internal override bool HonorsDeferredRetries => !Force; + /// + /// --force means "attempt everything", which includes the titles Audible recently refused. A --pdf run is + /// never held back either: the refusal recorded against a title is about its audiobook, and a PDF is a + /// different request. + /// + internal override bool HonorsDeferredRetries => !Force && !PdfOnly; protected override async Task ProcessAsync() { diff --git a/Source/LibationCli/Options/_ProcessableOptionsBase.cs b/Source/LibationCli/Options/_ProcessableOptionsBase.cs index 9947deb1..40cebec0 100644 --- a/Source/LibationCli/Options/_ProcessableOptionsBase.cs +++ b/Source/LibationCli/Options/_ProcessableOptionsBase.cs @@ -123,9 +123,7 @@ public abstract class ProcessableOptionsBase : OptionsBase { // Read once, before the first book: a run that spends hours downloading must not start skipping // titles because of failures it recorded itself a moment ago. - var deferrals = HonorsDeferredRetries && Processable is DownloadDecryptBook - ? DownloadDeferrals.Load(DateTimeOffset.Now) - : DownloadDeferrals.None; + var deferrals = HonorsDeferredRetries ? DownloadDeferrals.Load(DateTimeOffset.Now) : DownloadDeferrals.None; var libraryBooks = DbContexts.GetLibrary_Flat_NoTracking(); foreach (var lb in Processable.GetValidLibraryBooks(libraryBooks)) diff --git a/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs b/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs index d5b71ddb..2a351f45 100644 --- a/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs +++ b/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs @@ -27,13 +27,12 @@ public class DeferredRetryOptionsTests => Assert.IsFalse(((ProcessableOptionsBase)Parse("liberate", force)!).HonorsDeferredRetries); [TestMethod] - public void A_pdf_only_run_is_never_held_back() + [DataRow("--pdf")] + [DataRow("-p")] + public void A_pdf_only_run_is_never_held_back(string pdfOnly) { - // The audiobook download is what Audible refused; a --pdf run makes a different request entirely, and - // RunAsync only consults the record for a DownloadDecryptBook. - var options = (LiberateOptions)Parse("liberate", "--pdf")!; - - Assert.IsTrue(options.PdfOnly); + // The refusal recorded against a title is about its audiobook; a PDF is a different request. + Assert.IsFalse(((ProcessableOptionsBase)Parse("liberate", pdfOnly)!).HonorsDeferredRetries); } [TestMethod] From 54485c0825932a3bd5a824d3af968ca6e36f27e2 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Sun, 16 Aug 2026 17:01:29 +0000 Subject: [PATCH 07/14] fix(pdf): save a PDF with its book instead of loose in the Books directory getProposedDownloadFilePath looked for the book's audio file and fell back to the Books directory itself when it found none. That lookup matches on the product id appearing in the path, so it finds nothing for a library whose folder and file templates omit , and nothing for a title marked downloaded whose files are not on this machine. Those PDFs landed in the library root, where they also shared one namespace and so could collide with each other. Fall back to the folder template instead - the same folder the audiobook itself would go in - and create it, since nothing else does on the PDF-only path. Also give MockLibraryBook a three-field version: ToVersionString formats to at least three fields, so the two-field default threw as soon as anything rendered a naming template for a mock book. Co-authored-by: rmcrackan --- Source/DataLayer/MockLibraryBook.cs | 4 +- Source/FileLiberator/AudioFileStorageExt.cs | 5 +- Source/FileLiberator/DownloadPdf.cs | 27 +++- .../DownloadPdfPathTests.cs | 145 ++++++++++++++++++ 4 files changed, 171 insertions(+), 10 deletions(-) create mode 100644 Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs diff --git a/Source/DataLayer/MockLibraryBook.cs b/Source/DataLayer/MockLibraryBook.cs index e37f91b5..59171014 100644 --- a/Source/DataLayer/MockLibraryBook.cs +++ b/Source/DataLayer/MockLibraryBook.cs @@ -106,7 +106,9 @@ public class MockLibraryBook : LibraryBook localeName); lastDlFormat ??= new AudioFormat(Codec.AAC_LC, 128, 44100, 2); - lastDlVersion ??= new Version(13, 0); + // Three fields, like a real Libation version: Extensions.ToVersionString formats to at least three, + // so a two-field default throws as soon as anything renders a naming template for a mock book. + lastDlVersion ??= new Version(13, 0, 0); book.UserDefinedItem.SetLastDownloaded(lastDlVersion, lastDlFormat, "1"); book.UserDefinedItem.PdfStatus = pdfStatus; book.UserDefinedItem.BookStatus = bookStatus; diff --git a/Source/FileLiberator/AudioFileStorageExt.cs b/Source/FileLiberator/AudioFileStorageExt.cs index 965cff4b..9d08f945 100644 --- a/Source/FileLiberator/AudioFileStorageExt.cs +++ b/Source/FileLiberator/AudioFileStorageExt.cs @@ -39,14 +39,15 @@ public static class AudioFileStorageExt } /// - /// PDF: audio file does not exist + /// A file name from the file template, directly under the Books directory rather than in the book's own + /// folder. Only the "save a copy of the cover art" dialogs use this, and only for the name they suggest. /// public static string GetBooksDirectoryFilename(this AudioFileStorage _, LibraryBook libraryBook, string extension, bool returnFirstExisting = false) => AudibleFileStorage.BooksDirectory is { } books ? Templates.File.GetFilename(libraryBook.ToDto(), books, extension, null, returnFirstExisting) : throw new InvalidOperationException("Books directory is not set."); /// - /// PDF: audio file already exists + /// A file name from the file template, in a directory the caller has already chosen. /// public static string GetCustomDirFilename(this AudioFileStorage _, LibraryBook libraryBook, string dirFullPath, string extension, MultiConvertFileProperties? partProperties = null, bool returnFirstExisting = false) => partProperties is null ? Templates.File.GetFilename(libraryBook.ToDto(), dirFullPath, extension, returnFirstExisting: returnFirstExisting) diff --git a/Source/FileLiberator/DownloadPdf.cs b/Source/FileLiberator/DownloadPdf.cs index 81f7df9b..0d5cd732 100644 --- a/Source/FileLiberator/DownloadPdf.cs +++ b/Source/FileLiberator/DownloadPdf.cs @@ -24,7 +24,7 @@ public class DownloadPdf : Processable, IProcessable try { - var proposedDownloadFilePath = getProposedDownloadFilePath(libraryBook); + var proposedDownloadFilePath = GetProposedDownloadFilePath(libraryBook); var actualDownloadedFilePath = await downloadPdfAsync(libraryBook, proposedDownloadFilePath); var result = verifyDownload(actualDownloadedFilePath); @@ -53,16 +53,29 @@ public class DownloadPdf : Processable, IProcessable } } - private static string getProposedDownloadFilePath(LibraryBook libraryBook) + /// + /// Beside the book's audio files, in the folder the naming templates put that book in. + /// + /// The audio file is looked up first so a PDF joins the files already on disk even if they were named by + /// an older template or moved by hand. That lookup matches on the product id appearing in the path, so it + /// finds nothing for a library whose folder and file templates omit <id>, and nothing for a + /// book marked downloaded whose files are not on this machine. Falling back to the folder template rather + /// than to the Books directory itself keeps those PDFs with their book instead of loose in the library + /// root, where they also risk colliding with each other. + /// + /// + internal string GetProposedDownloadFilePath(LibraryBook libraryBook) { var extension = Path.GetExtension(getdownloadUrl(libraryBook)) ?? ".pdf"; - // if audio file exists, get it's dir. else return base Book dir - var existingPath = Path.GetDirectoryName(AudibleFileStorage.Audio.GetPath(libraryBook.Book.AudibleProductId)); - if (existingPath is not null) - return AudibleFileStorage.Audio.GetCustomDirFilename(libraryBook, existingPath, extension); + var destinationDir + = Path.GetDirectoryName(AudibleFileStorage.Audio.GetPath(libraryBook.Book.AudibleProductId)) + ?? AudibleFileStorage.Audio.GetDestinationDirectory(libraryBook, Configuration); - return AudibleFileStorage.Audio.GetBooksDirectoryFilename(libraryBook, extension); + // Nothing else creates it on the PDF-only path, where the book has no folder yet. + Directory.CreateDirectory(destinationDir); + + return AudibleFileStorage.Audio.GetCustomDirFilename(libraryBook, destinationDir, extension); } private static string? getdownloadUrl(LibraryBook libraryBook) diff --git a/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs new file mode 100644 index 00000000..10eceb30 --- /dev/null +++ b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs @@ -0,0 +1,145 @@ +using DataLayer; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.IO; +using System.Linq; + +namespace FileLiberator.Tests; + +/// +/// Where a PDF is saved, against a real Books directory on disk. Reported in issue #1947: PDFs landed loose in +/// the Books directory instead of with their book. +/// +[TestClass] +[DoNotParallelize] +public class DownloadPdfPathTests +{ + private string tempLibationFiles = string.Empty; + private string booksDir = string.Empty; + + [TestInitialize] + public void Initialize() + { + tempLibationFiles = Path.Combine(Path.GetTempPath(), $"libation-pdf-path-tests-{Guid.NewGuid():N}"); + booksDir = Path.Combine(tempLibationFiles, "Books"); + Directory.CreateDirectory(booksDir); + + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, tempLibationFiles); + var config = Configuration.CreateMockInstance(); + config.Books = booksDir; + + // The naming templates read a book's account nickname from here. + AudibleUtilities.AudibleApiStorage.EnsureAccountsSettingsFileExists(); + + // Each test uses its own Books directory, so the cached file list has to be rebuilt against it. + AudibleFileStorage.Audio.Refresh(); + } + + [TestCleanup] + public void Cleanup() + { + Configuration.RestoreSingletonInstance(); + Environment.SetEnvironmentVariable(LibationFiles.LIBATION_FILES_DIR, null); + + try + { + Directory.Delete(tempLibationFiles, recursive: true); + } + catch (IOException) + { + // A leftover temp directory is not worth failing a test over. + } + } + + private static LibraryBook BookWithPdf(string title) + { + var libraryBook = MockLibraryBook.CreateBook(title: title, subtitle: "", bookStatus: LiberatedStatus.Liberated); + libraryBook.Book.AddSupplementDownloadUrl("https://example.com/supplement.pdf"); + return libraryBook; + } + + private string GetPath(LibraryBook libraryBook) + => DownloadPdf.Create(Configuration.Instance).GetProposedDownloadFilePath(libraryBook); + + [TestMethod] + public void A_pdf_goes_beside_the_audio_files_already_on_disk() + { + var libraryBook = BookWithPdf("Beside The Audio"); + // Named by an older template, so not where the current folder template would put it. + var audioDir = Path.Combine(booksDir, "Some Old Folder Name"); + Directory.CreateDirectory(audioDir); + File.WriteAllText(Path.Combine(audioDir, $"whatever [{libraryBook.Book.AudibleProductId}].m4b"), "audio"); + AudibleFileStorage.Audio.Refresh(); + + var path = GetPath(libraryBook); + + Assert.AreEqual(audioDir, Path.GetDirectoryName(path)); + } + + [TestMethod] + public void A_pdf_for_a_book_with_no_audio_on_disk_goes_in_the_books_own_folder() + { + // The bug: this used to return a path directly under the Books directory. + var libraryBook = BookWithPdf("No Audio On Disk"); + + var path = GetPath(libraryBook); + var directory = Path.GetDirectoryName(path)!; + + Assert.AreNotEqual(booksDir, directory, "the PDF was saved loose in the Books directory"); + Assert.AreEqual(booksDir, Path.GetDirectoryName(directory)); + StringAssert.Contains(Path.GetFileName(directory), "No Audio On Disk"); + } + + [TestMethod] + public void The_books_own_folder_is_the_one_the_folder_template_names() + { + var libraryBook = BookWithPdf("Matches The Folder Template"); + + var expected = AudibleFileStorage.Audio.GetDestinationDirectory(libraryBook, Configuration.Instance); + + Assert.AreEqual(expected, Path.GetDirectoryName(GetPath(libraryBook))); + } + + [TestMethod] + public void The_folder_is_created_so_the_download_has_somewhere_to_land() + { + var libraryBook = BookWithPdf("Folder Gets Created"); + + var directory = Path.GetDirectoryName(GetPath(libraryBook))!; + + Assert.IsTrue(Directory.Exists(directory), $"{directory} was not created"); + } + + [TestMethod] + public void Two_books_with_no_audio_on_disk_get_separate_folders() + { + // Loose in the Books directory they shared one namespace, so same-titled books collided. + var first = BookWithPdf("First Book"); + var second = BookWithPdf("Second Book"); + + Assert.AreNotEqual(Path.GetDirectoryName(GetPath(first)), Path.GetDirectoryName(GetPath(second))); + } + + [TestMethod] + public void The_file_name_comes_from_the_file_template() + { + var libraryBook = BookWithPdf("Named By The Template"); + + var path = GetPath(libraryBook); + + // The default file template is " [<id>]"; a library that customises it gets what it asked for. + StringAssert.Contains(Path.GetFileName(path), "Named By The Template"); + StringAssert.Contains(Path.GetFileName(path), libraryBook.Book.AudibleProductId); + Assert.AreEqual(".pdf", Path.GetExtension(path)); + } + + [TestMethod] + public void The_extension_follows_the_supplement_url() + { + var libraryBook = MockLibraryBook.CreateBook(title: "Zip Supplement", subtitle: "", bookStatus: LiberatedStatus.Liberated); + libraryBook.Book.AddSupplementDownloadUrl("https://example.com/supplement.zip"); + + Assert.AreEqual(".zip", Path.GetExtension(GetPath(libraryBook))); + } +} From 870b596d3e53ce65ce822eb8c0bab121863b0739 Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 17:01:29 +0000 Subject: [PATCH 08/14] fix(cli): download the PDFs of titles whose audio is already downloaded A plain 'libationcli liberate' iterates the titles DownloadDecryptBook selects, and that step selects on '!AudioExists'. A title needing nothing but its PDF was therefore never reached by the verb documented as 'book and pdf backups' - only 'liberate --pdf' picked it up. For a library that was liberated before its PDFs were, that is every title with a PDF. Give the bulk run an optional second pass and have liberate use it for PDFs, the way the app's Liberate All always has. Skipped when the first pass stopped early so a run cut short by its download limit does not carry on doing other work, and titles the first pass attempted are excluded by product id rather than by asking Validate again, so a step that just failed is not immediately retried. Left alone: the Audiobookshelf upload stays tied to a fresh liberation. Its Validate passes for any liberated title, so including it here would walk the whole library on the next run. 'abs upload' already exists for that. Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- Source/LibationCli/Options/LiberateOptions.cs | 14 +++- .../Options/_ProcessableOptionsBase.cs | 41 ++++++++-- .../PdfBackFillSelectionTests.cs | 75 +++++++++++++++++++ .../PdfBackFillOptionsTests.cs | 50 +++++++++++++ 4 files changed, 173 insertions(+), 7 deletions(-) create mode 100644 Source/_Tests/FileLiberator.Tests/PdfBackFillSelectionTests.cs create mode 100644 Source/_Tests/LibationCli.Tests/PdfBackFillOptionsTests.cs diff --git a/Source/LibationCli/Options/LiberateOptions.cs b/Source/LibationCli/Options/LiberateOptions.cs index 22711063..aaf69bb9 100644 --- a/Source/LibationCli/Options/LiberateOptions.cs +++ b/Source/LibationCli/Options/LiberateOptions.cs @@ -78,10 +78,22 @@ public class LiberateOptions : ProcessableOptionsBase else { var isTargetedRun = GetProductIds().Any(); - await RunAsync(GetProcessable(), lb => PrepareBookForLiberate(lb, isTargetedRun)); + + await RunAsync( + GetProcessable(), + lb => PrepareBookForLiberate(lb, isTargetedRun), + bulkFollowUp: BackFillsPdfs ? CreateProcessable<DownloadPdf>() : null); } } + /// <summary> + /// Whether this run also picks up titles that need nothing but their PDF. The verb is "book and pdf + /// backups", but the main pass only selects titles that need downloading, so on its own it never reaches + /// one whose audio it already has. A --pdf run selects those titles to begin with, and a run that names + /// its titles re-downloads them and gets their PDFs from that. + /// </summary> + internal bool BackFillsPdfs => !PdfOnly && !GetProductIds().Any(); + private async Task LiberateFromLicense(string licPath) { var licenseInfo = licPath is "-" ? ReadLicenseFromStdIn() diff --git a/Source/LibationCli/Options/_ProcessableOptionsBase.cs b/Source/LibationCli/Options/_ProcessableOptionsBase.cs index 40cebec0..6a2fae89 100644 --- a/Source/LibationCli/Options/_ProcessableOptionsBase.cs +++ b/Source/LibationCli/Options/_ProcessableOptionsBase.cs @@ -90,7 +90,17 @@ public abstract class ProcessableOptionsBase : OptionsBase /// </summary> internal virtual bool HonorsDeferredRetries => false; - protected async Task RunAsync(Processable Processable, Action<LibraryBook>? config = null, Action<string>? notFound = null) + /// <param name="bulkFollowUp"> + /// A second pass over the library, run after <paramref name="Processable"/>, for the titles that pass its + /// own Validate but were not selected by the first. <c>liberate</c> uses this to back-fill PDFs for titles + /// whose audio it already has: the first pass only selects titles that need downloading, so on its own it + /// never reaches a title that needs nothing but its PDF. + /// <para> + /// Bulk runs only. A run that names its titles already gets every step each title needs, because the first + /// pass re-downloads a named title and its PDF follows from that. + /// </para> + /// </param> + protected async Task RunAsync(Processable Processable, Action<LibraryBook>? config = null, Action<string>? notFound = null, Processable? bulkFollowUp = null) { var skippedForDailyLimit = 0; var deferredThisRun = new List<DeferredDownload>(); @@ -107,7 +117,7 @@ public abstract class ProcessableOptionsBase : OptionsBase { if (DbContexts.GetLibraryBook_Flat_NoTracking(asin, caseSensative: false) is LibraryBook lb) { - if (!await ProcessOrStopAsync(lb, true)) + if (!await ProcessOrStopAsync(Processable, lb, true)) break; } else @@ -126,6 +136,8 @@ public abstract class ProcessableOptionsBase : OptionsBase var deferrals = HonorsDeferredRetries ? DownloadDeferrals.Load(DateTimeOffset.Now) : DownloadDeferrals.None; var libraryBooks = DbContexts.GetLibrary_Flat_NoTracking(); + var attempted = new HashSet<string>(StringComparer.OrdinalIgnoreCase); + foreach (var lb in Processable.GetValidLibraryBooks(libraryBooks)) { if (deferrals.Find(lb) is DeferredDownload deferred) @@ -138,9 +150,26 @@ public abstract class ProcessableOptionsBase : OptionsBase continue; } - if (!await ProcessOrStopAsync(lb, false)) + attempted.Add(lb.Book.AudibleProductId); + + if (!await ProcessOrStopAsync(Processable, lb, false)) break; } + + // Skipped when the first pass stopped early, so a run cut short by its download limit does not + // carry on doing other work. Titles the first pass attempted are excluded by product id rather + // than by asking Validate again, so a step that failed a moment ago is not immediately retried. + if (bulkFollowUp is not null && !runLimitReached) + { + foreach (var lb in bulkFollowUp.GetValidLibraryBooks(libraryBooks)) + { + if (attempted.Contains(lb.Book.AudibleProductId)) + continue; + + if (!await ProcessOrStopAsync(bulkFollowUp, lb, false)) + break; + } + } } if (deferredThisRun.Count > 0) @@ -170,7 +199,7 @@ public abstract class ProcessableOptionsBase : OptionsBase // False ends the run. The limit is checked here rather than at the top of the run so that a run whose // books happen to end exactly at the limit says nothing: nothing was cut short. - async Task<bool> ProcessOrStopAsync(LibraryBook libraryBook, bool validate) + async Task<bool> ProcessOrStopAsync(Processable processable, LibraryBook libraryBook, bool validate) { if (runLimit is not null && runLimit.TryStop(out var stopMessage)) { @@ -182,14 +211,14 @@ public abstract class ProcessableOptionsBase : OptionsBase config?.Invoke(libraryBook); - if (IsSkippedByDailyLimit(Processable, libraryBook)) + if (IsSkippedByDailyLimit(processable, libraryBook)) { skippedForDailyLimit++; return true; } runLimit?.Attempting(libraryBook.Book.AudibleProductId); - await ProcessOneAsync(Processable, libraryBook, validate); + await ProcessOneAsync(processable, libraryBook, validate); return true; } } diff --git a/Source/_Tests/FileLiberator.Tests/PdfBackFillSelectionTests.cs b/Source/_Tests/FileLiberator.Tests/PdfBackFillSelectionTests.cs new file mode 100644 index 00000000..b517c36d --- /dev/null +++ b/Source/_Tests/FileLiberator.Tests/PdfBackFillSelectionTests.cs @@ -0,0 +1,75 @@ +using DataLayer; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System.Linq; + +namespace FileLiberator.Tests; + +/// <summary> +/// Which titles each liberation step selects out of a library. Reported in issue #1947: the CLI had never +/// downloaded PDFs. The cause is here - the audiobook step selects on audio alone, so a title that needs +/// nothing but its PDF is not in the set a plain run iterates. +/// </summary> +[TestClass] +public class PdfBackFillSelectionTests +{ + private static LibraryBook Book(string title, LiberatedStatus bookStatus, LiberatedStatus? pdfStatus, bool hasSupplement = true) + { + var libraryBook = MockLibraryBook.CreateBook(title: title, subtitle: "", bookStatus: bookStatus); + libraryBook.WithPdfStatus(pdfStatus ?? LiberatedStatus.NotLiberated); + + if (hasSupplement) + libraryBook.Book.AddSupplementDownloadUrl("https://example.com/supplement.pdf"); + + return libraryBook; + } + + private static LibraryBook[] Library() => + [ + Book("Needs Audio And Pdf", LiberatedStatus.NotLiberated, LiberatedStatus.NotLiberated), + Book("Needs Only Its Pdf", LiberatedStatus.Liberated, LiberatedStatus.NotLiberated), + Book("Needs Nothing", LiberatedStatus.Liberated, LiberatedStatus.Liberated), + Book("Has No Supplement", LiberatedStatus.Liberated, LiberatedStatus.NotLiberated, hasSupplement: false), + ]; + + private static string[] Selected<T>(LibraryBook[] library) where T : Processable, IProcessable<T> + => [.. T.Create(Configuration.CreateMockInstance()) + .GetValidLibraryBooks(library) + .Select(lb => lb.Book.Title)]; + + [TestCleanup] + public void Cleanup() => Configuration.RestoreSingletonInstance(); + + [TestMethod] + public void The_audiobook_step_passes_over_a_title_that_needs_only_its_pdf() + { + // Not a bug in itself: this step has nothing to do for such a title. The bug was that a plain + // liberate run iterated only this set, so nothing else got a look at it either. + CollectionAssert.AreEqual(new[] { "Needs Audio And Pdf" }, Selected<DownloadDecryptBook>(Library())); + } + + [TestMethod] + public void The_pdf_step_selects_every_title_missing_a_pdf_it_can_fetch() + { + CollectionAssert.AreEqual( + new[] { "Needs Audio And Pdf", "Needs Only Its Pdf" }, + Selected<DownloadPdf>(Library())); + } + + [TestMethod] + public void A_title_with_no_supplement_is_never_selected_for_a_pdf() + => Assert.IsFalse(Selected<DownloadPdf>(Library()).Contains("Has No Supplement")); + + [TestMethod] + public void A_title_whose_pdf_is_already_downloaded_is_never_selected() + => Assert.IsFalse(Selected<DownloadPdf>(Library()).Contains("Needs Nothing")); + + [TestMethod] + public void Together_the_two_steps_cover_every_title_that_needs_anything() + { + var library = Library(); + var covered = Selected<DownloadDecryptBook>(library).Union(Selected<DownloadPdf>(library)).ToArray(); + + CollectionAssert.AreEquivalent(new[] { "Needs Audio And Pdf", "Needs Only Its Pdf" }, covered); + } +} diff --git a/Source/_Tests/LibationCli.Tests/PdfBackFillOptionsTests.cs b/Source/_Tests/LibationCli.Tests/PdfBackFillOptionsTests.cs new file mode 100644 index 00000000..485cc889 --- /dev/null +++ b/Source/_Tests/LibationCli.Tests/PdfBackFillOptionsTests.cs @@ -0,0 +1,50 @@ +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System.IO; + +namespace LibationCli.Tests; + +/// <summary> +/// Which liberate runs also pick up titles that need nothing but their PDF. Reported in issue #1947: the CLI +/// had never downloaded PDFs for titles it had already downloaded the audio of. +/// </summary> +[TestClass] +public class PdfBackFillOptionsTests +{ + private static LiberateOptions Parse(params string[] args) + { + using var error = new StringWriter(); + var options = Program.ParseInvocation(args, error).Result?.Value as LiberateOptions; + Assert.IsNotNull(options); + return options; + } + + [TestMethod] + public void A_plain_run_picks_them_up() + => Assert.IsTrue(Parse("liberate").BackFillsPdfs); + + [TestMethod] + public void A_forced_run_picks_them_up() + => Assert.IsTrue(Parse("liberate", "--force").BackFillsPdfs); + + [TestMethod] + public void A_run_with_a_download_limit_picks_them_up() + => Assert.IsTrue(Parse("liberate", "--limit-books", "5").BackFillsPdfs); + + [TestMethod] + [DataRow("--pdf")] + [DataRow("-p")] + public void A_pdf_only_run_needs_no_second_pass(string pdfOnly) + { + // It selects those titles to begin with. + Assert.IsFalse(Parse("liberate", pdfOnly).BackFillsPdfs); + } + + [TestMethod] + [DataRow("liberate", "B017V4IM1G")] + [DataRow("liberate", "--id", "B017V4IM1G")] + public void A_run_that_names_its_titles_needs_no_second_pass(params string[] args) + { + // Naming a title re-downloads it, so its PDF follows from the main pass. + Assert.IsFalse(Parse(args).BackFillsPdfs); + } +} From 87e2ea0ad35ee9ef684fe9005b7d3270b50d7ee2 Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 17:03:01 +0000 Subject: [PATCH 09/14] docs: cover both PDF fixes and the cost of dropping <id> from a template Troubleshooting gains an entry for missing and misplaced PDFs, including the naming-template cause, since a library with no <id> in its folder and file templates is one Libation cannot recognise the output of at all. The CLI reference notes what a plain liberate run now covers, and that the Audiobookshelf upload is deliberately not part of the PDF back-fill. Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- docs/advanced/command-line-interface.md | 8 ++++++++ docs/advanced/troubleshoot.md | 15 +++++++++++++++ docs/features/naming-templates.md | 6 ++++++ 3 files changed, 29 insertions(+) diff --git a/docs/advanced/command-line-interface.md b/docs/advanced/command-line-interface.md index db31a1d3..b91d25bf 100644 --- a/docs/advanced/command-line-interface.md +++ b/docs/advanced/command-line-interface.md @@ -160,6 +160,10 @@ If Audiobookshelf auto-upload is enabled in Settings, `liberate` also uploads ea Titles Audible has recently refused a license for are left out of the run and reported as one summary, rather than being requested again every time. This matters most for a scheduled run. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads); naming an ASIN or passing `--force` overrides it. +The run covers both halves of "book and pdf backups": titles that need downloading, and titles whose audio you already have but whose PDF is missing. Before 13.7.9 it only did the first, so `liberate --pdf` was the only way to get a PDF for a title downloaded earlier. + +Audiobookshelf auto-upload is not part of that second half. It runs when a title is liberated, so a run that only back-fills a PDF does not upload; use `abs upload` to send titles liberated earlier. + ## Upload Already-Liberated Books to Audiobookshelf Auto-upload only runs at the moment a book is liberated. Use `abs upload` to send books liberated earlier, using the files already on disk. Nothing is re-downloaded. @@ -190,6 +194,10 @@ libationcli liberate --pdf libationcli liberate -p ``` +Downloads nothing but PDFs, and never downloads an audiobook. A plain `liberate` covers the same titles, so this is for when you want only the PDFs. + +A PDF is saved beside its audiobook, or in the folder the [folder template](/docs/features/naming-templates) names for that title when Libation cannot find the audio files. Before 13.7.9 the second case put the PDF directly in your Books directory. + ## Re-Liberate a Single Book After Audible updates a title (or to replace a bad file), re-download just that book. Naming an ASIN always re-downloads it, even if it is already liberated: diff --git a/docs/advanced/troubleshoot.md b/docs/advanced/troubleshoot.md index 33f1f209..b6fd5061 100644 --- a/docs/advanced/troubleshoot.md +++ b/docs/advanced/troubleshoot.md @@ -193,6 +193,21 @@ After a refusal Libation waits before asking about that title again, so you see Attach your log file when opening a GitHub issue. +## PDFs are missing, or land loose in the Books directory + +Both were fixed in 13.7.9. + +**`libationcli liberate` downloaded no PDFs.** A plain run only looked at titles that needed an audiobook, so a title whose audio was already downloaded was never reached and its PDF was never fetched. `libationcli liberate --pdf` was the only way to get them. A plain run now covers both. If your library predates the fix, one `libationcli liberate` (or **Liberate** \> **Begin Book and PDF Backups** in the app) collects the PDFs you are missing. + +**PDFs went into the Books directory instead of the book's folder.** Libation saves a PDF beside its audiobook, which it locates by looking for the title's ASIN in the file path. When that lookup found nothing it fell back to the Books directory itself. It now falls back to the folder the [folder template](/docs/features/naming-templates) names for that title. + +The lookup finds nothing in two situations, and the second is worth checking: + +1. The audio files are not on this machine — the title is marked downloaded but the files live elsewhere, or were deleted. +2. **Your folder and file templates have no `<id>` tag.** Then no file Libation writes has the ASIN in its path, so Libation cannot recognise its own output for any title. Add `<id>` back in Settings \> Download/Decrypt; the defaults are `<title short> [<id>]` for folders and `<title> [<id>]` for files. This also explains PDFs with no ASIN in the name: the file name comes from your file template. + +Already-misplaced PDFs are not moved. Move them into their book folders yourself, or set the affected titles' PDF status to Not Downloaded and download them again. + ## The log file is too large to attach to a bug report From 13.7.9 the log rolls every 10 MB as well as every month, keeping the 20 newest files, so the current diff --git a/docs/features/naming-templates.md b/docs/features/naming-templates.md index ff6c605f..2ad0a523 100644 --- a/docs/features/naming-templates.md +++ b/docs/features/naming-templates.md @@ -8,6 +8,12 @@ File and Folder names can be customized using Libation's built-in tag template n These templates apply to both GUI and CLI. +::: tip Keep `<id>` somewhere in your templates +Libation finds a title's existing files by looking for its ASIN in the path. Drop `<id>` from both the folder +and the file template and Libation can no longer recognise its own output, so a later PDF, cover or metadata +download cannot be placed beside the audiobook it belongs to, and the grid cannot tell that a file is present. +::: + ## Template Tags These are the naming template tags currently supported by Libation. From 8fd3b918589bc1160eed737f24dfb7fb66541e3e Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 17:08:13 +0000 Subject: [PATCH 10/14] fix(cli): do not fetch the PDF of a title Audible just refused A PDF is fetched through the same license request as the audiobook, so following a refusal with a PDF request reproduced, through the PDF, exactly the per-run refusal the wait exists to stop. The follow-up pass now skips the titles the first pass deliberately left alone as well as the ones it attempted. Also stop a failed PDF download leaving an empty folder in the library: a PDF-only download is the one case that has to create the book's folder before it has anything to put in it, so it now removes a folder it created and did not fill. GetProposedDownloadFilePath goes back to being a pure path computation. Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- Source/FileLiberator/DownloadPdf.cs | 36 ++++++++++++++++--- .../Options/_ProcessableOptionsBase.cs | 20 +++++++---- .../DownloadPdfPathTests.cs | 25 ++++++++++--- 3 files changed, 67 insertions(+), 14 deletions(-) diff --git a/Source/FileLiberator/DownloadPdf.cs b/Source/FileLiberator/DownloadPdf.cs index 0d5cd732..9074558c 100644 --- a/Source/FileLiberator/DownloadPdf.cs +++ b/Source/FileLiberator/DownloadPdf.cs @@ -21,10 +21,12 @@ public class DownloadPdf : Processable, IProcessable<DownloadPdf> public override async Task<StatusHandler> ProcessAsync(LibraryBook libraryBook) { OnBegin(libraryBook); + string? createdDirectory = null; try { var proposedDownloadFilePath = GetProposedDownloadFilePath(libraryBook); + createdDirectory = createDirectoryFor(proposedDownloadFilePath); var actualDownloadedFilePath = await downloadPdfAsync(libraryBook, proposedDownloadFilePath); var result = verifyDownload(actualDownloadedFilePath); @@ -49,12 +51,41 @@ public class DownloadPdf : Processable, IProcessable<DownloadPdf> } finally { + removeIfLeftEmpty(createdDirectory); OnCompleted(libraryBook); } } + /// <summary>The directory this run had to create, or null when it was already there.</summary> + private static string? createDirectoryFor(string filePath) + { + if (Path.GetDirectoryName(filePath) is not string directory || Directory.Exists(directory)) + return null; + + Directory.CreateDirectory(directory); + return directory; + } + /// <summary> - /// Beside the book's audio files, in the folder the naming templates put that book in. + /// A PDF-only download is the one case that has to make the book's folder before it has anything to put + /// in it. Without this, every failed download would leave an empty folder in the library. + /// </summary> + private static void removeIfLeftEmpty(string? directory) + { + try + { + if (directory is not null && Directory.Exists(directory) && !Directory.EnumerateFileSystemEntries(directory).Any()) + Directory.Delete(directory); + } + catch (Exception ex) + { + Serilog.Log.Logger.Debug(ex, "Could not remove the empty folder left by a failed PDF download: {directory}", directory); + } + } + + /// <summary> + /// Beside the book's audio files, in the folder the naming templates put that book in. The directory may + /// not exist yet; see <see cref="createDirectoryFor"/>. /// <para> /// The audio file is looked up first so a PDF joins the files already on disk even if they were named by /// an older template or moved by hand. That lookup matches on the product id appearing in the path, so it @@ -72,9 +103,6 @@ public class DownloadPdf : Processable, IProcessable<DownloadPdf> = Path.GetDirectoryName(AudibleFileStorage.Audio.GetPath(libraryBook.Book.AudibleProductId)) ?? AudibleFileStorage.Audio.GetDestinationDirectory(libraryBook, Configuration); - // Nothing else creates it on the PDF-only path, where the book has no folder yet. - Directory.CreateDirectory(destinationDir); - return AudibleFileStorage.Audio.GetCustomDirFilename(libraryBook, destinationDir, extension); } diff --git a/Source/LibationCli/Options/_ProcessableOptionsBase.cs b/Source/LibationCli/Options/_ProcessableOptionsBase.cs index 6a2fae89..bf4f674a 100644 --- a/Source/LibationCli/Options/_ProcessableOptionsBase.cs +++ b/Source/LibationCli/Options/_ProcessableOptionsBase.cs @@ -136,10 +136,21 @@ public abstract class ProcessableOptionsBase : OptionsBase var deferrals = HonorsDeferredRetries ? DownloadDeferrals.Load(DateTimeOffset.Now) : DownloadDeferrals.None; var libraryBooks = DbContexts.GetLibrary_Flat_NoTracking(); - var attempted = new HashSet<string>(StringComparer.OrdinalIgnoreCase); + + // Titles the follow-up pass must leave alone: the ones the first pass attempted, and the ones it + // deliberately did not. Recorded by product id rather than re-derived, because neither question + // can be answered from a title's state afterwards - a step that just failed still validates, and + // a title being waited on looks like any other title that needs downloading. + // + // The deferred half matters as much as the attempted half: a PDF is fetched through the same + // license request as the audiobook, so following a refusal with a PDF request would reproduce, + // through the PDF, exactly the per-run refusal the wait exists to stop. + var settledByFirstPass = new HashSet<string>(StringComparer.OrdinalIgnoreCase); foreach (var lb in Processable.GetValidLibraryBooks(libraryBooks)) { + settledByFirstPass.Add(lb.Book.AudibleProductId); + if (deferrals.Find(lb) is DeferredDownload deferred) { deferredThisRun.Add(deferred); @@ -150,20 +161,17 @@ public abstract class ProcessableOptionsBase : OptionsBase continue; } - attempted.Add(lb.Book.AudibleProductId); - if (!await ProcessOrStopAsync(Processable, lb, false)) break; } // Skipped when the first pass stopped early, so a run cut short by its download limit does not - // carry on doing other work. Titles the first pass attempted are excluded by product id rather - // than by asking Validate again, so a step that failed a moment ago is not immediately retried. + // carry on doing other work. if (bulkFollowUp is not null && !runLimitReached) { foreach (var lb in bulkFollowUp.GetValidLibraryBooks(libraryBooks)) { - if (attempted.Contains(lb.Book.AudibleProductId)) + if (settledByFirstPass.Contains(lb.Book.AudibleProductId)) continue; if (!await ProcessOrStopAsync(bulkFollowUp, lb, false)) diff --git a/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs index 10eceb30..9fb3872d 100644 --- a/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs +++ b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs @@ -4,6 +4,7 @@ using Microsoft.VisualStudio.TestTools.UnitTesting; using System; using System.IO; using System.Linq; +using System.Threading.Tasks; namespace FileLiberator.Tests; @@ -102,13 +103,29 @@ public class DownloadPdfPathTests } [TestMethod] - public void The_folder_is_created_so_the_download_has_somewhere_to_land() + public async Task A_failed_download_leaves_no_empty_folder_behind() { - var libraryBook = BookWithPdf("Folder Gets Created"); - + // A PDF-only download is the one case that has to make the book's folder before it has anything to + // put in it, and this download fails: there is no account for the book's locale. + var libraryBook = BookWithPdf("Download Will Fail"); var directory = Path.GetDirectoryName(GetPath(libraryBook))!; - Assert.IsTrue(Directory.Exists(directory), $"{directory} was not created"); + var status = await DownloadPdf.Create(Configuration.Instance).ProcessAsync(libraryBook); + + Assert.IsFalse(status.IsSuccess); + Assert.IsFalse(Directory.Exists(directory), $"{directory} was left behind"); + } + + [TestMethod] + public async Task A_failed_download_leaves_an_existing_folder_alone() + { + var libraryBook = BookWithPdf("Folder Already There"); + var directory = Path.GetDirectoryName(GetPath(libraryBook))!; + Directory.CreateDirectory(directory); + + await DownloadPdf.Create(Configuration.Instance).ProcessAsync(libraryBook); + + Assert.IsTrue(Directory.Exists(directory), "a folder this run did not create was removed"); } [TestMethod] From b212c47cade1221a5861c3c76344b1c4508cabf6 Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 17:08:27 +0000 Subject: [PATCH 11/14] docs: correct how the wait applies to a title's PDF Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- docs/features/retrying-refused-downloads.md | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/docs/features/retrying-refused-downloads.md b/docs/features/retrying-refused-downloads.md index c515dde3..056e901c 100644 --- a/docs/features/retrying-refused-downloads.md +++ b/docs/features/retrying-refused-downloads.md @@ -65,8 +65,9 @@ appearing to have forgotten it. "Waiting before trying again after a recent failure", with what Audible said and when each comes back. A single-title download is never held back. -`--pdf` runs are never held back either: the refusal is about the audiobook, and a PDF is a different -request. +A `--pdf` run is never held back: asking for PDFs specifically is an explicit request. A plain run does hold +back the PDF of a title it is waiting on, though, because Libation fetches a PDF through the same license +request as the audiobook — asking for one would reproduce the refusal it is waiting out. ## Relationship to marking a book as an error From d7a6ef03029e2c13c891d5a40ec7aa0cb92ad583 Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 18:01:37 +0000 Subject: [PATCH 12/14] test(pdf): compare paths the way Libation produces them The two path assertions added with the PDF fix compared a path the test built itself against one that had been through LongPath, which on Windows prefixes a drive-rooted path with \\?\ so paths past the 260 character limit work. Linux adds no prefix, so this only showed up on the Windows job. Normalising both sides is not just about the false failure. The inequality assertion guarding 'the PDF was saved loose in the Books directory' compared a raw temp path against a prefixed one, so on Windows it passed on the prefix alone and would not have caught the bug it exists to catch. Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- .../FileLiberator.Tests/DownloadPdfPathTests.cs | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs index 9fb3872d..9d8d0c77 100644 --- a/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs +++ b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs @@ -63,6 +63,14 @@ public class DownloadPdfPathTests private string GetPath(LibraryBook libraryBook) => DownloadPdf.Create(Configuration.Instance).GetProposedDownloadFilePath(libraryBook); + /// <summary> + /// Every path Libation produces has been through <see cref="FileManager.LongPath"/>, which on Windows + /// prefixes a drive-rooted path with <c>\\?\</c> so paths past the 260 character limit work. A path this + /// test built itself has not. Comparing the two directly is not just a false failure on Windows: an + /// inequality assertion would pass on the prefix alone, whatever the directory actually was. + /// </summary> + private static string? Normalize(string? path) => ((FileManager.LongPath?)path)?.Path; + [TestMethod] public void A_pdf_goes_beside_the_audio_files_already_on_disk() { @@ -75,7 +83,7 @@ public class DownloadPdfPathTests var path = GetPath(libraryBook); - Assert.AreEqual(audioDir, Path.GetDirectoryName(path)); + Assert.AreEqual(Normalize(audioDir), Normalize(Path.GetDirectoryName(path))); } [TestMethod] @@ -87,8 +95,8 @@ public class DownloadPdfPathTests var path = GetPath(libraryBook); var directory = Path.GetDirectoryName(path)!; - Assert.AreNotEqual(booksDir, directory, "the PDF was saved loose in the Books directory"); - Assert.AreEqual(booksDir, Path.GetDirectoryName(directory)); + Assert.AreNotEqual(Normalize(booksDir), Normalize(directory), "the PDF was saved loose in the Books directory"); + Assert.AreEqual(Normalize(booksDir), Normalize(Path.GetDirectoryName(directory))); StringAssert.Contains(Path.GetFileName(directory), "No Audio On Disk"); } @@ -99,7 +107,7 @@ public class DownloadPdfPathTests var expected = AudibleFileStorage.Audio.GetDestinationDirectory(libraryBook, Configuration.Instance); - Assert.AreEqual(expected, Path.GetDirectoryName(GetPath(libraryBook))); + Assert.AreEqual(Normalize(expected), Normalize(Path.GetDirectoryName(GetPath(libraryBook)))); } [TestMethod] From 6daaf33dbce0a55961dae299c623a3355af38b2a Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 18:21:12 +0000 Subject: [PATCH 13/14] docs: the PDF and log fixes ship in 13.7.10, not 13.7.9 Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs | 2 +- .../LibationFileManager.Tests/SerilogConfigurationTests.cs | 2 +- docs/advanced/command-line-interface.md | 4 ++-- docs/advanced/troubleshoot.md | 4 ++-- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs b/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs index 91feb715..937015a0 100644 --- a/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs +++ b/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs @@ -46,7 +46,7 @@ public class LogRolloverTests } } - /// <summary>The pre-13.7.9 default: a monthly rolling interval and nothing about size.</summary> + /// <summary>The pre-13.7.10 default: a monthly rolling interval and nothing about size.</summary> private JObject LegacySerilogConfig(long? fileSizeLimitBytes = null) { var args = new JObject diff --git a/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs b/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs index ed269b85..d0f19758 100644 --- a/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs +++ b/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs @@ -102,7 +102,7 @@ public class SerilogConfigurationTests [TestMethod] public void EnsureSerilogConfig_adds_size_rolling_to_an_existing_config() { - // Existing installs kept the pre-13.7.9 default: monthly rolling only, which let a single + // Existing installs kept the pre-13.7.10 default: monthly rolling only, which let a single // month's log grow past the point where it can be attached to a bug report. var config = Configuration.CreateMockInstance(); config.SetNonString(CreateSerilog("File"), "Serilog"); diff --git a/docs/advanced/command-line-interface.md b/docs/advanced/command-line-interface.md index b91d25bf..90f6362f 100644 --- a/docs/advanced/command-line-interface.md +++ b/docs/advanced/command-line-interface.md @@ -160,7 +160,7 @@ If Audiobookshelf auto-upload is enabled in Settings, `liberate` also uploads ea Titles Audible has recently refused a license for are left out of the run and reported as one summary, rather than being requested again every time. This matters most for a scheduled run. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads); naming an ASIN or passing `--force` overrides it. -The run covers both halves of "book and pdf backups": titles that need downloading, and titles whose audio you already have but whose PDF is missing. Before 13.7.9 it only did the first, so `liberate --pdf` was the only way to get a PDF for a title downloaded earlier. +The run covers both halves of "book and pdf backups": titles that need downloading, and titles whose audio you already have but whose PDF is missing. Before 13.7.10 it only did the first, so `liberate --pdf` was the only way to get a PDF for a title downloaded earlier. Audiobookshelf auto-upload is not part of that second half. It runs when a title is liberated, so a run that only back-fills a PDF does not upload; use `abs upload` to send titles liberated earlier. @@ -196,7 +196,7 @@ libationcli liberate -p Downloads nothing but PDFs, and never downloads an audiobook. A plain `liberate` covers the same titles, so this is for when you want only the PDFs. -A PDF is saved beside its audiobook, or in the folder the [folder template](/docs/features/naming-templates) names for that title when Libation cannot find the audio files. Before 13.7.9 the second case put the PDF directly in your Books directory. +A PDF is saved beside its audiobook, or in the folder the [folder template](/docs/features/naming-templates) names for that title when Libation cannot find the audio files. Before 13.7.10 the second case put the PDF directly in your Books directory. ## Re-Liberate a Single Book diff --git a/docs/advanced/troubleshoot.md b/docs/advanced/troubleshoot.md index b6fd5061..39e2ca97 100644 --- a/docs/advanced/troubleshoot.md +++ b/docs/advanced/troubleshoot.md @@ -195,7 +195,7 @@ Attach your log file when opening a GitHub issue. ## PDFs are missing, or land loose in the Books directory -Both were fixed in 13.7.9. +Both were fixed in 13.7.10. **`libationcli liberate` downloaded no PDFs.** A plain run only looked at titles that needed an audiobook, so a title whose audio was already downloaded was never reached and its PDF was never fetched. `libationcli liberate --pdf` was the only way to get them. A plain run now covers both. If your library predates the fix, one `libationcli liberate` (or **Liberate** \> **Begin Book and PDF Backups** in the app) collects the PDFs you are missing. @@ -210,7 +210,7 @@ Already-misplaced PDFs are not moved. Move them into their book folders yourself ## The log file is too large to attach to a bug report -From 13.7.9 the log rolls every 10 MB as well as every month, keeping the 20 newest files, so the current +From 13.7.10 the log rolls every 10 MB as well as every month, keeping the 20 newest files, so the current `LogYYYYMM.log` is always small enough to upload. Existing installs pick this up on the next start: Libation fills in the size-rolling settings your `Settings.json` is missing without touching anything you set yourself. From a297715b8ab0d2fe8af3c211fc9478de12996f17 Mon Sep 17 00:00:00 2001 From: Cursor Agent <cursoragent@cursor.com> Date: Sun, 16 Aug 2026 18:24:25 +0000 Subject: [PATCH 14/14] Revert "docs: the PDF and log fixes ship in 13.7.10, not 13.7.9" This reverts 6daaf33d. Master is 13.7.8 and the next release is the 0.0.1 increment from it, so the original 13.7.9 references were correct. Co-authored-by: rmcrackan <rmcrackan@gmail.com> --- Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs | 2 +- .../LibationFileManager.Tests/SerilogConfigurationTests.cs | 2 +- docs/advanced/command-line-interface.md | 4 ++-- docs/advanced/troubleshoot.md | 4 ++-- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs b/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs index 937015a0..91feb715 100644 --- a/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs +++ b/Source/_Tests/LibationFileManager.Tests/LogRolloverTests.cs @@ -46,7 +46,7 @@ public class LogRolloverTests } } - /// <summary>The pre-13.7.10 default: a monthly rolling interval and nothing about size.</summary> + /// <summary>The pre-13.7.9 default: a monthly rolling interval and nothing about size.</summary> private JObject LegacySerilogConfig(long? fileSizeLimitBytes = null) { var args = new JObject diff --git a/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs b/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs index d0f19758..ed269b85 100644 --- a/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs +++ b/Source/_Tests/LibationFileManager.Tests/SerilogConfigurationTests.cs @@ -102,7 +102,7 @@ public class SerilogConfigurationTests [TestMethod] public void EnsureSerilogConfig_adds_size_rolling_to_an_existing_config() { - // Existing installs kept the pre-13.7.10 default: monthly rolling only, which let a single + // Existing installs kept the pre-13.7.9 default: monthly rolling only, which let a single // month's log grow past the point where it can be attached to a bug report. var config = Configuration.CreateMockInstance(); config.SetNonString(CreateSerilog("File"), "Serilog"); diff --git a/docs/advanced/command-line-interface.md b/docs/advanced/command-line-interface.md index 90f6362f..b91d25bf 100644 --- a/docs/advanced/command-line-interface.md +++ b/docs/advanced/command-line-interface.md @@ -160,7 +160,7 @@ If Audiobookshelf auto-upload is enabled in Settings, `liberate` also uploads ea Titles Audible has recently refused a license for are left out of the run and reported as one summary, rather than being requested again every time. This matters most for a scheduled run. See [Retrying titles Audible refuses](/docs/features/retrying-refused-downloads); naming an ASIN or passing `--force` overrides it. -The run covers both halves of "book and pdf backups": titles that need downloading, and titles whose audio you already have but whose PDF is missing. Before 13.7.10 it only did the first, so `liberate --pdf` was the only way to get a PDF for a title downloaded earlier. +The run covers both halves of "book and pdf backups": titles that need downloading, and titles whose audio you already have but whose PDF is missing. Before 13.7.9 it only did the first, so `liberate --pdf` was the only way to get a PDF for a title downloaded earlier. Audiobookshelf auto-upload is not part of that second half. It runs when a title is liberated, so a run that only back-fills a PDF does not upload; use `abs upload` to send titles liberated earlier. @@ -196,7 +196,7 @@ libationcli liberate -p Downloads nothing but PDFs, and never downloads an audiobook. A plain `liberate` covers the same titles, so this is for when you want only the PDFs. -A PDF is saved beside its audiobook, or in the folder the [folder template](/docs/features/naming-templates) names for that title when Libation cannot find the audio files. Before 13.7.10 the second case put the PDF directly in your Books directory. +A PDF is saved beside its audiobook, or in the folder the [folder template](/docs/features/naming-templates) names for that title when Libation cannot find the audio files. Before 13.7.9 the second case put the PDF directly in your Books directory. ## Re-Liberate a Single Book diff --git a/docs/advanced/troubleshoot.md b/docs/advanced/troubleshoot.md index 39e2ca97..b6fd5061 100644 --- a/docs/advanced/troubleshoot.md +++ b/docs/advanced/troubleshoot.md @@ -195,7 +195,7 @@ Attach your log file when opening a GitHub issue. ## PDFs are missing, or land loose in the Books directory -Both were fixed in 13.7.10. +Both were fixed in 13.7.9. **`libationcli liberate` downloaded no PDFs.** A plain run only looked at titles that needed an audiobook, so a title whose audio was already downloaded was never reached and its PDF was never fetched. `libationcli liberate --pdf` was the only way to get them. A plain run now covers both. If your library predates the fix, one `libationcli liberate` (or **Liberate** \> **Begin Book and PDF Backups** in the app) collects the PDFs you are missing. @@ -210,7 +210,7 @@ Already-misplaced PDFs are not moved. Move them into their book folders yourself ## The log file is too large to attach to a bug report -From 13.7.10 the log rolls every 10 MB as well as every month, keeping the 20 newest files, so the current +From 13.7.9 the log rolls every 10 MB as well as every month, keeping the 20 newest files, so the current `LogYYYYMM.log` is always small enough to upload. Existing installs pick this up on the next start: Libation fills in the size-rolling settings your `Settings.json` is missing without touching anything you set yourself.