failed test: parallel/test-child-process-stdout-flush-exit

[jbergstroem]

I'm seeing a rare test fail (been able to reproduce twice over ~100 test runs) on a mac os x 10.10 machine. Tested with io.js 8a1e22a:

Path: parallel/test-child-process-stdout-flush-exit
assert.js:87
  throw new assert.AssertionError({
        ^
AssertionError: false == true
    at ChildProcess.<anonymous> (/Users/jbergstroem/io.js/test/parallel/test-child-process-stdout-flush-exit.js:43:5)
    at emitTwo (events.js:87:13)
    at ChildProcess.emit (events.js:169:7)
    at maybeClose (child_process.js:984:16)
    at Socket.<anonymous> (child_process.js:1153:11)
    at emitOne (events.js:77:13)
    at Socket.emit (events.js:166:7)
    at Pipe.close (net.js:464:12)
Command: out/Release/iojs /Users/jbergstroem/io.js/test/parallel/test-child-process-stdout-flush-exit.js

[jbergstroem]

Can't reproduce this any longer. Closing for now.

[Fishrock123]

There's something flaky going on here:

Jeremiahs-MacBook-Pro:io.js Jeremiah$ make test
/Applications/Xcode.app/Contents/Developer/usr/bin/make -C out BUILDTYPE=Release V=1
make[1]: Nothing to be done for `all'.
ln -fs out/Release/iojs iojs
/usr/bin/python tools/test.py --mode=release message parallel sequential -J
=== release test-child-process-stdout-flush-exit ===                      
Path: parallel/test-child-process-stdout-flush-exit
assert.js:87
  throw new assert.AssertionError({
        ^
AssertionError: false == true
    at ChildProcess.<anonymous> (/Users/Jeremiah/Documents/io.js/test/parallel/test-child-process-stdout-flush-exit.js:43:5)
    at emitTwo (events.js:87:13)
    at ChildProcess.emit (events.js:169:7)
    at maybeClose (child_process.js:984:16)
    at Socket.<anonymous> (child_process.js:1153:11)
    at emitOne (events.js:77:13)
    at Socket.emit (events.js:166:7)
    at Pipe.close (net.js:464:12)
Command: out/Release/iojs /Users/Jeremiah/Documents/io.js/test/parallel/test-child-process-stdout-flush-exit.js
[00:57|% 100|+ 818|-   1]: Done                                                
make: *** [test] Error 1

OS X 10.10.2, io.js at 78581c8, happened only once so far.

[piscisaureus]

@bnoordhuis Could this have something to do with stdout being asynchronous?

[tellnes]

I've also seen this on os x 10.9.5.

[bnoordhuis]

@piscisaureus That seems to be the issue, yes. The test failure is 100% reproducible when you add a delay in the parent process:

diff --git a/test/parallel/test-child-process-stdout-flush-exit.js b/test/parallel/test-child-process-stdout-flush-exit.js
index eba8927..5fbb1e9 100644
--- a/test/parallel/test-child-process-stdout-flush-exit.js
+++ b/test/parallel/test-child-process-stdout-flush-exit.js
@@ -17,6 +17,8 @@ if (process.argv[2] === 'child') {
   // spawn self as child
   var child = spawn(process.argv[0], [process.argv[1], 'child']);

+  for (var t = Date.now(); t + 1e3 > Date.now(););
+
   var gotHello = false;
   var gotBye = false;

It doesn't seem to be an issue of libuv buffering data and not getting a chance to flush it because even when all writes hit the kernel, the test still fails. I speculate that data ends up in the kernel pipe buffer and is subsequently lost when the child process exits.

[Fishrock123]

Also cropped up on the latest (otherwise green) windows build: https://jenkins-iojs.nodesource.com/job/iojs+any-pr+multi/359/nodes=iojs-win2012r2/console

[rvagg]

been a semi-regular offender on the Windows CI machines of late actually

[abrady0]

I'm seeing this 100% of the time when a child process outputs a large amount of text (>8k) and calls subprocess.exit().

here is a gist that repros: https://gist.github.com/abrady0/f69de07b79d1b50b0ca0

if you comment line 43 out it will succeed.

[Fishrock123]

Should be fixed in 311c3e4

[bnoordhuis]

Make that b926718.