Test runner with junit reporter and forceExit flag results in incomplete report

[samuelmurray]

Version

v20.15.0

Platform

Microsoft Windows NT 10.0.22621.0 x64

Subsystem

test

What steps will reproduce the bug?

// index.test.js

import {describe, test} from 'node:test';
import * as assert from 'node:assert/strict';

describe('Suite', () => {
    test('Failing test', () => {
        assert.fail()
    })

    test('Passing test', () => {
        assert.ok(true)
    })
});

Run tests:

$ node  --test-reporter junit --test-reporter-destination test-results.xml --test --test-force-exit

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

Problem arises every time.

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

test-results.xml should have the following content:

<?xml version="1.0" encoding="utf-8"?>
<testsuites>
	<testcase name="Passing test" time="0.001314" classname="test"/>
	<!-- tests 1 -->
	<!-- suites 0 -->
	<!-- pass 1 -->
	<!-- fail 0 -->
	<!-- cancelled 0 -->
	<!-- skipped 0 -->
	<!-- todo 0 -->
	<!-- duration_ms 115.2994 -->
</testsuites>

This is what we get without passing the --test-force-exit flag. Also, other test-reporters (e.g. tap) don't seem to be affected by the flag, i.e. they produce the same report regardless of if the flag is passed or not.

What do you see instead?

test-results.xml is an incomplete file with the following content:

<?xml version="1.0" encoding="utf-8"?>
<testsuites>

Additional information

From what I can understand of #52038, this is supposed to work, i.e. the report should always be complete even if the flag is passed.

[avivkeller]

(v22.6.0 and v20.16.0)

import {describe, test} from 'node:test';
import * as assert from 'node:assert/strict';

describe('Suite', () => {
    test('Failing test', () => {
        assert.fail()
    })

    test('Passing test', () => {
        assert.ok(true)
    })
});

---

$ node  --test-reporter junit --test-reporter-destination test-results.xml --test --test-force-exit

<!-- test-results.xml -->
<?xml version="1.0" encoding="utf-8"?>
<testsuites>
	<!-- tests 0 -->
	<!-- suites 0 -->
	<!-- pass 0 -->
	<!-- fail 0 -->
	<!-- cancelled 0 -->
	<!-- skipped 0 -->
	<!-- todo 0 -->
	<!-- duration_ms 8.168875 -->
</testsuites>

$ node  --test-reporter junit --test-reporter-destination test-results.xml --test

<?xml version="1.0" encoding="utf-8"?>
<testsuites>
	<!-- tests 0 -->
	<!-- suites 0 -->
	<!-- pass 0 -->
	<!-- fail 0 -->
	<!-- cancelled 0 -->
	<!-- skipped 0 -->
	<!-- todo 0 -->
	<!-- duration_ms 8.122069 -->
</testsuites>

---

$ node  --test-reporter tap --test-reporter-destination test-results.tap --test --test-force-exit

TAP version 13
1..0
# tests 0
# suites 0
# pass 0
# fail 0
# cancelled 0
# skipped 0
# todo 0
# duration_ms 8.349482

$ node  --test-reporter tap --test-reporter-destination test-results.tap --test

TAP version 13
1..0
# tests 0
# suites 0
# pass 0
# fail 0
# cancelled 0
# skipped 0
# todo 0
# duration_ms 7.965605

---

I'm not seeing a difference in the junit report rather than the other ones, am I missing something?

[samuelmurray]

@redyetidev are you sure your setup acutally detects the test file? It looks suspicious that all your reports state 0 tests. Can you try naming the file index.test.js, or alternatively explicity specify the file when running node --test [...]?

[avivkeller]

Haha! I forgot to name the file, you are correct, sorry! Reproduction results:

---

import {describe, test} from 'node:test';
import * as assert from 'node:assert/strict';

describe('Suite', () => {
    test('Failing test', () => {
        assert.fail()
    })

    test('Passing test', () => {
        assert.ok(true)
    })
});

---

$ node  --test-reporter junit --test-reporter-destination test-results.xml --test --test-force-exit

<?xml version="1.0" encoding="utf-8"?>
<testsuites>

$ node  --test-reporter junit --test-reporter-destination test-results.xml --test

<?xml version="1.0" encoding="utf-8"?>
<testsuites>
	<testsuite name="Suite" time="0.002112" disabled="0" errors="0" tests="2" failures="1" skipped="0" hostname="Jedi8-KALI">
		<testcase name="Failing test" time="0.001014" classname="test" failure="Failed">
			<failure type="testCodeFailure" message="Failed">
Error [ERR_TEST_FAILURE]: Failed
    at new Promise (&lt;anonymous>)
    at Array.map (&lt;anonymous>) {
  code: 'ERR_TEST_FAILURE',
  failureType: 'testCodeFailure',
  cause: AssertionError [ERR_ASSERTION]: Failed
      at TestContext.&lt;anonymous> (file:///xyz/index.test.mjs:8:16)
      at Test.runInAsyncScope (node:async_hooks:206:9)
      at Test.run (node:internal/test_runner/test:865:25)
      at Test.start (node:internal/test_runner/test:762:17)
      at node:internal/test_runner/test:1224:71
      at node:internal/per_context/primordials:488:82
      at new Promise (&lt;anonymous>)
      at new SafePromise (node:internal/per_context/primordials:456:29)
      at node:internal/per_context/primordials:488:9
      at Array.map (&lt;anonymous>) {
    generatedMessage: true,
    code: 'ERR_ASSERTION',
    actual: undefined,
    expected: undefined,
    operator: 'fail'
  }
}
			</failure>
		</testcase>
		<testcase name="Passing test" time="0.000147" classname="test"/>
	</testsuite>
	<!-- tests 2 -->
	<!-- suites 1 -->
	<!-- pass 1 -->
	<!-- fail 1 -->
	<!-- cancelled 0 -->
	<!-- skipped 0 -->
	<!-- todo 0 -->
	<!-- duration_ms 57.794832 -->
</testsuites>

---

$ node  --test-reporter tap --test-reporter-destination test-results.tap --test --test-force-exit

TAP version 13
# Subtest: Suite
    # Subtest: Failing test
    not ok 1 - Failing test
      ---
      duration_ms: 1.328963
      location: '/xyz/index.test.mjs:7:5'
      failureType: 'testCodeFailure'
      error: 'Failed'
      code: 'ERR_ASSERTION'
      name: 'AssertionError'
      operator: 'fail'
      stack: |-
        TestContext.<anonymous> (file:///xyz/index.test.mjs:8:16)
        Test.runInAsyncScope (node:async_hooks:206:9)
        Test.run (node:internal/test_runner/test:865:25)
        Test.start (node:internal/test_runner/test:762:17)
        node:internal/test_runner/test:1224:71
        node:internal/per_context/primordials:488:82
        new Promise (<anonymous>)
        new SafePromise (node:internal/per_context/primordials:456:29)
        node:internal/per_context/primordials:488:9
        Array.map (<anonymous>)
      ...
    # Subtest: Passing test
    ok 2 - Passing test
      ---
      duration_ms: 0.146173
      ...
    1..2
not ok 1 - Suite
  ---
  duration_ms: 2.495924
  type: 'suite'
  location: '/xyz/index.test.mjs:6:1'
  failureType: 'subtestsFailed'
  error: '1 subtest failed'
  code: 'ERR_TEST_FAILURE'
  ...
1..1

$ node  --test-reporter tap --test-reporter-destination test-results.tap --test

TAP version 13
# Subtest: Suite
    # Subtest: Failing test
    not ok 1 - Failing test
      ---
      duration_ms: 1.071312
      location: '/xyz/index.test.mjs:7:5'
      failureType: 'testCodeFailure'
      error: 'Failed'
      code: 'ERR_ASSERTION'
      name: 'AssertionError'
      operator: 'fail'
      stack: |-
        TestContext.<anonymous> (file:///xyz/index.test.mjs:8:16)
        Test.runInAsyncScope (node:async_hooks:206:9)
        Test.run (node:internal/test_runner/test:865:25)
        Test.start (node:internal/test_runner/test:762:17)
        node:internal/test_runner/test:1224:71
        node:internal/per_context/primordials:488:82
        new Promise (<anonymous>)
        new SafePromise (node:internal/per_context/primordials:456:29)
        node:internal/per_context/primordials:488:9
        Array.map (<anonymous>)
      ...
    # Subtest: Passing test
    ok 2 - Passing test
      ---
      duration_ms: 0.146884
      ...
    1..2
not ok 1 - Suite
  ---
  duration_ms: 2.167982
  type: 'suite'
  location: '/xyz/index.test.mjs:6:1'
  failureType: 'subtestsFailed'
  error: '1 subtest failed'
  code: 'ERR_TEST_FAILURE'
  ...
1..1
# tests 2
# suites 1
# pass 1
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 58.838293

---

The file is named index.test.mjs (mjs for module features)

I've hidden my older to comment to prevent confusion.

[cjihrig]

I'm guessing we need more logic around here when we're using any file destinations.

[MoLow]

I am on vacation without a computer until mid-september, I will give a look when I am back if no one else does before me

[avivkeller]

I'm looking into it. It looks like the close event is being emitted before the stream actually finishes. it could be because the composed stream is not the same as the reporter?

[avivkeller]

I have a patch. Just gotta add tests

[avivkeller]

See #54953