feat: Improved logging

- Handle exceptions better (also write them to serilog)
- Better redaction code
- Less verbose HTTP exception output
- Log more details about git cmd failures

CHANGELOG.md

@@ -8,6 +8,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Changed
+
+- Improved logging: theme changes, better exception handling, more detail written to log files.
+
 ## [3.0.0] - 2022-12-03
 
 This release contains **BREAKING CHANGES**. See the [v3.0 Upgrade Guide][breaking3] for required

src/Directory.Packages.props

@@ -21,6 +21,7 @@
     <PackageVersion Include="ReactiveUI.Blazor" Version="18.4.1" />
     <PackageVersion Include="Serilog" Version="2.12.0" />
     <PackageVersion Include="Serilog.AspNetCore" Version="6.1.0" />
+    <PackageVersion Include="Serilog.Expressions" Version="3.4.1" />
     <PackageVersion Include="Serilog.Sinks.Console" Version="4.1.0" />
     <PackageVersion Include="Serilog.Sinks.File" Version="5.0.0" />
     <PackageVersion Include="System.Data.HashFunction.FNV" Version="2.0.0" />

src/Recyclarr/Command/BaseCommand.cs

@@ -1,13 +1,17 @@
 using Autofac;
 using CliFx;
 using CliFx.Attributes;
+using CliFx.Exceptions;
 using CliFx.Infrastructure;
+using Flurl.Http;
 using JetBrains.Annotations;
 using MoreLinq.Extensions;
 using Recyclarr.Command.Setup;
 using Recyclarr.Logging;
 using Serilog;
 using Serilog.Events;
+using TrashLib.Http;
+using TrashLib.Repo.VersionControl;
 using TrashLib.Startup;
 
 namespace Recyclarr.Command;
@@ -23,6 +27,8 @@ public abstract class BaseCommand : ICommand
     // ReSharper disable once MemberCanBeProtected.Global
     public bool Debug { get; [UsedImplicitly] set; } = false;
 
+    protected ILogger Logger { get; private set; } = Log.Logger;
+
     protected virtual void RegisterServices(ContainerBuilder builder)
     {
     }
@@ -47,6 +53,7 @@ public abstract class BaseCommand : ICommand
             RegisterServices(builder);
         });
 
+        Logger = container.Resolve<ILogger>();
         var tasks = container.Resolve<IOrderedEnumerable<IBaseCommandSetupTask>>().ToArray();
         tasks.ForEach(x => x.OnStart());
 
@@ -54,6 +61,26 @@ public abstract class BaseCommand : ICommand
         {
             await Process(container);
         }
+        catch (Exception e)
+        {
+            switch (e)
+            {
+                case GitCmdException e2:
+                    Logger.Error(e2, "Non-zero exit code {ExitCode} while executing Git command: {Error}",
+                        e2.ExitCode, e2.Error);
+                    break;
+
+                case FlurlHttpException e2:
+                    Logger.Error("HTTP error: {Message}", e2.SanitizedExceptionMessage());
+                    break;
+
+                default:
+                    Logger.Error(e, "Non-recoverable exception");
+                    break;
+            }
+
+            throw new CommandException("Exiting due to exception");
+        }
         finally
         {
             tasks.Reverse().ForEach(x => x.OnFinish());

src/Recyclarr/Command/ServiceCommand.cs

@@ -1,16 +1,8 @@
-using System.Text;
 using Autofac;
 using CliFx.Attributes;
-using CliFx.Exceptions;
-using CliFx.Infrastructure;
-using Flurl.Http;
 using JetBrains.Annotations;
 using Recyclarr.Migration;
-using Serilog;
-using TrashLib.Http;
 using TrashLib.Repo;
-using TrashLib.Repo.VersionControl;
-using YamlDotNet.Core;
 
 namespace Recyclarr.Command;
 
@@ -39,43 +31,12 @@ public abstract class ServiceCommand : BaseCommand, IServiceCommand
         builder.RegisterInstance(this).As<IServiceCommand>();
     }
 
-    public sealed override async ValueTask ExecuteAsync(IConsole console)
-    {
-        try
-        {
-            await base.ExecuteAsync(console);
-        }
-        catch (YamlException e)
-        {
-            var message = e.InnerException is not null ? e.InnerException.Message : e.Message;
-            var msg = new StringBuilder();
-            msg.AppendLine($"Found Unrecognized YAML Property: {message}");
-            msg.AppendLine("Please remove the property quoted in the above message from your YAML file");
-            msg.AppendLine("Exiting due to invalid configuration");
-            throw new CommandException(msg.ToString());
-        }
-        catch (FlurlHttpException e)
-        {
-            throw new CommandException(
-                $"HTTP error while communicating with {Name}: {e.SanitizedExceptionMessage()}");
-        }
-        catch (GitCmdException e)
-        {
-            await console.Output.WriteLineAsync(e.ToString());
-        }
-        catch (Exception e) when (e is not CommandException)
-        {
-            throw new CommandException(e.ToString());
-        }
-    }
-
     public override async Task Process(ILifetimeScope container)
     {
-        var log = container.Resolve<ILogger>();
         var repoUpdater = container.Resolve<IRepoUpdater>();
         var migration = container.Resolve<IMigrationExecutor>();
 
-        log.Debug("Recyclarr Version: {Version}", GitVersionInformation.InformationalVersion);
+        Logger.Debug("Recyclarr Version: {Version}", GitVersionInformation.InformationalVersion);
 
         // Will throw if migration is required, otherwise just a warning is issued.
         migration.CheckNeededMigrations();

src/Recyclarr/Logging/LoggerFactory.cs

@@ -1,6 +1,8 @@
 using System.IO.Abstractions;
 using Serilog;
 using Serilog.Events;
+using Serilog.Templates;
+using Serilog.Templates.Themes;
 using TrashLib.Startup;
 
 namespace Recyclarr.Logging;
@@ -9,21 +11,42 @@ public class LoggerFactory
 {
     private readonly IAppPaths _paths;
 
-    private const string ConsoleTemplate = "[{Level:u3}] {Message:lj}{NewLine}{Exception}";
+    private const string BaseTemplate =
+        "{@m}" +
+        "{@x}" +
+        "\n";
 
     public LoggerFactory(IAppPaths paths)
     {
         _paths = paths;
     }
 
+    private static ExpressionTemplate GetConsoleTemplate()
+    {
+        const string template =
+            "[{@l:u3}] " +
+            BaseTemplate;
+
+        return new ExpressionTemplate(template, theme: TemplateTheme.Code);
+    }
+
+    private static ExpressionTemplate GetFileTemplate()
+    {
+        const string template =
+            "[{@t:HH:mm:ss} {@l:u3}] " +
+            BaseTemplate;
+
+        return new ExpressionTemplate(template);
+    }
+
     public ILogger Create(LogEventLevel level)
     {
         var logPath = _paths.LogDirectory.File($"trash_{DateTime.Now:yyyy-MM-dd_HH-mm-ss}.log");
 
         return new LoggerConfiguration()
             .MinimumLevel.Is(LogEventLevel.Debug)
-            .WriteTo.Console(outputTemplate: ConsoleTemplate, restrictedToMinimumLevel: level)
-            .WriteTo.File(logPath.FullName)
+            .WriteTo.Console(GetConsoleTemplate(), level)
+            .WriteTo.File(GetFileTemplate(), logPath.FullName)
             .CreateLogger();
     }
 }

src/Recyclarr/Recyclarr.csproj

@@ -10,6 +10,7 @@
     <PackageReference Include="Autofac.Extras.Ordering" />
     <PackageReference Include="CliFx" />
     <PackageReference Include="Serilog" />
+    <PackageReference Include="Serilog.Expressions" />
     <PackageReference Include="Serilog.Sinks.Console" />
     <PackageReference Include="Serilog.Sinks.File" />
     <PackageReference Include="TestableIO.System.IO.Abstractions" />

src/TrashLib.Tests/Sonarr/SonarrCompatibilityTest.cs

@@ -7,6 +7,7 @@ using Newtonsoft.Json.Linq;
 using Newtonsoft.Json.Serialization;
 using NSubstitute;
 using NUnit.Framework;
+using Serilog;
 using TestLibrary.AutoFixture;
 using TrashLib.Config.Services;
 using TrashLib.ExceptionTypes;
@@ -57,7 +58,7 @@ public class SonarrCompatibilityTest
 
         var compat = Substitute.For<ISonarrCompatibility>();
         var dataV1 = new SonarrReleaseProfileV1 {Ignored = "one,two,three"};
-        var sut = new SonarrReleaseProfileCompatibilityHandler(compat, ctx.Mapper);
+        var sut = new SonarrReleaseProfileCompatibilityHandler(Substitute.For<ILogger>(), compat, ctx.Mapper);
 
         var result = sut.CompatibleReleaseProfileForReceiving(JObject.Parse(ctx.SerializeJson(dataV1)));
 
@@ -74,7 +75,7 @@ public class SonarrCompatibilityTest
 
         var compat = Substitute.For<ISonarrCompatibility>();
         var dataV2 = new SonarrReleaseProfile {Ignored = new List<string> {"one", "two", "three"}};
-        var sut = new SonarrReleaseProfileCompatibilityHandler(compat, ctx.Mapper);
+        var sut = new SonarrReleaseProfileCompatibilityHandler(Substitute.For<ILogger>(), compat, ctx.Mapper);
 
         var result = sut.CompatibleReleaseProfileForReceiving(JObject.Parse(ctx.SerializeJson(dataV2)));
 
@@ -93,7 +94,7 @@ public class SonarrCompatibilityTest
         }.ToObservable());
 
         var data = new SonarrReleaseProfile {Ignored = new List<string> {"one", "two", "three"}};
-        var sut = new SonarrReleaseProfileCompatibilityHandler(compat, ctx.Mapper);
+        var sut = new SonarrReleaseProfileCompatibilityHandler(Substitute.For<ILogger>(), compat, ctx.Mapper);
 
         var result = await sut.CompatibleReleaseProfileForSendingAsync(data);
 
@@ -112,7 +113,7 @@ public class SonarrCompatibilityTest
         }.ToObservable());
 
         var data = new SonarrReleaseProfile {Ignored = new List<string> {"one", "two", "three"}};
-        var sut = new SonarrReleaseProfileCompatibilityHandler(compat, ctx.Mapper);
+        var sut = new SonarrReleaseProfileCompatibilityHandler(Substitute.For<ILogger>(), compat, ctx.Mapper);
 
         var result = await sut.CompatibleReleaseProfileForSendingAsync(data);
 

src/TrashLib/Http/FlurlExtensions.cs

@@ -7,10 +7,19 @@ public static class FlurlExtensions
 {
     public static string SanitizedExceptionMessage(this FlurlHttpException exception)
     {
-        const string expression =
+        // Replace full URLs
+        const string urlExpression =
             @"https?:\/\/(www\.)?[-a-zA-Z0-9@:%._\+~#=]{1,256}(\:[0-9]+)?\b([-a-zA-Z0-9()@:%_\+.~#?&//=]*)";
+        var result = Regex.Replace(exception.Message, urlExpression, Sanitize);
 
-        return Regex.Replace(exception.ToString(), expression,
-            match => FlurlLogging.SanitizeUrl(match.Value).ToString());
+        // There are sometimes parenthetical parts of the message that contain the host but are not
+        // detected as true URLs. Just strip those out completely.
+        const string hostExpression = @"\([-a-zA-Z0-9@:%._+~#=]{1,256}(?:\:[0-9]+)\)";
+        return Regex.Replace(result, hostExpression, "");
+    }
+
+    private static string Sanitize(Match match)
+    {
+        return FlurlLogging.SanitizeUrl(match.Value).ToString();
     }
 }

src/TrashLib/Http/FlurlLogging.cs

@@ -54,10 +54,10 @@ public static class FlurlLogging
     public static Url SanitizeUrl(Url url)
     {
         // Replace hostname and API key for user privacy
-        url.Host = "hostname";
+        url.Host = "REDACTED";
         if (url.QueryParams.Contains("apikey"))
         {
-            url.QueryParams.AddOrReplace("apikey", "SNIP");
+            url.QueryParams.AddOrReplace("apikey", "REDACTED");
         }
 
         return url;

src/TrashLib/Repo/RepoUpdater.cs

@@ -35,21 +35,19 @@ public class RepoUpdater : IRepoUpdater
     {
         // Retry only once if there's a failure. This gives us an opportunity to delete the git repository and start
         // fresh.
-        var exception = await CheckoutAndUpdateRepo();
-        if (exception is not null)
+        try
+        {
+            await CheckoutAndUpdateRepo();
+        }
+        catch (GitCmdException)
         {
-            _log.Information("Deleting local git repo and retrying git operation...");
+            _log.Warning("Deleting local git repo and retrying git operation due to error...");
             _fileUtils.DeleteReadOnlyDirectory(RepoPath.FullName);
-
-            exception = await CheckoutAndUpdateRepo();
-            if (exception is not null)
-            {
-                throw exception;
-            }
+            await CheckoutAndUpdateRepo();
         }
     }
 
-    private async Task<Exception?> CheckoutAndUpdateRepo()
+    private async Task CheckoutAndUpdateRepo()
     {
         var repoSettings = _settingsProvider.Settings.Repository;
         var cloneUrl = repoSettings.CloneUrl;
@@ -61,19 +59,9 @@ public class RepoUpdater : IRepoUpdater
             _log.Warning("Using explicit SHA1 for local repository: {Sha1}", repoSettings.Sha1);
         }
 
-        try
-        {
-            using var repo = await _repositoryFactory.CreateAndCloneIfNeeded(cloneUrl, RepoPath.FullName, branch);
-            await repo.ForceCheckout(branch);
-            await repo.Fetch();
-            await repo.ResetHard(repoSettings.Sha1 ?? $"origin/{branch}");
-        }
-        catch (GitCmdException e)
-        {
-            _log.Error(e, "An exception occurred during git operations on path: {RepoPath}", RepoPath);
-            return e;
-        }
-
-        return null;
+        using var repo = await _repositoryFactory.CreateAndCloneIfNeeded(cloneUrl, RepoPath.FullName, branch);
+        await repo.ForceCheckout(branch);
+        await repo.Fetch();
+        await repo.ResetHard(repoSettings.Sha1 ?? $"origin/{branch}");
     }
 }

src/TrashLib/Repo/VersionControl/GitCmdException.cs

@@ -4,7 +4,6 @@ public class GitCmdException : Exception
 {
     // ReSharper disable UnusedAutoPropertyAccessor.Global
     public string Error { get; }
-
     public int ExitCode { get; }
     // ReSharper restore UnusedAutoPropertyAccessor.Global
 

src/TrashLib/Repo/VersionControl/GitRepository.cs

@@ -26,7 +26,7 @@ public sealed class GitRepository : IGitRepository
 
     private async Task RunGitCmd(ICollection<string> args)
     {
-        _log.Debug("Executing command: git {Args}", args);
+        _log.Debug("Executing git command with args: {Args}", args);
 
         var output = new StringBuilder();
         var error = new StringBuilder();
@@ -71,6 +71,11 @@ public sealed class GitRepository : IGitRepository
         await RunGitCmd("fetch", remote);
     }
 
+    public async Task Status()
+    {
+        await RunGitCmd("status");
+    }
+
     public async Task ResetHard(string toBranchOrSha1)
     {
         await RunGitCmd("reset", "--hard", toBranchOrSha1);

src/TrashLib/Repo/VersionControl/GitRepositoryFactory.cs

@@ -1,45 +1,20 @@
-using System.IO.Abstractions;
-using System.Text;
-using CliWrap;
-using Common;
 using Serilog;
 
 namespace TrashLib.Repo.VersionControl;
 
 public class GitRepositoryFactory : IGitRepositoryFactory
 {
-    private readonly IFileUtilities _fileUtils;
     private readonly Func<string, IGitRepository> _repoFactory;
-    private readonly IGitPath _gitPath;
     private readonly ILogger _log;
 
     public GitRepositoryFactory(
-        IFileUtilities fileUtils,
         Func<string, IGitRepository> repoFactory,
-        IGitPath gitPath,
         ILogger log)
     {
-        _fileUtils = fileUtils;
         _repoFactory = repoFactory;
-        _gitPath = gitPath;
         _log = log;
     }
 
-    private async Task<(bool Succeeded, string OutputMsg, string ErrorMsg)> IsValid(IDirectoryInfo repoPath)
-    {
-        var output = new StringBuilder();
-        var error = new StringBuilder();
-        var result = await Cli.Wrap(_gitPath.Path)
-            .WithArguments("status")
-            .WithStandardErrorPipe(PipeTarget.ToStringBuilder(error))
-            .WithStandardOutputPipe(PipeTarget.ToStringBuilder(output))
-            .WithValidation(CommandResultValidation.None)
-            .WithWorkingDirectory(repoPath.FullName)
-            .ExecuteAsync();
-
-        return (result.ExitCode == 0, output.ToString(), error.ToString());
-    }
-
     public async Task<IGitRepository> CreateAndCloneIfNeeded(string repoUrl, string repoPath, string branch)
     {
         var repo = _repoFactory(repoPath);
@@ -51,16 +26,9 @@ public class GitRepositoryFactory : IGitRepositoryFactory
         }
         else
         {
-            var validResult = await IsValid(repo.Path);
-            if (!validResult.Succeeded)
-            {
-                _log.Information("Git repository is invalid; deleting and cloning again");
-                _log.Debug("Validity Check Output: {Message}", validResult.OutputMsg.Trim());
-                _log.Debug("Validity Check Error: {Message}", validResult.ErrorMsg.Trim());
-
-                _fileUtils.DeleteReadOnlyDirectory(repo.Path.FullName);
-                await repo.Clone(repoUrl, branch);
-            }
+            // Run just to check repository health. If unhealthy, an exception will
+            // be thrown. That exception will propagate up and result in a re-clone.
+            await repo.Status();
         }
 
         _log.Debug("Remote 'origin' set to {Url}", repoUrl);

src/TrashLib/Repo/VersionControl/IGitRepository.cs

@@ -10,4 +10,5 @@ public interface IGitRepository : IDisposable
     Task SetRemote(string name, string newUrl);
     IDirectoryInfo Path { get; }
     Task Clone(string cloneUrl, string? branch = null);
+    Task Status();
 }

src/TrashLib/Services/CustomFormat/CustomFormatUpdater.cs

@@ -88,7 +88,7 @@ internal class CustomFormatUpdater : ICustomFormatUpdater
         if (_persistenceProcessor.InvalidProfileNames.Count > 0)
         {
             _log.Warning("The following quality profile names are not valid and should either be " +
-                         "removed or renamed in your YAML config");
+                "removed or renamed in your YAML config");
             _log.Warning("{QualityProfileNames}", _persistenceProcessor.InvalidProfileNames);
         }
     }
@@ -136,13 +136,12 @@ internal class CustomFormatUpdater : ICustomFormatUpdater
 
     private bool ValidateGuideDataAndCheckShouldProceed()
     {
-        _console.Output.WriteLine("");
-
         if (_guideProcessor.CustomFormatsNotInGuide.Count > 0)
         {
-            _log.Warning("The Custom Formats below do not exist in the guide and will " +
-                         "be skipped. Trash IDs must match what is listed in the output when using the " +
-                         "`--list-custom-formats` option");
+            _log.Warning(
+                "The Custom Formats below do not exist in the guide and will " +
+                "be skipped. Trash IDs must match what is listed in the output when using the " +
+                "`--list-custom-formats` option");
             _log.Warning("{CfList}", _guideProcessor.CustomFormatsNotInGuide);
 
             _console.Output.WriteLine("");
@@ -155,8 +154,9 @@ internal class CustomFormatUpdater : ICustomFormatUpdater
 
         if (cfsWithoutQualityProfiles.Count > 0)
         {
-            _log.Debug("These custom formats will be uploaded but are not associated to a quality profile in the " +
-                       "config file: {UnassociatedCfs}", cfsWithoutQualityProfiles);
+            _log.Debug(
+                "These custom formats will be uploaded but are not associated to a quality profile in the " +
+                "config file: {UnassociatedCfs}", cfsWithoutQualityProfiles);
 
             _console.Output.WriteLine("");
         }
@@ -171,8 +171,9 @@ internal class CustomFormatUpdater : ICustomFormatUpdater
 
         if (_guideProcessor.CustomFormatsWithoutScore.Count > 0)
         {
-            _log.Information("The below custom formats have no score in the guide or in your YAML config. They will " +
-                             "still be synced, but no score will be set in your chosen quality profiles");
+            _log.Information(
+                "The below custom formats have no score in the guide or in your YAML config. They will " +
+                "still be synced, but no score will be set in your chosen quality profiles");
             foreach (var tuple in _guideProcessor.CustomFormatsWithoutScore)
             {
                 _log.Information("{CfList}", tuple);

src/TrashLib/Services/Sonarr/Api/SonarrReleaseProfileCompatibilityHandler.cs

@@ -10,13 +10,16 @@ namespace TrashLib.Services.Sonarr.Api;
 
 public class SonarrReleaseProfileCompatibilityHandler : ISonarrReleaseProfileCompatibilityHandler
 {
+    private readonly ILogger _log;
     private readonly ISonarrCompatibility _compatibility;
     private readonly IMapper _mapper;
 
     public SonarrReleaseProfileCompatibilityHandler(
+        ILogger log,
         ISonarrCompatibility compatibility,
         IMapper mapper)
     {
+        _log = log;
         _compatibility = compatibility;
         _mapper = mapper;
     }
@@ -38,10 +41,10 @@ public class SonarrReleaseProfileCompatibilityHandler : ISonarrReleaseProfileCom
         if (profile.IsValid(schema, out errorMessages))
         {
             return profile.ToObject<SonarrReleaseProfile>()
-                   ?? throw new InvalidDataException("SonarrReleaseProfile V2 parsing failed");
+                ?? throw new InvalidDataException("SonarrReleaseProfile V2 parsing failed");
         }
 
-        Log.Debug("SonarrReleaseProfile is not a match for V2, proceeding to V1: {Reasons}", errorMessages);
+        _log.Debug("SonarrReleaseProfile is not a match for V2, proceeding to V1: {Reasons}", errorMessages);
 
         schema = JSchema.Parse(SonarrReleaseProfileSchema.V1);
         if (profile.IsValid(schema, out errorMessages))