stdout always cuts off the stream at character 8192

[aight8]

Using fork, spawn, exec in async and sync mode - stdout stream only returns up to 8192 characters. (note that the output is without any newlines)
Note that maxBuffer does not let increase this maximum. But it's possible to lower it by setting it to a value below 8192.

• Version: 7.10 / 7.9
• Platform: macOC Sierra 10.12.5

[addaleax]

Can you provide some example code that demonstrates the problem?

[vsemozhetbyt]

I cannot reproduce in Windows 7 x64:

const fs = require('fs');
const cp = require('child_process');

console.log(process.version);

fs.writeFileSync('data.txt', 'x'.repeat(8192 + 100));
console.log(fs.statSync('data.txt').size);

cp.exec('cat data.txt', (error, stdout, stderr) => {
  console.log(stdout.length);
});

v7.10.0
8292
8292

[aight8]

Example:

const child_process = require('child_process')

const stdout = child_process.execFileSync(
    'yarn',
    ['info', 'joi', '--json'],
    {
        encoding: 'utf8',
        maxBuffer: 500 * 1024
    }
)

console.log('Stdout length:', stdout.length)

try {
    const stdoutObject = JSON.parse(stdout)
    console.log('stdout is a valid JSON object.')
} catch (err) {
    console.log('stdout is an invalid JSON object.')
    console.error(err.toString())
}

---

Output:

$ node ./stdout-8192.js 
Stdout length: 8192
stdout is an invalid JSON object.
SyntaxError: Unexpected token m in JSON at position 8188

---

# bytes
$ yarn info joi --json | wc -c
   11222

# lines
$ yarn info joi --json | wc -l
       1

edit:
On my virtual machine with OS Ubuntu 16.04.2 LTS it works btw:

Stdout length: 11222
stdout is a valid JSON object.

but node.js v7.4.0

---

edit2:
updated node.js to v7.10.0 on the ubuntu VM. it's the same output than with v7.4.0.

---

edit3:
Your example:

const fs = require('fs');
const cp = require('child_process');

console.log(process.version);

fs.writeFileSync('data.txt', 'x'.repeat(8192 + 100));
console.log(fs.statSync('data.txt').size);

cp.exec('cat data.txt', (error, stdout, stderr) => {
  console.log(stdout.length);
});

works on my macOS also correctly.

EDIT 4!:
The same code but using npm (have the same arguments in this case) works well on macOS also. I don't know what yarn doing else, but this problem should be investigated since there is inconsistent behaviour across different operating systems.

[gireeshpunathil]

Here is the test case isolated from yarn, npm ect.

const cp = require('child_process');

if (process.argv[2] === 'child') {
console.log('g'.repeat(8193).toString());
}
else {
const child = cp.spawn(process.execPath, [__filename, 'child']);
  child.stdout.on('data', function(d) { 
	console.log(d.toString());
  });
}

In MAC OS + v7.10, a new line is inserted between 8192nd and 8193rd character, possibly buffering is happening at 8K. This is not happening in Linux.

Due to this, the incoming JSON gets corrupted.

[addaleax]

@gireeshpunathil Can you write that script as a test case that makes clear what the expected outcome is (i.e. that crashes otherwise)? I’ve tried a variant of your script in a Travis CI run and it seems to work fine on OS X.

[santigimeno]

In MAC OS + v7.10, a new line is inserted between 8192nd and 8193rd character, possibly buffering is happening at 8K

Isn't that expected as the data event is fired twice? Changing that to child.stdout.pipe(process.stdout); seems to print data correctly.

[aight8]

Shouldn't the sync. functions return all the received data?
It's an inconsitent behaviour anyway.

[santigimeno]

I can reproduce the issue on OS X with the first example in #12921 (comment) and with an async version:

const child_process = require('child_process')

const child = child_process.spawn(
    'yarn',
    ['info', 'joi', '--json']
);

let stdout = '';
child.stdout.on('data', (d) => {
  stdout += d;
});

child.stdout.on('close', () => {
  try {
      const stdoutObject = JSON.parse(stdout)
      console.log('stdout is a valid JSON object.')
  } catch (err) {
      console.log('stdout is an invalid JSON object.')
      console.error(err.toString())
  }
});

By running the code with dtruss the child process only writes 8192 bytes. Later on it exits, so could it be an specific issue with yarn interoperating with node child_process module 🤷‍♂️ ?

Dtruss output. Parent Process PID: 31586 | Child PID: 31587:

31587/0x61cba:  write(0x1, "{\"type\":\"inspect\",\"data\":{\"name\":\"joi\",\"description\":\"Object schema validation\",\"dist-tags\":{\"latest\":\"10.4.1\",\"node-0.x\":\"6.10.1\",\"9-beta\":\"9.0.0-9\"},\"versions\":[\"0.0.1\",\"0.0.2\",\"0.0.3\",\"0.0.4\",\"0.0.5\",\"0.0.6-1\",\"0.0.6\",\"0.0.7\",\"0.0.8\",\"0.0.9\",\"0.0.10\",\"0", 0x2BD6)              = 8192 0
31586/0x61cac:  kevent(0x5, 0x7FFF5FBF6C30, 0x5)                 = 1 0
31586/0x61cac:  read(0xD, "{\"type\":\"inspect\",\"data\":{\"name\":\"joi\",\"description\":\"Object schema validation\",\"dist-tags\":{\"latest\":\"10.4.1\",\"node-0.x\":\"6.10.1\",\"9-beta\":\"9.0.0-9\"},\"versions\":[\"0.0.1\",\"0.0.2\",\"0.0.3\",\"0.0.4\",\"0.0.5\",\"0.0.6-1\",\"0.0.6\",\"0.0.7\",\"0.0.8\",\"0.0.9\",\"0.0.10\",\"0", 0x10000)              = 8192 0
31587/0x61cba:  open("/Users/sgimeno/Library/Caches/Yarn/.roadrunner.json\0", 0x1000601, 0x1B6)          = 14 0
31587/0x61cba:  mmap(0x187DABEB8000, 0x139000, 0x0, 0x1042, 0xFF000000, 0x0)             = 0x187DABEB8000 0
31587/0x61cba:  munmap(0x187DABEB8000, 0x48000)          = 0 0
31587/0x61cba:  munmap(0x187DABFB9000, 0x38000)          = 0 0
31587/0x61cba:  mmap(0x187DABF00000, 0xB9000, 0x3, 0x1012, 0xFF000000, 0x0)              = 0x187DABF00000 0
31587/0x61cba:  pwrite(0xE, "{\n  \"path\": {\n    \"{\\\"request\\\":\\\"../lib/cli/index.js\\\",\\\"paths\\\":[\\\"/Users/sgimeno/.nave/installed/7.10.0/lib/node_modules/yarn/bin\\\"]}\": \"/Users/sgimeno/.nave/installed/7.10.0/lib/node_modules/yarn/lib/cli/index.js\",\n    \"{\\\"request\\\":\\\"chalk\\\",\\\"paths\\\"", 0xB6166, 0x0)              = 745830 0
31587/0x61cba:  close(0xE)               = 0 0
31587/0x61cba:  psynch_cvsignal(0x101582D70, 0x390000003D00, 0x3900)             = 256 0
31587/0x61cc1:  psynch_cvwait(0x101582D70, 0x360000003A00, 0x3600)               = 0 0
31587/0x61cc1:  psynch_cvsignal(0x101582D70, 0x3A0000003D00, 0x3A00)             = 256 0
31587/0x61cc3:  psynch_cvwait(0x101582D70, 0x370000003B00, 0x3700)               = 0 0
31587/0x61cc1:  __disable_threadsignal(0x1, 0x3A0000003D00, 0x3A00)              = 0 0
31587/0x61cc3:  psynch_cvsignal(0x101582D70, 0x3B0000003D00, 0x3B00)             = 256 0
31587/0x61cc3:  __disable_threadsignal(0x1, 0x3B0000003D00, 0x3B00)              = 0 0
31587/0x61cc0:  psynch_cvwait(0x101582D70, 0x380000003C00, 0x3800)               = 0 0
31587/0x61cc0:  psynch_cvsignal(0x101582D70, 0x3C0000003D00, 0x3C00)             = 257 0
31587/0x61cc2:  psynch_cvwait(0x101582D70, 0x390000003D00, 0x3900)               = 0 0
31587/0x61cc0:  __disable_threadsignal(0x1, 0x3C0000003D00, 0x3C00)              = 0 0
31587/0x61cc2:  __disable_threadsignal(0x1, 0x390000003D00, 0x3900)              = 0 0
31587/0x61cba:  __semwait_signal(0x2407, 0x0, 0x0)               = 0 0
31587/0x61cba:  __semwait_signal(0x2703, 0x0, 0x0)               = 0 0
31587/0x61cba:  __semwait_signal(0x1D07, 0x0, 0x0)               = 0 0
31587/0x61cba:  __semwait_signal(0x2803, 0x0, 0x0)               = 0 0
31587/0x61cba:  psynch_cvwait(0x101582D70, 0x3D0100003E00, 0x3D00)               = -1 Err#316
...
31586/0x61cac:  wait4(0x7B63, 0x7FFF5FBF68BC, 0x1)               = 31587 0
```�

[addaleax]

31587/0x61cba: write(0x1, "…", 0x2BD6) = 8192 0

Okay, that’s curious. stdio should be blocking, so why doesn’t libuv write the rest of the 0x2bd6 bytes immediately after the first write()? Should write() even do that for blocking I/O?

Alternatively, does Node somehow mess up making FD 1 blocking, and consequently uv_try_write doesn’t write the whole block (16 kB is Node’s current limit for using try_write, and if OS X is the only platform where the buffer is smaller than that by default, it might explain platform-specific weirdness) and “forgets” to write the rest?

[vsemozhetbyt]

(It seems links to comments are broken in GitHub lately: hashes are stripped. I've reported to Github about the issue. Be careful)

[santigimeno]

The problem seems to be that stdout is non-blocking. From process.exit() documentation:

It is important to note that calling process.exit() will force the process to exit as quickly as possible even if there are still asynchronous operations pending that have not yet completed fully, including I/O operations to process.stdout and process.stderr.

This is a test case that reproduces the error:

const cp = require('child_process');

if (process.argv[2] === 'child') {
  console.log('g'.repeat(81933).toString());
  process.exit();
} else {
  const child = cp.spawn(process.execPath, [__filename, 'child']);
  child.stdout.pipe(process.stdout);
}

I guess yarn is calling process.exit() before waiting the data to be written out.