internal: make VerifierError more succinct

Instead of dumping sometimes megabytes of log lines, summarise verifier
errors. Very short logs are shown in full, while longer longs only show
the last few lines by default.

    internal/errors_test.go:55: invalid argument: JIT doesn't support bpf-to-bpf calls (1 line(s) omitted)
    internal/errors_test.go:60: invalid argument: [52] STRUCT task_struct size=7744 vlen=218: cpus_mask type_id=109 bitfield_size=0 bits_offset=7744 Invalid member (27 line(s) omitted)
    internal/errors_test.go:64: invalid argument: [11] FUNC helper_func2 type_id=10 vlen != 0 (24 line(s) omitted)
    internal/errors_test.go:69: invalid argument: str_off: 3166088: str_len: 228 (truncated, 6 line(s) omitted)

Using %(+|-)v users can print the first or last n log lines. Individual
fields of VerifierError are also exported.

Author: lmb

btf/btf.go

@@ -698,9 +698,9 @@ func NewHandle(spec *Spec) (*Handle, error) {
 		attr.BtfLogBuf = sys.NewSlicePointer(logBuf)
 		attr.BtfLogSize = uint32(len(logBuf))
 		attr.BtfLogLevel = 1
-		_, logErr := sys.BtfLoad(attr)
 		// NB: The syscall will never return ENOSPC as of 5.18-rc4.
-		return nil, internal.ErrorWithLog(err, logBuf, logErr)
+		_, _ = sys.BtfLoad(attr)
+		return nil, internal.ErrorWithLog(err, logBuf)
 	}
 
 	return &Handle{spec.Copy(), fd}, nil

internal/errors.go

@@ -2,46 +2,186 @@ package internal
 
 import (
 	"bytes"
-	"errors"
 	"fmt"
-
-	"github.com/cilium/ebpf/internal/unix"
+	"io"
+	"strings"
 )
 
-// ErrorWithLog returns an error that includes logs from the
-// kernel verifier.
+// ErrorWithLog returns an error which includes logs from the kernel verifier.
+//
+// The default error output is a summary of the full log. The latter can be
+// accessed via VerifierError.Log or by formatting the error, see Format.
 //
-// logErr should be the error returned by the syscall that generated
-// the log. It is used to check for truncation of the output.
-func ErrorWithLog(err error, log []byte, logErr error) error {
+// A set of heuristics is used to determine whether the log has been truncated.
+func ErrorWithLog(err error, log []byte) *VerifierError {
+	const whitespace = "\t\r\v\n "
+
 	// Convert verifier log C string by truncating it on the first 0 byte
 	// and trimming trailing whitespace before interpreting as a Go string.
+	truncated := false
 	if i := bytes.IndexByte(log, 0); i != -1 {
+		if i == len(log)-1 && !bytes.HasSuffix(log[:i], []byte{'\n'}) {
+			// The null byte is at the end of the buffer and it's not preceded
+			// by a newline character. Most likely the buffer was too short.
+			truncated = true
+		}
+
 		log = log[:i]
+	} else if len(log) > 0 {
+		// No null byte? Dodgy!
+		truncated = true
 	}
-	logStr := string(bytes.Trim(log, "\t\r\n "))
 
-	if errors.Is(logErr, unix.ENOSPC) {
-		logStr += " (truncated...)"
+	log = bytes.Trim(log, whitespace)
+	logLines := bytes.Split(log, []byte{'\n'})
+	lines := make([]string, 0, len(logLines))
+	for _, line := range logLines {
+		// Don't remove leading white space on individual lines. We rely on it
+		// when outputting logs.
+		lines = append(lines, string(bytes.TrimRight(line, whitespace)))
 	}
 
-	return &VerifierError{err, logStr}
+	return &VerifierError{err, lines, truncated}
 }
 
 // VerifierError includes information from the eBPF verifier.
+//
+// It summarises the log output, see Format if you want to output the full contents.
 type VerifierError struct {
-	cause error
-	log   string
+	// The error which caused this error.
+	Cause error
+	// The verifier output split into lines.
+	Log []string
+	// Whether the log output is truncated, based on several heuristics.
+	Truncated bool
 }
 
 func (le *VerifierError) Unwrap() error {
-	return le.cause
+	return le.Cause
 }
 
 func (le *VerifierError) Error() string {
-	if le.log == "" {
-		return le.cause.Error()
+	log := le.Log
+	if n := len(log); n > 0 && strings.HasPrefix(log[n-1], "processed ") {
+		// Get rid of "processed 39 insns (limit 1000000) ..." from summary.
+		log = log[:n-1]
+	}
+
+	output := 0
+	switch n := len(log); n {
+	case 0:
+		return le.Cause.Error()
+
+	case 1, 2:
+		output = n
+
+	default:
+		output = 1
+		if strings.HasPrefix(log[n-1], "\t") || le.Truncated {
+			// Add one more line of context if the last line starts with a tab,
+			// or if it has been truncated.
+			// For example:
+			//     [13] STRUCT drm_rect size=16 vlen=4
+			//     \tx1 type_id=2
+			output++
+		}
+	}
+
+	var b strings.Builder
+	fmt.Fprintf(&b, "%s: ", le.Cause.Error())
+
+	lines := log[len(log)-output:]
+	for i, line := range lines {
+		b.WriteString(strings.TrimSpace(line))
+		if i != len(lines)-1 {
+			b.WriteString(": ")
+		}
+	}
+
+	omitted := len(le.Log) - len(lines)
+	if omitted == 0 && !le.Truncated {
+		return b.String()
+	}
+
+	b.WriteString(" (")
+	if le.Truncated {
+		b.WriteString("truncated")
+	}
+
+	if omitted > 0 {
+		if le.Truncated {
+			b.WriteString(", ")
+		}
+		fmt.Fprintf(&b, "%d line(s) omitted", omitted)
 	}
+	b.WriteString(")")
+
+	return b.String()
+}
+
+// Format the error.
+//
+// Understood verbs are %s and %v, which are equivalent to calling Error(). %v
+// allows outputting additional information using the following flags:
+//
+//     +   Output the first <width> lines, or all lines if no width is given.
+//     -   Output the last <width> lines, or all lines if no width is given.
+//
+// Use width to specify how many lines to output. Use the '-' flag to output
+// lines from the end of the log instead of the beginning.
+func (le *VerifierError) Format(f fmt.State, verb rune) {
+	switch verb {
+	case 's':
+		_, _ = io.WriteString(f, le.Error())
+
+	case 'v':
+		n, haveWidth := f.Width()
+		if !haveWidth || n > len(le.Log) {
+			n = len(le.Log)
+		}
+
+		if !f.Flag('+') && !f.Flag('-') {
+			if haveWidth {
+				_, _ = io.WriteString(f, "%!v(BADWIDTH)")
+				return
+			}
 
-	return fmt.Sprintf("%s: %s", le.cause, le.log)
+			_, _ = io.WriteString(f, le.Error())
+			return
+		}
+
+		if f.Flag('+') && f.Flag('-') {
+			_, _ = io.WriteString(f, "%!v(BADFLAG)")
+			return
+		}
+
+		fmt.Fprintf(f, "%s:", le.Cause.Error())
+
+		omitted := len(le.Log) - n
+		lines := le.Log[:n]
+		if f.Flag('-') {
+			// Print last instead of first lines.
+			lines = le.Log[len(le.Log)-n:]
+			if omitted > 0 {
+				fmt.Fprintf(f, "\n\t(%d line(s) omitted)", omitted)
+			}
+		}
+
+		for _, line := range lines {
+			fmt.Fprintf(f, "\n\t%s", line)
+		}
+
+		if !f.Flag('-') {
+			if omitted > 0 {
+				fmt.Fprintf(f, "\n\t(%d line(s) omitted)", omitted)
+			}
+		}
+
+		if le.Truncated {
+			fmt.Fprintf(f, "\n\t(truncated)")
+		}
+
+	default:
+		fmt.Fprintf(f, "%%!%c(BADVERB)", verb)
+	}
 }

internal/errors_test.go

@@ -2,12 +2,16 @@ package internal
 
 import (
 	"errors"
+	"fmt"
+	"os"
+	"syscall"
 	"testing"
 
 	"github.com/cilium/ebpf/internal/unix"
+	qt "github.com/frankban/quicktest"
 )
 
-func TestErrorWithLog(t *testing.T) {
+func TestVerifierErrorWhitespace(t *testing.T) {
 	b := []byte("unreachable insn 28")
 	b = append(b,
 		0xa,  // \n
@@ -17,9 +21,9 @@ func TestErrorWithLog(t *testing.T) {
 		0, 0, // trailing NUL bytes
 	)
 
-	err := ErrorWithLog(errors.New("test"), b, unix.ENOSPC)
+	err := ErrorWithLog(errors.New("test"), b)
 
-	want := "test: unreachable insn 28 (truncated...)"
+	want := "test: unreachable insn 28"
 	got := err.Error()
 
 	t.Log(got)
@@ -28,3 +32,84 @@ func TestErrorWithLog(t *testing.T) {
 		t.Fatalf("\nwant: %s\ngot: %s", want, got)
 	}
 }
+
+func TestVerifierError(t *testing.T) {
+	for _, test := range []struct {
+		name string
+		log  string
+	}{
+		{"missing null", "foo"},
+		{"missing newline before null", "foo\x00"},
+	} {
+		t.Run("truncate "+test.name, func(t *testing.T) {
+			ve := ErrorWithLog(syscall.ENOENT, []byte(test.log))
+			qt.Assert(t, ve, qt.IsNotNil, qt.Commentf("should return error"))
+			qt.Assert(t, ve.Truncated, qt.IsTrue, qt.Commentf("should be truncated"))
+		})
+	}
+
+	ve := ErrorWithLog(syscall.ENOENT, nil)
+	qt.Assert(t, ve, qt.IsNotNil, qt.Commentf("should return error without log or logErr"))
+
+	errno524 := readErrorFromFile(t, "testdata/errno524.log")
+	t.Log(errno524)
+	qt.Assert(t, errno524.Error(), qt.Contains, "JIT doesn't support bpf-to-bpf calls")
+	qt.Assert(t, errno524.Error(), qt.Not(qt.Contains), "processed 39 insns")
+
+	invalidMember := readErrorFromFile(t, "testdata/invalid-member.log")
+	t.Log(invalidMember)
+	qt.Assert(t, invalidMember.Error(), qt.Contains, "STRUCT task_struct size=7744 vlen=218: cpus_mask type_id=109 bitfield_size=0 bits_offset=7744 Invalid member")
+
+	issue43 := readErrorFromFile(t, "testdata/issue-43.log")
+	t.Log(issue43)
+	qt.Assert(t, issue43.Error(), qt.Contains, "[11] FUNC helper_func2 type_id=10 vlen != 0")
+	qt.Assert(t, issue43.Error(), qt.Not(qt.Contains), "[10] FUNC_PROTO (anon) return=3 args=(3 arg)")
+
+	truncated := readErrorFromFile(t, "testdata/truncated.log")
+	t.Log(truncated)
+	qt.Assert(t, truncated.Truncated, qt.IsTrue)
+	qt.Assert(t, truncated.Error(), qt.Contains, "str_off: 3166088: str_len: 228")
+}
+
+func ExampleVerifierError() {
+	err := &VerifierError{
+		syscall.ENOSPC,
+		[]string{"first", "second", "third"},
+		false,
+	}
+
+	fmt.Printf("With %%s: %s\n", err)
+	err.Truncated = true
+	fmt.Printf("With %%v and a truncated log: %v\n", err)
+	fmt.Printf("All log lines: %+v\n", err)
+	fmt.Printf("First line: %+1v\n", err)
+	fmt.Printf("Last two lines: %-2v\n", err)
+
+	// Output: With %s: no space left on device: third (2 line(s) omitted)
+	// With %v and a truncated log: no space left on device: second: third (truncated, 1 line(s) omitted)
+	// All log lines: no space left on device:
+	// 	first
+	// 	second
+	// 	third
+	// 	(truncated)
+	// First line: no space left on device:
+	// 	first
+	// 	(2 line(s) omitted)
+	// 	(truncated)
+	// Last two lines: no space left on device:
+	// 	(1 line(s) omitted)
+	// 	second
+	// 	third
+	// 	(truncated)
+}
+
+func readErrorFromFile(tb testing.TB, file string) *VerifierError {
+	tb.Helper()
+
+	contents, err := os.ReadFile(file)
+	if err != nil {
+		tb.Fatal("Read file:", err)
+	}
+
+	return ErrorWithLog(unix.EINVAL, contents)
+}