testfx: Getting test output that breaks Visual Studio Devops Build pipeline (MSTest.Adapter v2.2.3)

Well, to be honest, it was sheer luck that lead me to this workaround: I was merely trying to dump some information while investigating with my Console.WriteLine stuff… And then, I’m not that surprised the hack works with assembly level init/cleanup code as well: ultimately it taps into the same LogCleanupResult method deep down the test adapter.

@Haplois I think the parts to investigate are what happens during initialization and cleanup steps relating to console redirections. Mongo2go may be specifically at fault (although it didn’t bother MSTest v2.1), but I suspect we’d end up with the same errors if we were to use any code that spawns a process and monitors its output.

I know from experience that Windows Console redirection is a b*tch to get right so I had a look at how this behaves on Linux: I ran my test test on WSL and… it just works!

Hi @odalet - thank you for all your work here. Since you did all the investigation, if you open the PR; I can guide you on the tests.

@Haplois I’ve just cloned the testfx repo, walked down the call stack of my exception, and I think I came up with a fix:

I noticed that in TestExecutionManager.LogCleanupResult, one makes sure that messages are neither null nor empty before passing them to testExecutionRecorder.SendMessage.

However (I took the liberty to examine the implementation of ITestExecutionRecorder from my Visual Studio installation), this SendMessage method throws if the message is null or whitespace! And I confirmed that, with my use case, I was indeed retrieving some output full of whitespaces and cr/lf…

So I replaced the calls to string.IsNullOrEmpty with string.IsNullOrWhitespace (and added one such test inside the loop over warnings as well) and tried it against my test. And it works.

Here is the proposed code for TestExecutionManager.LogCleanupResult:

private void LogCleanupResult(ITestExecutionRecorder testExecutionRecorder, RunCleanupResult result)
{
	Debug.Assert(testExecutionRecorder != null, "Logger should not be null");

	if (!string.IsNullOrWhiteSpace(result.StandardOut))
	{
		testExecutionRecorder.SendMessage(TestMessageLevel.Informational, result.StandardOut);
	}

	if (!string.IsNullOrWhiteSpace(result.DebugTrace))
	{
		testExecutionRecorder.SendMessage(TestMessageLevel.Informational, result.DebugTrace);
	}

	if (!string.IsNullOrWhiteSpace(result.StandardError))
	{
		testExecutionRecorder.SendMessage(
			MSTestSettings.CurrentSettings.TreatClassAndAssemblyCleanupWarningsAsErrors ? TestMessageLevel.Error : TestMessageLevel.Warning,
			result.StandardError);
	}

	if (result.Warnings != null)
	{
		foreach (string warning in result.Warnings)
		{
			if (!string.IsNullOrWhiteSpace(warning))
			{
				testExecutionRecorder.SendMessage(
					MSTestSettings.CurrentSettings.TreatClassAndAssemblyCleanupWarningsAsErrors ? TestMessageLevel.Error : TestMessageLevel.Warning,
					warning);
			}
		}
	}
}		

What’s left:

• This does not explain why these tests of ours did not fail when using v2.1 of testfx. I can only suppose that other parts of the code were changed that previously prevented these whitespace strings from reaching LogCleanupResult or maybe the previous code didn’t capture at all the output from external processes…
• Proposing a proper PR; but for that, I’m afraid I won’t know what to implement in Unit Tests… I just discovered the code base today. So, unless this change is deemed harmless enough to not require unit tests, it may be more efficient to let you or anyone here at Microsoft handle the PR or, alternatively, guide me toward the correct place for unit testing this.

Tell me what you think!

@odalet, Thanks for all the investigation, hacking and narrowing down! I’ll look into this as well and try to see if we need fix this on our side.

@odalet that is a brilliant narrowing down. @Haplois I can confirm I am using Mongo2Go as well in my tests.

Haa haa… @odalet you wonderful hacker 😆 It works! Here is our Assembly level initialization MockMongoFactory is just a custom class where we initialize the DB with some custom params.

using Microsoft.VisualStudio.TestTools.UnitTesting;

using MyCompany.TestHelpers.Tests.Common.Mocks;
using System;

[TestClass]
public class TestStartup
{
    public static MockMongoFactory MockMongoFactory { get; set; }


    [AssemblyInitialize]
    public static void AssemblyInitialize(TestContext context)
    {
        TestStartup.MockMongoFactory = new MockMongoFactory();

    }

    [AssemblyCleanup]
    public static void AssemblyCleanup()
    {
        //Console.Out.WriteLine("Before Dispose");
        TestStartup.MockMongoFactory.Dispose();
        Console.Out.WriteLine("After Dispose of Tests.Integration");
    }
}

@Haplois Here is the exception I get if we don’t use the Console.Out.WriteLine("...") hack. Notice the first one Tests.Integration passes and the second one Tests.Local fails (because the second one doesn’t have the hack yet).

Also I am using the release version MSTest.TestAdapter v2.2.4. So just confirming @odalet 's workaround works for previous builds too.

    MSTest Executor: Test Parallelization enabled for C:\Workspaces\MyCompany\App\Main\Tests.Integration\bin\x64\Debug\net48\Tests.Integration.dll (Workers: 12, Scope: ClassLevel).


After Dispose of Tests.Integration

MSTest Executor: Test Parallelization enabled for C:\Workspaces\MyCompany\App\Main\Tests.Local\bin\x64\Debug\net48\Tests.Local.dll (Workers: 12, Scope: ClassLevel).
An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.
Parameter name: message
Stack trace:
   at Microsoft.VisualStudio.TestPlatform.Common.Logging.TestSessionMessageLogger.SendMessage(TestMessageLevel testMessageLevel, String message)
   at Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestExecutionManager.LogCleanupResult(ITestExecutionRecorder testExecutionRecorder, RunCleanupResult result)
   at Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestExecutionManager.RunCleanup(ITestExecutionRecorder testExecutionRecorder, UnitTestRunner testRunner)
   at Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestExecutionManager.ExecuteTestsInSource(IEnumerable`1 tests, IRunContext runContext, IFrameworkHandle frameworkHandle, String source, Boolean isDeploymentDone)
   at Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestExecutionManager.ExecuteTests(IEnumerable`1 tests, IRunContext runContext, IFrameworkHandle frameworkHandle, Boolean isDeploymentDone)
   at Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestExecutionManager.RunTests(IEnumerable`1 tests, IRunContext runContext, IFrameworkHandle frameworkHandle, TestRunCancellationToken runCancellationToken)
   at Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.MSTestExecutor.RunTests(IEnumerable`1 tests, IRunContext runContext, IFrameworkHandle frameworkHandle)
   at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.RunTestsWithTests.InvokeExecutor(LazyExtension`2 executor, Tuple`2 executorUri, RunContext runContext, IFrameworkHandle frameworkHandle)
   at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.BaseRunTests.<>c__DisplayClass48_0.<RunTestInternalWithExecutors>b__0()
   at Microsoft.VisualStudio.TestPlatform.PlatformAbstractions.PlatformThread.<>c__DisplayClass0_0.<Run>b__0()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.VisualStudio.TestPlatform.PlatformAbstractions.PlatformThread.Run(Action action, PlatformApartmentState apartmentState, Boolean waitForCompletion)
   at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.BaseRunTests.TryToRunInSTAThread(Action action, Boolean waitForCompletion)
   at Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Execution.BaseRunTests.RunTestInternalWithExecutors(IEnumerable`1 executorUriExtensionMap, Int64 totalTests)

I managed to narrow down the issue to a rather simple repro (note that you’ll need to add Mongo2go:

using System;
using System.Diagnostics.CodeAnalysis;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using Mongo2Go;

namespace MSTestTest
{
    [TestClass, ExcludeFromCodeCoverage]
    public class UnitTests
    {
        private static MongoDbRunner runner;

        [ClassInitialize, SuppressMessage("Style", "IDE0060:Remove unused parameter", Justification = "Required by VSTest conventions")]
        public static void Setup(TestContext context)
        {
            //Console.Out.WriteLine("Before Start");
            runner = MongoDbRunner.Start();
            //Console.Out.WriteLine("After Start");
        }

        [ClassCleanup]
        public static void Teardown()
        {
            //Console.Out.WriteLine("Before Dispose");
            runner.Dispose();
            //Console.Out.WriteLine("After Dispose");
        }

        [TestMethod]
        public void Fake_test() => Assert.IsTrue(true);
    }
}

This test reproduces the error that prevent later tests to execute (in Visual Studio). What’s interesting is that:

• If I uncomment either the first or the second Console.WriteLine in the Cleanup method, the error goes away.
• If I do so in the Initialize method, the error does not go away and as a side note, the WriteLine calls do not appear in the Tests output…
• MongoDbRunner.Start() starts an external process (that runs mongo.exe) that in turn writes to its console. I suppose (did not check) that Mongo2go redirects mongo.exe out and err outputs.

Well all this to say that I think there is some buggy behavior both in the Test initialization and cleanup methods with respect to console output maybe when some of this comes from out/err files redirected from an external process…

Hope this helps

@odalet thanks! If it’s a different issue you’re welcome to create a new issue for better visibility.