Aspnetcore: dotnet test keeps hanging

[livarcocc]

_From @dustinmoris on August 21, 2018 20:20_

Steps to reproduce

1. Go to https://github.com/giraffe-fsharp/Giraffe
2. Clone the repo and switch to the develop branch
3. Run .\build.ps1 (or just run dotnet test ./tests/Giraffe.Tests/Giraffe.Tests.fsproj -f netcoreapp2.1)

The build will succeed.

If you go to the Giraffe.Tests.fsproj file and change

<PackageReference Include="Microsoft.AspNetCore.TestHost" Version="2.0.*" />

to

<PackageReference Include="Microsoft.AspNetCore.TestHost" Version="2.1.*" />

and re-run the tests then you'll see that it will hang forever as if something went into a deadlock.

Previously I was using dotnet xunit which also didn't have problems, but since dotnet xunit has been discontinued I switched over to dotnet test which is giving me problems now.

Also this issue doesn't exist if I downgrade the test project to netcoreapp2.0.

Expected behavior

Tests will not deadlock with Microsoft.AspNetCore.TestHost version 2.1.*.

Actual behavior

Tests hang forever.

Environment data

dotnet --info output:

Dustins-MBP:giraffe dustinmoris$ dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.1.401
 Commit:    91b1c13032

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  10.13
 OS Platform: Darwin
 RID:         osx.10.13-x64
 Base Path:   /usr/local/share/dotnet/sdk/2.1.401/

Host (useful for support):
  Version: 2.1.3
  Commit:  124038c13e

.NET Core SDKs installed:
  2.0.0 [/usr/local/share/dotnet/sdk]
  2.0.3 [/usr/local/share/dotnet/sdk]
  2.1.3 [/usr/local/share/dotnet/sdk]
  2.1.4 [/usr/local/share/dotnet/sdk]
  2.1.300 [/usr/local/share/dotnet/sdk]
  2.1.301 [/usr/local/share/dotnet/sdk]
  2.1.302 [/usr/local/share/dotnet/sdk]
  2.1.400 [/usr/local/share/dotnet/sdk]
  2.1.401 [/usr/local/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.1 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.3 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.1 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.3 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.0.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.3 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.4 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.5 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.1 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.2 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.3 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download

_Copied from original issue: dotnet/cli#9874_

[livarcocc]

@natemcmaster do you know who owns Microsoft.AspNetCore.TestHost?

[livarcocc]

_From @natemcmaster on August 21, 2018 21:11_

That's my team. You can move this to aspnet/Home.

[natemcmaster]

@dustinmoris can share more logs? What do you see in console before the tests hang? Also, VSTest diagnostic logs may provide information about which process is stuck. Unlike dotnet xunit,dotnet testuses multiple processes to launch and run tests.dotnet test --diag mylog.txt`. If you take a look inside those logs, you'll be able to see which processes were created and which are hanging. This will help if we need you to gather a process dump.

[dustinmoris]

@natemcmaster:

Before the tests I just see the normal .NET Core output from building the project:

Dustins-MBP:giraffe dustinmoris$ dotnet build ./tests/Giraffe.Tests/Giraffe.Tests.fsproj
Microsoft (R) Build Engine version 15.8.166+gd4e8d81a88 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  Restoring packages for /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/Giraffe.Tests.fsproj...
  Restore completed in 32.02 ms for /Users/dustinmoris/GitHub/Giraffe/src/Giraffe/Giraffe.fsproj.
  Restore completed in 989.08 ms for /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/Giraffe.Tests.fsproj.
  Giraffe -> /Users/dustinmoris/GitHub/Giraffe/src/Giraffe/bin/Debug/netstandard2.0/Giraffe.dll
  Giraffe -> /Users/dustinmoris/GitHub/Giraffe/src/Giraffe/bin/Debug/net461/Giraffe.dll
  Giraffe.Tests -> /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/bin/Debug/net461/Giraffe.Tests.dll
  Giraffe.Tests -> /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/bin/Debug/netcoreapp2.1/Giraffe.Tests.dll

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:18.40
Dustins-MBP:giraffe dustinmoris$ dotnet test ./tests/Giraffe.Tests/Giraffe.Tests.fsproj -f netcoreapp2.1 --diag testlog.txt
Microsoft (R) Build Engine version 15.8.166+gd4e8d81a88 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  Restore completed in 41.46 ms for /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/Giraffe.Tests.fsproj.
  Restore completed in 41.44 ms for /Users/dustinmoris/GitHub/Giraffe/src/Giraffe/Giraffe.fsproj.
Build started, please wait...
Build completed.

Test run for /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/bin/Debug/netcoreapp2.1/Giraffe.Tests.dll(.NETCoreApp,Version=v2.1)
Microsoft (R) Test Execution Command Line Tool Version 15.8.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
Logging Vstest Diagnostics in file: /Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/testlog.txt
^C
Attempting to cancel the build...
Dustins-MBP:giraffe dustinmoris$ 

Because it hangs I had to cancel the build.

After running dotnet test with the --diag flag it actually created two log files:

testlog.host.18-08-24_23-22-45_88253_4.txt
testlog.txt

Seems like this is the point at which it starts hanging. After this line it just keeps saying Polling on remoteEndPoint:

"TestRunStatistics":{"ExecutedTests":59,"Stats":{"Passed":59}},"ActiveTests":[{"Id":"1c4254f9-7162-8077-35e3-3e0a4cbbd847","FullyQualifiedName":"Giraffe.Tests.HttpContextExtensionsTests.WriteHtmlFileAsync should return html from content folder","DisplayName":"Giraffe.Tests.HttpContextExtensionsTests.WriteHtmlFileAsync should return html from content folder","ExecutorUri":"executor://xunit/VsTestRunner2/netcoreapp","Source":"/Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/bin/Debug/netcoreapp2.1/Giraffe.Tests.dll","CodeFilePath":null,"LineNumber":0,"Properties":[]}]}}
TpTrace Verbose: 0 : 61463, 5, 2018/08/24, 23:22:48.749, 158168527666476, vstest.console.dll, TestRunRequest:SendTestRunStatsChange: Starting.
TpTrace Verbose: 0 : 61463, 5, 2018/08/24, 23:22:48.749, 158168527877462, vstest.console.dll, InProgress is Giraffe.Tests.HttpContextExtensionsTests.WriteHtmlFileAsync should return html from content folder
TpTrace Information: 0 : 61463, 5, 2018/08/24, 23:22:48.750, 158168528048414, vstest.console.dll, TestRunRequest:SendTestRunStatsChange: Completed.
TpTrace Verbose: 0 : 61463, 5, 2018/08/24, 23:22:48.750, 158168528196945, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:55624 localEndPoint: 127.0.0.1:55623
TpTrace Verbose: 0 : 61463, 5, 2018/08/24, 23:22:49.755, 158169533575644, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:55624 localEndPoint: 127.0.0.1:55623

Let me know if there's more information I can provide!

[natemcmaster]

Thanks for the test logs. As far as I can tell, this rules out issues in the test runner itself. There appears to be some kind of deadlock in the test code. Gathering a process dump is the next step for investigating this. When dotnet test runs, there will be several "dotnet.exe" processes. I recommend using Process Explorer to find the right dotnet.exe process for which to collect a full process dump. The dotnet.exe process which is hanging will have startup arguments like this:

dotnet.exe exec --runtimeconfig "/Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/bin/Debug/netcoreapp2.1/Giraffe.Tests.runtimeconfig.json" --depsfile "/Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/bin/Debug/netcoreapp2.1/Giraffe.Tests.deps.json" "/Users/dustinmoris/.nuget/packages/microsoft.testplatform.testhost/15.8.0/lib/netstandard1.5/testhost.dll" --port 55623 --endpoint 127.0.0.1:055623 --role client --parentprocessid 61463 --diag "/Users/dustinmoris/GitHub/Giraffe/tests/Giraffe.Tests/testlog.host.18-08-24_23-22-45_88253_4.txt" --telemetryoptedin false

Once you have a process dump, we can look at where the threads are stuck. You should be able to open .dmp files in Visual Studio.

[muratg]

This issue was moved to aspnet/Hosting#1537

[dmitry-pavlov]

Sometimes xUnit tests hang forever because the test runner pipeline can't handle parallel threads. To check if that's the issue try adding xunit.runner.json file to the tests project root

  <ItemGroup>
    <None Update="xunit.runner.json">
      <CopyToOutputDirectory>Always</CopyToOutputDirectory>
    </None>
  </ItemGroup>

And put inside 1 thread config.

{
  "parallelizeTestCollections": true,
  "maxParallelThreads": -1
}

[daniel-white]

this seems to be happening more with the newer sdk and xunit

NET Core SDK (reflecting any global.json):
 Version:   2.1.700
 Commit:    c2ef055a0f

Runtime Environment:
 OS Name:     Mac OS X
 OS Version:  10.14
 OS Platform: Darwin
 RID:         osx.10.14-x64
 Base Path:   /usr/local/share/dotnet/sdk/2.1.700/

Host (useful for support):
  Version: 2.1.11
  Commit:  d6a5616240

.NET Core SDKs installed:
  2.1.302 [/usr/local/share/dotnet/sdk]
  2.1.503 [/usr/local/share/dotnet/sdk]
  2.1.505 [/usr/local/share/dotnet/sdk]
  2.1.700 [/usr/local/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.7 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.9 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.11 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.7 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.9 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.11 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.2 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.7 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.9 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.11 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

@dmitry-pavlov's solution worked for me.