You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
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
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.
child_process.createSocket creates the this.stdout socket, which kicks off a call to Socket.Readable.read.
echo completes, calling this._handle.onexit from internal/child_process.js.
The child process calls flushStdio, which calls flush() on this.stdout, setting its state.flowing to true.
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:
child_process.createSocket creates the this.stdout socket, which kicks off a call to Socket.Readable.read.
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.
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.
echo completes, calling this._handle.onexit from internal/child_process.js.
The child process calls flushStdio, but since stdout.readable is false, it doesn't call resume on it.
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?
Activity
cjihrig commentedon Dec 3, 2015
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 commentedon Dec 3, 2015
Also, cc: @davidvgalbraith
davidvgalbraith commentedon Dec 3, 2015
Shucks! I'll see what I can do for this tonight.
davidvgalbraith commentedon Dec 3, 2015
I still can't see the CI output, is it just the close event handler never getting called?
cjihrig commentedon Dec 3, 2015
Yes, here is the output:
davidvgalbraith commentedon Dec 3, 2015
I've been running
while :; do ./node test/parallel/test-child-process-flush-stdio.js ; donein 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 gotwhile :; 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 commentedon Dec 3, 2015
Looks pretty consistent on both centos5-64 and -32.
davidvgalbraith commentedon Dec 3, 2015
Yep, I have it failing 100% of the time on my centos5 VM. Let's see if I can fix it...
davidvgalbraith commentedon Dec 3, 2015
Ok, so here's the order of operations on my Mac:
child_process.createSocketcreates thethis.stdoutsocket, which kicks off a call toSocket.Readable.read.echocompletes, callingthis._handle.onexitfrominternal/child_process.js.flushStdio, which callsflush()onthis.stdout, setting itsstate.flowingto true.state.flowingis true inreadableAddChunk, emits the data and kicks off anotherreadwhich hits EOF. Innet.js'sonread, the conditionif (self._readableState.length === 0)prevails and the socket is destroyed, triggering thecloseevent and a successful test.And here's the order of operations on centos5:
child_process.createSocketcreates thethis.stdoutsocket, which kicks off a call toSocket.Readable.read.state.flowingisnullinreadableAddChunk, so it buffers the data and kicks off another read.onEofChunk, thanks to streams: update .readable/.writable to false #4083,stdout's.readableis set to false. Since we have buffered data, the stream does not close at this point.echocompletes, callingthis._handle.onexitfrominternal/child_process.js.flushStdio, but sincestdout.readableis false, it doesn't callresumeon it.stdoutsits 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.readableremains true afteronEofChunkis called. If I take out thestream.readable = false;line fromonEofChunk, the test passes on centos5 every time. Does that make sense?CC @mscdex
cjihrig commentedon Dec 4, 2015
@davidvgalbraith thank you for digging into this
stream: be less eager with readable flag
stream: be less eager with readable flag