jest: Make console.error (and warn?) log a stack trace and codeframe like thrown errors do

Doing this only for console.error and console.warn matches how browsers show expandable arrows with JS stack next to them. The implementation itself is just new Error().stack. Sure, it’s not asynchronous — but that’s a question to VM implementors. Eventually it would be (or maybe it already is in recent Nodes). This sounds like a simple enough proposal and likely doable in 30 minutes. Let me tweet this.

Released in 25.4.0, please try it out 🙂

The implementation itself is just new Error().stack

Since this is targeting Node, I would recommend Error.captureStackTrace with the constructorOpt parameter, which can be used to avoid adding unnecessary Jest-internal frames to the stack.

Simplified example:

console.error = function consoleErrorWithStack(message) {
  const error = {message};
  Error.captureStackTrace(error, consoleErrorWithStack);
  // error.stack will not include consoleErrorWithStack
  doRealLogging(error.stack);
}

(EDIT: Fixed the example.)

I believe Jest filters stack traces anyway before displaying them, but it’s probably better to avoid adding unnecessary info than rely on filtering to remove it.

Next release will respect noStackTrace

I agree it makes sense, but it’s also technically a breaking change. We could duplicate it over though, and only break it in v26

I think it would be a mistake to do it for all console methods 😬 like @FredyC said, console.log is a common workflow method people engage in and it could get very noisy very quickly. It’s unlikely that if there’s a console.log I don’t know what called it. The benefit of console.error/warn is that they typically exist in dependency code and are unexpected so require some debugging to determine the root cause.

This is how React does it https://github.com/facebook/react/blob/master/scripts/jest/setupTests.js#L69-L128 Works well for us

We have a util for formatting errors that attach a code frame already, I think it makes sense to reuse that:

One challenge I noticed is that jest-message-util depends on jest-test-result, and jest-test-result depends on jest-console. If jest-console tries to use jest-message-util, it creates a circular dependency.

jest-message-util depends on jest-test-result because of the following function: https://github.com/facebook/jest/blob/db055c2f413b1301d69c5a8924ba811bdd7c0e53/packages/jest-message-util/src/index.ts#L288

Since there are a number of test result formatters in jest-test-result, does it make sense to move formatResultError to jest-test-result? That way we can make both jest-test-result and jest-console depend on jest-message-util.

We have a util for formatting errors that attach a code frame already, I think it makes sense to reuse that: https://github.com/facebook/jest/blob/677b763ec0a8c592c7395901c8efa1491c138c61/packages/jest-message-util/src/index.ts#L248

1. I think it’s easier to decide with some screenshots comparing different approaches on how to present the log entry. I’d start with just getting the stack below the current output, then start working on how to improve it
2. We already have a helper for captureStackTrace which is used here and there throughout the code base: https://github.com/facebook/jest/blob/677b763ec0a8c592c7395901c8efa1491c138c61/packages/jest-util/src/ErrorWithStack.ts

@ParthS007 Just a heads up this might not be necessarily the most beginner-friendly issue. Please feel free to dig into it but I think we shouldn’t hold off progress on fixing this if someone else wants to work on it too.

I had entered https://github.com/facebook/jest/issues/8819 For the Winston logging issue, after going through above conversation i want to make sure that our workflow is not impacted:

1. We use Jest + Selenium WebDriver for UI Test Automation, We really like it because through jest workers we are able to run tests in parallel and significantly reduce test runtime. We also use async await in tests heavily.
2. One of the issues we get into with parallel runs is when test fails then to quickly figure out which jest worker ran it and the test data associated with it. To facilitate this we heavily rely on console logging through winston . We also like the fact that jest does console buffering when running multiple tests as this way the logs are automatically organized per test file vs getting interleaved. See examples of both: a) Logs organized per test file through jest (Jest current behavior): I believe this is because jest does ConsoleBuffering in this scenario when multiple tests are run. The logs show up only after each testfile completion (not near realtime), but they are organized as per test file and hence very helpful in debugging (e.g. in below logs jest parallel WorkerID 2 was used). Also, this encourages breaking up long running testfiles into smaller ones so we can get their logs sooner.

`PASS test/ui/admin/ahanges.parallel.test.js (25.328s) ● Console

console.log node_modules/winston/lib/winston/transports/console.js:79
  2019-08-19 13:19:28:752 WorkerID:2 info: Navigating to: https://automation-zzz.app
  
console.log node_modules/winston/lib/winston/transports/console.js:79
  2019-08-19 13:19:29:081 WorkerID:2 info: Session ID: 82230c17aa91d9f43e5ca97c527b
  
console.log node_modules/winston/lib/winston/transports/console.js:79
  2019-08-19 13:19:30:558 WorkerID:2 info: Login Page - Entered username: 
  
console.log node_modules/winston/lib/winston/transports/console.js:79
  2019-08-19 13:19:30:755 WorkerID:2 info: Login Page - Entered password`

b) Logs getting interleaved (Undesirable for us and it’s good that jest currently doesn’t do this): Logs show up in near realtime but they are interleaved (with jest workerID for mutliple tests running in parallel showing up) as shown below. (I am running an older version of jest and older winston to exhibit this behavior) `2019-08-09 15:30:54 WorkerID:5 info: Login Page - Entered password

2019-08-09 15:30:55 WorkerID:3 info: Updating app session via API

2019-08-09 15:30:54 WorkerID:1 info: Login Page - Entered username:

2019-08-09 15:30:55 WorkerID:3 info: Navigating to: https://engineering-zzz

2019-08-09 15:30:55 WorkerID:1 info: Login Page - Entered username:`

I see above there was conversation around console.logs not being used much - we actually use it quite a bit along with console.warn and console.error as well. I want to make sure that with the changes agreed to in this ticket it doesn’t break jest’s current behavior of consoleBuffering when multiple tests are run. Also, this feature is already used in jest-junit https://github.com/jest-community/jest-junit/issues/45 so another reason for not breaking this feature. So essentially current jest behavior as described in 2 a) is preserved.

Also, I agree that this should be automatic and opt out with --noStackTrace as @jeysal suggested.

I would argue it’s needed for all console types. From practice, the console.log is often used for debugging tests when I am lazy enough to start a debugger. I might have 5 or more log statements at the time and if each of them would spill out a full stack trace, it would pretty awful to find anything useful there.

Unless of course some sort of filtering would be applied. I think it makes total sense to start at first frame that is out of node_modules and take like 3-5 following ones. That’s usually enough to pinpoint the origin.

Or make it configurable for each log level, although people with CRA would be unable to change it anyway 🤷‍♂