Node: Investigate flaky test-worker-init-failure

Created on 5 Jun 2020 · 23Comments · Source: nodejs/node

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

CI / flaky test macos

Source

Trott

Most helpful comment

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.

Trott on 17 Jul 2020

👍2

All 23 comments

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

MylesBorins on 14 Jul 2020

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 on 15 Jul 2020

cc @nodejs/workers @HarshithaKP

Trott on 15 Jul 2020

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

addaleax on 15 Jul 2020

👍1

I will try to reproduce it.

HarshithaKP on 15 Jul 2020

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

MylesBorins on 16 Jul 2020

🎉1

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   ...

Trott on 16 Jul 2020

https://github.com/nodejs/node/blob/bf0d82c1024710e13c9f2140cac2ed5acb273faf/test/parallel/test-worker-init-failure.js#L37-L40

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?

gireeshpunathil on 17 Jul 2020

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

// 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.

Trott on 17 Jul 2020

👍2

@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 on 17 Jul 2020

👍1

Ref: https://github.com/nodejs/node/issues/11520

gireeshpunathil on 17 Jul 2020

👍1

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

addaleax on 17 Jul 2020

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

MylesBorins on 17 Jul 2020

Happened in node-daily-master again.

https://ci.nodejs.org/job/node-test-commit-osx/35435/nodes=osx1015/console
Host: test-orka-macos10.15-x64-2

00:22:37 ok 2460 parallel/test-worker-message-channel-sharedarraybuffer
00:22:37   ---
00:22:37   duration_ms: 1.968
00:22:37   ...
00:22:38 not ok 2461 parallel/test-worker-init-failure
00:22:38   ---
00:22:38   duration_ms: 2.955
00:22:38   severity: fail
00:22:38   exitcode: 1
00:22:38   stack: |-
00:22:38     child stdout: 
00:22:38     
00:22:38     child stderr: events.js:291
00:22:38           throw er; // Unhandled 'error' event
00:22:38           ^
00:22:38     
00:22:38     AssertionError [ERR_ASSERTION]: The input did not match the regular expression /EMFILE/. Input:
00:22:38     
00:22:38     'ENOENT: no such file or directory, uv_cwd'
00:22:38     
00:22:38         at Worker.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:38:14)
00:22:38         at Worker.emit (events.js:314:20)
00:22:38         at Worker.[kOnErrorMessage] (internal/worker.js:238:10)
00:22:38         at Worker.[kOnMessage] (internal/worker.js:248:37)
00:22:38         at MessagePort.<anonymous> (internal/worker.js:167:57)
00:22:38         at MessagePort.[nodejs.internal.kHybridDispatch] (internal/event_target.js:352:41)
00:22:38         at MessagePort.exports.emitMessage (internal/per_context/messageport.js:18:26)
00:22:38         at Worker.[kOnExit] (internal/worker.js:220:5)
00:22:38         at Worker.<computed>.onexit (internal/worker.js:164:20)
00:22:38     Emitted 'error' event on process instance at:
00:22:38         at emitUnhandledRejectionOrErr (internal/event_target.js:541:11)
00:22:38         at MessagePort.[nodejs.internal.kHybridDispatch] (internal/event_target.js:356:9)
00:22:38         at MessagePort.exports.emitMessage (internal/per_context/messageport.js:18:26)
00:22:38         at Worker.[kOnExit] (internal/worker.js:220:5)
00:22:38         at Worker.<computed>.onexit (internal/worker.js:164:20) {
00:22:38       generatedMessage: true,
00:22:38       code: 'ERR_ASSERTION',
00:22:38       actual: 'ENOENT: no such file or directory, uv_cwd',
00:22:38       expected: /EMFILE/,
00:22:38       operator: 'match'
00:22:38     }
00:22:38     
00:22:38     
00:22:38     assert.js:103
00:22:38       throw new AssertionError(obj);
00:22:38       ^
00:22:38     
00:22:38     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
00:22:38     
00:22:38     1 !== 0
00:22:38     
00:22:38         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:64:12)
00:22:38         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/common/index.js:365:15)
00:22:38         at ChildProcess.emit (events.js:314:20)
00:22:38         at Process.ChildProcess._handle.onexit (internal/child_process.js:276:12) {
00:22:38       generatedMessage: true,
00:22:38       code: 'ERR_ASSERTION',
00:22:38       actual: 1,
00:22:38       expected: 0,
00:22:38       operator: 'strictEqual'
00:22:38     }
00:22:38   ...

Hopefully @addaleax and @MylesBorins can pair to debug this soon, and if not (or even if so) maybe someone on @nodejs/platform-macos is able to reproduce and/or debug.

Trott on 25 Jul 2020

other than the API call (process.chdir), the ony other place where uv_cwd can be called (in default control path) is here: https://github.com/nodejs/node/blob/c61b388c29dc73ef3c94aef0f790e012683d24ef/src/inspector_profiler.cc#L400

though I am unable to reproduce this, I will see if this line is relevant for the test, and possible reasons for this to fail

gireeshpunathil on 25 Jul 2020

other than the API call (process.chdir), the ony other place where uv_cwd can be called (in default control path) is here:

I’m assuming you mean process.cwd(), not process.chdir(), which is something that could potentially be called during startup.

addaleax on 25 Jul 2020

yes, process.cwd.

gireeshpunathil on 25 Jul 2020

this is the definite path that leads upto uv_cwd at startup, in this test:

    at process.wrappedCwd [as cwd] (internal/bootstrap/switches/does_own_process_state.js:128:3)
    at Object.resolve (path.js:978:47)
    at patchProcessObject (internal/bootstrap/pre_execution.js:101:28)
    at prepareMainThreadExecution (internal/bootstrap/pre_execution.js:25:3)
    at internal/main/run_main_module.js:7:1

and uv_cwd calls getcwd syscall which contain these kernel primitives:

85814/0x4cc3f2:  open_nocancel(".\0", 0x0, 0x1)      = 3 0
85814/0x4cc3f2:  fstat64(0x3, 0x7FFEE75254E0, 0x0)       = 0 0
85814/0x4cc3f2:  fcntl_nocancel(0x3, 0x32, 0x7FFEE7525050)       = 0 0
85814/0x4cc3f2:  close_nocancel(0x3)         = 0 0
85814/0x4cc3f2:  stat64("/Users/gireeshpunathil/Desktop\0", 0x7FFEE7525450, 0x0)         = 0 0

the most relevant one in this context is open_nocancel and from the look of it, it opens the current folder to obtain the cwd - leading to requiring a file descriptor.

So it is evident that a worker is prone to fail in this manner when run under restricted resources (in this case ulimit -n)

gireeshpunathil on 26 Jul 2020

Yeah, that makes sense – I think it would be nice to wrap the process.argv[1] = path.resolve(process.argv[1]); line in a try ... catch, we can’t expect it to succeed in all cases anyway.

addaleax on 26 Jul 2020

👍1

Still failing on CI on macOS.

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

01:05:25 not ok 2470 parallel/test-worker-init-failure
01:05:25   ---
01:05:25   duration_ms: 2.550
01:05:25   severity: fail
01:05:25   exitcode: 1
01:05:25   stack: |-
01:05:25     child stdout: 
01:05:25     
01:05:25     child stderr: events.js:291
01:05:25           throw er; // Unhandled 'error' event
01:05:25           ^
01:05:25     
01:05:25     AssertionError [ERR_ASSERTION]: The input did not match the regular expression /EMFILE/. Input:
01:05:25     
01:05:25     'ENOENT: no such file or directory, uv_cwd'
01:05:25     
01:05:25         at Worker.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:38:14)
01:05:25         at Worker.emit (events.js:314:20)
01:05:25         at Worker.[kOnErrorMessage] (internal/worker.js:241:10)
01:05:25         at Worker.[kOnMessage] (internal/worker.js:251:37)
01:05:25         at MessagePort.<anonymous> (internal/worker.js:167:57)
01:05:25         at MessagePort.[nodejs.internal.kHybridDispatch] (internal/event_target.js:353:41)
01:05:25         at MessagePort.exports.emitMessage (internal/per_context/messageport.js:18:26)
01:05:25         at Worker.[kOnExit] (internal/worker.js:223:5)
01:05:25         at Worker.<computed>.onexit (internal/worker.js:164:20)
01:05:25     Emitted 'error' event on process instance at:
01:05:25         at emitUnhandledRejectionOrErr (internal/event_target.js:542:11)
01:05:25         at MessagePort.[nodejs.internal.kHybridDispatch] (internal/event_target.js:357:9)
01:05:25         at MessagePort.exports.emitMessage (internal/per_context/messageport.js:18:26)
01:05:25         at Worker.[kOnExit] (internal/worker.js:223:5)
01:05:25         at Worker.<computed>.onexit (internal/worker.js:164:20) {
01:05:25       generatedMessage: true,
01:05:25       code: 'ERR_ASSERTION',
01:05:25       actual: 'ENOENT: no such file or directory, uv_cwd',
01:05:25       expected: /EMFILE/,
01:05:25       operator: 'match'
01:05:25     }
01:05:25     
01:05:25     
01:05:25     assert.js:103
01:05:25       throw new AssertionError(obj);
01:05:25       ^
01:05:25     
01:05:25     AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
01:05:25     
01:05:25     1 !== 0
01:05:25     
01:05:25         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-worker-init-failure.js:64:12)
01:05:25         at ChildProcess.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/common/index.js:365:15)
01:05:25         at ChildProcess.emit (events.js:314:20)
01:05:25         at Process.ChildProcess._handle.onexit (internal/child_process.js:276:12) {
01:05:25       generatedMessage: true,
01:05:25       code: 'ERR_ASSERTION',
01:05:25       actual: 1,
01:05:25       expected: 0,
01:05:25       operator: 'strictEqual'
01:05:25     }
01:05:25   ...

Trott on 11 Aug 2020

I wonder if the right thing to do is remove the e.message check and let the e.code check suffice.

Trott on 11 Aug 2020

looks like we have one more case that we missed here: the exact same libuv failure, but occurring after the worker is fully booted up - in which case the error is emitted as opposed to thrown.

So if we accept the previous fix in principle, the right thing is to accommodate this error type in the test case itself.

/cc @addaleax for opinion.

gireeshpunathil on 11 Aug 2020

o! failed to see @Trott 's PR. will review that instead.

gireeshpunathil on 11 Aug 2020

Was this page helpful?

0 / 5 - 0 ratings