"Test host process crashed" error hard to diagnose

[KirillOsenkov]

Our CI has an intermittent failure:

The active test run was aborted. Reason: Test host process crashed
Results File: C:\a\_temp\AzDevOps_2019-6vse00024V_2021-06-24_02_47_47.trx
Test Run Aborted.

As far as I can tell, the message is printed by this code:

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

Line 667 in eff66c0

reason = CommonResources.TestHostProcessCrashed;

It would be really helpful here if it printed the full path to the process executable that crashed. I took a quick look but I couldn't find where to get the executable full path from. Also it seems that the error output stream contents was empty (clientExitErrorMessage) so when the test process crashes it should print the full exception stack to the Console.Error so that the stack appears in the CI log.

[KirillOsenkov]

FYI @AArnott who has been investigating this recently

[KirillOsenkov]

I have found out what my problem was. It's that infamous 100ms bug striking again, I can't even fathom how much that bug has caused our ecosystem in terms of productivity loss. I personally wasted four full days tracking this down.

I had to add --diag to my dotnet test arguments to publish the diagnostic logs, and then a separate step to upload them as artifacts.

Finally I saw this:

TpTrace Error: 0 : 6860, 7, 2021/06/26, 19:34:34.416, 8580065582, vstest.console.dll, LengthPrefixCommunicationChannel.Send: Error sending data: System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
 ---> System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.BufferedStream.Flush()
   at System.IO.BinaryWriter.Flush()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data).
TpTrace Warning: 0 : 6860, 7, 2021/06/26, 19:34:34.417, 8580070372, vstest.console.dll, ProxyOperationManager: Failed to end session: Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.Interfaces.CommunicationException: Unable to send data over channel.
 ---> System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
 ---> System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.BufferedStream.Flush()
   at System.IO.BinaryWriter.Flush()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data)
   --- End of inner exception stack trace ---
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data)
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender.EndSession()
   at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Client.ProxyOperationManager.Close()
TpTrace Warning: 0 : 6860, 7, 2021/06/26, 19:34:34.417, 8580071127, vstest.console.dll, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process.

I think it's this issue:
#2379

vstest/src/Microsoft.TestPlatform.CrossPlatEngine/Client/ProxyOperationManager.cs

Lines 211 to 215 in d10bcbb

	// We want to give test host a chance to safely close.
	// The upper bound for wait should be 100ms.
	var timeout = 100;
	EqtTrace.Verbose("ProxyOperationManager.Close: waiting for test host to exit for {0} ms", timeout);
	this.testHostExited.Wait(timeout);

The process is busy doing something, then we impatiently kill it after 100ms, AND WE DON'T TELL THE USER WE KILLED IT. All the user sees is:

The active test run was aborted. Reason: Test host process crashed

So then the user is sent on a wild goose chase for 4 days trying to figure out various ways to deploy procdump.exe to the CI agent, find out that it doesn't work anyway because we only explicitly pass StackOverflowException and AccessViolationException as arguments to procdump and ignore other types of exceptions.

We killed the process, we know it, but we don't log it, don't publish the dump, don't have any MSBuild errors, leaving the user helpless, frustrated, blocked, not knowing how to proceed.

[nohwnd]

I agree it could be easier if you use dotnet test. But we also have vstest yaml task (and classic pipeline task) which has all those cool levers, which could have saved you those 4 days.

1. It enables crash dump for critical failures (it includes procdump and configures the procdump_path).
2. When running the pipeline, you can click Enable system diagnostics. The task will check that and add diag parameters to the call to vstest. And upload the logs afterwards. You will get them by clicking on ... on the run, and Download logs, our logs have .diag extension. Alternatively you can set syste.debug = true in your pipeline to have this enabled all the time.

The error above looks more like testhost crashed, rather than vstest.console just failing to await it. Please upload the logs if you can, or point me to the build. Or is it one of the builds you shared in chat?

[KirillOsenkov]

Yes, it's the build I mentioned in chat.

Things should work regardless of whether I'm using dotnet test or the VSTest yaml task. Where are the docs for the VSTest task? Where are these screenshots from? What is the yaml syntax if I wanted to switch my pipeline from dotnet test to VSTest?

dotnet test experience should be just as well supported as the VSTest task.

[KirillOsenkov]

I've switched to the LocalDumps registry key and will report how that goes.

- powershell: |
    $key = "HKLM:\\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps"
    $LogDir = "$(Build.ArtifactStagingDirectory)\build_logs"
    New-Item -Path $key -ErrorAction SilentlyContinue
    New-ItemProperty -Path $key -Name 'DumpType' -PropertyType 'DWord' -Value 2 -Force
    New-ItemProperty -Path $key -Name 'DumpCount' -PropertyType 'DWord' -Value 10 -Force
    New-ItemProperty -Path $key -Name 'DumpFolder' -PropertyType 'String' -Value $LogDir -Force
    displayName: Enable LocalDumps in registry
    continueOnError: true

- powershell: |
    $key = "HKLM:\\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps"
    New-Item -Path $key -ErrorAction SilentlyContinue
    New-ItemProperty -Path $key -Name 'DumpType' -PropertyType 'DWord' -Value 0 -Force
  displayName: Disable LocalDumps in registry
  continueOnError: true
  condition: always()

[michael-hawker]

Not sure if this is the same as this issue as well.

We've also just started encountering this error as well, seemingly randomly as we're trying to add one test and it's failing in a completely different error. Log notes here:

TpTrace Verbose: 0 : 6936, 7, 2021/08/02, 22:54:58.235, 23624538797, vstest.console.exe, TestRunRequest:SendTestRunStatsChange: Starting.
TpTrace Verbose: 0 : 6936, 7, 2021/08/02, 22:54:58.236, 23624542076, vstest.console.exe, InProgress is Test_AdvancedCollectionView_Sorting_CustomComparable_With_Shaping
TpTrace Information: 0 : 6936, 7, 2021/08/02, 22:54:58.236, 23624546076, vstest.console.exe, TestRunRequest:SendTestRunStatsChange: Completed.
TpTrace Verbose: 0 : 6936, 7, 2021/08/02, 22:54:58.236, 23624547234, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50149 localEndPoint: 127.0.0.1:50148
TpTrace Verbose: 0 : 6936, 7, 2021/08/02, 22:54:59.237, 23634551254, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50149 localEndPoint: 127.0.0.1:50148
TpTrace Verbose: 0 : 6936, 7, 2021/08/02, 22:55:00.237, 23644560575, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50149 localEndPoint: 127.0.0.1:50148
TpTrace Verbose: 0 : 6936, 7, 2021/08/02, 22:55:01.240, 23654583662, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:50149 localEndPoint: 127.0.0.1:50148
TpTrace Error: 0 : 6936, 7, 2021/08/02, 22:55:01.416, 23656349603, vstest.console.exe, Socket: Message loop: failed to receive message due to socket error System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.IO.Stream.ReadByte()
   at System.IO.BinaryReader.ReadByte()
   at System.IO.BinaryReader.Read7BitEncodedInt()
   at System.IO.BinaryReader.ReadString()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.NotifyDataAvailable()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TcpClientExtensions.MessageLoopAsync(TcpClient client, ICommunicationChannel channel, Action`1 errorHandler, CancellationToken cancellationToken), remoteEndPoint: 127.0.0.1:50149 localEndPoint: 127.0.0.1:50148

@nohwnd @KirillOsenkov any updates on getting more diagnostics? We've wasted a couple of weeks pulling our hair out trying to understand what's going wrong here.

FYI @azchohfi @huynhsontung

[KirillOsenkov]

Have you tried the LocalDumps registry key to upload dumps from your CI?

[Daniellled]

I was wondering if you had any update on this issue? I am seeing a stack trace that looks just like the one @michael-hawker mentioned.

The active test run was aborted. Reason: Test host process crashed

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(Span1 buffer) --- End of inner exception stack trace --- at System.Net.Sockets.NetworkStream.Read(Span1 buffer)
at System.Net.Sockets.NetworkStream.ReadByte()
at System.IO.BinaryReader.Read7BitEncodedInt()
at System.IO.BinaryReader.ReadString()
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.NotifyDataAvailable()
at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TcpClientExtensions.MessageLoopAsync(TcpClient client, ICommunicationChannel channel, Action`1 errorHandler, CancellationToken cancellationToken)
--- End of inner exception stack trace ---.

This worked fine in .NET 5 VS 2019. In .NET 6 VS 2022 I am seeing this issue.

I was wondering if I can provide something to help diagnose this issue. Until this is fixed I will have to turn off my unit test.

[nohwnd]

@Daniellled do you have diag logs that you could share? Please. Add --diag:logs/log.txt to collect them, multiple files will be written into the logs folder. Please share all if you can.

[delmyers]

I think that I'm seeing the same thing when trying to use the blame collector in dotnet test. It is causing my CI to fail tests and not upload any of the results or the blame crashes. There is a simple repro:

1. Create a test project with a single test that just hangs for 10 seconds (use Thread.Sleep()) or something
2. Build the test
3. run dotnet test mytestproj.csproj --blame-hang --blame-hang-dump-type full --blame-hang-timeout 5s

See this output:

A total of 1 test files matched the specified pattern.
The active test run was aborted. Reason: Test host process crashed
Data collector 'Blame' message: The specified inactivity time of 5 seconds has elapsed. Collecting hang dumps from testhost and its child processes.
Data collector 'Blame' message: Dumping 21452 - testhost.

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:
IntegrationTest1.IntegrationTest1.Test1

This test may, or may not be the source of the crash.

Attachments:
  E:\dd\dmshiftleft\WebAppRazorPages\Tests\IntegrationTest1\TestResults\02aefd21-43ee-49db-9235-84cd19e3a678\Sequence_13b9bc7b5d554ea9bdfab637b375ce44.xml
  E:\dd\dmshiftleft\WebAppRazorPages\Tests\IntegrationTest1\TestResults\02aefd21-43ee-49db-9235-84cd19e3a678\testhost_21452_20211130T132430_hangdump.dmp
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()
   at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TcpClientExtensions.MessageLoopAsync(TcpClient client, ICommunicationChannel channel, Action`1 errorHandler, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---.

I think that if any collector is attempting to gather data at the end of the test run, then this timeout will be hit and none of the attachments will be uploaded.

[nohwnd]

Was this file not created at all? The error below just means that the testhost was killed (the dumper tool did that because it was hanging), but it is the data collector that is reponsible for waiting for the dump to end and passing the file as attachment to the vstest.console. It shows up on the screen so the file should be created successfully.

E:\dd\dmshiftleft\WebAppRazorPages\Tests\IntegrationTest1\TestResults\02aefd21-43ee-49db-9235-84cd19e3a678\testhost_21452_20211130T132430_hangdump.dmp

[delmyers]

Was this file not created at all? The error below just means that the testhost was killed (the dumper tool did that because it was hanging), but it is the data collector that is reponsible for waiting for the dump to end and passing the file as attachment to the vstest.console. It shows up on the screen so the file should be created successfully.

E:\dd\dmshiftleft\WebAppRazorPages\Tests\IntegrationTest1\TestResults\02aefd21-43ee-49db-9235-84cd19e3a678\testhost_21452_20211130T132430_hangdump.dmp

The file gets created, but it doesn't get copied into the correct location to be uploaded to artifacts in my pipelines. Normally trx files and their corresponding dumps would get uploaded to artifacts. I've had to resort to scanning the temp directory for test results and dumps when the blame collector captures hangs.