Console output handling reimagined

[ravigneaux-1]

Console output is vital for the verification of the system under test (SUT) and understanding the status of the test execution. However, the current approach in the NUnit test adapter has some limitations. This issue suggests changes to the handling of console output from both the system under test and the test implementation, initiating a discussion for potential improvements.

Introduction

This discussion focuses primarily on the interaction between the test adapter and the test platform. We'll also have a brief look at the implications the adapter's capabilities have on test loggers.

Basically, there are two use cases for console output that we need to differentiate:

• Output from the test implementation, framework or adapter.
• Output from the system under test.

In my point of view, the current implementation of the NUnit test adapter assumes that console output is primarily used for logging information, warnings, and errors during test execution, which aligns with use case 1. However, this discussion addresses enabling use case 2.

Example use case

Under which circumstances would the system under test typically write to the console, and why is this relevant to the tests in the first place?

Let's assume we develop a console application. It's perfectly valid for such an application to write to the standard output stream as well as the standard error stream.¹ For example, a simple console application could look something like this:

internal class Program
{
    const int ExitCodeSuccess = 0;
    const int ExitCodeFailure = 1;

    internal static int Main(string[] args)
    {
        if (args.Length == 0)
        {
            Console.Error.WriteLine("Error: No user name provided.");
            return ExitCodeFailure;
        }
        else if (args.Length > 1)
            Console.Error.WriteLine("Warning: Ignoring excess arguments.");

        string userName = args[0];
        Console.WriteLine("Hello, {0}!", userName);

        return ExitCodeSuccess;
    }
}

Unit tests for such an application could include test cases like the following:

• Main method returns zero exit code if called with single argument
• Main method returns non-zero exit code if called with no arguments
• Main method returns zero exit code if called with multiple arguments

An implementation of these test cases using the NUnit framework could look like the following:

Test case implementation in the NUnit framework

public class UnitTests
{
    [TestCase(TestName = "Main method returns zero exit code if called with single argument")]
    public void Main_SingleArgument_ReturnsZeroExitCode()
    {
        int exitCode = Program.Main(new string[] { "John" });
        Assert.That(exitCode, Is.EqualTo(0));
    }

    [TestCase(TestName = "Main method returns non-zero exit code if called with no arguments")]
    public void Main_NoArguments_ReturnsNonZeroExitCode()
    {
        int exitCode = Program.Main(Array.Empty<string>());
        Assert.That(exitCode, Is.Not.EqualTo(0));
    }

    [TestCase(TestName = "Main method returns zero exit code if called with multiple arguments")]
    public void Main_MultipleArguments_ReturnsZeroExitCode()
    {
        int exitCode = Program.Main(new string[] { "John", "42" });
        Assert.That(exitCode, Is.EqualTo(0));
    }
}

For comparison, let's implement the same tests using MSTest and the xUnit framework as well:

Test case implementation in MSTest

[TestClass]
public class UnitTests
{
    [TestMethod("Main method returns zero exit code if called with single argument")]
    public void Main_SingleArgument_ReturnsZeroExitCode()
    {
        int exitCode = Program.Main(new string[] { "John" });
        Assert.AreEqual(exitCode, 0);
    }

    [TestMethod("Main method returns non-zero exit code if called with no arguments")]
    public void Main_NoArguments_ReturnsNonZeroExitCode()
    {
        int exitCode = Program.Main(Array.Empty<string>());
        Assert.AreNotEqual(exitCode, 0);
    }

    [TestMethod("Main method returns zero exit code if called with multiple arguments")]
    public void Main_MultipleArguments_ReturnsZeroExitCode()
    {
        int exitCode = Program.Main(new string[] { "John", "42" });
        Assert.AreEqual(exitCode, 0);
    }
}

Test case implementation in the xUnit framework

public class UnitTests
{
    [Fact(DisplayName = "Main method returns zero exit code if called with single argument")]
    public void Main_SingleArgument_ReturnsZeroExitCode()
    {
        int exitCode = Program.Main(new string[] { "John" });
        Assert.Equal(0, exitCode);
    }

    [Fact(DisplayName = "Main method returns non-zero exit code if called with no arguments")]
    public void Main_NoArguments_ReturnsNonZeroExitCode()
    {
        int exitCode = Program.Main(Array.Empty<string>());
        Assert.NotEqual(0, exitCode);
    }

    [Fact(DisplayName = "Main method returns zero exit code if called with multiple arguments")]
    public void Main_MultipleArguments_ReturnsZeroExitCode()
    {
        int exitCode = Program.Main(new string[] { "John", "42" });
        Assert.Equal(0, exitCode);
    }
}

Now we'll examine how the console output interacts with the test platform and impacts the test execution...

Test run result in the Test Explorer

First, let's run the tests in the Visual Studio Test Explorer.

❌ After the test run has finished, the Test Explorer issues warnings.

The developer would read this as an indication for issues in the tests ("The test run has finished with warnings, something must be wrong."), when in reality that's not the case at all.

Root cause

The NUnit test adapter forwards console output from the test host to the test platform via the IMessageLogger. Text written to the standard output stream is forwarded as informational or warning messages, or not at all, according to adapter setting ConsoleOut. Text written to the standard error stream is always forwarded as warning messages, regardless of the adapter settings.

Proposed change

It should be possible to control the message level (information, warning, error) with which console output from the test host is forwarded, and to disable forwarding altogether, both for the standard output and for the standard error stream. The adapter setting ConsoleOut should control both standard streams, or a new adapter setting ConsoleError should be introduced to control the standard error stream independently.

Rationale

Writing to the console is not inherently erroneous behavior of the system under test. Rather, it's often expected behavior that itself is testable. While writing to the console within the test implementation, on the other hand, might be used for logging, it should be noted that there are better alternatives for this purpose.² Extending the adapter settings as proposed enables users to implement both use cases: Either suppressing false-positive warnings for "normal" console output from the system under test or continue writing to the console for logging purposes.

The adapters of MSTest and the xUnit framework do not issue warnings for console output either.

Test run result in the Test Explorer using MSTest

✅ No warnings are issued.

Test run result in the Test Explorer using the xUnit framework

✅ No warnings issued.

Standard output and standard error in the Test Explorer

Another feature of the Test Explorer is listing text written to the standard output and standard error streams from the test host individually for each test case. The NUnit test adapter correctly implements this feature:³

✅ Console output from application listed for each test case.

In this regard, NUnit keeps up with MSTest and even outperforms the xUnit framework, which appears to ignore console output from the test host.

Standard streams in the Test Explorer using MSTest

✅ Console output from application listed for each test case.

Missing standard streams in the Test Explorer using the xUnit framework

❌ Console output from application not listed for each test case.

Proposed change

None. This feature should be maintained as it is, even if the test adapter's handling of console output is changed otherwise.

Rationale

The feature enables developers to inspect console output from the test host on a per test case basis and makes the output available to test loggers.

Console output in the Tests Output Pane

Another issue of running the tests in Visual Studio with the NUnit test adapter concerns the output generated during the test run:

========== Starting test run ==========
NUnit Adapter 4.5.0.0: Test execution started
Running selected tests in D:\Repositories\MyApp\MyApp.Tests.NUnit\bin\Debug\net6.0\MyApp.Tests.NUnit.dll
   NUnit3TestExecutor discovered 3 of 3 NUnit test cases using Current Discovery mode, Non-Explicit run
Warning: Ignoring excess arguments.
Hello, John!

Error: No user name provided.
Hello, John!

NUnit Adapter 4.5.0.0: Test execution complete
========== Test run finished: 3 Tests (3 Passed, 0 Failed, 0 Skipped) run in 286 ms ==========

❌ Console output from the system under test is listed in the Tests Output Pane.

This clutters the output with text that cannot be attributed to individual test cases⁴ and distracts from the actual diagnostic messages of the test run.

Root cause

The NUnit test adapter forwards console output from the test host to the test platform via the IMessageLogger, according to the ConsoleOut setting. In addition, the Verbosity setting acts like a filter in the message forwarding process.⁵ The forwarding of informational messages can be disabled, but warning and error messages are forwarded even with the lowest verbosity level.

Proposed change

It should be possible to disable forwarding of console output from the test host, so that it does not appear in the test output. Adapter setting Verbosity should not control console output from the test host, since the latter is already controlled by the ConsoleOut (and the proposed ConsoleError) setting. Instead, the verbosity level should only control diagnostics from the test framework and/or test adapter itself.

Rationale

The console output from the system under test does not provide useful information about test execution. With large numbers of test cases, isolating relevant information from the output can become a real problem.

Neither MSTest nor the xUnit framework write the standard streams to the test output, and it does not appear they would offer adapter settings to enable such functionality.

Output of the test run using MSTest

========== Starting test run ==========
========== Test run finished: 3 Tests (3 Passed, 0 Failed, 0 Skipped) run in 99 ms ==========

✅ Console output from the application is not listed in the Tests Output Pane.

The available adapter settings do not include a related setting.

Output of the test run using the xUnit framework

========== Starting test run ==========
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.5.8+bd6d97b49a (64-bit .NET 6.0.28)
[xUnit.net 00:00:00.17]   Starting:    MyApp.Tests.xUnit
[xUnit.net 00:00:00.33]   Finished:    MyApp.Tests.xUnit
========== Test run finished: 3 Tests (3 Passed, 0 Failed, 0 Skipped) run in 340 ms ==========

✅ Console output from the application is not listed in the Tests Output Pane.

The available adapter settings do not include a related setting.

Console output in the console logger

Next, let's run the test using dotnet test and the default console logger.

❌ Console output from the system under test appears on the console.

The line of argument follows that of the previous section. While I acknowledge that the test loggers' behavior is not within control of NUnit, the example shows the implications of the test adapter's handling of console output. The proposed changes to the adapter settings would provide more control over which messages the test loggers will receive or not.⁶

The default console logger does not write the application output when using MSTest or the xUnit framework.

Output of the dotnet test run using MSTest

✅ Console output from the system under test does not appear on the console.

Output of the dotnet test run using the xUnit framework

✅ Console output from the system under test does not appear on the console.

Capturing console output

Console output from the test host, including the system under test as well as the test adapter itself, will go nowhere by default, since its standard streams are not connected to the standard streams of the test platform. The adapter or framework must intercept/redirect the standard streams of the test host and capture the console output.⁷

This got me thinking: If the output needs to be captured anyway, why not make it available to the tests as well? After all, tests might want to verify that specific outputs are produced by the system under test.

That's why I've attempted to implement a ConsoleRecorder class. It allows users to selectively record console output and read it back in the test cases:

public class SystemTests
{
    [TestCase(TestName = "Warning is output if called with multiple arguments")]
    public void Program_MultipleArguments_OutputsWarning()
    {
        const string ignoredArgsWarning = "Ignoring excess arguments";
        
        ConsoleRecorder.Start();
        Program.Main(new string[] { "John", "42" });
        ConsoleRecorder.Stop();

        string errorOutput = ConsoleRecorder.Error.ReadToEnd();
        Assert.That(errorOutput, Contains.Substring(ignoredArgsWarning));
    }
}

Implementing this feature in NUnit would be highly beneficial. The correct domain, however, whether within the adapter or the framework itself, is open to discussion. Also, the design should be reviewed with care.

Summary

The proposed changes aim to refine the handling of console output within the test adapter, giving the user more control over how console output should be interpreted - as data from the system under test or as messages logged in the tests. At the same time, the captured console output is provided to the tests for verification.

The graphical overview below illustrates the modifications, where blocks with question marks resemble parts of the existing adapter implementation:

Footnotes

1. For instance, the POSIX standard defines

   standard output (for writing conventional output), and standard error (for writing diagnostic output).

   In practice, diagnostic output includes informational messages (e.g., progress updates), as well as warnings (e.g., about corrections applied to the input) and actual errors (e.g., failed operations), while conventional output includes "productive" data (i.e., the result of the executed command) that is meaningful to the user and could potentially be used as input for subsequent commands. ↩

2. I intend to create another issue for discussion of logging mechanisms. ↩

3. This mechanism involves adding a TestResultMessage with the corresponding category for each output to the TestResult. I believe this is currently implemented in the TestConverter of the test adapter. ↩

4. Adapter setting UseTestNameInConsoleOutput appears to be working only for the standard output stream, but not for the standard error stream. ↩

5. This is currently implemented in the TestLogger of the test adapter, from what I can tell. ↩

6. It should be noted that console output can be made available to test loggers via the TestResult.Messages, even if forwarding of log messages (information, warnings, errors) is disabled. ↩

7. I believe this is currently implemented in the NUnitTestAssemblyRunner of the framework. ↩

[ravigneaux-1]

Pull request for nunit3-vs-adapter.issues in preparation... ⏳

[OsirisTerje]

Thanks @ravigneaux-1 ! Awesome work. What you have written above should also go into the docs, after the issues have been cleared out.

[ravigneaux-1]

Pull request for nunit3-vs-adapter.issues created 📦 It contains demonstrators for the issues described (so that everyone can try it out easily) and a very crude proof of concept for the mentioned ConsoleRecorder class.

I didn't live up to the expectations I fueled - but only in the sense that the code examples above are not 100% accurate. I thought I could adapt my original implementation on-the-fly, but I didn't manage to do so. You actually get more: The ConsoleRecorder is wrapped in a static ConsoleOutput class, which allows to dynamically suppress console output...

[ravigneaux-1]

Maybe the TestContext would be a suitable place for this? 🤔 For example, adding a Console property like this...:

• Having it derive from TextReader, then one could so something like TestContext.Console.ReadLine() for reading the combined standard output and error streams. Adding nested TextReader properties Out and Error allows for reading only the standard output and standard error, respectively (e.g., TestContext.Console.Error.ReadLine()) 🤔 One would have to re-evaluate the existing Out, Error and Progress properties of the TestContext to avoid confusion, though 😅
• The recording functionality could also be hosted there: TestContext.Console.Recorder.Start() etc.
• The same holds true for the dynamic suppression (in case this is something we want to adopt): TestContext.Console.Enable() and TestContext.Console.Disable()
• And one more (completely crazy) idea: Connecting to the standard input stream of the test host, e.g. via TestContext.Console.In could enable system tests involving console input (even though that's not the primary use case of the NUnit framework...)

Just some things that came to my mind...