It takes too long to debug failing tests

[philbooth]

This issue is inspired by @seanmonstar and @rfk in following passage from #fxa:

12:00 AM <seanmonstar> i don't know how i managed to make so many tests fail... https://travis-ci.org/mozilla/fxa-auth-server/jobs/158587220
12:07 AM <•rfkelly> yikes!
2:41 AM <seanmonstar> omg this too many times that half the test suite has blown up. Something seems far too brittle here
3:01 AM <•rfkelly> in auth-server, I find that one failing test can cascade into a bunch of subsequent tests also failing
3:01 AM <•rfkelly> is that what you're hitting?
4:18 AM <seanmonstar> rfkelly: yep
4:18 AM <seanmonstar> Maybe
4:19 AM <seanmonstar> I dunno, my changes somehow made 45 tests blow up. There's no error output, and I dunno
4:19 AM <seanmonstar> I've wasted tooany hours on this the past several weeks
4:22 AM <•rfkelly> that sucks; sadly it's not obvious to me whether there's a small change we can make to improve the situation
4:22 AM <•rfkelly> sort of "change to a different test framework and runner"
4:22 AM <•rfkelly> *short
4:23 AM <seanmonstar> Yea, I think the issue might be that exceptions are somehow eaten, and output 
4:23 AM <seanmonstar> I noticed 1 test was passing because the exception didn't happen till the end, but the test only checked that the db methods were called
4:24 AM <seanmonstar> No clue that an exception even happened, until I added some more tests for the response
4:24 AM <seanmonstar> I imagine I'm in a similar case... Something is throw an exception and it's just eaten 
4:40 AM <seanmonstar> yep, finally able to output the exception. they're just silently ignored by the test framework
4:42 AM <•rfkelly> that just ain't right

The same thing has been bugging me for a long time too. Until now I assumed it was just me.

My historical list of complaints, in order of significance, are:

1. When an error occurs it usually cascades all the way down the promise chain and is caught miles away from where it was thrown. Debugging then involves divide-and-conquering the promise chain with extra catches, to try and identify the point of origin for the error.
2. When errors do get caught, the stack is usually meaningless anyway. So you still need to insert extra logging to find out what is actually wrong.
3. Many assertions don't have a description string, so you have to do extra work to find out what a problem actually is if it isn't immediately obvious from the assertion arguments.
4. If you run tests with coverage enabled, as npm test does, the line numbers get messed up.
5. The test runner doesn't nicely summarise the errors at the bottom of the output, it forces you to scroll up and wade through a gajillion lines of output to find the precious few gems that help you debug the issue.

[rfk]

I'll add another complaint:

• We have really poor test isolation; in fact some tests appear actively depend on state being set up correctly by previous tests. The result is that one test failure can balloon into a bunch of other tests also failing, making it harder to debug.

I don't think there'll be a silver bullet here, so much as we'll need to just refactor our way to a better place. Although I'd be very open to silver bullets if anyone has one handy :-)

[rfk]

BTW the docs at [1] contain this gem:

"""
If you do use a lot of Promises to chain your tests in a long declarative list, it’s a good idea to put .catch(t.threw) at the end, so that any unhandled rejections will be bubbled up to the top level handler rather than being ignored or reported in a less helpful manner.
"""

Which sounds like it's contributing to the problem here.

[1] http://www.node-tap.org/promises/

[philbooth]

put .catch(t.threw) at the end

Oh, that is a great find. Let's do this one right away!

[philbooth]

put .catch(t.threw) at the end

Oh, that is a great find. Let's do this one right away!

Hmm, I've not seen much benefit from this change yet. Perhaps I'm breaking the tests in the wrong way, or perhaps I've got my catches in the wrong place.

Anyway, I'll come back to it again later, fwiw my changes so far are in the phil/issue-1448-a branch.

[vbudhram]

We have really poor test isolation

This what what I noticed happening in #1440, with the tests being nested, and modifying values in the mockRequest/mockDB, the test state does not get restored correctly for the next test.

[seanmonstar]

This is what I found last night: An exception thrown during the handler can be silently ignored, since it goes through hapi's reply, and we just see it as a response:

fxa-auth-server/test/local/account_routes.js

Line 71 in c0c51fa

resolve(response)

I modified it so that I could see if there was an error (in my case, it was a TypeError: undefined is not a function or some nonsense) by changing it to this:

function runTest (route, request, assertions) {
  return new P(function (resolve, reject) {
    route.handler(request, function (response) {
      if (response instanceof Error) {
        reject(response)
      } else {
        resolve(response)
      }
    })
  })
  .then(assertions)
}

However, that still just sent the error back to tap, which did not do a good job of showing the error. It also blew up my screen of "test x not finished" and so forth. Maybe it'd have gone better combined with pass t, such that .then(assertions, t.fail)?

[philbooth]

This was fixed by #1537.

[vladikoff]

yaaaaay