stdout not being flushed before Jest's test result summary is written

[mfulton26]

Do you want to request a feature or report a bug?

I want to report a bug.

What is the current behavior?

The last process.stdout.write invocation in an async test is not flushed before Jest's test result summary is written.

If the current behavior is a bug, please provide the steps to reproduce and
either a repl.it demo through https://repl.it/languages/jest or a minimal
repository on GitHub that we can yarn install and yarn test.

https://repl.it/repls/DeepQuickwittedMite

What is the expected behavior?

I expect the console messages from the tests to all appear before Jest's test result summary:

  console.log flush.spec.js:6
    Hello

  console.log flush.spec.js:8
    Goodbye

 PASS  ./flush.spec.js
  ✓ something (1005ms)

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

But instead the last output message is flushed after Jest's test result summary:

  console.log flush.spec.js:6
    Hello

 PASS  ./flush.spec.js
  ✓ something (1004ms)

Test Suites: 1 passed, 1 total
Tests:       1 passed, 1 total
Snapshots:   0 total
Time:        1.238s
Ran all test suites.
  console.log flush.spec.js:8
    Goodbye

Please provide your exact Jest configuration and mention your Jest, node,
yarn/npm version and operating system.

jest 21.2.1
node 6.12.0
npm 3.10.10
Windows 10.0

[leebenson]

I'd love to see an option for displaying the current contents of the console buffer before the tests have finished.

Use-case:

I find Jest is super convenient for writing quick TDD blocks for HTTP servers and other long-running servers, that I want to augment with manual testing. Using a combo of jest -t <test-name> and awaiting a Promise that never resolves is a nice way of quickly spinning up snippets of code -- but the lack of visibility from console.log until after the test runs means I never get to see any feedback from within Node.

Granted, this is probably an edge case (and a bastardisation of Jest), but a simple jest.flushImmediately() option would be useful all the same.

[quezak]

I'm also experiencing this sometimes. Is there any workaround? Can I completely disable jest's console wrapper?

[brainchest]

I'm using the following workaround to wait for the console to be flushed

afterAll(async (done) => {
    if (!process.stdout.write('')) {
        process.stdout.once('drain', () => { done(); });
    }
});

process.stdout.write(data) returns true in case the console was flushed when writing data. In case the console was not flushed then you can wait for the drain event which basically says, the console was flushed. Using done(), I can then tell Jest to wait for the next flush event.

Probably not an ideal solution, but works for now.

[jimsnab]

In my case, the widely suggested stdout flush technique, such as writing an empty string to stdout, did not work - because kernel buffering isn't the problem. I still have completed process.stdout.write() calls that haven't printed by the time jest calls process.stderr.write(). And since stderr doesn't buffer, the final test results wind up somewhere in the middle of chatty test output.

I ultimately folded and went with this hack at the top of my test code:

if (process.stdout.isTTY && process.stderr.isTTY) {
    process.stderr.write = process.stdout.write;
}

I've tried reaching into the stdout._handle and turning off buffering via set-blocking, but yet it still buffers. My wild guess is that the host process (node) is using underlying user-mode buffered I/O, and doesn't expose a fflush(stdout) method.

And I couldn't get this to reproduce with a simple test.

Update: I tracked down the reason for my log output coming after Jest stderr write. See darrylwest/simple-node-logger#69

[glenne]

I solved mine with
afterAll(async (done) => { setTimeout(done, 100); });

Update: the async isn't needed so my workaround is:
afterAll((done) => { setTimeout(done, 100); });

[pedroteixeira]

Using --useStderr seems to have solved for the case I had here (i.e. for console.log to be flushed to the terminal sooner)

[jeanlescure]

Don't take this the wrong way, but I'm glad this is a Jest issue.

I really thought I had a race condition on the library I'm working on. But firstly, I am aware Jest complains if logs happen after the test is done with a warning about async functions that are not awaited, but I get no such error, and secondly our library is being used in production-ready apps and I'm certain whenever I await the logs they always show up in the order I expect them to and without allowing following operations to run before the logs are printed to console.

I can confirm both workarounds that @glenne and @pedroteixeira shared work.

I won't go down the route of using --useStderr since I am perfectly aware of how easy it is to break CI tools or monorepo builds (i.e. rush) by outputting to stderr (microsoft/rushstack#1329).

For now I will add the afterAll timeout, although mine looks like this:

const sleep = (ms: number) => new Promise(resolve => setTimeout(resolve, ms));

//...

  afterAll(async () => { await sleep(100); });

If you'd like a reproducible case you can download the simplyhexagonal/logger repo and use this commit of ours and simply remove the aforementioned afterAll:

simplyhexagonal/logger@eb3ae2e

Cheers

[glenne]

@jeanlescure You can also use your sleep function inside an individual test to work around this by putting

await sleep(100)

at the end of an async test.

My version works because afterAll has an overload where it passes a 'done' callback func to the user supplied function to signal completion.

[SimenB]

I think this is better tracked in #7900

[github-actions]

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.