`parallel/test-runner-output` is flaky

[avivkeller]

Test

parallel/test-runner-output

Platform

Windows

Console output

not ok 2761 parallel/test-runner-output
  ---
  duration_ms: 5831.75900
  severity: fail
  exitcode: 1
  stack: |-
    � test runner output
      � test-runner/output/abort.js (5044.243602ms)
      � test-runner/output/abort-runs-after-hook.js (5024.467414ms)
      � test-runner/output/abort_suite.js (5000.590488ms)
      � test-runner/output/abort_hooks.js (4979.5575ms)
      � test-runner/output/describe_it.js (4977.140656ms)
      � test-runner/output/describe_nested.js (4925.394205ms)
      � test-runner/output/eval_dot.js (4901.098336ms)
      � test-runner/output/eval_spec.js (4837.353ms)
      � test-runner/output/eval_tap.js (4710.94876ms)
      � test-runner/output/filtered-suite-delayed-build.js (4681.152445ms)
      � test-runner/output/filtered-suite-order.mjs (4642.805511ms)
      � test-runner/output/filtered-suite-throws.js (4612.421303ms)
      � test-runner/output/hooks.js (4622.774072ms)
      � test-runner/output/hooks_spec_reporter.js (4589.467662ms)
      � test-runner/output/skip-each-hooks.js (4526.797983ms)
      � test-runner/output/suite-skip-hooks.js (4502.179664ms)
      � test-runner/output/timeout_in_before_each_should_not_affect_further_tests.js (4422.895785ms)
      � test-runner/output/hooks-with-no-global-test.js (4306.540227ms)
      � test-runner/output/global-hooks-with-no-tests.js (4279.560221ms)
      � test-runner/output/before-and-after-each-too-many-listeners.js (4201.921211ms)
      � test-runner/output/before-and-after-each-with-timeout-too-many-listeners.js (4158.995317ms)
      � test-runner/output/force_exit.js (4130.514523ms)
      � test-runner/output/global_after_should_fail_the_test.js (4101.715736ms)
      � test-runner/output/no_refs.js (4050.275822ms)
      � test-runner/output/no_tests.js (3976.924663ms)
      � test-runner/output/only_tests.js (3872.183748ms)
      � test-runner/output/dot_reporter.js (3810.210886ms)
      � test-runner/output/junit_reporter.js (3816.323072ms)
      � test-runner/output/spec_reporter_successful.js (3710.15109ms)
      � test-runner/output/spec_reporter.js (3722.466172ms)
      � test-runner/output/spec_reporter_cli.js (3607.488084ms)
      � test-runner/output/source_mapped_locations.mjs (3511.73783ms)
      � test-runner/output/lcov_reporter.js (3515.362787ms)
      � test-runner/output/output.js (3432.210248ms)
      � test-runner/output/output_cli.js (3385.594322ms)
      � test-runner/output/name_and_skip_patterns.js (3116.385549ms)
      � test-runner/output/name_pattern.js (3012.778989ms)
      � test-runner/output/name_pattern_with_only.js (2944.807975ms)
      � test-runner/output/skip_pattern.js (2479.866823ms)
      � test-runner/output/unfinished-suite-async-error.js (2393.255322ms)
      � test-runner/output/unresolved_promise.js (2214.530445ms)
      � test-runner/output/default_output.js (2081.418465ms)
        AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
        + actual - expected ... Lines skipped
        
          '[32m� should pass [90m(*ms)[39m[39m\n' +
            '[31m� should fail [90m(*ms)[39m[39m\n' +
        ...
            '  *[39m\n' +
            '  *[39m\n' +
        +   '  [90m    at async startSubtestAfterBootstrap (node:internal/test_runn'
        -   '  *[39m\n' +
        -   '\n' +
        -   '*\n' +
        -   '[31m� should fail [90m(*ms)[39m[39m\n' +
        -   '  Error: fail\n' +
        -   '      *[39m\n' +
        -   '  *[39m\n' +
        -   '  *[39m\n' +
        -   '  *[39m\n' +
        -   '  *[39m\n' +
        -   '      *[39m\n' +
        -   '  *[39m\n' +
        -   '  *[39m\n' +
        -   '  *[39m\n' +
        -   '  *[39m\n' +
        -   '\n' +
        -   '*\n' +
        -   '[31m� should pass but parent fail [90m(*ms)[39m[39m\n' +
        -   "  [32m'test did not finish before its parent and was cancelled'[39m\n"
            at assertSnapshot (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix72-ppc64/test/common/assertSnapshot.js:56:12)
            at async Module.spawnAndAssert (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix72-ppc64/test/common/assertSnapshot.js:91:3)
            at async TestContext.<anonymous> (file:///home/iojs/build/workspace/node-test-commit-aix/nodes/aix72-ppc64/test/parallel/test-runner-output.mjs:286:5)
            at async Test.run (node:internal/test_runner/test:935:9)
            at async Promise.all (index 41)
            at async Suite.run (node:internal/test_runner/test:1320:7)
            at async startSubtestAfterBootstrap (node:internal/test_runner/harness:297:3) {
          generatedMessage: true,
          code: 'ERR_ASSERTION',
          actual: '[32m� should pass [90m(*ms)[39m[39m\n[31m� should fail [90m(*ms)[39m[39m\n  Error: fail\n      *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n...',
          expected: '[32m� should pass [90m(*ms)[39m[39m\n[31m� should fail [90m(*ms)[39m[39m\n  Error: fail\n      *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n...',
          operator: 'strictEqual'
        }
    
      � test-runner/output/arbitrary-output.js (1878.087741ms)
      � test-runner/output/async-test-scheduling.mjs (1841.915158ms)
      � test-runner/output/arbitrary-output-colored.js (2090.36852ms)
      � test-runner/output/dot_output_custom_columns.js (1552.294798ms)
      � test-runner/output/tap_escape.js (1461.577271ms)
      � test-runner/output/test-runner-plan.js (1421.101897ms)
      � test-runner/output/coverage_failure.js (1200.580922ms)
      � test-runner/output/test-diagnostic-warning-without-test-only-flag.js (1083.959424ms)
      � test-runner/output/coverage-width-40.mjs (1122.226143ms)
      � test-runner/output/coverage-width-80.mjs (888.268393ms)
      � test-runner/output/coverage-width-100.mjs (849.100504ms)
      � test-runner/output/coverage-width-150.mjs (881.08359ms)
      � test-runner/output/coverage-width-infinity.mjs (722.609533ms)
      � test-runner/output/coverage-width-80-uncovered-lines.mjs (758.820816ms)
      � test-runner/output/coverage-width-100-uncovered-lines.mjs (611.19314ms)
      � test-runner/output/coverage-width-150-uncovered-lines.mjs (692.291311ms)
      � test-runner/output/coverage-width-infinity-uncovered-lines.mjs (617.418721ms)
    � test runner output (5372.954414ms)
    � tests 59
    � suites 1
    � pass 58
    � fail 1
    � cancelled 0
    � skipped 0
    � todo 0
    � duration_ms 5392.306818
    
    � failing tests:
    
    test at test/parallel/test-runner-output.mjs:295:5
    � test-runner/output/default_output.js (2081.418465ms)
      AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
      + actual - expected ... Lines skipped
      
        '[32m� should pass [90m(*ms)[39m[39m\n' +
          '[31m� should fail [90m(*ms)[39m[39m\n' +
      ...
          '  *[39m\n' +
          '  *[39m\n' +
      +   '  [90m    at async startSubtestAfterBootstrap (node:internal/test_runn'
      -   '  *[39m\n' +
      -   '\n' +
      -   '*\n' +
      -   '[31m� should fail [90m(*ms)[39m[39m\n' +
      -   '  Error: fail\n' +
      -   '      *[39m\n' +
      -   '  *[39m\n' +
      -   '  *[39m\n' +
      -   '  *[39m\n' +
      -   '  *[39m\n' +
      -   '      *[39m\n' +
      -   '  *[39m\n' +
      -   '  *[39m\n' +
      -   '  *[39m\n' +
      -   '  *[39m\n' +
      -   '\n' +
      -   '*\n' +
      -   '[31m� should pass but parent fail [90m(*ms)[39m[39m\n' +
      -   "  [32m'test did not finish before its parent and was cancelled'[39m\n"
          at assertSnapshot (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix72-ppc64/test/common/assertSnapshot.js:56:12)
          at async Module.spawnAndAssert (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix72-ppc64/test/common/assertSnapshot.js:91:3)
          at async TestContext.<anonymous> (file:///home/iojs/build/workspace/node-test-commit-aix/nodes/aix72-ppc64/test/parallel/test-runner-output.mjs:286:5)
          at async Test.run (node:internal/test_runner/test:935:9)
          at async Promise.all (index 41)
          at async Suite.run (node:internal/test_runner/test:1320:7)
          at async startSubtestAfterBootstrap (node:internal/test_runner/harness:297:3) {
        generatedMessage: true,
        code: 'ERR_ASSERTION',
        actual: '[32m� should pass [90m(*ms)[39m[39m\n[31m� should fail [90m(*ms)[39m[39m\n  Error: fail\n      *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n...',
        expected: '[32m� should pass [90m(*ms)[39m[39m\n[31m� should fail [90m(*ms)[39m[39m\n  Error: fail\n      *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n  *[39m\n...',
        operator: 'strictEqual'
      }
  ...

Build links

• https://ci.nodejs.org/job/node-test-binary-windows-js-suites/30580/RUN_SUBSET=0,nodes=win11-arm64-COMPILED_BY-vs2022-arm64/testReport/junit/(root)/parallel/test_runner_coverage/

Additional information

I feel this is likely an issue with replaceStackTrace in assertSnapshot, since startSubtestAfterBootstrap is logged...

[aduh95]

It was previously reported in #52139

[avivkeller]

It was previously reported in #52139

FWIW That flake was caused by the different issue

[avivkeller]

I've been working on updating the old node-core-test library, and during that process, I believe I found the source of this flake, or at least information that will help: I don't think it's probably stripping some cases

[cjihrig]

@redyetidev could you be more specific? I'm not sure I understand your previous comment.

[avivkeller]

Yes, sorry for the confusion. During my porting of the test runner for node-core-test, I noticed that the common/assertSnapshot.js file wasn't trimming all of the stack traces.

In this case, the failing test is test-runner/output/default_output.js, which uses the specTransform function.

Essentially, the specTransform function looks like:

Everything

import { fileURLToPath } from 'node:url';
import path from 'node:path';

const stackFramesRegexp = /(?<=\n)(\s+)((.+?)\s+\()?(?:\(?(.+?):(\d+)(?::(\d+))?)\)?(\s+\{)?(\[\d+m)?(\n|$)/g;
const windowNewlineRegexp = /\r/g;

function replaceNodeVersion(str) {
  return str.replaceAll(process.version, '*');
}

function replaceStackTrace(str, replacement = '$1*$7$8\n') {
  return str.replace(stackFramesRegexp, replacement);
}

function replaceWindowsLineEndings(str) {
  return str.replace(windowNewlineRegexp, '');
}

function replaceWindowsPaths(str) {
  return (process.platform === 'win32') ? str.replaceAll(path.win32.sep, path.posix.sep) : str;
}

function replaceFullPaths(str) {
  return str.replaceAll('\\\'', "'").replaceAll(path.resolve(__dirname, '../..'), '');
}

function transform(...args) {
  return (str) => args.reduce((acc, fn) => fn(acc), str);
}

const root = fileURLToPath(new URL('../..', import.meta.url)).slice(0, -1);
const color = '(\\[\\d+m)';
const stackTraceBasePath = new RegExp(`${color}\\(${root.replaceAll(/[\\^$*+?.()|[\]{}]/g, '\\$&')}/?${color}(.*)${color}\\)`, 'g');

function replaceSpecDuration(str) {
  return str
    .replaceAll(/[0-9.]+ms/g, '*ms')
    .replaceAll(/duration_ms [0-9.]+/g, 'duration_ms *')
    .replace(stackTraceBasePath, '$3');
}

const specTransform = transform(
  replaceSpecDuration,
  replaceWindowsLineEndings,
  replaceStackTrace,
  replaceWindowsPaths,
);

For typical stack traces, this is fine:

const output = `
Error: ...
  [90m    at Test.runInAsyncScope (node:async_hooks:211:14)[39m
  [90m    at Test.run (node:internal/test_runner/test:934:25)[39m
  [90m    at Test.processPendingSubtests (node:internal/test_runner/test:633:18)[39m
  [90m    at Test.postRun (node:internal/test_runner/test:1045:19)[39m
`.trim();

console.log(specTransform(output));

Error: ...
  *[39m
  *[39m
  *[39m
  *[39m

However, if there's a slight difference in the output, such as it being cut off for some reason:

const output = `
Error: ...
  [90m    at Test.runInAsyncScope (node:async_hooks:211:14)[39m
  [90m    at Test.run (node:internal/test_runner/test:934:25)[39m
  [90m    at Test.processPendingSubtests (node:internal/test_runner/test:633:18)[39m
  [90m    at Test.postRun (node:internal/test
`.trim();

console.log(specTransform(output));

Error: ...
  *[39m
  *[39m
  *[39m
  [90m    at Test.postRun (node:internal/test

The line is logged.

[avivkeller]

Something is causing it to be cutoff (maybe?) which is an issue, however, IMO the stack remover shouldn't be so strict, I.E. it should know that "[90m at" is a stack trace, and handle the whole line.