Adapt async log queue from cinderbox for SMAPI

src/SMAPI/Framework/Logging/AsyncLogQueue.cs

@@ -0,0 +1,195 @@
+// Originally implemented by Ekyso in SMAPI-For-Cinderbox
+// https://github.com/Ekyso/SMAPI-For-Cinderbox/blob/2d499a9cf2521d2b97552988f30f7989e7bb4247/src/SMAPI/Framework/Logging/AsyncLogQueue.cs
+using System;
+using System.Collections.Concurrent;
+using System.Threading;
+using StardewModdingAPI.Internal.ConsoleWriting;
+
+namespace StardewModdingAPI.Framework.Logging;
+
+/// <summary>Provides asynchronous logging by queuing messages and processing them on a background thread.</summary>
+internal sealed class AsyncLogQueue : IDisposable
+{
+    /*********
+    ** Fields
+    *********/
+    /// <summary>The queue of pending log messages.</summary>
+    private readonly BlockingCollection<LogEntry> Queue = new(new ConcurrentQueue<LogEntry>());
+
+    /// <summary>The background thread that processes log messages.</summary>
+    private readonly Thread WorkerThread;
+
+    /// <summary>Whether the queue has been disposed.</summary>
+    private bool IsDisposed;
+
+    /// <summary>The log file manager for file output.</summary>
+    private readonly LogFileManager LogFile;
+
+    /// <summary>The console writer for logcat output.</summary>
+    private readonly IConsoleWriter ConsoleWriter;
+
+    /*********
+    ** Public methods
+    *********/
+    /// <summary>Construct an instance.</summary>
+    public AsyncLogQueue(LogFileManager logFile, IConsoleWriter consoleWriter)
+    {
+        this.LogFile = logFile;
+        this.ConsoleWriter = consoleWriter;
+        this.WorkerThread = new Thread(this.ProcessQueue)
+        {
+            Name = "SMAPI.AsyncLogger",
+            IsBackground = true,
+            Priority = ThreadPriority.BelowNormal
+        };
+        this.WorkerThread.Start();
+    }
+
+    /// <summary>Queue a message for logging.</summary>
+    /// <param name="consoleMessage">The message to write to console/logcat.</param>
+    /// <param name="fileMessage">The message to write to the log file.</param>
+    /// <param name="level">The log level.</param>
+    /// <param name="writeToConsole">Whether to write to console/logcat.</param>
+    public void Enqueue(string consoleMessage, string fileMessage, ConsoleLogLevel level, bool writeToConsole)
+    {
+        if (this.IsDisposed)
+            return;
+
+        try
+        {
+            this.Queue.Add(new LogEntry(consoleMessage, fileMessage, level, writeToConsole));
+        }
+        catch (InvalidOperationException)
+        {
+            // queue was marked as complete
+        }
+    }
+
+    /// <summary>Queue a newline for logging.</summary>
+    /// <param name="writeToConsole">Whether to write to console.</param>
+    public void EnqueueNewline(bool writeToConsole)
+    {
+        if (this.IsDisposed)
+            return;
+
+        try
+        {
+            this.Queue.Add(new LogEntry(null, "", ConsoleLogLevel.Info, writeToConsole, isNewline: true));
+        }
+        catch (InvalidOperationException)
+        {
+            // queue was marked as complete
+        }
+    }
+
+    /// <summary>Flush all pending messages synchronously.</summary>
+    public void Flush()
+    {
+        // wait for queue to drain
+        var timeout = DateTime.UtcNow.AddSeconds(5);
+        while (this.Queue.Count > 0 && DateTime.UtcNow < timeout)
+        {
+            Thread.Sleep(10);
+        }
+    }
+
+    /// <inheritdoc />
+    public void Dispose()
+    {
+        if (this.IsDisposed)
+            return;
+
+        this.IsDisposed = true;
+        this.Queue.CompleteAdding();
+
+        // wait for worker thread to finish
+        this.WorkerThread.Join(TimeSpan.FromSeconds(5));
+
+        this.Queue.Dispose();
+    }
+
+
+    /*********
+    ** Private methods
+    *********/
+    /// <summary>Process log messages from the queue.</summary>
+    private void ProcessQueue()
+    {
+        try
+        {
+            foreach (var entry in this.Queue.GetConsumingEnumerable())
+            {
+                try
+                {
+                    this.WriteEntry(entry);
+                }
+                catch (Exception ex)
+                {
+                    System.Diagnostics.Debug.WriteLine($"[AsyncLogQueue] Error writing log entry: {ex.Message}");
+                }
+            }
+        }
+        catch (OperationCanceledException)
+        {
+            // expected when disposing
+        }
+    }
+
+    /// <summary>Write a log entry to the configured outputs.</summary>
+    /// <param name="entry">The entry to write.</param>
+    private void WriteEntry(LogEntry entry)
+    {
+        if (entry.IsNewline)
+        {
+            if (entry.WriteToConsole)
+                Console.WriteLine();
+            this.LogFile?.WriteLine("");
+            return;
+        }
+
+        // write to console/logcat
+        if (entry.WriteToConsole && entry.ConsoleMessage != null)
+        {
+            this.ConsoleWriter?.WriteLine(entry.ConsoleMessage, entry.Level);
+        }
+
+        // write to log file
+        if (entry.FileMessage != null)
+        {
+            this.LogFile?.WriteLine(entry.FileMessage);
+        }
+    }
+
+
+    /*********
+    ** Private types
+    *********/
+    /// <summary>A log entry waiting to be written.</summary>
+    private readonly struct LogEntry
+    {
+        /// <summary>The message to write to console/logcat.</summary>
+        public readonly string? ConsoleMessage;
+
+        /// <summary>The message to write to the log file.</summary>
+        public readonly string? FileMessage;
+
+        /// <summary>The log level.</summary>
+        public readonly ConsoleLogLevel Level;
+
+        /// <summary>Whether to write to console/logcat.</summary>
+        public readonly bool WriteToConsole;
+
+        /// <summary>Whether this is a newline entry.</summary>
+        public readonly bool IsNewline;
+
+        /// <summary>Construct an instance.</summary>
+        public LogEntry(string? consoleMessage, string? fileMessage, ConsoleLogLevel level, bool writeToConsole, bool isNewline = false)
+        {
+            this.ConsoleMessage = consoleMessage;
+            this.FileMessage = fileMessage;
+            this.Level = level;
+            this.WriteToConsole = writeToConsole;
+            this.IsNewline = isNewline;
+        }
+    }
+}

src/SMAPI/Framework/Logging/LogManager.cs

@@ -3,7 +3,6 @@
 using System.Diagnostics.CodeAnalysis;
 using System.IO;
 using System.Linq;
-using System.Text;
 using System.Threading;
 using StardewModdingAPI.Framework.Commands;
 using StardewModdingAPI.Framework.Models;
@@ -38,6 +37,10 @@ internal class LogManager : IDisposable
     /*********
     ** Accessors
     *********/
+
+    /// <summary>The async log queue and worker thread for writing logs.</summary>
+    public AsyncLogQueue LogQueue { get; }
+
     /// <summary>The core logger and monitor for SMAPI.</summary>
     public Monitor Monitor { get; }
 
@@ -68,6 +71,8 @@ public LogManager(string logPath, MonitorColorScheme colorSchemeId, Dictionary<M
         this.ConsoleWriter = new ColorfulConsoleWriter(Constants.Platform, colorSchemeId, colorConfig);
         this.GetMonitorImpl = (id, name) => this.CreateAndRegisterMonitor(id, name, verboseLogging, getScreenIdForLog, writeToConsole, isDeveloperMode);
 
+        this.LogQueue = new AsyncLogQueue(this.LogFile, this.ConsoleWriter);
+
         this.Monitor = this.GetMonitor("SMAPI", "SMAPI");
         this.MonitorForGame = this.GetMonitor("game", "game");
 
@@ -342,6 +347,8 @@ public void LogModInfo(IReadOnlyList<IModMetadata> loaded, IReadOnlyList<IModMet
     /// <inheritdoc />
     public void Dispose()
     {
+        this.LogQueue.Flush();
+        this.LogQueue.Dispose();
         this.LogFile.Dispose();
     }
 
@@ -358,7 +365,7 @@ public void Dispose()
     /// <param name="isDeveloperMode">Whether to enable full console output for developers.</param>
     private Monitor CreateAndRegisterMonitor(string modId, string source, HashSet<string> verboseLogging, Func<int?> getScreenIdForLog, bool writeToConsole, bool isDeveloperMode)
     {
-        Monitor monitor = new(modId, source, this.LogFile, this.ConsoleWriter, getScreenIdForLog)
+        Monitor monitor = new(modId, source, this.LogQueue, getScreenIdForLog)
         {
             WriteToConsole = writeToConsole
         };

src/SMAPI/Framework/Monitor.cs

@@ -16,18 +16,15 @@ internal class Monitor : IMonitor
     /// <summary>The name of the module which logs messages using this instance.</summary>
     private readonly string Source;
 
-    /// <summary>Handles writing text to the console.</summary>
-    private readonly IConsoleWriter ConsoleWriter;
-
-    /// <summary>The log file to which to write messages.</summary>
-    private readonly LogFileManager LogFile;
-
     /// <summary>The maximum length of the <see cref="LogLevel"/> values.</summary>
     private static readonly int MaxLevelLength = Enum.GetValues<LogLevel>().Max(level => level.ToString().Length);
 
     /// <summary>The cached representation for each level when added to a log header.</summary>
     private static readonly Dictionary<ConsoleLogLevel, string> LogStrings = Enum.GetValues<ConsoleLogLevel>().ToDictionary(level => level, level => level.ToString().ToUpperInvariant().PadRight(Monitor.MaxLevelLength));
 
+    /// <summary>The async log queue and worker thread for writing logs.</summary>
+    private readonly AsyncLogQueue LogQueue;
+
     /// <summary>A cache of messages that should only be logged once.</summary>
     private readonly HashSet<LogOnceCacheKey> LogOnceCache = [];
 
@@ -76,10 +73,9 @@ public bool IsVerbose
     /// <summary>Construct an instance.</summary>
     /// <param name="modId">The mod ID, if applicable.</param>
     /// <param name="source">The name of the module which logs messages using this instance.</param>
-    /// <param name="logFile">The log file to which to write messages.</param>
-    /// <param name="consoleWriter">Handles writing text to the console.</param>
+    /// <param name="logQueue">The async log queue responsible for writing messages.</param>
     /// <param name="getScreenIdForLog">Get the screen ID that should be logged to distinguish between players in split-screen mode, if any.</param>
-    public Monitor(string modId, string source, LogFileManager logFile, IConsoleWriter consoleWriter, Func<int?> getScreenIdForLog)
+    public Monitor(string modId, string source, AsyncLogQueue logQueue, Func<int?> getScreenIdForLog)
     {
         // validate
         if (string.IsNullOrWhiteSpace(source))
@@ -88,8 +84,7 @@ public Monitor(string modId, string source, LogFileManager logFile, IConsoleWrit
         // initialize
         this.ModId = modId;
         this.Source = source;
-        this.LogFile = logFile ?? throw new ArgumentNullException(nameof(logFile), "The log file manager cannot be null.");
-        this.ConsoleWriter = consoleWriter ?? throw new ArgumentNullException(nameof(consoleWriter), "The console writer cannot be null.");
+        this.LogQueue = logQueue ?? throw new ArgumentNullException(nameof(logQueue), "The log queue cannot be null.");
         this.GetScreenIdForLog = getScreenIdForLog;
     }
 
@@ -123,9 +118,7 @@ public void VerboseLog([InterpolatedStringHandlerArgument("")] ref VerboseLogStr
     /// <summary>Write a newline to the console and log file.</summary>
     internal void Newline()
     {
-        if (this.WriteToConsole)
-            Console.WriteLine();
-        this.LogFile.WriteLine("");
+        this.LogQueue.EnqueueNewline(this.WriteToConsole);
     }
 
     /// <summary>Log a fatal error message.</summary>
@@ -141,7 +134,7 @@ internal void LogUserInput(string input)
     {
         // user input already appears in the console, so just need to write to file
         string prefix = this.GenerateMessagePrefix(this.Source, (ConsoleLogLevel)LogLevel.Info);
-        this.LogFile.WriteLine($"{prefix} $>{input}");
+        this.LogQueue.Enqueue(string.Empty, $"{prefix} $>{input}", (ConsoleLogLevel)LogLevel.Info, false);
     }
 
 
@@ -160,11 +153,9 @@ private void LogImpl(string source, string message, ConsoleLogLevel level)
         string consoleMessage = this.ShowFullStampInConsole ? fullMessage : $"[{source}] {message}";
 
         // write to console
-        if (this.WriteToConsole && (this.ShowTraceInConsole || level != ConsoleLogLevel.Trace || Monitor.ForceVerboseLoggingForAll || Monitor.ForceVerboseLogging.Contains(this.ModId)))
-            this.ConsoleWriter.WriteLine(consoleMessage, level);
+        bool writeToConsole = this.WriteToConsole && (this.ShowTraceInConsole || level != ConsoleLogLevel.Trace || Monitor.ForceVerboseLoggingForAll || Monitor.ForceVerboseLogging.Contains(this.ModId));
 
-        // write to log file
-        this.LogFile.WriteLine(fullMessage);
+        this.LogQueue.Enqueue(consoleMessage, fullMessage, level, writeToConsole);
     }
 
     /// <summary>Generate a message prefix for the current time.</summary>