Logs are getting mixed in Visual studio test explorer

[sampath-ganesan]

Reqnroll Version

2.1.1

Which test runner are you using?

MSTest

Test Runner Version Number

3.6.0

.NET Implementation

.NET 8.0

Test Execution Method

Visual Studio Test Explorer

Content of reqnroll.json configuration file

No response

Issue Description

1. when initializing the web driver we had to use AsyncLocal to initiate the browser this i am doing because when test run in browser its returning same webdriver session id to all scenarios which will do the action in that webdriver session only (Is there anything we can do on reqnroll project to solve this?)
2. when running in parallel run with this change + AsyncLocal i am able to run scenarios in parallel without any issues but the issue starts at the reporting when i see the report i can see the standard out is not having the proper output such as if i run 4 scenarios and all scenarios got executed then only one scenario have the standard output for all 4 scenarios along with thread Id so i did some changes on

Steps to Reproduce

1. create project that will initialize the web driver using AsyncLocal
2. run scenario in parallel
3. in the report scenario logs are getting mixed with each other

Link to Repro Project

No response

[ajeckmans]

For issue 1: What is the intended behaviour? A browser session per scenario?
For 2: Does this also happen when you run from console? I can image you're somehow only getting a reference to the outputwriter for the first scenario/test thread. That would mean your dependency resolving/injection is slightly off. Do you have a minimal reproduction somewhere?

[sampath-ganesan]

hi,

1. its opening A broker session per scenario and execution is getting succeeded with Support for scenario-level parallel execution #277 these changes but the logs are getting mixed for example if i run it in three thread and the thread id is 1,2,3 this is the output i am getting this is one scenario
   1 -> scenario 1 step 1 log
   1 -> scenario 2 step 1 log
   1 -> scenario 3 step 1 log
   and other scenarios is not having any logs
2. this one i tried in visual studio i haven't tried in console

[obligaron]

Standard output is a global resource. When running tests in parallel the standard output can't be directly associated with a test. This is a limitation of the global and can't be changed by Reqnroll. 😞 See also the related MsTest issue.

You can use ITestOutputHelper to write output that is guaranteed to be associated with a test (for MsTest this uses TestContext internally).

[Code-Grump]

1 -> scenario 1 step 1 log
1 -> scenario 2 step 1 log
1 -> scenario 3 step 1 log

Could you share with us the code that is writing this output?

[sampath-ganesan]

Hi @Code-Grump we are not writing it Reqnroll is writing these output.
@obligaron i fixed this issue by doing this change

Reqnroll/Reqnroll/Tracing/TraceListenerQueue.cs

Line 54 in cda0318

if (_isThreadSafeTraceListener || !_testRunnerManager.IsMultiThreaded)

To
if (_isThreadSafeTraceListener || _testRunnerManager.IsMultiThreaded)

this is working for MSTest and run is getting passed with proper logs as well

[gasparnagy]

@sampath-ganesan that change makes the logging synchronous so I fear that would cause other issues with massive parallelization.

I have tried to reproduce the issue, but I could not.

I think we are stuck with this issue. Could you please make some minimalistic repro project that shows the problem? Probably based on that we could figure out what's wrong.

[sampath-ganesan]

I will try to create that project

[sampath-ganesan]

I will try to create that project
@gasparnagy
https://github.com/sampath-ganesan/ReqnrollLogMixCheck

created it and I can able to replicate it

[obligaron]

Thanks for creating the repro. 👍

I ran the tests locally and got similar results.

-> done: SearchEngineStep.GivenINavigatedToSearchEngine("Yahoo") (3,8s)
When I search for reqnroll
-> done: SearchEngineStep.WhenISearchForReqnroll() (0,0s)
Then search result is displayed
-> done: SearchEngineStep.ThenSearchResultIsDisplayed() (0,0s)

This happens because Reqnroll itself writes to the console and the console is a global resource (as described before).

MSTestTraceListener:

Reqnroll/Plugins/Reqnroll.MSTest.ReqnrollPlugin/MSTestTraceListener.cs

Lines 15 to 25 in 4642769

	public override void WriteTestOutput(string message)
	{
	_testContextProvider.GetTestContext().WriteLine(message);
	base.WriteTestOutput(message);
	}
	public override void WriteToolOutput(string message)
	{
	_testContextProvider.GetTestContext().WriteLine("-> " + message);
	base.WriteToolOutput(message);
	}

This writes to TestContext, but also writes to the console with the base call which ends up calling the DefaultListener:

Reqnroll/Reqnroll/Tracing/DefaultListener.cs

Lines 7 to 15 in 4642769

	public void WriteTestOutput(string message)
	{
	Console.WriteLine(message);
	}
	public void WriteToolOutput(string message)
	{
	Console.WriteLine("-> " + message);
	}

Note that MsTest displays both standard output and TestContext output. The TestContext is not mixed up and is written correctly in the sample provided. Only the standard output is incorrect. Unfortunately, MsTest displays the standard output first.

If you don't like the extra writing to standard output, you can mitigate this by registering your own TraceListener:

[assembly: RuntimePlugin(typeof(Plugin))]

namespace LogMixCheck.Test.Steps;

public sealed class Plugin : IRuntimePlugin
{
    public void Initialize(RuntimePluginEvents runtimePluginEvents, RuntimePluginParameters runtimePluginParameters, UnitTestProviderConfiguration unitTestProviderConfiguration)
    {
        runtimePluginEvents.CustomizeTestThreadDependencies += RuntimePluginEvents_CustomizeTestThreadDependencies;
    }

    private void RuntimePluginEvents_CustomizeTestThreadDependencies(object? sender, CustomizeTestThreadDependenciesEventArgs e)
    {
        e.ObjectContainer.RegisterTypeAs<CustomTraceListener, ITraceListener>();
    }
}

public sealed class CustomTraceListener : ITraceListener
{
    private readonly IObjectContainer container;
    private readonly TestContext testContext;

    public CustomTraceListener(IObjectContainer container, TestContext testContext)
    {
        this.container = container;
        this.testContext = testContext;
    }

    TestContext GetTestContext()
    {
        var contextManager = container.Resolve<IContextManager>();
        var scenarioContext = contextManager.ScenarioContext;
        if (scenarioContext is null)
            return this.testContext;
        return scenarioContext.ScenarioContainer.Resolve<TestContext>();
    }

    public void WriteTestOutput(string message)
    {
        var testContext = GetTestContext();
        testContext.WriteLine(message);
    }

    public void WriteToolOutput(string message)
    {
        var testContext = GetTestContext();
        testContext.WriteLine("-> " + message);
    }
}

I'm not sure why Reqnroll writes to standard output and TestContext for MsTest. We don't do this in other test frameworks we don't do this, e.g. NUnit:

Reqnroll/Plugins/Reqnroll.NUnit.ReqnrollPlugin/NUnitTraceListener.cs

Lines 19 to 35 in 4642769

	public override void WriteTestOutput(string message)
	{
	TestContext.WriteLine(message);
	// avoid duplicate output entries in NUnit for scenario, forward only if no scenario active
	if (_contextManager.Value.ScenarioContext == null)
	base.WriteTestOutput(message);
	}
	public override void WriteToolOutput(string message)
	{
	TestContext.WriteLine("-> " + message);
	// avoid duplicate output entries in NUnit for scenario, forward only if no scenario active
	if (_contextManager.Value.ScenarioContext == null)
	base.WriteToolOutput(message);
	}

avoid duplicate output entries in NUnit for scenario, forward only if no scenario active

Perhaps we can should consider changing this? 🤔

I hope this helps. 🙂

[sampath-ganesan]

Thanks for the suggestion, I will try to implement this

[sampath-ganesan]

Hi @obligaron,
above suggestion is working, that suggestion will not show step details in Standard Output

so i modified it as in Reqnroll and this is how it will look like this

`namespace LogMixCheck.Properties
{
using System;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using Reqnroll.BoDi;
using Reqnroll.Infrastructure;
using Reqnroll.Plugins;
using Reqnroll.Tracing;
using Reqnroll.UnitTestProvider;

public sealed class Plugin : IRuntimePlugin
{
    public void Initialize(RuntimePluginEvents runtimePluginEvents, RuntimePluginParameters runtimePluginParameters, UnitTestProviderConfiguration unitTestProviderConfiguration)
    {
        runtimePluginEvents.CustomizeTestThreadDependencies += this.RuntimePluginEvents_CustomizeTestThreadDependencies;
    }

    private void RuntimePluginEvents_CustomizeTestThreadDependencies(object sender, CustomizeTestThreadDependenciesEventArgs e)
    {
        e.ObjectContainer.RegisterTypeAs<CustomTraceListener, ITraceListener>();
    }
}

public sealed class CustomTraceListener : ITraceListener
{
    private readonly IObjectContainer container;
    private readonly TestContext testContext;

    public CustomTraceListener(IObjectContainer container, TestContext testContext)
    {
        this.container = container;
        this.testContext = testContext;
    }

    public void WriteTestOutput(string message)
    {
        var testContext = this.GetTestContext();
        testContext.WriteLine(message);
        Console.WriteLine(message);
    }

    public void WriteToolOutput(string message)
    {
        var testContext = this.GetTestContext();
        testContext.WriteLine(message);
        Console.WriteLine(message);
    }

    private TestContext GetTestContext()
    {
        var contextManager = this.container.Resolve<IContextManager>();
        var scenarioContext = contextManager.ScenarioContext;
        if (scenarioContext is null)
        {
            return this.testContext;
        }

        return scenarioContext.ScenarioContainer.Resolve<TestContext>();
    }
}

}`

FYI, @gasparnagy, @ajeckmans, @Code-Grump