How to get stdout and stderr unbuffered or at least in order from child_process

Question

Here's a simple node program: (note: this is just an example. substitute any program that outputs to both stdout and stderr and for which if the lines are out of order they won't be that useful, examples llvm, gcc, clang, less, grep, etc...)

const log = msg => console.log(`log: ${msg}`);
const error = msg => console.error(`error: ${msg}`);

log('line1');
error('line2');
log('line3');
error('line4');

If I run it I get this output:

log: line1
error: line2
log: line3
error: line4

Now I want the same output from child_process.execFile. The problem is the lines are buffered so they don't arrive to me in the same order:

const child_process = require('child_process');
const lines = [];
const ch = child_process.execFile(process.argv[0], ['main.js'], () => {
  console.log(lines.join(''));
});
ch.stdout.on('data', (data) => { lines.push(data); });
ch.stderr.on('data', (data) => { lines.push(data); });

produces:

log: line1
error: line2
error: line4
log: line3

As another example here's a bash script:

#!/bin/sh
echo line 1
echo line 2 >&2
echo line 3
echo line 4 >&2

and running it in a terminal the output is:

line 1
line 2
line 3
line 4

but running it via child_process:

const child_process = require('child_process');
const lines = [];
const ch = child_process.execFile('sh', ['test.sh'], () => {
  console.log(lines.join(''));
});
ch.stdout.on('data', (data) => { lines.push(data); });
ch.stderr.on('data', (data) => { lines.push(data); });

outputs:

line 1
line 3
line 2
line 4

How can I get the lines in the same order and also know which are from stdout and which are from stderr?

note, the docs says some conflicting things about buffering. On the one hand they say

By default, pipes for stdin, stdout, and stderr are established between the parent Node.js process and the spawned child. These pipes have limited (and platform-specific) capacity. If the child process writes to stdout in excess of that limit without the output being captured, the child process will block waiting for the pipe buffer to accept more data

But later they mention a setting, maxBuffer which says

maxBuffer Largest amount of data in bytes allowed on stdout or stderr. If exceeded, the child process is terminated and any output is truncated

Those 2 explanations seem in conflict. I thought maybe setting maxBuffer to 0 might be the solution but apparently it's not.

In any case though it's not clear how to unbuffer these streams.

spawn itself has an example in the docs but trying it

const child_process = require('child_process');
const lines = [];
const ch = child_process.spawn(process.argv[0], ['main.js']);

ch.stdout.on('data', (data) => {
  console.log(`stdout: ${data}`);
});

ch.stderr.on('data', (data) => {
  console.error(`stderr: ${data}`);
});

ch.on('close', (code) => {
  console.log(`child process exited with code ${code}`);
});

leads to the same results

stdout: log: line1

stderr: error: line2
error: line4

stdout: log: line3

child process exited with code 0

I suspect it has to do with making a Writeable stream and passing it in with spawn but it's not clear how to do that. I tried creating a Writeable and passing it in but node complained

internal/child_process.js:996
      throw new ERR_INVALID_OPT_VALUE('stdio', inspect(stdio));
      ^

TypeError [ERR_INVALID_OPT_VALUE]: The value "Writable {
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 0,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function: bound onwrite],
    writecb: null,
    writelen: 0,
    afterWriteTickInfo: null,
    bufferedRequest: null,
    lastBufferedRequest: null,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: false,
    bufferedRequestCount: 0,
    corkedRequestsFree: {
      next: null,
      entry: null,
      finish: [Function: bound onCorkedFinish]
    }
  },
  writable: true,
  _write: [Function: write],
  _events: [Object: null prototype] {},
  _eventsCount: 0,
  _maxListeners: undefined,
  [Symbol(kCapture)]: false
}" is invalid for option "stdio"

Any idea how to make a synchronous or at least correctly interleaved capture of of stdout and stderr when spawning a child process in node?

---

I think what I'm trying to do is apparently impossible. IIUC I need to pass in the same stream for both stdout and stderr to do keep them interleaved correctly and as soon as I do I lose the ability to tell where the output came from.

But, if nothing else I need to results immediately (unbuffered). Imagine I'm making a node based terminal and running commands, that output needs to make it back to me so I can show it (like a text based spinner) where as if it's buffered (which is what I see now) I'll only get the output in chucks.

Answer 1

I'm afraid that what you did

const child_process = require('child_process');
const lines = [];
const ch = child_process.execFile('sh', ['test.sh'], () => {
  console.log(lines.join(''));
});
ch.stdout.on('data', (data) => { lines.push(data); });
ch.stderr.on('data', (data) => { lines.push(data); });

is the maximum we can do. The problem with your test script

#!/bin/sh
echo line 1
echo line 2 >&2
echo line 3
echo line 4 >&2

is that the two strings "line 1\n" and "line 3\n" are written so quickly.

I mean: the data transfer from child to parent is handled by the OS which (probably) uses low level pipes or any other kind of buffer. Even if the child writes unbuffered to stdout what happen? The child writes "line 1\n", the OS buffers it somewhere and sends a signal to the parent, the signal rises the parent which finally needs to read; if during this time the child writes "line 3\n" as well, the OS has no other way than buffer it (with the previously written data) so when the parent finally reads the data has no way to know how many (unbuffered) writes were done to write it.

Answer 2

If modifying the actual child process is an option, you could force it to log synchronously by flushing after writing each line.

Example for main.js:

var logbuffer = require('log-buffer');

const log = msg => {
    console.log(`log: ${msg}`);
    logbuffer.flush();
}
const error = msg => {
    console.error(`error: ${msg}`);
    logbuffer.flush();
}

log('line1');
error('line2');
log('line3');
error('line4');

Otherwise, as stated in the Node.js documentation for Console, the console instance is configured to write to process.stdout and process.stderr. The synchronous/asynchronous behaviour of these is described in detail as follows: