From 47a66e3c0dc8dcdfd065a01358e04baf5917774d Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 26 Oct 2026 20:17:42 +0100 Subject: [PATCH] Take a crashed file's cause only from what the run wrote after the last test, give a subtest's panic to that subtest, and keep the SDK's test count (issue 1901, review round 1) --- go/buildstep/capacity_test.go | 9 +- go/buildstep/conformance/captured/README.md | 6 + .../conformance/captured/go/subpanic.jsonl | 30 ++++ .../captured/node/logcrash.console | 2 + .../conformance/captured/node/logcrash.tap | 42 +++++ go/buildstep/conformance/conformance.go | 5 +- go/buildstep/conformance/conformance_test.go | 165 ++++++++++++++---- go/buildstep/failure.go | 16 +- go/buildstep/failure_test.go | 98 ----------- go/buildstep/gotest.go | 37 +++- go/buildstep/tap.go | 40 ++++- 11 files changed, 293 insertions(+), 157 deletions(-) create mode 100644 go/buildstep/conformance/captured/go/subpanic.jsonl create mode 100644 go/buildstep/conformance/captured/node/logcrash.console create mode 100644 go/buildstep/conformance/captured/node/logcrash.tap delete mode 100644 go/buildstep/failure_test.go diff --git a/go/buildstep/capacity_test.go b/go/buildstep/capacity_test.go index a9d1a60..0cb0c56 100644 --- a/go/buildstep/capacity_test.go +++ b/go/buildstep/capacity_test.go @@ -7,8 +7,9 @@ import ( ) // 1887/A7: the node's build capacity is the build module's setting, read at every pull: the control-node at 0 pulls -// nothing, a change takes effect at the next read, and a setting that cannot be read pulls nothing. -func TestNodeCapacity(t *testing.T) { +// nothing, a change takes effect at the next read, and a setting that cannot be read pulls nothing. ADR 0553 §4: a +// step's threads are the composer's share over the module's own capacity; without the word, none. +func TestNodeCapacityAndLimits(t *testing.T) { if got := NodeCapacity("", DefaultCapacities, "novox", nil)(); got != 0 { t.Errorf("novox = %d by default, want 0", got) } @@ -35,10 +36,6 @@ func TestNodeCapacity(t *testing.T) { if got := NodeCapacity(filepath.Join(t.TempDir(), "none"), DefaultCapacities, "shanks", nil)(); got != 0 { t.Errorf("a missing file = %d, want 0", got) } -} - -// ADR 0553 §4: a step's threads are the composer's share over the module's own capacity; without the word, none. -func TestNodeLimits(t *testing.T) { t.Setenv("MESH_BUILD_CPU_SHARE", "") if l := NodeLimits(3); l.Threads != 0 || l.Slots != 3 { t.Errorf("without the word: %+v", l) diff --git a/go/buildstep/conformance/captured/README.md b/go/buildstep/conformance/captured/README.md index db9f3dd..3c882c9 100644 --- a/go/buildstep/conformance/captured/README.md +++ b/go/buildstep/conformance/captured/README.md @@ -17,6 +17,9 @@ table (conformance.go) says what each failure must say. and a passing test before the failing one. - subtests: module `example.com/subtests`; `TestTheTable` runs `t.Run("passes", func(t *testing.T) {})` and `t.Run("fails", func(t *testing.T) { t.Errorf("got 3 machines, want 4") })`: the parent fails only by its subtest. +- `subpanic.jsonl` (2026-10-26, go1.27.3-X:nodwarf5, review round 1 of issue 1901's fix), the same way: module + `example.com/subpanic`; `TestTable` runs `t.Run("passes", func(t *testing.T) {})` and `t.Run("panics", ...)`, which + writes to a nil map. go test -json files the subtest's panic under the parent `TestTable`. - `logthenfatal.jsonl`, `panicking`, `timeout`, `deeptimeout`, `buildfail`, `exiting`, `killed`, `passthenfail`, `mainexit`, `race`, `racemain` were captured for issue 1901's first and third meetings (2026-10-23 and 2026-10-25, go1.27.3) in mesh-catalog's mesh-build-go (`testdata/captured/go-test-json-*.jsonl`, named there `go-test-json-pkg-` @@ -51,6 +54,9 @@ way mesh-build-node runs a test script: - crash: `test/a.test.ts` holds `test('passes before the crash', () => {})`; `test/b.test.ts` holds `test('throws after it returned', ...)`, which throws `new Error('the bus closed under the test')` in a `setTimeout` of 1 ms, and `test('waits after the throw', ...)`, which waits 50 ms: node fails the file with an uncaught exception. +- logcrash (review round 1): `test/a.test.ts` holds `test('passes and logs', ...)`, which logs + `retrying after Error: the store was not ready yet`; `test/b.test.ts` is crash's. A passing test's console line + holding "Error" comes before the crash's own. - timeout: `test/a.test.ts` holds `test('passes before the wait', () => {})` and `test('waits for an answer that never comes', { timeout: 200 }, async () => { await new Promise(() => {}); })`. - syntax: `test/a.test.ts` holds `test('passes in the first file', () => {})`; `test/b.test.ts` is diff --git a/go/buildstep/conformance/captured/go/subpanic.jsonl b/go/buildstep/conformance/captured/go/subpanic.jsonl new file mode 100644 index 0000000..ec85af7 --- /dev/null +++ b/go/buildstep/conformance/captured/go/subpanic.jsonl @@ -0,0 +1,30 @@ +{"Time":"2026-10-26T20:15:37.791161045+01:00","Action":"start","Package":"example.com/subpanic"} +{"Time":"2026-10-26T20:15:37.793205666+01:00","Action":"run","Package":"example.com/subpanic","Test":"TestTable"} +{"Time":"2026-10-26T20:15:37.793257158+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"=== RUN TestTable\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.793288149+01:00","Action":"run","Package":"example.com/subpanic","Test":"TestTable/passes"} +{"Time":"2026-10-26T20:15:37.793290669+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable/passes","Output":"=== RUN TestTable/passes\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.793298009+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable/passes","Output":"--- PASS: TestTable/passes (0.00s)\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.793311679+01:00","Action":"pass","Package":"example.com/subpanic","Test":"TestTable/passes","Elapsed":0} +{"Time":"2026-10-26T20:15:37.79331977+01:00","Action":"run","Package":"example.com/subpanic","Test":"TestTable/panics"} +{"Time":"2026-10-26T20:15:37.79332377+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable/panics","Output":"=== RUN TestTable/panics\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.79332773+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable/panics","Output":"--- FAIL: TestTable/panics (0.00s)\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.79333111+01:00","Action":"fail","Package":"example.com/subpanic","Test":"TestTable/panics","Elapsed":0} +{"Time":"2026-10-26T20:15:37.79333383+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"--- FAIL: TestTable (0.00s)\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.795322529+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"panic: assignment to entry in nil map [recovered, repanicked]\n"} +{"Time":"2026-10-26T20:15:37.795331489+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\n"} +{"Time":"2026-10-26T20:15:37.795340579+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"goroutine 9 [running]:\n"} +{"Time":"2026-10-26T20:15:37.79534387+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"testing.tRunner.func1.2({0x6b7010, 0x6eef80})\n"} +{"Time":"2026-10-26T20:15:37.79534657+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\t/usr/lib/go/src/testing/testing.go:2125 +0x232\n"} +{"Time":"2026-10-26T20:15:37.79534907+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"testing.tRunner.func1()\n"} +{"Time":"2026-10-26T20:15:37.79535172+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\t/usr/lib/go/src/testing/testing.go:2128 +0x329\n"} +{"Time":"2026-10-26T20:15:37.79535625+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"panic({0x6b7010?, 0x6eef80?})\n"} +{"Time":"2026-10-26T20:15:37.79535879+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\t/usr/lib/go/src/runtime/panic.go:859 +0x125\n"} +{"Time":"2026-10-26T20:15:37.79536129+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"example.com/subpanic.TestTable.func2(0x3b39436666c8?)\n"} +{"Time":"2026-10-26T20:15:37.79536452+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\t/tmp/1901k/go/subpanic/p_test.go:7 +0x28\n"} +{"Time":"2026-10-26T20:15:37.79536782+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"testing.tRunner(0x3b39436666c8, 0x6d4b58)\n"} +{"Time":"2026-10-26T20:15:37.7953704+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\t/usr/lib/go/src/testing/testing.go:2195 +0xea\n"} +{"Time":"2026-10-26T20:15:37.79537289+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"created by testing.(*T).Run in goroutine 7\n"} +{"Time":"2026-10-26T20:15:37.795381681+01:00","Action":"output","Package":"example.com/subpanic","Test":"TestTable","Output":"\t/usr/lib/go/src/testing/testing.go:2260 +0x4d4\n"} +{"Time":"2026-10-26T20:15:37.795731441+01:00","Action":"fail","Package":"example.com/subpanic","Test":"TestTable","Elapsed":0} +{"Time":"2026-10-26T20:15:37.795759332+01:00","Action":"output","Package":"example.com/subpanic","Output":"FAIL\texample.com/subpanic\t0.004s\n","OutputType":"frame"} +{"Time":"2026-10-26T20:15:37.795783503+01:00","Action":"fail","Package":"example.com/subpanic","Elapsed":0.005} diff --git a/go/buildstep/conformance/captured/node/logcrash.console b/go/buildstep/conformance/captured/node/logcrash.console new file mode 100644 index 0000000..90a8ef6 --- /dev/null +++ b/go/buildstep/conformance/captured/node/logcrash.console @@ -0,0 +1,2 @@ +npm notice run test +npm notice run node --test --experimental-strip-types 'test/*.test.ts' diff --git a/go/buildstep/conformance/captured/node/logcrash.tap b/go/buildstep/conformance/captured/node/logcrash.tap new file mode 100644 index 0000000..89dbfb8 --- /dev/null +++ b/go/buildstep/conformance/captured/node/logcrash.tap @@ -0,0 +1,42 @@ +TAP version 13 +# retrying after Error: the store was not ready yet +# Subtest: passes and logs +ok 1 - passes and logs + --- + duration_ms: 1.184595 + type: 'test' + ... +# Subtest: throws after it returned +ok 2 - throws after it returned + --- + duration_ms: 0.748862 + type: 'test' + ... +# Subtest: waits after the throw +ok 3 - waits after the throw + --- + duration_ms: 51.019875 + type: 'test' + ... +# Error: Test "throws after it returned" at test/b.test.ts:2:1 generated asynchronous activity after the test ended. This activity created the error "Error: the bus closed under the test" and would have caused the test to fail, but instead triggered an uncaughtException event. +# Subtest: test/b.test.ts +not ok 2 - test/b.test.ts + --- + duration_ms: 172.91715 + type: 'test' + location: '/tmp/1901k/node/logcrash/test/b.test.ts:1:1' + failureType: 'testCodeFailure' + exitCode: 1 + signal: ~ + error: 'test failed' + code: 'ERR_TEST_FAILURE' + ... +1..4 +# tests 4 +# suites 0 +# pass 3 +# fail 1 +# cancelled 0 +# skipped 0 +# todo 0 +# duration_ms 185.744334 diff --git a/go/buildstep/conformance/conformance.go b/go/buildstep/conformance/conformance.go index 45be842..42c2ca1 100644 --- a/go/buildstep/conformance/conformance.go +++ b/go/buildstep/conformance/conformance.go @@ -51,7 +51,7 @@ type Case struct { File string // Cause holds what the failure's cause must contain. Cause []string - // Passing are the names of tests that passed in the run: no failure's words may hold them. + // Passing are the names of tests that passed in the run, and what they logged: no failure's words may hold them. Passing []string } @@ -83,6 +83,7 @@ var cases = []Case{ {Name: "passthenfail", Runner: GoTest, Cause: []string{"panic: the bus closed after the tests: nats: connection closed"}}, {Name: "mainexit", Runner: GoTest, Cause: []string{"passed", "exited"}}, {Name: "race", Runner: GoTest, Test: "TestRacesOnTheSeat", Cause: []string{"DATA RACE", "Write at", "example.com/race.TestRacesOnTheSeat.func1()", "p_test.go:13", "created at example.com/race.TestRacesOnTheSeat()"}}, + {Name: "subpanic", Runner: GoTest, Test: "TestTable/panics", Cause: []string{"panic: assignment to entry in nil map"}, Passing: []string{"TestTable/passes"}}, {Name: "racemain", Runner: GoTest, Cause: []string{"DATA RACE", "Write at", "example.com/racemain.TestMain.func1()", "p_test.go:15", "created at example.com/racemain.TestMain()"}}, {Name: "two-files", Runner: NodeTest, Test: "fails in the second file", File: "test/b.test.ts:4:1", Cause: []string{"one plus one is not three"}, @@ -91,6 +92,8 @@ var cases = []Case{ Passing: []string{"passes inside"}}, {Name: "crash", Runner: NodeTest, Test: "test/b.test.ts", File: "test/b.test.ts:1:1", Cause: []string{"the bus closed under the test"}, Passing: []string{"passes before the crash"}}, + {Name: "logcrash", Runner: NodeTest, Test: "test/b.test.ts", File: "test/b.test.ts:1:1", Cause: []string{"the bus closed under the test"}, + Passing: []string{"passes and logs", "retrying after Error: the store was not ready yet"}}, {Name: "timeout", Runner: NodeTest, Test: "waits for an answer that never comes", File: "test/a.test.ts:3:1", Cause: []string{"test timed out after 200ms"}, Passing: []string{"passes before the wait"}}, {Name: "syntax", Runner: NodeTest, Test: "test/b.test.ts", File: "test/b.test.ts:1:1", Cause: []string{"SyntaxError", "Expected ',', got ''"}, diff --git a/go/buildstep/conformance/conformance_test.go b/go/buildstep/conformance/conformance_test.go index e54c676..2e1648d 100644 --- a/go/buildstep/conformance/conformance_test.go +++ b/go/buildstep/conformance/conformance_test.go @@ -1,55 +1,148 @@ package conformance import ( + "encoding/json" "strings" "testing" "git.novox.be/novox/mesh-sdk/go/buildstep" ) -// 1901/AC6: the SDK's own parsers keep the contract on every captured case of the kit. -func TestTheSDKParsersKeepTheFailureContract(t *testing.T) { - Run(t, GoTest, func(o Output) []buildstep.Failure { return buildstep.ReadGoTest(o.Stdout, ".").Failed }) - Run(t, NodeTest, func(o Output) []buildstep.Failure { return buildstep.ReadTAP(".", "test", o.Dir, o.Report, o.Stdout) }) - Run(t, TypeCheck, func(o Output) []buildstep.Failure { - return []buildstep.Failure{buildstep.ConsoleFailure(".", "type-check", o.Stdout+o.Stderr)} +// The failure contract (issue 1901): the SDK's own parsers keep it on every captured case of the kit (1901/AC6); the +// kit refuses what the build modules sent before it; the contract's own rules; and the Go reader's older guarantees. +func TestTheFailureContract(t *testing.T) { + t.Run("the SDK parsers keep it", func(t *testing.T) { + Run(t, GoTest, func(o Output) []buildstep.Failure { return buildstep.ReadGoTest(o.Stdout, ".").Failed }) + Run(t, NodeTest, func(o Output) []buildstep.Failure { return buildstep.ReadTAP(".", "test", o.Dir, o.Report, o.Stdout) }) + Run(t, TypeCheck, func(o Output) []buildstep.Failure { + return []buildstep.Failure{buildstep.ConsoleFailure(".", "type-check", o.Stdout+o.Stderr)} + }) }) -} -// The kit refuses what the build modules sent before the contract (issue 1901): node's output cut to its first fifteen -// lines with no cause, whose first line was a passing test of the first file, and a Go failure keeping its first line. -func TestTheKitRefusesAFailureThatHidesItsCause(t *testing.T) { - firstLines := func(s string) string { // mesh-build-node's lines() before the contract - var keep []string - for _, l := range strings.Split(s, "\n") { - if l = strings.TrimSpace(l); l != "" && len(keep) < 15 { - keep = append(keep, l) + // node's output cut to its first fifteen lines with no cause, whose first line was a passing test of the first file + // (mesh-build-node's lines() before the contract), and a Go failure keeping its first line. + t.Run("the kit refuses a failure that hides its cause", func(t *testing.T) { + firstLines := func(s string) string { + var keep []string + for _, l := range strings.Split(s, "\n") { + if l = strings.TrimSpace(l); l != "" && len(keep) < 15 { + keep = append(keep, l) + } + } + return strings.Join(keep, "\n") + } + for _, c := range []struct { + runner, name string + old func(Output) []buildstep.Failure + }{ + {NodeTest, "two-files", func(o Output) []buildstep.Failure { + return []buildstep.Failure{{Package: ".", Test: "test", Output: firstLines(o.Report)}} + }}, + {GoTest, "passfirst", func(o Output) []buildstep.Failure { + return []buildstep.Failure{{Package: "example.com/passfirst/b", Test: "TestTheSecondPackageFails", Cause: "ok \texample.com/passfirst/a", Output: "--- PASS: TestTheSecondPackagePassesFirst"}} + }}, + } { + for _, k := range Cases(c.runner) { + if k.Name != c.name { + continue + } + out, err := Load(k) + if err != nil { + t.Fatal(err) + } + if problems := Judge(k, c.old(out)); len(problems) == 0 { + t.Errorf("%s %s: the kit passed a failure that hides its cause", c.runner, c.name) + } } } - return strings.Join(keep, "\n") - } - for _, c := range []struct { - runner, name string - old func(Output) []buildstep.Failure - }{ - {NodeTest, "two-files", func(o Output) []buildstep.Failure { - return []buildstep.Failure{{Package: ".", Test: "test", Output: firstLines(o.Report)}} - }}, - {GoTest, "passfirst", func(o Output) []buildstep.Failure { - return []buildstep.Failure{{Package: "example.com/passfirst/b", Test: "TestTheSecondPackageFails", Cause: "ok \texample.com/passfirst/a", Output: "--- PASS: TestTheSecondPackagePassesFirst"}} - }}, - } { - for _, k := range Cases(c.runner) { - if k.Name != c.name { - continue + }) + + // What a passing line is (a test's own line starting "ok " is none), when a failure hides its cause, and that a long + // failure keeps its last lines within the bound and starts with a real line for an older checker, which reads only + // the first line of the output cut to 120 characters (1901/AC1, AC3). + t.Run("its rules", func(t *testing.T) { + for _, c := range []struct { + line string + passing bool + }{ + {"✔ the same merge has the same id (8.0ms)", true}, {"ok 1 - passes", true}, {" ok 3 - inside", true}, + {"ok \texample.com/a\t0.01s", true}, {"PASS", true}, {"--- PASS: TestA (0.00s)", true}, + {" --- PASS: TestA/sub (0.00s)", true}, {"✖ fails (1ms)", false}, {"not ok 2 - fails", false}, + {"okay, the seat moved", false}, {"ok then: the store refused the write", false}, {"ok the seat", false}, {"FAIL", false}, + } { + if buildstep.PassingLine(c.line) != c.passing { + t.Errorf("PassingLine(%q) = %v, want %v", c.line, !c.passing, c.passing) } - out, err := Load(k) + } + if buildstep.Hidden(buildstep.Failure{Cause: "the seat has 2 holders"}) != "" || buildstep.Hidden(buildstep.Failure{}) == "" || + buildstep.Hidden(buildstep.Failure{Cause: "✔ passes (1ms)"}) == "" { + t.Error("Hidden does not tell a real cause from none and from a passing line") + } + var lines []string + for i := 0; i < 400; i++ { + lines = append(lines, " x_test.go:1: log line "+strings.Repeat("y", 40)) + } + lines = append(lines, " x_test.go:9: the real cause", "--- FAIL: TestX (0.00s)") + oldFirst := func(out string) string { // the older checker's rule (judge.go firstLine before issue 1901) + for _, l := range strings.Split(out, "\n") { + if l = strings.TrimSpace(l); l != "" { + return l[:min(len(l), 120)] + } + } + return "" + } + for _, cause := range []string{"the real cause", ""} { + out := buildstep.Clip(lines, cause) + if len(out) > buildstep.OutputBytes+buildstep.LineBytes { + t.Errorf("1901/AC1: kept %d bytes, bound is %d", len(out), buildstep.OutputBytes) + } + if !strings.HasSuffix(out, "the real cause\n--- FAIL: TestX (0.00s)") || !strings.Contains(out, "\n... (") { + t.Errorf("1901/AC1: the last lines or the marker are lost: %q...%q", out[:40], out[len(out)-60:]) + } + if got := oldFirst(out); strings.HasPrefix(got, "... (") || got == "" || (cause != "" && got != cause) { + t.Errorf("1901/AC3: cause %q: an older checker would read %q", cause, got) + } + } + }) + + // The Go reader (moved from mesh-build-go): an older checker, which knows no "cause" field, still reads a failure and + // gets at least the lines it kept (1901/AC3); a test's indented log line saying "panic:" is not the cause, go's own at + // column 0 is (1901/AC4); and each package counts its own skipped tests (issue 890). + t.Run("the Go reader", func(t *testing.T) { + read := func(name string) string { + raw, err := captured.ReadFile("captured/go/" + name + ".jsonl") if err != nil { t.Fatal(err) } - if problems := Judge(k, c.old(out)); len(problems) == 0 { - t.Errorf("%s %s: the kit passed a failure that hides its cause", c.runner, c.name) - } + return string(raw) } - } + b, _ := json.Marshal(buildstep.ReadGoTest(read("logthenfatal"), ".").Failed) + var old []struct { + Output string `json:"output,omitempty"` + } + if err := json.Unmarshal(b, &old); err != nil || len(old) != 1 || !strings.Contains(old[0].Output, "judged against") || !strings.Contains(old[0].Output, "3 subscription(s)") { + t.Errorf("1901/AC3: an older checker reads %+v, %v", old, err) + } + lines := strings.SplitAfter(read("deeptimeout"), "\n") + added := `{"Action":"output","Package":"example.com/deeptimeout","Test":"TestHoldsTheSeat","Output":" p_test.go:9: the child said:\n"}` + "\n" + + `{"Action":"output","Package":"example.com/deeptimeout","Test":"TestHoldsTheSeat","Output":" panic: child retried and recovered\n"}` + "\n" + + `{"Action":"output","Package":"example.com/deeptimeout","Test":"TestHoldsTheSeat","Output":" WARNING: DATA RACE\n"}` + "\n" + if got := buildstep.ReadGoTest(strings.Join(lines[:10], "")+added+strings.Join(lines[10:], ""), ".").Failed; len(got) != 1 || !strings.HasPrefix(got[0].Cause, "panic: test timed out after 2s") { + t.Errorf("1901/AC4: failures = %+v, want the timeout's panic as the cause", got) + } + res := buildstep.ReadGoTest(`{"Action":"run","Package":"m/a","Test":"TestA"} +{"Action":"skip","Package":"m/a","Test":"TestA","Elapsed":0} +{"Action":"run","Package":"m/b","Test":"TestB"} +{"Action":"pass","Package":"m/b","Test":"TestB","Elapsed":0} +{"Action":"pass","Package":"m/a","Elapsed":0} +{"Action":"pass","Package":"m/b","Elapsed":0} +`, ".") + got := map[string]int{} + for _, p := range res.Packages { + got[p.Package] = p.Skipped + } + if res.Skipped != 1 || got["m/a"] != 1 || got["m/b"] != 0 { + t.Errorf("skipped = %d, per package %v, want 1 with m/a 1 and m/b 0", res.Skipped, got) + } + }) } diff --git a/go/buildstep/failure.go b/go/buildstep/failure.go index 98100fa..78c27af 100644 --- a/go/buildstep/failure.go +++ b/go/buildstep/failure.go @@ -44,16 +44,18 @@ func By(module string) string { return module + " with mesh-sdk " + sdkversion.Version() } -// PassingLine says a line is a test runner's word for a test or a package that passed: node's '✔', TAP's and go test's -// "ok", go test's "PASS" and "--- PASS". Such a line is never a failure's cause, nor part of a failure's output. +// PassingLine says a line is a test runner's word for a test or a package that passed: node's '✔', TAP's "ok N" (at any +// indent), go test's "ok \t", "PASS" and "--- PASS". A line of a test's own that starts "ok " is none of these. Such a line is never a failure's cause, nor part of a failure's output. func PassingLine(l string) bool { - t := strings.TrimSpace(l) - switch { - case t == "PASS", t == "ok", strings.HasPrefix(t, "✔"), strings.HasPrefix(t, "--- PASS"), - strings.HasPrefix(t, "ok "), strings.HasPrefix(t, "ok\t"): + if strings.HasPrefix(l, "ok \t") { // go test's package line, at column 0 return true } - return false + t := strings.TrimSpace(l) + switch { + case t == "PASS", strings.HasPrefix(t, "✔"), strings.HasPrefix(t, "--- PASS"): + return true + } + return tapOk(t) } // Hidden says how a failure hides why it failed, or "" when it does not: it has no cause, or its cause is a passing line. diff --git a/go/buildstep/failure_test.go b/go/buildstep/failure_test.go deleted file mode 100644 index 6aa4622..0000000 --- a/go/buildstep/failure_test.go +++ /dev/null @@ -1,98 +0,0 @@ -package buildstep - -import ( - "encoding/json" - "os" - "strings" - "testing" -) - -// The contract's own rules (issue 1901): what a passing line is, when a failure hides its cause, and that a long failure -// keeps its last lines within the bound and starts with a real line for an older checker, which reads only the first -// line of the output cut to 120 characters (1901/AC1, AC3, moved from mesh-build-go). -func TestTheFailureContractsRules(t *testing.T) { - for _, c := range []struct { - line string - passing bool - }{ - {"✔ the same merge has the same id (8.0ms)", true}, {"ok 1 - passes", true}, {"ok \texample.com/a\t0.01s", true}, - {"PASS", true}, {"--- PASS: TestA (0.00s)", true}, {" --- PASS: TestA/sub (0.00s)", true}, - {"✖ fails (1ms)", false}, {"not ok 2 - fails", false}, {"okay, the seat moved", false}, {"FAIL", false}, - } { - if PassingLine(c.line) != c.passing { - t.Errorf("PassingLine(%q) = %v, want %v", c.line, !c.passing, c.passing) - } - } - if Hidden(Failure{Cause: "the seat has 2 holders"}) != "" || Hidden(Failure{}) == "" || Hidden(Failure{Cause: "✔ passes (1ms)"}) == "" { - t.Error("Hidden does not tell a real cause from none and from a passing line") - } - - var lines []string - for i := 0; i < 400; i++ { - lines = append(lines, " x_test.go:1: log line "+strings.Repeat("y", 40)) - } - lines = append(lines, " x_test.go:9: the real cause", "--- FAIL: TestX (0.00s)") - oldFirst := func(out string) string { // the older checker's rule (judge.go firstLine before issue 1901) - for _, l := range strings.Split(out, "\n") { - if l = strings.TrimSpace(l); l != "" { - return l[:min(len(l), 120)] - } - } - return "" - } - for _, cause := range []string{"the real cause", ""} { - out := Clip(lines, cause) - if len(out) > OutputBytes+LineBytes { - t.Errorf("1901/AC1: kept %d bytes, bound is %d", len(out), OutputBytes) - } - if !strings.HasSuffix(out, "the real cause\n--- FAIL: TestX (0.00s)") || !strings.Contains(out, "\n... (") { - t.Errorf("1901/AC1: the last lines or the marker are lost: %q...%q", out[:40], out[len(out)-60:]) - } - if got := oldFirst(out); strings.HasPrefix(got, "... (") || got == "" || (cause != "" && got != cause) { - t.Errorf("1901/AC3: cause %q: an older checker would read %q", cause, got) - } - } -} - -// The Go reader (moved from mesh-build-go): an older checker, which knows no "cause" field, still reads a failure and -// gets at least the lines it kept (1901/AC3); a test's indented log line saying "panic:" is not the cause, go's own at -// column 0 is (1901/AC4); and each package counts its own skipped tests (issue 890). -func TestTheGoReader(t *testing.T) { - read := func(name string) string { - raw, err := os.ReadFile("conformance/captured/go/" + name + ".jsonl") - if err != nil { - t.Fatal(err) - } - return string(raw) - } - b, _ := json.Marshal(ReadGoTest(read("logthenfatal"), ".").Failed) - var old []struct { - Output string `json:"output,omitempty"` - } - if err := json.Unmarshal(b, &old); err != nil || len(old) != 1 || !strings.Contains(old[0].Output, "judged against") || !strings.Contains(old[0].Output, "3 subscription(s)") { - t.Errorf("1901/AC3: an older checker reads %+v, %v", old, err) - } - - lines := strings.SplitAfter(read("deeptimeout"), "\n") - added := `{"Action":"output","Package":"example.com/deeptimeout","Test":"TestHoldsTheSeat","Output":" p_test.go:9: the child said:\n"}` + "\n" + - `{"Action":"output","Package":"example.com/deeptimeout","Test":"TestHoldsTheSeat","Output":" panic: child retried and recovered\n"}` + "\n" + - `{"Action":"output","Package":"example.com/deeptimeout","Test":"TestHoldsTheSeat","Output":" WARNING: DATA RACE\n"}` + "\n" - if got := ReadGoTest(strings.Join(lines[:10], "")+added+strings.Join(lines[10:], ""), ".").Failed; len(got) != 1 || !strings.HasPrefix(got[0].Cause, "panic: test timed out after 2s") { - t.Errorf("1901/AC4: failures = %+v, want the timeout's panic as the cause", got) - } - - res := ReadGoTest(`{"Action":"run","Package":"m/a","Test":"TestA"} -{"Action":"skip","Package":"m/a","Test":"TestA","Elapsed":0} -{"Action":"run","Package":"m/b","Test":"TestB"} -{"Action":"pass","Package":"m/b","Test":"TestB","Elapsed":0} -{"Action":"pass","Package":"m/a","Elapsed":0} -{"Action":"pass","Package":"m/b","Elapsed":0} -`, ".") - got := map[string]int{} - for _, p := range res.Packages { - got[p.Package] = p.Skipped - } - if res.Skipped != 1 || got["m/a"] != 1 || got["m/b"] != 0 { - t.Errorf("skipped = %d, per package %v, want 1 with m/a 1 and m/b 0", res.Skipped, got) - } -} diff --git a/go/buildstep/gotest.go b/go/buildstep/gotest.go index cd3e997..7db4c8c 100644 --- a/go/buildstep/gotest.go +++ b/go/buildstep/gotest.go @@ -169,16 +169,20 @@ func (r *goReader) event(ev goEvent) { if r.subtestFailed(ev.Package, ev.Test) { return // a parent failed only by its subtest is that subtest's failure, said once } + if r.subtestTakesTheCause(ev.Package, ev.Test) { + return // a subtest's panic, which go files under its parent, is said on the subtest + } r.res.Failed = append(r.res.Failed, r.testFailure(ev.Package, ev.Test)) } } } } -// subtestFailed says a failure of test under pkg was already reported for one of its subtests (they end first), and the -// test reported no error of its own. +// subtestFailed says a failure of test under pkg was already reported for one of its subtests (they end first), each with +// a cause of its own, and the test reported no error and no runtime cause (a subtest's panic) of its own. func (r *goReader) subtestFailed(pkg, test string) bool { - if r.causes[pkg+"\x00"+test] != "" { + key := pkg + "\x00" + test + if r.causes[key] != "" || goRuntimeCause(r.testOut[key]) != "" { return false } for _, f := range r.res.Failed { @@ -189,6 +193,31 @@ func (r *goReader) subtestFailed(pkg, test string) bool { return false } +// noMessage is the cause of a test that failed and said nothing of why. +const noMessage = "the test failed without an error message (t.Fail or t.FailNow)" + +// subtestTakesTheCause gives a parent's runtime cause (a subtest's panic: go test -json files its lines under the +// parent) to the subtests of that parent that failed with no message of their own, and says it did. A parent with an +// error line of its own, or whose failed subtests each said why, is reported as itself. +func (r *goReader) subtestTakesTheCause(pkg, test string) bool { + key := pkg + "\x00" + test + if r.causes[key] != "" { + return false + } + cause := goRuntimeCause(r.testOut[key]) + if cause == "" { + return false + } + took := false + for i, f := range r.res.Failed { + if f.Package == pkg && strings.HasPrefix(f.Test, test+"/") && f.Cause == noMessage { + r.res.Failed[i].Cause, r.res.Failed[i].Output = cause, Clip(r.testOut[key], cause) + took = true + } + } + return took +} + // testFailure is a test that failed: its cause is its first error line, the race it ran into, the runtime's line, or // words saying it failed without a message. func (r *goReader) testFailure(pkg, test string) Failure { @@ -200,7 +229,7 @@ func (r *goReader) testFailure(pkg, test string) Failure { cause = goRuntimeCause(r.testOut[key]) } if cause == "" { - cause = "the test failed without an error message (t.Fail or t.FailNow)" + cause = noMessage } return Failure{Package: pkg, Test: test, Output: Clip(r.testOut[key], cause), Cause: cause} } diff --git a/go/buildstep/tap.go b/go/buildstep/tap.go index 3cea35a..09331a0 100644 --- a/go/buildstep/tap.go +++ b/go/buildstep/tap.go @@ -30,10 +30,15 @@ func stripANSI(s string) string { return ansiEscape.ReplaceAllString(s, "") } func ReadTAP(pkg, script, dir, report, console string) []Failure { var failed []Failure all := strings.Split(stripANSI(strings.ReplaceAll(report, "\r\n", "\n")), "\n") - prev := 0 // the line after the last test block: what the run wrote since belongs to the next test + var cancelled []Failure // failed because a suite around them did: said after the failure that carries the cause + prev := 0 // the line after the last test block, passing or not: what the run wrote since belongs to the next test for i := 0; i < len(all); i++ { name, ok := tapNotOk(all[i]) if !ok { + if tapOk(all[i]) { + i = tapBlockEnd(all, i) - 1 + prev = i + 1 + } continue } indent := len(all[i]) - len(strings.TrimLeft(all[i], " ")) @@ -65,7 +70,7 @@ func ReadTAP(pkg, script, dir, report, console string) []Failure { fields[key] = t // the first line of a block scalar } } - from := prev + from, at := prev, i i, prev = j-1, j if fields["failureType"] == "subtestsFailed" { continue @@ -75,7 +80,7 @@ func ReadTAP(pkg, script, dir, report, console string) []Failure { // a file that did not load, or an error after a test ended: node says only "test failed" and wrote the // error as comment lines before it var own []string - for _, l := range all[from:i] { + for _, l := range all[from:at] { if t := strings.TrimSpace(l); strings.HasPrefix(t, "# ") && !strings.HasPrefix(t, "# Subtest") { own = append(own, strings.TrimPrefix(t, "# ")) } @@ -102,9 +107,14 @@ func ReadTAP(pkg, script, dir, report, console string) []Failure { if dir != "" { file = strings.TrimPrefix(file, strings.TrimSuffix(dir, "/")+"/") } - failed = append(failed, Failure{Package: pkg, Test: name, File: file, Cause: cause, Output: Clip(block, cause)}) + f := Failure{Package: pkg, Test: name, File: file, Cause: cause, Output: Clip(block, cause)} + if fields["failureType"] == "cancelledByParent" { + cancelled = append(cancelled, f) + continue + } + failed = append(failed, f) } - if len(failed) > 0 { + if failed = append(failed, cancelled...); len(failed) > 0 { return failed } var comments []string @@ -126,6 +136,26 @@ func tapCount(t string) bool { return false } +// tapOk says a line is a passing test's "ok N - name", indented or not. +func tapOk(l string) bool { + rest, ok := strings.CutPrefix(strings.TrimSpace(l), "ok ") + return ok && rest != "" && rest[0] >= '0' && rest[0] <= '9' +} + +// tapBlockEnd is the line after the test line at i and its YAML block ("---" to "..."). +func tapBlockEnd(all []string, i int) int { + j := i + 1 + if j >= len(all) || strings.TrimSpace(all[j]) != "---" { + return j + } + for j++; j < len(all); j++ { + if strings.TrimSpace(all[j]) == "..." { + return j + 1 + } + } + return j +} + // tapNotOk is the test name of a "not ok N - name" line, indented or not; a TODO or SKIP directive fails nothing. func tapNotOk(l string) (string, bool) { t := strings.TrimSpace(l)