Show only the useful lines of stack trace - fixes #22 #29

mdibaiee · 2015-08-29T08:00:37Z

Fix "Assertion count does not match planned" error's stack trace not showing

mdibaiee · 2015-08-29T08:02:26Z

About promises, I couldn't find a way of finding the stack trace for them, and as it's self-explainatory that the the returned promise was rejected, I think we can just ignore printing and stack trace for that.

Qix- · 2015-08-29T17:29:05Z

Without looking too deeply at the code, is there an option to show full stacks? This is one thing about Mocha I actually hate; a lot of the time I'm writing two modules that complement each other concurrently, and the stack traces never show the other's stack entries unless I use --full-trace.

sindresorhus · 2015-09-01T15:19:13Z

@Qix- What would you like to keep?

Currently it looks like:

  AssertionError: false === true
    at Test.(anonymous function) [as assert] (/Users/sindresorhus/dev/ava/lib/test.js:49:14)
    at Test.fn (/Users/sindresorhus/dev/acosh/test.js:8:4)
    at Test.run (/Users/sindresorhus/dev/ava/lib/test.js:78:18)
    at Runner.<anonymous> (/Users/sindresorhus/dev/ava/lib/runner.js:39:8)
    at Immediate.immediate._onImmediate (timers.js:418:16)
    at processImmediate [as _immediateCallback] (timers.js:367:17)

With this PR, it looks like:

false === true
    at Test.fn (/Users/sindresorhus/dev/acosh/test.js:8:4)

All it hides is useless stack info coming from AVA and Node.js core libs.

sindresorhus · 2015-09-01T15:21:19Z

lib/test.js

@@ -99,14 +101,15 @@ Test.prototype.end = function () {

 Test.prototype.exit = function () {
 	if (this.planCount !== null && this.planCount !== this.assertCount) {
+		console.log(this.planStack);


Qix- · 2015-09-01T15:42:23Z

I'd have to see a full stack. If it's just removing lines caused by the tests then that should be just fine.

sindresorhus · 2015-09-01T15:45:17Z

Can you provide some code that result in a "full stack"? I definitely agree it should not remove that.

Qix- · 2015-09-01T19:22:04Z

Well more specifically with Mocha in general, it removes any stack entries that have node_modules in them. I suppose it makes sense, but at the same time it's somewhat futile and time-wasting because, in the case of errors with suppressed node_modules stack lines, the error message doesn't normally correspond with the actual error site at the "top" of the trace, causing confusion.

Just wanting to make sure this isn't the case.

mdibaiee · 2015-09-01T19:50:26Z

I see that this approach doesn't work in some cases, consider this example:

test('something', function(t) {
  t.is('hey', 'hey');
  doSomeTest(t, 2);
  doSomeTest(t, {});
  t.end();
});

function doSomeTest(t, x) {
  t.same({x: x}, {x: {}});
}

This is the output for this example:

1. something
  { x: 2 } === { x: {} }
    at doSomeTest (/Users/mahdi/Documents/Workshop/github/ava-test/test.js:13:5)

But we should also show the line for:

at Test.fn (/Users/mahdi/Documents/Workshop/github/ava-test/test.js:9:5)

I think that's what @Qix- means. I'm going to see if I can find a better approach.

Qix- · 2015-09-01T20:00:30Z

Not quite, but that is true. For instance,

// mocha

// Note, `my-module' is not part of the source tree, but it's still mine
// in this example. Maybe a sister/plugin module, etc.
var myModule = require('my-module');

it('should xyz', function () {
  myModule(); // throws
});

stack:

Error: some sort of error
    at function (test.js:8:4)
    at <mocha stuff>

It doesn't show where inside the module my-module the error was thrown. I have to pass --full-trace in order to get that information.

mdibaiee · 2015-09-01T20:21:47Z

Okay, I think I found the ultimate solution ✊

We can filter out the stack lines which start with the directory of the test file, see:

let dir = path.dirname(module.parent.filename);

var split = (result.error.stack || '').split('\n');
let related = split.filter(line => line.indexOf(dir) > -1);

var beautiful = result.error.message + '\n' + related.join('\n');

What do you think?

Qix- · 2015-09-01T20:26:11Z

Then assertions won't show up correctly. 🍊

mdibaiee · 2015-09-01T20:27:09Z

@Qix- Why? I tested it with the example I said above, it's working correctly, have you tested this?

Output:

0:50 » ~/Documents/Workshop/github/ava-test $ node test.js
  ✖ something { x: 2 } === { x: {} }

  1 test failed

  1. something
  { x: 2 } === { x: {} }
    at doSomeTest (/Users/mahdi/Documents/Workshop/github/ava-test/test.js:13:5)
    at Test.fn (/Users/mahdi/Documents/Workshop/github/ava-test/test.js:7:3)

…ul lines are printed

mdibaiee · 2015-09-01T21:05:29Z

@sindresorhus Do you think I should squash my commits into one?

sindresorhus · 2015-09-02T05:44:30Z

@mdibaiee No need. I squash one merge. Easier to see individual changes the current way.

mdibaiee · 2015-09-03T09:11:37Z

What's the plan now? Anything else has to be done in this PR?

sindresorhus · 2015-09-03T09:28:14Z

Looks good to me now :)

@Qix- ?

Qix- · 2015-09-03T15:06:17Z

index.js

@@ -36,6 +37,18 @@ function stack(results) {

 		i++;

+		// Don't print the full stack but the only useful line showing
+		// the actual test file stack
+		var dir = path.dirname(module.parent.filename);


Sorry for my thickness, but what is this actually doing? I mean, what is the intent? Isn't it just filtering out anything that's not in the project directory? What is this improving/fixing?

In an edge case, what happens if I require() something outside of my immediate project directory? It will be dropped, too.

This is fixing the issue defined here.

It doesn't necessarily have to show the stack for your required modules, users are least concerned with how the error was generated in the module they are using, they're mostly interested in how their code causes an error, afterall they are testing their own code, not their modules.

It's about defaults, what most people prefer, users usually prefer simplicity, and if they really want the full stack, we can provide an option for that (--full-stack as you said).

Qix- · 2015-09-03T15:42:23Z

I understand the desire for clean stack traces. I just heavily question the usefulness of this particular approach.

Tape's stack errors are even more useless than Mocha's if all they're showing is the deepest user-script call site of the error. Many times, the parts of the stack that make the error's cause immediately clear are the parts above (deeper) the deepest user script. For example:

TypeError: Cannot convert object to primitive value
    at String (unknown source)
    at util.js:38:25
    at String.replace (native)
    at Object.<anonymous> (util.js:35:23)
    at Object.<anonymous> (console.js:25:36)
    at EventEmitter.<anonymous> (/project/src/routines/debug/boot.js:16:21)

Without looking at boot.js in the above project, I can safely assume looking at the affected line (boot.js:16) by itself is probably not clear about what exactly is going on. Take a look.

'use strict';

var path = require('path');

var message = 'TypeError: Cannot convert object to primitive value';
var stack = [
  '    at String (unknown source)',
  '    at util.js:38:25',
  '    at String.replace (native)',
  '    at Object.<anonymous> (util.js:35:23)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at EventEmitter.<anonymous> (' + __filename + ':16:21)',
].join('\n');

var dir = path.dirname(module.filename);
console.log('DIR', dir);

var split = (stack || '').split('\n');
var related = split.filter(function (line) {
    return line.indexOf(dir) > -1;
});

var beautiful = message + '\n' + related.join('\n');

console.log(beautiful);

which outputs

$ node test.js
DIR /private/tmp/avatest
TypeError: Cannot convert object to primitive value
    at EventEmitter.<anonymous> (/private/tmp/avatest/test.js:16:21)

I'd have no idea what was going on, making the stack trace absolutely useless - hence why I asked if there was a way to show full traces.

If the intent here is to only show relevant stack lines, so that we exclude:

Lines that are part of Node.js proper
Lines that belong to the AVA module

then why not filter on lines that have absolute paths, starting at the first found? The logic here is that, beginning at the deepest source file (going upward through the stack), we filter out anything that isn't a user script. We also show anything deeper than the deepest user script.

This is an approach I've used elsewhere for clean error printing and I've never run into problems with not seeing enough information.

/\((?:[\\\/](?:(?!node_modules[\\\/]ava[\\\/])[^:\\\/])+)+:\d+:\d+\)/

The above regex looks for all () groups with absolute paths inside of them, along with line numbers and characters (i.e. (/a/b/c/d.js:10:5)). It excludes those that have node_modules/ava in them.

Example:

'use strict';

var path = require('path');

var message = 'TypeError: Cannot convert object to primitive value';
var stack = [
  '    at String (unknown source)',
  '    at util.js:38:25',
  '    at String.replace (native)',
  '    at Object.<anonymous> (util.js:35:23)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at EventEmitter.<anonymous> (' + __filename + ':16:21)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at EventEmitter.<anonymous> (' + __filename + ':16:21)',
  '    at EventEmitter.<anonymous> (' + __filename + ':16:21)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at Object.<anonymous> (console.js:25:36)'
].join('\n');

var reg = /\((?:[\\\/](?:(?!node_modules[\\\/]ava[\\\/])[^:\\\/])+)+:\d+:\d+\)/;
function beautifulStack(stack) {
  var found = false;
  return stack.split('\n').filter(function (line) {
    var relevant = reg.test(line);
    found = found || relevant;
    return !found || relevant;
  }).join('\n');
}

console.log(message + '\n' + beautifulStack(stack));

which yields

$ node test.js
TypeError: Cannot convert object to primitive value
    at String (unknown source)
    at util.js:38:25
    at String.replace (native)
    at Object.<anonymous> (util.js:35:23)
    at Object.<anonymous> (console.js:25:36)
    at EventEmitter.<anonymous> (/private/tmp/avatest/test.js:16:21)
    at EventEmitter.<anonymous> (/private/tmp/avatest/test.js:16:21)
    at EventEmitter.<anonymous> (/private/tmp/avatest/test.js:16:21)

For @sindresorhus's stack example, this yields

$ node test.js
AssertionError: false === true
    at Test.(anonymous function) [as assert] (/Users/sindresorhus/dev/ava/lib/test.js:49:14)
    at Test.fn (/Users/sindresorhus/dev/acosh/test.js:8:4)
    at Test.run (/Users/sindresorhus/dev/ava/lib/test.js:78:18)
    at Runner.<anonymous> (/Users/sindresorhus/dev/ava/lib/runner.js:39:8)

which, if we replace dev/ava with node_modules/ava (since it's clear it's his dev environment), we actually get:

$ node test.js
AssertionError: false === true
    at Test.(anonymous function) [as assert] (/Users/sindresorhus/node_modules/ava/lib/test.js:49:14)
    at Test.fn (/Users/sindresorhus/dev/acosh/test.js:8:4)

Another example, this stacktrace:

Error: `foo` has been removed in favorof `bar`
    at function() (/home/ray/dev/test/error.js:53:3)
    at b() (domain.js:183:18)
    at Domain.run() (domain.js:123:23)
    at function() (/home/ray/dev/test/error.js:52:3)
    at Module._compile() (module.js:456:26)
    at Module._extensions..js() (module.js:474:10)
    at Module.load() (module.js:356:32)
    at Module._load() (module.js:312:12)
    at Module.runMain() (module.js:497:10)

gets reduced down to

$ node test.js
Error: `foo` has been removed in favorof `bar`
    at function() (/home/ray/dev/test/error.js:53:3)
    at function() (/home/ray/dev/test/error.js:52:3)

That seems much more appropriate to me.

The point is that reducing the amount of information in errors is going to cause more headache than it solves. It should be intelligent, not "beautiful", as there is beauty in intelligence itself.

If it improves the signal-to-noise ratio on callsites, then great - I'm all for it. If it removes pieces of information relevant to debugging my code, it's 100% absolutely useless.

mdibaiee · 2015-09-03T15:58:05Z

@Qix- Can you give me the actual test that produces this stack?

at String (unknown source)',
  '    at util.js:38:25',
  '    at String.replace (native)',
  '    at Object.<anonymous> (util.js:35:23)',
  '    at Object.<anonymous> (console.js:25:36)',
  '    at EventEmitter.<anonymous> (' + __filename + ':16:21)',

Qix- · 2015-09-03T16:01:07Z

@mdibaiee No, it's an example stack trace I found on SO. My point is is that you don't need to look at the code to know that the first 5 frames are important for debugging the error.

mdibaiee · 2015-09-03T16:02:20Z

@Qix- My point is knowing what your fault was in the error is good enough for debugging most codes, and starting debugging of others.

Qix- · 2015-09-03T16:04:38Z

@mdibaiee aren't tests a vital part of debugging code?

mdibaiee · 2015-09-03T16:06:57Z

@Qix- You know the answer, yes. And how does that relate?

Qix- · 2015-09-03T16:11:05Z

@mdibaiee Because a first glance view of all of the relevant parts of an error is important. Removing the internals of the deepest user-call will remove the relevant parts of an error.

mdibaiee · 2015-09-03T16:15:09Z

I don't think so. I don't understand your worries, almost all commands have a --verbose option, do you know why? Because I don't need to know all the details everytime, I don't want ls to be like ls -l everytime, it takes spaces, it takes my time and my attention.

If you really think all relevant paths are important, alias ava='ava --full-trace'. Problem solved. I'm not continuing this discussion.

@sindresorhus if we are going to ship this, should I implement --full-trace in this PR or a new one?

Qix- · 2015-09-03T16:18:25Z

Which is what I requested to begin with; however

$ grep -r "full-trace" *
$

You don't have the option in there.

@mdibaiee add it to this PR.

Qix- · 2015-09-03T16:57:46Z

I'd also recommend setting infinity length stack traces before filtering.

Error.stackTraceLimit = Infinity;

sindresorhus · 2015-09-04T05:20:50Z

Minimal vs verbose is a hard one, but from experience with debugging a lot of failed assertions I have to agree with @Qix-. I often have to dig deeper than just the test file. I'm willing to sacrifice visual beauty in favor of practicality here. We should preserve any stack info referencing user code as @Qix- has outlined above. I'm allergic to options and I'd rather go with a good default. We can always change it in the future if it turns out to be the wrong choice.

@mdibaiee Would you be willing to update your PR even though you seem to strongly disagree?

Error.stackTraceLimit = Infinity;

👍

Qix- · 2015-09-04T05:29:55Z

One last thing (I know I'm persistent) but since the introduction of modules like error-ex we might run into exceptions with non-standard lines that start with something other than at; we shouldn't filter those out either.

// in filter function
return str.substr(4, 6) !== 'at' || <other regex stuff>;

should suffice. Could probably be worked into the regex, but you get the idea. 👍

For clarification, I'm referring to the fact one could add a line that said

Error: `foo` has been removed in favorof `bar`
    in file /a/b/c/d/some-file.json                         <--------
    at function() (/home/ray/dev/test/error.js:53:3)
    at b() (domain.js:183:18)
    at Domain.run() (domain.js:123:23)
    at function() (/home/ray/dev/test/error.js:52:3)
    at Module._compile() (module.js:456:26)
    at Module._extensions..js() (module.js:474:10)
    at Module.load() (module.js:356:32)
    at Module._load() (module.js:312:12)
    at Module.runMain() (module.js:497:10)

sindresorhus · 2015-09-04T05:31:32Z

but since the introduction of error-ex we might run into exceptions with non-standard lines that start with something other than at; we shouldn't filter those out either.

👍 I've seen other error modules add stuff too. Better to be on the safe side.

mdibaiee · 2015-09-04T09:52:09Z

@sindresorhus So what's the plan now? Don't filter anything out? Use @Qix- 's RegExp?

sindresorhus · 2015-09-04T09:53:22Z

Use @Qix- 's RegExp?

Yes

mdibaiee · 2015-09-06T11:24:21Z

@sindresorhus Alright, sorry for the delay, I was busy working on another projet, are we ready to go?

Qix- · 2015-09-06T17:06:46Z

index.js

@@ -36,6 +36,19 @@ function stack(results) {

 		i++;

+		// Don't print the full stack but the only useful line showing
+		// the actual test file stack
+		var reg = /\((?:[\\\/](?:(?!node_modules[\\\/]ava[\\\/])[^:\\\/])+)+:\d+:\d+\)/;


Mind updating the regex?

(?:^(?! {4}at\b).{6})|(?:\((?:[\\\/](?:(?!node_modules[\\\/]ava[\\\/])[^:\\\/])+)+:\d+:\d+\))

This won't kill the error message and won't filter out lines that don't start with at.

mdibaiee · 2015-09-07T22:47:45Z

@sindresorhus done

Update beautifulStack's RegExp Do not modify original error's stack property

sindresorhus · 2015-09-08T02:17:15Z

Landed! Thanks for the PR @mdibaiee. Keep'em coming ;)

And thanks for the review @Qix-.

Qix- · 2015-09-08T02:19:00Z

No problem! Thanks @mdibaiee 💃 👍

Closes #29

mdibaiee · 2015-09-08T10:40:43Z

✊✌️

Progress on avajs#22 - Show only the useful lines of stack trace

11abcac

Fix "Assertion count does not match planned" error's stack trace not showing

mdibaiee changed the title ~~Progress on #22 - Show only the useful lines of stack trace~~ Fix #22 - Show only the useful lines of stack trace Aug 29, 2015

Fix lint: remove multiple blank lines

57fd116

mdibaiee mentioned this pull request Aug 29, 2015

Error context #22

Closed

sindresorhus reviewed Sep 1, 2015
View reviewed changes

sindresorhus changed the title ~~Fix #22 - Show only the useful lines of stack trace~~ Show only the useful lines of stack trace - fixes #22 Sep 1, 2015

mdibaiee force-pushed the better-errors branch 3 times, most recently from c3cb76b to 67afa9d Compare September 1, 2015 20:55

Filter stack trace by parent module directory to make sure *all* usef…

67afa9d

…ul lines are printed

Qix- reviewed Sep 3, 2015
View reviewed changes

mdibaiee mentioned this pull request Sep 3, 2015

How should the test interface be configured? #34

Closed

Switch to RegExp-based approach with more verbosity

95c8d43

Qix- reviewed Sep 6, 2015
View reviewed changes

mdibaiee force-pushed the better-errors branch from 98868a6 to b0c697f Compare September 7, 2015 22:57

Set Error.stackTraceLimit to infinity

b0c697f

Update beautifulStack's RegExp Do not modify original error's stack property

sindresorhus closed this in 1fe70ec Sep 8, 2015

sindresorhus pushed a commit that referenced this pull request Sep 8, 2015

Show only useful lines of stack trace - fixes #22

b370dd5

Closes #29

Show only the useful lines of stack trace - fixes #22 #29

Show only the useful lines of stack trace - fixes #22 #29

Conversation

mdibaiee commented Aug 29, 2015

mdibaiee commented Aug 29, 2015

Qix- commented Aug 29, 2015

sindresorhus commented Sep 1, 2015

sindresorhus Sep 1, 2015

Choose a reason for hiding this comment

Qix- commented Sep 1, 2015

sindresorhus commented Sep 1, 2015

Qix- commented Sep 1, 2015

mdibaiee commented Sep 1, 2015

Qix- commented Sep 1, 2015

mdibaiee commented Sep 1, 2015

Qix- commented Sep 1, 2015

mdibaiee commented Sep 1, 2015

mdibaiee commented Sep 1, 2015

sindresorhus commented Sep 2, 2015

mdibaiee commented Sep 3, 2015

sindresorhus commented Sep 3, 2015

Qix- Sep 3, 2015

Choose a reason for hiding this comment

mdibaiee Sep 3, 2015

Choose a reason for hiding this comment

Qix- commented Sep 3, 2015

mdibaiee commented Sep 3, 2015

Qix- commented Sep 3, 2015

mdibaiee commented Sep 3, 2015

Qix- commented Sep 3, 2015

mdibaiee commented Sep 3, 2015

Qix- commented Sep 3, 2015

mdibaiee commented Sep 3, 2015

Qix- commented Sep 3, 2015

Qix- commented Sep 3, 2015

sindresorhus commented Sep 4, 2015

Qix- commented Sep 4, 2015

sindresorhus commented Sep 4, 2015

mdibaiee commented Sep 4, 2015

sindresorhus commented Sep 4, 2015

mdibaiee commented Sep 6, 2015

Qix- Sep 6, 2015

Choose a reason for hiding this comment

mdibaiee commented Sep 7, 2015

sindresorhus commented Sep 8, 2015

Qix- commented Sep 8, 2015

mdibaiee commented Sep 8, 2015