Open milesj opened 6 years ago
The output is the same as above.
I assume, you mean the output is the truncated one?
even when
maxBuffer
is set
I think spawn
ignores that anyway, so it’s probably not related.
Do you get the same issue with other scripts, e.g. when trying to run yes | head -n 10000
via exec()
?
duplicate of #2360 or #2049?
@addaleax Yes, the same output as the truncated one. I'll update the post.
I'll try with that script and report back.
It looks a duplicate of https://github.com/nodejs/node/issues/784. Making the stdio pipes blocking as suggested here fixes the issue though probably there was a reason why it didn't land.
@santigimeno That this also occurs with non-Node child processes makes that sound unlikely (assuming that that’s correct)?
@addaleax I just tested with the jest
command that is a node script afaik.
@santigimeno I asked the OP to also check with yes | head -n 10000
to figure out whether this is related to child process stdio; that they said it doesn’t stop the issue from appearing seems to indicate it is not?
I think his response was he'll try and report back
BTW, yes | head -n 10000
works correctly
@santigimeno Thanks for testing that for me.
I've tried blocking the process, but that doesn't seem to work either. Same truncated output.
Code as follows:
const cp = require('child_process');
const out = [];
const p = cp.spawn('./node_modules/.bin/jest', ['--help'], {
cwd: process.cwd(),
maxBuffer: 1000 * 1000 * 10, // 10 MB
});
p.stdout._handle.setBlocking(true);
p.stdout.on('data', line => {
out.push(String(line));
});
p.on('close', code => {
console.log(code);
console.log(out.join(''));
});
This is easily reproducible in MAC through:
const cp = require('child_process')
const op = {maxBuffer: 100 * 1024 * 1024}
if (process.argv[2]) {
child = cp.spawn('node', ['-e', 'process.stdout.write(Buffer.alloc(10 * 1024 * 1024))'], op)
}
else
child = cp.spawn('node', ['-e', 'console.log(Buffer.alloc(10 * 1024 * 1024))'], op)
let buf = ''
child.stdout.on('data', (c) => {
buf += c
})
child.stdout.on('end', () => {
console.log('ENDED')
console.log(buf.length)
})
ENDED
164
ENDED
10485760
#
maxBuffer
is not a consideration in this problem.
And the root cause identified as the fact that console.log
non blocking, so if a process issues it and exits afterwards, the actual number of bytes written depends on the time gap between the two actions and the capability of the I/O channel to transfer the data in between the gap.
I don't know the latest on this, also don't know the best practice / workaround. So /cc @nodejs/process @nodejs/child_process
I've tried blocking the process, but that doesn't seem to work either. Same truncated output.
I think that's not working because you are making blocking the parent side of the pipe. For this to work the child process would need to make stdout/stderr blocking on its side (That's the reason why applying https://github.com/nodejs/node/issues/784#issuecomment-73744882 to node would fix this issue)
@gireeshpunathil Your scripts can not reproduce the bug.
It should use child = cp.spawn('node', ['-e', 'console.log(Buffer.alloc(10 * 1024 * 1024).toString())'], op)
.
console.log(Buffer.alloc(0))
will print <Buffer >
.
@killagu - thanks for checking. So basically the difference between yours and mine is that you add a toString()
to get the actual data, while I didn't do that instead counted the numbers. The bug
is not the way it is printed, but the fact that data was truncated right?
Nevertheless, no need to investigate this further as the underlying bug is well understood, and we have open issues on the same. The effort be better directed towards looking at how do we fix it. Does that sound good to you?
@gireeshpunathil If you use toString
, It will print
ENDED
10485761
The data is not truncated.
If you do not use toString
, it will print <Buffer 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ... >
, so the number is 164.
So the script can not reproduce the bug.
, so the number is 164.
can you please expand on that? what that number 164 signifies, according to you?
never mind, I got what you are saying. So the stringified version of the buffer object was passed across rather than the whole content. thanks for clarifying. How about this version?
const cp = require('child_process')
const op = {maxBuffer: 100 * 1024 * 1024}
if (process.argv[2] === 'child') {
const buf = Buffer.alloc(10).toString()
for(var i=0; i< 1024 * 1024; i++)
console.log(buf)
process.exit(0)
} else {
const child = cp.spawn(process.execPath, [__filename, 'child'])
let buf = ''
child.stdout.on('data', (c) => {
buf += c
})
child.stdout.on('end', () => {
console.log(buf.length)
})
}
shows random length if you run multiple times - both on linux and mac.
If you use toString
, It will print
ENDED
10485761
Not use toString
, it will print
ENDED
164
You can run the script @gireeshpunathil
@gireeshpunathil The new script works well. Thanks for the reply.
I can reproduce this too (Node v10.11.0, v10.13.0, v11.0.0), the child.stdout._handle.setBlocking(true)
workaround doesn't work for me.
const cp = require("child_process");
const op = { maxBuffer: 100 * 1024 * 1024 };
if (process.argv[2] === "child") {
const buf = Buffer.alloc(10).toString();
for (var i = 0; i < 1024 * 1024; i++) console.log(buf);
process.exit(0);
} else {
const child = cp.spawn(process.execPath, [__filename, "child"]);
child.stdout._handle.setBlocking(true);
let buf = "";
child.stdout.on("data", c => {
buf += c;
});
child.stdout.on("end", () => {
console.log(buf.length);
});
}
$ node test.js
1235597
$ node test.js
1214246
$ node test.js
1214257
$ node test.js
1159708
$ node test.js
1152624
$ node test.js
1150754
Is there another workaround at the moment?
Remove the process.exit()
and let node exit when its flushed it's I/O.
@sam-github Is there a way to do this and still be able to dictate the exit code when Node eventually exits?
You can do process.exitCode = 3
or whatever 👍
https://nodejs.org/api/process.html#process_process_exitcode
This problem still exists in child_process and in almost all of the libraries that build on it or that attempt to replace it. There's one library that just works
and doesn't, in my experience, truncate the output: https://www.npmjs.com/package/cross-spawn
The maintainers of child_process
might want to look at that library for solutions to this bug.
It looks like maxBuffer
option isn't working at all.
In the example below, if you limit the output to 10 bytes, it will still show the whole 200 kb output:
const out = []
const p = childProcess.spawn('curl', ['https://stackoverflow.com'], {maxBuffer: 10})
p.stdout.on('data', line => {
out.push(String(line))
})
p.on('close', () => {
console.log(out.join(''))
})
Version: 15.14.0 Platform: Windows 10
@aleksey-hoffman spawn
does not list maxBuffer
as a supported option: https://nodejs.org/api/child_process.html#child_process_child_process_spawn_command_args_options
@benjie I see, only sync version supports it. Thanks.
So the problem with truncated output is not caused by the maxBuffer
then
I'm still seeing this problem when using exec and spawn on macOS Monterey 12.0.1. Is there a status on the fix?
Having this problem reading stdout on a large command output using exec() in macOS Monterey
Still happens on macOS 14.4 and Node v18.19.1. This is a really serious bug in a very basic part of Node that I'm quite surprised didn't receive any attention... 😢
Though in my case there isn't any process.exit
it happens in the middle of the output, some of it is just dropped, and then resuming later on, my parent code doesn't have child.stdout._handle.setBlocking(true)
, I'm not sure why would output be dropped like that...
It seems like
spawn()
andexec()
is truncatingstdout
, even whenmaxBuffer
is set. I've been trying to capture the output ofjest --help
, which the full output looks like the following:spawn()
Here's an example
spawn()
script:And the captured output:
Notice that about half the output is missing.
exec()
Another attempt using
exec()
.The output is the same as the truncated above.
Execa
Another attempt using
execa
.The output is the same as the truncated above.