Extreme stack traces

[TheLudd]

I am just trying out cucmber-js and I notice that when a test fails, an enormous stack trace is produced (160 lines). This makes it really hard to understand which test failed and why. Is there some kind of workaround or solution to this problem?

[jbpros]

Please use our cukes group for support.

There are some libraries to help deal with stack traces on NPM. We could reduce the traces a bit by filtering Cucumber's source from it. I'd be curious to see your complete testing stack though as 160 lines seem a bit much. Are you using webdriverjs or something similar?

[jbpros]

I wrote a little stack trace filter. It will only display stack trace "sites" related to your own code (based on the file path). It could be smarter but this is a good starting point. Add the following to features/support/stack_filter.js:

var path = require('path');
var filteredPathPrefix = path.resolve(__dirname, '..', '..');
var originalPrepareStackTrace;

if (originalPrepareStackTrace = Error.prepareStackTrace) {
  Error.prepareStackTrace = function (error, stack) {
    var originalString = originalPrepareStackTrace(error, stack);
    var string = 'Error: ' + error.message + "\n";
    var lines = originalString.replace('Error: ' + error.message + "\n", '').replace(/\s*$/, '').split("\n");
    var i;
    for (i = 0; i < lines.length; i++) {
      var line = lines[i];
      var callSite = stack[i];
      if (callSite.getFileName().indexOf(filteredPathPrefix) == 0)
        string = string + line + "\n";
    };
    return string;
  };
}

I'm reopening the issue as it could make sense to get something similar (better) built in Cucumber.js.

[TheLudd]

Thanks for reopening. Here is a simple failing test that gives me 160 lines of stack trace:

Feature: Stack traces
    In order to prove long stack traces
    As a programmer
    I want this test to fail

    Scenario: Fail
        Given a passing pre condition
        Then the test fails 

//steps.js
module.exports = function() {
    this.Given(/^a passing pre condition$/, function (callback) {
         callback();
     });

     this.Then(/^the test fails$/, function (callback) {
         callback.fail(new Error('I am an error'));
     });
}

I don't have much experience with cucumber but I do have with testing in general and I really think this is a hindered (even if there are workarounds), By default IMHO only the error message needs to be printed.

[jbpros]

Well I do not completely agree. When doing TDD/BDD, the stack trace helps you figure out what should be done next. An error message alone is often not enough to work efficiently.

That being said, I agree everything related to the testing framework should be hidden from the stack trace.

[TheLudd]

I actually agree with that and did so before as well. It was a weird choice of words on my behalf in my last post.

[laurelnaiad]

My stack trace is

Feature: ...

  ...

  Scenario:                     # features/speeches/add-button.feature:7
    ...
      AssertionError: expected 'something to equal 'something else''
          at <anonymous>
      ==== async task ====
      WebDriver.getTitle()
          at <anonymous>
          at <anonymous>
          at <anonymous>

"at anonymous" goes on for pages and pages for one single assertion error.

FWIW, I'm running with chai, chai-as-promised, protractor and selenium. Please, please, please add a flag to turn off stack traces? In a webdriver context, it seems the stack traces are not going to be very helpful -- all I really need to know is that my webapp isn't doing the right thing! I have to scroll so far up to find the actual errors... I'm going to try hacking my console but I wish the stack trace religion could soften for those of us who really get no value from them.

[laurelnaiad]

Doh! Somehow I managed to overlook that there is a fine solution sitting right in this issue. I should get more sleep. Thank you @jbpros, your snippet was exactly what I needed to get me started.

Here is my webdriver-compatible patch:

// monkey-patch stack trace more-or-less compatible with webdriver
var isMyStack = new RegExp(
  path.join(
    __dirname,
    '../..', // go up two dirs to get to repo root -- ymmv, adjust accordingly
    '[^node_modules/]' // exclude node_modules
  )
      .replace(/\//g, '\\/')
);

Error.prepareStackTrace = function (err, stack) {
  var i;
  var frame;
  var results = [];
  for (i = 0; i < stack.length; i++) {
    frame = stack[i].toString();
    if (isMyStack.test(frame)) {
      results.push('    at ' + frame);
    }
  }
  // believe it or not you need to let webdriver throw away the first line
  // so prepend a newline if intending to return anything
  return results.length ? '\n' + results.join('\n') : '';
};

It is based on a regular expression that keeps away any code that is coming from outside of my repo or from node_modules in my repo. This might be a fairly decent pattern for others, subject to modifying the relative directory resolution for the location of the code that does the monkeying (I happen to do it in my World module). I certainly hope it helps out anyone who is using webdriver and cucumber-js together.

For me, it gets rid of the protractor, webdriver and cucumber internals, which together are a very long list of uninteresting stack frames -- with this patch, I'm left with the two stack relevant trace lines and that makes me happy.

The gory parts of the story... I suspect anyone who's using webdriver -- probably a healthy chunk of cucumber-js users -- might be in this boat.

Both cucumber and webdriver are messing around with error objects.

This seems maybe to be causing an issue in that:

1. cucumber appears to be trying to get stuff to be logged by putting it in the stack. The one I've noticed so far is "AssertionError: expected 'blah' to equal 'junk'".
2. webdriver parses and reformats what it expects to be V8 stack errors using this regexp:

/^    at(?: (?:(?:((?:new )?(?:\[object Object\]|[a-zA-Z_$][\w$]*(?:\.[a-zA-Z_$][\w$]*)*))\.|(new )))?((?:[a-zA-Z_$][\w$]*|<anonymous>))(?: \[as ([a-zA-Z_$][\w$]*)\])?)? (?:\((.*)\)|(.*))$/

So it drops anything that doesn't look like that and replaces is with " at <anonymous>":

https://github.com/SeleniumHQ/selenium/blob/master/javascript/webdriver/stacktrace.js#L614

webdriver.stacktrace.parse_ = function(stack) {
  if (!stack) {
    return [];
  }

  var lines = stack.
      replace(/\s*$/, '').
      split('\n');
  var frames = [];
  for (var i = 0; i < lines.length; i++) {
    var frame = webdriver.stacktrace.parseStackFrame_(lines[i]);
    // The first two frames will be:
    //   webdriver.stacktrace.Snapshot()
    //   webdriver.stacktrace.get()
    // In the case of Opera, sometimes an extra frame is injected in the next
    // frame with a reported line number of zero. The next line detects that
    // case and skips that frame.
    if (!(goog.userAgent.OPERA && i == 2 && frame.getLine() == 0)) {
      frames.push(frame || webdriver.stacktrace.ANONYMOUS_FRAME_);
    }
  }
  return frames;
};

The apparent lost rendering of an AssertionError message is only one minor symptom (in fact, I still see the AssertionError messages even after witnessing some of their demises, so they must be tough little buggers).

I do believe that for the actual stack traces, anything that looks at all out of the ordinary is being "murdered" by webdriver -- and hence we "webdriver victims" sometimes get a long list of "at <anonymous>".

It's also one of the reasons that, while your particular monkeypatch put me onto the solution, it didn't work for me. First, it depends on someone already having provided a prepareStackTrace override... I'm going to guess that it works if you run cucumber-js from the command line because it requires coffee-script, which does such a thing. So you're basing your patch on the coffee-script-tweaking process being available, I guess.

If you don't run cucumber-js from the command line and don't otherwise include coffeescript, then it just flat out errors. If you do load coffeescript, it goes back to the bigger problem of webdriver-the-intolerant being very finicky about what a valid stack trace line looks like.

After I figured out that I wasn't going to have a preexisting prepareStackTrace function to leverage, I was playing fast and loose with my formatting, and thus webdriver was clobbering my trace. One I got that worked out I was home free.

[jbpros]

Thanks Stu, this is very useful feedback.

I think I understand the whole thing and I didn't realise prepareStackTrace was there thanks to coffeescript.

To be honest, I'm not sure what to do now. It looks like we'll be fighting against stealth ennemies (i.e. other libraries) that are messing with the stack traces in unpredictable ways (and already kinda fighting between themselves). I guess we could detect the presence of webdriver, chai, test-my-thing and whatnot but I can foresee how things will go out of control pretty quickly.

What if we didn't care about this at all in Cucumber.js but published separate packages to handle the different well-known libs? There could be a cucumber-js-webdriver package that would insert your filter, another one called cucumber-js-phantom that would address Phantom.js-specific issues. Those could even provide helper methods.

Just like cucumber-rails.

Thoughts?

[laurelnaiad]

I think making stack traces optional altogether in the reporter would be great.

I think factoring out reporters so that they can be developed independently of Cucumber-JS would be great (since I'm also needing the XUnit reporter that is in limbo lacking its own tests in a different issue here).

As to what to do about stack traces in this reporter, it would great to provide a hook in a convenient place in Cucumber-JS so that we could customize what's reported.

That all said, I think first and foremost if Cucumber didn't rewrite the stack traces, or rewrote them to V8's expected format (which seems to be compatible elsewhere as well), then webdriver in particular wouldn't choke on them, and in fact would be able to suppress them itself.... but to be honest I can't remember all of the code I was looking at, and the path through it that the stack trace content takes, to know for sure whether that would be enough for webdriver to not cause the clutter. At the least it wouldn't clobber everything with at <anonymous> and at best it would catch those lines as coming from itself and strip them for us. As I said, I can't remember how it plays out. If asked, I can try to dig back into it. In my case, Angular's protractor harness driving Cucumber is a factor, but obviously that's well within the realm of a corner case for Cucumber generally.

[laurelnaiad]

Sorry -- forgot to mention -- I think webdriver at the very least should be accommodated somehow. Too may Cucumber users are testing webapps in end-to-end scenarios for the current situation, where Selenium is the main way to drive them -- the patch works for me so I'm ok but it wasn't a pretty experience for me! :)

[laurelnaiad]

For what it's worth I do the patch as a side of effect of "Node-require"'ing the module that exposes my World constructor via the protractor harness, all before the testing actually kicks in, then I make that constructor a global object so that I don't have to require it all over the place.

[jlin412]

@jbpros
I tried your stack trace filter code but cucumber stop running at the first failure from Chai as promise. And no error is reporting.

[jbpros]

@jlin412 could you share some code to reproduce this?

[jlin412]

@jbpros Here is my code:

Feature File:
Feature: To smoke test Redbox application
It will include login and click on each individual menu.
Scenario Outline: To login and click on each menu tabs
When I login as a default user
And I go to page
And the title should equal "<title>"
Then the url should equal ""
Examples:
| module | title | url |
| calendar | abc | /#/calendar |

Step Definition:

function CommonStepDefinition () {
var loginPage = new pages.LoginPage();
var leftNav = new pages.LeftNav();
var topNav = new pages.TopNav();

this.Given(/^I login as a default user/, function (next) {
  loginPage.login().then(next);
});

this.Given(/^I go to (.*) page$/, function (module, next) {
  Q.all([
    leftNav.goToTab(module)
  ]).should.notify(next);
});

this.Then(/the title should equal "([^"]*)"$/, function(title, next) {
    browser.getTitle().should.eventually.equal(title).and.notify(next);
});

this.Then(/the url should equal "([^"]*)"$/, function(url, next) {
    browser.getLocationAbsUrl().should.eventually.equal(redbox.host + url).and.notify(next);
});
}module.exports = CommonStepDefinition;

Commandline:
OSELCXB0073323:redbox_angular linj$ grunt e2e::smoke.feature::chrome --env=dev --source=1
Running "e2e::smoke.feature::chrome" (e2e) task

Cannot delete nonexistent file.
Cannot delete nonexistent file.
Using the selenium server at http://localhost:4444/wd/hub
[launcher] Running 1 instances of WebDriver
Feature: To smoke test Redbox application
It will include login and click on each individual menu.

Scenario Outline: To login and click on each menu tabs # test/e2e/features/smoke.feature:4
When I login as a default user # test/e2e/features/smoke.feature:5
And I go to calendar page # test/e2e/features/smoke.feature:6
[launcher] chrome passed

Done, without errors.

[jbpros]

@jlin412 and if you remove the filter, you got the whole suite running?

If so, I'm afraid something else than us is trying to mess around with the stack trace and fail to do so because of the filtering.

[jbpros]

@jlin412 can you confirm everything runs as expected without the filter?

[jlin412]

@jbpros I confirm that everything still runs as expected without the filter. The stack_trace.js seems to filter out chai as promise exception or error. What should I do to enable that? Is there a way that I can modify the existing code that you provided.

[pumbers]

Following on from the above monkey patch, here's a shorter version:

    var path = require('path');
    var filteredPathPrefix = path.resolve(__dirname, '..');
    var originalPrepareStackTrace;
    var stackTraceDepth = 1;
    if (originalPrepareStackTrace = Error.prepareStackTrace) {
        Error.prepareStackTrace = function (error, stack) {
            var message = [error.name + ': ' + error.message];
            for (var i = 0; i < stack.length; i++ ) {
                if (stack[i].getFileName().indexOf(filteredPathPrefix) == 0) message.push('  at ' + stack[i]);
            }
            return message.slice(0, stackTraceDepth + 1).join('\n');
        };
    }

[jlin412]

@pumbers not sure what magic you did in your code. I didn't get the same issue anymore and error message filter works great.

[terokaisti]

@pumbers Nice patch. Just what I needed.

However, +1 for the command line option to suppress the stack trace.

[sebs]

is this somehow usable? I just need the first line of an assert and the rest optional. It really takes the fun out of a gulp-watch stlyle development.

[laurelnaiad]

I agree that it is particularly painful when it completely "buries the lead" in a watch console. I and others have overcome it. Have you tried any of our hacks?

[sebs]

No. I have not yet.

Lets get through these hacks:

The first one by jbpros does not tell me where to actually call these. Do I just put a file there and magically it gets filtered? I tried following the instructions, but putting a file into the support folder does not cut it.

The second one by stu-salsbury is a webdriver compatible change. I do not use webdriver. I use zombie.js

pumbers proposes something that looks quite useful, bit there is no way to see where I have to apply the change to in order to make it work.

All in all, I did not find any "patch" or "fix" in this thread that was useful to me. I am sorry, maybe I am just a bit too much of a "present me the fix on a plate" guy. But I really wonder why not ever someone has had the idea to fix this once and for all since cucumber is kind of a tool where you work from exception to exception in order to make all acceptance tests pass. So everyone ever has scrolled all the lines up for every condition that failed?

regards

[jlin412]

@sebs you can add it as a hook by creating a stack_trace.js file and add it to features/support/ directory and copy @pumbers's code into it.

[djungowski]

In case you're using assertions, I've just released the library "cucumber-assert" which allows you to assert things and get a nice error message w/o 5 pages of stacktrace: https://github.com/djungowski/cucumber-assert

[cades]

Mocha encounter the same problem, and there's a nice solution using pipe to shorten stack trace.
It plays well with cucumber.js, too!

[dtinth]

I think I just found a gem. clarify is a module that removes Node.js-related stack frames from the stack trace. Under the hood, it uses stack-chain module, which allows stack frames to be extended, filtered, and replaced.

Therefore, I created a package hide-stack-frames-from, and you can use it like this:

require('hide-stack-frames-from')('cucumber')

[jlin412]

Thai, How about submitting a PR using this code to give an option to hide
node.js stack trace?

On Thursday, January 8, 2015, Thai Pangsakulyanont [email protected]
wrote:

I think I just found a gem. clarify
https://www.npmjs.com/package/clarify is a module that removes
Node.js-related stack frames from the stack trace. Under the hood, it uses
stack-chain https://www.npmjs.com/package/stack-chain module, which
allows stack frames to be extended, filtered, and replaced.

Therefore, I created a package hide-stack-frames-from, and you can use it
like this:

require('hide-stack-frames-from')('cucumber')

—
Reply to this email directly or view it on GitHub
#157 (comment)
.

[dtinth]

@jlin412 I am already happy putting that line of code in some support file. Therefore, although it doesn't hurt to do so, I don't see the need of it being in Cucumber's core.

I also use it to hide stack frames from Bluebird, and etc. That's why I prefer being able to configure all of them from a single supporting script.

[sebs]

require('hide-stack-frames-from')('cucumber')

Works like a charms and fixes my problem. thanks

[plato-cambrian]

thanks @pumbers !

[floribon]

Just a heads up, not sure if there is a better solution today on March 2016.

I tried using hide-stack-frames-from module but it was failing on some scenario, and would leave some node related traces.

Instead I used @laurelnaiad's snippet with the addition of the error message. Indeed the algorithm was removing any custom message sent by throw new Error or a failing promise. However some cucumber error messages were still ugly, such as:

UnknownError: unknown error: Element is not clickable at point (580, 60). Other element would receive the click: <div class="collapse navbar-collapse">...</div>
        (Session info: chrome=48.0.2564.116)
        (Driver info: chromedriver=2.21.371459 (36d3d07f660ff2bc1bf28a75d1cdabed0983e7c4),platform=Mac OS X 10.11.3 x86_64) (WARNING: The server did not provide any stacktrace information)
      Command duration or timeout: 36 milliseconds
      Build info: version: '2.51.0', revision: '1af067d', time: '2016-02-05 19:15:17'
      System info: host: 'bookmac.local', ip: '192.168.0.13', os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '10.11.3', java.version: '1.8.0_05'
      Driver info: org.openqa.selenium.chrome.ChromeDriver
      Capabilities [{applicationCacheEnabled=false, rotatable=false, mobileEmulationEnabled=false, chrome={chromedriverVersion=2.21.371459 (36d3d07f660ff2bc1bf28a75d1cdabed0983e7c4), userDataDir=/var/folders/09/5x0xspyd11sd9lm1423fsrxw0000gn/T/.org.chromium.Chromium.EiV0Gx}, takesHeapSnapshot=true, databaseEnabled=false, handlesAlerts=true, hasTouchScreen=false, version=48.0.2564.116, platform=MAC, browserConnectionEnabled=false, nativeEvents=true, acceptSslCerts=true, locationContextEnabled=true, webStorageEnabled=true, browserName=chrome, takesScreenshot=true, javascriptEnabled=true, cssSelectorsEnabled=true}]
      Session ID: 8f132e9736404994a5d7c0610574d8e2

So at the end I ended up keeping only the first line of any error message:

var message = err.message.split('\n')[0];
return message + (results.length ? results.join('\n') : '');

[leegee]

FWIW, as a developer using Cucumber JS for BDD, I like to have a full stack trace.

As a developer creating BDD reports for the rest of the team, I like to use various reporter modules that hide the trace in an HTML report.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.