vstest.console indefinite TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint

Created on 5 Jul 2018 · 5Comments · Source: microsoft/vstest

Description

IMPORTANT: if the defect is reproduced only in a workflow from within the Visual Studio IDE then do not report the issue here - instead, please report it using Visual Studio's "Send Feedback" option that can be accessed from the Help menu OR using this link https://developercommunity.visualstudio.com.

For a defect reproducable from the vstest command line, describe the issue you've observed.

I am trying to run a .Net Core 2.0 integration test suite I have written. It connects to a SQL database via configuration and runs a series of commands. When running the tests locally via vstest.console.exe, the tests run successfully. When they are run from the build server (Win2012 with VS Ent 2017 15.7.4 installed, either via the VSTest task or manually via vstest.console.exe), the tests do not finish. The first test runs and then the logs reflect Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584 indefinitely.

Steps to reproduce

What steps can reproduce the defect?
Please share the setup, commandline for vstest.console, sample project, target
framework etc.

I have a VSTS build with a locally-installed build agent on the server that created the build and placed it on the server. When running via VSTS task or via the command line, the situation is reproduced. The command run is:
C:\Windows\system32>"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe" "C:\VSTS_work\r3\a(redacted).Tests.Integration.dll" /logger:"trx";LogFileName="c:\test\log.trx" /Framework:".NETCoreApp,Version=v2.0" --diag:c:\test\testoutput.txt /Blame
When run on the local workstation, the tests finish successfully in about three seconds. I have tried setting vstest.console.exe to run as local administrator, running the command from an administrative command prompt, and it will not run. I copied the directory to my local workstation and it ran successfully.

Expected behavior

Share the expected output
Expected output is this:
C:Users\davidg>"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe" "
Tests.Integration.dll" /logger:"trx";LogFileName="c:\test\log.trx" /Framework:".NETCoreApp,Version=v2.0" --diag:c:\test\testoutput.txt /Blame
Microsoft (R) Test Execution Command Line Tool Version 15.7.2
Copyright (c) Microsoft Corporation. All rights reserved.

Starting test execution, please wait...
Logging Vstest Diagnostics in file: c:\test\testoutput.txt
Data collection : Logging DataCollector Diagnostics in file: c:\test\testoutput.datacollector.18-07-05_15-26-10_03800_5.txt
[xUnit.net 00:00:00.8955332] Discovering:

[xUnit.net 00:00:01.0468070] Discovered:

[xUnit.net 00:00:01.0548524] Starting:

Passed

[xUnit.net 00:00:01.8435416] Finished:

Passed

WARNING: Overwriting results file: c:\test\log.trx
Results File: c:\test\log.trx

Total tests: 13. Passed: 13. Failed: 0. Skipped: 0.
Test Run Successful.
Test execution time: 2.8257 Seconds

Actual behavior

What is the behavior observed?
The tests are started, but hangs indefinitely until killed with Ctrl+C.

C:\Windows\system32>"C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe" "C:\VSTS_work\r3\a\
Tests.Integration.dll" /logger:"trx";LogFileName="c:\test\log.trx" /Framework:".NETCoreApp,Version=v2.0" --diag:c:\test\testoutput.txt /Blame
Microsoft (R) Test Execution Command Line Tool Version 15.7.2
Copyright (c) Microsoft Corporation. All rights reserved.

Starting test execution, please wait...
Logging Vstest Diagnostics in file: c:\test\testoutput.txt
[xUnit.net 00:00:00.9199706] Discovering:

[xUnit.net 00:00:01.1464786] Discovered:

[xUnit.net 00:00:01.1572183] Starting:

Diagnostic logs

Please share test platform diagnostics logs. Instructions to collect logs are here.
The logs may contain test assembly paths, kindly review and mask those before sharing.

TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.283, 320093028696, vstest.console.exe, Using .Net Framework version:.NETCoreApp,Version=v2.0
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.353, 320093981244, vstest.console.exe, TestPluginCache: Discovering the extensions using extension path.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.537, 320096622171, vstest.console.exe, TestPluginCache: Discovered the extensions using extension path ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.539, 320096645095, vstest.console.exe, TestPluginCache: Discoverers are ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.539, 320096646671, vstest.console.exe, TestPluginCache: Executors are ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.539, 320096647889, vstest.console.exe, TestPluginCache: Setting providers are ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.539, 320096649061, vstest.console.exe, TestPluginCache: Loggers are ''.
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.556, 320096891540, vstest.console.exe, RunTestsArgumentProcessor:Execute: Test run is starting.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.556, 320096894062, vstest.console.exe, RunTestsArgumentProcessor:Execute: Queuing Test run.
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.559, 320096934044, vstest.console.exe, TestRequestManager.RunTests: run tests started.
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.658, 320098349895, vstest.console.exe, AssemblyMetadataProvider.GetFrameWork: Determined framework:'.NETCoreApp,Version=v2.0' for source: 'C:\VSTS_work\r3\a(redacted)Internal.Tests.Integration.dll'
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.658, 320098353477, vstest.console.exe, Determined framework for all sources: .NETCoreApp,Version=v2.0
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.661, 320098395593, vstest.console.exe, AssemblyMetadataProvider.GetArchitecture: Determined architecture:AnyCPU info for assembly: C:\VSTS_work\r3\a(redacted)Tests.Integration.dll
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.663, 320098425184, vstest.console.exe, Determined platform for all sources: X86
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.668, 320098494721, vstest.console.exe, Compatible sources list :
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.668, 320098496761, vstest.console.exe, C:\VSTS_work\r3\a(redacted)ntegration.dll
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.673, 320098563348, vstest.console.exe, InferRunSettingsHelper.IsTestSettingsEnabled: Unable to navigate to RunSettings/MSTest. Current node: RunSettings
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.705, 320099028997, vstest.console.exe, TestPluginCache: Discovering the extensions using extension path.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.708, 320099064449, vstest.console.exe, TestPluginCache: Discovered the extensions using extension path ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.708, 320099066419, vstest.console.exe, TestPluginCache: Discoverers are ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.708, 320099067716, vstest.console.exe, TestPluginCache: Executors are ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.708, 320099068955, vstest.console.exe, TestPluginCache: Setting providers are ''.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.708, 320099070521, vstest.console.exe, TestPluginCache: Loggers are 'logger://Microsoft/TestPlatform/Extensions/Blame/v1,logger://Microsoft/TestPlatform/TrxLogger/v1'.
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.712, 320099130461, vstest.console.exe, TestPluginManager.CreateTestExtension: Attempting to load test extension: Microsoft.VisualStudio.TestPlatform.Extensions.TrxLogger.TrxLogger
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.717, 320099201133, vstest.console.exe, TestPluginManager.CreateTestExtension: Attempting to load test extension: Microsoft.TestPlatform.Extensions.BlameDataCollector.BlameLogger
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.721, 320099261166, vstest.console.exe, TestPluginManager.CreateTestExtension: Attempting to load test extension: Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Hosting.DefaultTestHostManager
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.722, 320099272150, vstest.console.exe, TestPluginManager.CreateTestExtension: Attempting to load test extension: Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Hosting.DotnetTestHostManager
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.726, 320099328791, vstest.console.exe, TestEngine: Initializing Parallel Execution as MaxCpuCount is set to: 1
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:25.728, 320099357595, vstest.console.exe, InferRunSettingsHelper.IsTestSettingsEnabled: Unable to navigate to RunSettings/MSTest. Current node: RunSettings
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:25.739, 320099514859, vstest.console.exe, TestRequestSender is acting as server
TpTrace Verbose: 0 : 6104, 5, 2018/07/05, 15:26:25.752, 320099695135, vstest.console.exe, DataCollectionRequestSender.InitializeCommunication : Initialize communication.
TpTrace Information: 0 : 6104, 5, 2018/07/05, 15:26:25.755, 320099739614, vstest.console.exe, Listening on Endpoint : 127.0.0.1:50581
TpTrace Information: 0 : 6104, 5, 2018/07/05, 15:26:25.766, 320099903652, vstest.console.exe, ProxyDataCollectionManager.Initialize: Launched datacollector processId: 4852 port: 50581
TpTrace Information: 0 : 6104, 5, 2018/07/05, 15:26:25.767, 320099913557, vstest.console.exe, ProxyDataCollectionManager.Initialize: waiting for connection with timeout: 30000
TpTrace Verbose: 0 : 6104, 5, 2018/07/05, 15:26:25.767, 320099917373, vstest.console.exe, DataCollectionRequestSender.WaitForRequestHandlerConnection : Waiting for connection with timeout: 30000
TpTrace Verbose: 0 : 6104, 5, 2018/07/05, 15:26:25.894, 320101729118, vstest.console.exe, ProxyDataCollectionManager.InvokeDataCollectionServiceAction: Starting.
TpTrace Information: 0 : 6104, 5, 2018/07/05, 15:26:25.894, 320101738905, vstest.console.exe, ProxyDataCollectionManager.BeforeTestRunStart: Get env variable and port for datacollector processId: 4852 port: 50581
TpTrace Verbose: 0 : 6104, 5, 2018/07/05, 15:26:25.895, 320101749818, vstest.console.exe, DataCollectionRequestSender.SendBeforeTestRunStartAndGetResult : Send BeforeTestRunStart message with settingsXml: C:\Windows\system32\TestResultsX86.NETCoreApp,Version=v2.0FalseFalseC:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\Common7\IDE\Extensions\TestPlatform\Extensionsc:\test\log.trxC:\Windows\system32\TestResults
TpTrace Information: 0 : 6104, 6, 2018/07/05, 15:26:25.912, 320101995639, vstest.console.exe, Using the buffer size of 16384 bytes
TpTrace Information: 0 : 6104, 6, 2018/07/05, 15:26:25.912, 320101998136, vstest.console.exe, Accepted Client request and set the flag
TpTrace Verbose: 0 : 6104, 5, 2018/07/05, 15:26:26.230, 320106547985, vstest.console.exe, DataCollectionRequestSender.SendBeforeTestRunStartAndGetResult : Received message: (DataCollection.BeforeTestRunStartResult) -> {
"EnvironmentVariables": {},
"DataCollectionEventsPort": 50583
}
TpTrace Information: 0 : 6104, 5, 2018/07/05, 15:26:26.236, 320106628458, vstest.console.exe, ProxyDataCollectionManager.BeforeTestRunStart: SendBeforeTestRunStartAndGetResult successful, env variable from datacollector: and testhost port: 50583
TpTrace Information: 0 : 6104, 5, 2018/07/05, 15:26:26.236, 320106630071, vstest.console.exe, ProxyDataCollectionManager.InvokeDataCollectionServiceAction: Completed.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:26.237, 320106639430, vstest.console.exe, TestRunRequest.ExecuteAsync: Creating test run request.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:26.239, 320106679477, vstest.console.exe, TestRunRequest.ExecuteAsync: Starting.
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:26.240, 320106691738, vstest.console.exe, TestRunRequest.ExecuteAsync: Starting run with settings:TestRunCriteria:
KeepAlive=False,FrequencyOfRunStatsChangeEvent=10,RunStatsChangeEventTimeout=00:00:01.5000000,TestCaseFilter=,TestExecutorLauncher=
Settingsxml=

C:\Windows\system32\TestResults
X86
.NETCoreApp,Version=v2.0
False
False

c:\test\log.trx

C:\Windows\system32\TestResults

TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:26.240, 320106693735, vstest.console.exe, TestRunRequest.ExecuteAsync: Wait for the first run request is over.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:26.243, 320106735948, vstest.console.exe, ParallelProxyExecutionManager: Start execution. Total sources: 1
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:26.247, 320106782423, vstest.console.exe, ProxyParallelExecutionManager: Triggering test run for next source: C:\VSTS_work\r3\a(redacted)Internal.Tests.Integration.dll
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:26.247, 320106793919, vstest.console.exe, ProxyParallelExecutionManager: No sources available for execution.
TpTrace Information: 0 : 6104, 1, 2018/07/05, 15:26:26.248, 320106795790, vstest.console.exe, TestRunRequest.ExecuteAsync: Started.
TpTrace Verbose: 0 : 6104, 1, 2018/07/05, 15:26:26.248, 320106801862, vstest.console.exe, TestRunRequest.WaitForCompletion: Waiting with timeout -1.
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.765, 320114206297, vstest.console.exe, ParallelProxyExecutionManager: Execution started. Started clients: 1
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.773, 320114317437, vstest.console.exe, ProxyExecutionManager: Test host is always Lazy initialize.
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.778, 320114386906, vstest.console.exe, TestRequestSender.InitializeCommunication: initialize communication.
TpTrace Information: 0 : 6104, 8, 2018/07/05, 15:26:26.780, 320114419510, vstest.console.exe, SocketServer.Start: Listening on endpoint : 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.785, 320114498651, vstest.console.exe, DotnetTestHostmanager: Full path of dotnet.exe is C:\Program Files\dotnet\dotnet.exe
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.786, 320114503627, vstest.console.exe, DotnetTestHostmanager: Adding --runtimeconfig "C:\VSTS_work\r3\a(redacted)Tests.Integration.runtimeconfig.json" in args
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.786, 320114507272, vstest.console.exe, DotnetTestHostmanager: Adding --depsfile "C:\VSTS_work\r3\a(redacted)Integration.deps.json" in args
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.793, 320114603312, vstest.console.exe, DotnetTestHostManager: Assume published test project, with test host path = C:\VSTS_work\r3\a(redacted)Integration\testhost.dll.
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:26.793, 320114607108, vstest.console.exe, DotnetTestHostmanager: Full path of testhost.dll is C:\VSTS_work\r3\a(redacted)Integration\testhost.dll
TpTrace Verbose: 0 : 6104, 9, 2018/07/05, 15:26:27.766, 320128541179, vstest.console.exe, DotnetTestHostManager: Starting process 'C:\Program Files\dotnet\dotnet.exe' with command line 'exec --runtimeconfig "C:\VSTS_work\r3\a(redacted)Integration.runtimeconfig.json" --depsfile "C:\VSTS_work\r3(redacted)Integration\testhost.dll" --port 50584 --endpoint 127.0.0.1:050584 --role client --parentprocessid 6104 --diag "c:\test\testoutput.host.18-07-05_15-26-26_78190_8.txt" --datacollectionport 50583 --telemetryoptedin false'
TpTrace Verbose: 0 : 6104, 9, 2018/07/05, 15:26:27.773, 320128632332, vstest.console.exe, Test Runtime launched
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:27.788, 320128851292, vstest.console.exe, TestRequestSender.WaitForRequestHandlerConnection: waiting for connection with timeout: 60000
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:28.776, 320142992584, vstest.console.exe, TestRequestSender.InitializeExecution: Sending initializing execution with message: {"MessageType":"TestExecution.Initialize","Payload":["C:\VSTS\_work\r3\a\(redacted).Tests.Integration\xunit.runner.visualstudio.dotnetcore.testadapter.dll"]}
TpTrace Verbose: 0 : 6104, 8, 2018/07/05, 15:26:28.828, 320143727256, vstest.console.exe, TestRequestSender.StartTestRun: Sending test run with message: {"MessageType":"TestExecution.StartWithSources","Payload":{"AdapterSourceMap":{"_none_":["C:\VSTS\_work\r3\(redacted).Tests.Integration.dll"]},"RunSettings":"\r\n \r\n C:\Windows\system32\TestResults\r\n X86\r\n .NETCoreApp,Version=v2.0\r\n False\r\n False\r\n \r\n \r\n \r\n \r\n \r\n c:\test\log.trx\r\n \r\n \r\n \r\n \r\n \r\n \r\n \r\n \r\n \r\n \r\n C:\Windows\system32\TestResults\r\n \r\n \r\n \r\n \r\n","TestExecutionContext":{"FrequencyOfRunStatsChangeEvent":10,"RunStatsChangeEventTimeout":"00:00:01.5000000","InIsolation":false,"KeepAlive":false,"AreTestCaseLevelEventsRequired":false,"IsDebug":false,"TestCaseFilter":null,"FilterOptions":null},"Package":null}}
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:28.861, 320144197780, vstest.console.exe, SocketServer.OnClientConnected: Client connected for endPoint: 127.0.0.1:50584, starting MessageLoopAsync:
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:28.863, 320144233212, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:29.863, 320158545226, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.479, 320167369538, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.481, 320167395790, vstest.console.exe, TestRequestSender.OnExecutionMessageReceived: Received message: {"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:00.9199706] Discovering: (redacted).Tests.Integration"}}
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.485, 320167452585, vstest.console.exe, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Information: 0 : 6104, 11, 2018/07/05, 15:26:30.485, 320167463205, vstest.console.exe, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.485, 320167464821, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.661, 320169978270, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.661, 320169982328, vstest.console.exe, TestRequestSender.OnExecutionMessageReceived: Received message: {"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:01.1464786] Discovered: (redacted).Tests.Integration"}}
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.662, 320169986841, vstest.console.exe, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Information: 0 : 6104, 11, 2018/07/05, 15:26:30.662, 320169989355, vstest.console.exe, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.662, 320169990751, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.671, 320170127342, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.672, 320170130387, vstest.console.exe, TestRequestSender.OnExecutionMessageReceived: Received message: {"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:01.1572183] Starting: (redacted).Tests.Integration"}}
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.672, 320170133273, vstest.console.exe, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Information: 0 : 6104, 11, 2018/07/05, 15:26:30.672, 320170134953, vstest.console.exe, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:30.672, 320170136321, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:31.009, 320174963744, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:31.010, 320174968556, vstest.console.exe, TestRequestSender.OnExecutionMessageReceived: Received message: {"MessageType":"TestExecution.StatsChange","Payload":{"NewTestResults":[],"TestRunStatistics":{"ExecutedTests":0,"Stats":{}},"ActiveTests":[{"Properties":[{"Key":{"Id":"TestCase.FullyQualifiedName","Label":"FullyQualifiedName","Category":"","Description":"","Attributes":1,"ValueType":"System.String"},"Value":"(redacted).Tests.Integration.ServiceTicketQueryDbTests.GetServiceTicketEntries_GivenNoEntriesForTicketNumber_NoTicketEntriesReturned"},{"Key":{"Id":"TestCase.ExecutorUri","Label":"Executor Uri","Category":"","Description":"","Attributes":1,"ValueType":"System.Uri"},"Value":"executor://xunit/VsTestRunner2/netcoreapp"},{"Key":{"Id":"TestCase.Source","Label":"Source","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"C:\VSTS\_work\r3\a\API-Internal\API-Internal\(redacted).Tests.Integration\(redacted).Tests.Integration.dll"},{"Key":{"Id":"TestCase.CodeFilePath","Label":"File Path","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":null},{"Key":{"Id":"TestCase.DisplayName","Label":"Name","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"(redacted).Tests.Integration.ServiceTicketQueryDbTests.GetServiceTicketEntries_GivenNoEntriesForTicketNumber_NoTicketEntriesReturned(expectedSrvcTcktId: 900000)"},{"Key":{"Id":"TestCase.Id","Label":"Id","Category":"","Description":"","Attributes":1,"ValueType":"System.Guid"},"Value":"2113f7c8-2de0-500f-f8bf-99b3811c9153"},{"Key":{"Id":"TestCase.LineNumber","Label":"Line Number","Category":"","Description":"","Attributes":1,"ValueType":"System.Int32"},"Value":-1},{"Key":{"Id":"TestObject.Traits","Label":"Traits","Category":"","Description":"","Attributes":5,"ValueType":"System.Collections.Generic.KeyValuePair`2[[System.String],[System.String]][]"},"Value":[{"Key":"Type","Value":"Integration"},{"Key":"Category","Value":"Method"},{"Key":"Path","Value":"Negative"}]}]}]}}
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:31.056, 320175637772, vstest.console.exe, TestRunRequest:SendTestRunStatsChange: Starting.
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:31.057, 320175641769, vstest.console.exe, InProgress is (redacted)Integration.ServiceTicketQueryDbTests.GetServiceTicketEntries_GivenNoEntriesForTicketNumber_NoTicketEntriesReturned(expectedSrvcTcktId: 900000)
TpTrace Information: 0 : 6104, 11, 2018/07/05, 15:26:31.057, 320175651651, vstest.console.exe, TestRunRequest:SendTestRunStatsChange: Completed.
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:31.057, 320175654041, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:32.058, 320189976984, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:33.058, 320204295030, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:34.058, 320218616958, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:35.059, 320232946861, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:36.059, 320247266178, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:37.059, 320261584985, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:38.059, 320275903980, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:39.059, 320290226176, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:40.060, 320304557475, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:41.061, 320318889509, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:42.062, 320333212227, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:43.062, 320347541861, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584
TpTrace Verbose: 0 : 6104, 11, 2018/07/05, 15:26:44.063, 320361860738, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:50585 localEndPoint: 127.0.0.1:50584

Environment

Please share additional details about the test environment.
Operating system, Build version of vstest.console

Working on Win10 with Visual Studio Enterprise 15.7.3, running as local administrator
Not working on Win2012 server with Visual Studio Enterprise 15.7.4 installed, running as local administrator

need-additional-info need-repro question

Source

GreenDavidA

👍3

Most helpful comment

Actually, I determined the cause of the issue. These were integration tests going against a database, and two tests were running in parallel causing a deadlock. I decorated the assembly to disable parallelism and this resolved the issue. Thanks!

GreenDavidA on 26 Jul 2018

👍2

All 5 comments

It's worth noting that when running SQL trace, the commands for the first test are sent to the SQL server, but no further commands are sent.

GreenDavidA on 5 Jul 2018

i have the same hanging issue, using VS2017 with parallelize enable

oscarcabrero on 10 Jul 2018

@GreenDavidA
Can you please share complete vstest.console logs and testhost logs to debug into this issue further?
Also can you share a sample repro project where issue is reproducing?

abhishkk on 18 Jul 2018

@GreenDavidA can you please provide the logs requested above.

From the logs above it seems that the testhost process is in a hang state, could be because of test issue as well, can you enable /blame data collector, to check which test is stuck on your agent machine.
Also if possible capture the full dumps for testhost process, when it gets stuck