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

[kentcdodds]

🚀 Feature Proposal

99% of the time, if console.error and console.warn are called during tests (and they're not mocked), it's something that needs to be fixed.

Motivation

In particular, with React's new act warning, people are seeing output like this:

 console.error node_modules/react-dom/cjs/react-dom.development.js:545
    Warning: An update to User inside a test was not wrapped in act(...).
    
    When testing, code that causes React state updates should be wrapped into act(...):
    
    act(() => {
      /* fire events that update state */
    });
    /* assert on the output */
    
    This ensures that you're testing the behavior the user would see in the browser. Learn more at https://fb.me/react-wrap-tests-with-act
        in User

It's not entirely helpful. It does show that this is happening in the User component, but there could be any number of places within that component that could have triggered that error to be logged.

Example

Here's a proof of concept of what I'm suggesting (definitely wouldn't work like this if built-in):

const originalError = console.error
beforeAll(() => {
  console.error = (...args) => {
    console.log(new Error().stack)
    originalError(...args)
  }
})

afterAll(() => {
  console.error = originalError
})

This would look like:

console.log src/__tests__/tmp.js:31
    Error: 
        at CustomConsole.console.error (/Users/kentcdodds/code/react-testing-library/src/__tests__/tmp.js:31:17)
        at warningWithoutStack (/Users/kentcdodds/code/react-testing-library/node_modules/react-dom/cjs/react-dom.development.js:545:32)
        at warnIfNotCurrentlyActingUpdatesInDEV (/Users/kentcdodds/code/react-testing-library/node_modules/react-dom/cjs/react-dom.development.js:23281:7)
        at dispatchAction (/Users/kentcdodds/code/react-testing-library/node_modules/react-dom/cjs/react-dom.development.js:15813:9)
        at setUser (/Users/kentcdodds/code/react-testing-library/src/__tests__/tmp.js:8:5)
        at processTicksAndRejections (internal/process/task_queues.js:89:5)

  console.error src/__tests__/tmp.js:32
    Warning: An update to User inside a test was not wrapped in act(...).
    
    When testing, code that causes React state updates should be wrapped into act(...):
    
    act(() => {
      /* fire events that update state */
    });
    /* assert on the output */
    
    This ensures that you're testing the behavior the user would see in the browser. Learn more at https://fb.me/react-wrap-tests-with-act
        in User

And visually:

And it could be potentially improved within Jest so it's even more helpful (with color coding to highlight the part of the code that triggered the error). Similar to when an error is thrown.

    some error in React

       6 |   async function fetchUserData(id) {
       7 |     const response = await fetch(`/${id}`)
    >  8 |     setUser(await response.json())
         |     ^
       9 |   }
      10 |   React.useEffect(() => {
      11 |     fetchUserData(props.id)

      at dispatchAction (node_modules/react-dom/cjs/react-dom.development.js:15809:11)
      at setUser (src/__tests__/tmp.js:8:5)

And visually:

To be clear, what I mean is that console.error could print out a stack trace and codeframe where the part of the stack trace which is not in user code could be dimmed to reduce confusion and the codeframe would show the part of the user's code which ultimately triggered the error to be logged.

Pitch

I think this would help more than just act and it seems like the correct place for this to happen. It would help people get rid of error (and potentially warn) logs quicker, and move on to building their apps faster (which I believe is the goal of Jest).

Reference: testing-library/react-testing-library#434

I'd love to hear what you all think!

[danielkcz]

@kentcdodds Thanks for filling the issue.

I wonder how did you manage to have such a nice stack trace (without any sort of filtering) that shows correct test file right away. When we initially fiddled with it, there was a fairly long stack to be useful and we had very similar console hijack there. Does beforeAll make such a difference?

Error.stackTraceLimit = Infinity
const origError = console.error
console.error = function(msg) {
    if (/react-wrap-tests-with-act/.test("" + msg)) throw new Error("missing act")
    return origError.apply(this, arguments)
}

https://github.com/mobxjs/mobx-react/blob/c27fc785051c378aa23fe4f205ddac06285f1b62/jest.setup.js#L6

[kentcdodds]

Does beforeAll make such a difference?

No, that's just what I was doing in my example. If it were to be built into jest, then it would be done completely different.

The length of the stack trace will certainly differ based on the scenario. It'll be as long as it is 🤷‍♂️ My example was a pretty simple component. I'm not surprised that you have a long stack trace with an abstraction like mobx. This is why the dimming of lines that include the text node_modules and making the codeframe around the last line before node_modules appears in the stack trace is key.

[SimenB]

In the general case, I think this sounds like a good idea. Might be noisy, but maybe not 🙂 We already collect a stack, although we only keep a single frame. Expanding that to keep all frames and construct a visual code frame should be straight forward (happens here: https://github.com/facebook/jest/blob/0d4834427f66091f403964c9be86a71d50a9f965/packages/jest-console/src/BufferedConsole.ts#L51). Semi related: #8790

Will it still work for async (concurrent?) React? Unless the logging happens synchronously I think we'll lose the real stack. Maybe one could configure act to throw instead of log? That should give the correct trace and just work ™ with code frame etc. without any change in Jest (and it should work for other test runners as well that don't intercept console).

/cc @threepointone

EDIT: I see this was discussed in the React repo already. I still think having act throw instead of log would help, but maybe not?

EDIT2: It's the reporter's responsibility to actually print the log to the console, so if we stick a longer trace in the console entry given to the reporter, this (a code frame) could be implemented in user land as a custom reporter.

https://github.com/facebook/jest/blob/0d4834427f66091f403964c9be86a71d50a9f965/packages/jest-reporters/src/default_reporter.ts#L175-L186

[danielkcz]

@SimenB

entry given to the reporter, this (a code frame) could be implemented in user land as a custom reporter.

I already do have a "hacky" solution in user-land. I could make it into a separate package, but that kinda beats the point that user seeing that warning wants it to be helpful right away and not to look for some module or tool to improve error message.

Since React doesn't want this, RTL doesn't want it either, then I guess Jest is only place left so I have my hopes here :)

[SimenB]

Getting a stack trace when logging works ok-ish for synchronous updates, but not at all for async updates. I tested with an apollo component at work now, and not a single line of user code is available in the stack. The code that updates the component is triggered by an observable (https://github.com/apollographql/react-apollo/blob/3e0a436561de1b37358166d4e9a4e14af5a94693/packages/hooks/src/data/QueryData.ts#L283) and the stack trace in its entirety is in node_modules (in this case, going back and forth between apollo-client, zen-observable and @apollo/react-hooks before landing in react-dom). I'm not sure if we can do anything in this case? A half solution only working for sync updates seems somehow worse, and more confusing, than the current status quo

[threepointone]

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

[SimenB]

Yeah, something like that works for sync logging, but the trace is not necessarily useful for asynchronous logging. Might still be worth building something like that into Jest, of course

[danielkcz]

@threepointone That's somewhat sad that you have to "hack" React instead of supplying proper solution into React :/

[kentcdodds]

Getting a stack trace when logging works ok-ish for synchronous updates, but not at all for async updates.

Don't we have the exact same problem for async errors though? And we seem pretty happy with that anyway 🤷‍♂️

[SimenB]

That's a fair point. I'm down with adding support for code frames in log messages, but I think it should be behind a config flag, and for all console usage, from error to trace and log. I think it'd be pretty inconsistent to only do it for error or warn.

/cc @thymikee @jeysal @scotthovestadt thoughts and that (and the issue in general)?

[danielkcz]

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 🤷‍♂

[SimenB]

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.

Right, which is why I think it should be opt-in, but I think per-level config is overkill. You can use a custom reporter of that's what you want, as the reporter would still control what to output and what not to.

Whether or not CRA allows you to configure that is orthogonal IMO - if it's useful they'll add support for it

Unless of course some sort of filtering would be applied.

We'd probably use the same filtering we do with errors now, which removes all of jest's internal stuff and tries to find the topmost line in user code for the frame itself

[kentcdodds]

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.

[jeysal]

/cc @thymikee @jeysal @scotthovestadt thoughts and that (and the issue in general)?

I think this is a good idea. I'm wondering how common it really is to permanently have console output written during a test run. Pretty much every project I've seen so far makes sure tests do not log because even without stack traces they mess up the output in an annoying way. Exceptions being some small projects with just a few test files, and of course temporary log statements inserted while debugging that won't be committed. If this perception is correct I don't even see the need to make it opt-in. Side note: The opt-out could be a generalization of --noStackTrace for certain types of stack traces (throw/console).

[kentcdodds]

Agreed. Typically console.log statements don't appear in user code or node_modules code long-term. It's more of a workflow thing. However node_modules code and even user code will have console.warn and console.error to let the user know of exceptional behavior/scenarios which need debugging.

[kentcdodds]

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

[cisum-la]

I had entered #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 jest-community/jest-junit#45 so another reason for not breaking this feature. So essentially current jest behavior as described in 2 a) is preserved.

[gaearon]

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.

[ParthS007]

Hello @gaearon , I am interested to work on this issue. Can you please help me getting started. Thanks :)

[motiz88]

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.

[ychi]

Hi @ParthS007 are you working on this issue? If not, I have some clues and would like to try to solve it.

[ParthS007]

Hey @ychi , I am currently reading all the comments and just understanding whats needed to be done here.

[gaearon]

@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.

[ParthS007]

okay @gaearon , Sounds good to me. @ychi If you want to work on this, you can go ahead 👍

[ychi]

Thanks @ParthS007 & @gaearon. I will take it.

Hi @SimenB
My thought is storing the call stack as a single string in LogEntry.origin (without Jest-internal frame); in getConsoleOutput just split it with \n and use chalk to colour it. Does it make sense to you?

Two questions would be:

1. I think it makes more sense to print type message first, then message itself in a separate line, then the call stack.

   Here is an error message!
     at functionA (fileA.js)
     at anotherFunction (anotherFile.js) 

It makes reading easier, and react prints message before stack in setupTests, too. However this will make console.log a special case (print type message, origin and then the message). Is there any concern?

2. the package callsites does not use Error.captureStackTrace() internally, what do you think if we get rid of the dependency and call Error.captureStackTrace() directly?

[SimenB]

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

[ychi]

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.

[gaearon]

Seems reasonable.

[SimenB]

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

[ychi]

Hi @SimenB,

I have another question: in jest-runner I see a lot of effort goes to source map support, including sending SourceMapRegistry to BufferedConsole; however, in expect package where stack traces are read and processed quite a bit, there is no source map related path lookup or substitution.

stack-utils does support wrapCallSite to allow source mapping, it's however not used in formatStackTrace(). Is there a reason behind? Or did I missed something? Thanks in advance!

[ychi]

In order to capture the stack trace in a 'source-mapped' flavour, I think it might make sense to extend (or duplicate, to avoid breaking change) the following function so that it return Array.<callsites.CallSite>, and BufferedConsole.write() can parse those file paths and put them together as stack trace string.
https://github.com/facebook/jest/blob/c1bea10ee62344c86eac58d5ab82924d2d4e544d/packages/jest-source-map/src/getCallsite.ts#L52

Or maybe even add a function that dedicated to this task.

getCallsitesArray(
  level: number, 
  sourceMap ?: SourceMapRegistry | null): Array.<callsites.CallSite>

Would that bring any concerns?

[SimenB]

I've removed the dependency on @jest/test-result from jest-message-util in #9749, so the dependency cycle should be broken. Moving formatResultsErrors to @jest/test-result makes sense to me, bit it depends on a few functions not exported from jest-message-util, so I think we should wait with it. This issue should be unblocked at least

[SimenB]

Released in 25.4.0, please try it out 🙂

[rbordeanu]

Is there a corresponding noStackTrace option in the configuration?

[SimenB]

Next release will respect noStackTrace

[Smolations]

@SimenB I am looking at the Jest 26 docs and am not seeing a config option for noStackTrace. Right now I have console.warn statements getting stack traces in the results. Is the option there but not documented or should I resort to mocking the console?

[rbordeanu]

Next release will respect noStackTrace

@SimenB any updates about this? The current release still doesn't have it in the config, and we'd like to disable it as it is much too noisy for our tests.

[ychi]

@SimenB: I think it's because the global config not passed down to getConsoleOutput. I will create a PR to address this.

[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.