Trace and Debug output is not displayed

[OsirisTerje]

This is extracted from Issue #301

"
FransBouma commented on Aug 15, 2017
I know I'm late to the party here, but maybe this will help:

For v3, trace output isn't picked up, as I found out the hard way as well. After a day fighting with this (also on .NET core 2.0), it appears to be rather straightforward.

As NUnit stores all output send to console output with the test result, a single tracelistener is enough:
Trace.Listeners.Add(new ConsoleTraceListener());
This will store any trace info resulting from a test with the test results for that test, and if you select the test in your runner, e.g. R#, it will show the output there.
For .NET core 2.0, you need to use:
Trace.Listeners.Add(new TextWriterTraceListener(Console.Out));

Do this one time, in the OneTimeSetUp method in your TestFixture.

It doesn't end there though :) You can then add another tracelistener and write to a file.
Trace.Listeners.Add(new TextWriterTraceListener(@"c:\temp\testoutput.txt"));
add that line before or after the consoletracelistener and it writes the output also to that file.

To make sure the data is written to the file, add:

	[OneTimeTearDown]
	public void TearDown()
	{
		Trace.Flush();
	}

so it's flushed at the end of the tests.

Again, it's late, you likely already have moved on but perhaps others like me who run into the problem of not having any trace output in nunit 3 can again sleep well :) (I moved to nunit3 because we too had to support netstandard2.0 so was confronted with this).

A redundant note perhaps: parallel tests likely won't work with this.

@psulek

psulek commented on Aug 31, 2017
@FransBouma I'm currently experiencing same issue. I have netcoreapp1.1, xunit. Trying your workaroud with add trace listener and flush does not help me. Resharper unit test output is still empty. Can someone point some tips redirect dotnet test command output into resharper unit test output window?

@chostelet

chostelet commented on Nov 20, 2017 •
Hello,

I concurre, having the same kind of issues. Debug.Print() statements in the application are no longer being visible in the Output window.
And, as suggested above, being obliged to add a [OneTimeSetup] method just to add a
' Trace.Listeners.Add(new ConsoleTraceListener());' is hardly manageable when having thousands of unit tests.
And even the result (output) is no available at once for the whole tests playlist, but needs to be pickup in each test.
Hard to believe.
And this should be documented in the Known Problems!
Regards

@CharliePoole

Member
CharliePoole commented on Nov 20, 2017
Let's note we are talking about two entirely different things here. @NightOwl888 started this issue about capture of Console.WriteLine. @FransBouma and subsequent commenters have been talking about Debug and Trace output.

It might seem as if they are the same, provided you are directing your trace to the console, but it isn't. NUnit intercepts your Console writes and the original bug applies to that. NUnit does absolutely nothing with Debug and Trace output. So we may need to look at these two things separately.

@chostelet

chostelet commented on Nov 21, 2017
It looks like, the net result to the user appears to be the same => No output in a straightforward way.
I understand having the capability of parallel execution can mess up the output, but this is something one should expect anyway.

@CharliePoole

Member
CharliePoole commented on Nov 22, 2017
@chostelet It's definitely an issue for the user but I wanted to note that fixing the one (console output) might not necessarily fix the other (debug / Trace). It's info for whomever takes on the issue.

@chostelet

chostelet commented on Nov 22, 2017
Hi,
You're right.
As a temporary workaround, does solving the console output may help get the default debug/trace output?
"

[CharliePoole]

For the sake of history, adding to the prior comments...

With NUnit 3, I actually made a decision not to support trace directly, but to leave it up to the user to get the trace into the console output if necessary.

I also dropped log output at the same time. In that case, the reason was that it required different code for each logging subsystem. We supported log4net in NUnit V2 but ran into a problem when user code under test made use of a different version of log4net. That was resolved with a lot of hassle (I think using reflection) but it was a lesson learned.

Basically, logging and tracing are the domains of other applications, not NUnit. We use a homemade internal trace to avoid conflicting with any packages imported by the user and we rely on the user to send the output to NUnit if they want NUnit to have it.

Of course, this could change in future, but it seems like the reasons for the prior decision should continue to be taken into account.

[FransBouma]

Sounds fair. It might be good to document this somewhere tho, as people coming from v2 or people who think it'll be written to the output have a hard time finding a solution otherwise (as in: it's not that obvious :P )

[CharliePoole]

You're right. At the time, there was discussion, but it was transient and folks just coming into it now don't have any place to get that info. I don't think we thought NUnit V2 would keep going as long as it did.

[OsirisTerje]

@FransBouma Have you considered writing a blog post about this? There are many ways a tracelistener can be enabled in the code, and given the current way of NUnit, the workaround you suggest is probably the best solution too.

[maettu-this]

Just ran into the same issue, found this documentation-wise, but it's only about the VS Test Adapter, not NUnit in general.

Having to add this the each TestFixture is quite inconvenient. I'd prefer having this global in TestContext or whatever. And why not having e.g. TestCentric again reflect that global state in Tools > Settings... > Gui > Text Output? After all, seeing a progress trace (e.g. during test case debugging) is more a user preference than a test property.

[OsirisTerje]

@maettu-this It is done in a SetupFixture. You only have one of these for each test project, not one per TestFixture.

TestCentric is not part of NUnit, so please ask there about adding that feature.

[maettu-this]

@OsirisTerje, thanks for clarifying what I have overseen. In case of my project, having three root namespaces, this means needing three SetupFixture. While not ideal it can be handled.

However I have come across two subsequent limitations/issues, resulting in a total of three sub-issues:

1. Documentation is only available for the VS Test Adapter, not NUnit in general.
2. The above proposed workaround ties Debug and Trace, it is not possible to selectively enable Debug or Trace.
3. Text output may be delayed until the OneTimeTearDown calls Trace.Flush(). This may make existing progress code pretty much useless, e.g. my code outputs this, the "Waiting..." being output by the test code and the " @ ..." being output by the testee:

 @ 21:11:00.846 @ Thread #009 : ...state has changed from 'StartingConnecting' to 'Connecting', is neither client nor server.
 @ 21:11:00.846 @ Thread #009 : ...state has changed from 'Reset' to 'Connecting'.
Waiting for connection, 0 ms have passed, time-out is 5000 ms...
Waiting for connection, 100 ms have passed, time-out is 5000 ms...
Waiting for connection, 200 ms have passed, time-out is 5000 ms...
Waiting for connection, 300 ms have passed, time-out is 5000 ms...
Waiting for connection, 400 ms have passed, time-out is 5000 ms...
...
Waiting for connection, 1900 ms have passed, time-out is 5000 ms...
 @ 21:11:02.868 @ Thread #005 : ...state has changed from 'Connecting' to 'Stopping'.
 @ 21:11:02.868 @ Thread #004 : ...state has changed from 'Connecting' to 'Stopping'.

In NUnit 2.6.4 and its GUI each line immediately got output, helping to get progress details when debugging test code in combination with testee code. Now with NUnit 3.14.0 the whole text output only appears at the very end of a test run. Useless in my case. Any proposal or improvement on this is highly appreciated.

[OsirisTerje]

@maettu-this You can have ONE SetupFixture per assembly. If you place it outside any namespace, at global level, it will apply to all namespaces in that assembly.

1. We can obviously add something to the NUnit docs too, but there is a Search possibility there.
2. Ref https://learn.microsoft.com/en-us/dotnet/framework/debug-trace-profile/trace-listeners

Debug and trace share the same Listeners collection, so if you add a listener object to a Debug.Listeners collection in your application, it gets added to the Trace.Listeners collection as well.

3. It "may" be, but normally it will come out in the correct sequence, and as the test is running. It does not come out at the end of the test run. If you do have parallel execution, it will all be mixed up, as expected. Since it seems you're running on multiple threads, I assume you do use parallel execution.
   I think the best would be if you added a small repro to illustrate your case.

[maettu-this]

@OsirisTerje, I understand 2. being a limitation of the .NET framework, but it is not that obvious when looking at the VS Test Adapter documentation. In my code I added // Note that this listener "directs tracing or debugging output", i.e. always both, even being named "Trace". to make it more obvious.

Creating a repro has revealed the behavior is even stranger:

VS Test Explorer Standard Output => TestContext.Progress output is missing

...doing something, 100 ms have elapsed, duration is 1000 ms...
...doing something, 200 ms have elapsed, duration is 1000 ms...
...doing something, 300 ms have elapsed, duration is 1000 ms...
...doing something, 400 ms have elapsed, duration is 1000 ms...
...doing something, 500 ms have elapsed, duration is 1000 ms...
...doing something, 600 ms have elapsed, duration is 1000 ms...
...doing something, 700 ms have elapsed, duration is 1000 ms...
...doing something, 800 ms have elapsed, duration is 1000 ms...
...doing something, 900 ms have elapsed, duration is 1000 ms...
...something done

VS Tests Output Window => wrong sequence

...awaiting testee, 250 ms have elapsed, time-out is 2000 ms...
...awaiting testee, 500 ms have elapsed, time-out is 2000 ms...
...awaiting testee, 750 ms have elapsed, time-out is 2000 ms...
...awaiting testee, 1000 ms have elapsed, time-out is 2000 ms...
...test completed after less than 1000 ms
...doing something, 100 ms have elapsed, duration is 1000 ms...
...doing something, 200 ms have elapsed, duration is 1000 ms...
...doing something, 300 ms have elapsed, duration is 1000 ms...
...doing something, 400 ms have elapsed, duration is 1000 ms...
...doing something, 500 ms have elapsed, duration is 1000 ms...
...doing something, 600 ms have elapsed, duration is 1000 ms...
...doing something, 700 ms have elapsed, duration is 1000 ms...
...doing something, 800 ms have elapsed, duration is 1000 ms...
...doing something, 900 ms have elapsed, duration is 1000 ms...
...something done

Only by changing TestContext.Progress to TestContext.Out, output becomes correct in both:

...doing something, 100 ms have elapsed, duration is 1000 ms...
...doing something, 200 ms have elapsed, duration is 1000 ms...
...awaiting testee, 250 ms have elapsed, time-out is 2000 ms...
...doing something, 300 ms have elapsed, duration is 1000 ms...
...doing something, 400 ms have elapsed, duration is 1000 ms...
...awaiting testee, 500 ms have elapsed, time-out is 2000 ms...
...doing something, 500 ms have elapsed, duration is 1000 ms...
...doing something, 600 ms have elapsed, duration is 1000 ms...
...doing something, 700 ms have elapsed, duration is 1000 ms...
...awaiting testee, 750 ms have elapsed, time-out is 2000 ms...
...doing something, 800 ms have elapsed, duration is 1000 ms...
...doing something, 900 ms have elapsed, duration is 1000 ms...
...something done
...awaiting testee, 1000 ms have elapsed, time-out is 2000 ms...
...test completed after less than 1000 ms

TextOutputIssue.zip

I'll contact TestCentric about the behavior in that GUI.

[maettu-this]

Two things I have forgotten to explicitly mention yesterday:

• In all cases described above the output only becomes visible after the test has finished, i.e. after Flush() has been called.
• TestContext.Progress states "Gets a TextWriter used for sending normal (non-error) output intended for immediate display."

[maettu-this]

Please see ProgressTraceListener as proposed by @CharliePoole at TestCentric/testcentric-gui#1043 (comment). This should be added to the documentation. Even better provided by NUnit itself.

[CharliePoole]

More a suggestion of future experimentation than a proposal, at least that was my intention. Also, I think it would NOT be better provided by NUnit itself because NUnit should not know who is running it or what is eventually happening to its output. If it works, however, it might belong in the Tips and Tricks section of the adapter docs.

[OsirisTerje]

The adapter receives the output through the events coming in from the framework/engine, and "sends" it further to the testhost. It has no concept of "immediate", that is up to whoever calls the adapter, which up to now has been the testhost.

So adding a special listener for Progress is fine, but doesn't change anything with respect to "immediate".
Whether it should be added to the documentation, that's fine with me - just raise a PR in the docs repo.

Also, the output comes in sequence when you're not running in parallel. When you run in parallel it doesn't - of course.

I am not sure what is the ask here for the adapter. (And as @CharliePoole says, the framework should not be runner-aware)

[maettu-this]

As mentioned to @CharliePoole at TestCentric/testcentric-gui#1043 (comment), it is not that obvious for me as an outsider where an issue originates from.

The same applies to where things should be documented. I personally think the NUnit framework documentation TestContext.Progress should at least mention this. But I now understand your preference is to document this in the runners. I don't think it would be efficient to have me raising PRs for NUnit and several other repos if information may end up in the wrong location, leading to more lengthy discussions, it would be more efficient you taking the input from this discussion right to the spot that fits the NUnit documentation concept.

I am not sure what is the ask here for the adapter.

I think the adapter documentation should state that output written to TestContext.Progress isn't shown in the VS [Test Explorer] window, but is visible in the VS [Output > Tests] window "immediately". Ideally, a summary of the available output paths and their behavior is added to the documentation.

[OsirisTerje]

Ideally, a summary of the available output paths and their behavior is added to the documentation.

Ok, so your ask is to improve the documentation.

That's a fair ask.

I once tried to make a table, but it stalled at some point with there being too many possible variations.
I can make a new try.

PS:
If you look at how many issues we have with the output, and also how the "target" has been moving (yes, dotnet test and Test Explorer has also changed over the years).