Skip to content

Commit da24ea8

Browse files
authored
Use interpolated string handler for dotnet test logging (#50599)
1 parent 2435146 commit da24ea8

File tree

5 files changed

+94
-47
lines changed

5 files changed

+94
-47
lines changed

src/Cli/dotnet/Commands/Test/Logger.cs

Lines changed: 73 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,42 +1,107 @@
11
// Licensed to the .NET Foundation under one or more agreements.
22
// The .NET Foundation licenses this file to you under the MIT license.
33

4-
#nullable disable
4+
using System.Runtime.CompilerServices;
55

66
namespace Microsoft.DotNet.Cli.Commands.Test;
77

88
internal static class Logger
99
{
10+
[InterpolatedStringHandler]
11+
internal readonly struct LoggerInterpolatedStringHandler
12+
{
13+
/// <summary>The handler we use to perform the formatting.</summary>
14+
private readonly StringBuilder.AppendInterpolatedStringHandler _stringBuilderHandler;
15+
private readonly StringBuilder? _stringBuilder;
16+
17+
public LoggerInterpolatedStringHandler(int literalLength, int formattedCount, out bool shouldAppend)
18+
{
19+
shouldAppend = Logger.TraceEnabled;
20+
if (shouldAppend)
21+
{
22+
_stringBuilder = new StringBuilder();
23+
_stringBuilderHandler = new(literalLength, formattedCount, _stringBuilder);
24+
}
25+
}
26+
27+
public override string ToString()
28+
=> _stringBuilder?.ToString() ?? string.Empty;
29+
30+
public void AppendLiteral(string value) => _stringBuilderHandler!.AppendLiteral(value);
31+
32+
public void AppendFormatted<T>(T value) => _stringBuilderHandler.AppendFormatted<T>(value);
33+
34+
public void AppendFormatted<T>(T value, string? format) => _stringBuilderHandler.AppendFormatted<T>(value, format);
35+
36+
public void AppendFormatted<T>(T value, int alignment) => _stringBuilderHandler.AppendFormatted<T>(value, alignment);
37+
38+
public void AppendFormatted<T>(T value, int alignment, string? format) => _stringBuilderHandler.AppendFormatted<T>(value, alignment, format);
39+
40+
public void AppendFormatted(ReadOnlySpan<char> value) => _stringBuilderHandler.AppendFormatted(value);
41+
42+
public void AppendFormatted(ReadOnlySpan<char> value, int alignment = 0, string? format = null) => _stringBuilderHandler.AppendFormatted(value, alignment, format);
43+
44+
public void AppendFormatted(string? value) => _stringBuilderHandler.AppendFormatted(value);
45+
46+
public void AppendFormatted(string? value, int alignment = 0, string? format = null) => _stringBuilderHandler.AppendFormatted(value, alignment, format);
47+
48+
public void AppendFormatted(object? value, int alignment = 0, string? format = null) => _stringBuilderHandler.AppendFormatted(value, alignment, format);
49+
}
50+
1051
public static bool TraceEnabled { get; private set; }
11-
private static readonly string _traceFilePath;
52+
private static readonly string? _traceFilePath;
1253
private static readonly object _lock = new();
1354

1455
static Logger()
1556
{
1657
_traceFilePath = Environment.GetEnvironmentVariable(CliConstants.TestTraceLoggingEnvVar);
1758
TraceEnabled = !string.IsNullOrEmpty(_traceFilePath);
1859

19-
string directoryPath = Path.GetDirectoryName(_traceFilePath);
60+
string? directoryPath = Path.GetDirectoryName(_traceFilePath);
2061
if (!string.IsNullOrEmpty(directoryPath))
2162
{
2263
Directory.CreateDirectory(directoryPath);
2364
}
2465
}
2566

26-
public static void LogTrace(Func<string> messageLog)
67+
/// <summary>
68+
/// Use this overload carefully for performance reasons.
69+
/// We don't want the argument to have expensive calculations.
70+
/// </summary>
71+
/// <param name="message"></param>
72+
public static void LogTrace(string message)
2773
{
28-
if (!TraceEnabled)
74+
if (TraceEnabled)
2975
{
30-
return;
76+
LogTraceCore(message);
3177
}
78+
}
3279

80+
public static void LogTrace(ref LoggerInterpolatedStringHandler handler)
81+
{
82+
if (TraceEnabled)
83+
{
84+
LogTraceCore(handler.ToString());
85+
}
86+
}
87+
88+
public static void LogTrace<T>(T arg, Func<T, string> messageGetter)
89+
{
90+
if (TraceEnabled)
91+
{
92+
LogTraceCore(messageGetter(arg));
93+
}
94+
}
95+
96+
private static void LogTraceCore(string message)
97+
{
3398
try
3499
{
35-
string message = $"[dotnet test - {DateTimeOffset.UtcNow:MM/dd/yyyy HH:mm:ss.fff}]{messageLog()}";
100+
message = $"[dotnet test - {DateTimeOffset.UtcNow:MM/dd/yyyy HH:mm:ss.fff}]{message}";
36101

37102
lock (_lock)
38103
{
39-
using StreamWriter logFile = File.AppendText(_traceFilePath);
104+
using StreamWriter logFile = File.AppendText(_traceFilePath!);
40105
logFile.WriteLine(message);
41106
}
42107
}

src/Cli/dotnet/Commands/Test/MSBuildHandler.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,6 @@ private static void LogProjectProperties(IEnumerable<ParallelizableTestModuleGro
179179
}
180180
}
181181

182-
Logger.LogTrace(() => logMessageBuilder.ToString());
182+
Logger.LogTrace(logMessageBuilder, static logMessageBuilder => logMessageBuilder.ToString());
183183
}
184184
}

src/Cli/dotnet/Commands/Test/SolutionAndProjectUtility.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -205,7 +205,7 @@ public static IEnumerable<ParallelizableTestModuleGroupWithSequentialInnerModule
205205
var targetFramework = projectInstance.GetPropertyValue(ProjectProperties.TargetFramework);
206206
var targetFrameworks = projectInstance.GetPropertyValue(ProjectProperties.TargetFrameworks);
207207

208-
Logger.LogTrace(() => $"Loaded project '{Path.GetFileName(projectFilePath)}' with TargetFramework '{targetFramework}', TargetFrameworks '{targetFrameworks}', IsTestProject '{projectInstance.GetPropertyValue(ProjectProperties.IsTestProject)}', and '{ProjectProperties.IsTestingPlatformApplication}' is '{projectInstance.GetPropertyValue(ProjectProperties.IsTestingPlatformApplication)}'.");
208+
Logger.LogTrace($"Loaded project '{Path.GetFileName(projectFilePath)}' with TargetFramework '{targetFramework}', TargetFrameworks '{targetFrameworks}', IsTestProject '{projectInstance.GetPropertyValue(ProjectProperties.IsTestProject)}', and '{ProjectProperties.IsTestingPlatformApplication}' is '{projectInstance.GetPropertyValue(ProjectProperties.IsTestingPlatformApplication)}'.");
209209

210210
if (!string.IsNullOrEmpty(targetFramework) || string.IsNullOrEmpty(targetFrameworks))
211211
{
@@ -235,7 +235,7 @@ public static IEnumerable<ParallelizableTestModuleGroupWithSequentialInnerModule
235235
foreach (var framework in frameworks)
236236
{
237237
projectInstance = EvaluateProject(projectCollection, projectFilePath, framework);
238-
Logger.LogTrace(() => $"Loaded inner project '{Path.GetFileName(projectFilePath)}' has '{ProjectProperties.IsTestingPlatformApplication}' = '{projectInstance.GetPropertyValue(ProjectProperties.IsTestingPlatformApplication)}' (TFM: '{framework}').");
238+
Logger.LogTrace($"Loaded inner project '{Path.GetFileName(projectFilePath)}' has '{ProjectProperties.IsTestingPlatformApplication}' = '{projectInstance.GetPropertyValue(ProjectProperties.IsTestingPlatformApplication)}' (TFM: '{framework}').");
239239

240240
if (GetModuleFromProject(projectInstance, projectCollection.Loggers, buildOptions) is { } module)
241241
{
@@ -249,7 +249,7 @@ public static IEnumerable<ParallelizableTestModuleGroupWithSequentialInnerModule
249249
foreach (var framework in frameworks)
250250
{
251251
projectInstance = EvaluateProject(projectCollection, projectFilePath, framework);
252-
Logger.LogTrace(() => $"Loaded inner project '{Path.GetFileName(projectFilePath)}' has '{ProjectProperties.IsTestingPlatformApplication}' = '{projectInstance.GetPropertyValue(ProjectProperties.IsTestingPlatformApplication)}' (TFM: '{framework}').");
252+
Logger.LogTrace($"Loaded inner project '{Path.GetFileName(projectFilePath)}' has '{ProjectProperties.IsTestingPlatformApplication}' = '{projectInstance.GetPropertyValue(ProjectProperties.IsTestingPlatformApplication)}' (TFM: '{framework}').");
253253

254254
if (GetModuleFromProject(projectInstance, projectCollection.Loggers, buildOptions) is { } module)
255255
{

src/Cli/dotnet/Commands/Test/TestApplication.cs

Lines changed: 11 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -162,20 +162,13 @@ private async Task WaitConnectionAsync(CancellationToken token)
162162
catch (OperationCanceledException ex)
163163
{
164164
// We are exiting
165-
if (Logger.TraceEnabled)
166-
{
167-
string tokenType = ex.CancellationToken == token ? "internal token" : "external token";
168-
Logger.LogTrace(() => $"WaitConnectionAsync() throws OperationCanceledException with {tokenType}");
169-
}
165+
Logger.LogTrace($"WaitConnectionAsync() throws OperationCanceledException with {(ex.CancellationToken == token ? "internal token" : "external token")}");
170166
}
171167
catch (Exception ex)
172168
{
173-
if (Logger.TraceEnabled)
174-
{
175-
Logger.LogTrace(() => ex.ToString());
176-
}
177-
178-
Environment.FailFast(ex.ToString());
169+
var exAsString = ex.ToString();
170+
Logger.LogTrace(exAsString);
171+
Environment.FailFast(exAsString);
179172
}
180173
}
181174

@@ -213,10 +206,7 @@ private Task<IResponse> OnRequest(NamedPipeServer server, IRequest request)
213206

214207
// If we don't recognize the message, log and skip it
215208
case UnknownMessage unknownMessage:
216-
if (Logger.TraceEnabled)
217-
{
218-
Logger.LogTrace(() => $"Request '{request.GetType()}' with Serializer ID = {unknownMessage.SerializerId} is unsupported.");
219-
}
209+
Logger.LogTrace($"Request '{request.GetType()}' with Serializer ID = {unknownMessage.SerializerId} is unsupported.");
220210
return Task.FromResult((IResponse)VoidResponse.CachedInstance);
221211

222212
default:
@@ -226,12 +216,9 @@ private Task<IResponse> OnRequest(NamedPipeServer server, IRequest request)
226216
}
227217
catch (Exception ex)
228218
{
229-
if (Logger.TraceEnabled)
230-
{
231-
Logger.LogTrace(() => ex.ToString());
232-
}
233-
234-
Environment.FailFast(ex.ToString());
219+
string exAsString = ex.ToString();
220+
Logger.LogTrace(exAsString);
221+
Environment.FailFast(exAsString);
235222
}
236223

237224
return Task.FromResult((IResponse)VoidResponse.CachedInstance);
@@ -273,10 +260,7 @@ private static HandshakeMessage CreateHandshakeMessage(string version) =>
273260

274261
private async Task<int> StartProcess(ProcessStartInfo processStartInfo)
275262
{
276-
if (Logger.TraceEnabled)
277-
{
278-
Logger.LogTrace(() => $"Test application arguments: {processStartInfo.Arguments}");
279-
}
263+
Logger.LogTrace($"Test application arguments: {processStartInfo.Arguments}");
280264

281265
using var process = Process.Start(processStartInfo);
282266
StoreOutputAndErrorData(process);
@@ -314,7 +298,7 @@ private bool ModulePathExists()
314298
if (!File.Exists(Module.RunProperties.Command))
315299
{
316300
// TODO: The error should be shown to the user, not just logged to trace.
317-
Logger.LogTrace(() => $"Test module '{Module.RunProperties.Command}' not found. Build the test application before or run 'dotnet test'.");
301+
Logger.LogTrace($"Test module '{Module.RunProperties.Command}' not found. Build the test application before or run 'dotnet test'.");
318302

319303
return false;
320304
}
@@ -391,7 +375,7 @@ public void Dispose()
391375
foreach (var kvp in handshake.Properties)
392376
{
393377
messageBuilder.AppendLine($"{kvp.Key}: {kvp.Value}");
394-
}
378+
}
395379
}
396380
else
397381
{

src/Cli/dotnet/Commands/Test/TestApplicationHandler.cs

Lines changed: 6 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -168,9 +168,7 @@ internal void OnSessionEventReceived(TestSessionEvent sessionEvent)
168168
{
169169
// TODO: We shouldn't only log here!
170170
// We should use it in a more meaningful way. e.g, ensure we received session start/end events.
171-
if (!Logger.TraceEnabled) return;
172-
173-
Logger.LogTrace(() => $"TestSessionEvent: {sessionEvent.SessionType}, {sessionEvent.SessionUid}, {sessionEvent.ExecutionId}");
171+
Logger.LogTrace($"TestSessionEvent: {sessionEvent.SessionType}, {sessionEvent.SessionUid}, {sessionEvent.ExecutionId}");
174172
}
175173

176174
internal void OnTestProcessExited(int exitCode, List<string> outputData, List<string> errorData)
@@ -214,7 +212,7 @@ private static void LogHandshake(HandshakeMessage handshakeMessage)
214212
logMessageBuilder.AppendLine($"{GetHandshakePropertyName(property.Key)}: {property.Value}");
215213
}
216214

217-
Logger.LogTrace(() => logMessageBuilder.ToString());
215+
Logger.LogTrace(logMessageBuilder, static logMessageBuilder => logMessageBuilder.ToString());
218216
}
219217

220218
private static void LogDiscoveredTests(DiscoveredTestMessages discoveredTestMessages)
@@ -234,7 +232,7 @@ private static void LogDiscoveredTests(DiscoveredTestMessages discoveredTestMess
234232
logMessageBuilder.AppendLine($"DiscoveredTest: {discoveredTestMessage.Uid}, {discoveredTestMessage.DisplayName}");
235233
}
236234

237-
Logger.LogTrace(() => logMessageBuilder.ToString());
235+
Logger.LogTrace(logMessageBuilder, static logMessageBuilder => logMessageBuilder.ToString());
238236
}
239237

240238
private static void LogTestResults(TestResultMessages testResultMessages)
@@ -263,7 +261,7 @@ private static void LogTestResults(TestResultMessages testResultMessages)
263261
$"{failedTestResult.StandardOutput}, {failedTestResult.ErrorOutput}, {failedTestResult.SessionUid}");
264262
}
265263

266-
Logger.LogTrace(() => logMessageBuilder.ToString());
264+
Logger.LogTrace(logMessageBuilder, static logMessageBuilder => logMessageBuilder.ToString());
267265
}
268266

269267
private static void LogFileArtifacts(FileArtifactMessages fileArtifactMessages)
@@ -285,7 +283,7 @@ private static void LogFileArtifacts(FileArtifactMessages fileArtifactMessages)
285283
$"{fileArtifactMessage.SessionUid}");
286284
}
287285

288-
Logger.LogTrace(() => logMessageBuilder.ToString());
286+
Logger.LogTrace(logMessageBuilder, static logMessageBuilder => logMessageBuilder.ToString());
289287
}
290288

291289
private static void LogTestProcessExit(int exitCode, string outputData, string errorData)
@@ -312,6 +310,6 @@ private static void LogTestProcessExit(int exitCode, string outputData, string e
312310
logMessageBuilder.AppendLine($"Error Data: {errorData}");
313311
}
314312

315-
Logger.LogTrace(() => logMessageBuilder.ToString());
313+
Logger.LogTrace(logMessageBuilder, static logMessageBuilder => logMessageBuilder.ToString());
316314
}
317315
}

0 commit comments

Comments
 (0)