Repository navigation
test-cluster-master-{error,kill} fail only in weird CI environment #6193
Description
- Version: 4.4.3
- Platform: some rhel 6
- Subsystem: cluster
We build 4.x for use internally in the company, using a Jenkins job which creates a docker image in which the actual build and tests are run. Very oddly, test-cluster-master-error and test-cluster-master-kill fail every build. I've not been able to reproduce this in any other environment, even running the same docker image on my macbook.
Here is the output of the two failing tests:
00:30:43.898 not ok 97 test-cluster-master-error.js
00:30:43.898 #
00:30:43.898 # assert.js:90
00:30:43.898 # throw new assert.AssertionError({
00:30:43.899 # ^
00:30:43.899 # AssertionError: The workers did not die after an error in the master
00:30:43.899 # at process.<anonymous> (/var/builds/workspace/105338-v3-component/BUILD_CONTAINER/rhel6/label/DOCKER-LOW/app_root/test/parallel/test-cluster-master-error.js:152:12)
00:30:43.899 # at process.g (events.js:260:16)
00:30:43.900 # at emitOne (events.js:82:20)
00:30:43.900 # at process.emit (events.js:169:7)
00:30:43.900 ---
00:30:43.900 duration_ms: 0.710
00:30:43.900 ...
00:30:45.613 not ok 98 test-cluster-master-kill.js
00:30:45.613 #
00:30:45.613 # assert.js:90
00:30:45.613 # throw new assert.AssertionError({
00:30:45.614 # ^
00:30:45.614 # AssertionError: worker was alive after master died
00:30:45.614 # at process.<anonymous> (/var/builds/workspace/105338-v3-component/BUILD_CONTAINER/rhel6/label/DOCKER-LOW/app_root/test/parallel/test-cluster-master-kill.js:79:12)
00:30:45.614 # at process.g (events.js:260:16)
00:30:45.614 # at emitOne (events.js:82:20)
00:30:45.614 # at process.emit (events.js:169:7)
00:30:45.615 ---
00:30:45.615 duration_ms: 1.712
00:30:45.615 ...
The tests were run via:
export NODE_COMMON_PORT=16733
export NODE_TEST_DIR=/tmp/screwdriver
scl enable devtoolset-4 python27 -- gmake CFLAGS=-m64 LDFLAGS=-Wl,-rpath,/home/y/lib64 test-ci
Activity
drewfish commentedon Apr 14, 2016
Given that I can only reproduce this in our CI build, I've started checking in experimental changes just to see how they fair.
Here's an experiment which just adds logging:
With that, this is what I see in the build (where the test fails):
This is what I see when I run locally (where the test passes):
Trott commentedon Apr 14, 2016
@nodejs/testing
drewfish commentedon Apr 14, 2016
Odd... I just ran the same test on my macbook using off-the-shelf v4.4.3 and got a log of events very similar to the CI log above, except isAlive() returned false and the test passed. I suspect I'll have to do some deeper logging, perhaps adding additional listeners in the test or adding logging in the lib/cluster.js itself.
Trott commentedon Apr 14, 2016
@nodejs/docker Not sure that Docker is a factor here, but not sure it isn't. Maybe it's something those folks have seen?
drewfish commentedon Apr 14, 2016
Curious. I updated the logging to (a) specify which event listener is emitting the events, and (b) add listeners for a bunch more stuff.
With that, this is what I see in the build (where the test fails):
This is what I see when I run locally (where the test passes):
In both environments, the worker
process.on('exit')happen before checkWorkers. Oddly, isAlive() is still showing true in the failing environment.I think the next thing to check is the actual timing. Is the checkWorkers happening so quickly after the worker process.on(exit) that the process hasn't actually died yet? Is there something else that is causing the worker processes to hang around after that event?
santigimeno commentedon Apr 14, 2016
@drewfish I've been able to reproduce the error in
test-cluster-master-error.js, can you check if this patch fixes the test for you?drewfish commentedon Apr 14, 2016
@santigimeno I tried that patch (plus the logging stuff). I'm still able to reproduce the test failure. Here's the log:
drewfish commentedon Apr 15, 2016
Uggg.. no new insights, just more weirdness. I added timestamps and listeners for many events. The most interesting change is calling this in each process:
With that, here's what I get in the failing environment:
Here's what I get in the succeeding environment:
(The multiple
MASTER process.on:exitis confusing. I'm only registering one process.on('exit') handler in the master which appears to be called three times. Not sure if this behavior is related to the leaking child processes, but probably isn't because it's consistent across the passing and failing environments.)drewfish commentedon Apr 15, 2016
@bengl suggested I try the same test on 0.12. Here's the same test code (with new language features downgraded) run on 0.12.13:
drewfish commentedon Apr 15, 2016
Hmm... worker.process.once('exit') seems to be tunneling the event to work.emit('exit') but not worker.process.emit('exit'):
Nevermind, thinking about it it shouldn't.https://github.com/nodejs/node/blob/v4.x/lib/cluster.js#L347-L362
santigimeno commentedon Apr 19, 2016
@drewfish I've been able to reproduce the error more or less consistently by increasing the number of workers. I think the problem might be that sometimes the workers are not dying immediately (at least not in the 200ms after the master dies. Code here: https://github.com/nodejs/node/blob/v4.x/lib/cluster.js#L534-L540). Have you tried increasing the
checkWorkerstimeout?drewfish commentedon Apr 20, 2016
I had bumped up the timeout to 10 seconds but I was still seeing the failure.
drewfish commentedon Apr 20, 2016
Yeah, I just added back a setInterval() and had it checkWorkers() every second and after 10 seconds all children were still alive.
I think I'm going to have to wire some logging into lib/cluster and start looking at what's going on there.
drewfish commentedon Apr 27, 2016
Rats. I just ran a build on 6.0.0 (w/out any custom modifications) and saw the same failures:
ncopa commentedon May 4, 2016
You mentioned it happens in docker?
If the master dies before the workers, then will the workers become orphans and it will be the job of init (pid 1) to reap the exited worker process. (that is what takes 200ms). If you run it in docker, then there will the pid 1 not be an
initwhich is designed to clean up orphans, so the workers ends up as zombies.The point is: something needs to reap the workers, using
wait(2)orwaitpid(2). Ideally, the master process should stay til all workers have exited and only after that it can exit, but to my understanding there are no API for that in node.Try run tini as first process in your container and see if that helps.
EDIT: fix spelling of
tinistefanmb commentedon May 4, 2016
@ncopa Thanks for pointing out the init issue! I wasn't aware of this limitation in Docker, but it seems there has already been some discussion on this topic in nodejs/build-containers#19, @drewfish maybe the workaround mentioned there ("my_init" script) can resolve your issue.
drewfish commentedon May 5, 2016
Yeah, this smells about right, thanks @ncopa! I'll give it a try (either tini or some other reaper).
Trott commentedon May 11, 2016
@drewfish Is this issue resolved? Or not exactly?
cjihrig commentedon Jun 1, 2016
ping @drewfish. Can this be closed?
bengl commentedon Jun 1, 2016
I built upon the work of @drewfish internally and found that, indeed, it's a custom
initof ours that isn't correctly reaping workers.Thanks @ncopa for pointing us in that direction! Closing this now, as we'll resolve it internally.
cjihrig commentedon Jun 2, 2016
Awesome. Thanks for following up @bengl