flaky test: test-child-process-flush-stdio

[jbergstroem]

• https://ci.nodejs.org/job/node-test-commit-linux/1378/nodes=centos5-32/
• https://ci.nodejs.org/job/node-test-commit-linux/1379/nodes=centos5-64/

[cjihrig]

This test was just changed in 34b535f. Either the commit will have to be reverted, or the test is flakey.

EDIT: Obviously the test is flakey. I meant it might be possible that only the test needs to be updated.

[cjihrig]

Also, cc: @davidvgalbraith

[davidvgalbraith]

Shucks! I'll see what I can do for this tonight.

[davidvgalbraith]

I still can't see the CI output, is it just the close event handler never getting called?

[cjihrig]

Yes, here is the output:

not ok 36 test-child-process-flush-stdio.js
# Mismatched <anonymous> function calls. Expected 1, actual 0.
# at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-64/test/parallel/test-child-process-flush-stdio.js:8:22)
# at Module._compile (module.js:399:26)
# at Object.Module._extensions..js (module.js:406:10)
# at Module.load (module.js:345:32)
# at Function.Module._load (module.js:302:12)
# at Function.Module.runMain (module.js:431:10)
# at startup (node.js:138:18)
# at node.js:976:3

[davidvgalbraith]

I've been running while :; do ./node test/parallel/test-child-process-flush-stdio.js ; done in three parallel terminals on my Mac for the last 2 hours, which adds up to tens of thousands of runs, and every one has passed. In another terminal, I've got while :; do /usr/bin/python tools/test.py --mode=release parallel -J; done; running to see if there's some interplay between tests that breaks it, and that's gone 30 runs without the test in question failing.

I notice that the failed tests happened on centos5, so I'm thinking there's some platform compatibility issue at play here. Currently building Node on a centos5 VM, when that finishes up I'll run similar testing and report back.

[jbergstroem]

Looks pretty consistent on both centos5-64 and -32.

[davidvgalbraith]

Yep, I have it failing 100% of the time on my centos5 VM. Let's see if I can fix it...

[davidvgalbraith]

Ok, so here's the order of operations on my Mac:

1. child_process.createSocket creates the this.stdout socket, which kicks off a call to Socket.Readable.read.
2. echo completes, calling this._handle.onexit from internal/child_process.js.
3. The child process calls flushStdio, which calls flush() on this.stdout, setting its state.flowing to true.
4. The read from step 1 finishes at this point, sees that state.flowing is true in readableAddChunk, emits the data and kicks off another read which hits EOF. In net.js's onread, the condition if (self._readableState.length === 0) prevails and the socket is destroyed, triggering the close event and a successful test.

And here's the order of operations on centos5:

1. child_process.createSocket creates the this.stdout socket, which kicks off a call to Socket.Readable.read.
2. The read from step 1 finishes at this point and sees that state.flowing is null in readableAddChunk, so it buffers the data and kicks off another read.
3. The read from step 2 finishes and gets EOF. In ChildProcess's onEofChunk, thanks to streams: update .readable/.writable to false #4083, stdout's .readable is set to false. Since we have buffered data, the stream does not close at this point.
4. echo completes, calling this._handle.onexit from internal/child_process.js.
5. The child process calls flushStdio, but since stdout.readable is false, it doesn't call resume on it.
6. That's all! stdout sits never closes, so the ChildProcess never closes and the test fails.

My 100% Mac pass rates were on a branch that didn't have #4083; pulling in that commit, I get a ~1% fail rate. On centos5 it fails every time.

So my view is that #4083 was a little hasty and didn't account for ChildProcess's expectation that stream.readable remains true after onEofChunk is called. If I take out the stream.readable = false; line from onEofChunk, the test passes on centos5 every time. Does that make sense?

CC @mscdex

[cjihrig]

@davidvgalbraith thank you for digging into this