Add a globally accessible TestContext.Progress logger

[Danielku15]

Summary

MSTest should provide a mechanism of globally logging outputs to the stdout of the test execution similar to the TestContext.Progress of NUnit

Background and Motivation

When having long running processes in your tests as a developer you want to see intermediate outputs when having test executed on any platform (local CLI, CI/CD, IDE outputs). In the .net test ecosystem it generally seems common to capture the stdout/stderr and attach it to the test directly so that the attached loggers can decide what to do with the outputs (write a trx, nicely format the console printing). MSTest goes that far that no outputs "leak" to the host process and everything is captured and attached to results.

This capturing is in conflict with doing any kind of intermediate progress reporting. Especially when preparing tests (AssemblyInitialize, ClassInitialize, TestInitialize) but also during normal test execution progress information improves the developer experience significantly by giving immediate feedback.

Hence a mechanism to report "test progress logs" in parallel to normal test related outputs, being printed immediately on the stdout/stderr of the host process can improve the feedback to the developers executing tests and in case of problems improve the troubleshooting experience without breaking current principles on how normal outputs are handled.

Proposed Feature

It is not the responsibility of MSTest to change and adapt the principles of dotnet test and the way logs are maybe forwarded to these environments for instantenous logging. While it might be a legit discussion it should be out of scope for this request.

Instead this request is about adding the exact same feature NUnit offers with the static TextWriter TestContext.Progress property. From within the test framework you can access this quasi-global progress logger to write messages. These messages are received by the test adapter in the host process and immediately logged to the console output.

Additionally (I think) NUnit tries to 'attach' these logs to the current test context but from what I've seen in my tests, the logs are always printed instantly, and not listed in the "test output" section.

When using logging frameworks (e.g. via Microsoft Extensions Logging) you could choose to forward all outputs accordingly to your needs/preference also getting intermediate logs for the application logs.

Alternative Designs

• Enable an option (e.g. runsettings) which also forward any Console.Out and Console.Error outputs to the host. It can be still captured and attached to the tests as output for the loggers, but with this option active also log it to the stdout of the host process.
• Ensure somehow that test logs are forwarded immediately to the console logger and printed as the arrive. Not sure where exactly in the chain this immediate logging is broken. Certainly here seem to be a capture until the test execution completes. Looking (narrow minded) to the console logger of vstest there is a way to receive intermediate test messages (logs).

Example

A simple example executed like this will only have output a the very end.

// dotnet test --verbosity=normal --logger "console;verbosity=detailed" 
namespace MSTestOutput;

[TestClass]
public class UnitTest1
{
    
    [TestMethod]
    public void TestMethod1()
    {
        for (var i = 0; i < 3; i++)
        {
            Console.WriteLine("UnitTest1.TestMethod1");
            Thread.Sleep(1000);
        }
    }
}

Output:

...
     2>BuildProject:
         Build completed.

Test run for D:\Dev\Other\NUnit\NUnitOutput\MSTestOutput\bin\Debug\net8.0\MSTestOutput.dll (.NETCoreApp,Version=v8.0)
Microsoft (R) Test Execution Command Line Tool Version 17.9.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
D:\Dev\Other\NUnit\NUnitOutput\MSTestOutput\bin\Debug\net8.0\MSTestOutput.dll
  Passed TestMethod1 [3 s]
  Standard Output Messages:
 UnitTest1.TestMethod1
 UnitTest1.TestMethod1
 UnitTest1.TestMethod1



Test Run Successful.
Total tests: 1
     Passed: 1
 Total time: 4,1637 Seconds
     2>Done Building Project "D:\Dev\Other\NUnit\NUnitOutput\MSTestOutput\MSTestOutput.csproj" (VSTest target(s)).
     1>Done Building Project "D:\Dev\Other\NUnit\NUnitOutput\NUnitOutput.sln" (VSTest target(s)).

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

Time Elapsed 00:00:05.90

In NUnit:

// dotnet test --verbosity=normal --logger "console;verbosity=detailed"
namespace NUnitOutput;

public class UnitTest1
{
    [Test]
    public void Test1()
    {
        for (var i = 0; i < 3; i++)
        {
            Console.WriteLine("UnitTest1.TestMethod1");
            TestContext.Progress.WriteLine("Progress UnitTest1.TestMethod1");
            Thread.Sleep(1000);
        }
    }
}

Output:

     2>BuildProject:
         Build completed.

Test run for D:\Dev\Other\NUnit\NUnitOutput\NUnitOutput\bin\Debug\net8.0\NUnitOutput.dll (.NETCoreApp,Version=v8.0)
Microsoft (R) Test Execution Command Line Tool Version 17.9.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
D:\Dev\Other\NUnit\NUnitOutput\NUnitOutput\bin\Debug\net8.0\NUnitOutput.dll
NUnit Adapter 4.5.0.0: Test execution started
Running all tests in D:\Dev\Other\NUnit\NUnitOutput\NUnitOutput\bin\Debug\net8.0\NUnitOutput.dll
   NUnit3TestExecutor discovered 1 of 1 NUnit test cases using Current Discovery mode, Non-Explicit run
Progress UnitTest1.TestMethod1
Progress UnitTest1.TestMethod1
Progress UnitTest1.TestMethod1
UnitTest1.TestMethod1
UnitTest1.TestMethod1
UnitTest1.TestMethod1

NUnit Adapter 4.5.0.0: Test execution complete
  Passed Test1 [3 s]
  Standard Output Messages:
 UnitTest1.TestMethod1
 UnitTest1.TestMethod1
 UnitTest1.TestMethod1



Test Run Successful.
Total tests: 1
     Passed: 1
 Total time: 3,9993 Seconds
     2>Done Building Project "D:\Dev\Other\NUnit\NUnitOutput\NUnitOutput\NUnitOutput.csproj" (VSTest target(s)).
     1>Done Building Project "D:\Dev\Other\NUnit\NUnitOutput\NUnitOutput.sln" (VSTest target(s)).

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

Time Elapsed 00:00:06.22

[nohwnd]

<CaptureTraceOutput>false</CaptureTraceOutput> option disables the output capturing in recent version of MSTest. So the output goes directly to console when you are using MSTest runner (the new testing platform).

VSTest in the current stable version still captures the output, but the next version (17.11) is bringing options to forward the output to console / VS.

Please see this PR microsoft/vstest#4998

We are also considering adding an API for progress reporting, for long running tasks, such as installing of Playwright drivers, or doing long setup in AssemblyInitialize.

Closing because the options in the suggested solution are available, or will soon be available.