Timeout attribute does not call test cleanup method

[jayaranigarg]

Steps to reproduce

[TestClass] 
public class TestCleanup 
{ 
[TestInitialize()] 
public void MyTestInitialize() 
{ 
Console.WriteLine("Calling initialize"); 
} 


// Use TestCleanup to run code after each test has run 

[TestCleanup()] 
public void MyTestCleanup() 
{ 
MessageBox.Show("Cleanup"); 
Console.WriteLine( ng cleanup"); 
} 

[Timeout(5000)] 
[TestMethod] 
public void TestMethod1() 
{ 
Console.WriteLine("Sleeping for 10 seconds"); 
System.Threading.Thread.Sleep(10000); 
Console.WriteLine("Waking up"); 
} 

} 

Expected behavior

It is essential all tests execute their TestCleanup code, as this code may have important steps to recover from an error such as a time out.

Actual behavior

The result of executing this code is the test times out but the message box is not displayed and the Calling cleanup message is not written to the console.

AB#1634637

In more complex scenarios like E2E UI tests where more than one failure may need to be collected and analyzed per test, this could be called a bug rather than enhancement.

[michael-colclough]

I agree completely. I raised it initially as a bug but then Microsoft downgraded it from bug to enhancement, and now after nearly a year have not done anything about it

[kzu]

I can't fathom how this is remotely an enhancement rather than a serious bug that should be fixed ASAP :/. Makes using Timeout absolutely useless and dangerous.

[michael-colclough]

As the person who first reported this, I agree entirely! Thanks Michael Colclough

[LazyBonez]

Is there a workaround for this case?

[kzu]

The workaround is to not use the attribute, and instead have your test methods run as part of a call to something like Execute(timeout, () => { actual test method }), where the Execute helper essentially does the same thing the timeout does, which is at https://github.com/microsoft/testfx/blob/master/src/Adapter/PlatformServices.Desktop/Services/DesktopThreadOperations.cs#L27. Instead of returning false for timed out execution, it could just throw an exception which would cause the test to fail like a regular test failure, causing the proper cleanup to run.

As to why the current implementation is doomed and not trivially fixable, see the implementation where you can observe how the timeout is basically wrapping the entire execution (including test class creation, test initialize and cleanup, as well as class cleanup) in a delegate that is then timed-out. If the timeout happens, none of the lifecycle events may run (depending on where the timeout occurs) since that ExecuteInternalWithTimeout has no knowledge of the lifetime events and just wraps ExecuteInternal.

Fixing it would require refactoring that code so that execution is split in the actual lifetime phases, the timeout is applied to just the test method invocation, and the lifetime phases are always ensured to run to completion.

[nohwnd]

Okay, researched on this a bit and I am not sure what is the best way forward here. So let me sum up what I found out so far.

The behavior differs based on where we are running.

• on full framework, as @kzu pointed out, thread is aborted and the cleanup never has chance to run
• on core, the task is cancelled, but core does not provide apis to abort threads, so thread lives on, and two things can happen:
  • the tests are finished executing, test host process aborts, and so do the threads, cleanup is not run
  • there are more tests to run, test host continues running, and the test runs to completion on background and even does the cleanup

using Microsoft.VisualStudio.TestTools.UnitTesting;
using System;
using System.IO;
using System.Threading;
using System.Runtime.InteropServices;
using System.Diagnostics;

namespace CleanupOnTimeout
{
    [TestClass]
    public class TestCleanup
    {
        [TestInitialize()]
        public void MyTestInitialize()
        {
            File.AppendAllText($@"c:\temp\test.txt", "initialize\n");
        }

        [TestCleanup()]
        public void MyTestCleanup()
        {
            File.AppendAllText($@"c:\temp\test.txt", "cleanup\n");
        }

        [Timeout(1000)]
        [TestMethod]
        public void TestMethod1()
        {
            var s = Stopwatch.StartNew();
            File.AppendAllText($@"c:\temp\test.txt", "Sleeping for 3 seconds\n");
            Thread.Sleep(3_000);
            File.AppendAllText($@"c:\temp\test.txt", $"done {s.ElapsedMilliseconds}ms\n");
        }
    } 

    [TestClass]
    public class Wait
    {
        [TestMethod]
        public void JustWaitForIt()
        {
            File.AppendAllText($@"c:\temp\test.txt", "Doing some more work...\n");
            Thread.Sleep(5_000);
        }
    }
}

Will log this:

// on Framework
initialize
Sleeping for 3 seconds
Doing some more work...

// on Core
initialize
Sleeping for 3 seconds
Doing some more work...
done 3001ms
cleanup

Neither of the behaviors are correct.

There are few ways to solve this, but neither strikes me as the best solution what I am most concerned about is consistency in behavior, access to resources from different threads, and actually being able to cancel the task.

consistency & threads

One way to solve this is to skip the invoking the Cancellation logic in the inner lifetime when we know that there is timeout, and invoke it ouside of the task.

• On Framework this would work fine but would change the behavior, if we are running and not running with timeout, because suddenly we are accessing the same resource from two different threads.
• On Core we are in even worse situation. Because we are still running the work that the test is doing, and on other thread we start cleaning up, we are now touching the same resource from two places.

I am not sure what the implications here are, but I assume that in some cases (like UI testing) suddenly using two threads just because we added timeout might be confusing (maybe logical to developers, but still confusing).

cancellation

Because the Cleanup was broken, cancelling the task did not have to wait for the cleanup to finish running. I assume that running an expensive cleanup could make the ui/console seem unresponsive, especially when we trying to cancel the whole run.

solution

To me it seems like the best solution would be to keep it as is, in case TimeOut is not specified, and if it is then we would skip running cleanup in the ExecuteInternal, and instead run it as a separate task or tasks after we cancelled.

This will unfortunately have all the thread and cancellation problems described above, but at least there is no change of behavior for the tests that do not use Timeout.

Thoughts?

[michael-colclough]

What you describe seems reasonable to me, although I am not a programmer, more a tester, so wouldn't be able to comment on the internal details of the proposed fix. All I can say is .net core and .net framework should work in the same way and if you do not specify a timeout the behaviour should be unchanged.

Thanks @nohwnd for investigation. Unit tests and UI tests are differing quite much from each other regarding the resources they are instantiating. While Unit tests create data objects in the memory, UI tests are opening browser windows or even starting applications. There are many cases where you do not want or just cannot open two instances (i.e. of an application) in parallel on a separate task.
On the other hand, when running unit tests you want the complete test run to run as fast as possible and there is no problem in creating instances of the same type several times.

Would it be possible to create two kinds of timeout, one which allows parallel execution and one which doesnt?

Does MaxCpuCount in the runsettings have an impact on the parallelism of the whole test run? If MaxCpuCount is set to 1, does it only mean that not more than one test ist being executed at a time on one machine or should it also prevent cleanup and following tests to be run in parallel?

What I saw is that the cleanup was run in parallel which was causing trouble during UI tests. MaxCpuCount was always set to 1.