Investigate flaky test-runner-cli

[F3n67u]

Test

test-runner-cli

Platform

macos

Console output

node:assert:1027
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The input did not match the regular expression /not ok 1 - this should fail/. Input:

'TAP version 13\n' +
  '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js\n' +
  'not ok 1 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js\n' +
  '  ---\n' +
  '  duration_ms: 0.065594886\n' +
  "  failureType: 'subtestsFailed'\n" +
  '  exitCode: 1\n' +
  "  stdout: ''\n" +
  '  stderr: |-\n' +
  '    /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js:2\n' +
  "    throw new Error('thrown from index.js');\n" +
  '    ^\n' +
  '    \n' +
  '    Error: thrown from index.js\n' +
  '        at Object.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js:2:7)\n' +
  '        at Module._compile (node:internal/modules/cjs/loader:1114:14)\n' +
  '        at Module._extensions..js (node:internal/modules/cjs/loader:1168:10)\n' +
  '        at Module.load (node:internal/modules/cjs/loader:992:32)\n' +
  '        at Module._load (node:internal/modules/cjs/loader:832:12)\n' +
  '        at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)\n' +
  '        at node:internal/main/run_main_module:17:47\n' +
  '    \n' +
  '    Node.js v19.0.0-pre\n' +
  '    \n' +
  "  error: 'test failed'\n" +
  "  code: 'ERR_TEST_FAILURE'\n" +
  '  ...\n' +
  '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.test.js\n' +
  'ok 2 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.test.js\n' +
  '  ---\n' +
  '  duration_ms: 0.110061674\n' +
  '  ...\n' +
  '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/random.test.mjs\n' +
  'not ok 3 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/random.test.mjs\n' +
  '  ---\n' +
  '  duration_ms: 0.072654973\n' +
  "  failureType: 'subtestsFailed'\n" +
  '  exitCode: 1\n' +
  "  stdout: ''\n" +
  "  stderr: ''\n" +
  "  error: 'test failed'\n" +
  "  code: 'ERR_TEST_FAILURE'\n" +
  '  ...\n' +
  '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/subdir/subdir_test.js\n' +
  'ok 4 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/subdir/subdir_test.js\n' +
  '  ---\n' +
  '  duration_ms: 0.083164097\n' +
  '  ...\n' +
  '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/test/random.cjs\n' +
  'ok 5 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/test/random.cjs\n' +
  '  ---\n' +
  '  duration_ms: 0.065502184\n' +
  '  ...\n' +
  '1..5\n' +
  '# tests 5\n' +
  '# pass 3\n' +
  '# fail 2\n' +
  '# skipped 0\n' +
  '# todo 0\n' +
  '# duration_ms 0.242462392\n'

    at Object.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/parallel/test-runner-cli.js:49:10)
    at Module._compile (node:internal/modules/cjs/loader:1114:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1168:10)
    at Module.load (node:internal/modules/cjs/loader:992:32)
    at Module._load (node:internal/modules/cjs/loader:832:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)
    at node:internal/main/run_main_module:17:47 {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: 'TAP version 13\n' +
    '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js\n' +
    'not ok 1 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js\n' +
    '  ---\n' +
    '  duration_ms: 0.065594886\n' +
    "  failureType: 'subtestsFailed'\n" +
    '  exitCode: 1\n' +
    "  stdout: ''\n" +
    '  stderr: |-\n' +
    '    /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js:2\n' +
    "    throw new Error('thrown from index.js');\n" +
    '    ^\n' +
    '    \n' +
    '    Error: thrown from index.js\n' +
    '        at Object.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.js:2:7)\n' +
    '        at Module._compile (node:internal/modules/cjs/loader:1114:14)\n' +
    '        at Module._extensions..js (node:internal/modules/cjs/loader:1168:10)\n' +
    '        at Module.load (node:internal/modules/cjs/loader:992:32)\n' +
    '        at Module._load (node:internal/modules/cjs/loader:832:12)\n' +
    '        at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)\n' +
    '        at node:internal/main/run_main_module:17:47\n' +
    '    \n' +
    '    Node.js v19.0.0-pre\n' +
    '    \n' +
    "  error: 'test failed'\n" +
    "  code: 'ERR_TEST_FAILURE'\n" +
    '  ...\n' +
    '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.test.js\n' +
    'ok 2 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/index.test.js\n' +
    '  ---\n' +
    '  duration_ms: 0.110061674\n' +
    '  ...\n' +
    '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/random.test.mjs\n' +
    'not ok 3 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/random.test.mjs\n' +
    '  ---\n' +
    '  duration_ms: 0.072654973\n' +
    "  failureType: 'subtestsFailed'\n" +
    '  exitCode: 1\n' +
    "  stdout: ''\n" +
    "  stderr: ''\n" +
    "  error: 'test failed'\n" +
    "  code: 'ERR_TEST_FAILURE'\n" +
    '  ...\n' +
    '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/subdir/subdir_test.js\n' +
    'ok 4 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/subdir/subdir_test.js\n' +
    '  ---\n' +
    '  duration_ms: 0.083164097\n' +
    '  ...\n' +
    '# Subtest: /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/test/random.cjs\n' +
    'ok 5 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/test/random.cjs\n' +
    '  ---\n' +
    '  duration_ms: 0.065502184\n' +
    '  ...\n' +
    '1..5\n' +
    '# tests 5\n' +
    '# pass 3\n' +
    '# fail 2\n' +
    '# skipped 0\n' +
    '# todo 0\n' +
    '# duration_ms 0.242462392\n',
  expected: /not ok 1 - this should fail/,
  operator: 'match'
}

Node.js v19.0.0-pre

Build links

https://ci.nodejs.org/job/node-test-commit-osx/45870/nodes=osx1015/testReport/junit/(root)/test/parallel_test_runner_cli/

Additional information

I cannot reproduce this flaky problem on my Mac with repeat 1000 ./node test/parallel/test-runner-cli.js

cc @nodejs/test_runner

[F3n67u]

Related test:

node/test/parallel/test-runner-cli.js

Lines 37 to 51 in ed1e9ae

	{
	// User specified files that don't match the pattern are still run.
	const args = ['--test', testFixtures, join(testFixtures, 'index.js')];
	const child = spawnSync(process.execPath, args);
	assert.strictEqual(child.status, 1);
	assert.strictEqual(child.signal, null);
	assert.strictEqual(child.stderr.toString(), '');
	const stdout = child.stdout.toString();
	assert.match(stdout, /not ok 1 - .+index\.js/);
	assert.match(stdout, /ok 2 - .+index\.test\.js/);
	assert.match(stdout, /not ok 3 - .+random\.test\.mjs/);
	assert.match(stdout, /not ok 1 - this should fail/);
	assert.match(stdout, /ok 4 - .+subdir.+subdir_test\.js/);
	}

When running test/fixtures/test-runner/random.test.mjs, the stdout and stderr is empty. So the test fails, it expects stdout to have not ok 1 - this should fail message.

Actual

    'not ok 3 - /Users/iojs/build/workspace/node-test-commit-osx/nodes/osx1015/test/fixtures/test-runner/random.test.mjs\n' +
    '  ---\n' +
    '  duration_ms: 0.072654973\n' +
    "  failureType: 'subtestsFailed'\n" +
    '  exitCode: 1\n' +
    "  stdout: ''\n" +
    "  stderr: ''\n" +
    "  error: 'test failed'\n" +
    "  code: 'ERR_TEST_FAILURE'\n" +
    '  ...\n' +

Expected

not ok 3 - /Users/bytedance/Projects/node/test/fixtures/test-runner/random.test.mjs
  ---
  duration_ms: 0.153871203
  failureType: 'subtestsFailed'
  exitCode: 1
  stdout: |-
    TAP version 13
    not ok 1 - this should fail
      ---
      duration_ms: 0.000535456
      failureType: 'testCodeFailure'
      error: 'this is a failing test'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        TestContext.<anonymous> (file:///Users/bytedance/Projects/node/test/fixtures/test-runner/random.test.mjs:4:9)
        Test.runInAsyncScope (node:async_hooks:202:9)
        Test.run (node:internal/test_runner/test:340:20)
        Test.start (node:internal/test_runner/test:292:17)
        Test.test (node:internal/test_runner/harness:126:18)
        file:///Users/bytedance/Projects/node/test/fixtures/test-runner/random.test.mjs:3:1
        ModuleJob.run (node:internal/modules/esm/module_job:197:25)
        async Promise.all (index 0)
        async ESMLoader.import (node:internal/modules/esm/loader:527:24)
        async loadESM (node:internal/process/esm_loader:83:5)
      ...
    1..1
    # tests 1
    # pass 0
    # fail 1
    # skipped 0
    # todo 0
    # duration_ms 0.116038223
    
  stderr: |-
    (node:19382) ExperimentalWarning: The test runner is an experimental feature. This feature could change at any time
    (Use `node --trace-warnings ...` to show where the warning was created)
    
  error: 'test failed'
  code: 'ERR_TEST_FAILURE'
  ...

[MoLow]

IL try taking a look