[Feature]: Print error.cause

[conartist6]

🚀 Feature Proposal

The proposal for error.cause is currently stage 3. This proposal is to support jest printing chains of cause properties if they are present on errors.

Motivation

Nested errors can be critical to debugging. JSON.parse might throw a syntax error when reading a file. But if the filename isn't hardcoded in the stack from that called JSON.parse, a developer debugging would have no idea which particular file could not be parsed. The solution is to support chains of causally related errors: as errors bubble up through layers of code they can be caught and rethrown as a cause, allowing additional information to be captured.

Example

Imagine the application contains this code

const readJson = (path) => {
  try {
    const json = JSON.parse(fs.readFileSync(path));
  } catch (e) {
    throw new Error(`Failed to parse JSON from ${path}`, {cause: e});
  }
}

If the application throws during testing complete information is available about the problem. The code throws an error with a cause property defined, per the spec. The cause contains critical information about what the error is, but if jest does not opt in to printing it that information is only present in interactive environments for those who know to look for it. Currently jest would print

Error: Failed to parse JSON from 'path/to/file'.
  at readJson:5

If this feature is implemented jest would print:

Error: Failed to parse JSON from 'path/to/file'.
  at readJson:5
Caused by: SyntaxError: Unexpected token u in JSON at position 0
  at JSON.parse (<anonymous>)
  at readJson:3

Pitch

Jest has the ability to bring the improved debuggability that this proposal creates to a large audience. It is relevant and stable enough for inclusion.

[conartist6]

From what I can see in the codebase this would likely involve changes to (or additons to) the AssertionResult core type. Currently the relevant portion of that type is:

export type AssertionResult = {
  failureDetails: Array<unknown>;
  failureMessages: Array<string>;
};

failureDetails may contain error objects (or other objects describing errors for the jasmine2 runner). failureMessages will actually contain stack traces if they are present on errors.

The most powerful way to expose the functionality would be to simply change failureMessages to include the full nested stack trace with causes, and all code consuming those messages would benefit. Some downstream work would be created through as jest later parses that message.

[SimenB]

I like this idea! We currently print a codeframe - I assume we wouldn't want a frame for any causes along the way? I imagine that would take up a lot of space.

I'm happy to take a PR implementing this. 🙂

The most powerful way to expose the functionality would be to simply change failureMessages to include the full nested stack trace with causes, and all code consuming those messages would benefit.

Yeah, that sounds reasonable to me

[conartist6]

Yeah I was considering that. It might become a lot of extra space, particularly as the cause feature starts to be used more heavily. In the use case I have right now the least specific cause is the one that really benefits from a code frame, but I'm not sure that will always be the case. I'll leave it at one frame to start out.

[conartist6]

I'm going to hard fork the stack-utils package. I've got most of a proper parser written, and the current stack-utils is really meant mainly for node usage where I want to come up with something that works equally well in node and browser environments. Plus I know I need breaking changes to their API to support cause stacks in a first-class way.

[conartist6]

OK that was a lot more work than I anticipated (and I'm still not quite done), but I've accomplished what I set out to so I'm pretty happy about that. This implementation already beats the pants off the old one in many regards. My work is up in tapjs/stack-utils#62. I'm sure it's still got some bugs, but I think I'm to the point where I could test integrating it with jest.

[conartist6]

Correction, I've completed my hard fork and further development will be done at https://github.com/conartist6/stack-tools and released under the name stack-tools.

[SimenB]

Looking forward to seeing how it shakes out! Looks promising 🙂

[conartist6]

OK I've now got a proper AST for errors and printing based on traversal with a visitor. This lays the groundwork for me to offer base printing behavior while ensuring it is still possible for the end user to override any part of the printing as they see fit. This is great as it means the project can offer several extensible printers, for example a colored terminal printer with chalk, an html printer, and even (eventually) a React component hierarchy which could support some very rich functionality indeed.

I have 100% test coverage, but my plan is to test the whole thing out by finishing the integration with jest and hopefully getting some review on an integration PR here once I have that ready.

[SimenB]

If you're after encouragement I'm super excited about this direction 😃 But I do not have any comment about the implementation up until any integration with Jest starts to materialize. I have faith in this improving errors for our users though, which is essentially one of our strongest value propositions

[conartist6]

I'll always take encouragement! I should have the integration ready pretty soon.

[conartist6]

Here's what I've got. Don't pay too much attention to the specific formatting, as I was mostly just testing whether I could apply formatting.

Here is the content of test/integration/test.js:

const { relative } = require('path');
const { ChalkPrintVisitorMixin } = require('@stack-tools/chalk-tools');
const {
  parseErrors,
  cleanErrors,
  PrintVisitor: V8PrintVisitor,
} = require('@stack-tools/node-tools');

const PrintVisitor = class extends ChalkPrintVisitorMixin(V8PrintVisitor) {
  PathLocator(locator) {
    if (locator.path.startsWith('/')) {
      locator.path = relative(process.cwd(), locator.path);
    }
    return super.PathLocator(locator);
  }
};

function doStuff() {
  throw new Error('Uh oh');
}

try {
  doStuff();
} catch (e) {
  process.stdout.write(`${PrintVisitor.visit(cleanErrors(parseErrors(e)))}\n\n`);
}

[conartist6]

Actually I'm not even sure I really want a chalk package, since it's not clear what formatting I would put in there.

[conartist6]

OK one more try with everything:

...which is generated by:

const { relative } = require('path');
const chalk = require('chalk');
const {
  parseErrors,
  cleanErrors,
  PrintVisitor: V8PrintVisitor,
} = require('@stack-tools/node-tools');

class PrintVisitor extends V8PrintVisitor {
  ErrorChain(errors) {
    return chalk.magenta.bold`${super.ErrorChain(errors)}`;
  }

  Error(error) {
    return chalk.magenta.bold`${super.Error(error)}`;
  }

  ErrorMessage(message) {
    return chalk.white`${super.ErrorMessage(message)}`;
  }

  Frame(frame) {
    return chalk.reset.magenta`${super.Frame(frame).replace(/^ {2}/, '')}`;
  }

  Call(call) {
    return chalk.white`${super.Call(call)}`;
  }

  Site(site) {
    return chalk.white.underline`${super.Site(site)}`;
  }

  PathLocator(locator) {
    const { cwd } = this.options;
    const { path } = locator;

    return super.PathLocator({
      ...locator,
      path: path.startsWith('/') ? relative(cwd, path) : path,
    });
  }
}

function doLowLevelStuff() {
  throw new Error('fubar');
}

function doStuff() {
  try {
    doLowLevelStuff();
  } catch (cause) {
    throw Object.assign(new Error('Uh oh'), { cause });
  }
}

try {
  doStuff();
} catch (e) {
  process.stdout.write(
    `${PrintVisitor.visit(cleanErrors(parseErrors(e)), { cwd: process.cwd() })}\n\n`,
  );
}

[conartist6]

Sorry I had to make a bunch of edits as I noticed little things that were wrong.

Edit: Oooh I just cannot stop myself making more and more edits, sorry. It's like eating a chip and then the next one and the next one. But if this is something that might get copy pasted around, I may as well make sure it's good code.

[conartist6]

I've got an integration and it type checks now. Moving on to runtime debugging.

[conartist6]

Oh no oh no I didn't consider that jest uses itself to test itself so because I broke the package that formats errors in tests I can't see the errors from the tests I broke O_O

[conartist6]

Oooh I can actually npm install --global jest and then just test jest with jest (as opposed to yarn jest that is). This is super useful for working on the test runner itself as it ensures that the thing running the tests is working production code while the thing under test is the version with your changes.

[conartist6]

I can also rebuild a single package easily by changing this line in scripts/build.js to:

const packages = [path.resolve(__dirname, '../packages/pgk-name')];

[conartist6]

I've got at least a couple tests passing on the integration now. Current puzzle: the tests assert that frames from Jasmine are filtered out and not displayed, and yet I can't find the code that would be doing it if indeed those tests are presently passing.

Here's the relevant test stack trace:

  at stack (../jest-jasmine2/build/jasmine-2.4.1.js:1580:17)
  at Object.addResult (../jest-jasmine2/build/jasmine-2.4.1.js:1550:14)
  at jasmine.addResult (../jest-jasmine2/build/index.js:82:44)
  at Spec.Env.factory (../jest-jasmine2/build/jasmine-2.4.1.js:641:18)
  at Spec.addResult (../jest-jasmine2/build/jasmine-2.4.1.js:333:34)
  at Expectation.addResult (../jest-jasmine2/build/jasmine-2.4.1.js:591:21)
  at Expectation.toBe (../jest-jasmine2/build/jasmine-2.4.1.js:1504:12)
  at Object.it (build/__tests__/messages-test.js:45:41)
  at Object.<anonymous> (../jest-jasmine2/build/jasmine-pit.js:35:32)
  at attemptAsync (../jest-jasmine2/build/jasmine-2.4.1.js:1919:24)

And the snapshot indicates that the correct set of frames after filtering is:

  at stack (../jest-jasmine2/build/jasmine-2.4.1.js:1580:17)
  at Object.addResult (../jest-jasmine2/build/jasmine-2.4.1.js:1550:14)
  at Object.it (build/__tests__/messages-test.js:45:41)

...but why? How? I really don't know. I don't see any defining pattern to those three frames at all. All the frames are basically the same format. Some frames from ../jest-jasmine2/build/jasmine-2.4.1.js are included and some are excluded, even though in theory all of those paths match the JEST_INTERNALS_IGNORE regexp -- if we followed that regex only a single frame would be left, the Object.it frame.

OH!

Ok, brainwave. I am remembering that the snapshot for this test was all kinds of a mess, and I know that I must be cognizant that the old code may not have worked the way I assumed it did, and I think this is one of those moments. I couldn't understand why the snapshot had a blank line in the middle of the stack trace, but that's crucial. The "parsing" code was cutting off the first line assuming it to be the message (it is not), and then it was treating the remaining lines as the stack trace. One of them legitimately doesn't match the jest internals ignore pattern, and the other one is saved because the code always saves the top frame, even if it's from Jest. I just couldn't see that this was what was happening, because I thought the other frame was the top one.

So the corrected expected trace is:

     at stack (../jest-jasmine2/build/jasmine-2.4.1.js:1580:17)
     at Object.it (build/__tests__/messages-test.js:45:41)

[SimenB]

All stack filtering is in that file. Feeding new (full) traces through the tests in https://github.com/facebook/jest/blob/2a5e51590ed77f5db2ab0beec8020ce116f06e67/packages/jest-message-util/src/__tests__/messages.test.ts is probably a good idea, that way you can see that it spits out the correct thing quicker that the integration tests can

[SimenB]

I can also rebuild a single package easily by changing this line in scripts/build.js to:

const packages = [path.resolve(__dirname, '../packages/pgk-name')];

I recommend running yarn watch which will build all packages, then watch for changes and rebuild each file 🙂

[conartist6]

Yep those are the tests I've been running since that's the code I've been changing. It's pretty cool how integrating with jest has allowed me to catch many bugs and flaws in my design and API that would have been difficult to see otherwise.

I think I've nearly got them all passing too...

[conartist6]

The tests show two contradictory behaviors likely due to bugs I've resolved in the logic. I need to know which is correct.

Should noStackTrace ever show stack trace frames, specifically should it show the top frame from the stack? The no stack test checks to make sure that no frames are printed, while the does not print codeframe when noStackTrace = true test expects a single stack frame to be printed.

There's also a comment that says, if no stack, no codeframe is implied. Hmm.

[conartist6]

The documentation for noStackTrace says "Disables stack trace in test results output." Given that this is a documented option that comes with no qualifications and noCodeFrame is an undocumented object that is also predicated on the existence of a stack in order to have any use, I'd say it seems relatively clear to me that noStackTrace should take precedence and the correct result whenever that option is present is no stack frames and no code frames. But it's certainly different behavior than was present before. Perhaps running the broader test suite will shed some light on what that's about.

[conartist6]

OK all the jest-message-util tests pass now that I've cleared up that ambiguity. Initial state of the broader test suite at this point is:

Test Suites: 43 failed, 1 skipped, 376 passed, 419 of 420 total
Tests:       109 failed, 36 skipped, 4246 passed, 4391 total
Snapshots:   101 failed, 1626 passed, 1727 total
Time:        164.339 s
Ran all test suites in 16 projects.

I'm not too worried though -- it looks like most of the failures are due to easily fixable problems.

[conartist6]

The broader test suite seems to indicate that noStackTrace means "no more than one stack frame".

[conartist6]

The console e2e contains a respects --noStackTrace case which passes {noCodeFrame: false, noStackTrace: true} to jest-message-util and then expects there to be one printed stack frame with no code frame.

I'm not gonna say that makes sense to me, but if that's the behavior I have to replicate that's what I'll make it do.

[conartist6]

Test Suites: 17 failed, 1 skipped, 402 passed, 419 of 420 total
Tests:       57 failed, 36 skipped, 4298 passed, 4391 total
Snapshots:   50 failed, 1679 passed, 1729 total
Time:        165.92 s

[conartist6]

I'm in the home stretch! Most of those remaining failures are caused by one of the 3 remaining anomalies that I still need to debug.

Test Suites: 6 failed, 1 skipped, 413 passed, 419 of 420 total
Tests:       10 failed, 36 skipped, 4345 passed, 4391 total
Snapshots:   9 failed, 1720 passed, 1729 total
Time:        166.294 s

[conartist6]

Oh and there are a few places left in the implementation where I don't yet support errors with causes, which I absolutely do need to fix because the old code did "support" them at least in that it didn't blow up if there's a message in the middle of your stack trace, which my code will. This will require a little thought as to what the correct formatting and behavior should be.

[conartist6]

The PR will go up today though, as most of the work I've done so far has just been to capture the existing logic with better code. The review for that code will be an excellent place to discuss what changes to the existing logic might be desired.

[conartist6]

Oh and I probably broke windows \ compatibility which is untested so I must remember to fix that. My intention was/is to move that functionality wholly into stack-tools.

[conartist6]

Draft PR is up! Let the feedback roll in! I'll be doing my own review there as well.

[mattfysh]

Looks like this issue has stalled - but it would be super valuable to ensure error chains are being correctly reported

[thw0rted]

This was closed in #13606, unless there's some additional request here I'm missing.

[dubzzz]

Maybe this one has to be merged before? #13965

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.

[SimenB]

https://github.com/jestjs/jest/releases/tag/v30.0.0-alpha.1