Nunit3 console doesn't show test output continously

[yoyos06]

The Nunit 2 console had a great feature, it reported the test output on the fly and not only after the test finished. It was very useful because you could track the test case and check the progress, but now I have to wait the end of the test case to see the output. Do you plan to reimplement this feature?

[rprouse]

Reporting test output as it is created is problematic now that we have parallel test execution. If we reported the output as it came in, the output from several tests would get mixed together making it very difficult to figure out what output is coming from which test.

I will leave this open as an idea. If enough people want this ability, we will consider it again, we don't plan on implementing it at the moment. Are your tests really so long that you can't wait? :wink:

[yoyos06]

Our tests take 4-5 minutes and it is inconvenient for us, that we can't follow the progress of the tests. When we can we are using the GUI to see the output, but in the CI we are using console. During tests we would like to follow the test output and check what happens with the SUT application in the same time. In case of failure you can catch what was the state of the app right after the console output.

Just an idea: There could be a console option to write the output as it came in, and in case of parallel execution that could be ignored.

[CharliePoole]

Let's pin this down a bit more, to be sure there is no misunderstanding.

NUnit does not make you wait for the end of the test run to see output from tests. It makes you wait until the end of each test case. Is it each case that's taking 4 or 5 minutes for you? That seems like quite a long time, even for a functional test.

If you are looking for some progress notification within a test case, one possibility would be for us to handle Console.Error output immediately and/or to provide an additionaly TestContext method for immediate writing. This might be better than a global option for the entire run, since it would let you decide which tests require this sort of feedback.

[yoyos06]

Yes we have several test cases that are 4-5 minutes long, because these cover long flows which cannot be tested separately.

[flaub]

While developing a test, it's convenient to log output and be able to watch its progress. In my case, I have a test that exercises code which apparently has a broken break condition from a loop. Thus, my test runs forever and I have no easy way of figuring out why.

It seems like there should be two 'modes' for running unit tests. Interactive and batch. Batch mode should make use of parallelism, but interactive mode should be slow and output as much detail in realtime as the developer specifies.

[CharliePoole]

@flaub When you say "as much detail in realtime as the developer specifies" do you have something in mind beyond an output channel that can be written to?

[flaub]

When I'm developing a new test or exploring an existing one, sometimes I want to turn up tracing (I happen to be using NLog, so I can do this with environment variables). It would be nice if there was a way to have command line options control the level and facility/category of logging/printing.

I'd use 'interactive' mode for developing/exploring tests, but then I'd use 'batch' mode for continuous integration, nightly builds, or pre-commit checks.

All that said, my main point was really that I can't wait until the test case completes because the said test case has a problem with a loop and so no output will be seen until the end of the test (IIUC). Being able to quickly turn on and off output from the command line seems to be the most productive capability, rather than having to change code and re-compile.

There is a good question as to whether this should be NUnit's problem or not, users could write their own code to do this. NLog (and many other logging solutions) provide a lot of functionality that probably doesn't belong in NUnit. However, I feel there's an implied contract about configuring the logging output to go to stdout/stderr; I usually expect this channel to be unbuffered.

[CharliePoole]

@flaub Note that we have categorized this issue as an "idea." By that we mean that it isn't sufficiently fleshed out to be considered a feature. That's what I'm trying to do here with my questions.

You may be aware that the NUnit 2.x GUI was able to capture console stdout and error, trace output and log4net log output. You could specify as a setting which of those should be captured and displayed in the gui. In the case of trace and log, output continued to be written to it's original destination in addition to appearing in the gui.

With NUnit 3.0, I decided that this needed to be simplified. NUnit was trying to do too many things and they were not all working well together. So, with 3.0, we only capture stdout and stderr and there is no option to prevent this from happening.

It could be that the simplification went a step too far. In fact, I think it did. The question is exactly how to walk it back. One possibility is to simply provide an option (--nocapture?) that turns off the capture entirely. Another is to never capture stderr, which is usually expected to be unbuffered.

In addition to stdout, we also now have TextContext.Write, which I think might be conceived of as implicitly buffered in all cases.

[WiktorJagusiak]

I know that NUnit is designed for unit testing. But many people use is for NightlyBuilds and Automation Tests. In this case the result of each test should be visible on the fly. You said the output will be mixed in parallel test execution. In fact, it indicates a problem in parallel launching tests. The output should provide an opportunity to distinguish test. Especially then TestContext is empty between tests and you don't have any history. Also, many people will want to have the ability to run tests sequentially. If you have long running test package (what takes many hours) and NUnit not finish the job to the end you don't have results at all. Even debug and trace options in NUnit do not give you any information about the result of completed tests.

[CharliePoole]

Not sure I understand why you say results should be visible on the fly for nightly builds. Normally, nobody is sitting there watching the builds. I take it that your concern is what output is available if the test run crashes and can't produce it's normal report output. Of course, our main focus is to make sure that tests can't crash NUnit but this is still a valid concern. What info would you want to see in this case?

As far as parallel execution goes, that's a user choice. If there is something in your tests that don't allow them to run correctly in parallel, then don't run them in parallel!

The NUnit internal trace is intended for use in debugging NUnit, not the tests. That's why we call it internal. :-)

[dpkano]

NUnit is the test runner for my UI automated tests. I chose NUnit because of its functionalities and the ease of use. Even a single UI test case might take a while (eventually more than 10 minutes) to run. Because of that my tests are not multi threaded so I would not have the console output racing condition (Actually this change is great for multi thread unit test running!). So, to be able to trace the intermediate steps of my test case I really need the ability to flush the output console right away. (Maybe this is the same issue that WiktorJagusiak has...)

[WiktorJagusiak]

Yes, indeed. But in my case all automation tests needs 9-11 hours.

[CharliePoole]

I think that we still need to decide a few details in order to firm this up as a planned feature rather than just an "idea":

1. Is there some reason why Trace can't do the job?
2. Is it necessary for all text output to be flushed immediately or is it good enough that only a particular stream is flushed. One such stream might be standard error. Another might be an "error" or "unbuffered" stream added to TextContext alongside the current Output stream.
3. Where should such flushed output appear? On the console? In a file?

[CharliePoole]

Adding to item 2 above: if we were to send all output immediately, then it would no longer be available in the report that is produced at the end of a run, organized and labeled by test. Is this a concern?

[dpkano]

1) Since we already relay on that to keep track of the existing tests. I'd say that we'd have to change the existing tests (or even the intermediate infrastructure layers) to use Trace in order to get what we already had. 2 and 3) In MY case I redirect the output (I don't use the error) to a file and track the progress from there... But it might depend case by case... All this is to accommodate the previous behavior and adopt v3 without big changes. 2b) For me that is not a concern because I'm keeping track of that myself.

But having that said, I really liked the way you handled the racing condition on the output (and I'll used it on my multi threaded unit tests), I'd just like to be able to tweak (through a parameter) to a single thread mode where its output is flushed right way to keep backward compatibility with v2 (behavior).

[CharliePoole]

@dpkano OK, that's clear. Single thread execution is already available through the command-line options. A switch that says "don't capture output" would most likely work for you. Since TestContext.Write was not available in V2, I would imagine that we could continue to buffer that.

Other opinions?

[unickq]

Well, it makes sence to downgrade to 2.6.4 then. Really hard to debug UI tests :(

[CharliePoole]

I'd be curious to know the relation between Console output and UI tests, i.e. what are you trying to accomplish. It might even help move this issue forward. :-)

[unickq]

Ok. So I have a desktop application where I need to perform several small operations to perform the test. Each step is documented by log message - so it's easy to find what is going to be wrong in realtime. I use Resharper for a test run in VS - the application instance is launched on remote server and I can't see what exactly happening on the screen. That's why it's not comfortable.

I know, that tests should be atomic - but it's not always possible with UI tests. Switched to NUnit 3 cause its reports more informative, but gonna go back because of it.

If future versions have --showOutput option in single thread mode it would be cool :)

[CharliePoole]

@NickQA That certainly makes sense. Do you prefer having all output live - perhaps as an option - or would a single live channel suffice? In the latter case, you would have to use that channel in order to see the output.

Currently, the "channels" we capture are Console.Out, Console.Error and TestContext.Out. We could reasonably make Error always live or we could create a TestContext.Live TextWriter object.

[unickq]

@CharliePoole

As I understood first case of adding --option will work only for nunit3.console? So it makes sense to have just another channel for output.

[rprouse]

I also like the new property on TestContext, it explicitly states the intention and you do not have to tell other developers on your team about some command line option or GUI setting.

Other possible names, TestContext.Immediate or TestContext.ImmediateOut?

[CharliePoole]

@NickQA That's a good point. An option would only work if the runner passed a corresponding setting to the NUnit engine. Our console runner would do that and so can our gui, when we get that far. We can also do it in our VS adapter. But it would be up to third parties whether to do so or not.

But note: if we dedicate a channel to live output, individual 3rd party runners may not recognize it or display it unless their users ask them to do so.

I think we have enough info on this to promote it from an idea to a feature. That's not saying when we will do it, but I'll put it on the backlog anyway.

[CharliePoole]

@rprouse Implementation-wise, we might need create a new test event that passes this output all the way back to the runner, where it gets written to stdout or stderr. We had such an event in V2, but eliminated it since the output is now bundled into the test result.

Another implementation detail: does the live output only go out live or is it also placed in the test result?

[unickq]

@CharliePoole

I really like the way that output placed in test results. So I think also is the right option. In my case it would be easy to monitor changes live and then build right reports with detailed steps

[sttodorov]

I have same case with monitoring UI test which sometimes are slow, because of installation / configuration of the product. I have decided to stay with 2.6.4 because of this. the idea for having TestContext.immediateOut is great, hope to see it implemented soon.

[drazul]

I see that with the '--teamcity' option nunit provide some real time feedback. Is possible provide a configuration with the print template format? Maybe in future releases.

[CharliePoole]

If we provide TestContext.ImmediateOut or similar, should Console.Error.Write also be handled as immediate?

@drazul Can you explain a bit more what you mean?

[drazul]

@CharliePoole now with the --teamcity argument I get the next line:

teamcity[testFinished name='example.test' duration='124' flowId='1-1040']

For me is enough feedback during the execution, but not easy readable if you use other CI server like jenkins. I ask for a feature to configure that print format in order to provide better support for any CI.

[CharliePoole]

@drazul I'd like to see the TeamCity feature become an extension to NUnit and get the JB guys to support it. Since we don't use it, it's a bit of a burden to keep it working right.

A feature such as yours could also be an extension... either published or one you develop for yourself. If you are interested in working on it yourself, I'd be glad to point you in the right direction.

The use of an extension point has been in my mind for a while, but was not an issue till now. I just created #1225 for teamcity.

[espenalb]

I have one more suggestion/comment/input on this topic: When NUnit starts a new test, it would be very helpful if the "test starting" message was printed immediately. I recently had an issue where I had a bug in a long-running TestFixtureSetup (Integration testing). Looking at the NUnit log, it was impossible to tell which test was causing the problem. I had to fire up the test suite in VS and use the debugger to find out where it was stopping.

A simple => NameOfTest would have solved my problem.

Other than that - I think the TestContext.ImmediateOut option sound like a perfect solution - and I support the notion that content here should go both to output and to the test log.

[CharliePoole]

@espenalb The output you want would be available if you used the --labels:All option on the command line. That option causes starting labels to be produced for every test, rather than waiting for them to produce output as --labels:On does.

[espenalb]

@CharliePoole Is the --labels:All behavior you describe implemented in the released NUnit version? I just tested with NUnit Console Runner 3.0.5813, (Latest from NuGet) and it produces no output (Same behavior with All and On options)...

This simple test produces no output until the test times out with "Test exceeded Timeout value of 5000ms":

    [TestFixture]
    [Timeout(5000)]
    public class Suite
    {
        [Test]
        public void StupidTestWithInfiniteLoop()
        {
            TestContext.WriteLine("StupidTestWithInfiniteLoop");
            while (true)
                Thread.Sleep(500);
        }
    }

Sample project: NUnitReportLabels.zip I executed the tests like this: packages\NUnit.Console.3.0.1\tools\nunit3-console.exe NUnitReportLabels\bin\Debug\NUnitReportLabels.dll --labels:All

[rprouse]

@espenalb --labels:all is in 3.0 and outputs the label to the console in blue. I believe it may not be exactly what you want though, I expect it outputs the label at the end of the test, not at the beginning. We could change that though. New issue?

One thing that I liked about the MbUnit console was it's curses-style interface that output the currently running test with a spinner at the end, then erased the line for the next test.

[CharliePoole]

I recall that change now. Under V2, the label was displayed at the start of the test. Early 3.0 releases did the same thing, but this was confusing when multiple tests were run in parallel. I moved the logic to the end of the test so that the label line would always appear immediately before any output from that test. That change makes this unsuitable for tracking tests as they run or for knowing which test caused a hang.

We should rethink this. It may be that we need two different lines, perhaps in different colors. Using --labels:On would function as it now does but --labels:All would add an extra line of output for every test, as it started.

Alternatively, we could use the MbUnit approach, provided it can be made to work for multiple sets of tests running in parallel.

I think we need an issue for this, separate from this one.

[andrewcartwright1]

Hi, Just like to throw my opinions into this discussion, the benefits of the output being displayed as the test is running are that:

• I am aware of the values that are being used at what point during my test
• I am aware of what my test is doing/trying to do

This was a great feature that made running selenium tests far easier for myself as I was always aware of what was going on, since removing I now have to wait for a test to fail/complete before I can see any information relating to why it may have failed / if my fix has worked.

Is there any plans to reintroduce this feature?

[yoyos06]

I agree and good to continue this thread. We use Nunit 2.64 on Windows because this version has this continuous logging feature. Version 2.64 doesn't work well on OSX with mono, because Nunit can't close itself after test run, so we have to use version 3, but this restriction is pain for us.

[CharliePoole]

@andrewcartwright1 Well yes, you are looking at the plan. :-)

When an issue is categorized (is:feature), prioritized (pri:normal) and assigned to the Backlog milestone, that means we plan to do it.

In this case, it's not yet entirely certain how we will do it, since we don't want to completely change the handling of all text output from the tests. Probably, it should be listed with a design status - which I just gave it. I'm assigning it to myself for now and will do a follow-up comment about the design questions I see.

[CharliePoole]

Here is a shot at designing how this should work...

The current implementation follows the specification at https://github.com/nunit/docs/wiki/Text-Output-from-Tests-Spec

1. All stdOut output is captured and associated with the test result as is all output through the TestContext using TestContext.Write, etc. As described in the spec, stdErr is not captured but is left to go directly to the console.
2. My preference is that we leave things as is, but document the fact that for continuous output you must use Console.Error.Write and WriteLine.
3. In addition, we could provide an extra output stream as part of TestContext, using a name that would more clearly show it's purpose... for example, TestContext.Immediate.WriteLine or TestContext.Progress.WriteLine.

Since Console.Error already works, this could be implemented pretty quickly.

What does everyone think of this approach?

[unickq]

I think it's cool idea to keep things as is and add additional progress.writeline.

So when could it be implemented?

[oznetmaster]

This seems to relate to my issue #1226.

[CharliePoole]

@oznetmaster Yes, we discussed the similarities and differences on #1226. The main difference is that this is simply an unstructured text write, whereas you asked for a percent completion progress indication in #1226.

@NickQA Let's allow some more folks to comment. If we take the simple approach, I think it can be in the next release.

[CharliePoole]

OK, pending further comments, I am going ahead with this.

1. Console.Error will continue to be unintercepted.
2. TestContext.Progress will go to Console.Error for now as the easiest way to get it displayed.

Point 2 is an implementation detail that might change in the future, particularly if the gui provides for a special progress display area. In general, we could support any number of streams that are displayed in different ways by different runners.

[CharliePoole]

OK... a slight complication. StdErr initially appeared to me to be uncaptured, but it is, in fact, captured.

I can stop capturing it - that makes sense for stdErr actually - but it may have some side effects on some people. If you are one of those folks, please comment here!

[CharliePoole]

Technically, of course, I won't stop capturing it. I have to capture it and do something else with it. Since console output may be created in a separate process from the one running nunit3-console, anything that is to be displayed has to be routed back as an event.

In NUnit V2 we had separate output events, which were removed for V3. I'll have to reinstate that code.

IOW, a can of worms!

[yoyos06]

"In addition, we could provide an extra output stream as part of TestContext, using a name that would more clearly show it's purpose... for example, TestContext.Immediate.WriteLine or TestContext.Progress.WriteLine."

This sounds great!

"If we take the simple approach, I think it can be in the next release..." ... "..., a can of worms!"

Familiar to me :)

[CharliePoole]

Yes, that's how it goes sometimes. Fortunately, it's code that was already written once.

No more promises as to timing however. :-(

[SidShetye]

FYI, we also need this, posting to follow release updates.

For context, most of our are quick but we do have a couple of performance/stress tests that run once all tests pass. These run for a few minutes.

The use case is

1. During R&D and trying new things, we run the stress tests to rapidly iterate but nothing comes up on the developer's workstation/console. It's kinda silly to fork into a separate temporary console project just to see real time test updates because it's essentially our unit tests with just jacked up counters/loops/threads. Allowing engineers to develop/test/iterate rapidly without frustration would be nice.

2. During failed runs on the build server, the log is absent instead of being partially captured.

EDIT: Ok, we're confused. This issue is closed and marked as done but still no console output for us ...

[rprouse]

@SidShetye in order for test output to be sent to the console immediately, you must write it out using TestContext.Progress(...). Writing output in other ways (Console.WriteLine() or TestContext.WriteLine() for example) is captured by the test and output when the test completes. This is done so that test output is grouped with the test in the correct order for multiple tests run in parallel.

[NedNedyalkov]

Hello. I've recently updated to the latest versions of NUnit(3.14.0), NUnit3TestAdapter(4.5.0) and NunitXml.TestLogger(3.1.15).

Before the update I had my TestContext.Progress.WriteLine() print immediately. And now it doesn't however Console.Error.WriteLine() still prints immediately.

Also after a test is completed if it passed I used to get no console output while running the tests with: dotnet test --verbosity minimal --logger "nunit;LogFileName=TestResults.xml" After the update I see the console output regardless of what verbosity I use.

Since I can use Console.Error.WriteLine I'm ok with doing that. I can also capture the console output and decide to dump it at the end of each test, but if this is undesired behavior/bug, I'm reporting it.