Output gets cut off if piped into another application

[joewhite]

If I run my Mocha tests directly from the command line, they run fine, and the output displays with no problems. But if I try to pipe Mocha's output to another program, the output doesn't all get there; only the beginning of the output ever makes it into the pipe.

I've seen this in several manifestations, but it's easy to reproduce just from the command line. I've reproduced this on two different computers, both running 64-bit Windows 7, the latest version of Node.js installed from the Web site, and the latest Mocha installed with npm install -g mocha.

If I create a file with just one test in it:

it('works', function() {});

and run it from the command line, I see the expected output:

C:\Temp>mocha test.js

  .

  ✔ 1 tests complete (2ms)


C:\Temp>

But if I pipe its output into any other tool, even something as simple as more, then Mocha's output is cut off. I only see the line of dots -- sometimes not even that. The summary line isn't shown.

C:\Temp>mocha test.js | more

  .

C:\Temp>

If there are failing tests, and you run STDERR through a pipe, then the test-failure information will be cut off:

C:\Temp>mocha fail.js 2>&1 | more

  .  Γ£û 1 of 1 tests failed:


C:\Temp>

I've also seen this behavior when running Mocha from my text editor (Sublime Text 2) and capturing the output into an output window (the output doesn't all appear); and when writing Node.js code that shells out to Mocha (using child_process.exec) and captures its STDOUT and STDERR (the output doesn't all get sent). I haven't seen any other app cutting off its output like this in any of these circumstances, but Mocha does it every time its output is a pipe.

[tj]

well we do write to both std{err,out}, so some of that is expected

[joewhite]

Why would it be expected that the output doesn't all get written?

[tj]

each stream should definitely finish writing, which version of node is this? there have been a few issues

[joewhite]

I'm using Node v0.6.12.

If the tests all pass, then Mocha doesn't write anything to stderr, and the output is still cut off when I run it through a pipe. So I'm not sure being able to use both streams has anything to do with it.

The docs for process.stdout mention that writes to stdout and stderr usually block, but when they're pipes, writes are non-blocking. I wonder if that's relevant.

[tj]

guess we need to add those callbacks back, we used to have them but I removed them after isaac mentioned stdout was sync now (must have missed the pipe thing), seems kinda weird to do both.

[joewhite]

I'm not sure when you removed these callbacks, but if it helps, I tried snagging older versions of Mocha, and this problem has existed since the oldest version available in npm (0.0.1-alpha1).

[tj]

i'll mark it as a bug

[shwaydogg]

On Ubuntu 11.10 and OSX 10.7.2 pipes worked fine. On windows7, node 0.6.10, powershell and command prompt we could reproduce the bug. When output was piped to more there was either no output or just the a period nondeterministically.

PS C:\Users\Shwaydogg\Documents\HackerSchool> mocha test.js

  .

  ? 1 tests complete (12ms)


PS C:\Users\Shwaydogg\Documents\HackerSchool> mocha test.js | more

PS C:\Users\Shwaydogg\Documents\HackerSchool> mocha test.js 2>&1 | more

PS C:\Users\Shwaydogg\Documents\HackerSchool> mocha test.js | more

  .

PS C:\Users\Shwaydogg\Documents\HackerSchool>

[tj]

This issue has been inactive for over 1 month so I'm closing it. If you think it's still an issue re-open. - tjbot

[joewhite]

Did you test this before you closed it? The problem is still trivially reproducible with the steps described, with the latest version of Mocha in npm (1.1.0).

I'd be happy to reopen the issue, but my "Reopen" button is grayed out, and when I hover over it, GitHub tells me "You don't have permission to reopen this issue".

[tj]

my bot closed it, but yeah everything looks fine for me

[joewhite]

shwaydogg already commented that it seems to work correctly on Ubuntu 11.10 and OSX 10.7.2. What OS and Node version are you using? I get the problem behavior every time on Windows 7 64-bit with Node 0.6.12 (and shwaydogg confirmed with Windows 7 and Node 0.6.10). I'd be happy to upgrade my Node if you're seeing no problems with a newer version.

[tj]

i doubt it has anything to do with node/mocha, just terminals / shells, unicode blah blah

[joewhite]

Seems likely, but I've tried reproducing the problem in a standalone app (without Mocha), and so far I haven't been able to. So there's probably some Node feature Mocha is using that behaves badly with pipes, but it's not obvious to me what that feature might be (and it's also not obvious whether it would be easier to fix it in Node, or work around it in Mocha). Here's what I know so far from my experiments:

• If I run Mocha with --no-colors and a pipe, it still has the problem. (Not surprising, since Node probably assumes no-colors when its output isn't a TTY, but it's good to narrow the scope.)
• If I write an app that console.logs all the same strings Mocha outputs -- "", " .", "", and " \u2714 1 test complete (2ms)" -- then all the output comes through more; nothing is cut off. more apparently doesn't understand UTF-8, so it outputs three nonsense characters instead of the check, but the output is all there. So I don't think it's Unicode that's causing the failure, or at least not in an obvious way.
• Same thing if I use process.stdout.write (and manually add \n to each string) instead of console.log. IIRC, Mocha does use process.stdout.
• Same thing if I write everything up to the . immediately, and the remainder (including the .'s \n) from inside a setTimeout (to simulate the sort of async work Mocha is doing, and try to bring on any concurrency problems the async pipe might have). Doesn't matter whether I do a short timeout (I tried 50, 10, and even 0) or a long one (1000). Same thing if I use process.nextTick instead of setTimeout.

more evidently buffers its output a line at a time, so if I output the . and then wait before I output the \n, then I see a pause before I see the . at all. But that's different from Mocha, where there's a pause, and then either the dot appears or it doesn't, and nothing after the dot ever appears.

Here's my test app, in case it's helpful:

process.stdout.write("\n");
process.stdout.write("  .");
setTimeout(function() {
    process.stdout.write("\n");
    process.stdout.write("\n");
    process.stdout.write("  \u2714 1 test complete (2ms)\n");
}, 1000);

Any thoughts on what sorts of things Mocha might be doing with its I/O that I'm not covering? It'd be good to narrow down where the problem is.