Vstest hangs after "Cancelling the operation as requested." message

[richardwerkman]

Description

Note This** is a follow up issue for #2578. Lowering the timeout does not fix our issue. Stryker keeps crashing thanks to the error coming out of vstest.

Original issue:
When working on Stryker mutator I noticed vstest is reporting some sort of error when running a session with two assemblies. At some point in stryker we know all mutations have been tested and we can abort/cancel the testrun. This goes right most of the times. Some times however a error with the message Cancelling the operation as requested. comes from vstest. After that the session seems to have crashed. No clear exception is thrown and it's not clear how to handle the error.

This might be a bug in vstest.

Steps to reproduce

The error occurs when running stryker against two test projects.
1.
a. Clone Stryker-net
b. Rename dir to stryker-net-main
c. Checkout branch 1136_multi_test_project_bug
2.
a. Clone Stryker-net
b. Checkout branch multi_test_project_example
3. Open stryker-net-main (Solution Stryker.CLI.sln)
3. Run project Stryker.CLI in that solution with the following settings (Project Stryker.CLI -> Properties -> Debug)
Working directory: {path where you cloned}\stryker-net\src\Stryker.Core\Stryker.Core
Application arguments: -f
4. Set a breakpoint on this line in the clone from step 1
5. Run clone 1 with the settings as in step 3. The breakpoint should go off in a few minutes.

windows example for step 1&2:

git clone https://github.com/stryker-mutator/stryker-net.git
ren stryker-net stryker-net-main
cd ./stryker-net-main
git checkout 1136_multi_test_project_bug
cd ..
git clone https://github.com/stryker-mutator/stryker-net.git
cd ./stryker-net
git checkout multi_test_project_example

Expected behavior

I expect a clear error to occur or no error at all.

Actual behavior

Vstest sends a error message that we are unable to handle. If I throw an Exception (like in the reproduction code) vstest swallows the exception and doesn't let our own code handle it. I see no other way to detect the crashing of the testsession other than the message.

It would be great if someone could explain to me what the message means and why the vstest session crashes.

Diagnostic logs

As stryker runs a lot of testruns and testsessions it's not very helpful to send all the logs. Stryker puts them on file when the steps to reproduce are followed.

Environment

I ran on Windows 10 with vstest nuget package version 16.7.1.

Own research

I think the error originates from this file: https://github.com/microsoft/vstest/blob/a319f62bfd966d584b3a19e20bad55288436cc97/src/Microsoft.TestPlatform.Common/Utilities/CancellationTokenExtensions.cs

AB#1280844

[Sanan07]

@richardwerkman I remember this issue from you. Could you please run it with using diagnostic logs and send to us with case when you see that message "Cancelling the operation as requested". I think you can do it faster than us it would be nice to have and analyze again.

[richardwerkman]

VsTest-log.txt

This is the vstest logs until the moment that we get the error. Scroll all the way down to see what happened right before the error 👍

If you need anything else please let me know! I really hope this issue can be fixed as it is a real struggle for us at stryker.

[richardwerkman]

@Sanan07 any progress yet?

[Sanan07]

@richardwerkman Unfortunately, not big progress yet. I will try to start looking at this.

[richardwerkman]

@Sanan07 Did you have time to look into this yet?

[Sanan07]

@richardwerkman Sorry for late, have other priority tasks to complete. Will mark as current work to look at.
Will come to you next week.
Could you also provide testhost logs, which you can get form diagnostic logs (I mentioned earlier in comments). Log you provided is vstest.console logs.
Thank you.

[richardwerkman]

Sorry this took a while. Here are all the logs I can provide right up till the moment the error occurs. I hope this helps!
logs.zip

[Sanan07]

Just quick update : recently we made investigation on discovery flow and found potential issues with it. Also related to aborting flow. So we are planning to fix it in near future.

[richardwerkman]

Thats awesome news! Please keep me up to date as this is still a pressing matter for us at Stryker. Thanks for the update 👍

[richardwerkman]

Is this still being worked on?

[Sanan07]

We are planning to start soon, I will update you when done.

[richardwerkman]

Don't wanna be an annoyance but could I get a status update? This is still a pressing issue for us 🤐

[richardwerkman]

Hi, just checking once again if this will be picked up. Please keep us informed 👍

[richardwerkman]

@Sanan07 any status update for this?

[Sanan07]

We have PR, which should fix the issue and it is part of another big change. I will update when PR is merged. Probably in couple of weeks.

[richardwerkman]

Many thanks! This will help us in a big way 🙌

[Evangelink]

Closed by #3349