Test runner: TAP reporter should only print failing subtests

[GeoffreyBooth]

I’m trying to find which test failed in https://github.com/nodejs/node/actions/runs/5841030019/job/15840839276?pr=47999. There seems to be some kind of truncation issue, possibly caused by GitHub Actions or the ASAN environment rather than the test runner (or not, I don’t know) and so searching for not ok in this output is turning up empty, even though there’s at least one failing test. However what I do see is a bunch of output from the same file as the failing test, telling me how all the other tests in that file have passed.

I’m not sure why the truncation is happening in this particular case, but separate from that issue, I wish the reporter didn’t print verbose output for passing tests in a file that has failures. I want detailed output only for the failures. cc @nodejs/test_runner

[MoLow]

I think we can do this in a seperate reporter. TAP is supposed to be pretty verbose.
also - since the output is truncated in the middle of a line, I am pretty sure it is not on node's side.

[ljharb]

indeed, a compliant TAP reporter doesn't provide any way to make the output more concise, but i often pipe my TAP output to https://npmjs.com/faucet which collapses all the passing output.

[GeoffreyBooth]

also - since the output is truncated in the middle of a line, I am pretty sure it is not on node’s side.

Please ignore the truncation for the purposes of this issue. I included that for context of how this came up, but it’s a separate concern.

I think we can do this in a seperate reporter. TAP is supposed to be pretty verbose.

Here’s a reproducible example. In the Node codebase, run tools/test.py --mode=release es-module/test-esm-loader-hooks.mjs. You should get output like this:

[00:01|% 100|+   1|-   0]: Done

All tests passed.

Then change line 461 of test-esm-loader-hooks.mjs so that instead of comparing code to 0 it compares to 1. This will make that subtest fail. Then run the command again:

=== release test-esm-loader-hooks ===
Path: es-module/test-esm-loader-hooks
TAP version 13
# Subtest: Loader hooks
    # Subtest: are called with all expected arguments
    ok 1 - are called with all expected arguments
      ---
      duration_ms: 1085.372548
      ...
    # Subtest: are called with all expected arguments using register function
    ok 2 - are called with all expected arguments using register function
      ---
      duration_ms: 1085.752839
      ...
    # Subtest: should handle never-settling hooks in ESM files
        # Subtest: top-level await of a never-settling resolve
        ok 1 - top-level await of a never-settling resolve
          ---
          duration_ms: 1086.820762
          ...
        # Subtest: top-level await of a never-settling load
        ok 2 - top-level await of a never-settling load
          ---
          duration_ms: 1001.441529
          ...
        # Subtest: top-level await of a race of never-settling hooks
        ok 3 - top-level await of a race of never-settling hooks
          ---
          duration_ms: 907.429481
          ...
        # Subtest: import.meta.resolve of a never-settling resolve
        ok 4 - import.meta.resolve of a never-settling resolve
          ---
          duration_ms: 989.338638
          ...
        1..4
    ok 3 - should handle never-settling hooks in ESM files
      ---
      duration_ms: 1087.474971
      type: 'suite'
      ...
    # Subtest: should handle never-settling hooks in CJS files
        # Subtest: never-settling resolve
        ok 1 - never-settling resolve
          ---
          duration_ms: 999.869842
          ...
        # Subtest: never-settling load
        ok 2 - never-settling load
          ---
          duration_ms: 997.523426
          ...
        # Subtest: race of never-settling hooks
        ok 3 - race of never-settling hooks
          ---
          duration_ms: 1010.457102
          ...
        1..3
    ok 4 - should handle never-settling hooks in CJS files
      ---
      duration_ms: 1038.034031
      type: 'suite'
      ...
    # Subtest: should work without worker permission
    ok 5 - should work without worker permission
      ---
      duration_ms: 1060.382333
      ...
    # Subtest: should allow loader hooks to spawn workers when allowed by the CLI flags
    ok 6 - should allow loader hooks to spawn workers when allowed by the CLI flags
      ---
      duration_ms: 1072.150181
      ...
    # Subtest: should not allow loader hooks to spawn workers if restricted by the CLI flags
    ok 7 - should not allow loader hooks to spawn workers if restricted by the CLI flags
      ---
      duration_ms: 1009.090166
      ...
    # Subtest: should not leak internals or expose import.meta.resolve
    ok 8 - should not leak internals or expose import.meta.resolve
      ---
      duration_ms: 1052.749904
      ...
    # Subtest: should be fine to call `process.exit` from a custom async hook
    ok 9 - should be fine to call `process.exit` from a custom async hook
      ---
      duration_ms: 763.281411
      ...
    # Subtest: should be fine to call `process.exit` from a custom sync hook
    ok 10 - should be fine to call `process.exit` from a custom sync hook
      ---
      duration_ms: 833.260083
      ...
    # Subtest: should be fine to call `process.exit` from the loader thread top-level
    ok 11 - should be fine to call `process.exit` from the loader thread top-level
      ---
      duration_ms: 979.910903
      ...
    # Subtest: should handle a throwing top-level body
        # Subtest: should handle regular Error object
        ok 1 - should handle regular Error object
          ---
          duration_ms: 1027.197047
          ...
        # Subtest: should handle null
        ok 2 - should handle null
          ---
          duration_ms: 1002.005929
          ...
        # Subtest: should handle undefined
        ok 3 - should handle undefined
          ---
          duration_ms: 1017.506587
          ...
        # Subtest: should handle boolean
        ok 4 - should handle boolean
          ---
          duration_ms: 992.006595
          ...
        # Subtest: should handle empty plain object
        ok 5 - should handle empty plain object
          ---
          duration_ms: 1036.974659
          ...
        # Subtest: should handle plain object
        ok 6 - should handle plain object
          ---
          duration_ms: 1025.086805
          ...
        # Subtest: should handle number
        ok 7 - should handle number
          ---
          duration_ms: 1009.966614
          ...
        # Subtest: should handle bigint
        ok 8 - should handle bigint
          ---
          duration_ms: 1009.271832
          ...
        # Subtest: should handle string
        ok 9 - should handle string
          ---
          duration_ms: 1001.304
          ...
        # Subtest: should handle symbol
        ok 10 - should handle symbol
          ---
          duration_ms: 1054.683395
          ...
        # Subtest: should handle function
        ok 11 - should handle function
          ---
          duration_ms: 1004.180215
          ...
        1..11
    ok 12 - should handle a throwing top-level body
      ---
      duration_ms: 1124.805862
      type: 'suite'
      ...
    # Subtest: globalPreload
        # Subtest: should emit deprecation warning
        ok 1 - should emit deprecation warning
          ---
          duration_ms: 1056.188186
          ...
        # Subtest: should handle globalPreload returning undefined
        ok 2 - should handle globalPreload returning undefined
          ---
          duration_ms: 1042.566635
          ...
        # Subtest: should handle loading node:test
        not ok 3 - should handle loading node:test
          ---
          duration_ms: 1062.754804
          location: 'file:///Users/geoffrey/Sites/node/test/es-module/test-esm-loader-hooks.mjs:451:5'
          failureType: 'testCodeFailure'
          error: |-
            Expected values to be strictly equal:

            0 !== 1

          code: 'ERR_ASSERTION'
          name: 'AssertionError'
          expected: 1
          actual: 0
          operator: 'strictEqual'
          stack: |-
            TestContext.<anonymous> (file:///Users/geoffrey/Sites/node/test/es-module/test-esm-loader-hooks.mjs:461:14)
            process.processTicksAndRejections (node:internal/process/task_queues:95:5)
            async Test.run (node:internal/test_runner/test:632:9)
            async Promise.all (index 2)
            async Suite.run (node:internal/test_runner/test:929:7)
            async Promise.all (index 12)
            async Suite.run (node:internal/test_runner/test:929:7)
            async startSubtest (node:internal/test_runner/harness:208:3)
          ...
        # Subtest: should handle loading node:os with node: prefix
        ok 4 - should handle loading node:os with node: prefix
          ---
          duration_ms: 1055.572137
          ...
        # Subtest: should handle loading builtin module without node: prefix
        ok 5 - should handle loading builtin module without node: prefix
          ---
          duration_ms: 1044.650598
          ...
        # Subtest: should throw when loading node:test without node: prefix
        ok 6 - should throw when loading node:test without node: prefix
          ---
          duration_ms: 1035.402771
          ...
        # Subtest: should register globals set from globalPreload
        ok 7 - should register globals set from globalPreload
          ---
          duration_ms: 978.0884
          ...
        # Subtest: should log console.log calls returned from globalPreload
        ok 8 - should log console.log calls returned from globalPreload
          ---
          duration_ms: 1001.180792
          ...
        # Subtest: should crash if globalPreload returns code that throws
        ok 9 - should crash if globalPreload returns code that throws
          ---
          duration_ms: 996.397427
          ...
        1..9
    not ok 13 - globalPreload
      ---
      duration_ms: 1148.338498
      type: 'suite'
      location: 'file:///Users/geoffrey/Sites/node/test/es-module/test-esm-loader-hooks.mjs:426:3'
      failureType: 'subtestsFailed'
      error: '1 subtest failed'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        async Promise.all (index 12)
      ...
    # Subtest: should be fine to call `process.removeAllListeners("beforeExit")` from the main thread
    ok 14 - should be fine to call `process.removeAllListeners("beforeExit")` from the main thread
      ---
      duration_ms: 854.37478
      ...
    # Subtest: should invoke `initialize` correctly
    ok 15 - should invoke `initialize` correctly
      ---
      duration_ms: 841.47309
      ...
    # Subtest: should allow communicating with loader via `register` ports
    ok 16 - should allow communicating with loader via `register` ports
      ---
      duration_ms: 885.773254
      ...
    # Subtest: should have `register` work with cjs
    ok 17 - should have `register` work with cjs
      ---
      duration_ms: 801.156724
      ...
    # Subtest: `register` should work with `require`
    ok 18 - `register` should work with `require`
      ---
      duration_ms: 1142.268472
      ...
    # Subtest: `register` should work with `import`
    ok 19 - `register` should work with `import`
      ---
      duration_ms: 1078.711869
      ...
    # Subtest: should execute `initialize` in sequence
    ok 20 - should execute `initialize` in sequence
      ---
      duration_ms: 783.603801
      ...
    1..20
not ok 1 - Loader hooks
  ---
  duration_ms: 1188.019607
  type: 'suite'
  location: 'file:///Users/geoffrey/Sites/node/test/es-module/test-esm-loader-hooks.mjs:8:1'
  failureType: 'subtestsFailed'
  error: '1 subtest failed'
  code: 'ERR_TEST_FAILURE'
  ...
1..1
# tests 43
# suites 5
# pass 42
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 0.278286
Command: out/Release/node /Users/geoffrey/Sites/node/test/es-module/test-esm-loader-hooks.mjs


[00:01|% 100|+   0|-   1]: Done

Failed tests:
out/Release/node /Users/geoffrey/Sites/node/test/es-module/test-esm-loader-hooks.mjs

That’s a lot of output, and the failing test is hidden in the middle there. I need to search for not ok to find it (and even then, I get a false positive in that not ok is printed twice for the one failure).

I understand that maybe the reason I’m not getting the verbose output in the “everything passing” case is because the Python test runner doesn’t print output in that case, and this reporter on its own prints everything all the time. But I’d prefer if we could somehow get a filtered output that only shows the failing tests, so that when debugging files like this one I can work faster because I don’t need to wade through hundreds of lines of output that I don’t care about.

[MoLow]

I'l try getting the python test runner use another reporter

[cjihrig]

I'm going to close this because we've switched the default reporter to spec all the time (#54548). That should be significantly less verbose and won't cause any TAP inception issues.