Test logs get mixed across test cases

[AArnott]

Description

dotnet test (and Test Explorer in VS) both collect messages logged by tests to the wrong tests.
I am using xunit's ITestOutputHelper to log messages, and yet these messages which are meant to be collected under "Standard Output" on a per-test basis are getting mixed up, which makes analyzing test failures very difficult or impossible.

It seems to depend on logging taking place after the test class's DisposeAsync method completes, such that test 1 is actually logging after it allegedly finished, thus overlapping into test 2's time slice.
That said, since concurrent test execution is supported, it seems that logging is already distinguishable between concurrent tests. So why do the logs get mixed up when one test logs after its disposal?

The tested product may have async shutdown behavior that the test's DisposeAsync method cannot wait on, which is why logging happens beyond the DisposeAsync method. But I would like to capture such logs (if the test runner is still running) and associate them with the right test.

We decided this is an xunit bug rather than in the VSTest platform because we found evidence that the corruption happens within Xunit.Sdk.TestOutputHelper, and by the time the xunit.runner.visualstudio library hands off to the VS Test platform with the test result, the corruption has already occurred.

Steps to reproduce

Take this minimal repro:
TestProject1.zip

dotnet test -d log.txt -l "trx;LogFileName=console.trx"

Open the console.trx file in VS.
Go through each of the 5 tests to look at their logged messages.
Each message is prefixed with a unique test ID (and elapsed time) to record which test invocation it came from.

Expected behavior

Each of the tests have their own logged messages. This would manifest as each message starting with the same number as every other line.

Actual behavior

I see some test logs include multiple of these unique ID prefixes:

It also reproduces when tests are run in Test Explorer:

Diagnostic logs

logs.zip

Environment

Windows
.NET SDK 5.0.400

[drvic10k]

why was this issue closed? was it fixed?

[AArnott]

@drvic10k Why do you say it was closed? It's active now, and the history on the issue doesn't suggest it was ever closed. Perhaps you were confused by the link from a closed issue that appears in this issue's history?

[drvic10k]

@AArnott you are right, that is indeed a label from the linked issue

[slawomirbrys]

Hi @AArnott,
Do you know if there is any progress on that bug?
I've just encountered the same bug on my local tests. I tried as much as possible to have concrete logs per my test (that is quite extensive in logging) and now seems that everything is mixed up 🥴. It will be very hard to quickly diagnose issues with tests on CI/CD until someone will run single test on local machine and have proper logs.

[AArnott]

None that I've heard of.

[slawomirbrys]

Ok, thank you.

[bradwilson]

This bug comes because we resolve class constructor arguments once per class, so there is a shared instance of the test output helper being used for all tests in the same class:

xunit/src/xunit.execution/Sdk/Frameworks/Runners/XunitTestClassRunner.cs

Lines 226 to 230 in e022e5c

	if (parameter.ParameterType == typeof(ITestOutputHelper))
	{
	argumentValue = new TestOutputHelper();
	return true;
	}

It gets emptied and reset between tests:

xunit/src/xunit.execution/Sdk/Frameworks/Runners/XunitTestRunner.cs

Lines 64 to 73 in e022e5c

	if (testOutputHelper != null)
	testOutputHelper.Initialize(MessageBus, Test);
	var executionTime = await InvokeTestMethodAsync(aggregator);
	if (testOutputHelper != null)
	{
	output = testOutputHelper.Output;
	testOutputHelper.Uninitialize();
	}

By using it outside of its intended scope, you're writing to another test, since we're reusing the instance.

What would you prefer be done here @AArnott?

• Ignore the output that's done beyond scope
• Report the attempt to write output beyond scope as a fatal error

[bradwilson]

I should point out that in v3 this is already fixed and it takes the "ignore" stance.

[bradwilson]

No dispose messages anywhere (this is your test project, updated to v3)

Recording.2024-06-16.150259.mp4

[bradwilson]

The "ignore" behavior is available in 2.8.2-pre.15 https://xunit.net/docs/using-ci-builds

To be clear, your call to logger.WriteLine() will now be throwing, but since nobody is observing the task you spun off, the exception will be ignored (and the test will continue to pass):

Recording.2024-06-16.163019.mp4

[AArnott]

Great. Matching behavior between v2 and v3 seems like goodness.

Between silently failing and throwing, I'd prefer throwing so that the problem will usually be discoverable sooner than when we have some other test failure and we have to search the logs only to find that they're incomplete.

[bradwilson]

I'll add a new issue to make sure all the runners are subscribed to AppDomain.CurrentDomain.UnhandledException.