Investigate flaky parallel/test-trace-events-metadata #24129

Trott · 2018-11-06T14:05:54Z

https://ci.nodejs.org/job/node-test-commit-linux/22895/nodes=ubuntu1604-64/console

00:09:00 not ok 1930 parallel/test-trace-events-metadata
00:09:00   ---
00:09:00   duration_ms: 0.412
00:09:00   severity: fail
00:09:00   exitcode: 1
00:09:00   stack: |-
00:09:00     assert.js:351
00:09:00         throw err;
00:09:00         ^
00:09:00     
00:09:00     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:09:00     
00:09:00       assert(traces.some((trace) =>
00:09:00         trace.name === 'process_name' && trace.args.name === 'foo'))
00:09:00     
00:09:00         at fs.readFile.common.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-64/test/parallel/test-trace-events-metadata.js:67:7)
00:09:00         at /home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-64/test/common/index.js:340:15
00:09:00         at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:53:3)
00:09:00   ...

@nodejs/trace-events

Trott · 2018-11-06T22:59:14Z

Replicable under load (on macOS):

$ tools/test.py -j96 --repeat 192 test/parallel/test-trace-events-metadata.js 
=== release test-trace-events-metadata ===                    
Path: parallel/test-trace-events-metadata
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(traces.some((trace) =>
    trace.name === 'process_name' && trace.args.name === 'foo'))

    at fs.readFile.common.mustCall (/Users/trott/io.js/test/parallel/test-trace-events-metadata.js:67:7)
    at /Users/trott/io.js/test/common/index.js:340:15
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:53:3)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-trace-events-metadata.js
[00:18|% 100|+ 191|-   1]: Done   
$

Trott · 2018-11-06T23:18:11Z

(It's the setting of process.title that's not taking here.)

cjihrig · 2018-11-06T23:52:26Z

Replicable under load (on macOS):

and

(It's the setting of process.title that's not taking here.)

There's a possibility that this is related to (or at least could be improved by) libuv/libuv#2064. If so, a new release is being planned for later this week.

Trott · 2018-11-22T03:06:31Z

Alas, it appear that libuv fix is in libuv 1.24.0 which is also now on master, but this is still reproducible locally.

Trott · 2018-11-28T04:36:50Z

https://ci.nodejs.org/job/node-test-commit-linux/23528/nodes=debian9-64/console

20:15:43 not ok 1851 parallel/test-trace-events-metadata
20:15:43   ---
20:15:43   duration_ms: 0.335
20:15:43   severity: fail
20:15:43   exitcode: 1
20:15:43   stack: |-
20:15:43     assert.js:351
20:15:43         throw err;
20:15:43         ^
20:15:43     
20:15:43     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
20:15:43     
20:15:43       assert(traces.some((trace) =>
20:15:43         trace.name === 'process_name' && trace.args.name === 'foo'))
20:15:43     
20:15:43         at fs.readFile.common.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/debian9-64/test/parallel/test-trace-events-metadata.js:68:7)
20:15:43         at /home/iojs/build/workspace/node-test-commit-linux/nodes/debian9-64/test/common/index.js:346:15
20:15:43         at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)
20:15:43   ...

Trott · 2018-12-05T14:12:01Z

https://ci.nodejs.org/job/node-test-binary-arm/4667/RUN_SUBSET=2,label=pi3-docker/console

00:10:05 not ok 279 parallel/test-trace-events-metadata
00:10:05   ---
00:10:05   duration_ms: 3.871
00:10:05   severity: fail
00:10:05   exitcode: 1
00:10:05   stack: |-
00:10:05     assert.js:351
00:10:05         throw err;
00:10:05         ^
00:10:05     
00:10:05     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:10:05     
00:10:05       assert(traces.some((trace) =>
00:10:05         trace.name === 'process_name' && trace.args.name === 'foo'))
00:10:05     
00:10:05         at fs.readFile.common.mustCall (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-trace-events-metadata.js:68:7)
00:10:05         at /home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:346:15
00:10:05         at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)
00:10:05   ...

Trott · 2018-12-05T14:42:37Z

I wonder if V8 optimizes out the loop in this bit of code from the test, which is now causing this failure to show up once in a while because process.title setting is actually asynchronous.

setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1);

Trott · 2018-12-05T15:35:55Z

Load appears to not actually be a factor perhaps:

$ tools/test.py -j 1 --repeat 2048 test/parallel/test-trace-events-metadata.js
=== release test-trace-events-metadata ===                   
Path: parallel/test-trace-events-metadata
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(traces.some((trace) =>
    trace.name === 'process_name' && trace.args.name === 'foo'))

    at fs.readFile.common.mustCall (/Users/trott/io.js/test/parallel/test-trace-events-metadata.js:68:7)
    at /Users/trott/io.js/test/common/index.js:346:15
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-trace-events-metadata.js
=== release test-trace-events-metadata ===                   ^[[A
Path: parallel/test-trace-events-metadata
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(traces.some((trace) =>
    trace.name === 'process_name' && trace.args.name === 'foo'))

    at fs.readFile.common.mustCall (/Users/trott/io.js/test/parallel/test-trace-events-metadata.js:68:7)
    at /Users/trott/io.js/test/common/index.js:346:15
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-trace-events-metadata.js
=== release test-trace-events-metadata ===                    
Path: parallel/test-trace-events-metadata
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(traces.some((trace) =>
    trace.name === 'process_name' && trace.args.name === 'foo'))

    at fs.readFile.common.mustCall (/Users/trott/io.js/test/parallel/test-trace-events-metadata.js:68:7)
    at /Users/trott/io.js/test/common/index.js:346:15
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-trace-events-metadata.js
=== release test-trace-events-metadata ===                    
Path: parallel/test-trace-events-metadata
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(traces.some((trace) =>
    trace.name === 'process_name' && trace.args.name === 'foo'))

    at fs.readFile.common.mustCall (/Users/trott/io.js/test/parallel/test-trace-events-metadata.js:68:7)
    at /Users/trott/io.js/test/common/index.js:346:15
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-trace-events-metadata.js
[09:10|% 100|+ 2044|-   4]: Done                              
$

richardlau · 2018-12-22T01:53:39Z

https://ci.nodejs.org/job/node-test-commit-linux/24231/nodes=fedora-last-latest-x64/testReport/junit/(root)/test/parallel_test_trace_events_metadata/

assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(traces.some((trace) =>
    trace.name === 'process_name' && trace.args.name === 'foo'))

    at fs.readFile.common.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/fedora-last-latest-x64/test/parallel/test-trace-events-metadata.js:69:7)
    at /home/iojs/build/workspace/node-test-commit-linux/nodes/fedora-last-latest-x64/test/common/index.js:373:15
    at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:54:3)

ofrobots · 2018-12-26T22:04:15Z

I can reproduce on my machine and am investigating.

Multiple threads may be concurrently adding to the metadata_events list. Protect access with a mutex. Fixes: nodejs#24129

ofrobots · 2018-12-27T00:59:30Z

#25235

Multiple threads may be concurrently adding to the metadata_events list. Protect access with a mutex. Fixes: #24129 PR-URL: #25235 Reviewed-By: Anna Henningsen <[email protected]>

Multiple threads may be concurrently adding to the metadata_events list. Protect access with a mutex. Fixes: nodejs#24129 PR-URL: nodejs#25235 Reviewed-By: Anna Henningsen <[email protected]>

Multiple threads may be concurrently adding to the metadata_events list. Protect access with a mutex. Fixes: #24129 PR-URL: #25235 Reviewed-By: Anna Henningsen <[email protected]>

Trott added trace_events Issues and PRs related to V8, Node.js core, and userspace code trace events. flaky-test Issues and PRs related to the tests with unstable failures on the CI. labels Nov 6, 2018

richardlau mentioned this issue Dec 22, 2018

build: fix Windows shared lib build #25166

Closed

4 tasks

ofrobots added a commit to ofrobots/node that referenced this issue Dec 27, 2018

src: trace_events: fix race with metadata events

73859b6

Multiple threads may be concurrently adding to the metadata_events list. Protect access with a mutex. Fixes: nodejs#24129

ofrobots mentioned this issue Dec 27, 2018

src: trace_events: fix race with metadata events #25235

Closed

2 tasks

addaleax closed this as completed in f39b3e3 Jan 7, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Investigate flaky parallel/test-trace-events-metadata #24129

Investigate flaky parallel/test-trace-events-metadata #24129

Trott commented Nov 6, 2018

Trott commented Nov 6, 2018 •

edited

Loading

Trott commented Nov 6, 2018

cjihrig commented Nov 6, 2018

Trott commented Nov 22, 2018

Trott commented Nov 28, 2018

Trott commented Dec 5, 2018

Trott commented Dec 5, 2018

Trott commented Dec 5, 2018 •

edited

Loading

richardlau commented Dec 22, 2018

ofrobots commented Dec 26, 2018

ofrobots commented Dec 27, 2018

Investigate flaky parallel/test-trace-events-metadata #24129

Investigate flaky parallel/test-trace-events-metadata #24129

Comments

Trott commented Nov 6, 2018

Trott commented Nov 6, 2018 • edited Loading

Trott commented Nov 6, 2018

cjihrig commented Nov 6, 2018

Trott commented Nov 22, 2018

Trott commented Nov 28, 2018

Trott commented Dec 5, 2018

Trott commented Dec 5, 2018

Trott commented Dec 5, 2018 • edited Loading

richardlau commented Dec 22, 2018

ofrobots commented Dec 26, 2018

ofrobots commented Dec 27, 2018

Trott commented Nov 6, 2018 •

edited

Loading

Trott commented Dec 5, 2018 •

edited

Loading