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

[sumitkm]

Description

I was holding back on v2.2.1 and using v2.1.2 because of issue #789

When I upgraded to v2.2.2 and then to v2.2.3 I find the tests are running inside Visual Studio and the breaking behavior in 2.2.1 is resolved; however after running all the tests In the Test Output window I notice the following message

---------- Starting test run ----------
MSTest Executor: Test Parallelization enabled for C:\Path\To\My\Test\Project\bin\x64\Debug\net48\Tests.Integration.dll (Workers: 12, Scope: ClassLevel).
An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.
Parameter name: message
========== Test run finished: 693 Tests run in 48.9 sec (693 Passed, 0 Failed, 0 Skipped) ==========

This doesn't cause any issues in Visual studio but when they are executed in Visual Studio DevOps pipeline, the mention of the word exception causes the Pipeline task to fail, even though all tests have passed.

I have rolled back to 2.1.2 multiple times, and after reverting, the above error message goes away.

Steps to reproduce

1. Take test project with MSTest.Adapter version 2.1.2
2. Upgrade to 2.2.3

Expected behavior

All tests should pass without any messages mentioning any exception, e.g. when running same tests with v2.1.2 give the following message at end of run

---------- Starting test run ----------
MSTest Executor: Test Parallelization enabled for C:\Path\To\My\Test\Project\bin\x64\Debug\net48\Tests.Integration.dll (Workers: 12, Scope: ClassLevel).
========== Test run finished: 693 Tests run in 50.4 sec (693 Passed, 0 Failed, 0 Skipped) ==========

Actual behavior

I get the following message

---------- Starting test run ----------
MSTest Executor: Test Parallelization enabled for C:\Path\To\My\Test\Project\bin\x64\Debug\net48\Tests.Integration.dll (Workers: 12, Scope: ClassLevel).
An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.
Parameter name: message
========== Test run finished: 693 Tests run in 48.9 sec (693 Passed, 0 Failed, 0 Skipped) ==========

I could be missing some Run parameters, but I couldn't figure out which one exactly, quickly. Any pointers appreciated.

Environment

Visual Studio 2019 16.9.1
Windows 10 Enterprise x64
Test environment set to x64 explicitly
Nuget Package Style: PackageReference

Package references in the project

<ItemGroup>
    <PackageReference Include="Castle.Core" Version="4.4.1" />
    <PackageReference Include="EfCore.TestSupport" Version="3.2.0" />
    <PackageReference Include="FluentAssertions" Version="5.10.3" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.InMemory" Version="3.1.13" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.Sqlite.NetTopologySuite" Version="3.1.13" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer.NetTopologySuite" Version="3.1.13" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Abstractions" Version="5.0.0" />
    <PackageReference Include="Moq" Version="4.16.1" />
    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="16.9.1" />
    <PackageReference Include="MSTest.TestAdapter" Version="2.2.3" />
    <PackageReference Include="MSTest.TestFramework" Version="2.2.3" />
    <PackageReference Include="Newtonsoft.Json.Schema" Version="3.0.14" />
    <PackageReference Include="sqlite" Version="3.13.0" />
    <PackageReference Include="System.ValueTuple" Version="4.5.0" />
  </ItemGroup>

[Haplois]

Hi @sumitkm,

Are you getting that message after cleaning your solution?
If yes, can you try removing the hidden .vs folder in your solution root after closing Visual Studio and try again to see if you still get it?

[sumitkm]

@Haplois Unfortunately yes. I have cleaned the solution, closed Visual Studio, remove all bin/obj folders manually, removed .vs folder manually... reloaded... clean, rebuild... no avail. Still get the same error.

Please note this is not like old executor bugs that happened due to missing DLL... there are no missing DLL warnings. It is clearly saying it is missing a parameter, possibly named message somewhere.

[sumitkm]

Update: I tried to repro it with a standalone solution and project, I got the same issue when I upgraded from 2.1.2 to to 2.2.3. But after I closed VS, deleted .vs folder and reloaded the standalone project, the message went away. I am going to dig a little further into this.

[Haplois]

Yes, thank you for the clarification.

Could you run your tests from vstest.console.exe using the --diag option and send us the logs? (Test console should be on "C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\common7\ide\CommonExtensions\Microsoft\TestWindow\vstest.console.exe")

vstest.console.exe C:\Path\To\My\Test\Project\bin\x64\Debug\net48\Tests.Integration.dll --Diag:diag.log

And please share the resulting diag*.log file with us.

[sumitkm]

Hey @Haplois many thanks for the command line syntax. I have the files but these contain a bucket load of internal API details that I cannot share publicly.

Here's the bit from diag[timestamp].log file that might be of interest

TpTrace Verbose: 0 : 19676, 10, 2021/03/16, 18:50:51.727, 861819278695, testhost.net48.exe, TestRunCache: OnNewTestResult: Notified the onCacheHit callback.
TpTrace Verbose: 0 : 19676, 9, 2021/03/16, 18:50:51.869, 861820699161, testhost.net48.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:64737 localEndPoint: 127.0.0.1:64738
TpTrace Information: 0 : 19676, 15, 2021/03/16, 18:50:52.063, 861822636171, testhost.net48.exe, MSTest - Executed cleanup methods.
TpTrace Error: 0 : 19676, 3, 2021/03/16, 18:50:52.265, 861824664225, testhost.net48.exe, BaseRunTests.RunTestInternalWithExecutors: An exception occurred while invoking executor executor://mstestadapter/v2. System.ArgumentException: The parameter cannot be null or empty.
Parameter name: message
   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).
TpTrace Error: 0 : 19676, 3, 2021/03/16, 18:50:52.265, 861824666123, testhost.net48.exe, An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.
Parameter name: message
TpTrace Verbose: 0 : 19676, 3, 2021/03/16, 18:50:52.265, 861824666723, testhost.net48.exe, TestRequestHandler.SendData:  sending data from testhost: {"Version":5,"MessageType":"TestSession.Message","Payload":{"MessageLevel":2,"Message":"An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.\r\nParameter name: message"}}
TpTrace Information: 0 : 19676, 3, 2021/03/16, 18:50:52.267, 861824688479, testhost.net48.exe, Sending test run complete
TpTrace Verbose: 0 : 19676, 3, 2021/03/16, 18:50:52.274, 861824753915, testhost.net48.exe, TestRequestHandler.SendData:  sending data from testhost: {"Version":5,"MessageType":"TestExecution.Completed","Payload":{"TestRunCompleteArgs":{"TestRunStatistics":{"ExecutedTests":693,"Stats":{"Passed":693}},"IsCanceled":false,"IsAborted":false,"Error":null,"AttachmentSets":[],"ElapsedTimeInRunningTests":"00:00:42.4524916","Metrics":{}},"LastRunTests":{"NewTestResults":[],"TestRunStatistics":{"ExecutedTests":693,"Stats":{"Passed":693}},"ActiveTests":[]},"RunAttachments":[],"ExecutorUris":[]}}
TpTrace Verbose: 0 : 19676, 3, 2021/03/16, 18:50:52.274, 861824756598, testhost.net48.exe, BaseRunTests.RunTests: Run is complete.
TpTrace Verbose: 0 : 19676, 9, 2021/03/16, 18:50:52.275, 861824765510, testhost.net48.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:64737 localEndPoint: 127.0.0.1:64738
TpTrace Information: 0 : 19676, 9, 2021/03/16, 18:50:52.275, 861824766331, testhost.net48.exe, TestRequestHandler.ProcessRequests: received message: (TestSession.Terminate) -> null
TpTrace Information: 0 : 19676, 9, 2021/03/16, 18:50:52.275, 861824766645, testhost.net48.exe, Session End message received from server. Closing the connection.
TpTrace Information: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824770259, testhost.net48.exe, SocketClient.Stop: Stop communication from server endpoint: 127.0.0.1:064737
TpTrace Information: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824770622, testhost.net48.exe, SocketClient: Stop: Cancellation requested. Stopping message loop.
TpTrace Information: 0 : 19676, 1, 2021/03/16, 18:50:52.276, 861824771636, testhost.net48.exe, SocketClient.Stop: Stop communication from server endpoint: 127.0.0.1:064737
TpTrace Verbose: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824771938, testhost.net48.exe, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer.
TpTrace Information: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824772375, testhost.net48.exe, Closing the connection !
TpTrace Information: 0 : 19676, 1, 2021/03/16, 18:50:52.276, 861824772072, testhost.net48.exe, SocketClient: Stop: Cancellation requested. Stopping message loop.
TpTrace Verbose: 0 : 19676, 1, 2021/03/16, 18:50:52.276, 861824773342, testhost.net48.exe, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer.
TpTrace Information: 0 : 19676, 1, 2021/03/16, 18:50:52.276, 861824774516, testhost.net48.exe, Testhost process exiting.
TpTrace Information: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824775707, testhost.net48.exe, SocketClient.PrivateStop: Stop communication from server endpoint: 127.0.0.1:064737, error:
TpTrace Verbose: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824776998, testhost.net48.exe, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer.
TpTrace Verbose: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824777329, testhost.net48.exe, TcpClientExtensions.MessageLoopAsync: exiting MessageLoopAsync remoteEndPoint: 127.0.0.1:64737 localEndPoint: 127.0.0.1:64738
TpTrace Verbose: 0 : 19676, 9, 2021/03/16, 18:50:52.276, 861824777329, testhost.net48.exe, TcpClientExtensions.MessageLoopAsync: exiting MessageLoopAsync remoteEndPoint: 127.0.0.1:64737 localEndPoint: 127.0.0.1:64738

Here's the bit from diag.log

TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:51.729, 861819292751, vstest.console.exe, TestRunRequest:SendTestRunStatsChange: Completed.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:51.729, 861819293201, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:64738 localEndPoint: 127.0.0.1:64737
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.265, 861824667761, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:64738 localEndPoint: 127.0.0.1:64737
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.265, 861824668913, vstest.console.exe, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":5,"MessageType":"TestSession.Message","Payload":{"MessageLevel":2,"Message":"An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.\r\nParameter name: message"}}
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.266, 861824669928, vstest.console.exe, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:51.728, 861819292137, vstest.console.exe, TestRunRequest:SendTestRunStatsChange: Starting.
TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:52.266, 861824670602, vstest.console.exe, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.266, 861824671054, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:64738 localEndPoint: 127.0.0.1:64737
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.274, 861824755158, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:64738 localEndPoint: 127.0.0.1:64737
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.274, 861824756255, vstest.console.exe, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":5,"MessageType":"TestExecution.Completed","Payload":{"TestRunCompleteArgs":{"TestRunStatistics":{"ExecutedTests":693,"Stats":{"Passed":693}},"IsCanceled":false,"IsAborted":false,"Error":null,"AttachmentSets":[],"ElapsedTimeInRunningTests":"00:00:42.4524916","Metrics":{}},"LastRunTests":{"NewTestResults":[],"TestRunStatistics":{"ExecutedTests":693,"Stats":{"Passed":693}},"ActiveTests":[]},"RunAttachments":[],"ExecutorUris":[]}}
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.275, 861824763864, vstest.console.exe, TestRequestSender.EndSession: Sending end session.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.275, 861824765514, vstest.console.exe, ProxyOperationManager.Close: waiting for test host to exit for 100 ms
TpTrace Warning: 0 : 14436, 7, 2021/03/16, 18:50:52.294, 861824950843, vstest.console.exe, TestHostManagerCallbacks.ErrorReceivedCallback Test host standard error line: 
TpTrace Verbose: 0 : 14436, 10, 2021/03/16, 18:50:52.318, 861825192751, vstest.console.exe, TestHostProvider.ExitCallBack: Host exited starting callback.
TpTrace Information: 0 : 14436, 10, 2021/03/16, 18:50:52.318, 861825194855, vstest.console.exe, TestHostManagerCallbacks.ExitCallBack: Testhost processId: 19676 exited with exitcode: 0 error: ''
TpTrace Verbose: 0 : 14436, 10, 2021/03/16, 18:50:52.319, 861825197131, vstest.console.exe, CrossPlatEngine.TestHostManagerHostExited: calling on client process exit callback.
TpTrace Warning: 0 : 14436, 6, 2021/03/16, 18:50:52.319, 861825198053, vstest.console.exe, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process.
TpTrace Information: 0 : 14436, 10, 2021/03/16, 18:50:52.319, 861825198797, vstest.console.exe, TestRequestSender.OnClientProcessExit: Test host process exited. Standard error: 
TpTrace Information: 0 : 14436, 10, 2021/03/16, 18:50:52.319, 861825200668, vstest.console.exe, SocketServer.Stop: Stop server endPoint: 127.0.0.1:64737
TpTrace Information: 0 : 14436, 10, 2021/03/16, 18:50:52.319, 861825201146, vstest.console.exe, SocketServer.Stop: Cancellation requested. Stopping message loop.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.338, 861825389183, vstest.console.exe, TestRunRequest:TestRunComplete: Starting. IsAborted:False IsCanceled:False.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.338, 861825390587, vstest.console.exe, TestRequestSender.EndSession: Sending end session.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.338, 861825391600, vstest.console.exe, ProxyOperationManager.Close: waiting for test host to exit for 100 ms
TpTrace Warning: 0 : 14436, 6, 2021/03/16, 18:50:52.338, 861825392052, vstest.console.exe, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process.
TpTrace Warning: 0 : 14436, 6, 2021/03/16, 18:50:52.338, 861825394050, vstest.console.exe, TestLoggerManager.HandleTestRunStatsChange: Ignoring as the object is disposed.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.338, 861825394659, vstest.console.exe, TestLoggerManager.HandleTestRunComplete: Ignoring as the object is disposed.
TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:52.339, 861825402668, vstest.console.exe, TestRunRequest:TestRunComplete: Completed.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.339, 861825404272, vstest.console.exe, TestRequestSender.SetOperationComplete: Setting operation complete.
TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:52.339, 861825404801, vstest.console.exe, SocketServer.Stop: Stop server endPoint: 127.0.0.1:64737
TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:52.339, 861825405196, vstest.console.exe, SocketServer.Stop: Cancellation requested. Stopping message loop.
TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:52.340, 861825408582, vstest.console.exe, SocketServer.PrivateStop: Stop server endPoint: 127.0.0.1:64737 error: 
TpTrace Verbose: 0 : 14436, 1, 2021/03/16, 18:50:52.340, 861825409524, vstest.console.exe, TestRunRequest.Dispose: Starting.
TpTrace Information: 0 : 14436, 1, 2021/03/16, 18:50:52.340, 861825410212, vstest.console.exe, TestRunRequest.Dispose: Completed.
TpTrace Information: 0 : 14436, 1, 2021/03/16, 18:50:52.340, 861825410630, vstest.console.exe, TestRequestManager.RunTests: run tests completed.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.340, 861825411047, vstest.console.exe, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer.
TpTrace Information: 0 : 14436, 6, 2021/03/16, 18:50:52.340, 861825411586, vstest.console.exe, SocketServer.Stop: Raise disconnected event endPoint: 127.0.0.1:64737 error: 
TpTrace Information: 0 : 14436, 1, 2021/03/16, 18:50:52.340, 861825412367, vstest.console.exe, RunTestsArgumentProcessor:Execute: Test run is completed.
TpTrace Verbose: 0 : 14436, 1, 2021/03/16, 18:50:52.340, 861825414800, vstest.console.exe, Executor.Execute: Exiting with exit code of 1
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.341, 861825418085, vstest.console.exe, TestRequestSender: OnTestRunAbort: Operation is already complete. Skip error message.
TpTrace Verbose: 0 : 14436, 6, 2021/03/16, 18:50:52.341, 861825418676, vstest.console.exe, TcpClientExtensions.MessageLoopAsync: exiting MessageLoopAsync remoteEndPoint: 127.0.0.1:64738 localEndPoint: 127.0.0.1:64737

I am happy to share the full files privately you can use [email protected] address to send me a location to upload the logs.

[sumitkm]

Digging further, I can see out of the three Test projects I have, 2 are throwing the exception and 1 is not. So it narrows it down to an environment-ish issue.

Also I have updated the PackageReferences list in the original bug report above. I had inadvertently copied the packages from the Project that is actually working...

I'll keep digging in an attempt to reproduce it in a shareable project.

[Haplois]

Thank you, I wasn't able to reproduce this; please share with the repro if you are able to create one.

[sumitkm]

Quick update. I upgraded our project to latest Test Framework and tried out the latest adapter got stuck again. This time the behaviour is slightly different.

It is a mix of the 2.2.1 issues and the above issue.

I am back to 2 set of Unit Test projects being completely ignored by the test framework. It shows the Tree in Text Explorer but doesn't run them.

After carefully installing/uninstalling various combinations of MSTest's Nuget packages. I find that the following combination is able to discover and run all my tests.

Microsoft.NET.Test.Sdk v16.9.4
MSTest.TestFramework v2.2.3
MSTest.TestAdapter v2.1.2

As soon as I upgrade to MSTest.TestAdapter v2.2.3 2/3rds of my tests fail to get recognised and are not executed.

I am going to keep trying to isolate this issue and find a reproable Project that I can share here.

[Haplois]

@sumitkm, can you try with our latest preview (v2.2.4-preview-20210331-02)? If the issue persists, let's schedule a call on or after Tuesday. I'll send an email to you.

[sumitkm]

Thanks again for all your support @Haplois . I tried updating all the MSTest dependencies to the latest from the Test feed. but no dice.

As mentioned earlier only one of my three test projects run without the following error (even with new the pre packages)

An exception occurred while invoking executor 'executor://mstestadapter/v2': The parameter cannot be null or empty.
Parameter name: message

The Tests.Unit project doesn't throw the above error.

If I run each test project separately, all tests run.

However if I click Run all Tests from the explorer it first runs Tests.Integration, all tests pass but still I get the above exception and the tests in the other two projects are not executed. I have to then run the other two projects manually. This is fine, but the error on Tests.Integration will still break Visual Studio Build pipeline.

Cheers.

[odalet]

I experienced the same issue and for now reverted to v2.1.2 of both MSTest.TestAdapter and MSTest.TestFramework...

[Haplois]

@sumitkm, @odalet could you test it with our latest preview bits? If the issue still persists, is it possible to share a quick repro with us?

[odalet]

@Haplois Well, I don't seem to reproduce the The parameter cannot be null or empty. Parameter name: message error any more, but now I'm stuck with crashes of the test host in my CI... I suppose this is a completely different issue, but just FYI:

Using:

• MSTest.TestAdapter and MSTest.TestFramework version 2.2.5-preview-20210605-01
• Microsoft.NET.Test.Sdk 16.10.0
• Building on GitLab in a Debian Docker (.NET 5.0.202)

Test Execution:

$ dotnet test ${SOLUTION} --configuration Release --no-build --verbosity normal --logger:trx --logger:"junit;LogFilePath=./TestResults/{assembly}-test-result.xml;MethodFormat=Class;FailureBodyFormat=Verbose" /p:CollectCoverage=true /p:CoverletOutputFormat=opencover /p:CoverletOutput=./TestResults/
Build started 06/24/2021 07:57:40.
     1>Project "/builds/sii/ncore/ncore-messaging/src/AddUp.NCore.Messaging.sln" on node 1 (VSTest target(s)).
     1>ValidateSolutionConfiguration:
         Building solution configuration "Release|Any CPU".
Test run for /builds/sii/ncore/ncore-messaging/src/UnitTests/UnitTests.AddUp.NCore.Messaging/bin/Release/netcoreapp3.1/UnitTests.AddUp.NCore.Messaging.dll (.NETCoreApp,Version=v3.1)
Microsoft (R) Test Execution Command Line Tool Version 16.9.4
Copyright (c) Microsoft Corporation.  All rights reserved.
Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
  Passed Publishing_throws_when_not_connected [49 ms]
  Passed Publishing_throws_when_disconnected [8 ms]
  Passed Publishing_works_when_connected [16 ms]
  Passed Publishing_works_after_disconnection_then_reconnection [< 1 ms]
  Passed Publishing_throws_when_not_connected [2 ms]
  Passed Publishing_throws_when_disconnected [< 1 ms]
  Passed Publishing_throws_when_passed_a_null_message [< 1 ms]
  Passed Publishing_works_when_connected [10 ms]
  Passed Publishing_works_after_disconnection_then_reconnection [< 1 ms]
  Passed VariableListPublisher_can_publish_a_single_string_variable [1 ms]
  Passed TryConnectAsync_is_cancelable [10 s]
  Passed TryConnectAsync_succeeds_if_given_enough_time [3 ms]
  Passed New_Bus_is_not_null [< 1 ms]
The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.ObjectDisposedException: Safe handle has been closed.
Object name: 'SafeHandle'.
   at System.Runtime.InteropServices.SafeHandle.DangerousAddRef(Boolean& success)
   at System.StubHelpers.StubHelpers.SafeHandleAddRef(SafeHandle pHandle, Boolean& success)
   at Interop.Kernel32.SetEvent(SafeWaitHandle handle)
   at System.Threading.EventWaitHandle.Set()
   at AddUp.NCore.Messaging.ConnectionTests.<>c__DisplayClass0_0.<TryConnectAsync_is_cancelable>b__0() in /builds/sii/ncore/ncore-messaging/src/UnitTests/UnitTests.AddUp.NCore.Messaging/Messaging/ConnectionTests.cs:line 27
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()
Results File: /builds/sii/ncore/ncore-messaging/src/UnitTests/UnitTests.AddUp.NCore.Messaging/TestResults/_runner-zv7u1nny-project-34-concurrent-0_2021-06-24_07_57_43.trx
Results File: ./TestResults/UnitTests.AddUp.NCore.Messaging-test-result.xml
Test Run Aborted.
Total tests: Unknown
     Passed: 13
 Total time: 45.9657 Seconds
     1>Done Building Project "/builds/sii/ncore/ncore-messaging/src/AddUp.NCore.Messaging.sln" (VSTest target(s)) -- FAILED.
Build FAILED.
    0 Warning(s)
    0 Error(s)

[Haplois]

@odalet, can you share a quick repro? (If not can you run your tests with --diag and share the resulting *.log files with us?

[odalet]

I'm working on setting up a repro repository. Will post this here with details!

[Haplois]

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

[odalet]

So here is some bad news :(

Concerning the issue above, I did create a new issue (#887), but the thing is I was too quick at saying I didn't reproduce the issu any more; I was simply not looking at the right repository... .

So, I did apply version 2.2.5-preview-20210605-01 to test projects in the correct repository and:

• I still get only a part of my tests executed from Visual Studio when I select "Run all tests in view"

• and the Tests output console shows:

========== Test discovery finished: 1297 Tests found in 6,7 sec ==========
Aborting test discovery because a test run was requested.
Starting test discovery for requested test run
========== Starting test discovery ==========
No test is available in C:\work\repositories\addup-software\machinecontrol\src\ncore-server\Apps\ailc\bin\Debug\net472\ailc.exe. Make sure that test discoverer & executors are registered and platform & framework version settings are appropriate and try again.
========== Test discovery finished: 1494 Tests found in 14 sec ==========
========== Starting test run ==========
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)

========== Test run finished: 1078 Tests (1078 Passed, 0 Failed, 0 Skipped) run in 1 min ==========

I also upgraded Microsoft.NET.Test.Sdk from v16.9.4 to v16.10.0 (and I'm running VS Enterrprise 16.10.2), but same result...

[odalet]

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

[sumitkm]

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

[odalet]

@sumitkm thanks! And well, I couldn't have suspected you were also using mongo2go... I think (hope) the issue is not specific to mongo2go but rather arises when a subprocess is created with its console redirected.
Do you happen to use class initialization and cleanup methods as well?

[sumitkm]

We use [AssemblyInitialize] and [AssemblyCleanup], which kind of explains why all my tests in one assembly runs before failing to start the run of the next Test project.

I am going to try that Console.WriteLine hack and see if it behaves the same for me too. brb.

[sumitkm]

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)

[odalet]

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!

[Haplois]

@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]

@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!

[Haplois]

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.