Question: Handling of test output for parallel tests

[avonwyss]

This is a follow-up on the issue #575, the pull request #689, and also relates to issues such as #737.

TL;DR: What is the role of ITraceListener and how shall it work in parallel test runs?

Parallel tests do not play well with the classic Console, Debug and Trace redirect mechanisms. Therefore, the different frameworks have added specific output channels for test output (see for instance xUnit 2, NUnit 3) which must (xUnit 2) or should (NUnit 3) be used.

In contrast to the NUnit 3 static class TestContext, the authors of xUnit 2 chose the (arguably cleaner) way of constructor injection to inject the IOutputTestHelper which is then used for writing to the test output. My pull request #689 changes the xUnit 2 test provider so that it accepts this constructor parameter and injects it into the ScenarioContainer, ready to be retrieved and used in tests.

@gasparnagy has mentioned that implementing a tracelistener would fully fix #575. However, how is this supposed to work when we can only implement and inject the trace listener into the ScenarioContext? Would it be OK for the test code generator to generate a small inner class which implements ITraceListener and inject that into the ScenarioContext (e.g. at the same time as the ITestOutputHelper is injected for xUnit 2)? This would effectively make it impossible for manually replacing the ITraceListener through configuration.

Basically, I'm not sure I fully understand the role of ITraceListener. Shall it be used to redirect the final output, such as writing to an external file? In that case, the approach outlined above would be a no-go. Or in other words, shall it process the output received from the test framework, or shall it be used directly in tests, effectively bypassing the test framework output channels? Is it meant as sink for the unit test framework?

---

Looking at the code, ITraceListener is used (among other places) in the TestTracer constructor. The ITestTracer is used for the ContextManager constructor, which is used in the ContainerBuilder.CreateScenarioContainer method. So, if my reasoning is correct, replacing the ITraceListener during the ScenarioInitialize method of the generated test is too late to replace the ITraceListener used by ITestTracer, but it is the earliest moment where we do have a xUnit ITestOutputHelper instance...

So alternatively we could have a XUnit2TraceListener implementation which initially only buffers output and waits to have its ITestOutputHelper instance being set; at that time it would then flush the buffer and pipe new writes to the ITestOutputHelper. Feasible but that doesn't seem like a clean solution...

[LirazShay]

@avonwyss Your assumption that:

Parallel tests do not play well with the classic Console, Debug and Trace redirect mechanisms. Therefore, the different frameworks have added specific output channels for test output (see for instance xUnit 2, NUnit 3) which must (xUnit 2) or should (NUnit 3) be used.

Is not correct. I'm using NUnit 3 and while parallel execution call to Console.WriteLine() - it works perfect. the output goes to the correct test. @gasparnagy

[avonwyss]

@LirazShay Yes it does work, but it does not play well: https://github.com/nunit/docs/wiki/Parallel-Test-Execution#text-output-from-tests and related issues like https://github.com/nunit/nunit/issues/1139 which is why I wrote that TestContext should be used.

[gasparnagy]

@avonwyss Thx for the good summary. In general, the trace listener interface is responsible for collecting messages (in two categories: business and technical) from the SpecFlow runtime and forward them into a channel that the test execution framework can process and include into their own reporting.

There is a third kind of message as well, the user messages. So far these were emitted by the code by simply using Console.WriteLine, as this was the de-facto standard for including something into the test report.

To avoid test runner specific user messages in the automation code, SpecFlow should provide an API for this, that would also route these messages to the trace listener.

While the majority of the messages are related to a scenario, there might be messages that are emitted outside of a scenario execution. In practice this means that whenever the trace listener writes out a message there is either a current scenario context or not.

With the more modern test runner frameworks, we have to model this. I.e. if the message is emitted in a scenario context (ie, there is a current scenario context and the ITestOutputHelper is registered into it by #689), we should write out the message there. If there is no scenario context, we can do whatever is appropriate for the particular test runner - for NUnit, we can just use Console.WriteLine -- this will be sill captured, just not waved into the test output as far as I understand.

So based on this, I think implementing a unit test runner specific trace listener that forwards the messages to the appropriate channel should be OK.

For understanding the scope of the different classes in SpecFlow, we have a wiki page, that describes the scope (global, test thread, scenario) of the different classes. https://github.com/techtalk/SpecFlow/wiki/Available-Containers-&-Registrations

The trace listener is a bit special, because it is registered by default to the global container. By default it uses the DefaultTraceListener, that writes the messages out to the console (not thread safe). In order to support thread safety for parallel execution, the trace listener is re-defined in the test thread container with the AsyncTraceListener class, that is basically queuing the messages to the global trace listener in a separate thread in a synchronized way.

In case of xUnit/NUnit, we probably need to replace the trace listener in the test thread container, as the test output helpers provided by the unit test frameworks are anyway thread safe and in the global container, you cannot access the scenario context...

Does this help?

[LirazShay]

@avonwyss As Gaspar said, the NUnit framework has handled Console.Writeline even when using parallel tests. In the link that you gave: https://github.com/nunit/docs/wiki/Parallel-Test-Execution#text-output-from-tests

Text Output from Tests ...output is now collected in the result for each test and is not displayed until the test completes. That means that the in the end of the test we will have the correct output. this enough to generate the SpecFlow report. And the issue that you referenced https://github.com/nunit/nunit/issues/1139 was closed in status Done!

[elv1s42]

Hi! Any updates on this issue?

[LirazShay]

@elv1s42 I have a workaround: Add this class to your specs (tests) project: Please note that it will log the steps to the console, it will be saved as test output

using System;
using TechTalk.SpecFlow;

namespace GoogleSpecs
{
    [Binding]
    public sealed class Hooks : Steps
    {

        DateTime _lastStepStart;

        [BeforeStep]
        public void BeforeStepSaveStartTime()
        {
            _lastStepStart = DateTime.Now;
        }

        //This method is here to fix the bug in SpecFlow
        //the bug is when using parallel execution the test output log is not written to the tests
        //see https://github.com/techtalk/SpecFlow/issues/737
        [AfterStep]
        public void AfterStepLogStepResult()
        {
            //Log the step text - for example: "Given I am in the login page"
            string currentStepFullText = StepContext.StepInfo.StepDefinitionType + " " + StepContext.StepInfo.Text;
            Console.WriteLine(currentStepFullText);

            //If step has table argument, log it also
            var stepTable = StepContext.StepInfo.Table;
            if (stepTable != null && stepTable.ToString() != "")
                Console.Write(stepTable);

            //Log '-> error: ' if test failed, or '-> done: ' if not failed.
            var error = ScenarioContext.TestError;
            Console.Write(error != null ? "-> error: " + error.Message : "-> done: ");

            //Log step time in seconds (for example: 34.0s)
            string stepTimeInSec = $"({DateTime.Now.Subtract(_lastStepStart).TotalSeconds:0.0}s)";
            Console.Write(stepTimeInSec);
            Console.WriteLine();
        }

    }
}

[elv1s42]

Thanks @LirazShay ! But I was looking for any approach of capturing test output from specflow plugin (when tests are running in parallel). And it looks like there is no common way to do this for all test runner frameworks (xUnit, NUnit, MSTest)

[elv1s42]

@gasparnagy can you please help me with this?

I am not sure if it is possible to get output for separate test (when the are running in parallel). What interface can I use for this? I was looking here: https://github.com/techtalk/SpecFlow/wiki/Available-Containers-&-Registrations, but I am to sure what to do.

Tha main problem is rthat I'm trying to create SpecFlow Plugin (some kind of reporting tool), but I am not able to capture test output for tests runnind in parallel. By output I mean not only step details (i can capture them using ITestExecutionEngine) but all other test output (like Console.WriteLine("here are my test details...");)

EDIT: Raised a separate Issue for this question

[ae250219]

Do you have any news about it? we are facing the same issue

[SabotageAndi]

This should be fixed if you are using the new ISpecFlowOutputHelper API (https://docs.specflow.org/projects/specflow/en/latest/outputapi/outputapi.html).