diff --git a/modules/mesh-build-node/cmd/mesh-build-node/check.go b/modules/mesh-build-node/cmd/mesh-build-node/check.go index 1bf8c379..286fc5db 100644 --- a/modules/mesh-build-node/cmd/mesh-build-node/check.go +++ b/modules/mesh-build-node/cmd/mesh-build-node/check.go @@ -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)) +} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/check_test.go b/modules/mesh-build-node/cmd/mesh-build-node/check_test.go index 5a95a94a..ce5b63b2 100644 --- a/modules/mesh-build-node/cmd/mesh-build-node/check_test.go +++ b/modules/mesh-build-node/cmd/mesh-build-node/check_test.go @@ -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) + } + } + } +} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/tap.go b/modules/mesh-build-node/cmd/mesh-build-node/tap.go new file mode 100644 index 00000000..05bc2ec4 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/tap.go @@ -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") +} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/README.md b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/README.md new file mode 100644 index 00000000..8b225f5d --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/README.md @@ -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. diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite.tap b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite.tap new file mode 100644 index 00000000..253c6638 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite.tap @@ -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: + + actual - expected + +  { + + a: 1 + - a: 2 +  } + + code: 'ERR_ASSERTION' + name: 'AssertionError' + expected: + a: 2 + actual: + a: 1 + operator: 'deepStrictEqual' + stack: |- + TestContext. (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 diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite/package.json b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite/package.json new file mode 100644 index 00000000..192c20b0 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite/package.json @@ -0,0 +1 @@ +{"name":"p","type":"module"} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite/test/s.test.mjs b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite/test/s.test.mjs new file mode 100644 index 00000000..779d75c8 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/suite/test/s.test.mjs @@ -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 }); }); +}); diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax.tap b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax.tap new file mode 100644 index 00000000..2265a3c8 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax.tap @@ -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 +#  at compileSourceTextModule (node:internal/modules/esm/utils:344:16) +#  at ModuleLoader.moduleStrategy (node:internal/modules/esm/translators:106:18) +#  at \#translate (node:internal/modules/esm/loader:490:12) +#  at ModuleLoader.loadAndTranslate (node:internal/modules/esm/loader:537:27) +#  at async ModuleJob._link (node:internal/modules/esm/module_job:116:19) +# 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 diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/package.json b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/package.json new file mode 100644 index 00000000..192c20b0 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/package.json @@ -0,0 +1 @@ +{"name":"p","type":"module"} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/test/a.test.mjs b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/test/a.test.mjs new file mode 100644 index 00000000..d6da2f24 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/test/a.test.mjs @@ -0,0 +1,2 @@ +import test from 'node:test'; +test('passes', () => {}); diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/test/b.test.mjs b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/test/b.test.mjs new file mode 100644 index 00000000..7ca43fcd --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/syntax/test/b.test.mjs @@ -0,0 +1,2 @@ +import test from "node:test"; +test("never loads", () => {; diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files.tap b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files.tap new file mode 100644 index 00000000..b9cf8072 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files.tap @@ -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. (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 diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/package.json b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/package.json new file mode 100644 index 00000000..192c20b0 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/package.json @@ -0,0 +1 @@ +{"name":"p","type":"module"} diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/test/a.test.mjs b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/test/a.test.mjs new file mode 100644 index 00000000..9415092b --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/test/a.test.mjs @@ -0,0 +1,2 @@ +import test from 'node:test'; +test('passes in the first file', () => {}); diff --git a/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/test/b.test.mjs b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/test/b.test.mjs new file mode 100644 index 00000000..62f13319 --- /dev/null +++ b/modules/mesh-build-node/cmd/mesh-build-node/testdata/node-test-tap/two-files/test/b.test.mjs @@ -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', () => {});