Skip to content

Commit

Permalink
program: return unwrapped VerifierError
Browse files Browse the repository at this point in the history
Multiple users have been confused as to how to get at the full verifier
log. Due to how error wrapping with %w works, callers have to use
errors.As to retrieve a VerifierError before being able to format
with %+v to get the full log. This confusing exists even though we've
tried to document how to deal with it.

Try to make the problem less pressing by returning an unwrapped
VerifierError, which the user can then directly format using %+v or
similar.
  • Loading branch information
lmb authored and ti-mo committed Nov 22, 2022
1 parent 86000ec commit 67abdec
Show file tree
Hide file tree
Showing 5 changed files with 46 additions and 50 deletions.
2 changes: 1 addition & 1 deletion btf/btf.go
Original file line number Diff line number Diff line change
Expand Up @@ -668,7 +668,7 @@ func newHandleFromRawBTF(btf []byte) (*Handle, error) {
// the BTF blob is correct, a log was requested, and the provided buffer
// is too small.
_, ve := sys.BtfLoad(attr)
return nil, internal.ErrorWithLog(err, logBuf, errors.Is(ve, unix.ENOSPC))
return nil, internal.ErrorWithLog("load btf", err, logBuf, errors.Is(ve, unix.ENOSPC))
}

// NewHandleFromID returns the BTF handle for a given id.
Expand Down
23 changes: 11 additions & 12 deletions internal/errors.go
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ import (
//
// 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.
func ErrorWithLog(err error, log []byte, truncated bool) *VerifierError {
func ErrorWithLog(source string, err error, log []byte, truncated bool) *VerifierError {
const whitespace = "\t\r\v\n "

// Convert verifier log C string by truncating it on the first 0 byte
Expand All @@ -23,7 +23,7 @@ func ErrorWithLog(err error, log []byte, truncated bool) *VerifierError {

log = bytes.Trim(log, whitespace)
if len(log) == 0 {
return &VerifierError{err, nil, truncated}
return &VerifierError{source, err, nil, truncated}
}

logLines := bytes.Split(log, []byte{'\n'})
Expand All @@ -34,13 +34,14 @@ func ErrorWithLog(err error, log []byte, truncated bool) *VerifierError {
lines = append(lines, string(bytes.TrimRight(line, whitespace)))
}

return &VerifierError{err, lines, truncated}
return &VerifierError{source, 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 {
source string
// The error which caused this error.
Cause error
// The verifier output split into lines.
Expand All @@ -60,9 +61,12 @@ func (le *VerifierError) Error() string {
log = log[:n-1]
}

var b strings.Builder
fmt.Fprintf(&b, "%s: %s", le.source, le.Cause.Error())

n := len(log)
if n == 0 {
return le.Cause.Error()
return b.String()
}

lines := log[n-1:]
Expand All @@ -71,14 +75,9 @@ func (le *VerifierError) Error() string {
lines = log[n-2:]
}

var b strings.Builder
fmt.Fprintf(&b, "%s: ", le.Cause.Error())

for i, line := range lines {
for _, line := range lines {
b.WriteString(": ")
b.WriteString(strings.TrimSpace(line))
if i != len(lines)-1 {
b.WriteString(": ")
}
}

omitted := len(le.Log) - len(lines)
Expand Down Expand Up @@ -167,7 +166,7 @@ func (le *VerifierError) Format(f fmt.State, verb rune) {
return
}

fmt.Fprintf(f, "%s:", le.Cause.Error())
fmt.Fprintf(f, "%s: %s:", le.source, le.Cause.Error())

omitted := len(le.Log) - n
lines := le.Log[:n]
Expand Down
49 changes: 25 additions & 24 deletions internal/errors_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,33 +21,33 @@ func TestVerifierErrorWhitespace(t *testing.T) {
0, 0, // trailing NUL bytes
)

err := ErrorWithLog(errors.New("test"), b, false)
qt.Assert(t, err.Error(), qt.Equals, "test: unreachable insn 28")

err = ErrorWithLog(errors.New("test"), nil, false)
qt.Assert(t, err.Error(), qt.Equals, "test")

err = ErrorWithLog(errors.New("test"), []byte("\x00"), false)
qt.Assert(t, err.Error(), qt.Equals, "test")

err = ErrorWithLog(errors.New("test"), []byte(" "), false)
qt.Assert(t, err.Error(), qt.Equals, "test")
err := ErrorWithLog("frob", errors.New("test"), b, false)
qt.Assert(t, err.Error(), qt.Equals, "frob: test: unreachable insn 28")

for _, log := range [][]byte{
nil,
[]byte("\x00"),
[]byte(" "),
} {
err = ErrorWithLog("frob", errors.New("test"), log, false)
qt.Assert(t, err.Error(), qt.Equals, "frob: test", qt.Commentf("empty log %q has incorrect format", log))
}
}

func TestVerifierErrorWrapping(t *testing.T) {
ve := ErrorWithLog(unix.ENOENT, nil, false)
ve := ErrorWithLog("frob", unix.ENOENT, nil, false)
qt.Assert(t, ve, qt.ErrorIs, unix.ENOENT, qt.Commentf("should wrap provided error"))
qt.Assert(t, ve.Truncated, qt.IsFalse, qt.Commentf("verifier log should not be marked as truncated"))

ve = ErrorWithLog(unix.EINVAL, nil, true)
ve = ErrorWithLog("frob", unix.EINVAL, nil, true)
qt.Assert(t, ve, qt.ErrorIs, unix.EINVAL, qt.Commentf("should wrap provided error"))
qt.Assert(t, ve.Truncated, qt.IsTrue, qt.Commentf("verifier log should be marked as truncated"))

ve = ErrorWithLog(unix.EINVAL, []byte("foo"), false)
ve = ErrorWithLog("frob", unix.EINVAL, []byte("foo"), false)
qt.Assert(t, ve, qt.ErrorIs, unix.EINVAL, qt.Commentf("should wrap provided error"))
qt.Assert(t, ve.Error(), qt.Contains, "foo", qt.Commentf("verifier log should appear in error string"))

ve = ErrorWithLog(unix.ENOSPC, []byte("foo"), true)
ve = ErrorWithLog("frob", unix.ENOSPC, []byte("foo"), true)
qt.Assert(t, ve, qt.ErrorIs, unix.ENOSPC, qt.Commentf("should wrap provided error"))
qt.Assert(t, ve.Error(), qt.Contains, "foo", qt.Commentf("verifier log should appear in error string"))
qt.Assert(t, ve.Truncated, qt.IsTrue, qt.Commentf("verifier log should be marked truncated"))
Expand Down Expand Up @@ -79,9 +79,10 @@ func TestVerifierErrorSummary(t *testing.T) {

func ExampleVerifierError() {
err := &VerifierError{
syscall.ENOSPC,
[]string{"first", "second", "third"},
false,
source: "catastrophe",
Cause: syscall.ENOSPC,
Log: []string{"first", "second", "third"},
Truncated: false,
}

fmt.Printf("With %%s: %s\n", err)
Expand All @@ -91,18 +92,18 @@ func ExampleVerifierError() {
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:
// Output: With %s: catastrophe: no space left on device: third (2 line(s) omitted)
// With %v and a truncated log: catastrophe: no space left on device: second: third (truncated, 1 line(s) omitted)
// All log lines: catastrophe: no space left on device:
// first
// second
// third
// (truncated)
// First line: no space left on device:
// First line: catastrophe: no space left on device:
// first
// (2 line(s) omitted)
// (truncated)
// Last two lines: no space left on device:
// Last two lines: catastrophe: no space left on device:
// (1 line(s) omitted)
// second
// third
Expand All @@ -117,5 +118,5 @@ func readErrorFromFile(tb testing.TB, file string) *VerifierError {
tb.Fatal("Read file:", err)
}

return ErrorWithLog(unix.EINVAL, contents, false)
return ErrorWithLog("file", unix.EINVAL, contents, false)
}
13 changes: 4 additions & 9 deletions prog.go
Original file line number Diff line number Diff line change
Expand Up @@ -173,7 +173,7 @@ type Program struct {

// NewProgram creates a new Program.
//
// See NewProgramWithOptions for details.
// See [NewProgramWithOptions] for details.
func NewProgram(spec *ProgramSpec) (*Program, error) {
return NewProgramWithOptions(spec, ProgramOptions{})
}
Expand All @@ -183,7 +183,7 @@ func NewProgram(spec *ProgramSpec) (*Program, error) {
// Loading a program for the first time will perform
// feature detection by loading small, temporary programs.
//
// Returns a wrapped [VerifierError] if the program is rejected by the kernel.
// Returns a [VerifierError] if the program is rejected by the kernel.
func NewProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, error) {
if spec == nil {
return nil, errors.New("can't load a program from a nil spec")
Expand Down Expand Up @@ -242,8 +242,7 @@ func newProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, er
copy(insns, spec.Instructions)

handle, fib, lib, err := btf.MarshalExtInfos(insns)
btfDisabled := errors.Is(err, btf.ErrNotSupported)
if err != nil && !btfDisabled {
if err != nil && !errors.Is(err, btf.ErrNotSupported) {
return nil, fmt.Errorf("load ext_infos: %w", err)
}
if handle != nil {
Expand Down Expand Up @@ -358,11 +357,7 @@ func newProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, er
}

truncated := errors.Is(err, unix.ENOSPC) || errors.Is(err2, unix.ENOSPC)
err = internal.ErrorWithLog(err, logBuf, truncated)
if btfDisabled {
return nil, fmt.Errorf("load program: %w (kernel without BTF support)", err)
}
return nil, fmt.Errorf("load program: %w", err)
return nil, internal.ErrorWithLog("load program", err, logBuf, truncated)
}

// NewProgramFromFD creates a program from a raw fd.
Expand Down
9 changes: 5 additions & 4 deletions prog_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -361,13 +361,14 @@ func TestProgramVerifierOutputOnError(t *testing.T) {
t.Fatal("Expected program to be invalid")
}

var ve *VerifierError
if !errors.As(err, &ve) {
t.Fatal("Error does not contain a VerifierError")
ve, ok := err.(*VerifierError)
if !ok {
t.Fatal("NewProgram does return an unwrapped VerifierError")
}

if !strings.Contains(ve.Error(), "R0 !read_ok") {
t.Error("Unexpected verifier error contents:", ve)
t.Logf("%+v", ve)
t.Error("Missing verifier log in error summary")
}
}

Expand Down

0 comments on commit 67abdec

Please sign in to comment.