Skip to content

Commit eaa3a39

Browse files
mariam-abdullamariam-abdulla
authored
Improve logging in dotnet test (#47507)
1 parent 62ac2cd commit eaa3a39

20 files changed

+288
-87
lines changed

‎src/Cli/dotnet/commands/dotnet-test/LocalizableStrings.resx‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -500,6 +500,12 @@ See https://aka.ms/dotnet-test/mtp for more information.</value>
500500
<data name="HelpWaitingForOptionsAndExtensions" xml:space="preserve">
501501
<value>Waiting for options and extensions...</value>
502502
</data>
503+
<data name="CmdNonExistentRootDirectoryErrorDescription" xml:space="preserve">
504+
<value>The provided root directory does not exist: {0}.</value>
505+
</data>
506+
<data name="CmdNoTestModulesErrorDescription" xml:space="preserve">
507+
<value>No test modules found for the given test module pattern: {0} with root directory: {1}</value>
508+
</data>
503509
<data name="CmdHelpUsageTitle" xml:space="preserve">
504510
<value>Usage:</value>
505511
</data>

‎src/Cli/dotnet/commands/dotnet-test/MSBuildHandler.cs‎

Lines changed: 13 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@ public bool RunMSBuild(BuildOptions buildOptions)
5555

5656
if (msBuildExitCode != ExitCode.Success)
5757
{
58-
_output.WriteMessage(string.Format(Microsoft.DotNet.Tools.Test.LocalizableStrings.CmdMSBuildProjectsPropertiesErrorDescription, msBuildExitCode));
58+
_output.WriteMessage(string.Format(Tools.Test.LocalizableStrings.CmdMSBuildProjectsPropertiesErrorDescription, msBuildExitCode));
5959
return false;
6060
}
6161

@@ -99,7 +99,7 @@ private void InitializeTestApplications(IEnumerable<TestModule> modules)
9999

100100
_output.WriteMessage(
101101
string.Format(
102-
Microsoft.DotNet.Tools.Test.LocalizableStrings.CmdUnsupportedVSTestTestApplicationsDescription,
102+
Tools.Test.LocalizableStrings.CmdUnsupportedVSTestTestApplicationsDescription,
103103
string.Join(Environment.NewLine, vsTestTestProjects.Select(module => Path.GetFileName(module.ProjectFullPath)))),
104104
new SystemConsoleColor { ConsoleColor = ConsoleColor.Red });
105105

@@ -151,15 +151,20 @@ private void LogProjectProperties(IEnumerable<TestModule> modules)
151151
return;
152152
}
153153

154+
var logMessageBuilder = new StringBuilder();
155+
154156
foreach (var module in modules)
155157
{
156-
Logger.LogTrace(() => $"{ProjectProperties.ProjectFullPath}: {module.ProjectFullPath}");
157-
Logger.LogTrace(() => $"{ProjectProperties.IsTestProject}: {module.IsTestProject}");
158-
Logger.LogTrace(() => $"{ProjectProperties.IsTestingPlatformApplication}: {module.IsTestingPlatformApplication}");
159-
Logger.LogTrace(() => $"{ProjectProperties.TargetFramework}: {module.TargetFramework}");
160-
Logger.LogTrace(() => $"{ProjectProperties.TargetPath}: {module.TargetPath}");
161-
Logger.LogTrace(() => $"{ProjectProperties.RunSettingsFilePath}: {module.RunSettingsFilePath}");
158+
logMessageBuilder.AppendLine($"{ProjectProperties.ProjectFullPath}: {module.ProjectFullPath}");
159+
logMessageBuilder.AppendLine($"{ProjectProperties.IsTestProject}: {module.IsTestProject}");
160+
logMessageBuilder.AppendLine($"{ProjectProperties.IsTestingPlatformApplication}: {module.IsTestingPlatformApplication}");
161+
logMessageBuilder.AppendLine($"{ProjectProperties.TargetFramework}: {module.TargetFramework}");
162+
logMessageBuilder.AppendLine($"{ProjectProperties.TargetPath}: {module.TargetPath}");
163+
logMessageBuilder.AppendLine($"{ProjectProperties.RunSettingsFilePath}: {module.RunSettingsFilePath}");
164+
logMessageBuilder.AppendLine();
162165
}
166+
167+
Logger.LogTrace(() => logMessageBuilder.ToString());
163168
}
164169

165170
public void Dispose()

‎src/Cli/dotnet/commands/dotnet-test/MSBuildUtility.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -41,9 +41,9 @@ public static (IEnumerable<TestModule> Projects, bool IsBuiltOrRestored) GetProj
4141
{
4242
return (Array.Empty<TestModule>(), isBuiltOrRestored);
4343
}
44-
44+
4545
IEnumerable<TestModule> projects = SolutionAndProjectUtility.GetProjectProperties(projectFilePath, GetGlobalProperties(buildOptions), new ProjectCollection());
46-
46+
4747
return (projects, isBuiltOrRestored);
4848
}
4949

‎src/Cli/dotnet/commands/dotnet-test/TestApplication.cs‎

Lines changed: 11 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ public async Task<int> RunAsync(TestOptions testOptions)
5050
{
5151
if (testOptions.HasFilterMode && !ModulePathExists())
5252
{
53-
return 1;
53+
return ExitCode.GenericFailure;
5454
}
5555

5656
bool isDll = _module.TargetPath.HasExtension(CliConstants.DLLExtension);
@@ -134,17 +134,17 @@ private async Task WaitConnectionAsync(CancellationToken token)
134134
catch (OperationCanceledException ex)
135135
{
136136
// We are exiting
137-
if (VSTestTrace.TraceEnabled)
137+
if (Logger.TraceEnabled)
138138
{
139139
string tokenType = ex.CancellationToken == token ? "internal token" : "external token";
140-
VSTestTrace.SafeWriteTrace(() => $"WaitConnectionAsync() throws OperationCanceledException with {tokenType}");
140+
Logger.LogTrace(() => $"WaitConnectionAsync() throws OperationCanceledException with {tokenType}");
141141
}
142142
}
143143
catch (Exception ex)
144144
{
145-
if (VSTestTrace.TraceEnabled)
145+
if (Logger.TraceEnabled)
146146
{
147-
VSTestTrace.SafeWriteTrace(() => ex.ToString());
147+
Logger.LogTrace(() => ex.ToString());
148148
}
149149

150150
Environment.FailFast(ex.ToString());
@@ -188,9 +188,9 @@ private Task<IResponse> OnRequest(IRequest request)
188188

189189
// If we don't recognize the message, log and skip it
190190
case UnknownMessage unknownMessage:
191-
if (VSTestTrace.TraceEnabled)
191+
if (Logger.TraceEnabled)
192192
{
193-
VSTestTrace.SafeWriteTrace(() => $"Request '{request.GetType()}' with Serializer ID = {unknownMessage.SerializerId} is unsupported.");
193+
Logger.LogTrace(() => $"Request '{request.GetType()}' with Serializer ID = {unknownMessage.SerializerId} is unsupported.");
194194
}
195195
return Task.FromResult((IResponse)VoidResponse.CachedInstance);
196196

@@ -201,9 +201,9 @@ private Task<IResponse> OnRequest(IRequest request)
201201
}
202202
catch (Exception ex)
203203
{
204-
if (VSTestTrace.TraceEnabled)
204+
if (Logger.TraceEnabled)
205205
{
206-
VSTestTrace.SafeWriteTrace(() => ex.ToString());
206+
Logger.LogTrace(() => ex.ToString());
207207
}
208208

209209
Environment.FailFast(ex.ToString());
@@ -237,9 +237,9 @@ private static HandshakeMessage CreateHandshakeMessage(string version) =>
237237

238238
private async Task<int> StartProcess(ProcessStartInfo processStartInfo)
239239
{
240-
if (VSTestTrace.TraceEnabled)
240+
if (Logger.TraceEnabled)
241241
{
242-
VSTestTrace.SafeWriteTrace(() => $"Test application arguments: {processStartInfo.Arguments}");
242+
Logger.LogTrace(() => $"Test application arguments: {processStartInfo.Arguments}");
243243
}
244244

245245
var process = Process.Start(processStartInfo);
@@ -400,13 +400,11 @@ public override string ToString()
400400
{
401401
builder.Append($"{ProjectProperties.ProjectFullPath}: {_module.ProjectFullPath}");
402402
}
403-
;
404403

405404
if (!string.IsNullOrEmpty(_module.TargetFramework))
406405
{
407406
builder.Append($"{ProjectProperties.TargetFramework} : {_module.TargetFramework}");
408407
}
409-
;
410408

411409
return builder.ToString();
412410
}

‎src/Cli/dotnet/commands/dotnet-test/TestApplicationEventHandlers.cs‎

Lines changed: 116 additions & 59 deletions
Original file line numberDiff line numberDiff line change
@@ -31,12 +31,7 @@ public void OnHandshakeReceived(object sender, HandshakeArgs args)
3131
_executions[testApplication] = appInfo;
3232
_output.AssemblyRunStarted(appInfo.ModulePath, appInfo.TargetFramework, appInfo.Architecture, appInfo.ExecutionId);
3333

34-
if (!Logger.TraceEnabled) return;
35-
36-
foreach (var property in args.Handshake.Properties)
37-
{
38-
Logger.LogTrace(() => $"{GetHandshakePropertyName(property.Key)}: {property.Value}");
39-
}
34+
LogHandshake(args);
4035
}
4136

4237
private static string GetHandshakePropertyName(byte propertyId) =>
@@ -65,13 +60,7 @@ public void OnDiscoveredTestsReceived(object sender, DiscoveredTestEventArgs arg
6560
test.Uid);
6661
}
6762

68-
if (!Logger.TraceEnabled) return;
69-
70-
Logger.LogTrace(() => $"DiscoveredTests Execution Id: {args.ExecutionId}");
71-
foreach (var discoveredTestMessage in args.DiscoveredTests)
72-
{
73-
Logger.LogTrace(() => $"DiscoveredTest: {discoveredTestMessage.Uid}, {discoveredTestMessage.DisplayName}");
74-
}
63+
LogDiscoveredTests(args);
7564
}
7665

7766
public void OnTestResultsReceived(object sender, TestResultEventArgs args)
@@ -108,23 +97,7 @@ public void OnTestResultsReceived(object sender, TestResultEventArgs args)
10897
errorOutput: null);
10998
}
11099

111-
if (!Logger.TraceEnabled) return;
112-
113-
Logger.LogTrace(() => $"TestResults Execution Id: {args.ExecutionId}");
114-
115-
foreach (SuccessfulTestResult successfulTestResult in args.SuccessfulTestResults)
116-
{
117-
Logger.LogTrace(() => $"SuccessfulTestResult: {successfulTestResult.Uid}, {successfulTestResult.DisplayName}, " +
118-
$"{successfulTestResult.State}, {successfulTestResult.Duration}, {successfulTestResult.Reason}, {successfulTestResult.StandardOutput}," +
119-
$"{successfulTestResult.ErrorOutput}, {successfulTestResult.SessionUid}");
120-
}
121-
122-
foreach (FailedTestResult failedTestResult in args.FailedTestResults)
123-
{
124-
Logger.LogTrace(() => $"FailedTestResult: {failedTestResult.Uid}, {failedTestResult.DisplayName}, " +
125-
$"{failedTestResult.State}, {failedTestResult.Duration}, {failedTestResult.Reason}, {string.Join(", ", failedTestResult.Exceptions?.Select(e => $"{e.ErrorMessage}, {e.ErrorType}, {e.StackTrace}"))}" +
126-
$"{failedTestResult.StandardOutput}, {failedTestResult.ErrorOutput}, {failedTestResult.SessionUid}");
127-
}
100+
LogTestResults(args);
128101
}
129102

130103
public void OnFileArtifactsReceived(object sender, FileArtifactEventArgs args)
@@ -140,16 +113,7 @@ public void OnFileArtifactsReceived(object sender, FileArtifactEventArgs args)
140113
artifact.TestDisplayName, artifact.FullPath);
141114
}
142115

143-
if (!Logger.TraceEnabled) return;
144-
145-
Logger.LogTrace(() => $"FileArtifactMessages Execution Id: {args.ExecutionId}");
146-
147-
foreach (FileArtifact fileArtifactMessage in args.FileArtifacts)
148-
{
149-
Logger.LogTrace(() => $"FileArtifact: {fileArtifactMessage.FullPath}, {fileArtifactMessage.DisplayName}, " +
150-
$"{fileArtifactMessage.Description}, {fileArtifactMessage.TestUid}, {fileArtifactMessage.TestDisplayName}, " +
151-
$"{fileArtifactMessage.SessionUid}");
152-
}
116+
LogFileArtifacts(args);
153117
}
154118

155119
public void OnSessionEventReceived(object sender, SessionEventArgs args)
@@ -180,39 +144,132 @@ public void OnTestProcessExited(object sender, TestProcessExitEventArgs args)
180144
_output.AssemblyRunCompleted(testApplication.Module.TargetPath ?? testApplication.Module.ProjectFullPath, testApplication.Module.TargetFramework, architecture: null, null, args.ExitCode, string.Join(Environment.NewLine, args.OutputData), string.Join(Environment.NewLine, args.ErrorData));
181145
}
182146

183-
if (!Logger.TraceEnabled) return;
147+
LogTestProcessExit(args);
148+
}
184149

185-
if (args.ExitCode != ExitCode.Success)
150+
public void OnExecutionIdReceived(object sender, ExecutionEventArgs args)
151+
{
152+
}
153+
154+
public static TestOutcome ToOutcome(byte? testState) => testState switch
155+
{
156+
TestStates.Passed => TestOutcome.Passed,
157+
TestStates.Skipped => TestOutcome.Skipped,
158+
TestStates.Failed => TestOutcome.Fail,
159+
TestStates.Error => TestOutcome.Error,
160+
TestStates.Timeout => TestOutcome.Timeout,
161+
TestStates.Cancelled => TestOutcome.Canceled,
162+
_ => throw new ArgumentOutOfRangeException(nameof(testState), $"Invalid test state value {testState}")
163+
};
164+
165+
private static void LogHandshake(HandshakeArgs args)
166+
{
167+
if (!Logger.TraceEnabled)
186168
{
187-
Logger.LogTrace(() => $"Test Process exited with non-zero exit code: {args.ExitCode}");
169+
return;
188170
}
189171

190-
if (args.OutputData.Count > 0)
172+
var logMessageBuilder = new StringBuilder();
173+
174+
foreach (var property in args.Handshake.Properties)
191175
{
192-
Logger.LogTrace(() => $"Output Data: {string.Join("\n", args.OutputData)}");
176+
logMessageBuilder.AppendLine($"{GetHandshakePropertyName(property.Key)}: {property.Value}");
193177
}
194178

195-
if (args.ErrorData.Count > 0)
179+
Logger.LogTrace(() => logMessageBuilder.ToString());
180+
}
181+
182+
private static void LogDiscoveredTests(DiscoveredTestEventArgs args)
183+
{
184+
if (!Logger.TraceEnabled)
196185
{
197-
Logger.LogTrace(() => $"Error Data: {string.Join("\n", args.ErrorData)}");
186+
return;
198187
}
188+
189+
var logMessageBuilder = new StringBuilder();
190+
191+
logMessageBuilder.AppendLine($"DiscoveredTests Execution Id: {args.ExecutionId}");
192+
foreach (var discoveredTestMessage in args.DiscoveredTests)
193+
{
194+
logMessageBuilder.AppendLine($"DiscoveredTest: {discoveredTestMessage.Uid}, {discoveredTestMessage.DisplayName}");
195+
}
196+
197+
Logger.LogTrace(() => logMessageBuilder.ToString());
199198
}
200199

201-
public void OnExecutionIdReceived(object sender, ExecutionEventArgs args)
200+
private static void LogTestResults(TestResultEventArgs args)
202201
{
202+
if (!Logger.TraceEnabled)
203+
{
204+
return;
205+
}
206+
207+
var logMessageBuilder = new StringBuilder();
208+
209+
logMessageBuilder.AppendLine($"TestResults Execution Id: {args.ExecutionId}");
210+
211+
foreach (SuccessfulTestResult successfulTestResult in args.SuccessfulTestResults)
212+
{
213+
logMessageBuilder.AppendLine($"SuccessfulTestResult: {successfulTestResult.Uid}, {successfulTestResult.DisplayName}, " +
214+
$"{successfulTestResult.State}, {successfulTestResult.Duration}, {successfulTestResult.Reason}, {successfulTestResult.StandardOutput}," +
215+
$"{successfulTestResult.ErrorOutput}, {successfulTestResult.SessionUid}");
216+
}
217+
218+
foreach (FailedTestResult failedTestResult in args.FailedTestResults)
219+
{
220+
logMessageBuilder.AppendLine($"FailedTestResult: {failedTestResult.Uid}, {failedTestResult.DisplayName}, " +
221+
$"{failedTestResult.State}, {failedTestResult.Duration}, {failedTestResult.Reason}, {string.Join(", ", failedTestResult.Exceptions?.Select(e => $"{e.ErrorMessage}, {e.ErrorType}, {e.StackTrace}"))}" +
222+
$"{failedTestResult.StandardOutput}, {failedTestResult.ErrorOutput}, {failedTestResult.SessionUid}");
223+
}
224+
225+
Logger.LogTrace(() => logMessageBuilder.ToString());
203226
}
204227

205-
public static TestOutcome ToOutcome(byte? testState)
228+
private static void LogFileArtifacts(FileArtifactEventArgs args)
206229
{
207-
return testState switch
208-
{
209-
TestStates.Passed => TestOutcome.Passed,
210-
TestStates.Skipped => TestOutcome.Skipped,
211-
TestStates.Failed => TestOutcome.Fail,
212-
TestStates.Error => TestOutcome.Error,
213-
TestStates.Timeout => TestOutcome.Timeout,
214-
TestStates.Cancelled => TestOutcome.Canceled,
215-
_ => throw new ArgumentOutOfRangeException(nameof(testState), $"Invalid test state value {testState}")
216-
};
230+
if (!Logger.TraceEnabled)
231+
{
232+
return;
233+
}
234+
235+
var logMessageBuilder = new StringBuilder();
236+
237+
logMessageBuilder.AppendLine($"FileArtifactMessages Execution Id: {args.ExecutionId}");
238+
239+
foreach (FileArtifact fileArtifactMessage in args.FileArtifacts)
240+
{
241+
logMessageBuilder.AppendLine($"FileArtifact: {fileArtifactMessage.FullPath}, {fileArtifactMessage.DisplayName}, " +
242+
$"{fileArtifactMessage.Description}, {fileArtifactMessage.TestUid}, {fileArtifactMessage.TestDisplayName}, " +
243+
$"{fileArtifactMessage.SessionUid}");
244+
}
245+
246+
Logger.LogTrace(() => logMessageBuilder.ToString());
247+
}
248+
249+
private static void LogTestProcessExit(TestProcessExitEventArgs args)
250+
{
251+
if (!Logger.TraceEnabled)
252+
{
253+
return;
254+
}
255+
256+
var logMessageBuilder = new StringBuilder();
257+
258+
if (args.ExitCode != ExitCode.Success)
259+
{
260+
logMessageBuilder.AppendLine($"Test Process exited with non-zero exit code: {args.ExitCode}");
261+
}
262+
263+
if (args.OutputData.Count > 0)
264+
{
265+
logMessageBuilder.AppendLine($"Output Data: {string.Join(Environment.NewLine, args.OutputData)}");
266+
}
267+
268+
if (args.ErrorData.Count > 0)
269+
{
270+
logMessageBuilder.AppendLine($"Error Data: {string.Join(Environment.NewLine, args.ErrorData)}");
271+
}
272+
273+
Logger.LogTrace(() => logMessageBuilder.ToString());
217274
}
218275
}

0 commit comments

Comments
 (0)