Not receiving stdout from nodejs spawned process

Question

I'm trying to have nodejs interact with adventure, an old text based game. The idea is to open adventure as a child process and then play the game by writing to its stdin and placing an event listener on stdout.

When the game starts, it prints an initial:

Welcome to Adventure!! Would you like instructions?

So to illustrate my problem, I have a nodejs+express instance with:

var childProcess = require('child_process');
var spawn = childProcess.spawn;
var child = spawn('adventure');

console.log("spawned: " + child.pid);

child.stdout.on('data', function(data) {
  console.log("Child data: " + data);
});
child.on('error', function () {
  console.log("Failed to start child.");
});
child.on('close', function (code) {
  console.log('Child process exited with code ' + code);
});
child.stdout.on('end', function () {
  console.log('Finished collecting data chunks.');
});

But when I start the server, the text from the game doesn't reach the event listener:

spawned: 24250

That's all the output I get. The child.stdout.on even listener is never called. Why isn't that initial line from the game being picked up?

If I append the following line to the above block of javascript, then the program output appears at once. So adventure runs, and I can now force it to trigger the child.stdout.on event listener... but this also ends the child process, which defeats the purpose of reading and writing to it.

...
child.stdout.on('end', function () {
  console.log('Finished collecting data chunks.');
});
child.stdin.end();

Now the output is:

spawned: 28778  
Child data:
Welcome to Adventure!!  Would you like instructions?
user closed input stream, quitting...

Finished collecting data chunks.
Child process exited with code 0

I'm sure its a trivial oversight on my part, I appreciate any help figuring this out though.

Luting

Answer 1

After going through the Nodejs documentation a few more times, I convinced myself I was either missing something pretty big, or the spawn command wasn't working correctly. So I created a github issue.

And the answer was immediately posted: the child process can't buffer output if you want fast access.

So to achieve what I was originally looking for:

var childProcess = require('child_process');
var spawn = childProcess.spawn;
var child = spawn('unbuffer', 'adventure');

console.log("spawned: " + child.pid);

child.stdout.on('data', function(data) {
  console.log("Child data: " + data);
});
child.on('error', function () {
  console.log("Failed to start child.");
});
child.on('close', function (code) {
  console.log('Child process exited with code ' + code);
});
child.stdout.on('end', function () {
  console.log('Finished collecting data chunks.');
});

With the functional difference being the use of unbuffer, a command that disables output buffering.

Luting

In my case I do not have unbuffer command on my system, but {shell: true} option for options parameter of spawn produced the output. Also there is stdbuf command on Linux to control buffering, but it does not change anything in my case. (I was spawning java compiler from openjdk package.) – Isaisaac

Answer 2

Why isn't that initial line from the game being picked up?

I had the same problem on a project that called a compiled C++ program from node.js. I realized the problem was in the compiled C++ program: I wasn't flushing the stdout stream. Adding fflush(stdout); after printing a line solved the issue. Hopefully you still have access to the source of the game!

Kiyokokiyoshi

It turned out the buffering was taking place on the node.js side, but buffering was the root issue. Thank you for taking the time to answer. – Luting

Answer 3

The data passed is a buffer type, not a string. Therefore, you need a decoder to read that buffer and then do the logging.

Here's how to do that.

var StringDecoder = require('string_decoder').StringDecoder;
var decoder = new StringDecoder('utf8');

child.stdout.on('data', function (data) {
    var message = decoder.write(data);
    console.log(message.trim());
});

Chingchinghai

Thank you for the tip on getting usable output from data. My problem is that child.stdout.on() is never called in the first place, though I know the sub process is writing output. This is the case even if the contents is only console.log("Something received from child"); and doesn't deal with data at all. – Luting

What happens if you open a blank terminal and type adventure? Does it print something? I'm curious whether node successfully launched adventure or not. Also try using absolute path. – Chingchinghai

The quoted text in the question "Welcome to Adventure..." is printed immediately after adventure is launched. I have nodejs print the PID so that I can check, and adventure is indeed running. I'll go ahead and add an absolute path to the program name, that strikes me as a good idea. – Luting

Because if adventure is not in your path, then launching it as spawn('adventure') would fail – Chingchinghai

@user528315 - In my case, I'm not able to go inside child.stdout.on(...){ ... } section. What could be the problem. The control goes to 'exit' though and I'm able to get the exit code as 0 (success). I'm just calling a shell script which only echoes "Pass" just one line. – Circumfluent