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

Fix missing console log output in verbose mode #6871

Merged
merged 10 commits into from Dec 18, 2018

Conversation

Projects
None yet
8 participants
@spion
Copy link
Contributor

spion commented Aug 20, 2018

Summary

This PR fixes missing / overwritten console.log output in verbose mode.

The monkey-patch of stderr and stdout streams' write methods that clears and rewrites the status report at the bottom is not used when streams are in "inherit" mode. Because of that, live unbuffered output from the child workers gets overwritten by subsequent write instructions.

The multi-worker (parallel) runner is used in watch mode, which force-sets runInBand to false when there are 2 or more tests to run. Additionally, its combined with a regular streaming console (not a buffered one) when verbose is set to true.

Therefore the test case that can be used to reproduce the issue is configured with {verbose: true}, runs in watch mode and contains two tests:

https://github.com/spion/jest-logging-repro

yarn install; yarn repro

To make sure the patched version receives those stdout/stderr 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. The streams are then piped manually to the parent process, which ensures the right write instruction gets called.

In most cases, the right test behavior is preserved by passing FORCE_COLOR with the right value as an environment variable to the child process, and setting it to 0 in runJest. However, istanbul-lib-reporter uses an old version of supports-color which incorrectly implements support for the FORCE_COLOR environment variable. Therefore I updated a few of the snapshot tests to strip ansi codes manually themselves from the coverage reports. This has been done in the mean time since I submitted this PR.

Fixes #2441

Test plan

WIP: I will try to add my repro case (except with runInBand = false) to the e2e test suite. Any other thoughts on tests welcome. Would like some feedback before I proceed further.

@SimenB

This comment has been minimized.

Copy link
Collaborator

SimenB commented Aug 21, 2018

Exciting! Thank you so much for tackling it.

I don't get why we have to mess with force color?

@SimenB SimenB requested review from thymikee , mjesun and rickhanlonii Aug 21, 2018

@spion

This comment has been minimized.

Copy link
Contributor Author

spion commented Aug 21, 2018

@SimenB when the child streams switch from 'inherit' to 'pipe', process.stdout.isTTY / process.stderr.isTTY are no longer true on them so most colorizes decide to stop adding their colors in the output unless that env var is set (e.g. the dark gray console.log and line number are no longer displayed in color)

Another approach would be to have something like BufferedConsole (StreamingConsole?), except instead of sending the output at the end of the method run it sends messages continuously to the parent worker via process.send.

@thymikee
Copy link
Collaborator

thymikee left a comment

Looks ok from my side, but I'd like to have @mjesun eye on it. Also @spion can you update the snapshots so tests pass?

@spion

This comment has been minimized.

Copy link
Contributor Author

spion commented Aug 22, 2018

Not sure why the tests aren't passing in CI, locally I get

Test Suites: 283 passed, 283 total
Tests:       7 skipped, 2855 passed, 2862 total
Snapshots:   1166 passed, 1166 total
Time:        88.746s
Ran all test suites in 13 projects.
@thymikee

This comment has been minimized.

Copy link
Collaborator

thymikee commented Aug 22, 2018

Can you run yarn jest worker -u locally?

@codecov-io

This comment has been minimized.

Copy link

codecov-io commented Aug 22, 2018

Codecov Report

Merging #6871 into master will increase coverage by 0.01%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #6871      +/-   ##
==========================================
+ Coverage   67.71%   67.72%   +0.01%     
==========================================
  Files         247      247              
  Lines        9501     9504       +3     
  Branches        5        6       +1     
==========================================
+ Hits         6434     6437       +3     
  Misses       3065     3065              
  Partials        2        2
Impacted Files Coverage Δ
packages/jest-runner/src/index.js 76.19% <100%> (+1.19%) ⬆️
...ages/jest-worker/src/workers/ChildProcessWorker.js 88.37% <100%> (+0.27%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 873c641...c90b048. Read the comment docs.

wcalderipe added a commit to wcalderipe/easy-toggles that referenced this pull request Sep 5, 2018

Disable Jest verbose option
Jest is presenting a bug when running in verbose mode that's impossible
to use `console.log` outside a test file. Use logs inside the source
modules is one of the main debugging actions to understand what is
going on.

References:
facebook/jest#2441 (comment)
facebook/jest#6871
@SimenB

This comment has been minimized.

Copy link
Collaborator

SimenB commented Sep 16, 2018

@mjesun could you take a look?

@SimenB

This comment has been minimized.

Copy link
Collaborator

SimenB commented Sep 29, 2018

Maybe @rafeca has an opinion? :D

@SimenB SimenB added this to the Jest 24 milestone Oct 16, 2018

@spion

This comment has been minimized.

Copy link
Contributor Author

spion commented Nov 21, 2018

A few things I forgot to mention, in case it helps:

  • While the fix does ensure that the output is there, I still get some non-deterministic results. For example, a worker will send its "I'm done" message before flushing the stderr/stdout buffers. If that flush happens after all the tests in all workers complete, the main Jest process will accept the output but will not re-render the status report (instead the output will appear below the status-report-and-shortcuts text blub)
  • I can't figure out if its possible to force flush the console buffers and/or (more importantly) wait for that event to happen. Reimplementing the console (i.e. the StreamingConsole approach) would allow us to wait for this flush to happen before sending the "I'm done" message.
  • A third alternative would be to rewrite the last status (shortcuts blub) anyway, even if the final flush happens after. That would probably be easiest, but I haven't checked what it would involve.
@SimenB

This comment has been minimized.

Copy link
Collaborator

SimenB commented Nov 21, 2018

@spion mind rebasing? 🙂
@rickhanlonii can you test this at FB somehow? I tested in a smaller project at work and it worked out fine there

@spion spion force-pushed the spion:fix/missing-logs branch 2 times, most recently from bd90227 to e99bb25 Nov 22, 2018

@spion spion force-pushed the spion:fix/missing-logs branch from e99bb25 to 7c83449 Nov 23, 2018

@spion

This comment has been minimized.

Copy link
Contributor Author

spion commented Nov 23, 2018

Rebased - the patch is now quite tiny because color stripping for snapshots has already been implemented...

@SimenB
Copy link
Collaborator

SimenB left a comment

please update the changelog as well 🙂

spion and others added some commits Nov 23, 2018

@SimenB

SimenB approved these changes Nov 23, 2018

Copy link
Collaborator

SimenB left a comment

I'd love the feedback of some FB peeps, but this LGTM

@rickhanlonii

This comment has been minimized.

Copy link
Member

rickhanlonii commented Nov 23, 2018

cc @cpojer

@thymikee thymikee changed the title WIP: Fix missing console log output in verbose mode Fix missing console log output in verbose mode Nov 23, 2018

@aleclarson

This comment has been minimized.

Copy link
Contributor

aleclarson commented Nov 27, 2018

Bump. Would love to get this merged (and released). Super annoying :)

@thisissami

This comment has been minimized.

Copy link

thisissami commented Nov 28, 2018

Thanks so much for your work @spion! It's been years of this being a consistent issue.

KingHenne added a commit to sinnerschrader/feature-hub that referenced this pull request Dec 8, 2018

fix(integration-tests): do not emit declaration files (to memory-fs)
First of all, we don't need them. And secondly, this reduces the webpack
output when running the tests.

I would have liked to also reduce the stats that are printed, but because
of the following bug, only the one of the two bundled files is printed:
facebook/jest#2441
Jest PR with a fix: facebook/jest#6871

When the PR is merged, we could use this stats config for example:

```json
{
  all: false,
  assets: true,
  colors: true,
  timings: true
}
```

KingHenne added a commit to sinnerschrader/feature-hub that referenced this pull request Dec 10, 2018

fix(integration-tests): do not emit declaration files (to memory-fs) (#…
…160)

First of all, we don't need them. And secondly, this reduces the webpack
output when running the tests.

I would have liked to also reduce the stats that are printed, but because
of the following bug, only the one of the two bundled files is printed:
facebook/jest#2441
Jest PR with a fix: facebook/jest#6871

When the PR is merged, we could use this stats config for example:

```json
{
  all: false,
  assets: true,
  colors: true,
  timings: true
}
```
Merge branch 'master' into pr/6871
* master: (24 commits)
  Add `jest.isolateModules` for scoped module initialization (#6701)
  Migrate to Babel 7 (#7016)
  docs: changed "Great Scott!" link (#7524)
  Use reduce instead of filter+map in dependency_resolver (#7522)
  Update Configuration.md (#7455)
  Support dashed args (#7497)
  Allow % based configuration of max workers (#7494)
  chore: Standardize filenames: jest-runner pkg (#7464)
  allow `bail` setting to control when to bail out of a failing test run (#7335)
  Add issue template labels (#7470)
  chore: standardize filenames in e2e/babel-plugin-jest-hoist (#7467)
  Add node worker-thread support to jest-worker (#7408)
  Add `testPathIgnorePatterns` to CLI documentation (#7440)
  pretty-format: Omit non-enumerable symbol properties (#7448)
  Add Jest Architecture overview to docs. (#7449)
  chore: run appveyor tests on node 10
  chore: fix failures e2e test for node 8 (#7446)
  chore: update docusaurus to v1.6.0 (#7445)
  Enhancement/expect-to-be-close-to-with-infinity (#7444)
  Update CHANGELOG formatting (#7429)
  ...
@thymikee

This comment has been minimized.

Copy link
Collaborator

thymikee commented Dec 18, 2018

I think we hit this bug yarnpkg/yarn#6042 :(

@thymikee

This comment has been minimized.

Copy link
Collaborator

thymikee commented Dec 18, 2018

Removing nohoist helps (and it turned out we don't need it, because we only have 1 version of RN). Also tested locally on Jest repo and it seems to work just fine.

@thymikee thymikee merged commit b21ab21 into facebook:master Dec 18, 2018

10 checks passed

ci/circleci: lint-and-typecheck Your tests passed on CircleCI!
Details
ci/circleci: test-browser Your tests passed on CircleCI!
Details
ci/circleci: test-jest-circus Your tests passed on CircleCI!
Details
ci/circleci: test-node-10 Your tests passed on CircleCI!
Details
ci/circleci: test-node-6 Your tests passed on CircleCI!
Details
ci/circleci: test-node-8 Your tests passed on CircleCI!
Details
ci/circleci: test-or-deploy-website Your tests passed on CircleCI!
Details
continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
deploy/netlify Deploy preview ready!
Details
@thymikee

This comment has been minimized.

Copy link
Collaborator

thymikee commented Dec 18, 2018

Thanks @spion, appreciated!

@spion spion deleted the spion:fix/missing-logs branch Dec 19, 2018

@SimenB

This comment has been minimized.

Copy link
Collaborator

SimenB commented Dec 19, 2018

released as alpha.9 (jest@beta)

@SimenB

This comment has been minimized.

Copy link
Collaborator

SimenB commented Jan 14, 2019

@spion this seems to work really well, thank you so much!

While looking at some other code, I noticed that #7408 (which introduced worker support) does not include this - do you think it needs to? Workers don't have the same stdio API (it has separate stdio, stderr and stdout flags): https://nodejs.org/api/worker_threads.html#worker_threads_new_worker_filename_options

@spion

This comment has been minimized.

Copy link
Contributor Author

spion commented Jan 14, 2019

I'm not sure if its needed - I guess I should have added a proper test to the PR 😞 - but it seems to be like after the refactor the pipe option no longer gets passed all the way to the process based workers.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment