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

[heft] "heft --debug test" and "heft test --verbose" should enable Jest's verbose mode #4402

Merged
merged 6 commits into from
Oct 21, 2023

Conversation

octogonz
Copy link
Collaborator

@octogonz octogonz commented Oct 20, 2023

Summary

The problem: When debugging code, it's common practice to add console.log() in various files to monitor variable states, while also interactively stepping through breakpoints in the VS Code debugger. This experience is broken for unit tests, because Jest reroutes console.log() to a special handler that only prints the output after the test has completed.

Details

Why would Jest do that? The ideal model seems something like:

  • When debugging tests, console.log() should print to the interactive console
  • For a normal build, console.log() should fail the build, because nobody wants thousands of lines of noisy unit test output in their CI logs

However, perhaps this restriction was too difficult to enforce. Probably many projects will call console.log() as part of their normal execution, and if it can't be mocked easily, then when Jest runs that code, it will always print to the console as a side effect. So instead Jest reroutes console.log() to its internal BufferedConsole which collects the strings, which are then passed to the Jest reporter for reporting at the end of the test. This probably also ensures that parallel test runs don't interfere with each other's output.

This also allows the console.log() output to be reformatted so that it cannot be confused with build logs from the toolchain. Our HeftJestReporter adds blue prefixes as seen below, for example:

image

Okay, but what about interactive debugging? It is extremely frustrating to call console.log() while stepping through code in the debugger, and it doesn't get printed, and there's no way to see the results without using watch windows to access Jest internals.

How can we ensure that console.log() gets printed immediately in that scenario, rather than buffering it? The obvious answer is to hook into Jest's BufferedConsole provider and also print to the real console.log() API. This would have the benefit of being compatible with VS Code's "console": "internalConsole" in launch.json, whereas Jest's output gets printed to STDERR and is therefore invisible without "console": "integratedTerminal".

But unfortunately, this turns out to be impossible without monkey-patching Jest, because the buffering is hard-wired:

jest-runner/src/runTest.ts

  if (globalConfig.silent) {
    testConsole = new NullConsole(consoleOut, consoleOut, consoleFormatter);
  } else if (globalConfig.verbose) {
    testConsole = new CustomConsole(consoleOut, consoleOut, consoleFormatter);
  } else {
    testConsole = new BufferedConsole();
  }

However although we can't intercept the logging events, if we set globalConfig.verbose then we get CustomConsole which does prints interactively, but just with rather ugly-looking output:

image

Despite being ugly, I think it is an improvement for the interactive debugging experience, and perhaps more consistent with expectations of --verbose. So that is what I've done in this PR.

How do we distinguish debugging from a normal build? In this PR the definition is heft --debug test or heft test --verbose.

Possible alternative implementation

If someone really hates the CustomConsole formatting, we could consider monkey-patching Jest instead.

What is particularly annoying with Jest's design is that console.error() gets formatted like a build failure:

image

But then the Jest run "succeeds" with process exit code 0. 🤦

How it was tested

  • Tested as shown in the screenshots above
  • I also confirmed that verbose:true does not affect the routing of logging to STDERR vs STDOUT (which would impact Rush's interpretation of "success with warnings")
  • I also confirmed that the process exit code is unaffected by this change

Impacted documentation

@D4N14L @elliot-nelson @dmichon-msft

…able Jest's "verbose=true" so that console.log() isn't delayed until after the test finishes (CustomConsole internally instead of BufferedConsole)
@octogonz octogonz enabled auto-merge October 20, 2023 22:07
@octogonz octogonz disabled auto-merge October 20, 2023 22:34
@octogonz octogonz enabled auto-merge October 21, 2023 01:28
@octogonz octogonz merged commit 8d6ba52 into main Oct 21, 2023
5 checks passed
@octogonz octogonz deleted the octogonz/jest-console-log branch October 21, 2023 01:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Archived in project
Development

Successfully merging this pull request may close these issues.

2 participants