Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

unhelpful error stack from expectationResultFactory stackFormatter #3839

Closed
capaj opened this issue Jun 16, 2017 · 31 comments
Closed

unhelpful error stack from expectationResultFactory stackFormatter #3839

capaj opened this issue Jun 16, 2017 · 31 comments

Comments

@capaj
Copy link
Contributor

capaj commented Jun 16, 2017

I have got an error from jest which leaves me blind to the actual problem that caused it:

  ● api functional tests › Can do password reset

    Failed: SyntaxError
      
      at stackFormatter (node_modules/jest-jasmine2/build/expectationResultFactory.js:30:20)
          at <anonymous>

Is it really necessary to create a new error there? Syntax error should always contain a line and collumn so couldn't jest just pass that?
https://github.com/facebook/jest/blob/master/packages/jest-jasmine2/src/expectationResultFactory.js#L30

My node: 8.1.0
My jest: 20.0.4

EDIT:I've since took all of the code out of a test and run it inside babel-node. This error is the one that was swallowed:

Error: connect ECONNREFUSED 127.0.0.1:80
    at Object.exports._errnoException (util.js:1014:11)
    at exports._exceptionWithHostPort (util.js:1037:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1138:14)
From previous event:
    at httpAdapter (/home/capaj/git_projects/looop/project-alpha/front-end/node_modules/axios/lib/adapters/http.js:18:10)
    at dispatchRequest (/home/capaj/git_projects/looop/project-alpha/front-end/node_modules/axios/lib/core/dispatchRequest.js:52:10)
    at __NR_wrappedThenHandler (/home/capaj/git_projects/looop/project-alpha/back-end/node_modules/newrelic/lib/instrumentation/promise.js:466:25)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)
From previous event:
    at Promise.__NR_wrappedThen (/home/capaj/git_projects/looop/project-alpha/back-end/node_modules/newrelic/lib/instrumentation/promise.js:424:23)
    at Promise.<anonymous> (/home/capaj/git_projects/looop/project-alpha/back-end/node_modules/sequelize/lib/promise.js:21:17)
    at Promise.__NR_wrappedThen [as then] (/home/capaj/git_projects/looop/project-alpha/back-end/node_modules/newrelic/lib/instrumentation/promise.js:424:23)
    at Axios.request (/home/capaj/git_projects/looop/project-alpha/front-end/node_modules/axios/lib/core/Axios.js:58:23)
    at Axios.(anonymous function) [as post] (/home/capaj/git_projects/looop/project-alpha/front-end/node_modules/axios/lib/core/Axios.js:78:17)
    at Function.wrap (/home/capaj/git_projects/looop/project-alpha/front-end/node_modules/axios/lib/helpers/bind.js:9:15)
    at Object.resetPassword (/home/capaj/git_projects/looop/project-alpha/front-end/src/api/user-api.js:15:20)
    at test (/home/capaj/git_projects/looop/project-alpha/back-end/test/password-reset.js:38:40)
    at <anonymous>

It's really a shame when the only way to debug a failing jest test is to rewrite the test in raw node.js

@thymikee
Copy link
Collaborator

thymikee commented Jun 19, 2017

Are you able to reproduce the issue on a clean repository, so we can work on proper fix?
cc: @DmitriiAbramov as he's rewriting Jasmine right now and sooner or later will work on better error handling.

@aaronabramov
Copy link
Contributor

oh yeah. I've seen this happen before, i'm still not sure when exactly this happens and what's causing it, since most of the time we still have stack traces.
But all of this logic will be replaced soon anyway

@balaarunreddyv1
Copy link

Yes its pretty annoying..

@capaj
Copy link
Contributor Author

capaj commented Jun 19, 2017

@thymikee I might be able to set up a reproductional repo. Let's see if I can.

So yeah, it's here: https://github.com/capaj/jest-stackFormatter-error

just clone, run jest and you'll get the mysterious error.

@jeffijoe
Copy link
Contributor

jeffijoe commented Jun 27, 2017

I'm having the same issue, using ts-jest. My TS compiles just fine though.

EDIT: Turns out it was due to using Axios, and the default Jest environment is not node, so it attempted to use XMLHTTPRequest or something.

@awilkins
Copy link

Getting a variant of this -

   Failed: [object Object]
      
      at stackFormatter (node_modules/jest-jasmine2/build/expectation_result_factory.js:71:32)
      at process._tickCallback (internal/process/next_tick.js:109:7)

In otherwise passing tests... works fine with 20, upgrading to 21 and these have started dropping all over.

These are tests using supertest on top of express, they are all responses with errors (which are what is being tested), with the call provoking the error occurring in the beforeAll() function.

What fixed this for me :

Changing from the callback style

  beforeAll((done) => {
    status = jest.spyOn(express.response, 'status');
    render = jest.spyOn(express.response, 'render');

    mock_logger = jest.fn();
    jest.mock('../../../app/util/logger', () => mock_logger);

    app = express();
    router = require('../../../app/routes/error');
    app.set('view engine', 'html');
    app.use('/', () => { throw new Error('mock error!'); });
    app.use(router);

    return request(app).get('/').then(done);
  });

To the promise style

  beforeAll(() => {
    status = jest.spyOn(express.response, 'status');
    render = jest.spyOn(express.response, 'render');

    mock_logger = jest.fn();
    jest.mock('../../../app/util/logger', () => mock_logger);

    app = express();
    router = require('../../../app/routes/error');
    app.set('view engine', 'html');
    app.use('/', () => { throw new Error('mock error!'); });
    app.use(router);

    return request(app).get('/');
  });

@dfroger
Copy link

dfroger commented Nov 16, 2017

same problem for me, did someone found a workaround?

@dfroger
Copy link

dfroger commented Nov 16, 2017

@thymikee @aaronabramov The problem seems to be using await on a rejected Promise directly in the it function:

describe('foo', () => {                                                                                                                                                                                                                        
    it('failed at stackFormatter', async () => {                                                                                                                                                                                               
        await new Promise((resolve, reject) => { reject() });                                                                                                                                                                                  
    });                                                                                                                                                                                                                                        
});  

give the error:

 FAIL  ./foo.test.js
  foo
    ✕ failed at stackFormatter (2ms)

  ● foo › failed at stackFormatter

    Failed
      
      at stackFormatter (node_modules/jest-jasmine2/build/expectation_result_factory.js:49:427)
          at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:188:7)

Test Suites: 1 failed, 1 total
Tests:       1 failed, 1 total
Snapshots:   0 total
Time:        0.551s, estimated 1s
Ran all test suites.

but if it is embedded in a function:

describe('foo', () => {
    it('failed at stackFormatter', async () => {
        async function foo() {
            await new Promise((resolve, reject) => { reject() });
        }
        foo()
    });
});

it give the same warnings as when using node directly:

(node:5073) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 2): undefined
(node:5073) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
 PASS  ./foo.test.js
  foo
    ✓ failed at stackFormatter (2ms)

Test Suites: 1 passed, 1 total
Tests:       1 passed, 1 total
Snapshots:   0 total
Time:        0.548s, estimated 1s
Ran all test suites.

edit: fix copy-paste of error message

@bguiz
Copy link

bguiz commented Nov 30, 2017

Getting the same behaviour as @awilkins and @dfroger - except I can't use the workaround, because the library I'm testing uses just callbacks. Started occurring upon upgrading jest:

-    "jest": "^20.0.4",
+    "jest": "^21.2.1",

Thus is seems like a bug has been introduced, so I think the Enhancement label really should be changed to the Bug label @thymikee .

@alem0lars
Copy link

I'm also having the error:


    Failed: [object Object]

      at stackFormatter (node_modules/jest-jasmine2/build/expectation_result_factory.js:49:427)

Everytime something fails in tests.

That's so much annoying since every time there is something to be fixed I need to wrap all logic inside a try/catch statement.

Are there any workarounds?

@SimenB
Copy link
Member

SimenB commented Jan 17, 2018

That's because you're doing done({foo: 'bar'});. In #4016 done with an argument fails. We should probably add a better error message is done is called with a non-error, PR welcome! (Also switching back to "Enhancement" - this is not a bug).

@capaj's example (if upgraded to jest 22) now fails looking like this:

image

Which is better, but not good. It at least points to jsdom, which as mentioned is the issue - you need to run the test in testEnvironment: node.

The full, unfiltered stack is this, but I don't think it's more useful than what we give you now:

SyntaxError: The string did not match the expected pattern.
    at XMLHttpRequest.open (/Users/simbekkh/repos/jest-stackFormatter-error/node_modules/jsdom/lib/jsdom/living/xmlhttprequest.js:470:15)
    at dispatchXhrRequest (/Users/simbekkh/repos/jest-stackFormatter-error/node_modules/axios/lib/adapters/xhr.js:45:13)
    at new Promise (<anonymous>)
    at xhrAdapter (/Users/simbekkh/repos/jest-stackFormatter-error/node_modules/axios/lib/adapters/xhr.js:12:10)
    at dispatchRequest (/Users/simbekkh/repos/jest-stackFormatter-error/node_modules/axios/lib/core/dispatchRequest.js:52:10)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:160:7)

Better stack traces from async tests are tracked in #5104

@alem0lars
Copy link

alem0lars commented Jan 17, 2018

@SimenB No, actually this is my code:

2018-01-17-173842_1261x205_scrot

That code gives me the error:

 Failed: [object Object]

      at stackFormatter (node_modules/jest-jasmine2/build/expectation_result_factory.js:49:427)

@SimenB
Copy link
Member

SimenB commented Jan 17, 2018

Hmm, OK. Can you provide a reproduction repo? Your issue is different than the OP and the last message before yours.

@alem0lars
Copy link

Repository is private (work issues).

However I can give you all pieces..

package.json is the following:

  "jest": {
    "moduleFileExtensions": ["js"],
    "testRegex": "dist/test/.+\\.test\\.js$",
    "testEnvironment": "node",
    "verbose": true
  },

In fact I have TypeScript code that gets compiled into dist/test/... and the compiled tests will be run with the following command: ./node_modules/.bin/tsc -w

This is an example snippet that gives the problem:

import * as Logger from "bunyan";

import { execFile as execFileWithCb, exec as execWithCb } from "child_process";

export function execFile(
  programName: string,
  args: Array<string>,
  options?: any,
): Promise<
  | { error: Error; stdout: string | Buffer; stderr: string | Buffer }
  | { stdout: string | Buffer; stderr: string | Buffer }
> {
  return new Promise((resolve, reject) => {
    execFileWithCb(programName, args, options, (error, stdout, stderr) => {
      if (error) {
        reject({ error: error, stdout: stdout, stderr: stderr });
      } else {
        resolve({ stdout: stdout, stderr: stderr });
      }
    });
  });
}

export function exec(
  command: string,
  options?: any,
): Promise<
  | { error: Error; stdout: string | Buffer; stderr: string | Buffer }
  | { stdout: string | Buffer; stderr: string | Buffer }
> {
  return new Promise((resolve, reject) => {
    execWithCb(command, options, (error, stdout, stderr) => {
      if (error) {
        reject({ error: error, stdout: stdout, stderr: stderr });
      } else {
        resolve({ stdout: stdout, stderr: stderr });
      }
    });
  });
}

describe("UserModel", () => {
  let logger: Logger;

  beforeEach(async () => {
    logger = await createLogger(); // Function that creates the logger, this doesn't give any error
    await execFile("npm", ["run", "jdwqiwqdoiwqjoidwqj"]); // This is supposed to be a command that fails 
  });

@SimenB
Copy link
Member

SimenB commented Jan 17, 2018

Your issue is reject({ error: error, stdout: stdout, stderr: stderr });. You should reject with an error, not an object. Doing reject(error) instead gives this:

    Command failed: npm run jdwqiwqdoiwqjoidwqj
    npm ERR! missing script: jdwqiwqdoiwqjoidwqj

    npm ERR! A complete log of this run can be found in:
    npm ERR!     /Users/simbekkh/.npm/_logs/2018-01-17T17_22_50_366Z-debug.log

When tests reject, or done is called, with a non-error we should provide a better message as mentioned above. A PR is very much welcome for that! 🙂

@alem0lars
Copy link

@SimenB You're right!! Thanks very much 😄

@SimenB
Copy link
Member

SimenB commented Jan 17, 2018

For your concrete use case of using child_process wrapped in promises I'd recommend using execa btw.

@dgoldstein0
Copy link

I discovered this independently this week. Wish I had read this thread before banging my head into it.

To summarize/recap, for anyone who doesn't want to read the whole thread: calling done with a param causes the test to fail (expects no params - so changing to () => done() works) and awaiting or returning a rejected promise from the test, that is not rejected via an exception (e.g. it("foo", async () => await Promise.reject()); should repro), triggers this unhelpful error message.

As far as a solution... the done case could probably capture a stack when done is called. For promises we're probably SOL on stack trace, as we don't know the promise is going to be the result of the test until it is returned, at which point the stack isn't there. But it would still be more helpful to have an error message like "Test returned/awaited rejected promise with value ..." than the current "FAILED" that lacks an explanation.

@SimenB
Copy link
Member

SimenB commented Feb 10, 2018

Sorry you're having issues!

The done case can probably be fixed quite easily as you mention.

For promise we can at least point back to the originating test, in addition to a message. We have the location of all tests in the results object behind a flag (https://facebook.github.io/jest/docs/en/cli.html#testlocationinresults) - we can ask the user to provide the flag and rerun the test for us to have it available.

@dgoldstein0
Copy link

dgoldstein0 commented Feb 10, 2018 via email

@stopsopa
Copy link

Same here, everything reasonably up to date..
#5902

@SimenB
Copy link
Member

SimenB commented Mar 29, 2018

PR welcome improving the message!

@wmertens
Copy link
Contributor

The PR can probably be just this commit jasmine/jasmine@8807bbb#diff-f41e57b2889bae3046aa9f352699785c

I'm completely new to this codebase - I assume there's an excellent reason for forking jasmine, so I wonder if there's documentation of the changes and perhaps a best practice for importing improvements?

@SimenB
Copy link
Member

SimenB commented Apr 11, 2018

It can be ported ish. instanceof doesn't work properly (#2549), so we'll probably have to duck type when checking if it's an error or not. Other than that, should be straight forward.

Reason of forking is discussed here: https://facebook.github.io/jest/blog/2017/05/06/jest-20-delightful-testing-multi-project-runner.html#breaking-changes and here: #3147

@SimenB
Copy link
Member

SimenB commented Apr 17, 2018

I'll call this fixed with #5980 and #6008. Alpha incoming if people want to test

@SimenB SimenB closed this as completed Apr 17, 2018
@SimenB
Copy link
Member

SimenB commented Apr 17, 2018

jest@23.0.0-alpha.7 is out with the fixes. It'd be awesome if people in this issue could test it and verify that the traces have improved!

@bielmorales
Copy link

I had this problem. It happent in my case, cause i was trying to throw an error when it was a promise and i should use returns({error:true}) instead

@ahmadao2214
Copy link

Upgrading to jest@23.0.0-alpha.7 fixed it for us

@mrchief
Copy link

mrchief commented Jun 19, 2018

Looks like jest@23.0.0-alpha.7 doesn't like Node 10 (v10.3.0). I know it's a dependency but seems like it was added with v23 or above maybe. Jest ^22.1.3 doesn't complain about node 10.

error upath@1.0.2: The engine "node" is incompatible with this module. Expected version ">=4 <=9".
error Found incompatible module

@SimenB
Copy link
Member

SimenB commented Jun 19, 2018

Jest 23 has been released as stable about a month ago, does it have the same issue?

EDIT: Also, upath does not exist in Jest's dependency tree, so it's not from us. Run yarn why upath or npm ls upath to see why it's in yours.

@github-actions
Copy link

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 12, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests