Broken error rendering for custom Mocha reporters

[KittyGiraudel]

Current behavior:

I believe version 4.3.0 broke the error output with customer reporters. I think it might be coming from one of these snippets (L140 for the 1st, L111 for the 2nd):

cypress/packages/driver/src/cypress/error_utils.js

Lines 139 to 143 in 36866da

	const cypressErr = (err) => {
	const newErr = new Error(err.message)
	return mergeErrProps(newErr, err, { name: 'CypressError' })
	}

cypress/packages/server/lib/reporter.coffee

Lines 103 to 119 in 689bef0

	## mocha tries to extract the error name using a regular expression
	## but when the error message includes a colon (:) like
	## "Timed out retrying: expected...", it thinks the error name is
	## "Timed out retrying" and replaces the entire message with only that
	##
	## Here's the code we're patching in the mocha version currently being used (2.4.5):
	## https://github.com/mochajs/mocha/blob/2a8594424c73ffeca41ef1668446372160528b4a/lib/reporters/base.js#L208
	if test.err and test.err.message
	message = new String(test.err.message)
	originalMatch = message.match
	message.match = (re) ->
	if _.isEqual(re, mochaErrMsgExtractionRe)
	return null
	originalMatch.apply(@, arguments)
	test.err.message = message

On a simple test that visits a page that doesn’t exist (HTTP 404), the output looks like this now:

Text version:

~/Sites/test-cypress  $ npx cypress run  --reporter reporter.js

====================================================================================================

  (Run Starting)

  ┌────────────────────────────────────────────────────────────────────────────────────────────────┐
  │ Cypress:    4.3.0                                                                              │
  │ Browser:    Electron 80 (headless)                                                             │
  │ Specs:      1 found (examples/index.js)                                                        │
  └────────────────────────────────────────────────────────────────────────────────────────────────┘


────────────────────────────────────────────────────────────────────────────────────────────────────
                                                                                                    
  Running:  examples/index.js                                                               (1 of 1)
{
  message: [String: '`cy.visit()` failed trying to load:\n' +
    '\n' +
    'https://example.com/dgfkdgkj\n' +
    '\n' +
    'The response we received from your web server was:\n' +
    '\n' +
    '  > 404: Not Found\n' +
    '\n' +
    'This was considered a failure because the status code was not `2xx`.\n' +
    '\n' +
    'If you do not want status codes to cause failures pass the option: `failOnStatusCode: false`'] {
    match: [Function]
  },
  name: 'CypressError',
  stack: 'CypressError: `cy.visit()` failed trying to load:\n' +
    '\n' +
    'https://example.com/dgfkdgkj\n' +
    '\n' +
    'The response we received from your web server was:\n' +
    '\n' +
    '  > 404: Not Found\n' +
    '\n' +
    'This was considered a failure because the status code was not `2xx`.\n' +
    '\n' +
    'If you do not want status codes to cause failures pass the option: `failOnStatusCode: false`\n' +
    '    at cypressErr (https://example.com/__cypress/runner/cypress_runner.js:146180:16)\n' +
    '    at cypressErrByPath (https://example.com/__cypress/runner/cypress_runner.js:146189:10)\n' +
    '    at Object.throwErrByPath (https://example.com/__cypress/runner/cypress_runner.js:146152:11)\n' +
    '    at https://example.com/__cypress/runner/cypress_runner.js:134410:34\n' +
    '    at visitFailedByErr (https://example.com/__cypress/runner/cypress_runner.js:133923:12)\n' +
    '    at https://example.com/__cypress/runner/cypress_runner.js:134391:22\n' +
    '    at tryCatcher (https://example.com/__cypress/runner/cypress_runner.js:9059:23)\n' +
    '    at Promise._settlePromiseFromHandler (https://example.com/__cypress/runner/cypress_runner.js:6994:31)\n' +
    '    at Promise._settlePromise (https://example.com/__cypress/runner/cypress_runner.js:7051:18)\n' +
    '    at Promise._settlePromise0 (https://example.com/__cypress/runner/cypress_runner.js:7096:10)\n' +
    '    at Promise._settlePromises (https://example.com/__cypress/runner/cypress_runner.js:7172:18)\n' +
    '    at _drainQueueStep (https://example.com/__cypress/runner/cypress_runner.js:3766:12)\n' +
    '    at _drainQueue (https://example.com/__cypress/runner/cypress_runner.js:3759:9)\n' +
    '    at Async.../../node_modules/bluebird/js/release/async.js.Async._drainQueues (https://example.com/__cypress/runner/cypress_runner.js:3775:5)\n' +
    '    at Async.drainQueues (https://example.com/__cypress/runner/cypress_runner.js:3645:14)'
}

  (Results)

  ┌────────────────────────────────────────────────────────────────────────────────────────────────┐
  │ Tests:        1                                                                                │
  │ Passing:      0                                                                                │
  │ Failing:      1                                                                                │
  │ Pending:      0                                                                                │
  │ Skipped:      0                                                                                │
  │ Screenshots:  1                                                                                │
  │ Video:        true                                                                             │
  │ Duration:     1 second                                                                         │
  │ Spec Ran:     examples/index.js                                                                │
  └────────────────────────────────────────────────────────────────────────────────────────────────┘

====================================================================================================

  (Run Finished)


       Spec                                              Tests  Passing  Failing  Pending  Skipped  
  ┌────────────────────────────────────────────────────────────────────────────────────────────────┐
  │ ✖  examples/index.js                        00:01        1        -        1        -        - │
  └────────────────────────────────────────────────────────────────────────────────────────────────┘
    ✖  1 of 1 failed (100%)                     00:01        1        -        1        -        -  

Note the weird:

{
  message: [String: '`cy.visit()` failed trying to load:\n' +
    '\n' +
    'https://example.com/dgfkdgkj\n' +
    '\n' +
    'The response we received from your web server was:\n' +
    '\n' +
    '  > 404: Not Found\n' +
    '\n' +
    'This was considered a failure because the status code was not `2xx`.\n' +
    '\n' +
    'If you do not want status codes to cause failures pass the option: `failOnStatusCode: false`'] {
    match: [Function]
  },

Desired behavior:

The main problem with this is that it doesn’t seem to be possible to get the original error message anymore. So a custom reporter is now stuck with Cypress’ hack without the ability to use the actual error message that was thrown.

My assumption is that this patching/String serialisation (L111) is happening too early. The given input is not a string, it seems to be JavaScript intended to compose a string through concatenation. Not sure. Doing a typeof on error.message also yields object instead of string which is a problem as well.

Test code to reproduce

Consider the following setup:

{ "baseUrl": "https://example.com" }

describe("Test", () => {
  it("visit", () => cy.visit("/dgfkdgkj"))
})

function Reporter(runner) {
  runner.on("fail", (test, error) => {
    console.log(error);
  });
}

module.exports = Reporter;

npx cypress run  --reporter reporter.js

Versions

4.3.0.

[jennifer-shehane]

I'm getting an error throwing reporter is not defined when running the example given.

We did make changes to the construction of error messages in 4.3.0 in #3762

[KittyGiraudel]

@jennifer-shehane My apologies for the mistake in the code. Here it is:

function Reporter(runner) {
  runner.on("fail", (test, error) => {
    console.log(error);
  });
}

module.exports = Reporter;

We did make changes to the construction of error messages in 4.3.0 in #3762

I understand that. I think you’ll find a regression between 4.2.0 and 4.3.0 though. :)

[jennifer-shehane]

This code is identical to the code pasted before. Is this supposed to be placed in the plugins/index.js file?

[KittyGiraudel]

@jennifer-shehane Yes, I update my initial post with the fix so you can try again. It was missing the runner argument from the constructor. The code snippet should be placed in reporter.js. That’s the customer reporter.

Allow me to give you all code snippets with their location again:

// cypress.json
{ "baseUrl": "https://example.com" }

// cypress/integration/examples/index.js
describe("Test", () => {
  it("visit", () => cy.visit("/dgfkdgkj"))
})

// reporter.js
function Reporter(runner) {
  runner.on("fail", (test, error) => {
    console.log(error);
  });
}

module.exports = Reporter;

[chrisbreiding]

I'll look into this as part of #3930.

[chrisbreiding]

I ran this with 4.2.0 and got essentially the same output:

{
  message: 'cy.visit() failed trying to load:\n' +
    '\n' +
    'https://example.com/dgfkdgkj\n' +
    '\n' +
    'The response we received from your web server was:\n' +
    '\n' +
    '  > 404: Not Found\n' +
    '\n' +
    "This was considered a failure because the status code was not '2xx'.\n" +
    '\n' +
    "If you do not want status codes to cause failures pass the option: 'failOnStatusCode: false'",
  name: 'CypressError',
  stack: 'CypressError: cy.visit() failed trying to load:\n' +
    '\n' +
    'https://example.com/dgfkdgkj\n' +
    '\n' +
    'The response we received from your web server was:\n' +
    '\n' +
    '  > 404: Not Found\n' +
    '\n' +
    "This was considered a failure because the status code was not '2xx'.\n" +
    '\n' +
    "If you do not want status codes to cause failures pass the option: 'failOnStatusCode: false'\n" +
    '    at cypressErr (http://localhost:63723/__cypress/runner/cypress_runner.js:138644:9)\n' +
    '    at throwErr (http://localhost:63723/__cypress/runner/cypress_runner.js:138577:11)\n' +
    '    at Object.throwErrByPath (http://localhost:63723/__cypress/runner/cypress_runner.js:138625:3)\n' +
    '    at http://localhost:63723/__cypress/runner/cypress_runner.js:127513:34\n' +
    '    at visitFailedByErr (http://localhost:63723/__cypress/runner/cypress_runner.js:127026:12)\n' +
    '    at http://localhost:63723/__cypress/runner/cypress_runner.js:127494:22\n' +
    '    at tryCatcher (http://localhost:63723/__ciypress/runner/cypress_runner.js:165465:23)\n' +
    '    at Promise._settlePromiseFromHandler (http://localhost:63723/__cypress/runner/cypress_runner.js:163401:31)\n' +
    '    at Promise._settlePromise (http://localhost:63723/__cypress/runner/cypress_runner.js:163458:18)\n' +
    '    at Promise._settlePromise0 (http://localhost:63723/__cypress/runner/cypress_runner.js:163503:10)\n' +
    '    at Promise._settlePromises (http://localhost:63723/__cypress/runner/cypress_runner.js:163578:18)\n' +
    '    at Async../node_modules/bluebird/js/release/async.js.Async._drainQueue (http://localhost:63723/__cypress/runner/cypress_runner.js:160190:16)\n' +
    '    at Async../node_modules/bluebird/js/release/async.js.Async._drainQueues (http://localhost:63723/__cypress/runner/cypress_runner.js:160200:10)\n' +
    '    at Async.drainQueues (http://localhost:63723/__cypress/runner/cypress_runner.js:160074:14)'
}

The only difference is the message doesn't include [String: , but that's negligible in my opinion. It's necessary for us to fix a larger issue with the way Mocha handles error messages.

The main problem with this is that it doesn’t seem to be possible to get the original error message anymore

In this example, at least, the original error message is only 404: Not Found. We're not truncating it, it's just that's all there is to it. We wrap the error message with some additional context, but that's what we've always done. It hasn't changed since 4.2.0.

That all said, it's clear this is a pared-down example for reproduction's sake, which I appreciate, but I'm not sure it demonstrates an actual issue. @hugogiraudel, if you could provide an example of an actual custom reporter that's behavior has been broken between 4.2.0 and 4.3.0, I'd be happy to look into it.

[KittyGiraudel]

Hello Chris and thank you for having a look. I’ll check next week again. :)

[KittyGiraudel]

The only difference is the message doesn't include [String: , but that's negligible in my opinion. It's necessary for us to fix a larger issue with the way Mocha handles error messages.

Hello Chris. I’m finally coming back to this. My understanding is that it makes a big difference, because what you receive in 4.2.0 is an object — correct me if I’m wrong. That means you can read its keys, its values, and so on. In 4.3.0 however, the received error is a string. Which means it’s not possible to access only error.message, or error.name or error.stack, making it not so useful anymore.

[chrisbreiding]

You still receive an object with message, name, and stack in either version. That can be seen in your original screenshot of the stdout. It prints an object with those properties.

The difference is that error.message is a String instance instead of a primitive string. But it behaves the same as a string. It has a length property and if you print it by itself, it will look the same.

Which reporter did you use that prompted this issue? Being able to reproduce the issue will enable me to debug it.

[KittyGiraudel]

Interesting, thank you for coming back to me so quick and explaining. I can reproduce the issue with the code samples I gave in my original comment. I’m a little puzzled why I see such differences between the 2 versions.

[chrisbreiding]

Okay, I was able to reproduce this in a way that highlights the issue. Printing only the message shows a starker difference between 4.2.0 and 4.3.0.

// reporter.js
function Reporter(runner) {
  runner.on("fail", (test, error) => {
    console.log(error.message);
  });
}

module.exports = Reporter;

In 4.2.0:

cy.visit() failed trying to load:

/dgfkdgkj

We failed looking for this file at the path:

/Users/chrisbreiding/Dev/cypress/_playground/dgfkdgkj

The internal Cypress web server responded with:

  > 404: Not Found

In 4.3.0:

[String: '`cy.visit()` failed trying to load:\n' +
  '\n' +
  '/dgfkdgkj\n' +
  '\n' +
  'We failed looking for this file at the path:\n' +
  '\n' +
  '/Users/chrisbreiding/Dev/cypress/_playground/dgfkdgkj\n' +
  '\n' +
  'The internal Cypress web server responded with:\n' +
  '\n' +
  '  > 404: Not Found'] {
  match: [Function]
}

I'll look into how we can address this.

[KittyGiraudel]

Ah right, thank you for pinpointing the problem! So maybe, it’s related to the code snippets I outlined in my original post. That would lovely to have this addressed as logs are pretty polluted right now unfortunately.

[cypress-bot]

The code for this is done in cypress-io/cypress#3930, but has yet to be released.
We'll update this issue and reference the changelog when it's released.

[cypress-bot]

Released in 4.6.0.

This comment thread has been locked. If you are still experiencing this issue after upgrading to
Cypress v4.6.0, please open a new issue.