Node: Chunked stdout/stderr drops writes if terminated early.

[jshkurti]

Hello,

I have an app which prints a long json to the output and I need to | grep this output in order to parse some data.
It works fine with Node.js but it doesn't with iojs.
It seems the output is chunked in some ways and grep stops before receiving all the data.
I came to this conclusion because when I redirect the output in some file and then cat file | grep it works, everything is there, but iojs app.js | grep won't.

Any ideas on this issue ?
Thanks.

[Fishrock123]

@jshkurti Did you try with node 0.12?

[jshkurti]

With Node 0.10.x 0.11.x and 0.12.x yeah :)

[jshkurti]

Actually, the background story here is that I'm working on https://github.com/Unitech/PM2 and tests don't pass with iojs.
PM2 seems to work fine with iojs though so I investigated a bit and found out that tests don't pass because of the grep issue.

[vkurchatkin]

Could it be related to #760?

[vkurchatkin]

A test (iojs test.js | grep hey):

var str = '';

for (var i = 0; i < 1000000; i++) {
  str += 'test\n'
}

str += 'hey\n';

process.stdout.write(str);
process.exit();

[vkurchatkin]

Looks like a fix:

diff --git a/lib/net.js b/lib/net.js
index 030083d..efebd03 100644
--- a/lib/net.js
+++ b/lib/net.js
@@ -135,8 +135,7 @@ function Socket(options) {
     this._handle = createHandle(options.fd);
     this._handle.open(options.fd);
     if ((options.fd == 1 || options.fd == 2) &&
-        (this._handle instanceof Pipe) &&
-        process.platform === 'win32') {
+        (this._handle instanceof Pipe)) {
       // Make stdout and stderr blocking on Windows
       var err = this._handle.setBlocking(true);
       if (err)

/cc @bnoordhuis

[jshkurti]

Tested with iojs-1.0.4, doesn't work either.

@vkurchatkin your solution works, thanks :)
It should be on the next release then I guess ?

[vkurchatkin]

It's not in yet, and I'm not sure it is a good solution, just a guess. let's wait for @bnoordhuis

[bnoordhuis]

It looks correct to me. I've looked at that code when I put together #774 but I wasn't completely sure if it needed updating. This bug report is good external validation. I'll update the PR with the proposed change and a regression test. :-)

[brendanashworth]

This is a known issue of io.js, but this is technically a duplicate of https://github.com/nodejs/io.js/issues/760 so I'm going to close this in favor of tracking it in the other issue. Thank you for reporting this!

[Fishrock123]

@brendanashworth I'm really not sure it is actually a duplicate, see: https://github.com/nodejs/io.js/pull/1771

Reopening for now.

[brendanashworth]

Totally sorry! You're right, I should have looked more closely.

[Fishrock123]

So in #1771 I describe that this only happens if your process exists prematurely. (I.e. process.exit() before all chunked writes are finished. @jshkurti Are you sure the current behavior isn't expected? Any idea what PM2 would be doing to cause that?

[jshkurti]

It's not PM2 related. Have a look at https://github.com/nodejs/io.js/issues/2049
Same behavior without using PM2.

[jshkurti]

https://github.com/nodejs/io.js/pull/1771/ fixes it so I'll just wait till it is merged some day :)

[Fishrock123]

Right, but I'm not actually sure that is a bug? Is it a regression from 0.12 or 0.10?

I was asking how PM2 was achieving the testcase functionality. :)

[oncletom]

I sort of faced this with [email protected].

I ended up piping into stdout to close the process once drained:

const through = require('through');

fetchData().then(result => {
  const stream = through();

  stream.on('end', () => process.exit(0));
  stream.pipe(process.stdout);

  stream.write(JSON.stringify(result));
});

[Fishrock123]

@oncletom Nice. I wouldn't mind a PR suggesting a process.exitGracefully() with some code like that. No guarantees on it being merged, but it might be good for discussion.

[oncletom]

@Fishrock123 oh well, I do not think it is needed: I never paid attention to this but WriteableStream.write is definitely non-blocking.

I guess the process.exit operation takes a bit of time and reveals the problem if the write+flush takes more time than the process to exit.

@vkurchatkin example should be rewritten as:

var str = '';

for (var i = 0; i < 1000000; i++) {
  str += 'test\n'
}

str += 'hey\n';

process.stdout.write(str, 'utf-8', () => process.exit());

And mine as:

fetchData().then(result => {
  process.stdout.write(JSON.stringify(result), 'utf-8', () => process.exit(0));
});

Does it sound correct to you?

[Fishrock123]

I never paid attention to this but WriteableStream.write is definitely non-blocking.

That function, and the streams state may be, but the crux of this issue is lower.

I guess the process.exit operation takes a bit of time and reveals the problem if the write+flush takes more time than the process to exit.

I would say the opposite is true. exit() is virtually instantaneous. And if flushing hasn't been done at an OS level, it will still drop chunked writes.

Did you check if your new examples worked? It's probable those only fire the callback after the stream has flushed, but not after chunked writes have actually been written/flushed to stdio.

[evanlucas]

@Fishrock123 Can this be closed now that stdio is blocking?

[TimothyGu]

@evanlucas, only stdio that are redirected to TTYs is blocking. @vkurchatkin's test case uses pipes, which still don't work.

[ryzokuken]

Is this still not fixed?

[addaleax]

@ryzokuken No, and it’s hard to fix this. I have some thoughts on how to tackle this after we can get https://github.com/nodejs/node/pull/19377 in, though:

I think we could flush the stdio streams as part of the handle cleanup methods (or possibly even all libuv-backed streams), by delaying closing those streams until after all libuv requests have drained from the event loop. We’d need a way to read all the pending stream.Writable JS-land buffers from C++, but I think that should be doable.

If we can get that going, we might even want to look into doing more async stdio again by default (because that’s Node.js’s general principle).

[ryzokuken]

hmm, this does seem complicated. I have been looking into the issue tracker trying to clean up as much as possible, so I'd be commenting a lot on issues I have next to no idea about anyway 😅

That said, I'd love to take this up on another day if it's still not fixed till then, once I have a deeper understanding of the inner-workings of libuv.

[addaleax]

@ryzokuken Yea, that sounds like a good idea – and if you want to actually bring some of these issues to a conclusion, that would be amazing. :blue_heart:

[ryzokuken]

Yes, that's the plan.

[jasnell]

There's been no further activity on this in over 2 years. Closing