Investigate flaky test-worker-init-failure

[Trott]

• Test: test-worker-init-failure
• Platform: macOS
• Console Output:

2020-06-05T18:48:01.6873370Z === release test-worker-init-failure ===
2020-06-05T18:48:01.6873870Z Path: parallel/test-worker-init-failure
2020-06-05T18:48:01.6874340Z --- stderr ---
2020-06-05T18:48:01.6874460Z assert.js:103
2020-06-05T18:48:01.6874620Z   throw new AssertionError(obj);
2020-06-05T18:48:01.6874720Z   ^
2020-06-05T18:48:01.6874780Z 
2020-06-05T18:48:01.6874950Z AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
2020-06-05T18:48:01.6875030Z 
2020-06-05T18:48:01.6875120Z 1 !== 0
2020-06-05T18:48:01.6875180Z 
2020-06-05T18:48:01.6875770Z     at ChildProcess.<anonymous> (/Users/runner/runners/2.263.0/work/node/node/test/parallel/test-worker-init-failure.js:64:12)
2020-06-05T18:48:01.6875930Z     at ChildProcess.<anonymous> (/Users/runner/runners/2.263.0/work/node/node/test/common/index.js:363:15)
2020-06-05T18:48:01.6876700Z     at ChildProcess.emit (events.js:315:20)
2020-06-05T18:48:01.6876820Z     at Process.ChildProcess._handle.onexit (internal/child_process.js:276:12) {
2020-06-05T18:48:01.6876940Z   generatedMessage: true,
2020-06-05T18:48:01.6877410Z   code: 'ERR_ASSERTION',
2020-06-05T18:48:01.6877530Z   actual: 1,
2020-06-05T18:48:01.6877630Z   expected: 0,
2020-06-05T18:48:01.6878040Z   operator: 'strictEqual'
2020-06-05T18:48:01.6878160Z }
2020-06-05T18:48:01.6878550Z --- stdout ---
2020-06-05T18:48:01.6878650Z child stdout: 
2020-06-05T18:48:01.6878710Z 
2020-06-05T18:48:01.6878810Z child stderr: assert.js:920
2020-06-05T18:48:01.6878910Z     throw err;
2020-06-05T18:48:01.6879000Z     ^
2020-06-05T18:48:01.6879060Z 
2020-06-05T18:48:01.6879170Z AssertionError [ERR_ASSERTION]: The input did not match the regular expression /EMFILE/. Input:
2020-06-05T18:48:01.6879230Z 
2020-06-05T18:48:01.6879660Z 'ENOENT: no such file or directory, uv_cwd'
2020-06-05T18:48:01.6879740Z 
2020-06-05T18:48:01.6880250Z     at Worker.<anonymous> (/Users/runner/runners/2.263.0/work/node/node/test/parallel/test-worker-init-failure.js:38:14)
2020-06-05T18:48:01.6880380Z     at Worker.emit (events.js:315:20)
2020-06-05T18:48:01.6880820Z     at Worker.[kOnErrorMessage] (internal/worker.js:235:10)
2020-06-05T18:48:01.6880990Z     at Worker.[kOnMessage] (internal/worker.js:245:37)
2020-06-05T18:48:01.6881140Z     at MessagePort.<anonymous> (internal/worker.js:166:57)
2020-06-05T18:48:01.6881260Z     at MessagePort.emit (events.js:315:20)
2020-06-05T18:48:01.6881460Z     at MessagePort.onmessage (internal/worker/io.js:80:8)
2020-06-05T18:48:01.6881580Z     at MessagePort.exports.emitMessage (internal/per_context/messageport.js:11:10)
2020-06-05T18:48:01.6881700Z     at Worker.[kOnExit] (internal/worker.js:217:5)
2020-06-05T18:48:01.6881810Z     at Worker.<computed>.onexit (internal/worker.js:163:20) {
2020-06-05T18:48:01.6881920Z   generatedMessage: true,
2020-06-05T18:48:01.6882380Z   code: 'ERR_ASSERTION',
2020-06-05T18:48:01.6882840Z   actual: 'ENOENT: no such file or directory, uv_cwd',
2020-06-05T18:48:01.6882960Z   expected: /EMFILE/,
2020-06-05T18:48:01.6883350Z   operator: 'match'
2020-06-05T18:48:01.6883460Z }
2020-06-05T18:48:01.6883950Z Command: out/Release/node /Users/runner/runners/2.263.0/work/node/node/test/parallel/test-worker-init-failure.js
2020-06-05T18:48:01.6884040Z 

• Build Links: https://pipelines.actions.githubusercontent.com/A76h8lUgAkJrcbixwhN7BUAsUydYrQl8Ux3JbU2S9vu9HqtlrL/_apis/pipelines/1/runs/31178/signedlogcontent/3?urlExpires=2020-06-05T18%3A50%3A01.4753944Z&urlSigningMethod=HMACV1&urlSignature=iuD1BKkUDgpJ0Q1%2FLAC3eULQYBZopJNd91Uu9NxmdMw%3D

[MylesBorins]

Seeing this flake a bunch locally while preparing a 14.x release

[Trott]

Happened in node-daily-master today.

https://ci.nodejs.org/job/node-test-commit-osx/35263/nodes=osx1015/console

00:25:58 not ok 2457 parallel/test-worker-init-failure
00:25:58   ---
00:25:58   duration_ms: 3.821
00:25:58   severity: fail
00:25:58   exitcode: 1
00:25:58   stack: |-
00:25:58     child stdout: 
00:25:58     
00:25:58     child stderr: assert.js:920
00:25:58         throw err;
00:25:58         ^
00:25:58     
00:25:58     AssertionError [ERR_ASSERTION]: The input did not match the regular expression /EMFILE/. Input:
00:25:58     
00:25:58     'ENOENT: no such file or directory, uv_cwd'
00:25:58     
00:25:58         at Worker.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:38:14)
00:25:58         at Worker.emit (events.js:314:20)
00:25:58         at Worker.[kOnErrorMessage] (internal/worker.js:238:10)
00:25:58         at Worker.[kOnMessage] (internal/worker.js:248:37)
00:25:58         at MessagePort.<anonymous> (internal/worker.js:167:57)
00:25:58         at MessagePort.emit (events.js:314:20)
00:25:58         at MessagePort.onmessage (internal/worker/io.js:80:8)
00:25:58         at MessagePort.exports.emitMessage (internal/per_context/messageport.js:11:10)
00:25:58         at Worker.[kOnExit] (internal/worker.js:220:5)
00:25:58         at Worker.<computed>.onexit (internal/worker.js:164:20) {
00:25:58       generatedMessage: true,
00:25:58       code: 'ERR_ASSERTION',
00:25:58       actual: 'ENOENT: no such file or directory, uv_cwd',
00:25:58       expected: /EMFILE/,
00:25:58       operator: 'match'
00:25:58     }
00:25:58     
00:25:58     
00:25:58     assert.js:103
00:25:58       throw new AssertionError(obj);
00:25:58       ^
00:25:58     
00:25:58     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
00:25:58     
00:25:58     1 !== 0
00:25:58     
00:25:58         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:64:12)
00:25:58         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/common/index.js:365:15)
00:25:58         at ChildProcess.emit (events.js:314:20)
00:25:58         at Process.ChildProcess._handle.onexit (internal/child_process.js:276:12) {
00:25:58       generatedMessage: true,
00:25:58       code: 'ERR_ASSERTION',
00:25:58       actual: 1,
00:25:58       expected: 0,
00:25:58       operator: 'strictEqual'
00:25:58     }
00:25:58   ...

[Trott]

cc @nodejs/workers @HarshithaKP

[addaleax]

I think this might be specific to macOS. If somebody can reproduce locally, I’m up for a joint debugging session.

[HarshithaKP]

I will try to reproduce it.

[MylesBorins]

@addaleax I can reproduce this somewhat reliably if you want to pair.

[Trott]

Showed up in node-daily-master again today.

https://ci.nodejs.org/job/node-test-commit-osx/35280/nodes=osx1015/console

01:33:40 not ok 2460 parallel/test-worker-init-failure
01:33:40   ---
01:33:40   duration_ms: 3.787
01:33:40   severity: fail
01:33:40   exitcode: 1
01:33:40   stack: |-
01:33:40     child stdout: 
01:33:40     
01:33:40     child stderr: assert.js:920
01:33:40         throw err;
01:33:40         ^
01:33:40     
01:33:40     AssertionError [ERR_ASSERTION]: The input did not match the regular expression /EMFILE/. Input:
01:33:40     
01:33:40     'ENOENT: no such file or directory, uv_cwd'
01:33:40     
01:33:40         at Worker.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:38:14)
01:33:40         at Worker.emit (events.js:314:20)
01:33:40         at Worker.[kOnErrorMessage] (internal/worker.js:238:10)
01:33:40         at Worker.[kOnMessage] (internal/worker.js:248:37)
01:33:40         at MessagePort.<anonymous> (internal/worker.js:167:57)
01:33:40         at MessagePort.emit (events.js:314:20)
01:33:40         at MessagePort.onmessage (internal/worker/io.js:80:8)
01:33:40         at MessagePort.exports.emitMessage (internal/per_context/messageport.js:11:10)
01:33:40         at Worker.[kOnExit] (internal/worker.js:220:5)
01:33:40         at Worker.<computed>.onexit (internal/worker.js:164:20) {
01:33:40       generatedMessage: true,
01:33:40       code: 'ERR_ASSERTION',
01:33:40       actual: 'ENOENT: no such file or directory, uv_cwd',
01:33:40       expected: /EMFILE/,
01:33:40       operator: 'match'
01:33:40     }
01:33:40     
01:33:40     
01:33:40     assert.js:103
01:33:40       throw new AssertionError(obj);
01:33:40       ^
01:33:40     
01:33:40     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
01:33:40     
01:33:40     1 !== 0
01:33:40     
01:33:40         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:64:12)
01:33:40         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/common/index.js:365:15)
01:33:40         at ChildProcess.emit (events.js:314:20)
01:33:40         at Process.ChildProcess._handle.onexit (internal/child_process.js:276:12) {
01:33:40       generatedMessage: true,
01:33:40       code: 'ERR_ASSERTION',
01:33:40       actual: 1,
01:33:40       expected: 0,
01:33:40       operator: 'strictEqual'
01:33:40     }
01:33:40   ...

[gireeshpunathil]

node/test/parallel/test-worker-init-failure.js

Lines 37 to 40 in bf0d82c

	worker.on('error', (e) => {
	assert.match(e.message, /EMFILE/);
	assert.ok(e.code === 'ERR_WORKER_INIT_FAILED' || e.code === 'EMFILE');
	});

I think the assumption that only EMFILE (too many open files) can occur in a ulimit -n setting is incorrect. Depending on where (early phase of process creation and setup versus runtime of the process) the inability to open new files occurs, the actual error code my differ.

• I don't know what control flow triggered ENOENT
• I don't know how many such places and errors exist

Accommodating this error code too in the assertion seems to a pragmatic approach?

[Trott]

Accommodating this error code too in the assertion seems to a pragmatic approach?

Accommodating a helpful ENOENT error message would indeed be pragmatic. Does 'ENOENT: no such file or directory, uv_cwd' qualify as sufficiently useful to the end user? uv_cwd is internal. It seems like the message is less than ideal. The test has this comment:

// Test that workers fail with meaningful error message
// when their initialization fails.

I'm conflicted about whether the right thing to do is to accommodate this error message or if the right thing to do is to try to improve it somehow.

[gireeshpunathil]

@Trott - agree, makes sense!

I think part of it has also to do with a limitation in libuv: it does not tell which file was missing. We had discussions on that in a different issue, but there wasn't any solution.

[gireeshpunathil]

Ref: #11520

[addaleax]

I would suggest that it’s worth figuring out why libuv is failing with this error, particularly because it’s OS-dependent.

@MylesBorins I’m available most of next week, maybe we can find some time then :)

[MylesBorins]

@addaleax next week is tough for me due to TC39. Ping me on chat and maybe we can work something out