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

Jest eats up all console.log messages during debugging #8208

Closed
WillAvudim opened this issue Mar 25, 2019 · 47 comments · Fixed by #11054
Closed

Jest eats up all console.log messages during debugging #8208

WillAvudim opened this issue Mar 25, 2019 · 47 comments · Fixed by #11054

Comments

@WillAvudim
Copy link

🚀 Feature Proposal

Currently Jest eats up all console.log/warn/error messages during debugging and I'm completely blind all the way through up until the test finishes.
I'd like to be able to enable Jest to spit out console.log messages immediately during debugging sessions.

Motivation

Being able to immediately see all console.log/warn/error messages while debugging unit tests in the debugger would enable all of us to observe the app behavior interactively.

@BrendanBall
Copy link

Jest was doing this the other day for me and then it randomly stopped immediately printing logs. I know this because I'm trying out using jest for some simple data tests that do 500+ http calls. The first few tests I wrote it was printing the logs as it went. Now it waits until the test is complete. As far as I know I didn't change any config in between so I really don't understand why it changed.

@noppa
Copy link

noppa commented Mar 27, 2019

Furthermore, Jest doesn't seem to output messages at all if the test fails, which makes debugging broken tests quite painful.

it('should do stuff', () => {
    console.log('Hello World')
    expect(1).toBe(2)
})
    expect(received).toBe(expected) // Object.is equality

    Expected: 2
    Received: 1

      33 |   it('should do stuff', () => {
      34 |     console.log('Hello World')
    > 35 |     expect(1).toBe(2)
         |               ^
      36 |   })

There's no "Hello World" to be seen anywhere ☹️

@orta
Copy link
Member

orta commented Apr 6, 2019

Just to clarify - is this when in watch mode? And which versions of Jest are you using?

@noppa
Copy link

noppa commented Apr 6, 2019

I just tried it again in a fresh project with version 24.7.1 and the "Hello World" example does output the message to console. Huh, I guess I must've used an older version or misconfigured something when I tried this before. Anyways, it's working fine for me now.

Edit: can't remember whether I was using watch mode or not when I made my previous comment.

@igorpavlov-zz
Copy link

igorpavlov-zz commented May 27, 2019

➕1️⃣ This is really crucial for TDD to be able to console.log when test fails. At the moment I have to comment all failing tests out to see the logs and this is pretty inconvenient.

Using Jest 24.8.0.

Jest config:

module.exports = {
  transform: {
    '^.+\\.ts$': 'ts-jest',
  },
  testRegex: '.+\\.ts',
  moduleFileExtensions: ['ts', 'js'],
  rootDir: 'tests',
  testEnvironment: "node",
}

Command that is run:

npx jest --runTestsByPath ${pathToTestFile} --colors --verbose=false

@davidsu
Copy link

davidsu commented Feb 17, 2020

+1

@yachaka
Copy link

yachaka commented Mar 5, 2020

As a temporary workaround, you can set DEBUG env variable to jest:

DEBUG=jest yarn test

@rogeliog
Copy link
Contributor

rogeliog commented Mar 9, 2020

Are you seeing the same issue if you run with --runInBand?

@marklombardi
Copy link

console.log was not working with v23.0.2. console.log messages are working again with v25.4.0 (current latest). The console.log messages were ONLY appearing when attached to a debugger in v23.0.2

@thesmart
Copy link

Rather than a feature request, I would call this a serious bug. In the best case, I would consider this a huge overreach by a library to swallow console output. What is the workaround for situations where process exits 1 and needs to print an error? Swallowing it makes issues very expensive to fix in continuous testing suites.

None of the proposals work for me. Running DEBUG=jest jest --forceExit --detectOpenHandles --silent false --verbose false --runInBand via npm run

@dborisenkowork
Copy link

Is it so hard to fix console.log issues? It's pretty frustrating to waste time because for some reasons jest won't display necessary logs and there is no workarounds about it at all.

@piecyk
Copy link

piecyk commented Oct 23, 2020

Looks like when you run jest via node --inspect node_modules/.bin/jest --runInBand <path_to_test> it logs console.logs to console without connecting to dev tools. More about node --inspect at https://artsy.github.io/blog/2018/08/24/How-to-debug-jest-tests/

@jalovatt
Copy link

I'm debugging some code that takes a while to run (if it finishes at all 😢) so, like the users above, being able to specify that I want my logs to be printed "live" is pretty important.

None of the workarounds listed above are working for me, but I've found one that does: process.stdout.write is swallowed alongside console.log, but process.stderr.write makes it out to the console immediately.

The downside is that you lose console.log's formatting for multiple arguments, and the automatic line break, but it's better than nothing.

@lindsaylevine
Copy link

+1 to everything here

@conartist6
Copy link
Contributor

I would expect that console output be held for purposes of parallelization, but when runInBand is passed I can't think of any reason why console output should be buffered.

@Tzxhy
Copy link

Tzxhy commented Jan 27, 2021

+1. Now is 2021, still open?

@nickitza
Copy link

nickitza commented Feb 3, 2021

+1

1 similar comment
@jamieowen
Copy link

+1

@conartist6
Copy link
Contributor

I'm going to dig into the code and see if I can figure out why it does it.

@conartist6
Copy link
Contributor

conartist6 commented Feb 4, 2021

I thought for sure the problem would be use of the BufferedConsole class from @jest/console.
That class buffers output into a javascript array. That output becomes part of the test result as the confusingly named result.console, where it remains until the default reporter prints it in the test file header.

BUT. That logic is short-circuited when the verbose flag is passed. I put a debugger in to be sure I wasn't getting the BufferedConsole after passing the verbose flag, and indeed I am not. A change will still be needed here though: in addition to --verbose, --runInBand should also choose the non-buffered output.

So time to turn the attention elsewhere. Fortunately I think in the course of the above investigation I found the next thing to investigate, which is stdio wrapping in the default reporter. Note that that code is actually monkey patching process.stdio.write! It writes after a debounce period. I feel reasonably confident that if this logic can also be bypassed this bug can be considered resolved. There is already a separate verbose reporter which inherits from the default reporter. It inherits the default reporter's stdio wrapping, but I'm inclined to think given the evidence of attempts to have verbose mode punch through buffering logic, this is the real root cause. I presume someone added the buffering to the default reporter without considering that the verbose reporter would also gain the behavior, breaking an untested use case.

Let me write up a PR and see if anyone takes note.

@conartist6
Copy link
Contributor

conartist6 commented Feb 4, 2021

Also it isn't necessary to read any config flag other than verbose because verbose gets set to true whenever there is only one test file, which should always be the case for debugging.

conartist6 added a commit to conartist6/jest that referenced this issue Feb 4, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Feb 4, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Feb 4, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Feb 4, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Feb 4, 2021
@cc-ebay
Copy link

cc-ebay commented May 17, 2021

@conartist6 Why #11054 is not being merged?

conartist6 added a commit to conartist6/jest that referenced this issue May 26, 2021
conartist6 added a commit to conartist6/jest that referenced this issue May 30, 2021
conartist6 added a commit to conartist6/jest that referenced this issue May 30, 2021
conartist6 added a commit to conartist6/jest that referenced this issue May 30, 2021
@conartist6
Copy link
Contributor

@cc-ebay hopefully there is now no longer any reason.

@MetaMmodern
Copy link

I have the same bug but not during debugging, but during simple run. Using jest ^24.9.0. This bug makes my library built over jest not work and not output logs if the expect doesn't pass. Fix that please!

@conartist6
Copy link
Contributor

@MetaMmodern are you able to test to find out if the fix in #11054 solves the issue you have?

@MetaMmodern
Copy link

@MetaMmodern are you able to test to find out if the fix in #11054 solves the issue you have?

Sorry, I'm hot sure how to install a pull request version of a package((
If you could explain me or give some sources where I can read how to do it--I would try it.

@MetaMmodern
Copy link

I managed this to work with --useStderr flag, but that made me change the logic a little in my library.
Also, now all the CI tools might not see actual error output from my library, which may lead to wrong logic in CI/CD. That's why maybe we'll still need @conartist6 s pull request to be merged(if it works there, I still don't know).

@conartist6
Copy link
Contributor

Maybe there's a better way, but you can just patch the code in node_modules. Download this patch and run git apply 11054.node_modules.patch from the root of your project.

@MetaMmodern
Copy link

Maybe there's a better way, but you can just patch the code in node_modules. Download this patch and run git apply 11054.node_modules.patch from the root of your project.

Okay, I'll try tomorrow.

@MetaMmodern
Copy link

MetaMmodern commented Jul 28, 2021

Maybe there's a better way, but you can just patch the code in node_modules. Download this patch and run git apply 11054.node_modules.patch from the root of your project.

It says corrupt patch at line 22. I removed that empty end line and it says corrupt patch at line 21.

But hey, the file is readible. I'll just go edit the file myself and check what happens))

@MetaMmodern
Copy link

@conartist6 Hi, I've managed to apply your changes from pull request manually and it seems like console logs are disabled completely after those actions, the only thing is shown for me is that Command failed.

@conartist6
Copy link
Contributor

Oh that's my bad. I did some hand editing to get the essential part of the fix to apply without any of the other changes, and I missed something: I forgot to change __clearStatus() back to _clearStatus() (same with __printStatus). I've updated the patch, or you can just make that change yourself.

@MetaMmodern
Copy link

Oh that's my bad. I did some hand editing to get the essential part of the fix to apply without any of the other changes, and I missed something: I forgot to change __clearStatus() back to _clearStatus() (same with __printStatus). I've updated the patch, or you can just make that change yourself.

Hi there, I've got some results.

The default reporter works well when the verbose flag is disabled, it shows console logs with you patch.
but there are some troubles in verbose reporter.
See, when I set verbose to true and put that _wrapStdio() function inside verbose reporter then failing test just does not output anything. Screenshot below(orange crossed part is output of my library, red part is where the jest result should be).
image

But if I comment out your code the behaviour stays as it was before the patch.
image
image

So as you can see there is an issue in verbose reporters method. If you fix it I think you may merge it in your PR.
Please let me know if I shoud duplicate this in the PR.

In a nutshell: You fixed default reporters console logs🎉, but verbose reporter has completely broken🙂.

@conartist6
Copy link
Contributor

If it is your belief that that my PR should not be merged, then you must show some kind of repro of what is wrong.

At the moment all I can say is that I suspect you made a mistake in your debugging. A couple things you say strike me as odd. First, you say my change fixed the default reporter. My change does not touch the default reporter at all. Second you say that my change is causing all output to disappear from the verbose reporter, but those seem like the exact same symptoms you were seeing before you changed __ to _. In the commented out code (you say you commented my fix out to get things working again), the _ fix is absent, so I'm assuming that means it was not present for the screenshot in which jest is completely broken.

Just to avoid any confusion at all, that method should read:

  _wrapStdio(stream) {
    const write = stream.write.bind(stream);

    stream.write = (chunk) => {
      this._clearStatus();
      write(chunk);
      this._printStatus();
      return true;
    };
  }

@conartist6
Copy link
Contributor

Also note that you may be using the verbose reporter even without -–verbose=true. The verbose reporter triggers automatically when only one test file is found.

@MetaMmodern
Copy link

If it is your belief that that my PR should not be merged, then you must show some kind of repro of what is wrong.

At the moment all I can say is that I suspect you made a mistake in your debugging. A couple things you say strike me as odd. First, you say my change fixed the default reporter. My change does not touch the default reporter at all. Second you say that my change is causing all output to disappear from the verbose reporter, but those seem like the exact same symptoms you were seeing before you changed __ to _. In the commented out code (you say you commented my fix out to get things working again), the _ fix is absent, so I'm assuming that means it was not present for the screenshot in which jest is completely broken.

Just to avoid any confusion at all, that method should read:

  _wrapStdio(stream) {
    const write = stream.write.bind(stream);

    stream.write = (chunk) => {
      this._clearStatus();
      write(chunk);
      this._printStatus();
      return true;
    };
  }

I've analyzed your PR and the only difference is:

  • in default reporter you've changed the stream.write to binding and called the write method without call
  • you added wrapStdio into verbose reporter
    I did not include __ and _ difference because as far as i know naming do not influence anything in js, those are just names of variables/methods, so in my changes I've left everything as it was and made sure that names were left as they were. Tell me if I'm wrong.

Also you say that your change does not touch the default reporter at all. That is strange, cause in your PR #11054 I see those files changed...
And also, just to be sure we understand each other, I'm not running tests in debug mode, I run them from Node's child_process exec tool.

@conartist6
Copy link
Contributor

conartist6 commented Jul 29, 2021

Yes there are some changes in the PR that aren't needed for the minimal fix.

Those aren't just variable names, they're methods defined by the base class. You can't just call whatever name you want, you have to call the method that exists, which is _clearStatus not __clearStatus (unless you've changed it like I did in my PR).

@MetaMmodern
Copy link

Yes there are some changes in the PR that aren't needed for the minimal fix.

Those aren't just variable names, they're methods defined by the base class. You can't just call whatever name you want, you have to call the method that exists, which is _clearStatus not __clearStatus (unless you've changed it like I did in my PR).

That's what i say, I did not change them in the base class as you did, so I just left them as they are. Look, it is kinda hard for me to create an example of what's not working, so maybe we could contact somewhere else and have a quick call whereI'd show you the code and check what's wrong? If this is an option for you--let me know, I'll contact you on gmail.

@conartist6
Copy link
Contributor

Respond on gmail. My address is on my profile. I know you didn't change those names in the base class, but you're still calling them by the __ name as if you did (as far as I can see at least).

conartist6 added a commit to conartist6/jest that referenced this issue Aug 23, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Oct 6, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Oct 6, 2021
conartist6 added a commit to conartist6/jest that referenced this issue Oct 6, 2021
@SimenB
Copy link
Member

SimenB commented Oct 8, 2021

https://github.com/facebook/jest/releases/tag/v27.2.5


There are probably still cases that doesn't work. If so, please open up a new issue (with a reproduction) and link this issue rather than comment here.

@github-actions
Copy link

github-actions bot commented Nov 8, 2021

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 Nov 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.