Trace and Debug output is not displayed; using SetUpFixture workaround not immediately displayed

[maettu-this]

Describe the bug

Opposed to the NUnit 2.x GUI, which allowed to enable Trace (and Debug) to be in the [Text Output], TestCentric does not have such option in [Tools > Settings... > Gui > Text Output]. Running a test where a testee outputs Trace or Debug output does not show this output.

The VS Test Adapter documentation describes a workaround to activate Trace and Debug output. However, with the workaround, the output only appears after the test got finished, i.e. Flush() got called.

See related comments in VS Test Adapter Issue 718 for background on why Trace or Debug output can be useful when debugging test and testee code.

To Reproduce

TextOutputIssue.zip

Steps to reproduce the behavior:

1. Build the attached [TextOutputIssue] project
2. Run the test in TestCentric

Expected behavior

"...doing something..." (testee Trace output) and "...awaiting testee..." (test Progress output) is expected to be immediately output in the correct sequence while the test is running:

...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

Screenshots

TestCentric 1.6.4 with SetUpFixture workaround:

TestCentric 2.0.0-beta4 with SetUpFixture workaround:

Environment (please complete the following information):

• TestCentric Version 1.6.4 / 2.0.0-beta4
• OS: Win10
• Target Runtime for your test assembly: .NET Framework 4.8

[CharliePoole]

NUnit 3 eliminated all special handling of Trace and Debug output. I did this both types of output give the user control of how and where that output appears. For the TestCentric GUI, I followed the same approach: there is no handling of trace or debug output.

HOWEVER, if the user installs something (e.g. a trace listener) which sends the trace or debug output to stdout, then that output will be captured by NUnit and transformed into an event. The particular runner you use determines which events it will handle and what should happen to the output.

[NOTE: The reason you may find difficulty in explaining this problem to folks who have only been with NUnit for only a few years is that this major change happened around 2007 or 2008.]

So, if you use a console trace listener, your trace output becomes standard output. It is captured by NUnit and converted to a TextOutput event. The GUI captures that event and saves it until the test case completes. It is then added to the XML output for the test and displayed by the GUI.

Therefore, if you want to see Trace or Debug output immediately, you must not send it to the console. It would be theoretically possible to create a listener which would capture the output and send it as a Progress event or write it to stderr, but I don't believe such a thing exists at this time.

[Incidentally, this is also how the NUnit console runner and the test adapter work. They are forced to work that way because multiple test cases may run in parallel, yet each test's output must remain separate in the result file.]

NUnit's own Progress output was designed to overcome this limitation. The Console runner displays it immediately and the GUI does the same. NOTE that this implies that all Progress output displays before all Standard output by design.

As discussed in an earlier issue, please only submit bugs for the 2.x GUI. For 1.x, I'm only taking questions and documentation issues.

I'm inclined to close this as "Not a bug" but I'll wait for your comments first.

@OsirisTerje some of this may relate to nunit/nunit3-vs-adapter#718

[maettu-this]

please only submit bugs for the 2.x GUI

Understand, I have tried to reproduce in TC 2.0.0-beta4, but that unfortunately crashed (see screenshot above) and I assume it has the same limitations and behavior regarding Trace and Debug output.

all Progress output displays before all Standard output by design

Better understanding the background now, I can adapt to this design. While the TestContext documentation does differentiate by "output to the current test result" vs. "immediate display", the implications on the sequential order and the moment the output appears could be documented in more detail, giving more background information there or in the TC documentation.

Now to the heart of it:

I have enriched the repro project with your proposed ProgressTraceListener, actually quite simple by looking at the implementation of the ConsoleTraceListener:

    [HostProtection(Synchronization = true)]
    public class ProgressTraceListener : TextWriterTraceListener
    {
        public ProgressTraceListener()
            : base(TestContext.Progress)
        {
        }
    }

TextOutputIssue with ProgressTraceListener.zip

But:

1. Either the NUnit or TC documentation should describe this somewhere. After all, this was a feature of the NUnit 2.x GUI but no longer is. The framework could even provide such ProgressTraceListener ready to use out-of-the-box.
2. In my opinion this is a breaking change that should be documented in the corresponding release notes. As mentioned at Add differences from NUnit V2 GUI to documentation #1042, I did take the time to read through the complete list of framework release notes since NUnit 2.6.4. I may have missed it, but I think there is no change related to the handling of Trace and Debug output documented.
3. Looks like there is a caching/flushing issue somewhere down the chain:

Output after running the repro sample test once

Output of the ProgressTraceListener multiplies with each test run

This issue persists with TC 2.0.0-beta4, which as mentioned earlier often crashes but fortunately sometimes doesn't:

[CharliePoole]

Can you clarify exactly which problem in TestCentric GUI you'd like me to fix. The stuff in NUnit is obviously out of my control.

[maettu-this]

For me as an outsider it is not that obvious where an issue originates from. If I raise it in NUnit, attaching the above screenshots, they may tell me to raise it here. Having raised it here, maybe it is in the wrong place.

Either the NUnit or TC documentation should describe this somewhere. After all, this was a feature of the NUnit 2.x GUI but no longer is. The framework could even provide such ProgressTraceListener ready to use out-of-the-box.

I cannot judge whether NUnit or TC documentation is the right place. But, the NUnit 2.x GUI provided the option to include Trace output whereas TC no longer does. In my opinion, the TC documentation should state something about this.

In my opinion this is a breaking change that should be documented in the corresponding release notes. As mentioned at #1042, I did take the time to read through the complete list of framework release notes since NUnit 2.6.4. I may have missed it, but I think there is no change related to the handling of Trace and Debug output documented.

Here again, I don't know the division of responsibilities. What would be the correct location in your opinion?

Looks like there is a caching/flushing issue somewhere down the chain.

While I assume the root cause is to be found in NUnit, the effect probably is only visible in TC, because TC allows to repeatingly run a test. So again, without looking into the depths of the NUnit and TC source code it is hardly possible for me to find the location the bug originates from, it could even be a combination of NUnit and TC.

[CharliePoole]

Your last post appears to be a comment on my use of the word "obviously." Point taken, it wasn't obvious to you. I used the word because only because TestCentric and NUnit are defined in GitHub as two different organizations, with different people involved.

Hopefully that finishes the discussion of "obviously, so I'll repeat the question:

Can you clarify exactly which problem in TestCentric GUI you'd like me to fix.

I'll add to that question the word "here." If a single issue is not about a single thing, it's difficult know what to do with it.
You can always create more issues if there is more than one thing to fix.

[maettu-this]

I see. Let me compact for this very issue...

1. The TC documentation should state something about how to achieve NUnit 2.x GUI like output of Trace and Debug.

...and extract to separate issues.

2. This I have taken to NUnit, I agree TC cannot do anything about this.
3. This I have extract into Redirected progress output appears multiplicated by the number a test has been ran #1044.

[CharliePoole]

So the crash with a null reference you described above is not one of the things you want to have fixed?

[maettu-this]

Thanks for reminding, that somehow got lost in the maze of issues. Extracted it to #1045.

[CharliePoole]

I downloaded TextOutputIssue.zip, built the solution and ran the tests in TestCentric.

I got this result...

=> TextOutputIssue.TestWithMixedProgressOutput.Test()
...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

My understanding is that you expected to see this instead...

...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

Since your "doing something" outputs are sent to stdout, which needs to be saved to TestResult.xml, it can only be processed after the test has completed. At the time that this breaking change was made in NUnit and the NUnit Console runner, TestContext.Progress was created to allow crucial messages to appear immediately. Note that those messages, issued and displayed while a test runs, are not saved to TestResult.xml. This is, of course, NUnit behavior since NUnit 3.0, but it is behavior that the GUI seeks to emulate.

Basically we could produce the output you expect in one of two ways...

1. Do not display Progress output immediately.
2. Stop saving stdout output to TestResult.xml

But neither of those two approaches are acceptable.TextContext.Progress is specifically intended to display output out of order and, I believe, is documented that way by NUnit. In sum, the GUI could do anything it wanted with the output - not display it at all, display it in reverse, etc. But we need to do things that make sense to the user.

[@maettu-this BTW, you know all this from other discussions, but each issue has to stand on it's own and the explanations have to remain available for folks who come here in future years.]

I'll next examine where (and if) this should be documented by TestCentric.

[CharliePoole]

Was hoping to add a link to NUnit's docs at http://test-centric.org/testcentric-runner/testcentric-gui/Features/result-tabs#text-output but there's nothing to link to. I'll add subheadings for each type of output there and give a better example in the image.

[maettu-this]

Glad you can reproduce the issue with the initial TextOutputIssue.zip. Just in case this got overlooked, TextOutputIssue with ProgressTraceListener.zip a bit further down the thread implements the proposed ProgressTraceListener that indeed achieves immediate progress output. I think the documentation should describe this approach, similar to what the VS Test Adapter documentation does for the ConsoleTraceListener.

[CharliePoole]

Isn't that the one that crashed? #1045? If the crash is caused by the redirection, we want to fix it before documenting it.

[maettu-this]

Good point. However, that already applied to the initial TextOutputIssue.zip using a ConsoleTraceListener. And with TextOutputIssue with ProgressTraceListener.zip containing the proposed ProgressTraceListener:

This issue persists with TC 2.0.0-beta4, which as mentioned earlier often crashes but fortunately sometimes doesn't

My guess is the crash is not because of the redirection, it is more likely because of having a SetUpFixture and a TestFixture in the very same file, resulting in some race condition when initializing this.

[CharliePoole]

I'll look at that issue next, after this one is finished. This is still beta so the docs are very fluid.

[CharliePoole]

Docs are updated... used @maettu-this 's example output in image.