--test-only produces unexpected results and unexpected call order

[ChALkeR]

Version

v22.5.1

Platform

Darwin Nikitas-Air.lan 23.5.0 Darwin Kernel Version 23.5.0: Wed May  1 20:14:59 PDT 2024; root:xnu-10063.121.3~5/RELEASE_ARM64_T8122 arm64

Subsystem

test_runner

What steps will reproduce the bug?

Run this script with node --test --test-only ~3-5 times:

Note that it shows the behavior with and without a bug with probability 0.6 (see top lines), so just launch it until there is a run with with global after() line and without it, and compare those

import { describe, test, after } from 'node:test'

const bug = Math.random() < 0.6
if (bug) {
  // await import('./preload.js') would also cause this, but let's be single-file
  // Any would do: beforeEach, afterEach, after, ...
  after(() => { console.log( 'with global after()') })
  await Promise.resolve()
}

const log = []
const logger = (...args) => () => { log.push(args) }

describe('A', () => {
  const one = 'A'
  test.only('A', logger(one, 'A'))
  test('B', logger(one, 'B'))
  describe.only('C', () => {
    const two = 'C'
    test.only('A', logger(one, two, 'A'))
    test('B', logger(one, two, 'B'))
  })
  describe('D', () => {
    const two = 'D'
    test.only('A', logger(one, two, 'A'))
    test('B', logger(one, two, 'B'))
  })
})

describe.only('B', () => {
  const one = 'B'
  test('A', logger(one, 'A'))
  test('B', logger(one, 'B'))
  describe('C', () => {
    const two = 'C'
    test('A', logger(one, two, 'A'))
  })
})

describe('C', () => {
  const one = 'C'
  test.only('A', logger(one, 'A'))
  test('B', logger(one, 'B'))
  describe.only('C', () => {
    const two = 'C'
    test('A', logger(one, two, 'A'))
    test('B', logger(one, two, 'B'))
  })
  describe('D', () => {
    const two = 'D'
    test('A', logger(one, two, 'A'))
    test.only('B', logger(one, two, 'B'))
  })
})

describe('D', () => {
  const one = 'D'
  test('A', logger(one, 'A'))
  test.only('B', logger(one, 'B'))
})

describe.only('E', () => {
  const one = 'E'
  test('A', logger(one, 'A'))
  test('B', logger(one, 'B'))
})

test.only('F', logger('F', '// is last'))

after(() => {
  console.log(log)
})

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

Always under a --test --test-only flag and if (bug) replaced to if (true)
In that specific file, with a 0.6 probability to demonstrate the inconsistency

What is the expected behavior? Why is that the expected behavior?

with global after()
[
  [ 'A', 'A' ],
  [ 'A', 'C', 'A' ],
  [ 'A', 'D', 'A' ],
  [ 'B', 'A' ],
  [ 'B', 'B' ],
  [ 'B', 'C', 'A' ],
  [ 'C', 'A' ],
  [ 'C', 'C', 'A' ],
  [ 'C', 'C', 'B' ],
  [ 'C', 'D', 'B' ],
  [ 'D', 'B' ],
  [ 'E', 'A' ],
  [ 'E', 'B' ],
  [ 'F', '// is last' ]
]

Order is preserved + that is what happens in node --test --test-only without an after() set
Also Jest seems to agree

What do you see instead?

with global after()
[
  [ 'F', '// is last' ],
  [ 'B', 'A' ],
  [ 'E', 'A' ],
  [ 'B', 'B' ],
  [ 'E', 'B' ],
  [ 'B', 'C', 'A' ]
]

Missing entries, strange (but always reproducible) test execution order
Note that there are even no async tests in the testcase

Additional information

Testcase above does not use t.fullName to be less Node.js-specific
Simplified but Node.js-specific testcase is:

import { describe, test, after } from 'node:test'

// await import('./preload.js') would also cause this, but let's be single-file
// Any would do: beforeEach, afterEach, after, ...
// Commenting out this line untriggers the bug
after(() => { console.log( 'with global after()') })
await Promise.resolve()

console.log('Execution order was:')
const ll = (t) => { console.log(` * ${t.fullName}`) }

describe('A', () => {
  test.only('A', ll)
  test('B', ll)
  describe.only('C', () => {
    test.only('A', ll)
    test('B', ll)
  })
  describe('D', () => {
    test.only('A', ll)
    test('B', ll)
  })
})
describe.only('B', () => {
  test('A', ll)
  test('B', ll)
  describe('C', () => {
    test('A', ll)
  })
})
describe('C', () => {
  test.only('A', ll)
  test('B', ll)
  describe.only('C', () => {
    test('A', ll)
    test('B', ll)
  })
  describe('D', () => {
    test('A', ll)
    test.only('B', ll)
  })
})
describe('D', () => {
  test('A', ll)
  test.only('B', ll)
})
describe.only('E', () => {
  test('A', ll)
  test('B', ll)
})
test.only('F', ll)

Expected output:

Execution order was:
 * A > A
 * A > C > A
 * A > D > A
 * B > A
 * B > B
 * B > C > A
 * C > A
 * C > C > A
 * C > C > B
 * C > D > B
 * D > B
 * E > A
 * E > B
 * F
with global after()

Actual output:

Execution order was:
 * F
 * B > A
 * E > A
 * B > B
 * E > B
 * B > C > A
with global after()

[cjihrig]

I have not verified it, but I think this issue probably has the same underlying cause as #54084, and is not necessarily related to the after hook.

[ChALkeR]

and is not necessarily related to the after hook.

That is true, any hook or even test() before await / import triggers this

[ChALkeR]

A usecase for triggering this without explicit await: after() / before() in an --import file, e.g. node --test --import preload.js 'test/**/*.test.js'