Improved logging. Updated nuget packages

.gitignore

@@ -332,3 +332,4 @@ ASALocalRun/
 
 # manually ignored files
 /__TODO.txt
+/DataLayer/LibationContext.db

ApplicationServices/UNTESTED/LibraryCommands.cs

@@ -9,30 +9,49 @@ namespace ApplicationServices
 {
 	public static class LibraryCommands
 	{
-		public static async Task<(int totalCount, int newCount)> IndexLibraryAsync(ILoginCallback callback)
+		public static async Task<(int totalCount, int newCount)> ImportLibraryAsync(ILoginCallback callback)
 		{
-			var audibleApiActions = new AudibleApiActions();
-			var items = await audibleApiActions.GetAllLibraryItemsAsync(callback);
-			var totalCount = items.Count;
+			try
+			{
+				var audibleApiActions = new AudibleApiActions();
+				var items = await audibleApiActions.GetAllLibraryItemsAsync(callback);
+				var totalCount = items.Count;
+				Serilog.Log.Logger.Debug($"GetAllLibraryItems: Total count {totalCount}");
 
-			var libImporter = new LibraryImporter();
-			var newCount = await Task.Run(() => libImporter.Import(items));
+				var libImporter = new LibraryImporter();
+				var newCount = await Task.Run(() => libImporter.Import(items));
+				Serilog.Log.Logger.Debug($"Import: New count {newCount}");
 
-			await Task.Run(() => SearchEngineCommands.FullReIndex());
+				await Task.Run(() => SearchEngineCommands.FullReIndex());
+				Serilog.Log.Logger.Debug("FullReIndex: success");
 
-			return (totalCount, newCount);
+				return (totalCount, newCount);
+			}
+			catch (Exception ex)
+			{
+				Serilog.Log.Logger.Error(ex, "Error importing library");
+				throw;
+			}
 		}
 
 		public static int UpdateTags(this LibationContext context, Book book, string newTags)
 		{
-			book.UserDefinedItem.Tags = newTags;
+			try
+			{
+				book.UserDefinedItem.Tags = newTags;
 
-			var qtyChanges = context.SaveChanges();
+				var qtyChanges = context.SaveChanges();
 
-			if (qtyChanges > 0)
-				SearchEngineCommands.UpdateBookTags(book);
+				if (qtyChanges > 0)
+					SearchEngineCommands.UpdateBookTags(book);
 
-			return qtyChanges;
+				return qtyChanges;
+			}
+			catch (Exception ex)
+			{
+				Serilog.Log.Logger.Error(ex, "Error updating tags");
+				throw;
+			}
 		}
 	}
 }

DataLayer/DataLayer.csproj

@@ -12,13 +12,13 @@
   </PropertyGroup>
   
   <ItemGroup>
-    <PackageReference Include="Microsoft.EntityFrameworkCore.Design" Version="3.0.0">
+    <PackageReference Include="Microsoft.EntityFrameworkCore.Design" Version="3.0.1">
       <PrivateAssets>all</PrivateAssets>
       <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
     </PackageReference>
-    <PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite" Version="3.0.0" />
-    <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="3.0.0" />
-    <PackageReference Include="Microsoft.EntityFrameworkCore.Tools" Version="3.0.0">
+    <PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite" Version="3.0.1" />
+    <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="3.0.1" />
+    <PackageReference Include="Microsoft.EntityFrameworkCore.Tools" Version="3.0.1">
       <PrivateAssets>all</PrivateAssets>
       <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
     </PackageReference>

DataLayer/Migrations/20191125182309_Fresh.Designer.cs

@@ -9,7 +9,7 @@ using Microsoft.EntityFrameworkCore.Storage.ValueConversion;
 namespace DataLayer.Migrations
 {
     [DbContext(typeof(LibationContext))]
-    [Migration("20191119144803_Fresh")]
+    [Migration("20191125182309_Fresh")]
     partial class Fresh
     {
         protected override void BuildTargetModel(ModelBuilder modelBuilder)
@@ -129,6 +129,13 @@ namespace DataLayer.Migrations
                     b.HasIndex("Name");
 
                     b.ToTable("Contributors");
+
+                    b.HasData(
+                        new
+                        {
+                            ContributorId = -1,
+                            Name = ""
+                        });
                 });
 
             modelBuilder.Entity("DataLayer.LibraryBook", b =>

DataLayer/Migrations/20191125182309_Fresh.cs

@@ -200,6 +200,11 @@ namespace DataLayer.Migrations
                 columns: new[] { "CategoryId", "AudibleCategoryId", "Name", "ParentCategoryCategoryId" },
                 values: new object[] { -1, "", "", null });
 
+            migrationBuilder.InsertData(
+                table: "Contributors",
+                columns: new[] { "ContributorId", "AudibleContributorId", "Name" },
+                values: new object[] { -1, null, "" });
+
             migrationBuilder.CreateIndex(
                 name: "IX_BookContributor_BookId",
                 table: "BookContributor",

DataLayer/Migrations/LibationContextModelSnapshot.cs

@@ -127,6 +127,13 @@ namespace DataLayer.Migrations
                     b.HasIndex("Name");
 
                     b.ToTable("Contributors");
+
+                    b.HasData(
+                        new
+                        {
+                            ContributorId = -1,
+                            Name = ""
+                        });
                 });
 
             modelBuilder.Entity("DataLayer.LibraryBook", b =>

DataLayer/UNTESTED/EfClasses/Book.cs

@@ -62,7 +62,8 @@ namespace DataLayer
             string description,
             int lengthInMinutes,
 			IEnumerable<Contributor> authors,
-			IEnumerable<Contributor> narrators)
+			IEnumerable<Contributor> narrators,
+			Category category)
         {
             // validate
             ArgumentValidator.EnsureNotNull(audibleProductId, nameof(audibleProductId));
@@ -80,8 +81,7 @@ namespace DataLayer
             _seriesLink = new HashSet<SeriesBook>();
             _supplements = new HashSet<Supplement>();
 
-            // since category/id is never null, nullity means it hasn't been loaded
-            CategoryId = Category.GetEmpty().CategoryId;
+			Category = category;
 
             // simple assigns
             Title = title;
@@ -91,7 +91,7 @@ namespace DataLayer
             // assigns with biz logic
             ReplaceAuthors(authors);
             ReplaceNarrators(narrators);
-        }
+		}
 
         #region contributors, authors, narrators
         // use uninitialised backing fields - this means we can detect if the collection was loaded
@@ -233,8 +233,8 @@ namespace DataLayer
 
         public void UpdateCategory(Category category, DbContext context = null)
         {
-            // since category is never null, nullity means it hasn't been loaded
-            if (Category != null || CategoryId == Category.GetEmpty().CategoryId)
+            // since category is never null, nullity means it hasn't been loaded. non null means we're correctly loaded. just overwrite
+            if (Category != null)
             {
                 Category = category;
                 return;

DataLayer/UNTESTED/EfClasses/Category.cs

@@ -18,8 +18,7 @@ namespace DataLayer
     public class Category
     {
         // Empty is a special case. use private ctor w/o validation
-        public static Category GetEmpty() => new Category { CategoryId = -1, AudibleCategoryId = "", Name = "", ParentCategory = null };
-        public bool IsEmpty() => string.IsNullOrWhiteSpace(AudibleCategoryId) || string.IsNullOrWhiteSpace(Name) || ParentCategory == null;
+        public static Category GetEmpty() => new Category { CategoryId = -1, AudibleCategoryId = "", Name = "" };
 
         internal int CategoryId { get; private set; }
         public string AudibleCategoryId { get; private set; }

DataLayer/UNTESTED/EfClasses/Contributor.cs

@@ -5,21 +5,24 @@ using Dinah.Core;
 namespace DataLayer
 {
     public class Contributor
-    {
-        // contributors search links are just name with url-encoding. space can be + or %20
-        //   author search link:   /search?searchAuthor=Robert+Bevan
-        //   narrator search link: /search?searchNarrator=Robert+Bevan
-        // can also search multiples. concat with comma before url encode
+	{
+		// Empty is a special case. use private ctor w/o validation
+		public static Contributor GetEmpty() => new Contributor { ContributorId = -1, Name = "" };
 
-        // id.s
-        // ----
-        // https://www.audible.com/author/Neil-Gaiman/B000AQ01G2 == https://www.audible.com/author/B000AQ01G2
-        //     goes to summary page
-        //     at bottom "See all titles by Neil Gaiman" goes to https://www.audible.com/search?searchAuthor=Neil+Gaiman
-        // some authors have no id. simply goes to https://www.audible.com/search?searchAuthor=Rufus+Fears
-        // all narrators have no id: https://www.audible.com/search?searchNarrator=Neil+Gaiman
+		// contributors search links are just name with url-encoding. space can be + or %20
+		//   author search link:   /search?searchAuthor=Robert+Bevan
+		//   narrator search link: /search?searchNarrator=Robert+Bevan
+		// can also search multiples. concat with comma before url encode
 
-        internal int ContributorId { get; private set; }
+		// id.s
+		// ----
+		// https://www.audible.com/author/Neil-Gaiman/B000AQ01G2 == https://www.audible.com/author/B000AQ01G2
+		//     goes to summary page
+		//     at bottom "See all titles by Neil Gaiman" goes to https://www.audible.com/search?searchAuthor=Neil+Gaiman
+		// some authors have no id. simply goes to https://www.audible.com/search?searchAuthor=Rufus+Fears
+		// all narrators have no id: https://www.audible.com/search?searchNarrator=Neil+Gaiman
+
+		internal int ContributorId { get; private set; }
         public string Name { get; private set; }
 
         private HashSet<BookContributor> _booksLink;

DataLayer/UNTESTED/LibationContext.cs

@@ -56,10 +56,13 @@ namespace DataLayer
             modelBuilder.ApplyConfiguration(new SeriesBookConfig());
             modelBuilder.ApplyConfiguration(new CategoryConfig());
 
-            // seeds go here. examples in scratch pad
-            modelBuilder
-                .Entity<Category>()
-                .HasData(Category.GetEmpty());
+			// seeds go here. examples in scratch pad
+			modelBuilder
+				.Entity<Category>()
+				.HasData(Category.GetEmpty());
+			modelBuilder
+				.Entity<Contributor>()
+				.HasData(Contributor.GetEmpty());
 
             // views are now supported via "query types" (instead of "entity types"): https://docs.microsoft.com/en-us/ef/core/modeling/query-types
         }

DtoImporterService/UNTESTED/BookImporter.cs

@@ -63,20 +63,30 @@ namespace DtoImporterService
 
 		private static Book createNewBook(Item item, LibationContext context)
 		{
+			// absence of authors is very rare, but possible
+			if (!item.Authors?.Any() ?? true)
+				item.Authors = new[] { new Person { Name = "", Asin = null } };
+
 			// nested logic is required so order of names is retained. else, contributors may appear in the order they were inserted into the db
 			var authors = item
 				.Authors
 				.Select(a => context.Contributors.Local.Single(c => a.Name == c.Name))
 				.ToList();
 
-			// if no narrators listed, author is the narrator
-			if (item.Narrators is null || !item.Narrators.Any())
-				item.Narrators = item.Authors;
-			// nested logic is required so order of names is retained. else, contributors may appear in the order they were inserted into the db
-			var narrators = item
-				.Narrators
-				.Select(n => context.Contributors.Local.Single(c => n.Name == c.Name))
-				.ToList();
+			var narrators
+				= item.Narrators is null || !item.Narrators.Any()
+				// if no narrators listed, author is the narrator
+				? authors
+				// nested logic is required so order of names is retained. else, contributors may appear in the order they were inserted into the db
+				: item
+					.Narrators
+					.Select(n => context.Contributors.Local.Single(c => n.Name == c.Name))
+					.ToList();
+
+			// categories are laid out for a breadcrumb. category is 1st, subcategory is 2nd
+			// absence of categories is very rare, but possible
+			var lastCategory = item.Categories.LastOrDefault()?.CategoryId ?? "";
+			var category = context.Categories.Local.SingleOrDefault(c => c.AudibleCategoryId == lastCategory);
 
 			var book = context.Books.Add(new Book(
 				new AudibleProductId(item.ProductId),
@@ -84,7 +94,8 @@ namespace DtoImporterService
 				item.Description,
 				item.LengthInMinutes,
 				authors,
-				narrators)
+				narrators,
+				category)
 			).Entity;
 
 			var publisherName = item.Publisher;
@@ -94,11 +105,6 @@ namespace DtoImporterService
 				book.ReplacePublisher(publisher);
 			}
 
-			// categories are laid out for a breadcrumb. category is 1st, subcategory is 2nd
-			var category = context.Categories.Local.SingleOrDefault(c => c.AudibleCategoryId == item.Categories.LastOrDefault().CategoryId);
-			if (category != null)
-				book.UpdateCategory(category, context);
-
 			book.UpdateBookDetails(item.IsAbridged, item.DatePublished);
 
 			if (!string.IsNullOrWhiteSpace(item.SupplementUrl))

DtoImporterService/UNTESTED/CategoryImporter.cs

@@ -33,8 +33,11 @@ namespace DtoImporterService
 				.Except(localIds)
 				.ToList();
 
+			// load existing => local
+			// remember to include default/empty/missing
+			var emptyName = Contributor.GetEmpty().Name;
 			if (remainingCategoryIds.Any())
-				context.Categories.Where(c => remainingCategoryIds.Contains(c.AudibleCategoryId)).ToList();
+				context.Categories.Where(c => remainingCategoryIds.Contains(c.AudibleCategoryId) || c.Name == emptyName).ToList();
 		}
 
 		// only use after loading contributors => local

DtoImporterService/UNTESTED/ContributorImporter.cs

@@ -47,11 +47,10 @@ namespace DtoImporterService
 				.ToList();
 
 			// load existing => local
+			// remember to include default/empty/missing
+			var emptyName = Contributor.GetEmpty().Name;
 			if (remainingContribNames.Any())
-				context.Contributors.Where(c => remainingContribNames.Contains(c.Name)).ToList();
-			// _________________________________^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
-			// i tried to extract this pattern, but this part prohibits doing so
-			// wouldn't work anyway for Books.GetBooks()
+				context.Contributors.Where(c => remainingContribNames.Contains(c.Name) || c.Name == emptyName).ToList();
 		}
 
 		// only use after loading contributors => local

FileManager/UNTESTED/FilePathCache.cs

@@ -83,9 +83,9 @@ namespace FileManager
             catch (IOException)
             {
                 try { resave(); }
-                catch (IOException)
-                {
-                    Console.WriteLine("...that's not good");
+                catch (IOException ex)
+				{
+					Serilog.Log.Logger.Error(ex, "Error saving FilePaths.json");
                     throw;
                 }
             }

FileManager/UNTESTED/QuickFilters.cs

@@ -105,12 +105,12 @@ namespace FileManager
             catch (IOException)
             {
                 try { resave(); }
-                catch (IOException)
-                {
-                    Console.WriteLine("...that's not good");
-                    throw;
-                }
-            }
+				catch (IOException ex)
+				{
+					Serilog.Log.Logger.Error(ex, "Error saving QuickFilters.json");
+					throw;
+				}
+			}
         }
     }
 }

InternalUtilities/UNTESTED/AudibleApiActions.cs

@@ -28,7 +28,7 @@ namespace InternalUtilities
 
 		private async Task<List<Item>> getItemsAsync(ILoginCallback callback)
 		{
-			var api = await getApiAsync(callback);
+			var api = await EzApiCreator.GetApiAsync(AudibleApiStorage.IdentityTokensFile, callback, Configuration.Instance.LocaleCountryCode);
 			var items = await AudibleApiExtensions.GetAllLibraryItemsAsync(api);
 
 			// remove episode parents
@@ -62,20 +62,6 @@ namespace InternalUtilities
 			return items;
 		}
 
-		private async Task<Api> getApiAsync(ILoginCallback callback)
-		{
-			try
-			{
-				return await EzApiCreator.GetApiAsync(AudibleApiStorage.IdentityTokensFile, callback, Configuration.Instance.LocaleCountryCode);
-			}
-			catch (Exception ex)
-			{
-				Serilog.Log.Logger.Error(ex, "Error getting Audible API");
-				throw;
-			}
-
-		}
-
 		private static List<IValidator> getValidators()
 		{
 			var type = typeof(IValidator);

InternalUtilities/UNTESTED/AudibleApiExtensions.cs

@@ -27,11 +27,11 @@ namespace InternalUtilities
 					ResponseGroups = LibraryOptions.ResponseGroupOptions.ALL_OPTIONS
 				});
 
-				string pageStr = null;
+				var pageStr = page.ToString();
+
 				LibraryDtoV10 libResult;
 				try
 				{
-					pageStr = page.ToString();
 					// important! use this convert method
 					libResult = LibraryDtoV10.FromJson(pageStr);
 				}
@@ -43,6 +43,8 @@ namespace InternalUtilities
 
 				if (!libResult.Items.Any())
 					break;
+				else
+					Serilog.Log.Logger.Debug($"Page {i}: {libResult.Items.Length} results");
 
 				allItems.AddRange(libResult.Items);
 			}

InternalUtilities/UNTESTED/AudibleApiValidators.cs

@@ -29,12 +29,12 @@ namespace InternalUtilities
 		{
 			var exceptions = new List<Exception>();
 
+			// a book having no authors is rare but allowed
+
 			if (items.Any(i => string.IsNullOrWhiteSpace(i.ProductId)))
 				exceptions.Add(new ArgumentException($"Collection contains item(s) with blank {nameof(Item.ProductId)}", nameof(items)));
 			if (items.Any(i => string.IsNullOrWhiteSpace(i.Title)))
 				exceptions.Add(new ArgumentException($"Collection contains item(s) with blank {nameof(Item.Title)}", nameof(items)));
-			if (items.Any(i => i.Authors is null))
-				exceptions.Add(new ArgumentException($"Collection contains item(s) with null {nameof(Item.Authors)}", nameof(items)));
 
 			return exceptions;
 		}

LibationWinForm/UNTESTED/BookLiberation/AutomatedBackupsForm.cs

@@ -13,10 +13,20 @@ namespace LibationWinForm.BookLiberation
             InitializeComponent();
         }
 
-        public void AppendError(Exception ex) => AppendText("ERROR: " + ex.Message);
-        public void AppendText(string text) => logTb.UIThread(() => logTb.AppendText($"{DateTime.Now} {text}{Environment.NewLine}"));
+		public void AppendError(Exception ex)
+		{
+			Serilog.Log.Logger.Error(ex, "Automated backup: error");
+			appendText("ERROR: " + ex.Message);
+		}
+		public void AppendText(string text)
+		{
+			Serilog.Log.Logger.Debug($"Automated backup: {text}");
+			appendText(text);
+		}
+		private void appendText(string text)
+			=> logTb.UIThread(() => logTb.AppendText($"{DateTime.Now} {text}{Environment.NewLine}"));
 
-        public void FinalizeUI()
+		public void FinalizeUI()
         {
             keepGoingCb.Enabled = false;
             logTb.AppendText("");

LibationWinForm/UNTESTED/BookLiberation/DecryptForm.cs

@@ -13,11 +13,10 @@ namespace LibationWinForm.BookLiberation
             InitializeComponent();
         }
 
-        System.IO.TextWriter origOut = Console.Out;
+        System.IO.TextWriter origOut { get; } = Console.Out;
         private void DecryptForm_Load(object sender, EventArgs e)
         {
             // redirect Console.WriteLine to console, textbox
-            System.IO.TextWriter origOut = Console.Out;
             var controlWriter = new RichTextBoxTextWriter(this.rtbLog);
             var multiLogger = new MultiTextWriter(origOut, controlWriter);
             Console.SetOut(multiLogger);
@@ -58,13 +57,19 @@ namespace LibationWinForm.BookLiberation
         public void SetCoverImage(byte[] coverBytes)
             => pictureBox1.UIThread(() => pictureBox1.Image = ImageReader.ToImage(coverBytes));
 
-        public static void AppendError(Exception ex) => AppendText("ERROR: " + ex.Message);
-        public static void AppendText(string text) =>
-            // redirected to log textbox
-            Console.WriteLine($"{DateTime.Now} {text}")
-            //logTb.UIThread(() => logTb.AppendText($"{DateTime.Now} {text}{Environment.NewLine}"))
-            ;
+		public void AppendError(Exception ex)
+		{
+			Serilog.Log.Logger.Error(ex, "Decrypt form: error");
+			appendText("ERROR: " + ex.Message);
+		}
+		public void AppendText(string text)
+		{
+			Serilog.Log.Logger.Debug($"Decrypt form: {text}");
+			appendText(text);
+		}
+		private void appendText(string text) => Console.WriteLine($"{DateTime.Now} {text}");
 
-        public void UpdateProgress(int percentage) => progressBar1.UIThread(() => progressBar1.Value = percentage);
+
+		public void UpdateProgress(int percentage) => progressBar1.UIThread(() => progressBar1.Value = percentage);
     }
 }

LibationWinForm/UNTESTED/Dialogs/IndexLibraryDialog.cs

@@ -19,12 +19,11 @@ namespace LibationWinForm
 		{
 			try
 			{
-				(TotalBooksProcessed, NewBooksAdded) = await LibraryCommands.IndexLibraryAsync(new Login.WinformResponder());
+				(TotalBooksProcessed, NewBooksAdded) = await LibraryCommands.ImportLibraryAsync(new Login.WinformResponder());
 			}
 			catch (Exception ex)
 			{
-				var msg = "Error importing library. Please try again. If this happens after 2 or 3 tries, contact administrator";
-				Serilog.Log.Logger.Error(ex, msg);
+				var msg = "Error importing library. Please try again. If this still happens after 2 or 3 tries, stop and contact administrator";
 				MessageBox.Show(msg, "Error importing library", MessageBoxButtons.OK, MessageBoxIcon.Error);
 			}
 

LibationWinForm/UNTESTED/Program.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Windows.Forms;
+using Dinah.Core.Logging;
 using Serilog;
 
 namespace LibationWinForm
@@ -45,11 +46,29 @@ Go to Import > Scan Library
 
 		private static void init()
 		{
+			// default. for reference. output example:
+			// 2019-11-26 08:48:40.224 -05:00 [DBG] Begin Libation
+			var default_outputTemplate = "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}";
+			// with class and method info. output example:
+			// 2019-11-26 08:48:40.224 -05:00 [DBG] (at LibationWinForm.Program.init()) Begin Libation
+			var code_outputTemplate = "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] (at {Caller}) {Message:lj}{NewLine}{Exception}";
+
+
 			var logPath = System.IO.Path.Combine(FileManager.Configuration.Instance.LibationFiles, "Log.log");
+
 			Log.Logger = new LoggerConfiguration()
+				.Enrich.WithCaller()
 				.MinimumLevel.Debug()
-				.WriteTo.File(logPath, rollingInterval: RollingInterval.Month)
+				.WriteTo.File(logPath,
+					rollingInterval: RollingInterval.Month,
+					outputTemplate: code_outputTemplate)
 				.CreateLogger();
+
+			Log.Logger.Debug("Begin Libation");
+
+			// .Here() captures debug info via System.Runtime.CompilerServices attributes. Warning: expensive
+			//var withLineNumbers_outputTemplate = "[{Timestamp:HH:mm:ss} {Level}] {SourceContext}{NewLine}{Message}{NewLine}in method {MemberName} at {FilePath}:{LineNumber}{NewLine}{Exception}{NewLine}";
+			//Log.Logger.Here().Debug("Begin Libation. Debug with line numbers");
 		}
 	}
 }

REFERENCE.txt

@@ -1,6 +1,8 @@
 -- begin VERSIONING ---------------------------------------------------------------------------------------------------------------------
 https://github.com/rmcrackan/Libation/releases
 
+v3.1-beta.6 : Improved logging
+v3.1-beta.5 : Improved importing
 v3.1-beta.4 : Added beta-specific logging
 v3.1-beta.3 : fixed known performance issue: Full-screen grid is slow to respond loading when books aren't liberated
 v3.1-beta.2 : fixed known performance issue: Tag add/edit