SCAN4NET-96 and SCAN4NET-97: Fix logger timestamp duplication

SonarSource · Sep 25, 2024 · a5c35f6 · a5c35f6
1 parent 054c9fa
commit a5c35f6
Show file tree

Hide file tree

Showing 4 changed files with 73 additions and 46 deletions.
diff --git a/Tests/SonarScanner.MSBuild.Common.Test/ILoggerTests.cs b/Tests/SonarScanner.MSBuild.Common.Test/ILoggerTests.cs
@@ -271,8 +271,9 @@ public void ConsoleLogger_Verbosity()
     [TestMethod]
     public void ConsoleLogger_SuspendAndResume()
     {
+        const string prefixRegex = @"\d{2}:\d{2}:\d{2}(.\d{1,3})?";
         var recorder = new OutputRecorder();
-        var logger = ConsoleLogger.CreateLoggerForTesting(false, recorder, fileWrapper);
+        var logger = ConsoleLogger.CreateLoggerForTesting(true, recorder, fileWrapper);
 
         // 1. Suspend output - should be able to call this multiple times
         logger.SuspendOutput();
@@ -301,17 +302,17 @@ public void ConsoleLogger_SuspendAndResume()
         logger.ResumeOutput();
 
         recorder.AssertExpectedOutputText(
-            "debug 1 xxx",
-            "WARNING: warning 1 xxx",
-            "error 1 xxx",
-            "info 1 xxx");
+            $"{prefixRegex}  debug 1 xxx",
+            $"{prefixRegex}  WARNING: warning 1 xxx",
+            $"{prefixRegex}  error 1 xxx",
+            $"{prefixRegex}  info 1 xxx");
 
         // 5. Log more -> output should be immediate
         logger.LogInfo("info 2");
-        recorder.AssertExpectedLastOutput("info 2", Console.ForegroundColor, false);
+        recorder.AssertExpectedLastOutput($"{prefixRegex}  info 2", Console.ForegroundColor, false);
 
         logger.LogError("error 2");
-        recorder.AssertExpectedLastOutput("error 2", ConsoleLogger.ErrorColor, true);
+        recorder.AssertExpectedLastOutput($"{prefixRegex}  error 2", ConsoleLogger.ErrorColor, true);
     }
 
     [TestMethod]
@@ -348,6 +349,23 @@ public void ConsoleLogger_WriteUIWarnings_GenerateFile()
              """);
     }
 
+    [TestMethod]
+    public void ConsoleLogger_WriteUIWarnings_ContainsTimeStampOnce()
+    {
+        const string prefixRegex = @"\d{2}:\d{2}:\d{2}(.\d{1,3})?  WARNING:";
+        using var output = new OutputCaptureScope();
+        var logger = new ConsoleLogger(includeTimestamp: true, fileWrapper);
+
+        logger.LogUIWarning("uiWarn1");
+        output.AssertExpectedLastMessageRegex($"{prefixRegex} uiWarn1");
+
+        logger.LogUIWarning("uiWarn2", null);
+        output.AssertExpectedLastMessageRegex($"{prefixRegex} uiWarn2");
+
+        logger.LogUIWarning("uiWarn3 {0}", "xxx");
+        output.AssertExpectedLastMessageRegex($"{prefixRegex} uiWarn3 xxx");
+    }
+
     [TestMethod]
     public void ILogger_Log_Debug()
     {

diff --git a/Tests/SonarScanner.MSBuild.Common.Test/Infrastructure/OutputCaptureScope.cs b/Tests/SonarScanner.MSBuild.Common.Test/Infrastructure/OutputCaptureScope.cs
@@ -64,6 +64,12 @@ public void AssertExpectedLastMessage(string expected)
         lastMessage.Should().Be(expected, "Expected message was not logged");
     }
 
+    public void AssertExpectedLastMessageRegex(string expected)
+    {
+        var lastMessage = GetLastMessage(outputWriter);
+        lastMessage.Should().MatchRegex(expected, "Expected message was not logged");
+    }
+
     public void AssertLastMessageEndsWith(string expected)
     {
         var lastMessage = GetLastMessage(outputWriter);

diff --git a/Tests/SonarScanner.MSBuild.Common.Test/Infrastructure/OutputRecorder.cs b/Tests/SonarScanner.MSBuild.Common.Test/Infrastructure/OutputRecorder.cs
@@ -30,43 +30,31 @@ namespace SonarScanner.MSBuild.Common.Test;
 /// </summary>
 internal class OutputRecorder : IOutputWriter
 {
-    private class OutputMessage
-    {
-        public OutputMessage(string message, ConsoleColor textColor, bool isError)
-        {
-            Message = message;
-            TextColor = textColor;
-            IsError = isError;
-        }
-
-        public string Message { get; }
-        public ConsoleColor TextColor { get; }
-        public bool IsError { get; }
-    }
-
-    private readonly List<OutputMessage> outputMessages = new List<OutputMessage>();
+    private readonly List<OutputMessage> outputMessages = [];
 
     #region Checks
 
-    public void AssertNoOutput()
-    {
+    public void AssertNoOutput() =>
         outputMessages.Should().BeEmpty("Not expecting any output to have been written to the console");
-    }
 
-    public void AssertExpectedLastOutput(string message, ConsoleColor textColor, bool isError)
+    public void AssertExpectedLastOutput(string regex, ConsoleColor textColor, bool isError)
     {
         outputMessages.Should().NotBeEmpty("Expecting some output to have been written to the console");
 
-        var lastMessage = outputMessages.Last();
-
-        lastMessage.Message.Should().Be(message, "Unexpected message content");
+        var lastMessage = outputMessages[outputMessages.Count - 1];
+        lastMessage.Message.Should().MatchRegex(regex, "Unexpected message content");
         lastMessage.TextColor.Should().Be(textColor, "Unexpected text color");
         lastMessage.IsError.Should().Be(isError, "Unexpected output stream");
     }
 
-    public void AssertExpectedOutputText(params string[] messages)
+    public void AssertExpectedOutputText(params string[] regexes)
     {
-        outputMessages.Select(om => om.Message).Should().BeEquivalentTo(messages, "Unexpected output messages");
+        outputMessages.Should().HaveCount(regexes.Length);
+
+        foreach (var pair in outputMessages.Zip(regexes, (message, regex) => (message, regex)))
+        {
+            pair.message.Message.Should().MatchRegex(pair.regex, "Unexpected output message");
+        }
     }
 
     #endregion Checks
@@ -82,4 +70,18 @@ public void WriteLine(string message, ConsoleColor color, bool isError)
     }
 
     #endregion IOutputWriter methods
+
+    private class OutputMessage
+    {
+        public OutputMessage(string message, ConsoleColor textColor, bool isError)
+        {
+            Message = message;
+            TextColor = textColor;
+            IsError = isError;
+        }
+
+        public string Message { get; }
+        public ConsoleColor TextColor { get; }
+        public bool IsError { get; }
+    }
 }
diff --git a/src/SonarScanner.MSBuild.Common/ConsoleLogger.cs b/src/SonarScanner.MSBuild.Common/ConsoleLogger.cs
@@ -111,7 +111,7 @@ public void ResumeOutput()
     }
 
     public void LogWarning(string message, params object[] args) =>
-        Write(MessageType.Warning, GetFormattedMessage(Resources.Logger_WarningPrefix + message, args));
+        Write(MessageType.Warning, Resources.Logger_WarningPrefix + message, args);
 
     public void LogError(string message, params object[] args) =>
         Write(MessageType.Error, message, args);
@@ -124,9 +124,8 @@ public void LogInfo(string message, params object[] args) =>
 
     public void LogUIWarning(string message, params object[] args)
     {
-        var formattedMessage = GetFormattedMessage(message, args);
-        uiWarnings.Add(formattedMessage);
-        LogWarning(formattedMessage);
+        uiWarnings.Add(GetFormattedMessage(message, args));
+        LogWarning(message, args);
     }
 
     public void WriteUIWarnings(string outputFolder)
@@ -148,7 +147,7 @@ private string GetFormattedMessage(string message, params object[] args)
 
         if (IncludeTimestamp)
         {
-            finalMessage = string.Format(CultureInfo.CurrentCulture, "{0}  {1}", System.DateTime.Now.ToString("HH:mm:ss.FFF",
+            finalMessage = string.Format(CultureInfo.CurrentCulture, "{0}  {1}", DateTime.Now.ToString("HH:mm:ss.FFF",
                 CultureInfo.InvariantCulture), finalMessage);
         }
         return finalMessage;
@@ -160,26 +159,28 @@ private void FlushOutput()
         Debug.Assert(suspendedMessages is not null, "suspendedMessages should be non-null if output is suspended");
 
         isOutputSuspended = false;
-
         foreach (var message in suspendedMessages)
         {
-            Write(message.MessageType, message.FinalMessage);
+            WriteFormatted(message.MessageType, message.FinalMessage); // Messages have already been formatted before they end up here.
         }
-
         suspendedMessages = null;
     }
 
+    /// <summary>
+    /// Formats a message and writes or records it.
+    /// </summary>
+    private void Write(MessageType messageType, string message, params object[] args) =>
+        WriteFormatted(messageType, GetFormattedMessage(message, args));
+
     /// <summary>
     /// Either writes the message to the output stream, or records it
-    /// if output is currently suspended
+    /// if output is currently suspended.
     /// </summary>
-    private void Write(MessageType messageType, string message, params object[] args)
+    private void WriteFormatted(MessageType messageType, string formatted)
     {
-        var finalMessage = GetFormattedMessage(message, args);
-
         if (isOutputSuspended)
         {
-            suspendedMessages.Add(new Message(messageType, finalMessage));
+            suspendedMessages.Add(new Message(messageType, formatted));
         }
         else
         {
@@ -190,7 +191,7 @@ private void Write(MessageType messageType, string message, params object[] args
                 var textColor = GetConsoleColor(messageType);
 
                 Debug.Assert(outputWriter is not null, "OutputWriter should not be null");
-                outputWriter.WriteLine(finalMessage, textColor, messageType == MessageType.Error);
+                outputWriter.WriteLine(formatted, textColor, messageType == MessageType.Error);
             }
         }
     }
@@ -204,7 +205,7 @@ private static ConsoleColor GetConsoleColor(MessageType messageType) =>
             _ => Console.ForegroundColor,
         };
 
-    private class Message
+    private sealed class Message
     {
         public MessageType MessageType { get; }
         public string FinalMessage { get; }