Colored-output text should not appear in middle of xml/html report

[GCheung55]

When xml or html is the reporter and the test suite takes a while to run, the output in the terminal displayed colored-output text:

[1m[33mUncaught exception: [assert.calledOnceWith] Expected function loadFrame() {} to be called once with arguments error[0m
[1m[33mUncaught exception: [assert.calledOnce] Expected function getMatchedUserDeviceImages() {} to be called once but was called 0 times[0m

https://github.com/busterjs/buster-test-cli/blob/master/lib/runners/browser.js#L40 seems to be the culprit.

Perhaps the reporters can take over logging, since the errors would be displayed in the reports?

[augustl]

First we need to find out why failed assertions suddenly trigger the uncaught exception handler.

Secondly, the problem of having reporters write to global mutable state - stdout - seems like a bad idea to me in hindsight.

A reporter should write to a separate stream that only the reporter knows about. Some reporters will delegate to require("util").print if no "out" stream is passed in, this should never happend and we should rewrite it to fail if no "out" stream is passed to the reporter, instead of defaulting to stdout.

Furthermore, an option to write the reporter stream to a file, instead of stdout, makes sense. You never know what might happen in stdout.

[GCheung55]

1. This is caused by an async test not triggering done or returning a promise. In the case where a promise is involved, the promise resolves after the test timeout occur, and the then attached to the promise has assertions that fail.

'Some test': function(){
    var deferred = new RSVP.defer()
    var someSpy = this.spy()

    deferred.promise.then(function(){
        assert.calledOnce(someSpy)
    })

    // Mimic async test resolution
    setTimeout(function(){
        deferred.resolve()
    }, 1000)
}

As you can see here, a promise isn't returned, so a test timeout occurs with no assertions. But then, somehow, the promise is resolved after the test timeout occurs, which could trigger an uncaught exception. The fix was to return the promise and trigger resolve earlier, but this doesn't change the fact that an uncaught exception will be logged as a warning.

1. I agree. I think the reporter should accept options, but I don't know the best way to do it. A possible interim solution would be to have a custom reporter copy and modify the out stream.

[augustl]

Thanks for the very detailed explanation of the cause of the uncaught exception!

Will look into reporters after investigating https://github.com/busterjs/buster/issues/440 some more.

[GCheung55]

This could be related to causing issues in https://github.com/busterjs/buster/issues/263

[GCheung55]

Where would it make most sense to define reporter options?

I think reporter options could be merged with the defaults and passed on to the reporter via buster.js config. That way an outputStream could be defined. Though, if we're going through the trouble, would it also make sense to pass a reporter as a configuration option?

[dominykas]

Ah... could this be because of throwOnFailure thing that changed [back] to true recently? Just noticed this locally too (different reporter, but a simple assertion failure ending up as uncaught and async test timing out, instead of failing)

/cc @dwittner

[dwittner]

I tried to reproduce the issue, but without success. I used this example.

Running the tests via buster-test --reporter xml 1> out.xml leads to this xml file:

<?xml version="1.0" encoding="UTF-8" ?>
<testsuites>
    <testsuite errors="0" tests="1" time="0.001" failures="1" skipped="0" name="Chrome 39.0.2171.95, Windows Server 2008 R2 / 7 7">
        <testcase time="0.011" classname="Chrome 39.0.2171.95, Windows Server 2008 R2 / 7 7.#439" name="some bad test">
            <failure type="AssertionError" message="No assertions!"></failure>
        </testcase>
    </testsuite>
    <testsuite errors="0" tests="1" time="0" failures="1" skipped="0" name="Chrome 39.0.2171.95, Windows Server 2008 R2 / 7 7">
        <testcase time="5.01" classname="Chrome 39.0.2171.95, Windows Server 2008 R2 / 7 7.#439 - 2" name="some slow test">
            <failure type="AssertionError" message="[assert.calledOnce] Expected function spy() {} to be called once but was called 0 times(empty string)">
                AssertionError: [assert.calledOnce] Expected function spy() {} to be called once but was called 0 times(empty string)
                    at Object.referee.fail (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/buster/bundle-0.7.js:8694:25)
                    at Object.ctx.fail (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/buster/bundle-0.7.js:8617:29)
                    at Function.referee.(anonymous function).(anonymous function) (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/buster/bundle-0.7.js:8625:21)
                    at http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/test.js:13:20
                    at A (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/node_modules/rsvp/dist/rsvp.min.js:9:2305)
                    at j (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/node_modules/rsvp/dist/rsvp.min.js:9:2396)
                    at b (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/node_modules/rsvp/dist/rsvp.min.js:9:2208)
                    at MutationObserver.hn (http://localhost:1111/sessions/5311ae0c-5f5e-4374-a64b-3ed55fbb6a4c/resources/node_modules/rsvp/dist/rsvp.min.js:9:6918)
            </failure>
        </testcase>
    </testsuite>
</testsuites>

If it turns out, that these lines of code are the cause of the problem, i would suggest to remove them. We don't have these warnings for node tests and i don't think we need them for browser tests either.

@augustl, maybe we have to rethink the current implementation writing to stdout, but i would like to postpone that until after 1.0. We already have a few other open reporter issues, which should be fixed before 1.0.

@dominykas, i don't know, if the change of throwOnFailure to true for async tests has something to do with this issue, because i can't reproduce it yet.

[jameskranz]

A good way to reproduce this is to have a test that is erroneous as follows:

'test that will assert out of scope, and should cause output in the console': function () {
  setTimeout(function (){
    assert(false);
  }, 1);

  assert(true);
}