Investigate flaky parallel/test-trace-events-metadata

[Trott]

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]

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]

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

[cjihrig]

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]

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]

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]

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]

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]

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]

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]

I can reproduce on my machine and am investigating.