blob: c07ca6387d66e80a10acec9c89856c3e5879a4e0 [file] [log] [blame]
// Copyright 2022 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
// Package logparser parses build.golang.org dashboard logs.
package logparser
import (
"regexp"
"strconv"
"strings"
)
// A Fail is a single failure mentioned in a dashboard log.
// (There can be multiple failures in a single log.)
type Fail struct {
Section string
Pkg string
Test string
Mode string
Output string
Snippet string
}
// compileRE matches compiler errors, with file:line:[col:] at the start of the line.
var compileRE = regexp.MustCompile(`^[a-zA-Z0-9_./\\]+:\d+:(\d+:)? `)
// runningRE matches the buildlet :: Running messages,
// which are displayed at the start of each operation the buildlet does.
var runningRE = regexp.MustCompile(`:: Running [^ ]+ with args \[([^\[\]]+)\] and env`)
// stringRE matches a single Go quoted string.
var stringRE = regexp.MustCompile(`"([^"\\]|\\.)*"`)
var testExecEnv = []string{
"# GOARCH:",
"# CPU:",
"# GOOS:",
"# OS Version:",
}
// Parse parses a build log, returning all the failures it finds.
// It always returns at least one failure.
func Parse(log string) []*Fail {
// Some logs have \r\n lines.
log = strings.ReplaceAll(log, "\r", "")
// Parsing proceeds line at a time, tracking the "section" of the build
// we are currently in.
// When we see lines that might be output associated with a failure,
// we accumulate them in the hold slice.
// When we see a line that definitely indicates a failure, we start a
// new failure f, append it to fails, and also append the lines associated
// with f to lines. (That is, fails[i]'s output lines are lines[i].)
// When we see a line that definitely indicates a non-failure, such as
// an "ok" result from go test, we "flush" the current failure, meaning
// we set f to nil so there's no current failure anymore, and we clear
// the hold slice as well. Before clearing the hold slice, we check to
// see if there are any compile failures in it that should be extracted.
var (
section string
hold []string
fails []*Fail
lines [][]string
f *Fail
)
// flush is called when we've reached a non-failing test in the output,
// meaning that any failing test is over. It clears f and the hold space,
// but it also processes the hold space to find any build failures lurking.
flush := func() {
// Any unattributed compile-failure-looking lines turn into a build failure.
for _, line := range hold {
if compileRE.MatchString(line) {
f = &Fail{
Section: section,
Mode: "build",
}
fails = append(fails, f)
lines = append(lines, hold)
hold = nil
break
}
}
f = nil
hold = hold[:0]
}
// Process the log, a line at a time.
Lines:
for i, line := range strings.SplitAfter(log, "\n") {
// first line is "<builder> at <hash> ..."; ignore.
if i == 0 && strings.Contains(line, " at ") {
continue
}
// ignore empty string left by Split at end of slice
if line == "" {
continue
}
// ignore "go: downloading" chatter.
if strings.HasPrefix(line, "go: downloading ") {
continue
}
// replace lines with trailing spaces with empty line
if strings.TrimSpace(line) == "" {
line = "\n"
if len(hold) == 0 && f == nil {
continue
}
}
if strings.TrimSpace(line) == "XXXBANNERXXX:Test execution environment." {
continue
}
// :: Running line says what command the buildlet is running now.
// Use this as the initial section.
if strings.HasPrefix(line, ":: Running") {
flush()
if m := runningRE.FindStringSubmatch(line); m != nil {
var args []string
for _, q := range stringRE.FindAllString(m[1], -1) {
s, _ := strconv.Unquote(q)
args = append(args, s)
}
args[0] = args[0][strings.LastIndex(args[0], `/`)+1:]
args[0] = args[0][strings.LastIndex(args[0], `\`)+1:]
section = strings.Join(args, " ")
}
continue
}
// cmd/dist in the main repo prints Building lines during bootstrap.
// Use them as sections.
if strings.HasPrefix(line, "Building ") {
flush()
section = strings.TrimSpace(line)
continue
}
// cmd/dist prints ##### lines between test sections in the main repo.
if strings.HasPrefix(line, "##### ") {
flush()
if p := strings.TrimSpace(line[len("##### "):]); p != "" {
section = p
continue
}
}
// skipped or passing test from go test marks end of previous failure
if strings.HasPrefix(line, "? \t") || strings.HasPrefix(line, "ok \t") {
flush()
continue
}
// test binaries print FAIL at the end of execution, as does "go test".
// If we've already found a specific failure, these are noise and can be dropped.
if line == "FAIL\n" && len(fails) > 0 {
continue
}
// --- FAIL: marks package testing's report of a failed test.
// Lines may have been printed above it, during test execution;
// they are picked up from the hold slice for inclusion in the report.
if strings.HasPrefix(line, "--- FAIL: ") {
if fields := strings.Fields(line); len(fields) >= 3 {
// Found start of test function failure.
f = &Fail{
Section: section,
Test: fields[2],
Mode: "test",
}
if strings.HasPrefix(section, "../") {
f.Pkg = strings.TrimPrefix(section, "../")
}
fails = append(fails, f)
// Include held lines printed above the --- FAIL
// since they could have been printed from the test.
lines = append(lines, append(hold, line))
hold = nil
continue
}
}
// During go test, build failures are reported starting with a "# pkg/path" or
// "# pkg/path [foo.test]" line. We have to distinguish these from the # lines
// printed during the "../test" part of all.bash, and we have to distinguish them
// from the # key: value lines printed in the # Test execution environment section.
if strings.HasPrefix(line, "# ") && strings.Contains(line, ":") {
for _, env := range testExecEnv {
if strings.HasPrefix(line, env) {
continue Lines
}
}
}
if strings.HasPrefix(line, "# ") && section != "../test" {
if fields := strings.Fields(line); len(fields) >= 2 {
flush()
// Found start of build failure.
f = &Fail{
Section: section,
Pkg: fields[1],
Mode: "build",
}
fails = append(fails, f)
lines = append(lines, nil)
continue
}
}
// In the ../test phase, run.go prints "go run run.go" lines for each failing test.
if strings.HasPrefix(line, "# go run run.go -- ") {
f = &Fail{
Section: section,
Pkg: strings.TrimSpace(strings.TrimPrefix(line, "# go run run.go -- ")),
Mode: "test",
}
fails = append(fails, f)
lines = append(lines, append(hold, line))
hold = nil
continue
}
// go test prints "FAIL\tpkg\t0.1s\n" after a failing test's output has been printed.
// We've seen the failing test cases already but didn't know what package they were from.
// Update them. If there is no active failure, it could be that the test panicked or
// otherwise exited without printing the usual test case failures.
// Create a new Fail in that case, recording whatever output we did see (from the hold slice).
//
// In the ../test phase, run.go prints "FAIL\ttestcase.go 0.1s" (space not tab).
// For those, we don't need to update any test cases.
//
if strings.HasPrefix(line, "FAIL\t") {
if fields := strings.Fields(line); len(fields) >= 3 {
if strings.Contains(line, "[build failed]") {
flush()
continue
}
// Found test package failure line printed by cmd/go after test output.
pkg := fields[1]
if f != nil && f.Section == "../test" {
// already collecting
} else if f != nil {
for i := len(fails) - 1; i >= 0 && fails[i].Test != ""; i-- {
fails[i].Pkg = pkg
}
} else {
f = &Fail{
Section: section,
Pkg: pkg,
Mode: "test",
}
fails = append(fails, f)
lines = append(lines, hold)
hold = nil
}
flush()
continue
}
}
if f == nil {
hold = append(hold, line)
} else {
lines[len(fails)-1] = append(lines[len(fails)-1], line)
}
}
// If we didn't find any failures in the log, at least grab the current hold slice.
// It's not much, but it's something.
if len(fails) == 0 {
f = &Fail{
Section: section,
}
fails = append(fails, f)
lines = append(lines, hold)
hold = nil
}
flush()
// Now that we have the full output for each failure,
// build the Output and Snippet fields.
for i, f := range fails {
// Trim trailing blank lines.
out := lines[i]
for len(out) > 0 && strings.TrimSpace(out[len(out)-1]) == "" {
out = out[:len(out)-1]
}
f.Output = strings.Join(out, "")
f.Snippet = strings.Join(shorten(out, true), "")
if f.Test == "" && strings.Contains(f.Output, "\n\ngoroutine ") {
// If a test binary panicked, it doesn't report what test was running.
// Figure that out by parsing the goroutine stacks.
findRunningTest(f, out)
}
}
return fails
}
var goroutineStack = regexp.MustCompile(`^goroutine \d+ \[(.*)\]:$`)
// findRunningTest looks at the test output to find the running test goroutine,
// extracts the test name from it, and then updates f.Test.
func findRunningTest(f *Fail, lines []string) {
goroutineStart := -1 // index of current goroutine's "goroutine N" line.
Scan:
for i, line := range lines {
s := strings.TrimSpace(line)
if s == "" { // blank line marks end of goroutine stack
goroutineStart = -1
continue
}
if goroutineStack.MatchString(s) {
goroutineStart = i
}
// If we find testing.tRunner on the stack, the frame above it is a test.
// But in the case of tests using t.Parallel, what usually happens is that
// many tests are blocked in t.Parallel and one is actually running.
// Take the first that hasn't called t.Parallel.
if goroutineStart >= 0 && strings.HasPrefix(s, "testing.tRunner(") && i > 2 {
// Frame above tRunner should be a test.
testLine := strings.TrimSpace(lines[i-2])
if name, _, ok := strings.Cut(testLine, "("); ok {
if _, test, ok := strings.Cut(name, ".Test"); ok {
// Ignore this goroutine if it is blocked in t.Parallel.
for _, line := range lines[goroutineStart+1 : i] {
if strings.HasPrefix(strings.TrimSpace(line), "testing.(*T).Parallel(") {
goroutineStart = -1
continue Scan
}
}
test, _, _ = strings.Cut(test, ".func")
f.Test = "Test" + test
// Append the stack trace down to tRunner,
// but without the goroutine line, and then re-shorten the snippet.
// We pass false to shorten to discard all the other goroutines:
// we've found the one we want, and we deleted its goroutine header
// so that shorten won't remove it.
var big []string
big = append(big, lines...)
big = append(big, "\n")
big = append(big, lines[goroutineStart+1:i+1]...)
f.Snippet = strings.Join(shorten(big, false), "")
return
}
}
}
}
}
// shorten shortens the output lines to form a snippet.
func shorten(lines []string, keepRunning bool) []string {
// First, remove most goroutine stacks.
// Those are often irrelevant and easy to drop from the snippet.
// If keepRunning is true, we keep the [running] goroutines.
// If keepRunning is false, we keep no goroutine stacks at all.
{
var keep []string
var wasBlank bool
var inGoroutine bool
for _, line := range lines {
s := strings.TrimSpace(line)
if inGoroutine {
if s == "" {
inGoroutine = false
wasBlank = true
}
continue
}
if wasBlank {
if m := goroutineStack.FindStringSubmatch(s); m != nil && (!keepRunning || m[1] != "running") {
inGoroutine = true
continue
}
}
keep = append(keep, line)
wasBlank = s == ""
}
lines = keep
}
// Remove trailing blank lines.
for len(lines) > 0 && strings.TrimSpace(lines[len(lines)-1]) == "" {
lines = lines[:len(lines)-1]
}
// If we have more than 30 lines, make the snippet by taking the first 10,
// the last 10, and possibly a middle 10. The middle 10 is included when
// the interior lines (between the first and last 10) contain an important-looking
// message like "panic:" or "--- FAIL:". The middle 10 start at the important-looking line.
// such as
if len(lines) > 30 {
var keep []string
keep = append(keep, lines[:10]...)
dots := true
for i := 10; i < len(lines)-10; i++ {
s := strings.TrimSpace(lines[i])
if strings.HasPrefix(s, "panic:") || strings.HasPrefix(s, "fatal error:") || strings.HasPrefix(s, "--- FAIL:") || strings.Contains(s, ": internal compiler error:") {
if i > 10 {
keep = append(keep, "...\n")
}
end := i + 10
if end >= len(lines)-10 {
dots = false
end = len(lines) - 10
}
keep = append(keep, lines[i:end]...)
break
}
}
if dots {
keep = append(keep, "...\n")
}
keep = append(keep, lines[len(lines)-10:]...)
lines = keep
}
return lines
}