Output truncated in Node 6

[MitMaro]

Problem

The text reporter has truncated output in Node 6.

Minimal Test Case

Test case repo

git clone https://github.com/MitMaro/IstanbulTruncateBug
nvm use 6
npm install
./node_modules/.bin/istanbul cover test.js --report text

Expected Output

Result of running with Node v4.4.4 and v5.11.1

$ ./node_modules/.bin/istanbul cover test.js --report text
=============================================================================
Writing coverage object [/IstanbulTruncate/coverage/coverage.json]
Writing coverage reports at [/IstanbulTruncate/coverage]
=============================================================================
-------------------|----------|----------|----------|----------|----------------|
File               |  % Stmts | % Branch |  % Funcs |  % Lines |Uncovered Lines |
-------------------|----------|----------|----------|----------|----------------|
 IstanbulTruncate/ |      100 |      100 |      100 |      100 |                |
  a.js             |      100 |      100 |      100 |      100 |                |
  b.js             |      100 |      100 |      100 |      100 |                |
  c.js             |      100 |      100 |      100 |      100 |                |
  test.js          |      100 |      100 |      100 |      100 |                |
-------------------|----------|----------|----------|----------|----------------|
All files          |      100 |      100 |      100 |      100 |                |
-------------------|----------|----------|----------|----------|----------------|


=============================== Coverage summary ===============================
Statements   : 100% ( 6/6 )
Branches     : 100% ( 0/0 )
Functions    : 100% ( 0/0 )
Lines        : 100% ( 6/6 )
================================================================================
$ 

Actual Output

Result from running in Node 6.1.0

$ ./node_modules/.bin/istanbul cover test.js --report text
=============================================================================
Writing coverage object [/IstanbulTruncate/coverage/coverage.json]
Writing coverage reports at [/IstanbulTruncate/coverage]
=============================================================================
-------------------|----------|----------|----------|----------|----------------|
File               |  % Stmts | % Branch |  % Funcs |  % Lines |Uncovered Lines |
-------------------|----------|----------|----------|----------|----------------|
 IstanbulTruncate/ |      100 |      100 |      100 |      100 |                |
  a.js             |      100 |      100 |      100 |      100 |                |
  b.js             |      100 |      100 |      100 |      100 |                |
  c.js             |      100 |      100 |      100 |      100 |                |
  test.js          |      100 |      100 |      100 |      100 |                |
-------------------|----------$ 

Investigation

I drilled down to lib/report/text.js:228 and text at this point contains the complete expected output. So it seems there is an issue with Node 6 and console.log. After some research I came across this issue. If you read through the comments it comes down to a change in libuv around non-blocking I/O with stdout.

On a suggestion found in the linked issue above, I changed lib/report/text.js:228 to instead be the following, which apparent forces stdout to be blocking and Istanbul works as expected. I am not sure if this is the correct way to fix the issue, but it does show that stdout not blocking, to be the issue.

process.stdout._handle.setBlocking(true);
console.log(text);
process.stdout._handle.setBlocking(false);

System

 $ node --version
v6.1.0

$ ./node_modules/.bin/istanbul help
...
istanbul version:0.4.3

$ uname -a
Darwin <host> 15.4.0 Darwin Kernel Version 15.4.0: Fri Feb 26 22:08:05 PST 2016; root:xnu-3248.40.184~3/RELEASE_X86_64 x86_64 i386 MacBookPro11,4 Darwin

Notes

It is possible that the above test case will pass if there isn't enough output.

[MitMaro]

Some more information. The reports are written on the process exit event but the docs state that

you must only perform synchronous operations in this handler. (source).

Since "the console functions are asynchronous unless the destination is a file" (source) this causes the problem with the truncated output. The node process will exit early before the console output is completely written.

[thealjey]

this is such a pain in the ass!
at first I thought that something was wrong with my tests that caused istanbul to die silently in the middle, but then, after investigating what was actually going on I came to the same conclusion as @MitMaro (although, he obviously did a much more thorough investigation)

[MitMaro]

This is probably a better issue to watch. Looks like a lot of CLI tools are breaking in Node 6 without a viable workaround. Guess we all need to wait for a solution to land in Node.

Another note, although I didn't test the new alpha, I did pick through the code and it looks like the issue would still be present.

[thealjey]

@MitMaro I think that if Node.js fixes a long standing bug and that causes a lot of tools, that do what they shouldn't, to break I do not think that it's Node that needs to come up with a solution, but those tools need to adapt.
If you must not do anything asynchronous in the exit handler (which makes perfect sense to me), then don't, deal with it, think of a better way to structure your app.
Istanbul needs to be fixed, not Node.js, imho.

[MitMaro]

I agree, it should be up to the various tools that use the broken behaviour to fix the problem. However, from reading the issues on the Node project, there doesn't seem to be a viable way to fix the problem at the moment as Node doesn't currently have a way to wait for (or force) stdout and stderr to flush on exit. There is some talk of adding another exit function (os.exit or similar) that would flush stdout and stderr.

There is a beforeExit event on process that does work with Istanbul (I tested locally) however it breaks some of the other functionality that depends on process.exit being called. This would require a fair bit of refactoring of the code base to not use process.exit. I think this is something that should be taken into account for the current alpha branch.

As an aside isaacs has stated in a comment that perhaps this is something that Node may need to fix as there are many tools have used this broken behaviour for some time.

[aparajita]

Unfortunately the Node docs say nothing about the exact behavior of `process.exit (all they say is "Ends the process with the specified code."), so users had no choice but to assume the observed behavior was expected. Since that behavior remained consistent for several years, it's hard to blame the users. On the other hand, I'm wondering how such a huge breaking change made it past the Node test suite.

In any case, there is a temporary fix.

[MitMaro]

Thought I already posted this, but this has been mostly fixed in Node v6.2.1. There is an outstanding issue that is tracking the overall problem.