test-cluster-master-{error,kill} fail only in weird CI environment

[drewfish]

• 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

[drewfish]

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:

diff --git a/test/parallel/test-cluster-master-error.js b/test/parallel/test-cluster-master-error.js
index ae0f655..16d63c1 100644
--- a/test/parallel/test-cluster-master-error.js
+++ b/test/parallel/test-cluster-master-error.js
@@ -2,21 +2,39 @@
 var common = require('../common');
 var assert = require('assert');
 var cluster = require('cluster');
+var fs = require('fs');
+
+// really wish we had `...values` syntax
+function log(strings){
+ var line = ['TEST-CLUSTER-MASTER-ERROR ', process.pid, ' '];
+ for (let i = 0; i < strings.length; i++){
+ line.push(strings[i]);
+ if (i+1 !== strings.length){
+ line.push(arguments[i+1]);
+ }
+ }
+ fs.appendFileSync(__dirname + '/../../artifacts/folta.log', line.join('') + '\n');
+}

 // Cluster setup
 if (cluster.isWorker){
+ log`WORKER started`;
 var http = require('http');
 http.Server(function(){

- }).listen(common.PORT, '127.0.0.1');
+ }).listen(common.PORT, '127.0.0.1', function(){
+ log`WORKER listening`;
+ });

 } else if (process.argv[2] === 'cluster'){
+ log`MASTER started`;

 var totalWorkers = 2;

 // Send PID to testcase process
 var forkNum = 0;
 cluster.on('fork', function forkEvent(worker){
+ log`MASTER on:fork ${worker.process.pid}`;

 // Send PID
 process.send({
@@ -26,6 +44,7 @@ if (cluster.isWorker){

 // Stop listening when done
 if (++forkNum === totalWorkers){
+ log`MASTER on:fork ${worker.process.pid} -- got totalWorkers`;
 cluster.removeListener('fork', forkEvent);
 }
 });
@@ -33,14 +52,17 @@ if (cluster.isWorker){
 // Throw accidently error when all workers are listening
 var listeningNum = 0;
 cluster.on('listening', function listeningEvent(){
+ log`MASTER on:listening`;

 // When all workers are listening
 if (++listeningNum === totalWorkers){
+ log`MASTER on:listening -- got totalWorkers`;
 // Stop listening
 cluster.removeListener('listening', listeningEvent);

 // throw accidently error
 process.nextTick(function(){
+ log`MASTER on:listening -- got totalWorkers -- about to throw`;
 console.error('about to throw');
 throw new Error('accidently error');
 });
@@ -52,7 +74,10 @@ if (cluster.isWorker){
 cluster.fork();
 cluster.fork();

+ log`MASTER done forking`;
 } else{
+ log`=================================================================`;
+ log`TEST started`;
 // This is the testcase

 var fork = require('child_process').fork;
@@ -62,8 +87,10 @@ if (cluster.isWorker){
 //this will throw an error if the process is dead
 process.kill(pid, 0);

+ log`TEST isAlive(${pid}) true`;
 return true;
 } catch (e){
+ log`TEST isAlive(${pid}) false -- ${e.message}`;
 return false;
 }
 };
@@ -82,12 +109,14 @@ if (cluster.isWorker){

 // Add worker pid to list and progress tracker
 if (data.cmd === 'worker'){
+ log`TEST on:message worker ${data.workerPID}`;
 workers.push(data.workerPID);
 }
 });

 // When cluster is dead
 master.on('exit', function(code){
+ log`TEST on:exit code=${code}`;

 // Check that the cluster died accidently
 existMaster = !!code;
@@ -101,6 +130,7 @@ if (cluster.isWorker){
 setTimeout(checkWorkers, timeout);

 function checkWorkers(){
+ log`TEST checkWorkers`;
 // When master is dead all workers should be dead to
 var alive = false;
 workers.forEach(function(pid){
@@ -110,15 +140,16 @@ if (cluster.isWorker){
 });

 // If a worker was alive this did not act as expected
- existWorker = !alive;
+ existWorker = alive;
 }
 });

 process.once('exit', function(){
+ log`TEST once:exit`;
 var m = 'The master did not die after an error was throwed';
 assert.ok(existMaster, m);
 m = 'The workers did not die after an error in the master';
- assert.ok(existWorker, m);
+ assert.ok(!existWorker, m);
 });

 }

With that, this is what I see in the build (where the test fails):

TEST-CLUSTER-MASTER-ERROR 10757 =================================================================
TEST-CLUSTER-MASTER-ERROR 10757 TEST started
TEST-CLUSTER-MASTER-ERROR 10762 MASTER started
TEST-CLUSTER-MASTER-ERROR 10762 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:fork 10767
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:fork 10772
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:fork 10772 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 10757 TEST on:message worker 10767
TEST-CLUSTER-MASTER-ERROR 10757 TEST on:message worker 10772
TEST-CLUSTER-MASTER-ERROR 10767 WORKER started
TEST-CLUSTER-MASTER-ERROR 10772 WORKER started
TEST-CLUSTER-MASTER-ERROR 10767 WORKER listening
TEST-CLUSTER-MASTER-ERROR 10772 WORKER listening
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:listening
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:listening
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 10762 MASTER on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 10757 TEST on:exit code=1
TEST-CLUSTER-MASTER-ERROR 10757 TEST checkWorkers
TEST-CLUSTER-MASTER-ERROR 10757 TEST isAlive(10767) true
TEST-CLUSTER-MASTER-ERROR 10757 TEST isAlive(10772) true
TEST-CLUSTER-MASTER-ERROR 10757 TEST once:exit

This is what I see when I run locally (where the test passes):

TEST-CLUSTER-MASTER-ERROR 7012 =================================================================
TEST-CLUSTER-MASTER-ERROR 7012 TEST started
TEST-CLUSTER-MASTER-ERROR 7017 MASTER started
TEST-CLUSTER-MASTER-ERROR 7017 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:fork 7022
TEST-CLUSTER-MASTER-ERROR 7012 TEST on:message worker 7022
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:fork 7027
TEST-CLUSTER-MASTER-ERROR 7012 TEST on:message worker 7027
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:fork 7027 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 7022 WORKER started
TEST-CLUSTER-MASTER-ERROR 7022 WORKER listening
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:listening
TEST-CLUSTER-MASTER-ERROR 7027 WORKER started
TEST-CLUSTER-MASTER-ERROR 7027 WORKER listening
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:listening
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 7017 MASTER on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 7012 TEST on:exit code=1
TEST-CLUSTER-MASTER-ERROR 7012 TEST checkWorkers
TEST-CLUSTER-MASTER-ERROR 7012 TEST isAlive(7022) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 7012 TEST isAlive(7027) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 7012 TEST once:exit

[Trott]

@nodejs/testing

[drewfish]

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]

@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]

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):

TEST-CLUSTER-MASTER-ERROR 10762 =================================================================
TEST-CLUSTER-MASTER-ERROR 10762 TEST started
TEST-CLUSTER-MASTER-ERROR 10767 MASTER started
TEST-CLUSTER-MASTER-ERROR 10767 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:fork 10772
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:fork 10777
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:fork 10777 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 10762 TEST master.on:message worker 10772
TEST-CLUSTER-MASTER-ERROR 10762 TEST master.on:message worker 10777
TEST-CLUSTER-MASTER-ERROR 10767 MASTER worker:10772.on:online
TEST-CLUSTER-MASTER-ERROR 10767 MASTER worker:10777.on:online
TEST-CLUSTER-MASTER-ERROR 10772 WORKER started
TEST-CLUSTER-MASTER-ERROR 10777 WORKER started
TEST-CLUSTER-MASTER-ERROR 10772 WORKER listening
TEST-CLUSTER-MASTER-ERROR 10777 WORKER listening
TEST-CLUSTER-MASTER-ERROR 10767 MASTER worker:10772.on:listening
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 10767 MASTER worker:10777.on:listening
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 10767 MASTER cluster.on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 10762 TEST master.on:exit code=1
TEST-CLUSTER-MASTER-ERROR 10772 WORKER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 10777 WORKER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 10762 TEST checkWorkers
TEST-CLUSTER-MASTER-ERROR 10762 TEST isAlive(10772) true
TEST-CLUSTER-MASTER-ERROR 10762 TEST isAlive(10777) true
TEST-CLUSTER-MASTER-ERROR 10762 TEST process.once:exit

This is what I see when I run locally (where the test passes):

TEST-CLUSTER-MASTER-ERROR 22253 =================================================================
TEST-CLUSTER-MASTER-ERROR 22253 TEST started
TEST-CLUSTER-MASTER-ERROR 22258 MASTER started
TEST-CLUSTER-MASTER-ERROR 22258 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:fork 22263
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:fork 22268
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:fork 22268 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 22253 TEST master.on:message worker 22263
TEST-CLUSTER-MASTER-ERROR 22253 TEST master.on:message worker 22268
TEST-CLUSTER-MASTER-ERROR 22258 MASTER worker:22263.on:online
TEST-CLUSTER-MASTER-ERROR 22258 MASTER worker:22268.on:online
TEST-CLUSTER-MASTER-ERROR 22263 WORKER started
TEST-CLUSTER-MASTER-ERROR 22268 WORKER started
TEST-CLUSTER-MASTER-ERROR 22263 WORKER listening
TEST-CLUSTER-MASTER-ERROR 22268 WORKER listening
TEST-CLUSTER-MASTER-ERROR 22258 MASTER worker:22263.on:listening
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 22258 MASTER worker:22268.on:listening
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 22258 MASTER cluster.on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 22253 TEST master.on:exit code=1
TEST-CLUSTER-MASTER-ERROR 22268 WORKER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 22263 WORKER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 22253 TEST checkWorkers
TEST-CLUSTER-MASTER-ERROR 22253 TEST isAlive(22263) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 22253 TEST isAlive(22268) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 22253 TEST process.once:exit

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]

@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?

diff --git a/test/parallel/test-cluster-master-error.js b/test/parallel/test-cluster-master-error.js
index ae0f655..82d1fc8 100644
--- a/test/parallel/test-cluster-master-error.js
+++ b/test/parallel/test-cluster-master-error.js
@@ -69,7 +69,6 @@ if (cluster.isWorker){
 };

 var existMaster = false;
- var existWorker = false;

 // List all workers
 var workers = [];
@@ -91,14 +90,12 @@ if (cluster.isWorker){

 // Check that the cluster died accidently
 existMaster = !!code;
+ });

- // Give the workers time to shut down
- var timeout = 200;
- if (common.isAix){
- // AIX needs more time due to default exit performance
- timeout = 1000;
- }
- setTimeout(checkWorkers, timeout);
+ process.once('exit', function(){
+ var existWorker = false;
+ var m = 'The master did not die after an error was throwed';
+ assert.ok(existMaster, m);

 function checkWorkers(){
 // When master is dead all workers should be dead to
@@ -112,11 +109,8 @@ if (cluster.isWorker){
 // If a worker was alive this did not act as expected
 existWorker = !alive;
 }
- });

- process.once('exit', function(){
- var m = 'The master did not die after an error was throwed';
- assert.ok(existMaster, m);
+ checkWorkers();
 m = 'The workers did not die after an error in the master';
 assert.ok(existWorker, m);
 });

[drewfish]

@santigimeno I tried that patch (plus the logging stuff). I'm still able to reproduce the test failure. Here's the log:

TEST-CLUSTER-MASTER-ERROR 10764 ======================================================================
TEST-CLUSTER-MASTER-ERROR 10764 TEST started
TEST-CLUSTER-MASTER-ERROR 10769 MASTER started
TEST-CLUSTER-MASTER-ERROR 10769 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:fork worker=10774
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:fork worker=10779
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:fork worker=10779 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 10764 TEST master.on:message worker=10774
TEST-CLUSTER-MASTER-ERROR 10764 TEST master.on:message worker=10779
TEST-CLUSTER-MASTER-ERROR 10769 MASTER worker:10774.on:online
TEST-CLUSTER-MASTER-ERROR 10769 MASTER worker:10779.on:online
TEST-CLUSTER-MASTER-ERROR 10774 WORKER started
TEST-CLUSTER-MASTER-ERROR 10779 WORKER started
TEST-CLUSTER-MASTER-ERROR 10774 WORKER listening
TEST-CLUSTER-MASTER-ERROR 10779 WORKER listening
TEST-CLUSTER-MASTER-ERROR 10769 MASTER worker:10774.on:listening
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 10769 MASTER worker:10779.on:listening
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 10769 MASTER cluster.on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 10764 TEST master.on:exit code=1
TEST-CLUSTER-MASTER-ERROR 10779 WORKER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 10774 WORKER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 10764 TEST process.once:exit code=0
TEST-CLUSTER-MASTER-ERROR 10764 TEST isAlive(10774) true
TEST-CLUSTER-MASTER-ERROR 10764 TEST isAlive(10779) true

[drewfish]

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:

function installHandlers(who) {
 process.on('error', (e) => { log`${who} process.on:error ${e}`; });
 process.on('uncaughtException', (e) => { log`${who} process.on:uncaughtException ${e}`; process.exit(20); });
 process.on('unhandledRejection', (reason, p) => { log`${who} process.on:unhandledRejection reason=${reason}`; process.exit(21); });
 process.on('exit', (code) => { log`${who} process.on:exit code=${code}`; });
 process.on('SIGPIPE', () => { log`${who} process.on:SIGPIPE`; });
 process.on('SIGCHLD', () => { log`${who} process.on:SIGCHLD`; });
 process.on('SIGTTIN', () => { log`${who} process.on:SIGTTIN`; });
 process.on('SIGTTOU', () => { log`${who} process.on:SIGTTOU`; });
 process.on('SIGTERM', () => { log`${who} process.on:SIGTERM`; process.exit(22); });
 process.on('SIGINT', () => { log`${who} process.on:SIGINT`; process.exit(23); });
 process.on('SIGHUP', () => { log`${who} process.on:SIGHUP`; process.exit(24); });
}

With that, here's what I get in the failing environment:

TEST-CLUSTER-MASTER-ERROR 43223 ======================================================================
TEST-CLUSTER-MASTER-ERROR 2 43223 TEST started
TEST-CLUSTER-MASTER-ERROR 62 43228 MASTER started
TEST-CLUSTER-MASTER-ERROR 71 43228 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 73 43228 MASTER cluster.on:fork worker=43233
TEST-CLUSTER-MASTER-ERROR 75 43228 MASTER cluster.on:fork worker=43238
TEST-CLUSTER-MASTER-ERROR 75 43228 MASTER cluster.on:fork worker=43238 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 75 43223 TEST master.on:message worker=43233
TEST-CLUSTER-MASTER-ERROR 76 43223 TEST master.on:message worker=43238
TEST-CLUSTER-MASTER-ERROR 105 43228 MASTER worker:43233.on:online
TEST-CLUSTER-MASTER-ERROR 124 43233 WORKER started
TEST-CLUSTER-MASTER-ERROR 128 43228 MASTER worker:43238.on:online
TEST-CLUSTER-MASTER-ERROR 144 43233 WORKER listening
TEST-CLUSTER-MASTER-ERROR 145 43228 MASTER worker:43233.on:listening
TEST-CLUSTER-MASTER-ERROR 145 43228 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 164 43238 WORKER started
TEST-CLUSTER-MASTER-ERROR 186 43238 WORKER listening
TEST-CLUSTER-MASTER-ERROR 187 43228 MASTER worker:43238.on:listening
TEST-CLUSTER-MASTER-ERROR 187 43228 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 187 43228 MASTER cluster.on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 187 43228 MASTER cluster.on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 190 43228 MASTER process.on:uncaughtException Error: accidently error
TEST-CLUSTER-MASTER-ERROR 191 43228 MASTER process.on:exit code=20
TEST-CLUSTER-MASTER-ERROR 194 43233 MASTER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 194 43238 MASTER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 194 43223 TEST master.on:exit code=20
TEST-CLUSTER-MASTER-ERROR 195 43223 TEST isAlive(43228) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 196 43223 TEST process.on:SIGCHLD
TEST-CLUSTER-MASTER-ERROR 199 43223 TEST process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 199 43223 TEST process.once:exit code=0
TEST-CLUSTER-MASTER-ERROR 199 43223 TEST isAlive(43233) true
TEST-CLUSTER-MASTER-ERROR 199 43223 TEST isAlive(43238) true
TEST-CLUSTER-MASTER-ERROR 200 43223 TEST process.on:uncaughtException AssertionError: The workers did not die after an error in the master

Here's what I get in the succeeding environment:

TEST-CLUSTER-MASTER-ERROR 971 ======================================================================
TEST-CLUSTER-MASTER-ERROR 2 971 TEST started
TEST-CLUSTER-MASTER-ERROR 99 976 MASTER started
TEST-CLUSTER-MASTER-ERROR 119 976 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 127 976 MASTER cluster.on:fork worker=981
TEST-CLUSTER-MASTER-ERROR 129 971 TEST master.on:message worker=981
TEST-CLUSTER-MASTER-ERROR 129 976 MASTER cluster.on:fork worker=984
TEST-CLUSTER-MASTER-ERROR 130 971 TEST master.on:message worker=984
TEST-CLUSTER-MASTER-ERROR 130 976 MASTER cluster.on:fork worker=984 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 183 976 MASTER worker:984.on:online
TEST-CLUSTER-MASTER-ERROR 188 976 MASTER worker:981.on:online
TEST-CLUSTER-MASTER-ERROR 212 984 WORKER started
TEST-CLUSTER-MASTER-ERROR 228 981 WORKER started
TEST-CLUSTER-MASTER-ERROR 243 984 WORKER listening
TEST-CLUSTER-MASTER-ERROR 244 976 MASTER worker:984.on:listening
TEST-CLUSTER-MASTER-ERROR 245 976 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 251 981 WORKER listening
TEST-CLUSTER-MASTER-ERROR 252 976 MASTER worker:981.on:listening
TEST-CLUSTER-MASTER-ERROR 253 976 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 253 976 MASTER cluster.on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 253 976 MASTER cluster.on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 259 976 MASTER process.on:uncaughtException Error: accidently error
TEST-CLUSTER-MASTER-ERROR 261 976 MASTER process.on:exit code=20
TEST-CLUSTER-MASTER-ERROR 265 981 MASTER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 268 984 MASTER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 268 971 TEST master.on:exit code=20
TEST-CLUSTER-MASTER-ERROR 269 971 TEST isAlive(976) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 271 971 TEST process.on:SIGCHLD
TEST-CLUSTER-MASTER-ERROR 277 971 TEST process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 277 971 TEST process.once:exit code=0
TEST-CLUSTER-MASTER-ERROR 277 971 TEST isAlive(981) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 278 971 TEST isAlive(984) false -- kill ESRCH

(The multiple MASTER process.on:exit is 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]

@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:

TEST-CLUSTER-MASTER-ERROR 49075 ======================================================================
TEST-CLUSTER-MASTER-ERROR 1 49075 TEST started
TEST-CLUSTER-MASTER-ERROR 99 49076 MASTER started
TEST-CLUSTER-MASTER-ERROR 107 49076 MASTER done forking
TEST-CLUSTER-MASTER-ERROR 108 49076 MASTER cluster.on:fork worker=49077
TEST-CLUSTER-MASTER-ERROR 108 49076 MASTER cluster.on:fork worker=49078
TEST-CLUSTER-MASTER-ERROR 109 49076 MASTER cluster.on:fork worker=49078 -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 109 49075 TEST master.on:message worker=49077
TEST-CLUSTER-MASTER-ERROR 110 49075 TEST master.on:message worker=49078
TEST-CLUSTER-MASTER-ERROR 182 49076 MASTER worker:49078.on:online
TEST-CLUSTER-MASTER-ERROR 184 49076 MASTER worker:49077.on:online
TEST-CLUSTER-MASTER-ERROR 196 49078 WORKER started
TEST-CLUSTER-MASTER-ERROR 198 49077 WORKER started
TEST-CLUSTER-MASTER-ERROR 213 49078 WORKER listening
TEST-CLUSTER-MASTER-ERROR 213 49077 WORKER listening
TEST-CLUSTER-MASTER-ERROR 213 49076 MASTER worker:49078.on:listening
TEST-CLUSTER-MASTER-ERROR 214 49076 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 214 49076 MASTER worker:49077.on:listening
TEST-CLUSTER-MASTER-ERROR 214 49076 MASTER cluster.on:listening
TEST-CLUSTER-MASTER-ERROR 214 49076 MASTER cluster.on:listening -- got totalWorkers
TEST-CLUSTER-MASTER-ERROR 214 49076 MASTER cluster.on:listening -- got totalWorkers -- about to throw
TEST-CLUSTER-MASTER-ERROR 216 49076 MASTER process.on:uncaughtException Error: accidently error
TEST-CLUSTER-MASTER-ERROR 216 49076 MASTER process.on:exit code=20
TEST-CLUSTER-MASTER-ERROR 219 49077 MASTER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 219 49078 MASTER process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 219 49075 TEST master.on:exit code=20
TEST-CLUSTER-MASTER-ERROR 219 49075 TEST isAlive(49076) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 220 49075 TEST process.on:SIGCHLD
TEST-CLUSTER-MASTER-ERROR 223 49075 TEST process.on:exit code=0
TEST-CLUSTER-MASTER-ERROR 223 49075 TEST process.once:exit code=0
TEST-CLUSTER-MASTER-ERROR 224 49075 TEST isAlive(49077) false -- kill ESRCH
TEST-CLUSTER-MASTER-ERROR 224 49075 TEST isAlive(49078) false -- kill ESRCH

[drewfish]

Hmm... worker.process.once('exit') seems to be tunneling the event to work.emit('exit') but not worker.process.emit('exit'):
https://github.com/nodejs/node/blob/v4.x/lib/cluster.js#L347-L362
Nevermind, thinking about it it shouldn't.

[santigimeno]

@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 checkWorkers timeout?

[drewfish]

I had bumped up the timeout to 10 seconds but I was still seeing the failure.

[drewfish]

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.