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)

2026-10-26 20:17:42 +01:00
parent 81ec7bd7de
commit 47a66e3c0d
11 changed files with 293 additions and 157 deletions
@@ -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-<case>`
@@ -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
@@ -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}
@@ -0,0 +1,2 @@
+npm notice run test
+npm notice run node --test --experimental-strip-types 'test/*.test.ts'
@@ -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
@@ -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 '<eof>'"},
@@ -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)
+		}
+	})
 }