redirect the game's debug messages into trace logs (#233)

The game writes debug messages directly to the console, which shows up for SMAPI users. This commit redirects direct console messages to a monitor.

8 files changed, 211 insertions, 45 deletions

diff --git a/release-notes.md b/release-notes.md
index e6becdbd..e3e8752b 100644
--- a/release-notes.md
+++ b/release-notes.md
@@ -4,13 +4,13 @@
 See [log](https://github.com/Pathoschild/SMAPI/compare/1.8...1.9).
 
 For players:
-* Updated for Stardew Valley 1.2.
+* Updated for Stardew Valley 1.2. Most mods are now rewritten for compatibility; some mods require an update from their authors.
 * Simplified log filename.
-* SMAPI now rewrites most mods for Stardew Valley 1.2 compatibility.
+* Fixed game's debug output being shown in the console for all users.
 
 For mod developers:
 * Added `SaveEvents.AfterReturnToTitle` event.
-* Added `GetPrivateProperty` to reflection helper.
+* Added `GetPrivateProperty` reflection helper.
 * Many deprecated APIs have been removed; see the
   [deprecation guide](http://canimod.com/guides/updating-a-smapi-mod) for more information.
 * Log files now always use `\r\n` to simplify crossplatform viewing.
diff --git a/src/StardewModdingAPI/Framework/Logging/ConsoleInterceptionManager.cs b/src/StardewModdingAPI/Framework/Logging/ConsoleInterceptionManager.cs
new file mode 100644
index 00000000..d84671ee
--- /dev/null
+++ b/src/StardewModdingAPI/Framework/Logging/ConsoleInterceptionManager.cs
@@ -0,0 +1,86 @@
+using System;
+
+namespace StardewModdingAPI.Framework.Logging
+{
+    /// <summary>Manages console output interception.</summary>
+    internal class ConsoleInterceptionManager : IDisposable
+    {
+        /*********
+        ** Properties
+        *********/
+        /// <summary>The intercepting console writer.</summary>
+        private readonly InterceptingTextWriter Output;
+
+
+        /*********
+        ** Accessors
+        *********/
+        /// <summary>Whether the current console supports color formatting.</summary>
+        public bool SupportsColor { get; }
+
+        /// <summary>The event raised when something writes a line to the console directly.</summary>
+        public event Action<string> OnLineIntercepted;
+
+
+        /*********
+        ** Public methods
+        *********/
+        /// <summary>Construct an instance.</summary>
+        public ConsoleInterceptionManager()
+        {
+            // redirect output through interceptor
+            this.Output = new InterceptingTextWriter(Console.Out);
+            this.Output.OnLineIntercepted += line => this.OnLineIntercepted?.Invoke(line);
+            Console.SetOut(this.Output);
+
+            // test color support
+            this.SupportsColor = this.TestColorSupport();
+        }
+
+        /// <summary>Get an exclusive lock and write to the console output without interception.</summary>
+        /// <param name="action">The action to perform within the exclusive write block.</param>
+        public void ExclusiveWriteWithoutInterception(Action action)
+        {
+            lock (Console.Out)
+            {
+                try
+                {
+                    this.Output.ShouldIntercept = false;
+                    action();
+                }
+                finally
+                {
+                    this.Output.ShouldIntercept = true;
+                }
+            }
+        }
+
+        /// <summary>Release all resources.</summary>
+        public void Dispose()
+        {
+            Console.SetOut(this.Output.Out);
+            this.Output.Dispose();
+        }
+
+
+        /*********
+        ** private methods
+        *********/
+        /// <summary>Test whether the current console supports color formatting.</summary>
+        private bool TestColorSupport()
+        {
+            try
+            {
+                this.ExclusiveWriteWithoutInterception(() =>
+                {
+                    Console.ForegroundColor = Console.ForegroundColor;
+                });
+                return true;
+            }
+            catch (Exception)
+            {
+                return false; // Mono bug
+            }
+        }
+    }
+}
diff --git a/src/StardewModdingAPI/Framework/Logging/InterceptingTextWriter.cs b/src/StardewModdingAPI/Framework/Logging/InterceptingTextWriter.cs
new file mode 100644
index 00000000..14789109
--- /dev/null
+++ b/src/StardewModdingAPI/Framework/Logging/InterceptingTextWriter.cs
@@ -0,0 +1,79 @@
+using System;
+using System.Collections.Generic;
+using System.IO;
+using System.Text;
+
+namespace StardewModdingAPI.Framework.Logging
+{
+    /// <summary>A text writer which allows intercepting output.</summary>
+    internal class InterceptingTextWriter : TextWriter
+    {
+        /*********
+        ** Properties
+        *********/
+        /// <summary>The current line being intercepted.</summary>
+        private readonly List<char> Line = new List<char>();
+
+
+        /*********
+        ** Accessors
+        *********/
+        /// <summary>The underlying console output.</summary>
+        public TextWriter Out { get; }
+
+        /// <summary>The character encoding in which the output is written.</summary>
+        public override Encoding Encoding => this.Out.Encoding;
+
+        /// <summary>Whether to intercept console output.</summary>
+        public bool ShouldIntercept { get; set; }
+
+        /// <summary>The event raised when a line of text is intercepted.</summary>
+        public event Action<string> OnLineIntercepted;
+
+
+        /*********
+        ** Public methods
+        *********/
+        /// <summary>Construct an instance.</summary>
+        /// <param name="output">The underlying output writer.</param>
+        public InterceptingTextWriter(TextWriter output)
+        {
+            this.Out = output;
+        }
+
+        /// <summary>Writes a character to the text string or stream.</summary>
+        /// <param name="ch">The character to write to the text stream.</param>
+        public override void Write(char ch)
+        {
+            // intercept
+            if (this.ShouldIntercept)
+            {
+                switch (ch)
+                {
+                    case '\r':
+                        return;
+
+                    case '\n':
+                        this.OnLineIntercepted?.Invoke(new string(this.Line.ToArray()));
+                        this.Line.Clear();
+                        break;
+
+                    default:
+                        this.Line.Add(ch);
+                        break;
+                }
+            }
+
+            // pass through
+            else
+                this.Out.Write(ch);
+        }
+
+        /// <summary>Releases the unmanaged resources used by the <see cref="T:System.IO.TextWriter" /> and optionally releases the managed resources.</summary>
+        /// <param name="disposing">true to release both managed and unmanaged resources; false to release only unmanaged resources.</param>
+        protected override void Dispose(bool disposing)
+        {
+            this.OnLineIntercepted = null;
+        }
+    }
+}
diff --git a/src/StardewModdingAPI/Framework/LogFileManager.cs b/src/StardewModdingAPI/Framework/Logging/LogFileManager.cs
index 80437e9c..1f6ade1d 100644
--- a/src/StardewModdingAPI/Framework/LogFileManager.cs
+++ b/src/StardewModdingAPI/Framework/Logging/LogFileManager.cs
@@ -1,7 +1,7 @@
 using System;
 using System.IO;
 
-namespace StardewModdingAPI.Framework
+namespace StardewModdingAPI.Framework.Logging
 {
     /// <summary>Manages reading and writing to log file.</summary>
     internal class LogFileManager : IDisposable
@@ -45,4 +45,4 @@ namespace StardewModdingAPI.Framework
             this.Stream.Dispose();
         }
     }
-}
\ No newline at end of file
+}
diff --git a/src/StardewModdingAPI/Framework/Monitor.cs b/src/StardewModdingAPI/Framework/Monitor.cs
index 39b567d8..33c1bbf4 100644
--- a/src/StardewModdingAPI/Framework/Monitor.cs
+++ b/src/StardewModdingAPI/Framework/Monitor.cs
@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using StardewModdingAPI.Framework.Logging;
 
 namespace StardewModdingAPI.Framework
 {
@@ -13,6 +14,9 @@ namespace StardewModdingAPI.Framework
         /// <summary>The name of the module which logs messages using this instance.</summary>
         private readonly string Source;
 
+        /// <summary>Manages access to the console output.</summary>
+        private readonly ConsoleInterceptionManager ConsoleManager;
+
         /// <summary>The log file to which to write messages.</summary>
         private readonly LogFileManager LogFile;
 
@@ -34,9 +38,6 @@ namespace StardewModdingAPI.Framework
         /*********
         ** Accessors
         *********/
-        /// <summary>Whether the current console supports color codes.</summary>
-        internal static readonly bool ConsoleSupportsColor = Monitor.GetConsoleSupportsColor();
-
         /// <summary>Whether to show trace messages in the console.</summary>
         internal bool ShowTraceInConsole { get; set; }
 
@@ -49,8 +50,9 @@ namespace StardewModdingAPI.Framework
         *********/
         /// <summary>Construct an instance.</summary>
         /// <param name="source">The name of the module which logs messages using this instance.</param>
+        /// <param name="consoleManager">Manages access to the console output.</param>
         /// <param name="logFile">The log file to which to write messages.</param>
-        public Monitor(string source, LogFileManager logFile)
+        public Monitor(string source, ConsoleInterceptionManager consoleManager, LogFileManager logFile)
         {
             // validate
             if (string.IsNullOrWhiteSpace(source))
@@ -61,6 +63,7 @@ namespace StardewModdingAPI.Framework
             // initialise
             this.Source = source;
             this.LogFile = logFile;
+            this.ConsoleManager = consoleManager;
         }
 
         /// <summary>Log a message for the player or developer.</summary>
@@ -68,7 +71,7 @@ namespace StardewModdingAPI.Framework
         /// <param name="level">The log severity level.</param>
         public void Log(string message, LogLevel level = LogLevel.Debug)
         {
-            this.LogImpl(this.Source, message, Monitor.Colors[level], level);
+            this.LogImpl(this.Source, message, level, Monitor.Colors[level]);
         }
 
         /// <summary>Immediately exit the game without saving. This should only be invoked when an irrecoverable fatal error happens that risks save corruption or game-breaking bugs.</summary>
@@ -83,8 +86,7 @@ namespace StardewModdingAPI.Framework
         /// <param name="message">The message to log.</param>
         internal void LogFatal(string message)
         {
-            Console.BackgroundColor = ConsoleColor.Red;
-            this.LogImpl(this.Source, message, ConsoleColor.White, LogLevel.Error);
+            this.LogImpl(this.Source, message, LogLevel.Error, ConsoleColor.White, background: ConsoleColor.Red);
         }
 
         /// <summary>Log a message for the player or developer, using the specified console color.</summary>
@@ -95,7 +97,7 @@ namespace StardewModdingAPI.Framework
         [Obsolete("This method is provided for backwards compatibility and otherwise should not be used. Use " + nameof(Monitor) + "." + nameof(Monitor.Log) + " instead.")]
         internal void LegacyLog(string source, string message, ConsoleColor color, LogLevel level = LogLevel.Debug)
         {
-            this.LogImpl(source, message, color, level);
+            this.LogImpl(source, message, level, color);
         }
 
 
@@ -105,9 +107,10 @@ namespace StardewModdingAPI.Framework
         /// <summary>Write a message line to the log.</summary>
         /// <param name="source">The name of the mod logging the message.</param>
         /// <param name="message">The message to log.</param>
-        /// <param name="color">The console color.</param>
         /// <param name="level">The log level.</param>
-        private void LogImpl(string source, string message, ConsoleColor color, LogLevel level)
+        /// <param name="color">The console foreground color.</param>
+        /// <param name="background">The console background color (or <c>null</c> to leave it as-is).</param>
+        private void LogImpl(string source, string message, LogLevel level, ConsoleColor color, ConsoleColor? background = null)
         {
             // generate message
             string levelStr = level.ToString().ToUpper().PadRight(Monitor.MaxLevelLength);
@@ -116,30 +119,19 @@ namespace StardewModdingAPI.Framework
             // log
             if (this.WriteToConsole && (this.ShowTraceInConsole || level != LogLevel.Trace))
             {
-                if (Monitor.ConsoleSupportsColor)
+                this.ConsoleManager.ExclusiveWriteWithoutInterception(() =>
                 {
-                    Console.ForegroundColor = color;
-                    Console.WriteLine(message);
-                    Console.ResetColor();
-                }
-                else
-                    Console.WriteLine(message);
+                    if (this.ConsoleManager.SupportsColor)
+                    {
+                        Console.ForegroundColor = color;
+                        Console.WriteLine(message);
+                        Console.ResetColor();
+                    }
+                    else
+                        Console.WriteLine(message);
+                });
             }
             this.LogFile.WriteLine(message);
         }
-
-        /// <summary>Test whether the current console supports color formatting.</summary>
-        private static bool GetConsoleSupportsColor()
-        {
-            try
-            {
-                Console.ForegroundColor = Console.ForegroundColor;
-                return true;
-            }
-            catch (Exception)
-            {
-                return false; // Mono bug
-            }
-        }
     }
-}
\ No newline at end of file
+}
diff --git a/src/StardewModdingAPI/Framework/SGame.cs b/src/StardewModdingAPI/Framework/SGame.cs
index 6a751b85..9e269df3 100644
--- a/src/StardewModdingAPI/Framework/SGame.cs
+++ b/src/StardewModdingAPI/Framework/SGame.cs
@@ -1170,7 +1170,6 @@ namespace StardewModdingAPI.Framework
             // after exit to title
             if (this.IsWorldReady && this.IsExiting && Game1.activeClickableMenu is TitleMenu)
             {
-                Console.WriteLine($"{Game1.currentGameTime.TotalGameTime}: after return to title");
                 SaveEvents.InvokeAfterReturnToTitle(this.Monitor);
                 this.AfterLoadTimer = 5;
                 this.IsExiting = false;
diff --git a/src/StardewModdingAPI/Program.cs b/src/StardewModdingAPI/Program.cs
index 75be23f2..a6302540 100644
--- a/src/StardewModdingAPI/Program.cs
+++ b/src/StardewModdingAPI/Program.cs
@@ -13,6 +13,7 @@ using Newtonsoft.Json;
 using StardewModdingAPI.AssemblyRewriters;
 using StardewModdingAPI.Events;
 using StardewModdingAPI.Framework;
+using StardewModdingAPI.Framework.Logging;
 using StardewModdingAPI.Framework.Models;
 using StardewValley;
 using Monitor = StardewModdingAPI.Framework.Monitor;
@@ -42,8 +43,11 @@ namespace StardewModdingAPI
         /// <summary>The log file to which to write messages.</summary>
         private static readonly LogFileManager LogFile = new LogFileManager(Constants.LogPath);
 
+        /// <summary>Manages console output interception.</summary>
+        private static readonly ConsoleInterceptionManager ConsoleManager = new ConsoleInterceptionManager();
+
         /// <summary>The core logger for SMAPI.</summary>
-        private static readonly Monitor Monitor = new Monitor("SMAPI", Program.LogFile);
+        private static readonly Monitor Monitor = new Monitor("SMAPI", Program.ConsoleManager, Program.LogFile);
 
         /// <summary>The user settings for SMAPI.</summary>
         private static UserSettings Settings;
@@ -87,14 +91,12 @@ namespace StardewModdingAPI
         /// <param name="args">The command-line arguments.</param>
         private static void Main(string[] args)
         {
-            // set log options
+            // initialise logging
             Program.Monitor.WriteToConsole = !args.Contains("--no-terminal");
             Thread.CurrentThread.CurrentCulture = CultureInfo.CreateSpecificCulture("en-GB"); // for consistent log formatting
-
-            // add info header
             Program.Monitor.Log($"SMAPI {Constants.ApiVersion} with Stardew Valley {Game1.version} on {Environment.OSVersion}", LogLevel.Info);
 
-            // initialise user settings
+            // read config
             {
                 string settingsPath = Constants.ApiConfigPath;
                 if (File.Exists(settingsPath))
@@ -108,6 +110,12 @@ namespace StardewModdingAPI
                 File.WriteAllText(settingsPath, JsonConvert.SerializeObject(Program.Settings, Formatting.Indented));
             }
 
+            // redirect direct console output
+            {
+                IMonitor monitor = Program.GetSecondaryMonitor("Console.Out");
+                Program.ConsoleManager.OnLineIntercepted += line => monitor.Log(line, LogLevel.Trace);
+            }
+
             // add warning headers
             if (Program.Settings.DeveloperMode)
             {
@@ -574,7 +582,7 @@ namespace StardewModdingAPI
         /// <param name="name">The name of the module which will log messages with this instance.</param>
         private static Monitor GetSecondaryMonitor(string name)
         {
-            return new Monitor(name, Program.LogFile) { WriteToConsole = Program.Monitor.WriteToConsole, ShowTraceInConsole = Program.Settings.DeveloperMode };
+            return new Monitor(name, Program.ConsoleManager, Program.LogFile) { WriteToConsole = Program.Monitor.WriteToConsole, ShowTraceInConsole = Program.Settings.DeveloperMode };
         }
     }
 }
diff --git a/src/StardewModdingAPI/StardewModdingAPI.csproj b/src/StardewModdingAPI/StardewModdingAPI.csproj
index 896721ea..ae08012d 100644
--- a/src/StardewModdingAPI/StardewModdingAPI.csproj
+++ b/src/StardewModdingAPI/StardewModdingAPI.csproj
@@ -145,6 +145,8 @@
     <Compile Include="Events\GraphicsEvents.cs" />
     <Compile Include="Framework\AssemblyDefinitionResolver.cs" />
     <Compile Include="Framework\AssemblyParseResult.cs" />
+    <Compile Include="Framework\Logging\ConsoleInterceptionManager.cs" />
+    <Compile Include="Framework\Logging\InterceptingTextWriter.cs" />
     <Compile Include="Framework\Reflection\PrivateProperty.cs" />
     <Compile Include="Framework\Serialisation\SemanticVersionConverter.cs" />
     <Compile Include="IModRegistry.cs" />
@@ -166,7 +168,7 @@
     <Compile Include="IManifest.cs" />
     <Compile Include="IMod.cs" />
     <Compile Include="IModHelper.cs" />
-    <Compile Include="Framework\LogFileManager.cs" />
+    <Compile Include="Framework\Logging\LogFileManager.cs" />
     <Compile Include="IPrivateProperty.cs" />
     <Compile Include="ISemanticVersion.cs" />
     <Compile Include="LogLevel.cs" />