don't dump stack of parent when child process exits unexpectedly

[danmoseley]

I'm not sure of configuration, but I've seen this for several years: when a child test process terminates unexpectedly (perhaps because it hung and was killed) then the test infra dumps the stack trace of the parent process when the connection drops. The example below came from running some tests in Azure DevOps yesterday.

This stack trace ought to be suppressed. It is not useful to anyone except someone debugging the vstest parent process, as far as I know. Each time I see it, I start analyzing it until I remember that it is not relevant. In the case below, I guess Azure DevOps (?) printed "Please inspect the call stack above, if available, to get more information about where the exception originated from." which makes the confusion worse.

Suggestion: do not dump the callstack from the parent when there's an exception inside NotifyDataAvailable(). It causes more confusion than value. Instead, just print something like "The test process exited unexpectedly."

cc @RussKie

  Passed Microsoft.Extensions.Diagnostics.ResourceMonitoring.Windows.Test.WindowsUtilizationExtensionsTest.AddWindowsCounters_Adds_WindowsCounters_To_ServiceCollection [< 1 ms]
[xUnit.net 00:05:31.65] Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests: [Long Running Test] 'Microsoft.Extensions.Diagnostics.ResourceMonitoring.Test.ResourceUtilizationTrackerServiceTest.ResourceUtilizationTracker_WhenInitializedWithZeroSnapshots_ReportsHighCpuSpikesThenConvergeInFewCycles', Elapsed: 00:05:29
The active test run was aborted. Reason: Test host process crashed
Data collector 'Blame' message: The specified inactivity time of 6 minutes has elapsed. Collecting hang dumps from testhost and its child processes.
Data collector 'Blame' message: Dumping 5976 - testhost.

Test Run Aborted with error System.Exception: One or more errors occurred.
 ---> System.Exception: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..
 ---> System.Exception: An existing connection was forcibly closed by the remote host.
   at System.Net.Sockets.NetworkStream.Read(Span`1 buffer)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Read(Span`1 buffer)
   at System.Net.Sockets.NetworkStream.ReadByte()
   at System.IO.BinaryReader.Read7BitEncodedInt()
   at System.IO.BinaryReader.ReadString()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.NotifyDataAvailable() in /_/src/Microsoft.TestPlatform.CommunicationUtilities/LengthPrefixCommunicationChannel.cs:line 90
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TcpClientExtensions.MessageLoopAsync(TcpClient client, ICommunicationChannel channel, Action`1 errorHandler, CancellationToken cancellationToken) in /_/src/Microsoft.TestPlatform.CommunicationUtilities/TcpClientExtensions.cs:line 53
   --- End of inner exception stack trace ---.
Total tests: Unknown
     Passed: 115
    Skipped: 74
 Total time: 6.3094 Minutes
Results File: D:\a\_work\1\s\artifacts\TestResults\Release\Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests_net8.0_x64.trx
Html test results file : D:\a\_work\1\s\artifacts\TestResults\Release\Microsoft.Extensions.Diagnostics.ResourceMonitoring.Tests_net8.0_x64.html

The active Test Run was aborted because the host process exited unexpectedly. Please inspect the call stack above, if available, to get more information about where the exception originated from.
The test running when the crash occurred: 
Microsoft.Extensions.Diagnostics.ResourceMonitoring.Test.ResourceUtilizationTrackerServiceTest.ResourceUtilizationTracker_WhenInitializedWithZeroSnapshots_ReportsHighCpuSpikesThenConvergeInFewCycles

[danmoseley]

Looks like this maybe means something liek when CommonResources.TestHostProcessCrashed

vstest/src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs

Line 664 in ba4e7b3

reason = CommonResources.TestHostProcessCrashed;

then don't include the exception in the TestRunCompleteEventArgs, or something.

vstest/src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs

Line 608 in ba4e7b3

var completeArgs = new TestRunCompleteEventArgs(null, false, true, exception, null, TimeSpan.Zero);

is the kind of thing I mean.

[MarcoRossignoli]

Hi @danmoseley I agree with you that error doesn't mean nothing pretty always only that the testhost process is not exited gracefully but the reason is usually a real crash or a forced crash for a requested dump.

@nohwnd what you think? I think it would be fine maybe log in the file but catch in some way and don't flow to the console.

cc: @jakubch1 @Evangelink

[RussKie]

It could be great to get the source of the crash, if possible. E.g., if the test was killed by timeout.

[MarcoRossignoli]

@RussKie in the output at the moment there's the reason...the issue is that is "mixed" with an useless and out of the context stack trace.

[danmoseley]

Right, we're all in agreement that the output should include all possible info about the test process, including any callstack, exit code, whether it timed out, etc. We should suppress the internal details of the parent behavior, which is irrelevant and misleading, so that the customer relevant info is clearer.

[nohwnd]

@marco Yes.

[nohwnd]

The error is raised here

vstest/src/Microsoft.TestPlatform.CommunicationUtilities/TcpClientExtensions.cs

Line 74 in b19ec25

error = ioException;

Which calls StopOnError, which triggers .Disconnected event, that we subscribe to on ICommunicationEndPoint and trigger TestRequestSender.OnTestRunAbort, which forwards the error as part of HandleRunCompleted completeArgs.

We can comment the passing of error where it is collected and we won't get it to show up in the output. Not sure if that is the best place to do it, but ignoring the error later is also not great because different transports can raise different errors.

Here after the patch we get testhost error that was written to testhostprocess ErrorOutput, but not the transport error: