mesh-build-go: a cause is the runtime's line at column 0, and only go's exact summary lines are dropped (issue 1901, review round 1)
mesh/delivery held for a person: merged without a passing check: only a person decides what follows
mesh/delivery-group group fix/1901-package-cause held: a member is held: novox/mesh-catalog@155124b59af4 (merged without a passing check: only a person decides…
mesh/check pass 155124b59af4 on f27f4c8cd58c | unit 2015 run, 2883 kept, 5 skipped | integration 2037 run, 2978 kept, 9 skipped | over bound: unit, in…

An indented log line of another running test that held 'panic:' won over the
real timeout panic, since the lines were trimmed before matching. Go prints
the runtime's lines at column 0; a test's log is indented.
This commit is contained in:
2026-10-25 15:58:07 +01:00
parent 6ec6fdaad2
commit 155124b59a
2 changed files with 30 additions and 6 deletions
@@ -192,7 +192,7 @@ func (r *reader) event(ev event) {
case "output": case "output":
// go test's own summary of a package ("PASS", "FAIL", "ok <pkg>", "FAIL <pkg>") is never a failure's // go test's own summary of a package ("PASS", "FAIL", "ok <pkg>", "FAIL <pkg>") is never a failure's
// words: a "PASS" before a "FAIL <pkg>" says only that the tests passed and the program failed after them. // words: a "PASS" before a "FAIL <pkg>" says only that the tests passed and the program failed after them.
switch l := strings.TrimSpace(ev.Output); { switch l := strings.TrimRight(ev.Output, "\r\n"); {
case l == "PASS": case l == "PASS":
r.passed[ev.Package] = true r.passed[ev.Package] = true
case summaryLine(l): case summaryLine(l):
@@ -275,22 +275,24 @@ func clip(lines []string, cause string) string {
return strings.Join(kept, "\n") return strings.Join(kept, "\n")
} }
// summaryLine says a line is go test's summary of a package: "PASS", "FAIL", "ok <pkg> <time>", "FAIL <pkg> <time>". // summaryLine says a line is go test's summary of a package, in go's exact forms only: "PASS" or "FAIL" alone,
// "ok \t<pkg>\t<time>" and "FAIL\t<pkg>\t<time>" (review round 1: a line of the package's own that starts "ok " is kept).
func summaryLine(l string) bool { func summaryLine(l string) bool {
return l == "PASS" || l == "FAIL" || strings.HasPrefix(l, "ok ") || strings.HasPrefix(l, "ok\t") || strings.HasPrefix(l, "FAIL\t") || strings.HasPrefix(l, "FAIL ") return l == "PASS" || l == "FAIL" || strings.HasPrefix(l, "ok \t") || strings.HasPrefix(l, "FAIL\t")
} }
// causeOf is the cause in a failure's output that is not a test's assertion (issue 1901): a race the race detector // causeOf is the cause in a failure's output that is not a test's assertion (issue 1901): a race the race detector
// reported (raceCause); else the first "panic:" line, a timeout's with the tests it names as running; else the first // reported (raceCause); else the first "panic:" line, a timeout's with the tests it names as running; else the first
// "fatal error:" (the runtime's) or "signal:" line (a test program killed); "" when there is none. It reads every line, // "fatal error:" (the runtime's) or "signal:" line (a test program killed); "" when there is none. It reads every line,
// so a long goroutine dump after the panic cannot hide it. // so a long goroutine dump after the panic cannot hide it. **It matches only lines at column 0**, where go prints the
// runtime's: a test's indented log line holding the same words is not the cause (review round 1).
func causeOf(lines []string) string { func causeOf(lines []string) string {
if race := raceCause(lines); race != "" { if race := raceCause(lines); race != "" {
return race return race
} }
for _, prefix := range []string{"panic: ", "fatal error: ", "signal: "} { for _, prefix := range []string{"panic: ", "fatal error: ", "signal: "} {
for i, l := range lines { for i, l := range lines {
l = strings.TrimSpace(l) l = strings.TrimRight(l, "\r\n") // at column 0: an indented line is a test's own log, not the runtime's
if !strings.HasPrefix(l, prefix) { if !strings.HasPrefix(l, prefix) {
continue continue
} }
@@ -322,7 +324,7 @@ func causeOf(lines []string) string {
func raceCause(lines []string) string { func raceCause(lines []string) string {
at := -1 at := -1
for i, l := range lines { for i, l := range lines {
if strings.TrimSpace(l) == "WARNING: DATA RACE" { if strings.TrimRight(l, "\r\n") == "WARNING: DATA RACE" { // at column 0, as causeOf
at = i at = i
break break
} }
@@ -79,3 +79,25 @@ func TestAnAssertionKeepsItsOwnCause(t *testing.T) { // 1901/AC4
t.Errorf("1901/AC4: failures = %+v", res.Failed) t.Errorf("1901/AC4: failures = %+v", res.Failed)
} }
} }
// go prints the runtime's lines ("panic:", "fatal error:", "signal:", "WARNING: DATA RACE") at column 0: a test's own
// log line that holds the same words is indented, and is not the cause (review round 1). The fixture is the deeptimeout
// capture with two log lines of the first running test added: a t.Logf and its indented continuation saying "panic:".
func TestALoggedPanicIsNotTheCause(t *testing.T) { // 1901/AC4
raw, err := os.ReadFile("testdata/captured/go-test-json-pkg-deeptimeout.jsonl")
if err != nil {
t.Fatal(err)
}
lines := strings.SplitAfter(string(raw), "\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"
out := strings.Join(lines[:10], "") + added + strings.Join(lines[10:], "")
res := &TestResult{}
rd := newReader(res, ".")
rd.read(out)
rd.finish()
if len(res.Failed) != 1 || !strings.HasPrefix(res.Failed[0].Cause, "panic: test timed out after 2s") {
t.Errorf("1901/AC4: failures = %+v, want the timeout's panic as the cause", res.Failed)
}
}