Skip to content

Commit 8483352

Browse files
gregory-paidis-sonarsourcegregory-paidis-sonarsource
authored
SCAN4NET-96 and SCAN4NET-97: Fix logger timestamp duplication (#2212)
1 parent 054c9fa commit 8483352

File tree

4 files changed

+73
-46
lines changed

4 files changed

+73
-46
lines changed

‎Tests/SonarScanner.MSBuild.Common.Test/ILoggerTests.cs‎

Lines changed: 25 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -271,8 +271,9 @@ public void ConsoleLogger_Verbosity()
271271
[TestMethod]
272272
public void ConsoleLogger_SuspendAndResume()
273273
{
274+
const string prefixRegex = @"\d{2}:\d{2}:\d{2}(.\d{1,3})?";
274275
var recorder = new OutputRecorder();
275-
var logger = ConsoleLogger.CreateLoggerForTesting(false, recorder, fileWrapper);
276+
var logger = ConsoleLogger.CreateLoggerForTesting(true, recorder, fileWrapper);
276277

277278
// 1. Suspend output - should be able to call this multiple times
278279
logger.SuspendOutput();
@@ -301,17 +302,17 @@ public void ConsoleLogger_SuspendAndResume()
301302
logger.ResumeOutput();
302303

303304
recorder.AssertExpectedOutputText(
304-
"debug 1 xxx",
305-
"WARNING: warning 1 xxx",
306-
"error 1 xxx",
307-
"info 1 xxx");
305+
$"{prefixRegex} debug 1 xxx",
306+
$"{prefixRegex} WARNING: warning 1 xxx",
307+
$"{prefixRegex} error 1 xxx",
308+
$"{prefixRegex} info 1 xxx");
308309

309310
// 5. Log more -> output should be immediate
310311
logger.LogInfo("info 2");
311-
recorder.AssertExpectedLastOutput("info 2", Console.ForegroundColor, false);
312+
recorder.AssertExpectedLastOutput($"{prefixRegex} info 2", Console.ForegroundColor, false);
312313

313314
logger.LogError("error 2");
314-
recorder.AssertExpectedLastOutput("error 2", ConsoleLogger.ErrorColor, true);
315+
recorder.AssertExpectedLastOutput($"{prefixRegex} error 2", ConsoleLogger.ErrorColor, true);
315316
}
316317

317318
[TestMethod]
@@ -348,6 +349,23 @@ public void ConsoleLogger_WriteUIWarnings_GenerateFile()
348349
""");
349350
}
350351

352+
[TestMethod]
353+
public void ConsoleLogger_WriteUIWarnings_ContainsTimeStampOnce()
354+
{
355+
const string prefixRegex = @"\d{2}:\d{2}:\d{2}(.\d{1,3})? WARNING:";
356+
using var output = new OutputCaptureScope();
357+
var logger = new ConsoleLogger(includeTimestamp: true, fileWrapper);
358+
359+
logger.LogUIWarning("uiWarn1");
360+
output.AssertExpectedLastMessageRegex($"{prefixRegex} uiWarn1");
361+
362+
logger.LogUIWarning("uiWarn2", null);
363+
output.AssertExpectedLastMessageRegex($"{prefixRegex} uiWarn2");
364+
365+
logger.LogUIWarning("uiWarn3 {0}", "xxx");
366+
output.AssertExpectedLastMessageRegex($"{prefixRegex} uiWarn3 xxx");
367+
}
368+
351369
[TestMethod]
352370
public void ILogger_Log_Debug()
353371
{

‎Tests/SonarScanner.MSBuild.Common.Test/Infrastructure/OutputCaptureScope.cs‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -64,6 +64,12 @@ public void AssertExpectedLastMessage(string expected)
6464
lastMessage.Should().Be(expected, "Expected message was not logged");
6565
}
6666

67+
public void AssertExpectedLastMessageRegex(string expected)
68+
{
69+
var lastMessage = GetLastMessage(outputWriter);
70+
lastMessage.Should().MatchRegex(expected, "Expected message was not logged");
71+
}
72+
6773
public void AssertLastMessageEndsWith(string expected)
6874
{
6975
var lastMessage = GetLastMessage(outputWriter);

‎Tests/SonarScanner.MSBuild.Common.Test/Infrastructure/OutputRecorder.cs‎

Lines changed: 26 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -30,43 +30,31 @@ namespace SonarScanner.MSBuild.Common.Test;
3030
/// </summary>
3131
internal class OutputRecorder : IOutputWriter
3232
{
33-
private class OutputMessage
34-
{
35-
public OutputMessage(string message, ConsoleColor textColor, bool isError)
36-
{
37-
Message = message;
38-
TextColor = textColor;
39-
IsError = isError;
40-
}
41-
42-
public string Message { get; }
43-
public ConsoleColor TextColor { get; }
44-
public bool IsError { get; }
45-
}
46-
47-
private readonly List<OutputMessage> outputMessages = new List<OutputMessage>();
33+
private readonly List<OutputMessage> outputMessages = [];
4834

4935
#region Checks
5036

51-
public void AssertNoOutput()
52-
{
37+
public void AssertNoOutput() =>
5338
outputMessages.Should().BeEmpty("Not expecting any output to have been written to the console");
54-
}
5539

56-
public void AssertExpectedLastOutput(string message, ConsoleColor textColor, bool isError)
40+
public void AssertExpectedLastOutput(string regex, ConsoleColor textColor, bool isError)
5741
{
5842
outputMessages.Should().NotBeEmpty("Expecting some output to have been written to the console");
5943

60-
var lastMessage = outputMessages.Last();
61-
62-
lastMessage.Message.Should().Be(message, "Unexpected message content");
44+
var lastMessage = outputMessages[outputMessages.Count - 1];
45+
lastMessage.Message.Should().MatchRegex(regex, "Unexpected message content");
6346
lastMessage.TextColor.Should().Be(textColor, "Unexpected text color");
6447
lastMessage.IsError.Should().Be(isError, "Unexpected output stream");
6548
}
6649

67-
public void AssertExpectedOutputText(params string[] messages)
50+
public void AssertExpectedOutputText(params string[] regexes)
6851
{
69-
outputMessages.Select(om => om.Message).Should().BeEquivalentTo(messages, "Unexpected output messages");
52+
outputMessages.Should().HaveCount(regexes.Length);
53+
54+
foreach (var pair in outputMessages.Zip(regexes, (message, regex) => (message, regex)))
55+
{
56+
pair.message.Message.Should().MatchRegex(pair.regex, "Unexpected output message");
57+
}
7058
}
7159

7260
#endregion Checks
@@ -82,4 +70,18 @@ public void WriteLine(string message, ConsoleColor color, bool isError)
8270
}
8371

8472
#endregion IOutputWriter methods
73+
74+
private class OutputMessage
75+
{
76+
public OutputMessage(string message, ConsoleColor textColor, bool isError)
77+
{
78+
Message = message;
79+
TextColor = textColor;
80+
IsError = isError;
81+
}
82+
83+
public string Message { get; }
84+
public ConsoleColor TextColor { get; }
85+
public bool IsError { get; }
86+
}
8587
}

‎src/SonarScanner.MSBuild.Common/ConsoleLogger.cs‎

Lines changed: 16 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -111,7 +111,7 @@ public void ResumeOutput()
111111
}
112112

113113
public void LogWarning(string message, params object[] args) =>
114-
Write(MessageType.Warning, GetFormattedMessage(Resources.Logger_WarningPrefix + message, args));
114+
Write(MessageType.Warning, Resources.Logger_WarningPrefix + message, args);
115115

116116
public void LogError(string message, params object[] args) =>
117117
Write(MessageType.Error, message, args);
@@ -124,9 +124,8 @@ public void LogInfo(string message, params object[] args) =>
124124

125125
public void LogUIWarning(string message, params object[] args)
126126
{
127-
var formattedMessage = GetFormattedMessage(message, args);
128-
uiWarnings.Add(formattedMessage);
129-
LogWarning(formattedMessage);
127+
uiWarnings.Add(GetFormattedMessage(message, args));
128+
LogWarning(message, args);
130129
}
131130

132131
public void WriteUIWarnings(string outputFolder)
@@ -148,7 +147,7 @@ private string GetFormattedMessage(string message, params object[] args)
148147

149148
if (IncludeTimestamp)
150149
{
151-
finalMessage = string.Format(CultureInfo.CurrentCulture, "{0} {1}", System.DateTime.Now.ToString("HH:mm:ss.FFF",
150+
finalMessage = string.Format(CultureInfo.CurrentCulture, "{0} {1}", DateTime.Now.ToString("HH:mm:ss.FFF",
152151
CultureInfo.InvariantCulture), finalMessage);
153152
}
154153
return finalMessage;
@@ -160,26 +159,28 @@ private void FlushOutput()
160159
Debug.Assert(suspendedMessages is not null, "suspendedMessages should be non-null if output is suspended");
161160

162161
isOutputSuspended = false;
163-
164162
foreach (var message in suspendedMessages)
165163
{
166-
Write(message.MessageType, message.FinalMessage);
164+
WriteFormatted(message.MessageType, message.FinalMessage); // Messages have already been formatted before they end up here.
167165
}
168-
169166
suspendedMessages = null;
170167
}
171168

169+
/// <summary>
170+
/// Formats a message and writes or records it.
171+
/// </summary>
172+
private void Write(MessageType messageType, string message, params object[] args) =>
173+
WriteFormatted(messageType, GetFormattedMessage(message, args));
174+
172175
/// <summary>
173176
/// Either writes the message to the output stream, or records it
174-
/// if output is currently suspended
177+
/// if output is currently suspended.
175178
/// </summary>
176-
private void Write(MessageType messageType, string message, params object[] args)
179+
private void WriteFormatted(MessageType messageType, string formatted)
177180
{
178-
var finalMessage = GetFormattedMessage(message, args);
179-
180181
if (isOutputSuspended)
181182
{
182-
suspendedMessages.Add(new Message(messageType, finalMessage));
183+
suspendedMessages.Add(new Message(messageType, formatted));
183184
}
184185
else
185186
{
@@ -190,7 +191,7 @@ private void Write(MessageType messageType, string message, params object[] args
190191
var textColor = GetConsoleColor(messageType);
191192

192193
Debug.Assert(outputWriter is not null, "OutputWriter should not be null");
193-
outputWriter.WriteLine(finalMessage, textColor, messageType == MessageType.Error);
194+
outputWriter.WriteLine(formatted, textColor, messageType == MessageType.Error);
194195
}
195196
}
196197
}
@@ -204,7 +205,7 @@ private static ConsoleColor GetConsoleColor(MessageType messageType) =>
204205
_ => Console.ForegroundColor,
205206
};
206207

207-
private class Message
208+
private sealed class Message
208209
{
209210
public MessageType MessageType { get; }
210211
public string FinalMessage { get; }

0 commit comments

Comments
 (0)