Show full stack on failure #330

AnIrishDuck · 2016-10-17T21:41:33Z

I rebased #265 and fixed all the tests. The easiest solution to fixing most tests was to strip out the stack trace parts that will change from machine to machine.

@devtristan @ljharb

ljharb · 2016-10-18T07:19:28Z

lib/results.js

@@ -157,8 +157,10 @@ function encodeResult (res, count) {
    if (res.at) {
        output += inner + 'at: ' + res.at + '\n';
    }
-    if (res.operator === 'error' && res.actual && res.actual.stack) {
-        var lines = String(res.actual.stack).split('\n');
+    var error = (res.actual instanceof Error ? res.actual : res.error)


instanceof will fail on cross-realm Error instances (like from an iframe, or the vm module.

ljharb · 2016-10-18T07:19:38Z

lib/results.js

-    if (res.operator === 'error' && res.actual && res.actual.stack) {
-        var lines = String(res.actual.stack).split('\n');
+    var error = (res.actual instanceof Error ? res.actual : res.error)
+    var stack = typeof error === 'object' ? error.stack : null


missing semicolon

ljharb · 2016-10-18T07:19:57Z

test/circular-things.js

@@ -2,13 +2,15 @@ var tape = require('../');
 var tap = require('tap');
 var concat = require('concat-stream');

+var stripFullStack = require('./common').stripFullStack


Ugh, sorry. This is what happens when you copy/paste. Will fix all cases.

ljharb · 2016-10-18T07:21:10Z

test/common.js

+}
+
+module.exports.stripFullStack = function (output) {
+    return output.replace(/^\W+at.*:\d+:\d+.*$\W/gm, '');


Rather than just stripping it, I'd prefer to try to normalize the output across engines - for example, use try/catch to get an actual stack trace at runtime, and then using that to figure out how stack traces should work?

So, here's the first-order problems that checking full stacks with every test would create:

The file names will change depending on the absolute directory of the git clone.

Any changes to line position (adding or removing things from a test or even potentially to a file that contains code as part of a test traceback) will cause tests to fail.

These are the two biggest problems, and could be easily fixed by stripping the relevant volatile part of the stack. The deeper issue that can't be resolved is the structure of the stack itself. Any refactoring that adds or removes a method to any "failing stack" will now fail the test.

As a result, many trivial refactors would then result in lots of pointless new test failures. It was annoying enough to go through all these tests myself once to fix this issue. I don't want to put that burden on every future author.

Does that make sense? Maybe I'm just not understanding what you're expecting to happen when normalizing output across engines. Is there some deeper property of the stacks we want to test everywhere?

Re 1, we can determine the filename with __filename and process.cwd() and similar.
Changes to line position are a fair point, and i'd be fine normalizing all of those (ie, all line numbers would be normalized to 0 - so that relative line numbers mattered but not absolute numbers).

I guess I'm mainly concerned (especially because this regex is pretty inscrutable) that there will be bugs in the stack traces, and we won't know.

How about I modify this to something like verifyAndStripTraces, which strips all stacks from the generated YAML and checks:

That the expected test file shows up somewhere in the stack trace

That every line of the stack trace "looks right". Honestly, the only thing I can think of here is matching against some basic regex (or regexes, which might make things more understandable).

For more clarification, here's an example error, with the stacks still fully in the test output:

+++ found --- wanted actual: |- {} stack: |- Error: should be equivalent + at Test.assert [as _assert] (/Users/fmurphy/src/tape/lib/test.js:216:54) + at Test.bound [as _assert] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Test.deepEqual.Test.deepEquals.Test.isEquivalent.Test.same (/Users/fmurphy/src/tape/lib/test.js:384:10) + at Test.bound [as deepEqual] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Test.<anonymous> (/Users/fmurphy/src/tape/test/undef.js:36:11) + at Test.bound [as _cb] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Test.run (/Users/fmurphy/src/tape/lib/test.js:84:10) + at Test.bound [as run] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Immediate.next (/Users/fmurphy/src/tape/lib/results.js:71:15) + at runCallback (timers.js:574:20) + at tryOnImmediate (timers.js:554:5) + at processImmediate [as _immediateCallback] (timers.js:533:5) ...

If any refactoring adds or removes a function, pulls something into an anonymous function, or moves things into a new file ... then this stack trace will change. Even if we do obvious things, like strip line numbers and character positions, and normalize file paths.

Completely checking stack correctness would require sophisticated code analysis, which seems like overkill. The challenge here is thus figuring out the right tradeoff between "smart" parsing and effort involved.

So, I think that it can be simplified by replacing process.cwd() with the string "$PWD", for example - and line numbers replaced :[0-9]+:[0-9]+ with :#:# - what other normalization would be needed there?

The problem is, stacks change. All the time. Even running the same test in node version 0.10.0 (which, guessing by the test matrix, you guys want to support) gives a different stack:

+++ found --- wanted actual: |- {} stack: |- Error: should be equivalent + at Test.assert (/Users/fmurphy/src/tape/lib/test.js:216:54) + at Test.bound [as _assert] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Test.deepEqual.Test.deepEquals.Test.isEquivalent.Test.same (/Users/fmurphy/src/tape/lib/test.js:384:10) + at Test.bound [as deepEqual] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Test.<anonymous> (/Users/fmurphy/src/tape/test/undef.js:36:11) + at Test.bound [as _cb] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Test.run (/Users/fmurphy/src/tape/lib/test.js:84:10) + at Test.bound [as run] (/Users/fmurphy/src/tape/lib/test.js:65:32) + at Object.next [as _onImmediate] (/Users/fmurphy/src/tape/lib/results.js:71:15) + at processImmediate [as _immediateCallback] (timers.js:309:15) ...

Because, at some point, someone refactored the timers core library in node (and added the runCallback and tryOnImmediate frames). What normalization method would reduce both stacks to the same value? One has more frames than the other...

We could strip out all frames that don't involve the test/ directory. So the result would look like this:

Error: should be equivalent [... frames omitted ...] at Test.<anonymous> ($BASE/test/undef.js:$LINE:$COLUMN) [... frames omitted ...]

Would that be a good compromise?

I think that would probably suffice, thanks for investigating!

ljharb · 2016-10-18T07:21:42Z

test/exit.js

@@ -3,6 +3,8 @@ var path = require('path');
 var spawn = require('child_process').spawn;
 var concat = require('concat-stream');

+var stripFullStack = require('./common').stripFullStack


ljharb · 2016-10-18T07:21:47Z

test/fail.js

@@ -3,12 +3,14 @@ var tape = require('../');
 var tap = require('tap');
 var concat = require('concat-stream');

+var stripFullStack = require('./common').stripFullStack


ljharb

Seems like tests are failing on node <= 4

ljharb · 2016-10-28T21:13:18Z

lib/results.js

@@ -157,8 +157,10 @@ function encodeResult (res, count) {
    if (res.at) {
        output += inner + 'at: ' + res.at + '\n';
    }
-    if (res.operator === 'error' && res.actual && res.actual.stack) {
-        var lines = String(res.actual.stack).split('\n');
+    var error = (res.actual instanceof Error ? res.actual : res.error);


I'd prefer not to use instanceof, since it's not reliable across realms. (same as #330 (comment))

Right, am still thinking about how to test / fix this. My current plan is to create a new test that throws an error from the node vm module. Does that sound like a good plan? Any suggestions on actually fixing this issue?

As a test that's great as long as the test is skipped in non-node environments.

For actually fixing it, it's probably easier to just continue ducktyping the existence of a stack property.

ljharb · 2016-10-28T21:13:37Z

lib/results.js

-    if (res.operator === 'error' && res.actual && res.actual.stack) {
-        var lines = String(res.actual.stack).split('\n');
+    var error = (res.actual instanceof Error ? res.actual : res.error);
+    var stack = typeof error === 'object' ? error.stack : null;


this won't catch when error is null

AnIrishDuck · 2016-11-08T23:42:28Z

I'm hoping to get to the rest of the comments tomorrow, just was trying to be sure that Travis was happy. Checking errors on node 5 now.

AnIrishDuck · 2016-11-11T21:44:30Z

@ljharb - I think it should be good to go now. I was never able to create a failing test with the vm module. For comparison functions i.e. vm.runInNewContext('t.equal(1,2)'), the result reporting would happen inside the vm realm, and the check would succeed.

For error-throw checks, I also tried doing:

t.throws(function () {
    vm.runInNewContext('throw new Error(\'CROSS\')');
}, /DOMAIN/);

The problem there is that every _assert for error testing sets actual and error to the same exception. Thus, the check was still harmless. Regardless, I think the new code is more foolproof, and doesn't implicate the same realm concerns.

Let me know if modifications are needed.

ljharb · 2016-11-12T00:31:58Z

lib/results.js

+
+    var actualStack = res.actual && res.actual.stack;
+    var errorStack = res.error && res.error.stack;
+    var stack = defined(actualStack, errorStack);


why defined and not actualStack || errorStack? Are we worried about a stack trace that's falsy but not undefined?

Nah, it just seemed like the right thing to me. I don't think there will be any practical difference between the two, so I'll switch it if you want.

nah, it's not adding a dep so i guess it's fine

AnIrishDuck · 2016-12-02T20:57:44Z

@ljharb - anything needed from me to move this forward? I just checked back and I think I addressed all of your issues?

ljharb

LGTM - I'll test and merge this weekend.

OliverJAsh · 2017-04-15T19:45:34Z

I'm only seeing one line of the stack trace on the latest version of tape. How do I get this working?

ljharb · 2017-04-15T22:51:03Z

@OliverJAsh a version containing this change has not yet been released.

- [Fix] fix spurious "test exited without ending" (#223) - [New] show full error stack on failure (#330) - [Deps] update `resolve`, `object-inspect`, `glob` - [Dev Deps] update `tap`, `concat-stream`, `js-yaml` - [Tests] fix stack differences on node 0.8 - [Tests] npm v4.6+ breaks on node < v1, npm v5+ breaks on node < v4 - [Tests] on `node` `v8`; no need for sudo; `v0.8` passes now; allow v5/v7/iojs to fail.

holgerd77 · 2017-09-21T14:48:00Z

Hmm, is it actually possible to make this change optional? We have downgraded our tape dependency due to this change, since in our setup the stack trace is useless information and this extremely bloats the test output makes debugging much harder.

ljharb · 2017-09-22T00:53:23Z

While I wouldn't say a short stack trace is a part of the contract for tape, if you want to open a new issue, I would support an option that limits the number of lines of a stack trace shown.

holgerd77 · 2017-09-22T07:57:40Z

@ljharb Thanks a lot, have done this: #397

nhamer · 2017-10-07T20:18:53Z

lib/results.js

-    if (res.operator === 'error' && res.actual && res.actual.stack) {
-        var lines = String(res.actual.stack).split('\n');
+
+    var actualStack = res.actual && res.actual.stack;


AnIrishDuck force-pushed the complete-stack branch from 5b0aeb1 to 4472fc4 Compare October 17, 2016 22:53

ljharb requested changes Oct 18, 2016

View reviewed changes

AnIrishDuck force-pushed the complete-stack branch from 247b6f5 to bc8be57 Compare October 28, 2016 19:51

ljharb requested changes Oct 28, 2016

View reviewed changes

ljharb added tests needs user feedback labels Oct 28, 2016

ljharb reviewed Nov 12, 2016

View reviewed changes

ljharb approved these changes Dec 3, 2016

View reviewed changes

ljharb added enhancement and removed needs user feedback labels Dec 4, 2016

ljharb force-pushed the complete-stack branch from 8ddd19a to c7c5943 Compare December 4, 2016 07:50

[New] show full error stack on failure

9302682

ljharb force-pushed the complete-stack branch from c7c5943 to 9302682 Compare December 4, 2016 08:13

ljharb merged commit 9302682 into tape-testing:master Dec 4, 2016

OliverJAsh mentioned this pull request Apr 15, 2017

show the entire stack when there's an error #265

Closed

holgerd77 mentioned this pull request Sep 22, 2017

Option to limit the number of lines of a stack trace shown #397

Open

nhamer reviewed Oct 7, 2017

View reviewed changes

This was referenced Dec 27, 2019

print the file name tape is running in for debuggability #70

Closed

Better error stack traces reporting #68

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Show full stack on failure #330

Show full stack on failure #330

AnIrishDuck commented Oct 17, 2016

ljharb Oct 18, 2016

ljharb Oct 18, 2016

ljharb Oct 18, 2016

AnIrishDuck Oct 18, 2016

ljharb Oct 18, 2016

AnIrishDuck Oct 18, 2016

ljharb Oct 18, 2016

AnIrishDuck Oct 19, 2016

ljharb Oct 19, 2016

AnIrishDuck Oct 19, 2016

AnIrishDuck Oct 19, 2016 •

edited

Loading

ljharb Oct 20, 2016

ljharb Oct 18, 2016

ljharb Oct 18, 2016

ljharb left a comment

ljharb Oct 28, 2016

AnIrishDuck Oct 31, 2016

ljharb Oct 31, 2016

ljharb Oct 28, 2016

AnIrishDuck Oct 31, 2016

AnIrishDuck commented Nov 8, 2016

AnIrishDuck commented Nov 11, 2016

ljharb Nov 12, 2016

AnIrishDuck Nov 14, 2016

ljharb Nov 14, 2016

AnIrishDuck commented Dec 2, 2016

ljharb left a comment

OliverJAsh commented Apr 15, 2017

ljharb commented Apr 15, 2017

holgerd77 commented Sep 21, 2017

ljharb commented Sep 22, 2017

holgerd77 commented Sep 22, 2017

nhamer Oct 7, 2017

Show full stack on failure #330

Show full stack on failure #330

Conversation

AnIrishDuck commented Oct 17, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AnIrishDuck Oct 19, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ljharb left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AnIrishDuck commented Nov 8, 2016

AnIrishDuck commented Nov 11, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

AnIrishDuck commented Dec 2, 2016

ljharb left a comment

Choose a reason for hiding this comment

OliverJAsh commented Apr 15, 2017

ljharb commented Apr 15, 2017

holgerd77 commented Sep 21, 2017

ljharb commented Sep 22, 2017

holgerd77 commented Sep 22, 2017

Choose a reason for hiding this comment

AnIrishDuck Oct 19, 2016 •

edited

Loading