jest: console.log does not emit output
Please try out Jest 24 if you’re having issues with missing console.log
output
Branching from Issue #2441
@cpojer I’m not seeing any console.log output with this setup (macOS):
$ node --version
v7.4.0
Files
package.json
:
{
"dependencies": {
"@types/jest": "19.2.4",
"jest": "20.0.4",
"ts-jest": "20.0.6",
"typescript": "2.3.4"
}
}
__tests__/jestconfig.json
:
{
"rootDir": "../",
"globals": {
"__TS_CONFIG__": {}
},
"moduleFileExtensions": [
"ts",
"tsx",
"js",
"jsx",
"json"
],
"transform": {
"\\.(ts|tsx)$": "<rootDir>/node_modules/ts-jest/preprocessor.js"
},
"testRegex": "__tests__/.*test_.*\\.(ts|tsx|js)$"
__tests__/test_foo.ts
:
import {} from 'jest';
console.log('CONSOLE before test');
test('fail', () => {
console.log('CONSOLE inside test');
expect(true).toEqual(false);
console.log('CONSOLE end of test');
})
__tests__/test_bar.js
:
console.log('BAR CONSOLE before test');
test('fail', () => {
console.log('BAR CONSOLE inside test');
expect(true).toEqual(false);
console.log('BAR CONSOLE end of test');
})
Output
$ jest -c __tests__/jestconfig.json
FAIL __tests__/test_foo.ts
● fail
expect(received).toEqual(expected)
Expected value to equal:
false
Received:
true
at Object.<anonymous> (__tests__/test_foo.ts:6:16)
at Promise.resolve.then.el (node_modules/p-map/index.js:42:16)
FAIL __tests__/test_bar.js
● fail
expect(received).toEqual(expected)
Expected value to equal:
false
Received:
true
at Object.<anonymous>.test (__tests__/test_bar.js:4:16)
at Promise.resolve.then.el (node_modules/p-map/index.js:42:16)
Test Suites: 2 failed, 2 total
Tests: 2 failed, 2 total
Snapshots: 0 total
Time: 1.379s
Ran all test suites.
Single JS test:
$ jest -c __tests__/jestconfig.json __tests__/test_bar.js
FAIL __tests__/test_bar.js
● fail
expect(received).toEqual(expected)
Expected value to equal:
false
Received:
true
at Object.<anonymous>.test (__tests__/test_bar.js:4:16)
at Promise.resolve.then.el (node_modules/p-map/index.js:42:16)
✕ fail (7ms)
Test Suites: 1 failed, 1 total
Tests: 1 failed, 1 total
Snapshots: 0 total
Time: 0.596s, estimated 1s
Ran all test suites matching "__tests__/test_bar.js".
Single TS test:
$ jest -c __tests__/jestconfig.json __tests__/test_foo.ts
FAIL __tests__/test_foo.ts
● fail
expect(received).toEqual(expected)
Expected value to equal:
false
Received:
true
at Object.<anonymous> (__tests__/test_foo.ts:6:16)
at Promise.resolve.then.el (node_modules/p-map/index.js:42:16)
✕ fail (116ms)
Test Suites: 1 failed, 1 total
Tests: 1 failed, 1 total
Snapshots: 0 total
Time: 1.27s
Ran all test suites matching "__tests__/test_foo.ts".
About this issue
- Original URL
- State: closed
- Created 7 years ago
- Reactions: 27
- Comments: 138 (32 by maintainers)
Commits related to this issue
- fix console.log output not show related issue: https://github.com/facebook/jest/issues/3853 — committed to noscripter/jest by noscripter 6 years ago
- test: preserve test console log https://github.com/facebook/jest/issues/3853#issuecomment-426895387 — committed to ant-design/ant-design by afc163 6 years ago
- Added workaround --verbose=false for Jest console log issue See https://github.com/facebook/jest/issues/3853. — committed to magjac/graphviz-visual-editor by magjac 6 years ago
- Added workaround --verbose=false for Jest console log issue See https://github.com/facebook/jest/issues/3853. — committed to magjac/graphviz-visual-editor by magjac 6 years ago
This is ridiculous - I am triggered by the amount of useless responses from @cpojer (in every issue and PR I go to) and trying to put everything on everyone else like somehow we aren’t smart enough.
Don’t use Jest - that’s my answer if you’re wondering. Find a new testing framework.
I am sure I’ll just be told to install a newer version of Node Lmao - what a joke 😂 😂 😂
Can confirm Node 7.4 eats console logs, but it works on Node 7.5.0, 7.10.0, 8.0.0 and 8.1.2. Please upgrade your Node version. Closing
Two years of no console logs made me a better developer. Thanks team Jest!
@thymikee So, I’ve upgraded my node version and I see no console logs on Node 8.2.1 Winx64 + Jest 20.0.4. I have to use a fallback for now
and I’m pretty sure it should be fixed in Jest, since previous versions didn’t have this issue.
I think the problem here is that Jest buffers messages but there is something that causes to bail out (or an infinite loop etc.). You’ll need to use
--verbose
to print the messages directly to the output stream.please fix, this really hurts productivity with jest
I guess I’m a little confused how this would be considered a Node bug and not at least have something to do with Jest itself. Using Node v7.4.0, with Jest v19.0.2 I see console logging from my tests. Simply updating Jest to v20.0.4 (without making any changes to any other configuration) causes console logging to no longer appear. Is there something that I’m missing?
I can’t believe this is still an issue. Why is the issue closed?
I mean, who would ever want to debug their failing tests, right?
@nf071590 cannot repro, works on repl.it with exactly the same Jest and Node versions: https://repl.it/KYLc/0
Please come up with a serious repro before ranting about project maintainers. Cheers!
It’s broken again?! Why does this keep breaking?
OMG this is a pain 😕 november 2018
Confirmed that
--verbose=false
fixes the issue.Currently it seems the only way I can get console logging to be reliable is to log the same thing 3-4 times in a row. Jest will only block a certain number of them. Still very annoying.
--verbose=false
does not work for me with version23.6.0
Update - I believe I’ve found a minimal patch that makes some progress, but it took me a while to understand the interaction between Jest reporters and the Status generator
Jest monkey-patches the process stderr and stdout streams’ write methods with its own writer. That writer writes down the output of jest-cli Status.js, which contains things such as the number of tests in progress, a progress bar, the elapsed time and so on.
Whenever there is a write instruction on that stream, that instruction is replaced with a “delete” instruction for the status (going up using ANSI control codes), the original write, and a “write the status again” instruction. Thus the illusion that the status is always at the bottom of the screen, whereas the text scrolls above it.
(Of course, its a bit smarter than that - the writes are buffered and the buffered data is only really written once every 100ms together with the status)
However, the parallel test runner (used in watch mode, which sets
runInBand
to false) runs other workers. Those workers are set up to “inherit” the stdio stream of the original process. Unfortunately, that doesn’t mean they inherit the patched version that updates the status! If those writes happen, they will beTo make sure the patched version receives those tty writes, its necessary to switch the child processes streams from “inherit” mode to “pipe” mode. This way the process outputs are available as streams in the child process instead of directly going to the main stdout/stderr. We also need to manually pipe the streams:
Manually piping the streams ensures that the monkey-patched write does get called by node.
I can reproduce this with node 8.9.0 and jest 21.2.1, macOS 10.12.6 (16G1036)
The same problem here.
FWIW, the --verbose=false workaround works for me. In my
package.json
:Some other observations:
The problem still persists with
--verbose
when combined with--forceExit
- I think the reason for that is thatconsole.log
outputs tostdout
while jest writes tostderr
and when--forceExit
there may still be content instdout
not be flushedI found the following solution (without the need for
--verbose
) to fix both console.log not showing and/or console.log being buffered and not displayed livecommand
jest .... --forceExit --setupTestFrameworkScriptFile ./src/tests/jestShim.js
contents of
jestShim.js
I think an option to instruct jest to not do magic on stdout and console would be very beneficial for everyone
This is a decent example of “too much magic” going on underneath the hood, and the consequences of that when something goes wrong. I’m not convinced grouping console.log output is worth a year and a half of missing console.log statements. 😕
Hello guys/girls, I also met the famous jest console log problem when running testing in --watch mode. The solution was to use --watchAll instead of --watch. The summary of tests became uglier, but the logs showed as expected.
macOS High Sierra node v8.11.3 jest: 23.6.0 ts-jest: 23.10.4
Here is one instance of the bug that I managed to reproduce. Not sure if there are multiple sources though:
https://github.com/spion/jest-logging-repro
yarn install; yarn repro
Setup: Jest is in watch mode, with verbose flag turned on, with at least two test files running.
Theory: Output from one of the workers moves the console cursor to the wrong place overwriting wrong content.
Observation in console:
If I remove the console log, visually “RUNS” get overwritten as intended:
If I add 3 console logs:
Node version:
Currently encountering same issue on node v8.7.0 (npm v5.4.2).
I’ve been using Jest for months and it’s great and while this bug is super annoying , the workaround I’ve always used is to make a junk assertion since that will log to console every time.
Example, when trying to log out a mock call:
expect('hello').toEqual(childFunc.mock.calls[0])
prints out:It’s not ideal but it gets the job done and allows me to finish writing my tests.
Running Jest with a --watch flag. Jest version 23.5.0 Node version 8.11.3
This issue is really hurting, I wish the maintainers could fix this as soon as possible, because Jest is meant to increase productivity, not the other way round right?
Anyway, the following is what I’m using write now:
You gotta spam your way out.
I’ve worked around this with:
😬
This breaks a lot of integration tests, however they’re mainly broken due to missing color. Doing
brings down that number significantly but its still pretty high:
I don’t think there is a way around this - the output is drastically changed, as a lot more writes end up adding the status update now.
edit: there is also the issue of node flushing the output stream too late in certain situations, long after the child process sent a success message to the parent.
I can often see the log output for a split second before the full test summary prints to the console. I’m having to
console.log
about 4-5 times in a row to get the output showing, and even then the last log will be chopped off halfway (for example when printing a large object, only the first half will be visible in the last printed log).It’s also very hard to predict. Sometimes one or two
console.log
s will suffice, whereas other times I have to put three to five in a row. It also doesn’t matter if my logs are in the code I’m testing, or in the test cases themselves.Seems like jest is printing the logs, then clearing the output before printing the full test summary, when really it should be retaining those logs.
I’ve accepted at this point that I have to copy-paste the logs multiple times to see them in the console.
This is still an issue
@thymikee Just tried with
jest@test
on node8.2.1
but same result.console.log
statements are always swallowed.Please reopen this issue
@SimenB I could but it looks like this issue has been discussed to death here and elsewhere. The multi-(child)process nature of jest means that it will overwrite
console.logs
, and without a massive rewrite that is not going to change. Anyone who comes to this thread and wants to avoid the issue where using the--verbose
flag disallows debugging withconsole.log
, should use the--watch
flag. This will avoid the child worker processes from overwriting and allow you see verbose output with console logs.--watch
is very fast and adds more value by focusing attention on the tests and code that have changed, by only running those tests that are changed on save.FWIW, I ended up here because I was having the exact same issue. Node v7.4.0. Upgraded my Node version, and
console.log
prints as expected now, even without--verbose
. V7.4.0 may not be the only version to have this issue, but it does seem to be version-related, and a non-issue for some Node versions. I’m now on Node v8.3.0, which seems to work.That said, prior to upgrade I had the same versions as @nf071590 , and the same problems. I’m not sure why it doesn’t happen on repl.it, but it’s not some weird thing only happening on his computer.
Not sure what to do about this. I literally pasted your example into a file, and ran Jest, and it works as advertised on my Mac, with the latest master version of Jest as of a minute ago. See:
I can confirm as well! It’s like Christmas. 🎅
Can people with the issue test
jest@24.0.0-alpha.9
? It includes #6871FYI I run my repro with the following command:
Thats zsh - you might want
script -qfce
in bashand then I viewed the log with
cat -vet raw.log
. Here are the results:Hope this helps. Looks like there is a miscount of control codes at a certain point.
Throwing in since I’m on windows (node 8.4, jest 21.0.0-alpha.2),
console.log
s are sometimes hidden if you don’t use--verbose
, but seem to show consistently with it. Happy to update with results using node 7 and stable jest when I get a minute.@thymikee What about Node 6, which is the current LTS release? (Looks like I’m hitting this too, though haven’t debugged it enough yet. However, I’m limited to LTS releases for now, so can’t upgrade).
@thymikee This is happening inconsistently so its really hard to reproduce it. example: following runs by selecting single file from tests ( option p )
Now I tried to replicate same steps and the result is inconsistent.
@tiborsaas You’re not waiting for
Promise.all
to complete: useawait Promise.all(...)
Using
expect
to log info is an okay workaround if you’re logging from within a test (especially since you can create a snippet for it with a keyword likelogjest
in your editor), but that falls short whenever you need to dig deeper and log from within the actual functions your tests are calling.For me this in
beforeAll
and this in the shell did the work:
console.log
does work if you run a specific test file onlyyarn test <your-test-file-name>
e.g.
yarn test FormValidator
In my case I found the verbose messaging would eat some but not all
console.log
messages. I removed the verbose option and it seems to somewhat work!Thanks for the quick response! That’ll be hard because the current repo is private in my org… I’ll let you know if I get to it 😃
In that case, the log statements might be lost since the function is never called, but you should still see log statements in the original
forEach
case since node will wait for the promises to complete before exiting the process. So it’s still a bug, even though it’s a user errorYeah, got confused with it, sorry. Thx @tobyhinloopen
const lol = await Promise.all(versions);
worked as expected.Can you open up a new issue with a reproduction? I believe the issue reported by the OP is fixed while you’re seeing a different one (no matter if you handle async right or not, you should still see the log statement)
This is really weird. There seems to be an issue with async handling. I can’t get the errors to be displayed. Even if wrapped to
try/catch
blocks, I can’t see the error.The parameter
generator
is correct for sure, If I remove the async function call, then it logs correctly. It also returns the correct string when it’s outside the for loop.Jest version is
24.0.0
, node is10.5
I am running jest version
24.0.0
, yet I still can’t seeconsole.log
orconsole.error
. Wondering what I might be doing wrong.just need no wait till create-react-app updates
that’s awesome @tobyhinloopen!
@tobyhinloopen Cool to see a proof of the progress that mentioned @SimenB .
@jamesta696 Hi, I think that you need to post that kind of questions on StackOverflow using the tag of “jest” here because the discussions here are for “issues”, nevertheless, I know that somebody could help you, but the issue here could be closed because the main issue is not being discussed. And for now, I cannot give you an answer for that question because I’m not developing something for react and the frontend, also, I’m not a member of jest, but let’s try to follow the rules.
This issue should be reopened, console output swallowed by jest too, my environment is:
→ node --version v8.11.3
→ npx jest --version 23.4.1
I tried with a clean setup and everything works fine.
output:
So I thought the problem might be related to my jest configuration:
My instinct told me to check
verbose
and after remove it everything is fine.recap
jest version 23.4.1 with configuration
verbose
set totrue
would cause console output to be swallowed.node 8.11.3 jest 23.4.0
I’m finding this issue, or at least a similar issue, when I turn on file regex matching (pressing
p
inwatch
mode). Withall
turned on, the logs are printed as expected. Note--verbose
is not on here.Sample 1
With
all
watching (prints bothlog
s anderror
s:In
file regex
mode (only prints the firstlog
and not theerror
s):Sample 2
all
(prints bothlog
anderror
as expected):watch
(nothing is printed with the above code):Sample 3
all
(prints all fourlog
s expected):watch
(only the first twolog
s are printed with the above code):For what it’s worth, I’ve seen differences between Terminal and iTerm2.
I’m still at the point of needing a reproduction.
--forceExit
seems somewhat broken, but I’ve not encountered it when not using that flagWorkaround of @ledbit worked for me NPM 5.3.0 jest 22.4.3