AssemblyCleanup executes after first test point in multi-test-point test run via Azure Devops Release pipeline VsTest Task when all tests are associated to the same TestMethod

[albert-yai]

Describe the bug

MSTest AssemblyCleanup executes immediately after the first test point in multi-test-point test run via Azure Devops Release pipeline VsTest Task. The bug only occurs when all tests in the test run are associated to the same MSTest TestMethod.

Version Info
bug is present on MSTest.TestFramework version >= 3.3.1
bug is not present on MSTest.TestFramework v2.2.3

Steps To Reproduce

1. define TestMethod and AssemblyCleanup methods
2. associate the same TestMethod to two Azure DevOps Test Cases
3. execute Azure DevOps Release pipeline VsTest Task test run for two test points associated to the same TestMethod

Outcome: AssemblyCleanup executes immediately after the first test point completes.

Minimum reproducible example Visual Studio 2019 MSTest Project
MSTestProject.zip

Example MSTest implementation

  [TestClass]
  public static class AssemblyHooks
  {

    [AssemblyInitialize]
    public static void AssemblyInitialize(TestContext testContext)
    {
      File.WriteAllText(@"C:\temp\mstest.log", $"{DateTime.Now} : AssemblyInitialize{Environment.NewLine}");
      Thread.Sleep(5000);
    }
    

    [AssemblyCleanup]
    public static void AssemblyCleanup()
    {
      File.AppendAllText(@"C:\temp\mstest.log", $"{DateTime.Now} : AssemblyCleanup{Environment.NewLine}");
      Thread.Sleep(5000);
    }

  }

  [TestClass]
  public class TestClass
  {

    [TestInitialize]
    public void TestInitialize()
    {
      File.AppendAllText(@"C:\temp\mstest.log", $"{DateTime.Now} : TestInitialize{Environment.NewLine}");
      Thread.Sleep(5000);
    }
    
    [TestMethod]
    public void TestMethod()
    {
      File.AppendAllText(@"C:\temp\mstest.log", $"{DateTime.Now} : TestMethod{Environment.NewLine}");
      Thread.Sleep(5000);
    }

    [TestCleanup]
    public void TestCleanup()
    {
      File.AppendAllText(@"C:\temp\mstest.log", $"{DateTime.Now} : TestCleanup{Environment.NewLine}");
      Thread.Sleep(5000);
    }

  }

Using the above example, execute Azure DevOps Release pipeline VsTest Task test run with two Test Cases associated to TestMethod.

Example mstest.log for MSTest.TestFramework v3.4.1

5/28/2024 12:46:07 PM : AssemblyInitialize
5/28/2024 12:46:12 PM : TestInitialize
5/28/2024 12:46:17 PM : TestMethod
5/28/2024 12:46:22 PM : TestCleanup
5/28/2024 12:46:27 PM : AssemblyCleanup
5/28/2024 12:46:32 PM : TestInitialize
5/28/2024 12:46:37 PM : TestMethod
5/28/2024 12:46:42 PM : TestCleanup

Example mstest.log for MSTest.TestFramework v2.2.3

5/22/2024 6:33:30 PM : AssemblyInitialize
5/22/2024 6:33:35 PM : TestInitialize
5/22/2024 6:33:40 PM : TestMethod
5/22/2024 6:33:45 PM : TestCleanup
5/22/2024 6:33:50 PM : TestInitialize
5/22/2024 6:33:55 PM : TestMethod
5/22/2024 6:34:00 PM : TestCleanup
5/22/2024 6:34:05 PM : AssemblyCleanup

NOTE: there are no MSTest code / Release pipeline changes between these two mstest.log examples. The only difference is the MSTest Nuget package version.

Expected behavior

AssemblyCleanup executes after all tests in the test run complete.

Actual behavior

AssemblyCleanup executes after the first test in a multi-test-point test run via Azure Devops Release pipeline VsTest Task when all tests are associated to the same TestMethod

Additional context

Azure DevOps Release pipeline definition
Azure DevOps Release pipeline logs

This bug does not occur if all tests in the test run are associated to unique TestMethods. All tests in the test run must be associated to the same TestMethod for the bug to manifest.

This bug was already reported on Visual Studio Developer Community. I was told to raise an issue here.

[Evangelink]

Hi @albert-yai,

Could you please confirm that running the test locally either by dotnet test or vstest.console.exe on the project produces the following output:

29/05/2024 09:45:07 : AssemblyInitialize
29/05/2024 09:45:08 : TestInitialize
29/05/2024 09:45:09 : TestMethod
29/05/2024 09:45:10 : TestCleanup
29/05/2024 09:45:11 : AssemblyCleanup

I'll investigate the behavior on AzDO to understand how VSTest calls us.

[albert-yai]

@Evangelink

Yes, running the test locally with vstest.console.exe produces the following output:

5/29/2024 11:53:40 AM : AssemblyInitialize
5/29/2024 11:53:45 AM : TestInitialize
5/29/2024 11:53:50 AM : TestMethod
5/29/2024 11:53:55 AM : TestCleanup
5/29/2024 11:54:00 AM : AssemblyCleanup

[Evangelink]

@engyebrahim could you please investigate this issue?

[Evangelink]

Any news here @engyebrahim?

[Evangelink]

I cannot find anything wrong on MSTest side. It would either be coming from VSTest or from AzDO. It seems they are wrapping VSTest.

@nohwnd Do you know how the test plan works technically?

[nohwnd]

Yes, it is done via TranslationLayer automation.

Here is a repro of the behavior. I send the same test twice for the execution:

https://github.com/microsoft/vstest/compare/Assembly-cleanup-repro

You should be able to get even simpler repro in your tests (without using translation layer) where you ask the engine to run the same test twice, which is what actually happens in the execution.

Problem is most likely the hashset here, where you check if all tests from a given class finished. But (because of the hashset) you only take unique names of tests, so the collection of tests that need to run before cleanup is [ TestMethod1 ], and not the correct [ TestMethod1, TestMethod1 ]. So right after the first test passes you assume all tests in the class passed.

https://github.com/microsoft/testfx/blob/main/src/Adapter/MSTest.TestAdapter/Execution/ClassCleanupManager.cs#L26-L30

[nohwnd]

Fixed in #3764 (rel/3.6) and #3766 (main).