Console.WriteLine does not appear to be working in unit tests

[rclabo]

Currently Lucene.Net uses Console.WriteLine 1804 times (although some lines are commented out). A quick scan of the files containing Console.WriteLine shows that it's being used in unit tests petty much exclusively. As a new developer on the project looking into a failing test, the first thing I wanted to see was the Console.WriteLine output for the failing test. But I struggled to find where the output was showing up and after talking with @NightOwl888 I came to understand that this is something that still needs to be resolved. Currently Console.WriteLine does not appear to be working in unit tests.

@NightOwl888 also mentioned that according to How do I get nunit3-console to output my debug to screen (on a Windows box)?, we should maybe be using TestContext.WriteLine() instead. So this is something I'm now investigating.

[NightOwl888]

I specifically brought this to the attention of the NUnit team when we started targeting NUnit 3 instead of NUnit 2. Console.WriteLine() used to work in NUnit 2 flawlessly, but we had to make the switch to NUnit 3 to support .NET Standard.

There seems to be more options in NUnit 3, but I haven't worked out which one is the "right" one for our use cases

• In Visual Studio, write output to debug or console output
• On dotnet test, output to stdout
• Xamarin.Android - not sure
• Xamarin.iOS - not sure
• UWP - not sure

I believe all of the mobile platforms have a standard way to write output, but they would need further investigation.

Verbose Setting

Do note that we also had an issue with some of the tests with larger output filling up a buffer in Visual Studio and crashing the IDE. Those tests have since had their Verbose output either disabled or truncated. We either need to find an actual way to increase the buffer, or find the "proper" way to output the logging from the tests.

Currently verbose is set to true when running tests in Debug mode. It can also be set to true by adding a file named lucene.testsettings.json in a test folder or parent folder of the tests with verbose set to true

{
    "tests": {
        "verbose": "true"
    }
}

Abstraction of Output Methods

I suggest using an abstract set of Write and WriteLine methods into the test framework for writing the output into a TextWriter and then we can easily switch that to whatever output NUnit requires or even do more than one output simultaneously, if needed. The Trace functionality of .NET is designed in just such a way.

Do note that in some cases, output is written to an InfoStream, which can be directed to any TextWriter as well.

Future Porting

One additional thing to keep in mind - when porting future tests, the logical thing to do is to change

• System.out.println() > Console.WriteLine()
• System.out.print() > Console.Write()

Whatever syntax we actually end up with, we should strive to make these lines intuitive to convert to .NET.

[rclabo]

Thanks @NightOwl888, great info.

I've done many hours of research on this and here is what I have found. I'd really value your thoughts.

Console.WriteLine IS going somewhere

Almost by accident, I discovered that at least for failing tests the output for Console.WriteLine does actually go someplace useful. When looking at the failing test, notice the error message column in the screenshot below

At first glance it seems like it's just telling that there was a certain type of exception. BUT if you right click that failing test and click "Copy Details" it will place the WHOLE message on the clipboard. By pasting that in some editor, I came to realize that the exception message is crazy long, and in fact does contain the Console.WriteLine output:

While this does not send the Console.WriteLine to the output window, it does make the output available when investigating a failing test which is probably one of it's most likely use cases.

Other API Options

I have tried all of theses:

TestContext.Progress.WriteLine
TestContext.Out.WriteLine
TestContext.WriteLine
Console.WriteLine
Console.Error.WriteLine

In the version of NUnit that Lucene.Net is using, none of these go to the output window. Although, System.Diagnostics.Debug.WriteLine can be routed in VS to the immediate window, which is not a totally bad option BUT it does not get included in the exception message which is an important consideration.

Parallel Unit tests

One of the reason that this whole issue cropped up in NUnit3 which did not exist in NUnit2 is that in NUnit3 there was a concern that when running unit tests in parallel, the output from something like Console.WriteLine was a bit problematic given that the output from several different tests running at the same time would be intermixed. One could certainly see how that could be a problem. This is why NUnit introduced the methods on the TextContext class for writing output in version 3.

The idea was to have some methods on that class write immediately (somewhere?!) and to have some be buffered at the unit test level and only output with the test results when that unit test completes. This in theory sounds pretty smart to me, as it gets away from the whole problem of having output intermixed for multiple tests but still provides the ability to theoretically output in real time if desired. In practice, the actual implementation seems wonky, however. Here is what my tests show based on examining the exception message content, and remember I can get none of these to go to the output window (or intermediate window) currently:

TestContext.Progress.WriteLine - I can't find this output anywhere, not in the exception message, not in the output window or immediate window. I don't know where it goes... crazy!
TestContext.Out.WriteLine - writes immediately even though the docs say it's buffered.
TestContext.WriteLine - writes immediately.
Console.WriteLine - writes immediately.
Console.Error.WriteLine - buffered till end of unit test then written.

In NUnit 3.17 it's now possible to send Console.WriteLine to Output Window

Apparently this is a recognized NUnit3 issue, issue 343. The issue was first placed in June 2017 and got plenty of community banter. The issue was resolved with the release of NUnit3TestAdapter ver 3.17 which is the current production release of NUnit. This is to say that being able to have Console.WriteLine go to the output window was only recently solved by NUnit.

Currently Lucene.Net uses NUnit3TestAdapter ver 3.16.1.

Wrap-up and Call for Feedback

So it seems tempting to recommend that we upgraded Lucene.net from NUnit3.16.1 to NUnit 3.17 but I know in a project of this size, and with the number of unit test it has, there may be hidden issues I'm unaware of. The good news is whether we upgrade NUnit or now, we now know how to see the output from Console.WriteLine in the exception message of failed tests. And frankly that's probably the time we most want to see the output. So maybe it's good enough to just know that's possible.

As an aside we now have a way to make the random seed for the test visible when a test fails. We can just use Console.WriteLine to write the seed and it will show up in the exception message. That's cool to know.

But we do still have to figure out if upgrading to NUnit 3.17 is worth while. Given that I don't personally use console messages that much in my own approach to debugging, I don't have a strong opinion either way, especially since I now know how to see the output in the exception messages. What are your thoughts?

[NightOwl888]

But we do still have to figure out if upgrading to NUnit 3.17 is worth while. Given that I don't personally use console messages that much in my own approach to debugging, I don't have a strong opinion either way, especially since I now know how to see the output in the exception messages. What are your thoughts?

There is one issue: Xamarin tests (which I am currently doing work on) cannot use anything higher than NUnit 3.10.1.

However, the way forward is to downgrade to that version on Lucene.Net.TestFramework as well as add targets to all of the test projects for .NET Standard 2.0 and .NET Standard 2.1, which will also target NUnit 3.10.1 (which will be consumed by projects that target Xamarin). All existing test project targets can use the latest version of NUnit, 3.17.

It is becoming clear that the Dependencies.props file needs to be changed to a later place in the pipeline after the TargetFramework has been set so it can have conditional PackageFramework dependency versions set for specific target frameworks. Currently it is referenced by the root Directory.Build.props file, which is before target framework is specified. This would allow us to specify 3.10.1 for .NET Standard 2.x and 3.1.7 for everything else.

I will need to check how difficult it may be to tie the output of Console.WriteLine to the output of Xamarin, although I wasn't planning on releasing the test runner I created along with Lucene.NET, it is just to verify compatibility with mobile platforms.

Parallel Unit tests

Sounds good in theory, but in Lucene.NET we are limited to running tests serially due to shared static members in the test framework. Changing this could be done, but would require some fairly extensive refactoring with how the codecs are loaded and breaking API changes.

So, in effect we are gaining nothing from this NUnit "feature" except confusion about where the results are and even worse, limits that cause truncation of the output and/or crashes.

Here is a test that is crashing when the buffer in VS is overloaded.

VS Test Output

"Copy Details" seems to have some finite limit. If the amount of text exceeds the limit, it is truncated and may not be very useful.

Unfortunately, the Lucene tests were designed with an infinite amount of space to log into.

I don't find the logging here particularly useful either. However, it is not just meant for the Lucene.NET team, it is meant for anyone that consumes the test framework - therefore, it should be set up in a reasonable way to make debugging easy for those who depend on it.

[rclabo]

Sounds good in theory, but in Lucene.NET we are limited to running tests serially due to shared static members in the test framework.

I kinda thought that might be the case. I see no pressing reason to switch from serially running the tests. That keeps our lives more sane.

All existing test project targets can use the latest version of NUnit, 3.17.

"Copy Details" seems to have some finite limit. If the amount of text exceeds the limit, it is truncated and may not be very useful. Unfortunately, the Lucene tests were designed with an infinite amount of space to log into.

I don't find the logging here particularly useful either. However, it is not just meant for the Lucene.NET team, it is meant for anyone that consumes the test framework - therefore, it should be set up in a reasonable way to make debugging easy for those who depend on it.

If we go to with NUnit 3.17 then the full output of Console.WriteLine will go to the output window in VS, for all tests except the .NET Standard 2.0 & 2.1 testing targets running NUnit 3.10.1 (for Xamarin compatibility). So that kinda solves the truncation problem and sounds like a good plan for how to move forward. Since you were planning on creating the additional testing targets for Xamerin that use NUnit 3.10 anyway, do you want to be the one to upgrade the other compilation targets to use NUnit 3.17 at the same time? I can do it, but it seems like a good fit for you to do it with the other XUnit dependency changes.

although I wasn't planning on releasing the test runner I created along with Lucene.NET, it is just to verify compatibility with mobile platforms.

Is it available elsewhere where I could take a look at it just to better understand what such a test runner looks like?

[NightOwl888]

Is it available elsewhere where I could take a look at it just to better understand what such a test runner looks like?

I have setup a temporary repo so you can have a peek.

BlameListener

BlameListener is a custom class that writes the name of each test before it is run so if there is a crash, we know which test caused the crash. I have been trying to get the NUnit team to implement such a feature for years.

• Test log to determine which test last ran when the test runner crashed
• How do I determine what exception caused Test Explorer to crash?

At least with the .NET 5 SDK, Microsoft finally added the blame-crash option to dotnet test so crashes can be detected, but it would be nice if this didn't have to be built for every other runner manually.

NOTE: In Xamarin, there are problems with how generics are implemented that caused infinite recursion in ArrayEqualityComparer. It would have been nearly impossible to track it down without this feature.

It also proved useful when you submitted your first PR, as it detected the crash of the runner on the command line, whereas Visual Studio simply ignores it and doesn't report anything.

---

Since you were planning on creating the additional testing targets for Xamerin that use NUnit 3.10 anyway, do you want to be the one to upgrade the other compilation targets to use NUnit 3.17 at the same time? I can do it, but it seems like a good fit for you to do it with the other XUnit dependency changes.

There is no conflict if you upgrade NUnit to 3.17 globally now (in Dependencies.props) and the other changes are implemented later, including the ability to specify a different version on specific target frameworks.

[rclabo]

BlameListener is a custom class that writes the name of each test before it is run so if there is a crash, we know which test caused the crash.

I'm unable to locate the BlameListener class. Where does that one live?

[NightOwl888]

BlameListener is a custom class that writes the name of each test before it is run so if there is a crash, we know which test caused the crash.

I'm unable to locate the BlameListener class. Where does that one live?

BlameListener.cs

[rclabo]

I totally didn't see that the whole project was there. Thank you!

[rclabo]

This issue can be assigned to me.

I have confirmed that upgrading to NUnit3TestAdapter 3.17.0 does in fact fix the issue with Console.WriteLine, at least in my configuration which is Visual Studio 2019. The output from Console.WriteLine now shows up in the Output window on my machine. It's kinda fun in fact to watch the output window while running tests.

However, I'm still not sure if this gonna be a go or no go as running the tests occasionally blows up NUnit, and other times blows up Visual Studio all together.

I see that NUnit itself versions independently of NUnit3TestAdapter . Lucene.Net currently uses NUnit 3.12.0 so I I may try to upgrade it to the latest version which is NUNit 3.13.1 to see if that fixes the stability issues I'm seeing with the upgrade NUnit3TestAdapter 3.17.0

[NightOwl888]

@rclabo

Great. I have assigned the issue to you. Thanks for putting in the grunt work on this.

When using NUnit 2.x, we didn't have any issues running out of space when the output actually went to the output window. That problem began occurring when NUnit 3.x started putting the output in each test, which apparently has a limited amount of space available. Maybe there is a way to increase the space available, but it certainly is a lot more like the intended experience direct the console output somewhere it could be viewed in one chunk of text, as there is information that is output between each test run that may otherwise be lost.

[rclabo]

Upgrading the two as a pair seemed to make things happy. Pull request submitted. PR#412