dotnet test sometimes hangs in a VM

[samuper]

We have a test written in the NUnit framework, which we start the following way:

dotnet test some_path/test.dll --filter 'TestCategory!=SomeCategory' -- 'TestRunParameters.Parameter(name="ProjectName", value="some_project_name")'

We use .NET SDK version 6.0.303.

Sometimes (cca once in 3 times) it hangs forever, but only on a virtual machine (on Windows and also on Debian), never on a native machine. When it hangs, we have the following in "log.txt":

TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:00.462, 877522506550121, vstest.console.dll, TestRunRequest:SendTestRunStatsChange: Starting.
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:00.462, 877522506618715, vstest.console.dll, InProgress is NodeOperations01
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:00.470, 877522514806546, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.RunStatsChanged: Invoking callbacks was skipped because there are no subscribers.
TpTrace Information: 0 : 1148293, 7, 2022/09/05, 17:10:00.470, 877522514873025, vstest.console.dll, TestRunRequest:SendTestRunStatsChange: Completed.
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:00.470, 877522514913909, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 18 ms.
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:00.470, 877522514934409, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:35402 localEndPoint: 127.0.0.1:41853
TpTrace Verbose: 0 : 1148293, 4, 2022/09/05, 17:10:00.496, 877522541438205, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestResult: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_2, took 34 ms.
TpTrace Verbose: 0 : 1148293, 4, 2022/09/05, 17:10:00.506, 877522551094771, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestResult: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestResultHandler, took 9 ms.
TpTrace Verbose: 0 : 1148293, 4, 2022/09/05, 17:10:00.506, 877522551332472, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestResult: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_2, took 0 ms.
TpTrace Verbose: 0 : 1148293, 4, 2022/09/05, 17:10:00.506, 877522551407626, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestResult: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestResultHandler, took 0 ms.
TpTrace Verbose: 0 : 1148293, 4, 2022/09/05, 17:10:00.506, 877522551460481, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestResult: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_2, took 0 ms.
TpTrace Verbose: 0 : 1148293, 4, 2022/09/05, 17:10:00.506, 877522551511680, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestResult: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestResultHandler, took 0 ms.
< ... and the last 2 lines appear again 6 more times ... >
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:01.471, 877523515994447, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:35402 localEndPoint: 127.0.0.1:41853
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:02.472, 877524516585138, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:35402 localEndPoint: 127.0.0.1:41853
TpTrace Verbose: 0 : 1148293, 7, 2022/09/05, 17:10:03.473, 877525517749870, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:35402 localEndPoint: 127.0.0.1:41853
< ... and the last line appears again every second ... >

In "log.host.<timestamp>.txt" we have:

TpTrace Verbose: 0 : 1148365, 7, 2022/09/05, 17:10:01.020, 877523065245413, testhost.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: [::ffff:127.0.0.1]:41853 localEndPoint: [::ffff:127.0.0.1]:35402
TpTrace Verbose: 0 : 1148365, 7, 2022/09/05, 17:10:02.021, 877524066239418, testhost.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: [::ffff:127.0.0.1]:41853 localEndPoint: [::ffff:127.0.0.1]:35402
TpTrace Verbose: 0 : 1148365, 7, 2022/09/05, 17:10:03.022, 877525067384380, testhost.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: [::ffff:127.0.0.1]:41853 localEndPoint: [::ffff:127.0.0.1]:35402
< ... and the last line appears again every second ... >

It looks like the test and test host lose the connection, for whatever reason. I've checked the connections with netstat ("VRA-TST-W-002" is the hostname of localhost), but that looks fine:

  TCP    127.0.0.1:41853        VRA-TST-W-002:35402    ESTABLISHED
 [dotnet.exe]
  TCP    127.0.0.1:35402        VRA-TST-W-002:41853    ESTABLISHED
 [testhost.exe]

I also generated a dump file, and when I open it in Visual Studio and try to Debug it with Native Only, I get the message: "Your app has entered a break state, but there is no code to show because all threads were executing external code (typically system or framework code).", from which I judge that the bug is probably not in our test code.

[timcassell]

Perhaps #9452?

[samuper]

After some further investigation, we concluded the bug is in our code.

Because others might also get into this trouble and find this thread, let me also link here some references:

• https://blog.stephencleary.com/2012/07/dont-block-on-async-code.html.
• https://docs.microsoft.com/en-us/archive/msdn-magazine/2013/march/async-await-best-practices-in-asynchronous-programming#configure-context

You can close this issue.