test_runner: expose location of tests

[cjihrig]

This commit adds each test's line and column number to the reporter output. This will aid in debugging test suite failures when error stacks are not helpful, test suites are large, or tests have the same name. This data is also exposed on the spec reporter.

This commit also replaces the filename that was previously being reported, with the filename where the test actually exists. These are normally correct, but could be wrong if tests were run from a file other than the user's entrypoint.

Fixes: #48457

[nodejs-github-bot]

Review requested:

• @nodejs/test_runner

[mcollina]

Amazing work! Could you add this information to the tap reporter as well? This happens relatively often in CI too.

[benjamingr]

This probably needs benchmark as taking a trace can be expensive, doesn't it?

[cjihrig]

This probably needs benchmark as taking a trace can be expensive, doesn't it?

I tried really hard to avoid implementing this because I was worried about that. I tried to make it as fast as possible while being accurate. It only collects two stack frames and does not iterate over them.

I think we actually need this from a correctness standpoint. The reporter emits events with filenames attached to it, which might not be correct. The DX is a secondary improvement for things like #48457 (comment).

[ljharb]

Usually perf isn’t that important in failure cases, which any failed tests would be. What’s the actual impact here?

[cjihrig]

The problem is that if you wait until you know that the test failed, you can't get at the original call site, so you have to do it for all tests. If you do know of a way to accurately get the original test() call site at failure time, I would love to use that instead.

There's also the issue of reporting the wrong filename if you run a test from a non-main file via, for example, require('./some-other-file-with-tests-in-it').

[ljharb]

Presumably the expensive part is stack generation, and that’s what needs to be done eagerly :-/

[benjamingr]

I tried really hard to avoid implementing this because I was worried about that. I tried to make it as fast as possible while being accurate. It only collects two stack frames and does not iterate over them.

We would still need a benchmark or alternatively to make this opt in only if you listen to the event + a doc warning?

[cjihrig]

alternatively to make this opt in only if you listen to the event

I'm not sure how that would work. The filename is already part of the public API. Even if we limited these changes to the 'test:fail' event, every meaningful reporter will listen for that event.

[rluvaton]

How would this work with compilers that change the code location (e.g. TypeScript)

[cjihrig]

How would this work with compilers that change the code location (e.g. TypeScript)

It points to the location at runtime (same as the file, which would be the .js file, not the .ts file). Source maps aren't really supported in the test runner yet.

[cjihrig]

I've updated this PR based on feedback, including updating the TAP reporter.

Here are the benchmark numbers:

test_runner/global-concurrent-tests.js type='async' n=100 *** -2.39 % ±1.20% ±1.61% ±2.11% test_runner/global-concurrent-tests.js type='async' n=1000 *** -15.10 % ±1.10% ±1.47% ±1.91% test_runner/global-concurrent-tests.js type='async' n=10000 *** -12.71 % ±1.95% ±2.61% ±3.45% test_runner/global-concurrent-tests.js type='sync' n=100 *** -2.82 % ±1.26% ±1.68% ±2.18% test_runner/global-concurrent-tests.js type='sync' n=1000 *** -14.19 % ±0.95% ±1.27% ±1.65% test_runner/global-concurrent-tests.js type='sync' n=10000 *** -13.48 % ±1.05% ±1.40% ±1.84% test_runner/global-sequential-tests.js type='async' n=100 ** 1.91 % ±1.39% ±1.85% ±2.41% test_runner/global-sequential-tests.js type='async' n=1000 0.91 % ±2.53% ±3.37% ±4.40% test_runner/global-sequential-tests.js type='async' n=10000 0.71 % ±1.22% ±1.62% ±2.11% test_runner/global-sequential-tests.js type='sync' n=100 0.78 % ±1.51% ±2.01% ±2.62% test_runner/global-sequential-tests.js type='sync' n=1000 0.72 % ±2.06% ±2.74% ±3.57% test_runner/global-sequential-tests.js type='sync' n=10000 -0.11 % ±1.20% ±1.59% ±2.07% test_runner/suite-tests.js concurrency='no' testType='async' testsPerSuite=10 numberOfSuites=10 *** -2.83 % ±0.71% ±0.94% ±1.23% test_runner/suite-tests.js concurrency='no' testType='async' testsPerSuite=10 numberOfSuites=100 *** 3.70 % ±1.45% ±1.94% ±2.53% test_runner/suite-tests.js concurrency='no' testType='async' testsPerSuite=100 numberOfSuites=10 *** 4.71 % ±1.37% ±1.83% ±2.41% test_runner/suite-tests.js concurrency='no' testType='async' testsPerSuite=100 numberOfSuites=100 *** -4.82 % ±0.70% ±0.94% ±1.22% test_runner/suite-tests.js concurrency='no' testType='async' testsPerSuite=1000 numberOfSuites=10 *** -4.63 % ±0.77% ±1.03% ±1.35% test_runner/suite-tests.js concurrency='no' testType='async' testsPerSuite=1000 numberOfSuites=100 -0.32 % ±4.42% ±5.92% ±7.79% test_runner/suite-tests.js concurrency='no' testType='sync' testsPerSuite=10 numberOfSuites=10 *** -3.96 % ±0.96% ±1.28% ±1.69% test_runner/suite-tests.js concurrency='no' testType='sync' testsPerSuite=10 numberOfSuites=100 *** 5.81 % ±1.68% ±2.25% ±2.95% test_runner/suite-tests.js concurrency='no' testType='sync' testsPerSuite=100 numberOfSuites=10 *** 4.96 % ±0.81% ±1.08% ±1.41% test_runner/suite-tests.js concurrency='no' testType='sync' testsPerSuite=100 numberOfSuites=100 *** -5.29 % ±0.68% ±0.91% ±1.19% test_runner/suite-tests.js concurrency='no' testType='sync' testsPerSuite=1000 numberOfSuites=10 *** -4.31 % ±0.62% ±0.83% ±1.08% test_runner/suite-tests.js concurrency='no' testType='sync' testsPerSuite=1000 numberOfSuites=100 * -4.90 % ±4.29% ±5.75% ±7.56% test_runner/suite-tests.js concurrency='yes' testType='async' testsPerSuite=10 numberOfSuites=10 *** -4.88 % ±0.71% ±0.94% ±1.23% test_runner/suite-tests.js concurrency='yes' testType='async' testsPerSuite=10 numberOfSuites=100 *** 7.81 % ±2.02% ±2.69% ±3.50% test_runner/suite-tests.js concurrency='yes' testType='async' testsPerSuite=100 numberOfSuites=10 *** 4.54 % ±1.33% ±1.77% ±2.31% test_runner/suite-tests.js concurrency='yes' testType='async' testsPerSuite=100 numberOfSuites=100 *** -4.98 % ±0.63% ±0.84% ±1.09% test_runner/suite-tests.js concurrency='yes' testType='async' testsPerSuite=1000 numberOfSuites=10 *** -5.33 % ±0.68% ±0.91% ±1.18% test_runner/suite-tests.js concurrency='yes' testType='async' testsPerSuite=1000 numberOfSuites=100 *** -5.40 % ±2.69% ±3.62% ±4.78% test_runner/suite-tests.js concurrency='yes' testType='sync' testsPerSuite=10 numberOfSuites=10 *** -5.96 % ±0.73% ±0.98% ±1.27% test_runner/suite-tests.js concurrency='yes' testType='sync' testsPerSuite=10 numberOfSuites=100 *** 7.47 % ±1.78% ±2.38% ±3.13% test_runner/suite-tests.js concurrency='yes' testType='sync' testsPerSuite=100 numberOfSuites=10 *** 5.63 % ±0.86% ±1.14% ±1.49% test_runner/suite-tests.js concurrency='yes' testType='sync' testsPerSuite=100 numberOfSuites=100 *** -5.14 % ±0.70% ±0.94% ±1.24% test_runner/suite-tests.js concurrency='yes' testType='sync' testsPerSuite=1000 numberOfSuites=10 *** -5.06 % ±0.67% ±0.89% ±1.17% test_runner/suite-tests.js concurrency='yes' testType='sync' testsPerSuite=1000 numberOfSuites=100 *** -8.32 % ±2.39% ±3.19% ±4.18% 

I'm on the fence because, as expected, there is a performance hit. On the other hand, as previously mentioned, this improves correctness and provides important debugging information. 🤷

[mcollina]

The alternative solution to this issue is to restore printing the file name when more than one file is being run (wrapping it in a suite automatically). It's a less accurate, but at least we can point out where things are broken.

[cjihrig]

The more I think about this, the more I think we should land this change.

I'm not entirely confident in the benchmarks. For example, why does global-concurrent-tests.js show a bigger perf hit when n=1,000 than when n=10,000? At the same time, running tests sequentially shows a small improvement (although not statistically significant) even though each test is doing more work. Similarly, there are a number of suite-tests.js runs that show over a 5% improvement.

[mcollina]

lgtm

[rluvaton]

The more I think about this, the more I think we should land this change.

I'm not entirely confident in the benchmarks. For example, why does global-concurrent-tests.js show a bigger perf hit when n=1,000 than when n=10,000? At the same time, running tests sequentially shows a small improvement (although not statistically significant) even though each test is doing more work. Similarly, there are a number of suite-tests.js runs that show over a 5% improvement.

If you think the benchmark would need an improvement I would love to see that... I added those as we did not have anything so we had no data to make a decision

[cjihrig]

Having the benchmarks is a great improvement. Thank you for that. Unfortunately, I don't have any suggestions for improving them (other than I'm not sure global-concurrent-tests.js makes a ton of sense because the test runner has internal concurrency machinery that I don't think that benchmark accounts for). It's good to see numbers and how changes impact them... I'm just having trouble reasoning about some of the results in the context of this change.

[rluvaton]

Yagiz suggested to improve the benchmark reliability we should extract to test creation an test running but I don't think that's possible but it might give you some idea 😄