Error output stack trace could be more useful

[nathanmarks]

Note: I don't know enough about Bluebird's handling of stack traces to know if what I'm bringing up is unique to my setup or a common problem.

Currently my error output looks like this:

✖ TypeError: Cannot read property 'jobId' of undefined
    -------------------------------------------------------
      operator: error
      expected: |-
        undefined
      actual: |-
        [TypeError: Cannot read property 'jobId' of undefined]
      at: tryCatcher (/d/node_modules/bluebird/js/release/util.js:16:23)
      stack: |-

Unfortunately, the error stack trace line there isn't very helpful for me.

But if I catch the error myself at the end of the test and console.log(err.stack), the start of my output looks like this:

    TypeError: Cannot read property 'jobId' of undefined
        at waitForJobToFinish (mozQueue.js:59:49)
        at mozQueue.js:49:40

Which is exactly where the error is.

[spion]

I can't tell for sure without looking at the example code, but can you try setting the env variable BLUEBIRD_DEBUG=1 and see if that makes a difference?

[nathanmarks]

@spion Same thing with the env var set. Here's some example code:

Test:

Test('MozQueue Integration', t => {
  // test setup

  return MozQueue.addUrls(urls)
    .then(jobs => Promise.all(map(n => waitForJobToFinish(n), jobs)))
    .then(result =>  t.deepEquals(result, expected, 'should have the correct output'));
});

If I remove the arg n from the waitForJobToFinish() call, I encounter the scenario outlined in the original post.

Here is the waitForJobToFinish() function. You can see where it fails if the arg is not provided (tries to access the property job.jobId, assuming it is an object and not undefined);

export function waitForJobToFinish (job) {
  const jobId = typeof job === 'number' ? job : job.jobId;

  return jobTracker.waitForJobToFinish(jobId);
}

[nathanmarks]

Would you rather I try reproduce this in a test and submit a PR?

[spion]

@nathanmarks A standalone test-case would be lovely, a PR with a test case even nicer. But just a standalone example would be quite sufficient, as I can't reproduce the issue.

[spion]

Nevermind, I managed to find the issue. This will require a slightly more invasive patch of tape

[nathanmarks]

@spion I didn't get a chance to debug yet -- what is the solution?

[spion]

The solution would be to send the captured exception to tape. Tape assumes that the error was caused in a sync context and generates a new Error object, capturing its trace. However because the function has already returned this trace is useless.

The patch would modify Test.prototype._assert to use the passed error object instead of generating a new one: https://github.com/substack/tape/blob/40be68520fedee580462bfaa7e91651154a65bea/lib/test.js#L212

edit: I actually remember encountering this error but I didn't find it critical to fix (the more tape patching we do, the bigger the chances that something will break on an upgrade of tape). The reason why I didn't think it was critical is because the stack trace printed below clearly shows the error. Isn't that the case for you? (not the at: line, the lines below the stack: line).

[nathanmarks]

The stack is empty for me, I just get the at: line:

stack: |-

[spion]

With a similar example (and BLUEBIRD_DEBUG=1) I get:

25303 % BLUEBIRD_DEBUG=1 node test
TAP version 13
# stack
not ok 1 TypeError: x.foo is not a function
  ---
    operator: error
    expected: |-
      undefined
    actual: |-
      [TypeError: x.foo is not a function]
    at: tryCatcher (blue-tape/node_modules/bluebird/js/release/util.js:16:23)
    stack: |-
      TypeError: x.foo is not a function
          at fail (blue-tape/test.js:6:12)
          at blue-tape/test.js:13:39
          at Array.map (native)
          at blue-tape/test.js:13:30
      From previous event:
          at Test.<anonymous> (blue-tape/test.js:13:4)
          at Test.bound [as _cb] (blue-tape/node_modules/tape/lib/test.js:61:32)
          at Test.run (blue-tape/blue-tape.js:13:30)
          at Test.bound [as run] (blue-tape/node_modules/tape/lib/test.js:61:32)
          at Immediate.next [as _onImmediate] (blue-tape/node_modules/tape/lib/results.js:70:15)
          at processImmediate [as _immediateCallback] (timers.js:383:17)
  ...

1..1
# tests 1
# pass  0
# fail  1

example:

var t = require('./blue-tape');
var P = require('bluebird');


function fail(x) {
  return x.foo();
}

var items = [1,2,3]

t.test("stack", function() {
  return P.resolve(items)
  .then(items => Promise.all(items.map(i => fail(i))));
});

Might need a test case to reproduce that issue then (the stack missing)

[nathanmarks]

@spion Ok, let me see what I can pull together for you

[nathanmarks]

@spion

Had inexplicable issues putting together a simple example.

I'm not sure if this helps, but I did dig into tape and follow the trail. You're correct, in Test.prototype.error I can still access my stack trace. in Test.prototype._assert() it is lost.

Is this because I'm executing my tests with babel-node?

[spion]

@nathanmarks I doubt it, I get the same stack trace with babel-node.

The issue with Test.prototype._assert() only pertains to the at: line. The stack line is different:

https://github.com/substack/tape/blob/master/lib/results.js#L156-L165

and is taken from the actual error.

edit: Seems like something is emptying the error stack. Wouldn't know how that happens though. My best guess is that something changes the Error.prototype.stack property to a getter that empties the property after its accessed for the first time. You could verify this by trying to console.log(err.stack && String(err.stack))

[nathanmarks]

@spion You're going to hate me. I was piping my output all this time into https://github.com/scottcorgan/tap-spec

and I think this is causing the issue: (from tap-out) https://github.com/scottcorgan/tap-out/blob/master/lib/assert.js#L18

[nathanmarks]

The raw output from tap-out is missing the stack trace which is present in the raw tap output:

"raw": "    operator: error\n    expected: |-\n      undefined\n    actual: |-\n      [TypeError: Cannot read property 'system' of undefined]\n    at: run (/Users/PoweredbySearch/Development/repos/poweredbysearch/vioc-dashboard-tools/node_modules/core-js/modules/es6.promise.js:104:47)\n    stack: |-"

[spion]

Ha! So is tap-spec doing that to all tape stack traces, or just blue-tape?

[spion]

Any news?

[nathanmarks]

@spion So many things to debug, too little time... It's on my radar!

[raphinesse]

@spion This only happens to the blue-tape stack traces, tape stack traces are passed through untouched.

I compared the raw tap output of both tools. After a common prefix, blue-tape prints the following to stdout

not ok 1 TypeError: Cannot read property 'paths' of undefined
  ---
    operator: error
    expected: |-
      undefined
    actual: |-
      [TypeError: Cannot read property 'paths' of undefined]
    at: Test.run <REST OF LINE OMITTED>
    stack: |-
      TypeError: Cannot read property 'paths' of undefined
          at <MULTIPLE LINES OMITTED>
  ...

1..1
# tests 1
# pass  0
# fail  1

while tape prints nothing to stdout and this to stderr:

<PATH TO FILE>:32
  const paths = foo.bar.paths
                        ^

TypeError: Cannot read property 'paths' of undefined
    at <MULTIPLE LINES OMITTED>

which seems to be passed through untouched by tap-spec.

The test were run directly with node. No test runners or such. I hope this helps.

FWIW, exceptions are reported correctly when piping output to faucet

Also see this issue and the issues and PRs linked therein : scottcorgan/tap-spec#53