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

Most upvoted comments

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.

describe('index', () => {
  it('doesnt print anything', () => {
    console.log('Hellllooo');
    expect(true).toBe(true);
  });
});
$ yarn test -- src/__tests__/index.spec.js --verbose
yarn test v0.27.5
warning package.json: No license field
$ jest "src/__tests__/index.spec.js" "--verbose"
 PASS  src/__tests__/index.spec.js
  Index
    ✓ doesnt print anything (2ms)

Test Suites: 1 passed, 1 total
Tests:       1 passed, 1 total
Snapshots:   0 total
Time:        0.969s, estimated 2s
$ jest "--version"
v20.0.4
$ node --version
v7.4.0

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

  console.log = s => {
    process.stdout.write(s + "\n");
  };

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!

screen shot 2017-08-24 at 17 39 59

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 version 23.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 be

  1. added after the status (the status does not get erased)
  2. will be erased on the next status erase (making the previous status partially visible too, since the erase doesn’t move up sufficiently to erase both the console output and the old status update)

To 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:

diff --git a/packages/jest-runner/src/index.js b/packages/jest-runner/src/index.js
index 2f4dd724..618a8cbf 100644
--- a/packages/jest-runner/src/index.js
+++ b/packages/jest-runner/src/index.js
@@ -97,11 +97,14 @@ class TestRunner {
     // $FlowFixMe: class object is augmented with worker when instantiating.
     const worker: WorkerInterface = new Worker(TEST_WORKER_PATH, {
       exposedMethods: ['worker'],
-      forkOptions: {stdio: 'inherit'},
+      forkOptions: {stdio: 'pipe'},
       maxRetries: 3,
       numWorkers: this._globalConfig.maxWorkers,
     });

+    worker.getStdout().pipe(process.stdout);
+    worker.getStderr().pipe(process.stderr);
+
     const mutex = throat(this._globalConfig.maxWorkers);

     // Send test suites to workers continuously instead of all at once to track

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.

describe('index', () => {
  it('doesnt print anything', () => {
    console.log('Hellllooo');
    expect(true).toBe(true);
  });
});
$ node --version
v7.4.0
$ jest "--version"
v21.1.0

screen shot 2017-09-21 at 14 34 32

FWIW, the --verbose=false workaround works for me. In my package.json:

"scripts": {
...
    "test": "react-scripts test --env=jsdom --verbose=false",

Some other observations:

  • Removing --env=jsdom (not an option for my real application) made it work without --verbose=false.
  • Running the test directly with jest (not through react-scripts) also made it work.
  • When an assertion fails and you get much more output from jest, much more of your console logs gets overwritten also.

The problem still persists with --verbose when combined with --forceExit - I think the reason for that is that console.log outputs to stdout while jest writes to stderr and when --forceExit there may still be content in stdout not be flushed

I 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 live

command jest .... --forceExit --setupTestFrameworkScriptFile ./src/tests/jestShim.js

contents of jestShim.js

const { Console } = require('console');
global.console = new Console(process.stderr, process.stderr);

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:

 RUNS  tests2/other-tests.js
 RUNS  lib/example.spec.js
 PASS  tests2/other-tests.js
  bar
    ✓ always is true (17ms)

 PASS  lib/example.spec.js
  foo
    ✓ adds 5 (5ms)

Test Suites: 2 passed, 2 total
Tests:       2 passed, 2 total
Snapshots:   0 total
Time:        1.673s
Ran all test suites.

Watch Usage: Press w to show more.

If I remove the console log, visually “RUNS” get overwritten as intended:

 PASS  lib/example.spec.js
  foo
    ✓ adds 5 (5ms)

 PASS  tests2/other-tests.js
  bar
    ✓ always is true (5ms)

Test Suites: 2 passed, 2 total
Tests:       2 passed, 2 total
Snapshots:   0 total
Time:        1.597s
Ran all test suites.

Watch Usage: Press w to show more.

If I add 3 console logs:

 PASS  lib/example.spec.js
  foo
    ✓ adds 5 (5ms)


 RUNS  tests2/other-tests.js

Test Suites: 1 passed, 1 of 2 total
Tests:       1 passed, 1 total
Snapshots:   0 total
  console.log tests2/other-tests.js:5
    JEST

 PASS  tests2/other-tests.jsests.js:6
  bar
    ✓ always is true (19ms)

Test Suites: 2 passed, 2 total
Tests:       2 passed, 2 total
Snapshots:   0 totalTime:        1.788sRan all test suites.

Watch Usage: Press w to show more.

Node version:

30656 % node --version
v8.11.2

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:

screen shot 2018-11-27 at 10 26 44 am

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:

export const log = (s: any) => {
    console.log(s);
    console.log(s);
    console.log(s);
    process.stdout.write(s + "\n");
};

You gotta spam your way out.

I’ve worked around this with:

expect(str).toBe("not this");

😬

This breaks a lot of integration tests, however they’re mainly broken due to missing color. Doing

diff --git a/packages/jest-worker/src/worker.js b/packages/jest-worker/src/worker.js
index 5eee64af..5e5126eb 100644
--- a/packages/jest-worker/src/worker.js
+++ b/packages/jest-worker/src/worker.js
@@ -94,6 +94,8 @@ export default class {
         {
           cwd: process.cwd(),
           env: Object.assign({}, process.env, {
+            // $FlowFixMe: Does not know about isTTY
+            FORCE_COLOR: process.stdout.isTTY,
             JEST_WORKER_ID: this._options.workerId,
           }),
           // Suppress --debug / --inspect flags while preserving others (like --harmony).

brings down that number significantly but its still pretty high:

Test Suites: 51 failed, 232 passed, 283 total
Tests:       149 failed, 7 skipped, 2706 passed, 2862 total
Snapshots:   19 failed, 17 obsolete, 996 passed, 1015 total

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.logs 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 node 8.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 with console.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:

screen shot 2017-08-24 at 4 38 11 pm

I can confirm as well! It’s like Christmas. 🎅

Can people with the issue test jest@24.0.0-alpha.9? It includes #6871

FYI I run my repro with the following command:

script -qfc 'yarn repro' /dev/null > raw.log

Thats zsh - you might want script -qfce in bash

and then I viewed the log with cat -vet raw.log. Here are the results:

^[[2K^[[1G^[[1myarn run v1.7.0^[[22m^M$
^[[2K^[[1G^[[2m$ jest --watch^[[22m^M$
^[[2J^[[3J^[[H^[[1m^[[2mDetermining test suites to run...^[[1m^[[22m^[[999D^[[K^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^[[0m^[[7m^[[1m^[[32m PASS ^[[39m^[[22m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A  foo^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A    ^[[32mM-bM-^\M-^S^[[39m ^[[2madds 5 (4ms)^[[22m^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mlib/^[[22m^[[1mexample.spec.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m0 of 2 total^M$
^[[1mTests:       ^[[22m0 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        0s, estimated 1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 of 2 total^M$
^[[1mTests:       ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        1s^[[999D^[[K  ^[[2mconsole.log^[[22m ^[[2mtests2/other-tests.js:5^[[22m^M$
    JEST^M$
^M$
^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^[[0m^[[7m^[[1m^[[32m PASS ^[[39m^[[22m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 of 2 total^M$
^[[1mTests:       ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A  bar^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 of 2 total^M$
^[[1mTests:       ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A    ^[[32mM-bM-^\M-^S^[[39m ^[[2malways is true (15ms)^[[22m^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 of 2 total^M$
^[[1mTests:       ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M$
^M$
^[[0m^[[7m^[[33m^[[1m RUNS ^[[22m^[[39m^[[27m^[[0m ^[[2mtests2/^[[22m^[[1mother-tests.js^[[22m^M$
^M$
^[[1mTest Suites: ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 of 2 total^M$
^[[1mTests:       ^[[22m^[[1m^[[32m1 passed^[[39m^[[22m, 1 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        1s^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^M^[[K^M^[[1A^[[999D^[[K^[[1mTest Suites: ^[[22m^[[1m^[[32m2 passed^[[39m^[[22m, 2 total^M$
^[[1mTests:       ^[[22m^[[1m^[[32m2 passed^[[39m^[[22m, 2 total^M$
^[[1mSnapshots:   ^[[22m0 total^M$
^[[1mTime:^[[22m        1.128s^M$
^[[2mRan all test suites^[[22m^[[2m related to changed files^[[22m^[[2m.^[[22m^M$
^M$
^[[1mWatch Usage^[[22m^M$
^[[2m M-bM-^@M-: Press ^[[22ma^[[2m to run all tests.^[[22m^M$
^[[2m M-bM-^@M-: Press ^[[22mf^[[2m to run only failed tests.^[[22m^M$
^[[2m M-bM-^@M-: Press^[[22m p ^[[2mto filter by a filename regex pattern.^[[22m^M$
^[[2m M-bM-^@M-: Press^[[22m t ^[[2mto filter by a test name regex pattern.^[[22m^M$
^[[2m M-bM-^@M-: Press^[[22m q ^[[2mto quit watch mode.^[[22m^M$
^[[2m M-bM-^@M-: Press ^[[22mEnter^[[2m to trigger a test run.^[[22m^M$

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.logs 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 )

  • console.log(‘pantz’) (works)
  • change console.log(myObject) (not working)
  • change it to fit (not working)
  • change to console.log(‘pantz’) (not working)
  • change fit to it (not working)
  • restart jest (not working)
  • change it to fit (working)

Now I tried to replicate same steps and the result is inconsistent.

@tiborsaas You’re not waiting for Promise.all to complete: use await 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 like logjest 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

  console.log = s => {
    process.stdout.write(s + "\n");
  };

and this in the shell did the work:

yarn test > test.log

console.log does work if you run a specific test file only

yarn 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 error

Yeah, 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.

image

Jest version is 24.0.0, node is 10.5

I am running jest version 24.0.0, yet I still can’t see console.log or console.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.

// console.test.js
describe('jest should console output', () => {
  test('should console.log output be print', () => {
    console.log('console.log')
    expect(1).toBe(1)
  })

  test('should console.error output be print', () => {
    console.error('console.error')
    expect(1).toBe(1)
  })

  test('should console.info output be print', () => {
    console.info('console.info')
    expect(1).toBe(1)
  })
})

output:

image

So I thought the problem might be related to my jest configuration:

{
  "globals": {
    "API_SERVER_PLACEHOLDER": "SOME_API_ADDRESS"
  },
  "moduleFileExtensions": [
    "js",
    "jsx"
  ],
  "transform": {
    "^.+\\.jsx?$": "babel-jest"
  },
  "moduleNameMapper": {
    "\\.(css|less|sass|scss|png)$": "<rootDir>/__mocks__/styleMock.js",
    "\\.(gif|ttf|eot|svg|png)$": "<rootDir>/__mocks__/fileMock.js"
  }
}

My instinct told me to check verbose and after remove it everything is fine.

recap

jest version 23.4.1 with configuration verbose set to true 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 in watch mode). With all turned on, the logs are printed as expected. Note --verbose is not on here.

Sample 1

it.only(`should display a ErrorMessage component if state.validated is 'error'`, () => {
    const fV = shallow(<FormValidator/>);
    console.log('r1');
    console.error('r2');
    console.error('r3');
    ...

With all watching (prints both logs and errors:

 PASS  src/components/__tests__/FormValidator.js
  ● Console

    console.log src/components/__tests__/FormValidator.js:56
      r1
    console.error src/components/__tests__/FormValidator.js:57
      r2
    console.error src/components/__tests__/FormValidator.js:58
      r3

In file regex mode (only prints the first log and not the errors):

Test Suites: 0 of 1 total
Tests:       0 total
Snapshots:   0 total
  console.log src/components/__tests__/FormValidator.js:56
    r1

 PASS  src/components/__tests__/FormValidator.jsidator.js:57
  FormValidator
    ○ skipped 3 tests
  FormValidator.displayMessage
    ✓ should display a ErrorMessage component if state.validated is 'error' (32ms)
    ○ skipped 5 tests
  FormValidator.render
    ○ skipped 1 test

Sample 2

it.only(`should display a ErrorMessage component if state.validated is 'error'`, () => {
    const fV = shallow(<FormValidator/>);
    console.log('r1');
    console.error('r3');
    ...

all (prints both log and error as expected):

 PASS  src/components/__tests__/FormValidator.js
  ● Console

    console.log src/components/__tests__/FormValidator.js:56
      r1
    console.error src/components/__tests__/FormValidator.js:59
      r3

watch (nothing is printed with the above code):

Snapshots:   0 total
 PASS  src/components/__tests__/FormValidator.jsator.js:56
  FormValidator
    ○ skipped 3 tests
  FormValidator.displayMessage
    ✓ should display a ErrorMessage component if state.validated is 'error' (20ms)
    ○ skipped 5 tests
  FormValidator.render
    ○ skipped 1 test

Test Suites: 1 passed, 1 total

Sample 3

it.only(`should display a ErrorMessage component if state.validated is 'error'`, () => {
    const fV = shallow(<FormValidator/>);
    console.log('r1');
    console.log('r2');
    console.log('r3');
    console.log('r4');
    ...

all (prints all four logs expected):

 PASS  src/components/__tests__/FormValidator.js
  ● Console

    console.log src/components/__tests__/FormValidator.js:56
      r1
    console.log src/components/__tests__/FormValidator.js:57
      r2
    console.log src/components/__tests__/FormValidator.js:58
      r3
    console.log src/components/__tests__/FormValidator.js:59
      r4

watch (only the first two logs are printed with the above code):

Snapshots:   0 total
  console.log src/components/__tests__/FormValidator.js:56
    r1

  console.log src/components/__tests__/FormValidator.js:57
    r2

 PASS  src/components/__tests__/FormValidator.jsator.js:58
  FormValidator
    ○ skipped 3 tests
  FormValidator.displayMessage
    ✓ should display a ErrorMessage component if state.validated is 'error' (31ms)
    ○ skipped 5 tests
  FormValidator.render
    ○ skipped 1 test

Test Suites: 1 passed, 1 total

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 flag

Workaround of @ledbit worked for me NPM 5.3.0 jest 22.4.3

  • Mac OS