`System.OperationCanceledException` thrown with `VsTest` test runner @0.14.1

[pedrostc]

Describe the bug I'm getting a System.OperationCanceledException when running stryker on my project. Also tested with NetCoreTestProject.XUnit project from this repo and could observe the same behaviour.

Logs

Version: 0.14.1 (beta)

[10:02:14 DBG] Stryker started with options: {"BasePath":"C:\\src\\PrivateCodeCoverage\\PrivateCodeCoverage.Specs","SolutionPath":null,"OutputPath":"C:\\src\\PrivateCodeCoverage\\PrivateCodeCoverage.Specs\\StrykerOutput\\2019-11-27.10-02-14","Reporters":["Progress","ClearText"],"LogOptions":{"LogToFile":false,"OutputPath":"C:\\src\\PrivateCodeCoverage\\PrivateCodeCoverage.Specs\\StrykerOutput\\2019-11-27.10-02-14","LogLevel":"Debug"},"DevMode":false,"ProjectUnderTestNameFilter":null,"TestProjectNameFilter":"*.csproj","DiffEnabled":false,"GitSource":"master","AdditionalTimeoutMS":5000,"ExcludedMutations":[],"IgnoredMethods":[],"ConcurrentTestrunners":4,"Thresholds":{"High":80,"Low":60,"Break":0},"TestRunner":"VsTest","FilePatterns":[{"Glob":{"Tokens":[{"TrailingPathSeparator":{"Value":"\\"},"LeadingPathSeparator":null},{}]},"IsExclude":false,"TextSpans":[{"Start":0,"End":2147483647,"Length":2147483647,"IsEmpty":false}]}],"LanguageVersion":"Latest","Optimizations":"CoverageBasedTest, AbortTestOnKill","OptimizationMode":"perTest"}
[10:02:14 DBG] Using C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\PrivateCodeCoverage.Specs.csproj as project file
[10:02:14 DBG] Analyzing project file C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\PrivateCodeCoverage.Specs.csproj
[10:02:16 INF] The project C:\src\PrivateCodeCoverage\PrivateCodeCoverage\PrivateCodeCoverage.csproj will be mutated
[10:02:16 DBG] Analyzing project file C:\src\PrivateCodeCoverage\PrivateCodeCoverage\PrivateCodeCoverage.csproj
[10:02:18 DBG] Scanning C:\src\PrivateCodeCoverage\PrivateCodeCoverage
[10:02:18 INF] Started initial build using dotnet build
[10:02:21 DBG] Initial build output Microsoft (R) Build Engine version 16.3.0+0f4c62fea for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  Restore completed in 31.9 ms for C:\src\PrivateCodeCoverage\PrivateCodeCoverage\PrivateCodeCoverage.csproj.
  Restore completed in 34.31 ms for C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\PrivateCodeCoverage.Specs.csproj.
  PrivateCodeCoverage -> C:\src\PrivateCodeCoverage\PrivateCodeCoverage\bin\Debug\netcoreapp2.1\PrivateCodeCoverage.dll
  PrivateCodeCoverage.Specs -> C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\bin\Debug\netcoreapp2.1\PrivateCodeCoverage.Specs.dll

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

Time Elapsed 00:00:01.91

[10:02:21 INF] Initial build successful
[10:02:21 DBG] Factory is creating testrunner for asked type VsTest
[10:02:21 DBG] Runner 0: Logging vstest output to: C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\StrykerOutput\2019-11-27.10-02-14\logs\vstest-log.txt
[10:02:23 DBG] VsTest zip was copied to: C:\Users\pedro.oc\AppData\Local\Temp\2qpxre5f.f1k\.vstest\vstest.zip
[10:02:24 DBG] VsTest zip was unzipped to: C:\Users\pedro.oc\AppData\Local\Temp\2qpxre5f.f1k\.vstest
[10:02:24 DBG] Using vstest from deployed vstest package
[10:02:24 DBG] Using vstest.console: C:\Users\pedro.oc\AppData\Local\Temp\2qpxre5f.f1k\.vstest\tools\net451\vstest.console.exe for OS WINDOWS
[10:02:24 DBG] Runner 0: VsTest logging set to Verbose
[10:02:24 DBG] Runner 0: VsTest runsettings set to: <RunSettings>
 <RunConfiguration>
  <MaxCpuCount>4</MaxCpuCount>
  <TargetFrameworkVersion>.NETCoreApp,Version = vnetcoreapp2.1</TargetFrameworkVersion>

 </RunConfiguration>
</RunSettings>
[10:02:27 DBG] Runner 0: Logging vstest output to: C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\StrykerOutput\2019-11-27.10-02-14\logs\vstest-log.txt
[10:02:27 DBG] Runner 0: Logging vstest output to: C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\StrykerOutput\2019-11-27.10-02-14\logs\vstest-log.txt
[10:02:27 DBG] Runner 0: Logging vstest output to: C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\StrykerOutput\2019-11-27.10-02-14\logs\vstest-log.txt
[10:02:27 DBG] Runner 0: Logging vstest output to: C:\src\PrivateCodeCoverage\PrivateCodeCoverage.Specs\StrykerOutput\2019-11-27.10-02-14\logs\vstest-log.txt
[10:02:28 DBG] VsTest zip was copied to: C:\Users\pedro.oc\AppData\Local\Temp\uxjx34ct.x0r\.vstest\vstest.zip
[10:02:29 DBG] VsTest zip was unzipped to: C:\Users\pedro.oc\AppData\Local\Temp\uxjx34ct.x0r\.vstest
[10:02:29 DBG] Using vstest from deployed vstest package
[10:02:29 DBG] Using vstest.console: C:\Users\pedro.oc\AppData\Local\Temp\uxjx34ct.x0r\.vstest\tools\net451\vstest.console.exe for OS WINDOWS
[10:02:29 DBG] Runner 0: VsTest logging set to Verbose
[10:02:29 DBG] Runner 0: VsTest logging set to Verbose
[10:02:29 DBG] Runner 0: VsTest logging set to Verbose
[10:02:29 DBG] Runner 0: VsTest logging set to Verbose
[10:02:30 INF] Using testrunner VsTest
[10:02:30 INF] Total number of tests found: 6
[10:02:30 INF] Initial testrun started
[10:02:30 DBG] Runner 4: VsTest runsettings set to: <RunSettings>
 <RunConfiguration>
  <MaxCpuCount>4</MaxCpuCount>
  <TargetFrameworkVersion>.NETCoreApp,Version = vnetcoreapp2.1</TargetFrameworkVersion>

 </RunConfiguration>
</RunSettings>
[10:02:31 ERR] An error occurred during the mutation test run
System.OperationCanceledException: The operation was canceled.
   at Stryker.Core.TestRunners.VsTest.VsTestRunner.RunVsTest(IEnumerable`1 testCases, Nullable`1 timeoutMs, Dictionary`2 envVars) in d:\a\1\s\src\Stryker.Core\Stryker.Core\TestRunners\VsTest\VsTestRunner.cs:line 189
   at Stryker.Core.TestRunners.VsTest.VsTestRunner.RunAll(Nullable`1 timeoutMs, IReadOnlyMutant mutant) in d:\a\1\s\src\Stryker.Core\Stryker.Core\TestRunners\VsTest\VsTestRunner.cs:line 100
   at Stryker.Core.TestRunners.VsTest.VsTestRunnerPool.RunAll(Nullable`1 timeoutMs, IReadOnlyMutant mutant) in d:\a\1\s\src\Stryker.Core\Stryker.Core\TestRunners\VsTest\VsTestRunnerPool.cs:line 54
   at Stryker.Core.Initialisation.InitialTestProcess.InitialTest(ITestRunner testRunner) in d:\a\1\s\src\Stryker.Core\Stryker.Core\Initialisation\InitialTestProcess.cs:line 43
   at Stryker.Core.Initialisation.InitialisationProcess.InitialTest(StrykerOptions options, Int32& nbTests) in d:\a\1\s\src\Stryker.Core\Stryker.Core\Initialisation\InitialisationProcess.cs:line 63
   at Stryker.Core.StrykerRunner.RunMutationTest(StrykerOptions options, IEnumerable`1 initialLogMessages) in d:\a\1\s\src\Stryker.Core\Stryker.Core\StrykerRunner.cs:line 82
[10:02:31 INF] Time Elapsed 00:00:17.3768319

Expected behavior Stryker should be able to run the mutations.

Desktop (please complete the following information):

• OS: Windows 10 Enterprise 1903
• Type of project: Dotnet core 2.1 C# class library
• Framework Version: core 2.1
• Stryker Version: beta 0.14.1

Additional context My project is using xUnit as the test framework. Tested with the DotNetTest test runner on version 0.14.1 and it worked as expected. Tested with stryker version 0.14.0 and it works for both test runners (VsTest and DotNetTest) I tried to change my project`s Target Framework version to 3.0 and 2.2 but the same problem still happens. Project repo for reference: https://github.com/pedrostc/PrivateCodeCoverage

[sdcooper]

I have the same problem. Changing the test runner to dotnettest stops it crashing but the output is unexpected:

[15:25:58 INF] Started initial build using dotnet build [15:26:00 INF] Initial build successful [15:26:00 INF] Using testrunner DotnetTest [15:26:00 INF] Total number of tests found: Unable to detect [15:26:00 INF] Initial testrun started [15:26:20 INF] Using 40532 ms as testrun timeout [15:26:23 INF] 17 mutants got status CompileError. Reason: Could not compile [15:26:23 INF] 11 mutants got status Skipped. Reason: Removed by method filter [15:26:23 INF] 132 mutants ready for test [15:26:23 INF] Capture mutant coverage using 'perTest' mode. [15:26:34 INF] 11 mutants are not reached by any tests and will survive! (Marked as Survived). [15:26:34 INF] Coverage analysis eliminated 100.00% of tests (i.e. -132 tests out of -132).

But it did continue and created a report that looked correct.

[rouke-broersma]

Hey, thank you for the reports!

It is expected that a bug with VsTest would not be present with dotnet test. The output does appear to be wrong, it looks like the coverage analysis statistic might not expect the 'Unable to detect' total number of tests.

Does the problem occur in every testrun or only in some?

[rouke-broersma]

@pedrostc I tested the newly released 0.14.2 on your project and the issue has been resolved for me

[dupdob]

Thanks for the fix, it looks like some regression I introduced while fixing the AppdDomain issue. But this issue also demonstrates that some error handling/reporting could be improved in that area. I will open issue(s) for these.

[sdcooper]

Can confirm - thanks for the quick fix!

[rouke-broersma]

@dupdob Actually I'm fairly sure I introduced the regression when I moved the logic from the VsTestRunner to the ProjectInfo 👎

[pedrostc]

Hey just confirmed that everything is working just fine now. Thanks a lot for the quick response o/