Output data lost from spawned process if process ends before all data read

[IanCollins]

• Version: v6.9.1
• Platform: Linux bld-1604 4.3.0 BrandZ virtual linux x86_64 x86_64 x86_64 GNU/Linux (Ubuntu 16.04)
• Subsystem: child_process

We have a gulp build step that converts a protobuf file to JSON using a tool 'pbjs'. We are seeing a truncated output file. This problem only appears on Linux, Windows builds aren't affected.

The conversion is called thus:

gulp.task('create-proto-json', ['prepare-proto-sources'], function () {
    var pbjs_cmd = path.resolve('node_modules/protobufjs/bin/pbjs');
    return gulp.src(targetFolder + 'proto-xxx.proto')
        .pipe(exec('node "' + pbjs_cmd + '" ' + path.normalize(targetFolder + 'proto-xxx.proto') + ' --target=json', { pipeStdout: true, maxBuffer: 1000000 }))
        .pipe(rename({extname: '.json'}))
        .pipe(gulp.dest(targetFolder));
});

The conversion generates over 800K of output, but only 219K are written to the output file. Running strace on the command give some hint:

[pid  2112]      0.002595 write(1, "{\n    \"package\": \"com.xxx\",\n   "..., 816819 <unfinished ...>
[pid  2095]      0.000396 <... epoll_wait resumed> [{EPOLLIN, {u32=14, u64=14}}], 1024, -1) = 1
[pid  2112]      0.000043 <... write resumed> ) = 219264
[pid  2095]      0.000090 read(14,  <unfinished ...>
[pid  2112]      0.000123 write(2, " \n", 2 <unfinished ...>

Changing exec to spawn and logging the stdout reads showed 3 64K reads and one 22K read before the stream closed:

var json = spawn(pbjs_cmd, [path.normalize(targetFolder + 'proto-xxx.proto'), '--target=json']);
json.stdout.on('data', function(data) { file.write(data); console.log(data.length);});
json.stdout.on('end', function(data)  { file.end(); console.log('End'); });
json.stderr.on('data', function(data) { console.log(data.toString()); });
json.on('exit', function(code) { console.log('Exit: ' + code ); });

 Processing: app/generated/proto/proto-xxx.proto ...
 
65536
65536
65536
22656

 pbjs OK Converted 1 source files to json (816819 bytes, 125 ms)

End
Exit: 0

If I simply use child_process.spawnSync and use the pbjs file output option rather than reading from stdin, the correct output is produced.

[mscdex]

FWIW you should almost always use the 'close' event instead of 'exit' since the former is emitted both when the process has exited and no more data will be available on either the stdout or stderr streams.

I can't really comment about exec() since that does not seem to be child_process.exec(), but some third-party module function instead.

[IanCollins]

exec is from gulp-exec.

If I change my test case to use json.on('close') I see the same truncated output (the same 4 reads).

[bnoordhuis]

I'll take a look if you can post a standalone (non-gulp) test case.

[sam-github]

Make very sure that the child process never explicitly exits with process.exit, that can terminate before output drains from the event loop.

[IanCollins]

Re process.exit: node_modules/protobufjs/bin/pbjs is

#!/usr/bin/env node
process.exit(require(__dirname+"/../cli/pbjs.js").main(process.argv));

[sam-github]

That isn't safe, not unless .main() can guarantee it has flushed all output, which it can't, since its called synchronously, and I/O is async in node.

https://github.com/dcodeIO/protobuf.js/blob/master/cli/pbjs.js#L61-L63 is buggy, too, it is writing code to a stream, then exiting before the stream has flushed.

This doesn't look like a node bug.

[IanCollins]

Interesting, thanks.

I wonder why the problem doesn't show on Windows?

[sam-github]

Linux and windows are sync/async differently on stdout, also, they have different buffer sizes and scheduling algorithms.

[Trott]

This issue has been inactive for sufficiently long that it seems like perhaps it should be closed. Feel free to re-open (or leave a comment requesting that it be re-opened) if you disagree. I'm just tidying up and not acting on a super-strong opinion or anything like that.