diff --git a/Source/AppScaffolding/LibationScaffolding.cs b/Source/AppScaffolding/LibationScaffolding.cs index 9c953ca0..0912665b 100644 --- a/Source/AppScaffolding/LibationScaffolding.cs +++ b/Source/AppScaffolding/LibationScaffolding.cs @@ -208,12 +208,34 @@ public static class LibationScaffolding private static void ensureSerilogConfig(Configuration config) => config.EnsureSerilogConfig(); + /// + /// Hands everything 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. + /// + 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, diff --git a/Source/LibationAvalonia/FormSaveExtension.cs b/Source/LibationAvalonia/FormSaveExtension.cs index b9480db5..d5618e24 100644 --- a/Source/LibationAvalonia/FormSaveExtension.cs +++ b/Source/LibationAvalonia/FormSaveExtension.cs @@ -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"); } } diff --git a/Source/LibationFileManager/CloudSyncedFolders.cs b/Source/LibationFileManager/CloudSyncedFolders.cs index 790bca5b..2dccb4d6 100644 --- a/Source/LibationFileManager/CloudSyncedFolders.cs +++ b/Source/LibationFileManager/CloudSyncedFolders.cs @@ -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; } } diff --git a/Source/LibationFileManager/EssentialFileValidator.cs b/Source/LibationFileManager/EssentialFileValidator.cs index 4a8eb5ef..fc077593 100644 --- a/Source/LibationFileManager/EssentialFileValidator.cs +++ b/Source/LibationFileManager/EssentialFileValidator.cs @@ -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) diff --git a/Source/LibationFileManager/InstallUpgradeManager.cs b/Source/LibationFileManager/InstallUpgradeManager.cs index 50fb9ff4..9216d5a6 100644 --- a/Source/LibationFileManager/InstallUpgradeManager.cs +++ b/Source/LibationFileManager/InstallUpgradeManager.cs @@ -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."); } /// @@ -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; } diff --git a/Source/LibationFileManager/InteropFactory.cs b/Source/LibationFileManager/InteropFactory.cs index 62c556cd..19d70a4d 100644 --- a/Source/LibationFileManager/InteropFactory.cs +++ b/Source/LibationFileManager/InteropFactory.cs @@ -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; } diff --git a/Source/LibationFileManager/LibationFiles.cs b/Source/LibationFileManager/LibationFiles.cs index 76a38192..8d922ffc 100644 --- a/Source/LibationFileManager/LibationFiles.cs +++ b/Source/LibationFileManager/LibationFiles.cs @@ -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; } } diff --git a/Source/LibationFileManager/SingleInstance.cs b/Source/LibationFileManager/SingleInstance.cs index 55e8a353..26011019 100644 --- a/Source/LibationFileManager/SingleInstance.cs +++ b/Source/LibationFileManager/SingleInstance.cs @@ -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); } diff --git a/Source/LibationFileManager/StartupAssemblyBootstrap.cs b/Source/LibationFileManager/StartupAssemblyBootstrap.cs index b5f38c06..5b6ca5ca 100644 --- a/Source/LibationFileManager/StartupAssemblyBootstrap.cs +++ b/Source/LibationFileManager/StartupAssemblyBootstrap.cs @@ -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"); } } diff --git a/Source/LibationFileManager/StartupLog.cs b/Source/LibationFileManager/StartupLog.cs new file mode 100644 index 00000000..8ecff8a2 --- /dev/null +++ b/Source/LibationFileManager/StartupLog.cs @@ -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); + +/// +/// Logging for the startup window that runs before , where +/// Serilog.Log.Logger is still Serilog's silent logger and writes nowhere. +/// +/// 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 +/// Serilog.dll is missing or older than the one this build was compiled against, that line throws. +/// A catch block cannot protect its own logging call, so an install broken badly enough to need +/// the upgrade recovery in was the exact case in which that recovery +/// destroyed the real exception and aborted. See issue #2001. +/// +/// Entries recorded before 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. +/// +public static class StartupLog +{ + /// + /// 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. + /// + private const int MaxBufferedEntries = 500; + + private static readonly object Gate = new(); + private static readonly List Buffered = []; + private static Action? 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); + + /// + /// Hands every buffered entry to in the order it was recorded, then sends + /// later entries straight through. Call once, immediately after logging is configured. + /// + public static void ReplayTo(Action sink) + { + ArgumentNullException.ThrowIfNull(sink); + + StartupLogEntry[] pending; + lock (Gate) + { + Sink = sink; + pending = [.. Buffered]; + Buffered.Clear(); + } + + foreach (var entry in pending) + Deliver(sink, entry); + } + + /// Entries recorded but not yet handed to a sink. + public static IReadOnlyList BufferedEntries + { + get + { + lock (Gate) + return [.. Buffered]; + } + } + + /// Drops the sink and anything buffered. Test support: this is process-wide state. + 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? 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. + } + } + + /// + /// 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. + /// + [MethodImpl(MethodImplOptions.NoInlining)] + private static void Deliver(Action sink, StartupLogEntry entry) + { + try + { + sink(entry); + } + catch + { + // see Record + } + } +}