Missing output with failed test stack traces for Assert.Multiple

[gps7]

Hi,
I am missing test output with stack traces for failed tests. For running example test fails but output not showing any information about failures nor even mention that test has failed:

[Test]
public void AssertMultiple()
{
Assert.Multiple(() =>
{
ValidateInteger();
Assert.That("a", Is.EqualTo("b"), "String");
ValidateInteger();
});
}

private void ValidateInteger() => Assert.That(1, Is.EqualTo(2), "Integer");
Running Nunit console with fallowing command line provides empty TEST_OUTPUT.log file:
"nunit3-console.exe" MyTests.dll --test=MyTests.TestClass.AssertMultiple --out=TEST_OUTPUT.log

I've tried to run v3.15.0. I assume this also affects the Test Centric since it shows failing test but output is always empty. I've expect to see not only failures but also 3 stack traces for 3 failures.

List of affected applications:

• Nunit-console
• Adapter @ Visual Studio
• TestCentric

I am using Framework 4.8.

This is a fallow up issue after creating issue #4129 at Nunit. Please refer to this item for more details if needed.

[CharliePoole]

The --out option tells the console runner to save any text output created by your tests in a file instead of displaying it at the console. Your tests do not create any text output, so the file is empty. This is how it is supposed to work. See https://docs.nunit.org/articles/nunit/running-tests/Console-Command-Line.html

Tests can create output by writing to the console or use of TestContext.Progress.

I'm closing this as not a bug, but in case you have added questions I'll still be able to see and answer your comments here.

[gps7]

Hi @CharliePoole , but this is the major problem for us since we have a lot of output entries (200Mb+!) and we want to see in this output failing tests including stack traces. We do not use TestContext.Progress but we use log4net since all our productive code is using this globally. I keep searching for a way to add failing test information into output file else this doubles work effort for test failure analysis: must find failing test with stack trace in TFS build then find the exact same line in the output file which never contains any test failures and analyze order of events. How else we can automate writing test failures to the output file?

Secondly, the problem which I face with multiple assert is that single stack trace shown to the test line but not including any internal failure stack traces which might be multiple ones too. Please check the Resharper output using Nunit tests and it provides all wanted information: image. Unfortunatelly, this is not fitting for our build servers but just for local debugging which is also in these case very complicated due scope of tests. Some test execution takes 5-10 minutes and hours to setup the environment to run. Thus this prevents us from using this feature and have to implement own handing which providing all internal stack trace information. Our complex and long tests have way much more levels in Assert.Multiple as result we cannot identify what exactly failed in the test without an internal stack trace in the Assert.Multiple. For us this is a clear bug since for such a case this is useless feature.

[CharliePoole]

I closed this because it talked about the --output option not working. The --output option indicates where any output is sent (i.e. to a file) but it doesn't create any more or less output. And by design it only affects things that are written from your tests not the overall output. The reason for this is that you can redirect the entire output (both from NUnit itself - like stack traces - and from your tests) by use of command-line redirection as supported by your particular operating system. The --output option was created to allow splitting the output, so your test's writes go to a separate place.

So it is now sounding as if your issue isn't with the --output option at all. It seems as if you are saying that you want NUnit's output to the console to contain multiple stack traces. when Assert.Multiple is used. Please stick with 3.15 and let's limit this issue to the console - forget about the adapter and GUI for now. (If you want to know why I say that see my comments here: nunit/nunit3-vs-adapter#987 )

Can you show me what is in your TestResult.xml file versus what is displayed by the console?

[gps7]

Thanks for clearing the idea, then still question for me how I can easily combine output file with test results (with stack traces) into single file?
With regards console output I can see full stack traces shown correctly in the console view as well as in the XML result file but still missing this information in the TestCentric as well as in Adapter used by Visual Studio by Test Explorer.

[CharliePoole]

@gps7 When using the console app from the command line, you can redirect the output with > FILENAME, if you are using windows. Isn't that what you are looking for? If not, please be more specific. I'll be happy to reopen this if you come up with some new functionality, which would be useful to all users.

NOTE: Use your own OS's command sequences if you aren't on windows. It's always a good idea say what OS you are using when posting an issue about an application, which runs under multiple operating systems.:-)

With respect to the other runners (TestCentric GUI and NUnit3 VS Adapter), this is the console runner project. As explained in more depth in the comments I linked above, their code and functionality is different. They each receive all the same information from the framework but of course may display it differently. That's what runners do!

My suggestion: make sure you are happy with this issue (the console) being closed and then see if you want to ask for new functionality from either of the other two runners, using their individual issue reporting.

[gps7]

We are using Windows 2016-2019 servers to execute tests on Azure DevOps server agents. Adding >FILENAME, I believe this will result in no visible build results on DevOps pages and it would print information shown in build page.
I think I discovered the rootcause of this problem on our build servers: for test coverage reports we need to have XML results in Nunit 2 format, thus our command line includes additional flag in Nunit console:

nunit3-console.exe My.Unittests.dll --test=My.TestClass --result=TEST_RESULT.xml;format=nunit2 --out=TEST_OUTPUT.log

The console view is still showing all stack traces, but TEST_RESULT.xml file is not showing all stack traces. Eliminating the format requirement is quit problematic until we find a solution to resolve with coverage report for Azure DevOps. So question what could be the reason to have different output for older Nunit format?

Here is part of result file with format=Nunit2:

              <test-case name="Eaf.Core.TestClass.AssertMultiple" executed="True" result="Failure" success="False" time="0.165" asserts="3">
                <failure>
                  <message><![CDATA[Multiple failures or warnings in test:

1. Integer
   Expected: 2
   But was: 1

2. String
   String lengths are both 1. Strings differ at index 0.
   Expected: "b"
   But was: "a"
   -----------^

3. Integer
   Expected: 2
   But was: 1

]]>

[CharliePoole]

OK... a number of things here...

You should experiment with redirection using the command-line as I suggested but also look at your Azure script to see if you can get the text output saved that way. (I'm not expert in Azure devops)

WRT the NUnit2 format, It's definitely true that it is unable to support Assert.Multiple correctly, since the feature never existed under NUnit2. Tell your coverage provider to support the NUnit 3 format, which has been around for about 10 years now!

However, I'm dubious that this is causing your problem because the internal format used by the framework and the console is still NUnit3. The information is there. You can prove this to yourself by adding a second --result option specifying nunit3 format. You'll get two files then.

Bottom line, if you can demonstrate that there is a real need for a way to redirect all output without turning off the console display, we can consider providing it. But you'll need to do the above experiments to show that.

[gps7]

I've eliminated output format requirement for results file which means Nunit 3 now used (checked the result file). Unfortunately, Build server still outputs same message as before. I don't have access to Azure scripts or have knowledge about it but I believe I found where the single stack trace coming. The result file has double information about failures and it contains stack trace to the test itself only and next XML block has detailed failure with separated stack traces:

As result build server shows only corresponding information:

The executed command on build server looks like this:
Execute OpenCover.Console (File version 4.6.519.0, Product version 4.6.519.0): D:\TfsBuildAgent2020\_work\288\s\Utility\NUnit3\OpenCover\OpenCover.Console.exe -target:"D:\TfsBuildAgent2020\_work\288\s\Utility\NUnit3\NUnit3-bin\nunit3-console.exe" -targetargs:""Eaf.UnitTests.dll" "Eaf.Core.UnitTests.dll" --process:Multiple --x86 --agents=1 --skipnontestassemblies --result="D:\TfsBuildAgent2020\_work\288\TestResults\results.xml" --out="D:\TfsBuildAgent2020\_work\288\TestResults\output.log"" -returntargetcode -targetdir:"D:\TfsBuildAgent2020\_work\288\s\Source\Implementation\bin" -register:Path32 -output:"D:\TfsBuildAgent2020\_work\288\TestResults\coverage.xml" -filter:"+[Eaf]* +[Eaf.Core]* -excludebyattribute:*.ExcludeFromCodeCoverage*

Full failure information it is available in results XML file but drilling into 3 different sources (build test result / Results.xml file / output.log file) becomes extra high effort job. So obviously this single stack trace should be extended with multiple stack trace information. I believe this should solve the problem for Azure DevOps. However, I am not sure if this will resolve problems for TestCentric as well as for Adapter used by Visual Studio. Maybe this simple change would help to resolve the problems.

[CharliePoole]

Yes, the result file has two kinds of error results provided. The <assertion> elements contain the newer format, which was added to support multiple assertions and warnings. The message shown under the <failure> element was kept for compatibility with older runners, which don't understand the <assertion> elements. It is also used when converting from nunit3 to nunit2 format.

The nunit3-console runner understands and uses the new format. When you run it directly from the command-line on your own machine or a server, it displays each error separately, with its own stack trace. If you had a case where running nunit3-console.exe directly did not show them separately, that would be a bug.

You suggest that the older format (in <failure> element) should be modified to have separate stack traces. That would be a change in the framework, where the XML originates. The engine only adds a <test-run> element to wrap all the assemblies. But that isn't possible in any case because this info is provided for backward compatibility and your change would make it incompatible. Older runners expect one message and one stacktrace inside the <failure> element.

I can see that your server display uses the old format. Can you explain where that display comes from?

[gps7]

The Nunit 3 console view shows all information as expected including all stack traces. With regards the build server output I really don't know. Can you clarify why the TestCentric shows Nunit 2 format information too?

My guess that this might be same reason for TestCentric , Build server and possibly for Nunit Adapter in VS2022. If I could get a test version of modified change resulting in fallowing information I could tell exactly if build server (and TC) results based on this message or not:

At the moment I cannot tell how Azure DevOps server reads test output which is displayed as test results.

[CharliePoole]

@gps7 Sorry to ask, but are you reading all my answers? The change you are asking for would have to be made in the framework. I'm not a member of the framework team. I did also give you my opinion that they would not make such a change because it would be breaking for other people. That message is a legacy feature for backward compatibility and needs to stay as it is.

Again, as already stated, TestCentric does not use the NUnit engine at all - it has its own. It's a separate project, which I created on my own and not as part of the NUnit organization. To a certain extent, it's a competing project with NUnit and any extended discussion should be done as an issue on the GUI at https://github.com/Testcentric/testcentric-gui. I will say this problem are probably due to the fact that the gui is unfinished. It's still in alpha release. I would definitely appreciate a bug report if you see one.

Back to your problem... I'm confused because I use Azure DevOps to build the console runner and I don't see a display like yours anywhere. However, other folks set up the Azure build originally, so I may just be missing something. @mikkelbu @rprouse Can either of you help here?

@gps7 what happens if you run the console through OpenCover on your desktop?

[gps7]

Sorry @CharliePoole , I am reading emails but I have no idea on which github source Nunit framework and Adapter is located since did not checked the source code. I've already raised question on Nunit github and they offered to ask here. With regards TestCentric I know about it but was not sure if I should raise issue there since I noticed similar behavior in other products. So I will create a new ticket for that if it has own engine.
It is good idea to verify the OpenCover since all request comes via this command utility and it seems out of support already. I will try this out tomorrow and see results including run without openCover. If nobody else is having such a problem on Azure DevOps then obviously something is misconfigured or outdated in our builds despite fact source control server version is almost latest. Thanks for support.

[CharliePoole]

Sorry for being a little testy, @gps7. I'm afraid that my leaving NUnit to do the GUI is a sore point for me and possibly others as well, so let's get into it on the TC project instead.

Summarizing...

• NUnit Framework creates all the XML for each assembly at the end of the run. In addition, it sends noifications as each test is run.
• The engine basically passes the XML on to any runner that uses it, adding a <test-run> element to wrap all the assemblies in the final result. It also passes on the notifications and adds start of run and end of run notifications.
• A runner like nunit3-console can use the notifications and/or final result to display or save whatever it likes.
• The vs-adapter acts as a runner on behalf of Test Explorer, vstest.exe or dotnet CLI. It too does what it likes with the output but is, of course, limited to what VS can understand when running in that environment.

For all the projects under github.com/nunit, we can transfer an issue for you if it isn't in the right place. Sometimes, however, it isn't clear or multiple projects are involved, so separate issues work better. TC GUI issues have to go to the gui repo, with which you are already familiar.

[gps7]

@CharliePoole thanks for detailed summary since was really hard to get how this part of Nunit works. I've created a new issue on TC, then same problem will be for vs-adapter. I believe the vs-adapter located here: https://github.com/nunit/nunit3-vs-adapter

[gps7]

I've eliminated OpenCover from Azure DevOps build and result is still same. Here is the executed command line this time:

Execute nunit3-console (File version 3.15.0.0, Product version 3.15.0): D:\TfsBuildAgent2020\_work\301\s\Utility\NUnit3\NUnit3-bin\nunit3-console.exe "Eaf.CellAutomation.UnitTests.dll" "Eaf.Core.UnitTests.dll" "Eaf.Equipment.Implementation.UnitTests.dll" "Eaf.Equipment.Interfaces.UnitTests.dll" "Eaf.Equipment.MergeModel.UnitTests.dll" "Eaf.Equipment.TraceJoin.UnitTests.dll" "Eaf.EquipmentConnector.CommandTranslation.UnitTests.dll" "Eaf.EquipmentConnector.UnitTests.dll" "Eaf.UnitTests.dll" "Eaf.ComponentTests.dll" "Eaf.Core.ComponentTests.dll" "Eaf.Equipment.TraceJoin.ComponentTests.dll" --process:Multiple --x86 --agents=1 --skipnontestassemblies --result="D:\TfsBuildAgent2020\_work\301\TestResults\results.xml" --out="D:\TfsBuildAgent2020\_work\301\TestResults\output.log"
Working Directory: D:\TfsBuildAgent2020\_work\301\s\Source\Implementation\bin
NUnit Console 3.15.0 (Release)
Copyright (c) 2022 Charlie Poole, Rob Prouse
Friday, July 1, 2022 8:24:10 AM

And test overview is still same:

I have no explanation on this and no ideas anymore what else I can try it out to determine the source of this test results.

[CharliePoole]

OK. I'll try to duplicate this myself.

[CharliePoole]

I'm pretty convinced that Azure is actually the cause of the problem. I believe it reads the TestCentric.xml file and only looks at the legacy failure element. In addition to the problem with Assert.Multiple this means that it probably will not report warnings. That's surprising to me given how long those features have been present in NUnit - but less surprising when I consider that it's Microsoft. Test Explorer doesn't handle either of those features well either. In fact the legacy message was created primarily for use under Test Explorer.

I'm closing this again and I'll see about filing an issue with the Azure team.

[CharliePoole]

@gps7 If there were an option in the console like --copyOutput=FILE do you think that would help? My thinking is that it should take all output displayed to the console and also send it to a file. That would include NUnit's own error messages as well as output written by your test (currently handled by --out)

I can't promise fast action, but if it makes sense and you file an issue, I'll put it on the backlog for version 4.

[gps7]

@CharliePoole thanks for analysis and great support. Offered feature would be a great benefit for us to have output of all information combined and this would help to have one source instead multiple sources. Additionally, start of test as well as test results with count of failed and successful tests would be a great advantage for us. I was planning to create a new feature request for the next week.