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.

[Bartvds]

i have this with a mocha fresh from npm on new node 0.8 64bit on Vista64 (yesyes :) where i fixed the path.existsSync warning, seems to work fine but im on windows for now and have no make to run tests (jake! :)

mocha runs ok from cmd, nice colors etc

but when calling mocha with node's child_process .exec or .spawn directly (and also through jake's .exec and using procstreams), then i get the warbled and unstable output mentioned above. it's same with the calling mocha js api from jake.

i get this in standard cmd, in some third party Console2 and also in SublimeText's console (when cli calling a jake build task).

i tried hacking/bypassing with my own reporter but ran into #323 (add arbitrary reporter) and so far failed in enabeling my reporter (index and needs a make/build?)

[velesin]

In my case (Windows7 64) everything works fine in console, but when I invoke the same command via Node's exec or spawn, only part of message is displayed (e.g. all error messages are missing). This problem makes it impossible for me to run mocha from my coffee script's Cake file.

[Honigbaum]

Any solutions? Same problem here with node 0.8.4 and mocha 1.3.0 on Windows 7 64Bit, it's not possible to use mocha from cakefile or in combination with nodemon (as workaround for failing --watch on Windows)

[dougwilson]

The problem is because mocha calls process.exit() which terminates the node event loop before the data to STDOUT/STDERR has finished being written. This only happens when you pipe it to another program that doesn't read enough from the pipe before mocha does process.exit(). Calling process.stdout.write is sometimes sync and sometimes async. The return value of process.stdout.write lets you know if the input was buffered or not. mocha should probably check that the streams have drained before calling process.exit().

I believe that when std{out,err} are connected to a console, they are a SyncWriteStream, in which case the .write() calls are indeed sync, but std{out,err} can be pointed anywhere. When they are pointed at a pipe they are instead a WriteStream in which case the .write() call could be buffering the the write (as determined by the return value).

There is a .flush() that will write the remaining buffer in a WriteStream in sync, but apparently node does not provide a no-op .flush() on a SyncWriteStream. The easiest change I can think of is to have mocha do this before calling process.exit():

process.stdout.flush && process.stdout.flush();
process.stderr.flush && process.stderr.flush();

I don't have Node.js installed on Windows to try, but if @Honigbaum, @velesin, @Bartvds, or @joewhite want to see if this is a fix that works under Windows, they can edit the _mocha program and change the mocha.loadFiles call at line 324 to

mocha.loadFiles(function(){
  mocha.run(function(){
    process.stdout.flush && process.stdout.flush();
    process.stderr.flush && process.stderr.flush();
    process.exit();
  });
});

[Honigbaum]

@dougwilson
Thank you for your answer. I tried your solution and it unfortunately did not work ...

[dougwilson]

@Honigbaum you have pushed me to actually install node on Windows and figure it out :) I have inspected process.stdout when it is connected to a pipe and it has the property _pendingWriteRequests set to a non-zero value, which confirms that the process.exit call occurs before the buffer is flushed out of node. Apparently it is actually a Socket object with _type set to "pipe" (for those interested, handling a pipe for stdio can be found in src/node.js line 397. This means that there actually isn't a .flush() on a piped stream, which is why my initial suggested didn't work.

It's too bad that the pipes are a Socket because it's more complicated to wait for them to drain before calling process.exit(). Here is a tested and confirmed working replacement for the mocha.loadFiles call:

mocha.loadFiles(function(){
  mocha.run(function(){
    var draining = 0;
    var exit = function(){ if (!draining--) process.exit(); };
    if (process.stdout.bufferSize) {
      draining += 1;
      process.stdout.once('drain', exit);
    }
    if (process.stderr.bufferSize) {
      draining += 1;
      process.stderr.once('drain', exit);
    }
    exit();
  });
});

Other solutions are to not actually call process.exit() or to provide callbacks to all the process.stdout.write calls throughout mocha, though that would be a lot of work. For Windows users who want to edit their mocha file, the file is located at %APPDATA%\npm\node_modules\mocha\bin\_mocha if mocha was installed globally (with npm install -g mocha).

[dougwilson]

As of mocha version 1.3.2, the workaround above now replaces the code in bin/_mocha line 322 with the following:

mocha.run(function(){
  var draining = 0;
  var exit = function(){ if (!draining--) process.exit(); };
  if (process.stdout.bufferSize) {
    draining += 1;
    process.stdout.once('drain', exit);
  }
  if (process.stderr.bufferSize) {
    draining += 1;
    process.stderr.once('drain', exit);
  }
  exit();
});

[matthewrobb]

I have version 1.4.2 and am just now beginning to experience this issue... :/

[tj]

i'll have a closer look at this soonish, kinda silly that we have to do this at the user level but hey

[matthewrobb]

And if it helps, replacing the above mentioned lines does solve the problem.

[tj]

keep in mind this needs to work for 0.4.x 0.6.x and 0.8.x

[tj]

0.4.x i imagine we can phase out soon though

[Honigbaum]

Same problem with 1.6 ... Would be happy if there is a solution in one of the next versions

[dougwilson]

@stevenvachon mocha directly implements the --no-exit option. What it does is simply not call process.exit(), which, as long as your code actually cleans itself up, allows the application to exit once the output has actually been written. As a Windows-only user, this is what I have been using for all this time.

[stevenvachon]

@dougwilson Yep, but if your solution were implemented, --no-exit would not be necessary for most cases under Windows. I personally like the idea of returning an exit code.

[dougwilson]

In 0.11, you can actually still exit with an exit code without the need to call process.exit(), though I'm not sure who actually uses 0.11.

[boneskull]

@dougwilson OK, so is @travisjeffery's patch good? With caveats? Can you summarize? :D

[dougwilson]

The patch just changes the issue instead of resolving it. The patch just needs to be changed to look like #333 (comment) . Let me know if you want me to send a PR and I can do it pretty quickly.

[boneskull]

@dougwilson Sure, thanks.


[dougwilson]

Done at #1440 . I'm just waiting to see if Travis CI says green, since the test suite doesn't actually work on Windows.

[am11]

Hello guys, over at node-sass, we are also experiencing the same issue. Any updates?

Related: sass/node-sass#506 and http://help.appveyor.com/discussions/problems/1091-npm-test-always-fails.

Note: we tried @stephenmathieson's suggestion and used --no-exit, but then it doesn't exit the test process even after passing all the testes (until the CI times out and reports failure).

[dougwilson]

@am11 solution's code: https://github.com/mochajs/mocha/pull/1440/files

[dougwilson]

@am11 it was merged here, but just hasn't yet been released to npm.

[am11]

@dougwilson, thanks for fixing this issue in mocha. 👍

Over at node.js, they have fixed it in 0.12 branch, but yet to backport to 0.10.x branch: nodejs/node-v0.x-archive#7196 (see the late comments). Not sure if/ever it will land in 0.10.x branch.

[dougwilson]

I doubt they'll ever backport it to 0.10.

[jbnicolai]

Fix has been shipped ^^

[chris-codaio]

Looks like this is failing now on node 7.2.1. The stream.write('', done); call never calls the callback. I'll open a new bug to track.