mirror of
https://github.com/rmcrackan/Libation.git
synced 2026-10-28 08:29:11 -04:00
Log startup recovery without Serilog so a broken install cannot silence it
Libation's releases are ReadyToRun, so a Serilog reference resolves lazily when the line holding it runs. An install folder whose Serilog.dll is missing or older than the build therefore threw inside the very catch blocks that were meant to report the problem, which destroyed the original exception and aborted the in-app upgrade recovery before it could roll anything back. Add StartupLog: a Serilog-free, never-throwing buffer for the window before ConfigureLogging runs, replayed into Serilog once logging exists. Move the pre-logging call sites onto it, including the crash-message and crash-dialog paths that run precisely when the install is broken. Those messages were silent before this change: Serilog.Log.Logger is still Serilog's silent logger until App.RunMigrations. They now reach the log file. Co-authored-by: rmcrackan <rmcrackan@gmail.com>
This commit is contained in:
10 files changed
+193
-45
No files matched your search
@@ -208,12 +208,34 @@ public static class LibationScaffolding
|
||||
private static void ensureSerilogConfig(Configuration config)
|
||||
=> config.EnsureSerilogConfig();
|
||||
|
||||
/// <summary>
|
||||
/// Hands everything <see cref="StartupLog"/> collected before this point to Serilog, and points it at
|
||||
/// Serilog from here on. Startup runs long before logging exists, so without this those diagnostics are
|
||||
/// simply dropped. This is also the only place in Libation that maps a startup entry onto a Serilog level.
|
||||
/// </summary>
|
||||
private static void replayStartupLog()
|
||||
=> StartupLog.ReplayTo(entry =>
|
||||
{
|
||||
var level = entry.Level switch
|
||||
{
|
||||
StartupLogLevel.Debug => Serilog.Events.LogEventLevel.Debug,
|
||||
StartupLogLevel.Warning => Serilog.Events.LogEventLevel.Warning,
|
||||
StartupLogLevel.Error => Serilog.Events.LogEventLevel.Error,
|
||||
_ => Serilog.Events.LogEventLevel.Information,
|
||||
};
|
||||
|
||||
// The message is already rendered: startup cannot build a Serilog template without
|
||||
// referencing Serilog, which is the whole point of StartupLog. See issue #2001.
|
||||
Log.Logger.Write(level, entry.Exception, "[startup {StartupTimestamp:HH:mm:ss.fff}] {StartupMessage}", entry.Timestamp, entry.Message);
|
||||
});
|
||||
|
||||
// to restore original: Console.SetOut(origOut);
|
||||
private static TextWriter origOut { get; } = Console.Out;
|
||||
|
||||
private static void configureLogging(Configuration config)
|
||||
{
|
||||
config.ConfigureLogging();
|
||||
replayStartupLog();
|
||||
Log.Information(
|
||||
"Paths: LibationFiles={LibationFiles} AppsettingsJson={AppsettingsJson} SQLiteDb={SqliteDb}",
|
||||
config.LibationFiles.Location,
|
||||
|
||||
@@ -70,7 +70,9 @@ public static class FormSaveExtension
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Error(ex, "Failed to save {form} size and location", form.GetType().Name);
|
||||
// The crash dialog restores its own position, so this runs while the install may be broken.
|
||||
// Logging through Serilog here took the dialog down with it. See issue #2001.
|
||||
StartupLog.Error(ex, $"Failed to restore {form.GetType().Name} size and location");
|
||||
}
|
||||
}
|
||||
public static void SaveSizeAndLocation(this Window form, Configuration config)
|
||||
@@ -99,7 +101,7 @@ public static class FormSaveExtension
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Error(ex, "Failed to save {form} size and location", form.GetType().Name);
|
||||
StartupLog.Error(ex, $"Failed to save {form.GetType().Name} size and location");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -52,7 +52,8 @@ public static class CloudSyncedFolders
|
||||
catch (Exception ex)
|
||||
{
|
||||
// cldapi.dll is absent before Windows 10 1709, where there are no sync roots to find.
|
||||
Serilog.Log.Logger.Debug(ex, "Could not read cloud sync root information for {Path}", path);
|
||||
// Reached while building a crash message, so it must not need Serilog. See issue #2001.
|
||||
StartupLog.Debug(ex, $"Could not read cloud sync root information for {path}");
|
||||
return CloudSyncStatus.NotSynced;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -67,7 +67,8 @@ public static class EssentialFileValidator
|
||||
// ensure we can open for read and write
|
||||
}
|
||||
|
||||
Log.Logger.Debug("Essential file validated: {DisplayName} at \"{Path}\"", displayName, path);
|
||||
// A Serilog failure here would be caught below and retried as if the file itself were bad.
|
||||
StartupLog.Debug($"Essential file validated: {displayName} at \"{path}\"");
|
||||
return (true, null);
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
@@ -117,12 +117,8 @@ public static class InstallUpgradeManager
|
||||
var pendingPath = GetPendingStatePath(installDirectory);
|
||||
File.WriteAllText(pendingPath, JsonSerializer.Serialize(pending, JsonOptions));
|
||||
|
||||
Serilog.Log.Logger.Information(
|
||||
"Prepared in-app upgrade to {TargetVersion}. Backed up {BackedUpCount} files to {BackupDirectory}. Expecting {ExpectedCount} install files to match the upgrade package.",
|
||||
targetVersion,
|
||||
backedUpFiles.Count,
|
||||
backupDirectory,
|
||||
expectedHashes.Count);
|
||||
StartupLog.Information(
|
||||
$"Prepared in-app upgrade to {targetVersion}. Backed up {backedUpFiles.Count} files to {backupDirectory}. Expecting {expectedHashes.Count} install files to match the upgrade package.");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -145,7 +141,7 @@ public static class InstallUpgradeManager
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Error(ex, "Could not read pending upgrade state at {PendingPath}. Attempting emergency rollback.", pendingPath);
|
||||
StartupLog.Error(ex, $"Could not read pending upgrade state at {pendingPath}. Attempting emergency rollback.");
|
||||
return RollbackAndReport(installDirectory, pendingPath, null, ["Could not read pending upgrade state."], ex.Message);
|
||||
}
|
||||
|
||||
@@ -153,16 +149,12 @@ public static class InstallUpgradeManager
|
||||
if (verification.Success)
|
||||
{
|
||||
CompleteUpgrade(installDirectory);
|
||||
Serilog.Log.Logger.Information(
|
||||
"In-app upgrade to {TargetVersion} verified successfully at startup.",
|
||||
pending.TargetVersion);
|
||||
StartupLog.Information($"In-app upgrade to {pending.TargetVersion} verified successfully at startup.");
|
||||
return null;
|
||||
}
|
||||
|
||||
Serilog.Log.Logger.Error(
|
||||
"Incomplete in-app upgrade detected at startup. Target version {TargetVersion}. {Summary}",
|
||||
pending.TargetVersion,
|
||||
verification.Summary);
|
||||
StartupLog.Error(
|
||||
$"Incomplete in-app upgrade detected at startup. Target version {pending.TargetVersion}. {verification.Summary}");
|
||||
|
||||
return RollbackAndReport(installDirectory, pendingPath, pending, verification.FailedFiles, verification.Summary);
|
||||
}
|
||||
@@ -245,7 +237,7 @@ public static class InstallUpgradeManager
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Warning(ex, "Could not delete upgrade state directory {StateDirectory}", stateDirectory);
|
||||
StartupLog.Warning(ex, $"Could not delete upgrade state directory {stateDirectory}");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -278,11 +270,8 @@ public static class InstallUpgradeManager
|
||||
{
|
||||
var restoredFiles = RestoreFromBackup(installDirectory);
|
||||
|
||||
Serilog.Log.Logger.Error(
|
||||
"In-app upgrade failed. Rolled back {RestoredCount} file(s) in {InstallDirectory}. {Summary}",
|
||||
restoredFiles.Count,
|
||||
installDirectory,
|
||||
summary);
|
||||
StartupLog.Error(
|
||||
$"In-app upgrade failed. Rolled back {restoredFiles.Count} file(s) in {installDirectory}. {summary}");
|
||||
|
||||
try
|
||||
{
|
||||
@@ -291,7 +280,7 @@ public static class InstallUpgradeManager
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Warning(ex, "Could not delete pending upgrade state at {PendingPath}", pendingPath);
|
||||
StartupLog.Warning(ex, $"Could not delete pending upgrade state at {pendingPath}");
|
||||
}
|
||||
|
||||
var targetVersion = pending?.TargetVersion ?? "unknown";
|
||||
@@ -339,7 +328,7 @@ public static class InstallUpgradeManager
|
||||
File.Copy(backupFile, targetPath, overwrite: true);
|
||||
restoredFiles.Add(relativePath);
|
||||
|
||||
Serilog.Log.Logger.Information("Upgrade rollback restored {FileName}", relativePath);
|
||||
StartupLog.Information($"Upgrade rollback restored {relativePath}");
|
||||
}
|
||||
|
||||
return restoredFiles;
|
||||
@@ -357,7 +346,7 @@ public static class InstallUpgradeManager
|
||||
|
||||
if (entry is null)
|
||||
{
|
||||
Serilog.Log.Logger.Warning("Upgrade package does not contain expected file {FileName}", fileName);
|
||||
StartupLog.Warning($"Upgrade package does not contain expected file {fileName}");
|
||||
continue;
|
||||
}
|
||||
|
||||
|
||||
@@ -58,7 +58,7 @@ public static class InteropFactory
|
||||
// nothing to load (normal for LibationCli / Docker: OS interop is optional)
|
||||
if (configApp is null)
|
||||
{
|
||||
Serilog.Log.Logger.Warning($"Unable to locate *{CONFIG_APP_ENDING}; continuing without OS interop helpers");
|
||||
StartupLog.Warning($"Unable to locate *{CONFIG_APP_ENDING}; continuing without OS interop helpers");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -75,7 +75,7 @@ public static class InteropFactory
|
||||
catch (Exception e)
|
||||
{
|
||||
//None of the interop functions are strictly necessary for Libation to run.
|
||||
Serilog.Log.Logger.Warning(e, "Unable to load types from assembly {configApp}; continuing without OS interop helpers", configApp);
|
||||
StartupLog.Warning(e, $"Unable to load types from assembly {configApp}; continuing without OS interop helpers");
|
||||
}
|
||||
}
|
||||
private static string? getOSConfigApp()
|
||||
@@ -104,7 +104,7 @@ public static class InteropFactory
|
||||
|
||||
// Let the runtime handle any dll not found exceptions
|
||||
if (assembly is null)
|
||||
Serilog.Log.Logger.Warning($"Unable to load module {args.Name}");
|
||||
StartupLog.Warning($"Unable to load module {args.Name}");
|
||||
|
||||
return assembly;
|
||||
}
|
||||
|
||||
@@ -1,8 +1,6 @@
|
||||
using Dinah.Core.Logging;
|
||||
using FileManager;
|
||||
using FileManager;
|
||||
using Newtonsoft.Json;
|
||||
using Newtonsoft.Json.Linq;
|
||||
using Serilog;
|
||||
using System;
|
||||
using System.Diagnostics;
|
||||
using System.IO;
|
||||
@@ -100,11 +98,11 @@ public class LibationFiles
|
||||
{
|
||||
// now it's set in the file again but no settings have moved yet
|
||||
File.WriteAllText(AppsettingsJsonFile, endingContents);
|
||||
Log.Logger.TryLogInformation("Libation files changed {@DebugInfo}", new { AppsettingsJsonFile, LIBATION_FILES_KEY, pathToPersist });
|
||||
StartupLog.Information($"Libation files changed. {AppsettingsJsonFile} {LIBATION_FILES_KEY}={pathToPersist}");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Log.Logger.TryLogError(ex, "Failed to change Libation files location {@DebugInfo}", new { AppsettingsJsonFile, LIBATION_FILES_KEY, pathToPersist });
|
||||
StartupLog.Error(ex, $"Failed to change Libation files location. {AppsettingsJsonFile} {LIBATION_FILES_KEY}={pathToPersist}");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -125,12 +123,12 @@ public class LibationFiles
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Log.Logger.Error(ex, "Failed to load settings file: {SettingsFile}", settingsFile);
|
||||
StartupLog.Error(ex, $"Failed to load settings file: {settingsFile}");
|
||||
try
|
||||
{
|
||||
Log.Logger.Information("Deleting invalid settings file: {SettingsFile}", settingsFile);
|
||||
StartupLog.Information($"Deleting invalid settings file: {settingsFile}");
|
||||
FileUtility.SaferDelete(settingsFile);
|
||||
Log.Logger.Information("Creating a new, empty setting file: {SettingsFile}", settingsFile);
|
||||
StartupLog.Information($"Creating a new, empty setting file: {settingsFile}");
|
||||
try
|
||||
{
|
||||
File.WriteAllText(settingsFile, "{}");
|
||||
@@ -138,12 +136,12 @@ public class LibationFiles
|
||||
}
|
||||
catch (Exception createEx)
|
||||
{
|
||||
Log.Logger.Error(createEx, "Failed to create new settings file: {SettingsFile}", settingsFile);
|
||||
StartupLog.Error(createEx, $"Failed to create new settings file: {settingsFile}");
|
||||
}
|
||||
}
|
||||
catch (Exception deleteEx)
|
||||
{
|
||||
Log.Logger.Error(deleteEx, "Failed to delete the invalid settings file: {SettingsFile}", settingsFile);
|
||||
StartupLog.Error(deleteEx, $"Failed to delete the invalid settings file: {settingsFile}");
|
||||
}
|
||||
|
||||
return false;
|
||||
@@ -228,7 +226,7 @@ public class LibationFiles
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Log.Logger.TryLogError(ex, $"Failed to create {appsettingsFile}");
|
||||
StartupLog.Error(ex, $"Failed to create {appsettingsFile}");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -298,7 +296,7 @@ public class LibationFiles
|
||||
}
|
||||
catch (Exception e)
|
||||
{
|
||||
Log.Error(e, "Failed to run shell command. {@Arguments}", psi.ArgumentList);
|
||||
StartupLog.Error(e, $"Failed to run shell command: {string.Join(' ', psi.ArgumentList)}");
|
||||
return null;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -55,7 +55,7 @@ public sealed class SingleInstance : IDisposable
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Never let the guard itself prevent startup. Fail open by treating this as the first instance.
|
||||
Serilog.Log.Logger.Warning(ex, "Could not evaluate the single-instance lock; continuing without it.");
|
||||
StartupLog.Warning(ex, "Could not evaluate the single-instance lock; continuing without it.");
|
||||
mutex?.Dispose();
|
||||
return new SingleInstance(null, true);
|
||||
}
|
||||
|
||||
@@ -40,7 +40,7 @@ public static class StartupAssemblyBootstrap
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Error(ex, "Failed while recovering from a pending in-app upgrade");
|
||||
StartupLog.Error(ex, "Failed while recovering from a pending in-app upgrade");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -55,7 +55,7 @@ public static class StartupAssemblyBootstrap
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Serilog.Log.Logger.Warning(ex, "Could not run install metadata sync at startup");
|
||||
StartupLog.Warning(ex, "Could not run install metadata sync at startup");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -0,0 +1,135 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Runtime.CompilerServices;
|
||||
|
||||
namespace LibationFileManager;
|
||||
|
||||
public enum StartupLogLevel
|
||||
{
|
||||
Debug,
|
||||
Information,
|
||||
Warning,
|
||||
Error,
|
||||
}
|
||||
|
||||
public sealed record StartupLogEntry(DateTimeOffset Timestamp, StartupLogLevel Level, string Message, Exception? Exception);
|
||||
|
||||
/// <summary>
|
||||
/// Logging for the startup window that runs before <see cref="Configuration.ConfigureLogging"/>, where
|
||||
/// <c>Serilog.Log.Logger</c> is still Serilog's silent logger and writes nowhere.
|
||||
/// <para/>
|
||||
/// Nothing here names a Serilog type, which is the point. Libation's releases are ReadyToRun, so a
|
||||
/// Serilog reference resolves lazily when the line holding it runs; if the install folder's
|
||||
/// <c>Serilog.dll</c> is missing or older than the one this build was compiled against, that line throws.
|
||||
/// A <c>catch</c> block cannot protect its own logging call, so an install broken badly enough to need
|
||||
/// the upgrade recovery in <see cref="InstallUpgradeManager"/> was the exact case in which that recovery
|
||||
/// destroyed the real exception and aborted. See issue #2001.
|
||||
/// <para/>
|
||||
/// Entries recorded before <see cref="ReplayTo"/> are buffered and handed over in order once real logging
|
||||
/// exists, so startup diagnostics reach the log file instead of vanishing. Every method here swallows its
|
||||
/// own failures: this must never be the reason startup ends.
|
||||
/// </summary>
|
||||
public static class StartupLog
|
||||
{
|
||||
/// <summary>
|
||||
/// Room for a whole startup and then some. Bounded so a caller in a retry loop cannot grow this
|
||||
/// without limit while there is still no sink to drain it.
|
||||
/// </summary>
|
||||
private const int MaxBufferedEntries = 500;
|
||||
|
||||
private static readonly object Gate = new();
|
||||
private static readonly List<StartupLogEntry> Buffered = [];
|
||||
private static Action<StartupLogEntry>? Sink;
|
||||
|
||||
public static void Debug(string message) => Record(StartupLogLevel.Debug, message, null);
|
||||
public static void Debug(Exception? exception, string message) => Record(StartupLogLevel.Debug, message, exception);
|
||||
public static void Information(string message) => Record(StartupLogLevel.Information, message, null);
|
||||
public static void Warning(string message) => Record(StartupLogLevel.Warning, message, null);
|
||||
public static void Warning(Exception? exception, string message) => Record(StartupLogLevel.Warning, message, exception);
|
||||
public static void Error(string message) => Record(StartupLogLevel.Error, message, null);
|
||||
public static void Error(Exception? exception, string message) => Record(StartupLogLevel.Error, message, exception);
|
||||
|
||||
/// <summary>
|
||||
/// Hands every buffered entry to <paramref name="sink"/> in the order it was recorded, then sends
|
||||
/// later entries straight through. Call once, immediately after logging is configured.
|
||||
/// </summary>
|
||||
public static void ReplayTo(Action<StartupLogEntry> sink)
|
||||
{
|
||||
ArgumentNullException.ThrowIfNull(sink);
|
||||
|
||||
StartupLogEntry[] pending;
|
||||
lock (Gate)
|
||||
{
|
||||
Sink = sink;
|
||||
pending = [.. Buffered];
|
||||
Buffered.Clear();
|
||||
}
|
||||
|
||||
foreach (var entry in pending)
|
||||
Deliver(sink, entry);
|
||||
}
|
||||
|
||||
/// <summary>Entries recorded but not yet handed to a sink.</summary>
|
||||
public static IReadOnlyList<StartupLogEntry> BufferedEntries
|
||||
{
|
||||
get
|
||||
{
|
||||
lock (Gate)
|
||||
return [.. Buffered];
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>Drops the sink and anything buffered. Test support: this is process-wide state.</summary>
|
||||
public static void ResetForTests()
|
||||
{
|
||||
lock (Gate)
|
||||
{
|
||||
Sink = null;
|
||||
Buffered.Clear();
|
||||
}
|
||||
}
|
||||
|
||||
private static void Record(StartupLogLevel level, string message, Exception? exception)
|
||||
{
|
||||
try
|
||||
{
|
||||
var entry = new StartupLogEntry(DateTimeOffset.Now, level, message, exception);
|
||||
|
||||
Action<StartupLogEntry>? sink;
|
||||
lock (Gate)
|
||||
{
|
||||
sink = Sink;
|
||||
if (sink is null)
|
||||
{
|
||||
if (Buffered.Count < MaxBufferedEntries)
|
||||
Buffered.Add(entry);
|
||||
return;
|
||||
}
|
||||
}
|
||||
|
||||
Deliver(sink, entry);
|
||||
}
|
||||
catch
|
||||
{
|
||||
// A logger that can end startup is worse than no logger at all.
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The sink is where Serilog lives, so it gets its own frame that is never inlined into a caller.
|
||||
/// A load failure raised inside it is then contained here rather than surfacing in the middle of
|
||||
/// whatever startup step asked for the log line.
|
||||
/// </summary>
|
||||
[MethodImpl(MethodImplOptions.NoInlining)]
|
||||
private static void Deliver(Action<StartupLogEntry> sink, StartupLogEntry entry)
|
||||
{
|
||||
try
|
||||
{
|
||||
sink(entry);
|
||||
}
|
||||
catch
|
||||
{
|
||||
// see Record
|
||||
}
|
||||
}
|
||||
}
|
||||
Reference in new issue
Block a user