VSTest task hanging on large test run across multiple test agents

[NDDeveloper13]

Required Information

Entering this information will route you directly to the right team and expedite traction.

Question, Bug, or Feature? bug

Enter Task Name: Visual Studio Test - v2

Environment

• Server - TFS on-premises 17.153.29522.3

• Agent - Private: Windows 10, Azure Pipeline Agent 2.164.7, Visual Studio Test Task 2.153.9, Microsoft TestPlatform 16.5.0

Issue Description

We have a test run that includes 133 test points that runs across 8 agents. It consistently has issues each time it runs. Multiple agents hang during the test run and are unable to complete tests. They continue to show as In Progress until they eventually abort or we kill them manually. I cannot find consistencies on any specific test agents that are causing the issue nor any specific test points. Sometimes it's just 1 agent that has the issue, sometimes up to 4 or more. In the screen shot below, 2 agents have the issue.

Task logs

I would prefer not to post the logs here. Please provide a way for me to send them to you directly.

Troubleshooting

Checkout how to troubleshoot failures and collect debug logs: https://docs.microsoft.com/en-us/vsts/build-release/actions/troubleshooting

Event Viewer Messages

In the Event Viewer on each machine, there are many of these errors with a Source of VSTTExecution: (testhost.x86.exe, PID 8828, Thread 11) HKEY_LOCAL_MACHINE\EnterpriseTools\QualityTools\TestTypes Key cannot be found!

One of them occurs within a few seconds of the error log provided below.

Error logs

I found the following logs for both test agents within one of the trace files (removed a large chunk of the JSON from one of the logs): TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.053, 60051849405, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:59582 localEndPoint: 127.0.0.1:59581 TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.068, 60051861243, vstest.console.exe, TestRequestSender.OnDiscoveryMessageReceived: Received message: {"Version":2,"MessageType":"TestDiscovery.Completed","Payload":{"TotalTests":139,"LastDiscoveredTests" .....................REMOVED LARGE AMOUNT OF INFORMATION HERE.......................{"VS.TestDiscovery.TimeTakenToLoadAdaptersInSec":0.0468704,"VS.TestDiscovery.AdaptersDiscoveredCount":4,"VS.TestDiscovery.TotalTestsDiscovered.executor://codedwebtestadapter/v1":0,"VS.TestDiscovery.TimeTakenAdapter.executor://codedwebtestadapter/v1":0.0625131,"VS.TestDiscovery.TotalTestsDiscovered.executor://mstestadapter/v1":139,"VS.TestDiscovery.TimeTakenAdapter.executor://mstestadapter/v1":0.48439859999999996,"VS.TestDiscovery.TotalTestsDiscovered.executor://nunit3testexecutor/":0,"VS.TestDiscovery.TimeTakenAdapter.executor://nunit3testexecutor/":0.2031082,"VS.TestDiscovery.TotalTestsDiscovered.executor://nunittestexecutor/":0,"VS.TestDiscovery.TimeTakenAdapter.executor://nunittestexecutor/":0.8281489,"VS.TestDiscovery.TimeTakenInSecByAllAdapters":1.5781687999999998,"VS.TestDiscovery.AdaptersUsedCount":4.0,"VS.TestDiscovery.DiscoveryState":"Completed","VS.TestDiscovery.TotalTests":139}}} TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.084, 60051913950, vstest.console.exe, TestRequestSender.EndSession: Sending end session. TpTrace Warning: 0 : 8392, 7, 2020/04/10, 05:36:02.131, 60052055076, vstest.console.exe, TestHostManagerCallbacks.ErrorReceivedCallback Test host standard error line: TpTrace Information: 0 : 8392, 5, 2020/04/10, 05:36:02.146, 60052078117, vstest.console.exe, TestHostManagerCallbacks.ExitCallBack: Testhost processId: 5864 exited with exitcode: 0 error: '' TpTrace Information: 0 : 8392, 5, 2020/04/10, 05:36:02.146, 60052079488, vstest.console.exe, TestRequestSender.OnClientProcessExit: Test host process exited. Standard error: TpTrace Information: 0 : 8392, 5, 2020/04/10, 05:36:02.146, 60052080150, vstest.console.exe, SocketServer.Stop: Stop server endPoint: 127.0.0.1:59581 TpTrace Information: 0 : 8392, 5, 2020/04/10, 05:36:02.146, 60052080397, vstest.console.exe, SocketServer.Stop: Cancellation requested. Stopping message loop. TpTrace Warning: 0 : 8392, 9, 2020/04/10, 05:36:02.146, 60052080642, vstest.console.exe, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process. TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052643106, vstest.console.exe, DiscoveryRequest.DiscoveryComplete: Starting. Aborted:False, TotalTests:139 TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052643681, vstest.console.exe, TestRequestSender.EndSession: Sending end session. TpTrace Error: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052666166, vstest.console.exe, 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: An existing connection was forcibly closed by the remote host at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags) 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.FlushWrite() at System.IO.BufferedStream.Flush() at System.IO.BinaryWriter.Flush() at Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.LengthPrefixCommunicationChannel.Send(String data). TpTrace Warning: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052669974, vstest.console.exe, 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: An existing connection was forcibly closed by the remote host at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags) 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.FlushWrite() 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 : 8392, 9, 2020/04/10, 05:36:02.365, 60052670306, vstest.console.exe, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process. TpTrace Warning: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052671033, vstest.console.exe, TestLoggerManager.HandleDiscoveredTests: Ignoring as the object is disposed. TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052671257, vstest.console.exe, TestLoggerManager.HandleDiscoveryComplete: Ignoring as the object is disposed. TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052671450, vstest.console.exe, DiscoveryRequest.DiscoveryComplete: Notified the discovery complete event. TpTrace Information: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052671694, vstest.console.exe, DiscoveryRequest.DiscoveryComplete: Completed. TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052672494, vstest.console.exe, TestRequestSender.SetOperationComplete: Setting operation complete. TpTrace Information: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052672872, vstest.console.exe, SocketServer.Stop: Stop server endPoint: 127.0.0.1:59581 TpTrace Information: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052673179, vstest.console.exe, SocketServer.Stop: Cancellation requested. Stopping message loop. TpTrace Verbose: 0 : 8392, 6, 2020/04/10, 05:36:02.365, 60052673310, vstest.console.exe, DiscoveryRequest.Dispose: Starting. TpTrace Information: 0 : 8392, 6, 2020/04/10, 05:36:02.365, 60052673839, vstest.console.exe, DiscoveryRequest.Dispose: Completed. TpTrace Information: 0 : 8392, 6, 2020/04/10, 05:36:02.365, 60052674089, vstest.console.exe, TestRequestManager.DiscoverTests: Discovery tests completed. TpTrace Information: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052674875, vstest.console.exe, SocketServer.PrivateStop: Stopp server endPoint: 127.0.0.1:59581 error: TpTrace Verbose: 0 : 8392, 9, 2020/04/10, 05:36:02.365, 60052675894, vstest.console.exe, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer. TpTrace Information: 0 : 8392, 1, 2020/04/10, 05:36:02.412, 60052800185, vstest.console.exe, DesignModeClient.ProcessRequests: Processing Message: (TestDiscovery.Cancel) -> null TpTrace Information: 0 : 8392, 1, 2020/04/10, 05:36:02.412, 60052801138, vstest.console.exe, TestRequestManager.CancelTestDiscovery: Sending cancel request. TpTrace Information: 0 : 8392, 1, 2020/04/10, 05:36:02.412, 60052802743, vstest.console.exe, DesignModeClient.ProcessRequests: Processing Message: (TestSession.Terminate) -> null TpTrace Information: 0 : 8392, 1, 2020/04/10, 05:36:02.412, 60052802991, vstest.console.exe, DesignModeClient: Session End message received from server. Closing the connection. TpTrace Verbose: 0 : 8392, 1, 2020/04/10, 05:36:02.412, 60052806133, vstest.console.exe, Executor.Execute: Exiting with exit code of 0 TpTrace Verbose: 0 : 428, 1, 2020/04/10, 05:36:02.803, 60053824194, vstest.console.exe, TestPluginCache.DiscoverTestExtensions: finding test extensions in assemblies endswith: RuntimeProvider.dll TPluginInfo: Microsoft.VisualStudio.TestPlatform.Common.ExtensionFramework.Utilities.TestRuntimePluginInformation TExtension: Microsoft.VisualStudio.TestPlatform.ObjectModel.Host.ITestRuntimeProvider TpTrace Verbose: 0 : 428, 1, 2020/04/10, 05:36:02.803, 60053833661, vstest.console.exe, TestPluginCache.GetExtensionPaths: Filtered extension paths: TpTrace Verbose: 0 : 428, 1, 2020/04/10, 05:36:02.803, 60053834095, vstest.console.exe, TestPluginCache.GetExtensionPaths: Added default extension paths: C:\agent_work_tool\VsTest\16.5.0\x64\tools\net451\Common7\IDE\Extensions\TestPlatform\Extensions\Microsoft.TestPlatform.Extensions.BlameDataCollector.dll

[ShreyasRmsft]

@NDDeveloper13 transferred the issue to the vstest repo because this seems like an issue with the testplatform rather than the task.

[NDDeveloper13]

What is the status of this one? This is affecting our regression in a big way. We haven't had a clean regression in months due to this issue. Do you need more information and log files?

[ManishJayaswal]

@pavelhorak @nohwnd - looks like this is a blocking issue for teams. Please take a look.

[nohwnd]

AB#1113915

[Sanan07]

@NDDeveloper13 Could you please provide more logs, which you mentioned in Task logs section, you can send it to my email which is in my profile. By first look, does not seem like a issue with Test Platform as this exception says : System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host and HKEY_LOCAL_MACHINE\EnterpriseTools\QualityTools\TestTypes - it is unable send data to testhost. You can try to reinstall agents for now.

[nohwnd]

@Sanan07 That connection error is mostly suggesting that testhost crashed, or was forcibly aborted so heartbeat request cannot be finished because the channel between the two processes was closed. That error usually does not suggest anything about the real cause.

[Sanan07]

@NDDeveloper13 Please also look at this solution provided by issue creator, maybe it or something close to that solution can help you : https://github.com/microsoft/vstest/issues/2490

[Sanan07]

@nohwnd reassigning to you, as you recently investigated it (in mail thread)