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/Source/ApplicationServices/DeferredDownload.cs b/Source/ApplicationServices/DeferredDownload.cs new file mode 100644 index 00000000..8c6adb2e --- /dev/null +++ b/Source/ApplicationServices/DeferredDownload.cs @@ -0,0 +1,62 @@ +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; +} 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/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..986c563e --- /dev/null +++ b/Source/ApplicationServices/DownloadRetryBackoff.cs @@ -0,0 +1,53 @@ +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]; + + // 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; + } + + /// 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/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/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..c58bd643 --- /dev/null +++ b/Source/FileLiberator/DownloadFailureClassifier.cs @@ -0,0 +1,90 @@ +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 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 + = stated.Length == 0 + || stated.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/DownloadPdf.cs b/Source/FileLiberator/DownloadPdf.cs index 81f7df9b..9074558c 100644 --- a/Source/FileLiberator/DownloadPdf.cs +++ b/Source/FileLiberator/DownloadPdf.cs @@ -21,10 +21,12 @@ public class DownloadPdf : Processable, IProcessable public override async Task ProcessAsync(LibraryBook libraryBook) { OnBegin(libraryBook); + string? createdDirectory = null; try { - var proposedDownloadFilePath = getProposedDownloadFilePath(libraryBook); + var proposedDownloadFilePath = GetProposedDownloadFilePath(libraryBook); + createdDirectory = createDirectoryFor(proposedDownloadFilePath); var actualDownloadedFilePath = await downloadPdfAsync(libraryBook, proposedDownloadFilePath); var result = verifyDownload(actualDownloadedFilePath); @@ -49,20 +51,59 @@ public class DownloadPdf : Processable, IProcessable } finally { + removeIfLeftEmpty(createdDirectory); OnCompleted(libraryBook); } } - private static string getProposedDownloadFilePath(LibraryBook libraryBook) + /// The directory this run had to create, or null when it was already there. + private static string? createDirectoryFor(string filePath) + { + if (Path.GetDirectoryName(filePath) is not string directory || Directory.Exists(directory)) + return null; + + Directory.CreateDirectory(directory); + return directory; + } + + /// + /// 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. + /// + 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); + } + } + + /// + /// Beside the book's audio files, in the folder the naming templates put that book in. The directory may + /// not exist yet; see . + /// + /// 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); + return AudibleFileStorage.Audio.GetCustomDirFilename(libraryBook, destinationDir, extension); } private static string? getdownloadUrl(LibraryBook libraryBook) diff --git a/Source/FileLiberator/Processable.cs b/Source/FileLiberator/Processable.cs index 813029ab..2e55d344 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,40 @@ 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; + } 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..aaf69bb9 100644 --- a/Source/LibationCli/Options/LiberateOptions.cs +++ b/Source/LibationCli/Options/LiberateOptions.cs @@ -49,6 +49,13 @@ public class LiberateOptions : ProcessableOptionsBase #endregion + /// + /// --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() { if (!RunDownloadLimit.TryCreate(LimitBooks, LimitMB, LimitGB, PdfOnly, out runLimit, out var limitError)) @@ -71,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() : null); } } + /// + /// 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. + /// + internal bool BackFillsPdfs => !PdfOnly && !GetProductIds().Any(); + private async Task LiberateFromLicense(string licPath) { var licenseInfo = licPath is "-" ? ReadLicenseFromStdIn() @@ -174,6 +193,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..bf4f674a 100644 --- a/Source/LibationCli/Options/_ProcessableOptionsBase.cs +++ b/Source/LibationCli/Options/_ProcessableOptionsBase.cs @@ -84,9 +84,26 @@ 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; - protected async Task RunAsync(Processable Processable, Action? config = null, Action? notFound = 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. + /// + internal virtual bool HonorsDeferredRetries => false; + + /// + /// A second pass over the library, run after , for the titles that pass its + /// own Validate but were not selected by the first. liberate 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. + /// + /// 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. + /// + /// + protected async Task RunAsync(Processable Processable, Action? config = null, Action? notFound = null, Processable? bulkFollowUp = 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 @@ -100,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 @@ -114,12 +131,65 @@ 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 ? DownloadDeferrals.Load(DateTimeOffset.Now) : DownloadDeferrals.None; + var libraryBooks = DbContexts.GetLibrary_Flat_NoTracking(); + + // 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(StringComparer.OrdinalIgnoreCase); + foreach (var lb in Processable.GetValidLibraryBooks(libraryBooks)) { - if (!await ProcessOrStopAsync(lb, false)) + settledByFirstPass.Add(lb.Book.AudibleProductId); + + 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(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. + if (bulkFollowUp is not null && !runLimitReached) + { + foreach (var lb in bulkFollowUp.GetValidLibraryBooks(libraryBooks)) + { + if (settledByFirstPass.Contains(lb.Book.AudibleProductId)) + continue; + + if (!await ProcessOrStopAsync(bulkFollowUp, 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) @@ -137,7 +207,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 ProcessOrStopAsync(LibraryBook libraryBook, bool validate) + async Task ProcessOrStopAsync(Processable processable, LibraryBook libraryBook, bool validate) { if (runLimit is not null && runLimit.TryStop(out var stopMessage)) { @@ -149,14 +219,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; } } @@ -219,18 +289,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/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/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; 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/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/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/FileLiberator.Tests/DownloadPdfPathTests.cs b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs new file mode 100644 index 00000000..9d8d0c77 --- /dev/null +++ b/Source/_Tests/FileLiberator.Tests/DownloadPdfPathTests.cs @@ -0,0 +1,170 @@ +using DataLayer; +using LibationFileManager; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System; +using System.IO; +using System.Linq; +using System.Threading.Tasks; + +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); + + /// + /// Every path Libation produces has been through , which on Windows + /// prefixes a drive-rooted path with \\?\ 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. + /// + private static string? Normalize(string? path) => ((FileManager.LongPath?)path)?.Path; + + [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(Normalize(audioDir), Normalize(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(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"); + } + + [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(Normalize(expected), Normalize(Path.GetDirectoryName(GetPath(libraryBook)))); + } + + [TestMethod] + public async Task A_failed_download_leaves_no_empty_folder_behind() + { + // 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))!; + + 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] + 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))); + } +} 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/DeferredRetryOptionsTests.cs b/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs new file mode 100644 index 00000000..2a351f45 --- /dev/null +++ b/Source/_Tests/LibationCli.Tests/DeferredRetryOptionsTests.cs @@ -0,0 +1,44 @@ +using Microsoft.VisualStudio.TestTools.UnitTesting; +using System.IO; + +namespace LibationCli.Tests; + +/// <summary> +/// Which liberate runs leave alone the titles Audible recently refused. A run that says what it wants +/// downloaded must always attempt it. +/// </summary> +[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] + [DataRow("--pdf")] + [DataRow("-p")] + public void A_pdf_only_run_is_never_held_back(string 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] + 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/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; + +/// <summary> +/// 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. +/// </summary> +[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. + } + } + + /// <summary>Exposes the shared per-book failure handling without running a real download.</summary> + 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<StatusHandler> 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<string> 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/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); + } +} 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; + +/// <summary> +/// 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. +/// </summary> +[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. + } + } + + /// <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 + { + ["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); + } +} 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<long>()); + Assert.IsTrue(args["rollOnFileSizeLimit"]!.Value<bool>()); + Assert.AreEqual(Configuration.LogRetainedFileCountLimit, args["retainedFileCountLimit"]!.Value<int>()); + + 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<long>()); + Assert.IsTrue(args["rollOnFileSizeLimit"]!.Value<bool>()); + Assert.AreEqual(Configuration.LogRetainedFileCountLimit, args["retainedFileCountLimit"]!.Value<int>()); + // the migration must not disturb what the user already had + Assert.AreEqual("Month", args["rollingInterval"]!.Value<string>()); + } + + [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<long>()); + Assert.IsFalse(args["rollOnFileSizeLimit"]!.Value<bool>()); + Assert.AreEqual(3, args["retainedFileCountLimit"]!.Value<int>()); + } + + [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/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"); + } } diff --git a/docs/advanced/command-line-interface.md b/docs/advanced/command-line-interface.md index 0b8c93c6..b91d25bf 100644 --- a/docs/advanced/command-line-interface.md +++ b/docs/advanced/command-line-interface.md @@ -158,6 +158,12 @@ 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. + +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. @@ -188,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: @@ -206,6 +216,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..b6fd5061 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,37 @@ 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 <ASIN>`) 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. + +## 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 +`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/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. diff --git a/docs/features/retrying-refused-downloads.md b/docs/features/retrying-refused-downloads.md new file mode 100644 index 00000000..056e901c --- /dev/null +++ b/docs/features/retrying-refused-downloads.md @@ -0,0 +1,83 @@ +# 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 <ASIN>` — 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 <ASIN>. 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. + +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 + +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. 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`.