Report each failing node --test test with its cause, read from the TAP reporter, so a passing line of the first file never stands for the failure (issue 1901)

2026-10-26 19:33:12 +01:00
parent da29f77b10
commit c255d56b71
15 changed files with 409 additions and 9 deletions
@@ -56,11 +56,15 @@ type TestResult struct {
 	Failed    []Failure `json:"failed,omitempty"`
 }

-// Failure is a check or script that failed; Output is the first lines it wrote.
+// Failure is a check or script that failed, or one failing test of a test script.
 type Failure struct {
 	Package string `json:"package"`
 	Test    string `json:"test,omitempty"`
-	Output  string `json:"output,omitempty"`
+	// File is the failing test's location (file:line:column) when node --test named it, Cause the first line of its
+	// error, and Output its own output, Cause first, up to 4096 bytes (issue 1901), as mesh-build-go's.
+	File   string `json:"file,omitempty"`
+	Cause  string `json:"cause,omitempty"`
+	Output string `json:"output,omitempty"`
 }

 func (m *Module) testTool() StepTool {
@@ -128,11 +132,19 @@ func (m *Module) test(ctx context.Context, args map[string]any) (any, error) {
 	var check, run time.Duration
 	var failed []Failure
 	// a command that could not start is not a verdict: the step fails. One that ran and said no is.
-	ran := func(name string, r forgekey.Ran) error {
+	ran := func(name string, r forgekey.Ran, tests bool) error {
 		if r.Err != "" {
 			return fmt.Errorf("%s could not be run: status %d %s: %s", name, r.Status, r.Err, firstLine(r.Stderr))
 		}
-		if r.Status != 0 {
+		if r.Status != 0 && tests {
+			// the test script ran under node's TAP reporter: each failing test is a failure of its own, never a passing line
+			for _, f := range tapFailures(where, r.Stdout+"\n"+r.Stderr) {
+				if f.Test == "" {
+					f.Test = name
+				}
+				failed = append(failed, f)
+			}
+		} else if r.Status != 0 {
 			failed = append(failed, Failure{Package: where, Test: name, Output: lines(r.Stdout + "\n" + r.Stderr)})
 		}
 		return nil
@@ -148,17 +160,17 @@ func (m *Module) test(ctx context.Context, args map[string]any) (any, error) {
 		start := m.now()
 		r := m.runIn(ctx, root, false, dir, nil, "node", line...)
 		check = m.now().Sub(start)
-		if err := ran(name, r); err != nil {
+		if err := ran(name, r, false); err != nil {
 			return nil, err
 		}
 		res.Ran = append(res.Ran, name)
 	}
 	if hasScript && len(failed) == 0 {
 		start := m.now()
-		env := []string{"PATH=" + binDir(root) + ":" + pathOrDefault(), "npm_config_cache=" + filepath.Join(m.Toolchain.Paths.Cache, "npm")}
+		env := []string{"PATH=" + binDir(root) + ":" + pathOrDefault(), "NODE_OPTIONS=" + TestReporterOption, "npm_config_cache=" + filepath.Join(m.Toolchain.Paths.Cache, "npm")}
 		r := m.runIn(ctx, root, false, dir, env, "npm", scriptArgs(script)...)
 		run = m.now().Sub(start)
-		if err := ran(script, r); err != nil {
+		if err := ran(script, r, true); err != nil {
 			return nil, err
 		}
 		res.Ran = append(res.Ran, script)
@@ -166,7 +178,7 @@ func (m *Module) test(ctx context.Context, args map[string]any) (any, error) {
 	res.Failed = failed
 	var why []string
 	for _, f := range failed {
-		why = append(why, fmt.Sprintf("%s failed in %s: %s", f.Test, f.Package, firstLine(f.Output)))
+		why = append(why, failureWhy(f))
 	}
 	if level == "unit" {
 		res.Elapsed, res.Bound = (check + run).Seconds(), UnitBound.Seconds()
@@ -280,3 +292,16 @@ func typeScriptFiles(dir string) ([]string, error) {
 	})
 	return out, err
 }
+
+// failureWhy is the words of one failure: the check or test that failed, where, and its cause (the first line of its output
+// when it has none).
+func failureWhy(f Failure) string {
+	if f.Cause == "" {
+		return fmt.Sprintf("%s failed in %s: %s", f.Test, f.Package, firstLine(f.Output))
+	}
+	file := ""
+	if f.File != "" {
+		file = " (" + f.File + ")"
+	}
+	return fmt.Sprintf("test %q failed in %s%s: %s", f.Test, f.Package, file, firstLine(f.Cause))
+}
@@ -138,7 +138,7 @@ func TestAFailingScriptIsAVerdictAndACommandThatCannotStartIsAFailedStep(t *test
 	f.answer["npm"] = forgekey.Ran{Status: 1, Stdout: "not ok 1 - adds\n"}
 	out, err := m.test(context.Background(), testArgs("unit"))
 	r, _ := out.(*TestResult)
-	if err != nil || r == nil || r.Passed || len(r.Failed) != 1 || r.Failed[0].Test != "test" || !strings.Contains(r.Failed[0].Output, "not ok 1") {
+	if err != nil || r == nil || r.Passed || len(r.Failed) != 1 || r.Failed[0].Test != "adds" || !strings.Contains(r.Failed[0].Output, "not ok 1") {
 		t.Errorf("a failing script = %+v, %v, want passed false and its output", r, err)
 	}
 	f.answer["npm"] = forgekey.Ran{Status: 127, Err: "ENOENT"}
@@ -199,3 +199,38 @@ func TestTheTestScriptFindsTscAndEsbuildOnItsPath(t *testing.T) {
 		t.Errorf("npm ran with PATH %q, want %s first", path, bin)
 	}
 }
+
+// 1901: a failing node --test run is reported test by test, from node's TAP reporter, in the output captured in
+// testdata/node-test-tap: each failing test with its name, file and cause, never a passing line of an earlier file.
+func TestFailingNodeTestsAreReportedEachWithTheirCause(t *testing.T) {
+	for _, c := range []struct {
+		file, test, location, cause, inOutput string
+		n                                     int
+	}{
+		{"two-files", "fails in the second file", "/work/two-files/test/b.test.mjs:3:1", "one plus one is not three", "2 !== 3", 1},
+		{"suite", "fails inside", "/work/suite/test/s.test.mjs:5:3", "Expected values to be strictly deep-equal:", "operator: 'deepStrictEqual'", 1},
+		{"syntax", "test/b.test.mjs", "/work/syntax/test/b.test.mjs:1:1", "", "SyntaxError: Unexpected end of input", 1},
+	} {
+		out, err := os.ReadFile(filepath.Join("testdata", "node-test-tap", c.file+".tap"))
+		if err != nil {
+			t.Fatal(err)
+		}
+		got := tapFailures("p", string(out))
+		if len(got) != c.n {
+			t.Fatalf("%s: %d failures %+v, want %d", c.file, len(got), got, c.n)
+		}
+		f := got[0]
+		if c.file == "syntax" {
+			c.cause = "SyntaxError: Unexpected end of input" // node names the file, the error is in the lines before it
+		}
+		if f.Test != c.test || f.File != c.location || !strings.HasPrefix(f.Cause, c.cause) ||
+			!strings.Contains(f.Output, c.inOutput) || len(f.Output) > 4096+len(f.Cause)+64 {
+			t.Errorf("%s: failure %+v, want test %q at %q, cause %q, output with %q", c.file, f, c.test, c.location, c.cause, c.inOutput)
+		}
+		for _, l := range strings.Split(f.Output, "\n") {
+			if strings.HasPrefix(strings.TrimSpace(l), "ok ") || strings.Contains(l, "passes in the first file") {
+				t.Errorf("%s: output keeps the passing line %q", c.file, l)
+			}
+		}
+	}
+}
@@ -0,0 +1,165 @@
+package main
+
+import (
+	"fmt"
+	"regexp"
+	"strings"
+)
+
+var ansi = regexp.MustCompile("\x1b\\[[0-9;]*m")
+
+// TestReporterOption is what the test script runs under: node's TAP reporter, which writes each failing test as a
+// "not ok" line with a YAML block (its error, its location, its stack), whatever the package's own script prints
+// otherwise (issue 1901: the default output of a run over several files kept the first file's passing lines).
+const TestReporterOption = "--test-reporter=tap"
+
+const outputBytes = 4096
+
+// tapFailures are the failing tests of a `node --test` run read from its TAP output, each with its name, its file
+// (the test's location), its Cause (the first line of its error) and its own block up to outputBytes, Cause first.
+// A suite that failed only because a test inside it did (failureType subtestsFailed) is not reported twice. When the
+// output holds no failing test (node itself failed: a syntax error, a file that could not load, a crash) the failure
+// is the last lines of the output without its passing lines, and its Cause the first line that names an error.
+func tapFailures(pkg, out string) []Failure {
+	var failed []Failure
+	all := strings.Split(ansi.ReplaceAllString(strings.ReplaceAll(out, "\r\n", "\n"), ""), "\n")
+	prev := 0 // the line after the last test block: what the run wrote since is the next test's own
+	for i := 0; i < len(all); i++ {
+		name, ok := notOk(all[i])
+		if !ok {
+			continue
+		}
+		indent := len(all[i]) - len(strings.TrimLeft(all[i], " "))
+		block := []string{strings.TrimSpace(all[i])}
+		fields := map[string]string{}
+		var key string
+		inYAML := false
+		j := i + 1
+		for ; j < len(all); j++ {
+			t := strings.TrimSpace(all[j])
+			if !inYAML {
+				if t == "---" {
+					inYAML = true
+					continue
+				}
+				break
+			}
+			if t == "..." {
+				j++
+				break
+			}
+			block = append(block, strings.TrimRight(all[j], " \t"))
+			if k, v, found := yamlKey(all[j], indent); found {
+				key = k
+				if v != "|-" && v != "|" {
+					fields[k] = strings.Trim(v, "'")
+				}
+			} else if key != "" && fields[key] == "" && t != "" {
+				fields[key] = t // the first line of a block scalar
+			}
+		}
+		from := prev
+		i, prev = j-1, j
+		if fields["failureType"] == "subtestsFailed" {
+			continue
+		}
+		cause := fields["error"]
+		if cause == "" {
+			cause = fields["failureType"]
+		}
+		if cause == "test failed" || cause == "" {
+			// a file that did not load (a syntax error, a crash): node says only "test failed" and writes the error
+			// as comment lines before it
+			var own []string
+			for _, l := range all[from:i] {
+				if t := strings.TrimSpace(l); strings.HasPrefix(t, "# ") && !strings.HasPrefix(t, "# Subtest") {
+					own = append(own, strings.TrimPrefix(t, "# "))
+				}
+			}
+			if len(own) > 0 {
+				cause = own[0]
+				for _, l := range own {
+					if strings.Contains(l, "Error") {
+						cause = l
+						break
+					}
+				}
+				block = append(own, block...)
+			}
+		}
+		failed = append(failed, Failure{Package: pkg, Test: name, File: fields["location"], Cause: cause, Output: clipBlock(cause, block)})
+	}
+	if len(failed) > 0 {
+		return failed
+	}
+	var rest []string
+	for _, l := range all {
+		t := strings.TrimSpace(l)
+		if t == "" || strings.HasPrefix(t, "ok ") || strings.HasPrefix(t, "✔") || strings.HasPrefix(t, "# Subtest") || strings.HasPrefix(t, "TAP version") {
+			continue
+		}
+		rest = append(rest, t)
+	}
+	cause := ""
+	for _, l := range rest {
+		if strings.Contains(l, "Error") || strings.HasPrefix(l, "not ok") {
+			cause = l
+			break
+		}
+	}
+	return []Failure{{Package: pkg, Cause: cause, Output: clipBlock(cause, rest)}}
+}
+
+// notOk is the test name of a "not ok N - name" line, indented or not.
+func notOk(l string) (string, bool) {
+	t := strings.TrimSpace(l)
+	rest, ok := strings.CutPrefix(t, "not ok ")
+	if !ok {
+		return "", false
+	}
+	if _, after, found := strings.Cut(rest, " - "); found {
+		rest = after
+	}
+	return strings.TrimSpace(rest), true
+}
+
+// yamlKey is "key: value" of a field of a TAP block, whose lines sit two spaces deeper than their "not ok" line; a
+// deeper line is part of a block scalar (an error's lines, a stack).
+func yamlKey(l string, indent int) (key, val string, ok bool) {
+	t := strings.TrimLeft(l, " ")
+	if len(l)-len(t) != indent+2 {
+		return "", "", false
+	}
+	k, v, found := strings.Cut(t, ": ")
+	if !found {
+		if k, found = strings.CutSuffix(t, ":"); !found {
+			return "", "", false
+		}
+	}
+	if k == "" || strings.ContainsAny(k, " ()/") {
+		return "", "", false
+	}
+	return k, strings.TrimSpace(v), true
+}
+
+// clipBlock is a failing test's block, Cause first, kept to its last lines within outputBytes.
+func clipBlock(cause string, lines []string) string {
+	size, from := 0, len(lines)
+	for from > 0 {
+		n := len(lines[from-1]) + 1
+		if size+n > outputBytes && from < len(lines) {
+			break
+		}
+		size += n
+		from--
+	}
+	var kept []string
+	if cause = strings.TrimSpace(cause); cause != "" && (from > 0 || len(lines) == 0 || strings.TrimSpace(lines[from]) != cause) {
+		kept = append(kept, cause)
+	}
+	if from > 0 {
+		kept = append(kept, fmt.Sprintf("... (%d earlier lines)", from))
+	}
+	kept = append(kept, lines[from:]...)
+	return strings.Join(kept, "\n")
+}
@@ -0,0 +1,12 @@
+# node --test TAP output, captured (issue 1901)
+
+Real output of `NODE_OPTIONS=--test-reporter=tap node --test 'test/*.test.mjs'` (node v23.9.0, the Node the build
+module runs with) in each project folder beside it, stdout and stderr together; every run exits 1.
+
+- `two-files`: a.test.mjs passes, b.test.mjs has one failing and one passing test (`two-files.tap`).
+- `suite`: a describe whose second test fails, and prints a line first (`suite.tap`); the suite itself is reported
+  `not ok` too, with failureType subtestsFailed.
+- `syntax`: a.test.mjs passes, b.test.mjs has a syntax error, so node reports the file `not ok` (`syntax.tap`).
+
+Captured by running the command in each folder. The only change to the captures: the absolute path of the capturing
+checkout is replaced by `/work/`. To capture again, run the command in the folder and redirect `2>&1` to the file.
@@ -0,0 +1,62 @@
+TAP version 13
+# a line the test printed
+# Subtest: a suite
+    # Subtest: passes inside
+    ok 1 - passes inside
+      ---
+      duration_ms: 0.786439
+      type: 'test'
+      ...
+    # Subtest: fails inside
+    not ok 2 - fails inside
+      ---
+      duration_ms: 4.551994
+      type: 'test'
+      location: '/work/suite/test/s.test.mjs:5:3'
+      failureType: 'testCodeFailure'
+      error: |-
+        Expected values to be strictly deep-equal:
+        [32m+ actual[39m [31m- expected[39m
+        
+        [39m  {
+        [32m+[39m   a: 1
+        [31m-[39m   a: 2
+        [39m  }
+        
+      code: 'ERR_ASSERTION'
+      name: 'AssertionError'
+      expected:
+        a: 2
+      actual:
+        a: 1
+      operator: 'deepStrictEqual'
+      stack: |-
+        TestContext.<anonymous> (file:///work/suite/test/s.test.mjs:5:77)
+        Test.runInAsyncScope (node:async_hooks:214:14)
+        Test.run (node:internal/test_runner/test:1047:25)
+        Suite.processPendingSubtests (node:internal/test_runner/test:744:18)
+        Test.postRun (node:internal/test_runner/test:1173:19)
+        Test.run (node:internal/test_runner/test:1101:12)
+        async Promise.all (index 0)
+        async Suite.run (node:internal/test_runner/test:1442:7)
+        async startSubtestAfterBootstrap (node:internal/test_runner/harness:297:3)
+      ...
+    1..2
+not ok 1 - a suite
+  ---
+  duration_ms: 6.475177
+  type: 'suite'
+  location: '/work/suite/test/s.test.mjs:3: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 69.244721
@@ -0,0 +1 @@
+{"name":"p","type":"module"}
@@ -0,0 +1,6 @@
+import { describe, it } from 'node:test';
+import assert from 'node:assert/strict';
+describe('a suite', () => {
+  it('passes inside', () => {});
+  it('fails inside', () => { console.log('a line the test printed'); assert.deepEqual({ a: 1 }, { a: 2 }); });
+});
@@ -0,0 +1,36 @@
+TAP version 13
+# Subtest: passes
+ok 1 - passes
+  ---
+  duration_ms: 0.929406
+  type: 'test'
+  ...
+# file:///work/syntax/test/b.test.mjs:3
+# SyntaxError: Unexpected end of input
+# [90m    at compileSourceTextModule (node:internal/modules/esm/utils:344:16)[39m
+# [90m    at ModuleLoader.moduleStrategy (node:internal/modules/esm/translators:106:18)[39m
+# [90m    at \#translate (node:internal/modules/esm/loader:490:12)[39m
+# [90m    at ModuleLoader.loadAndTranslate (node:internal/modules/esm/loader:537:27)[39m
+# [90m    at async ModuleJob._link (node:internal/modules/esm/module_job:116:19)[39m
+# Node.js v23.9.0
+# Subtest: test/b.test.mjs
+not ok 2 - test/b.test.mjs
+  ---
+  duration_ms: 37.927068
+  type: 'test'
+  location: '/work/syntax/test/b.test.mjs:1:1'
+  failureType: 'testCodeFailure'
+  exitCode: 1
+  signal: ~
+  error: 'test failed'
+  code: 'ERR_TEST_FAILURE'
+  ...
+1..2
+# tests 2
+# suites 0
+# pass 1
+# fail 1
+# cancelled 0
+# skipped 0
+# todo 0
+# duration_ms 68.264065
@@ -0,0 +1 @@
+{"name":"p","type":"module"}
@@ -0,0 +1,2 @@
+import test from 'node:test';
+test('passes', () => {});
@@ -0,0 +1,2 @@
+import test from "node:test";
+test("never loads", () => {;
@@ -0,0 +1,46 @@
+TAP version 13
+# Subtest: passes in the first file
+ok 1 - passes in the first file
+  ---
+  duration_ms: 0.596042
+  type: 'test'
+  ...
+# Subtest: fails in the second file
+not ok 2 - fails in the second file
+  ---
+  duration_ms: 1.962872
+  type: 'test'
+  location: '/work/two-files/test/b.test.mjs:3:1'
+  failureType: 'testCodeFailure'
+  error: |-
+    one plus one is not three
+    
+    2 !== 3
+    
+  code: 'ERR_ASSERTION'
+  name: 'AssertionError'
+  expected: 3
+  actual: 2
+  operator: 'strictEqual'
+  stack: |-
+    TestContext.<anonymous> (file:///work/two-files/test/b.test.mjs:3:49)
+    Test.runInAsyncScope (node:async_hooks:214:14)
+    Test.run (node:internal/test_runner/test:1047:25)
+    Test.start (node:internal/test_runner/test:944:17)
+    startSubtestAfterBootstrap (node:internal/test_runner/harness:297:17)
+  ...
+# Subtest: also passes
+ok 3 - also passes
+  ---
+  duration_ms: 0.148378
+  type: 'test'
+  ...
+1..3
+# tests 3
+# suites 0
+# pass 2
+# fail 1
+# cancelled 0
+# skipped 0
+# todo 0
+# duration_ms 69.115323
@@ -0,0 +1 @@
+{"name":"p","type":"module"}
@@ -0,0 +1,2 @@
+import test from 'node:test';
+test('passes in the first file', () => {});
@@ -0,0 +1,4 @@
+import test from 'node:test';
+import assert from 'node:assert/strict';
+test('fails in the second file', () => { assert.equal(1 + 1, 3, 'one plus one is not three'); });
+test('also passes', () => {});