Test diagnostics are ommited when running with --test

[MoLow]

Version

v20.0.0-pre

Platform

Darwin Moshes-MBP.localdomain 21.1.0 Darwin Kernel Version 21.1.0: Wed Oct 13 17:33:01 PDT 2021; root:xnu-8019.41.5~1/RELEASE_ARM64_T6000 arm64

Subsystem

test_runner

What steps will reproduce the bug?

run

const test = require('node:test');
test((t) => {
  t.diagnostic('this is a diagnostic');
  t.test((t) => {
    t.diagnostic('this is a nested diagnostic');
  });
});

How often does it reproduce? Is there a required condition?

always

What is the expected behavior?

when running without --flag the diagnostics are printed:

TAP version 13
# Subtest: <anonymous>
    # Subtest: <anonymous>
    ok 1 - <anonymous>
      ---
      duration_ms: 1.904541
      ...
    # this is a nested diagnostic
    1..1
ok 1 - <anonymous>
  ---
  duration_ms: 2.817666
  ...
# this is a diagnostic
1..1
# tests 1
# pass 1
# fail 0
# cancelled 0
# skipped 0
# todo 0
# duration_ms 5.736792

What do you see instead?

this is the result of adding a log where all the TAP parsed tokens are handled

node/lib/internal/test_runner/runner.js

Line 133 in f14fa1b

#handleReportItem({ kind, node, nesting = 0 }) {

TAP version 13
VersionKeyword { version: '13' } 1
# Subtest: /Users/moshe/repos/node/a.js
SubTestPointKeyword { name: '<anonymous>' } 1
SubTestPointKeyword { name: '<anonymous>' } 2
TestPointKeyword {
  status: { fail: false, pass: true, todo: false, skip: false },
  id: '1',
  description: '<anonymous>',
  reason: '',
  time: 1.886167,
  diagnostics: [ 'duration_ms: 1.886167' ]
} 2
PlanKeyword { start: '1', end: '1' } 2
TestPointKeyword {
  status: { fail: false, pass: true, todo: false, skip: false },
  id: '1',
  description: '<anonymous>',
  reason: '',
  time: 2.906042,
  diagnostics: [ 'duration_ms: 2.906042' ]
} 1
PlanKeyword { start: '1', end: '1' } 1
Comment { comment: 'tests 1' } 1
Comment { comment: 'pass 1' } 1
Comment { comment: 'fail 0' } 1
Comment { comment: 'cancelled 0' } 1
Comment { comment: 'skipped 0' } 1
Comment { comment: 'todo 0' } 1
Comment { comment: 'duration_ms 5.808208' } 1
ok 1 - /Users/moshe/repos/node/a.js
  ---
  duration_ms: 86.315
  ...
1..1
# tests 1
# pass 1
# fail 0
# cancelled 0
# skipped 0
# todo 0
# duration_ms 87.029333

the diagnostics are missing

Additional information

No response

[MoLow]

CC @manekinekko

[manekinekko]

This is indeed caused by

node/lib/internal/test_runner/runner.js

Line 185 in f14fa1b

// Ignore file top level diagnostics

This was done by design to prevent some undesired top-level comments from being parsed (can't remember the exact reason). This looks like an issue and we need to handle those top-level comments differently.

[MoLow]

@manekinekko that is not the only cause. see the steps I performed in the issue - commenting that condition out did not help

[manekinekko]

Gotcha! Let me investigate this.

[manekinekko]

After a quick investigation, it seems that the output of t.diagnostic(...); is of type TokenKind.Comment and thus the TAP parser treats it as a comment. Comments are appended to the next node that's not a comment. The parser assumes comments are printed before the line they are describing.

The current TAP parser was implemented following v14 specs which state:

Lines outside of a YAML diagnostic block which begin with a # character 
preceded by zero or more characters of whitespace, are comments.

However, it seems that TAP 13 specs treat any comment as a diagnostic value:

... Diagnostic lines should begin with a #, ...

@MoLow @cjihrig what do you suggest:

1. Should we downgrade the current TAP parser to follow TAP 13 specs (gonna probably require rewriting a bunch of internal rules)
2. Should we improve t.diagnostic(...); to output valid v14 diagnostics (YAML block)
3. Mix and match both v13 and v14 (gonna require a lot of maintenance)!

I'd recommend going with 2/ since TAP v14 is considered the current specs.

[cjihrig]

@manekinekko options 1 and 3 don't seem great. I'm not sure that option 2 would work because these diagnostics are happening at the root test, and the root test is a special case. Can the root test be special cased (this happens in other places in the test runner already)?

[MoLow]

Perhaps we can add a env var or a flag to tell the root test not to report the "common diagnostics", then the if can be removed

[cjihrig]

What are "common diagnostics"?

[MoLow]

All the diagnostics we emit by default once per "root test" - tests,pass,fail,canceled etc

[cjihrig]

Oh. I think the TAP parser should just get a bit smarter there. I really like that the test runner spawns child processes with no special/hidden/surprising config.

I also think that work would go well with some of the other TAP parsing bugs that have been reported - #45836, #45910, #45833, #45706

[ashutosh887]

Hi @MoLow @cjihrig
I would like to work on this Issue!

[MoLow]

@ashutosh887 go for it!

[vivek378521]

@MoLow I have raised a draft PR(#45989) for this issue, this is the first time I am raising contributing to this project. I have commented out the code which was blocking diagnostics. But if you can point me towards a better fix then it will be appreciated. Thanks!

[rubiagatra]

@manekinekko @cjihrig if that is the parsing bug, where I would start? I am reading this multiple times https://github.com/nodejs/node/blob/main/lib/internal/test_runner/tap_parser.js and don't know the context. I also tinkering with test tools/test.py test/message/test_runner_output_cli.js to strengthen my understanding.

The comment is using TAP14 but the code using TAP13.