Repository: cilium/ebpf
Pull request #1500 (2024-07-02 18:24:44)

program, btf: probe correct log buffer size
ci: fix golangci-lint

    For some reason the Action decided to break now, after being updated a
    couple of weeks ago.

    Signed-off-by: Lorenz Bauer <lmb@isovalent.com>

program, btf: probe correct log buffer size

    The kernel exposes a log of operations to aid debugging a program or BTF
    load. Until recently there was no way to know the size of that buffer, so
    the library forces the user to specify a buffer size. From a cursory survey
    on sourcegraph.com it seems that users either hardcode a large fixed buffer
    or probe the correct size by doubling the buffer size when hitting ENOSPC.

    Since commit 47a71c1f9af0 ("bpf: Add log_true_size output field to return
    necessary log buffer size") the kernel does provide a hint to user space.

    Move probing of the correct log buffer size into the library. On recent (>=
    6.4) kernels this is guaranteed to work in a single call. On older kernels
    we use the doubling strategy employed by cilium and tetragon.

    Signed-off-by: Lorenz Bauer <lmb@isovalent.com>



Patch:
diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
index 128303e..57b1660 100644
--- a/.github/workflows/ci.yml
+++ b/.github/workflows/ci.yml
@@ -37,7 +37,6 @@ jobs:
         uses: golangci/golangci-lint-action@v6.0.1
         with:
           args: "--out-format colored-line-number"
-          skip-pkg-cache: true
 
       - name: Generate and format code
         run: |
diff --git a/btf/handle.go b/btf/handle.go
index b6b3e87..adfa6fe 100644
--- a/btf/handle.go
+++ b/btf/handle.go
@@ -41,6 +41,8 @@ func NewHandle(b *Builder) (*Handle, error) {
 //
 // Returns an error wrapping ErrNotSupported if the kernel doesn't support BTF.
 func NewHandleFromRawBTF(btf []byte) (*Handle, error) {
+	const minLogSize = 64 * 1024
+
 	if uint64(len(btf)) > math.MaxUint32 {
 		return nil, errors.New("BTF exceeds the maximum size")
 	}
@@ -50,26 +52,54 @@ func NewHandleFromRawBTF(btf []byte) (*Handle, error) {
 		BtfSize: uint32(len(btf)),
 	}
 
-	fd, err := sys.BtfLoad(attr)
-	if err == nil {
-		return &Handle{fd, attr.BtfSize, false}, nil
+	var (
+		logBuf []byte
+		err    error
+	)
+	for {
+		var fd *sys.FD
+		fd, err = sys.BtfLoad(attr)
+		if err == nil {
+			return &Handle{fd, attr.BtfSize, false}, nil
+		}
+
+		if attr.BtfLogTrueSize != 0 && attr.BtfLogSize >= attr.BtfLogTrueSize {
+			// The log buffer already has the correct size.
+			break
+		}
+
+		if attr.BtfLogSize != 0 && !errors.Is(err, unix.ENOSPC) {
+			// Up until at least kernel 6.0, the BTF verifier does not return ENOSPC
+			// if there are other verification errors. ENOSPC is only returned when
+			// the BTF blob is correct, a log was requested, and the provided buffer
+			// is too small. We're therefore not sure whether we got the full
+			// log or not.
+			break
+		}
+
+		// Make an educated guess how large the buffer should be. Start
+		// at a reasonable minimum and then double the size.
+		logSize := uint32(max(len(logBuf)*2, minLogSize))
+		if int(logSize) < len(logBuf) {
+			return nil, errors.New("overflow while probing log buffer size")
+		}
+
+		if attr.BtfLogTrueSize != 0 {
+			// The kernel has given us a hint how large the log buffer has to be.
+			logSize = attr.BtfLogTrueSize
+		}
+
+		logBuf = make([]byte, logSize)
+		attr.BtfLogSize = logSize
+		attr.BtfLogBuf = sys.NewSlicePointer(logBuf)
+		attr.BtfLogLevel = 1
 	}
 
 	if err := haveBTF(); err != nil {
 		return nil, err
 	}
 
-	logBuf := make([]byte, 64*1024)
-	attr.BtfLogBuf = sys.NewSlicePointer(logBuf)
-	attr.BtfLogSize = uint32(len(logBuf))
-	attr.BtfLogLevel = 1
-
-	// Up until at least kernel 6.0, the BTF verifier does not return ENOSPC
-	// if there are other verification errors. ENOSPC is only returned when
-	// the BTF blob is correct, a log was requested, and the provided buffer
-	// is too small.
-	_, ve := sys.BtfLoad(attr)
-	return nil, internal.ErrorWithLog("load btf", err, logBuf, errors.Is(ve, unix.ENOSPC))
+	return nil, internal.ErrorWithLog("load btf", err, logBuf)
 }
 
 // NewHandleFromID returns the BTF handle for a given id.
diff --git a/internal/errors.go b/internal/errors.go
index bda01e2..19d5294 100644
--- a/internal/errors.go
+++ b/internal/errors.go
@@ -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(source string, err error, log []byte, truncated bool) *VerifierError {
+func ErrorWithLog(source string, err error, log []byte) *VerifierError {
 	const whitespace = "\t\r\v\n "
 
 	// Convert verifier log C string by truncating it on the first 0 byte
@@ -23,7 +23,7 @@ func ErrorWithLog(source string, err error, log []byte, truncated bool) *Verifie
 
 	log = bytes.Trim(log, whitespace)
 	if len(log) == 0 {
-		return &VerifierError{source, err, nil, truncated}
+		return &VerifierError{source, err, nil}
 	}
 
 	logLines := bytes.Split(log, []byte{'\n'})
@@ -34,7 +34,7 @@ func ErrorWithLog(source string, err error, log []byte, truncated bool) *Verifie
 		lines = append(lines, string(bytes.TrimRight(line, whitespace)))
 	}
 
-	return &VerifierError{source, err, lines, truncated}
+	return &VerifierError{source, err, lines}
 }
 
 // VerifierError includes information from the eBPF verifier.
@@ -46,8 +46,6 @@ type VerifierError struct {
 	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 {
@@ -70,7 +68,7 @@ func (le *VerifierError) Error() string {
 	}
 
 	lines := log[n-1:]
-	if n >= 2 && (includePreviousLine(log[n-1]) || le.Truncated) {
+	if n >= 2 && includePreviousLine(log[n-1]) {
 		// Add one more line of context if it aids understanding the error.
 		lines = log[n-2:]
 	}
@@ -81,22 +79,9 @@ func (le *VerifierError) Error() string {
 	}
 
 	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)
+		fmt.Fprintf(&b, " (%d line(s) omitted)", omitted)
 	}
-	b.WriteString(")")
 
 	return b.String()
 }
@@ -188,10 +173,6 @@ func (le *VerifierError) Format(f fmt.State, verb rune) {
 			}
 		}
 
-		if le.Truncated {
-			fmt.Fprintf(f, "\n\t(truncated)")
-		}
-
 	default:
 		fmt.Fprintf(f, "%%!%c(BADVERB)", verb)
 	}
diff --git a/prog.go b/prog.go
index f4f3af7..1761654 100644
--- a/prog.go
+++ b/prog.go
@@ -46,13 +46,9 @@ const (
 	outputPad = 256 + 2
 )
 
-// DefaultVerifierLogSize is the default number of bytes allocated for the
+// minVerifierLogSize is the default number of bytes allocated for the
 // verifier log.
-const DefaultVerifierLogSize = 64 * 1024
-
-// maxVerifierLogSize is the maximum size of verifier log buffer the kernel
-// will accept before returning EINVAL.
-const maxVerifierLogSize = math.MaxUint32 >> 2
+const minVerifierLogSize = 64 * 1024
 
 // ProgramOptions control loading a program into the kernel.
 type ProgramOptions struct {
@@ -73,17 +69,6 @@ type ProgramOptions struct {
 	// attempt at loading the program.
 	LogLevel LogLevel
 
-	// Controls the output buffer size for the verifier log, in bytes. See the
-	// documentation on ProgramOptions.LogLevel for details about how this value
-	// is used.
-	//
-	// If this value is set too low to fit the verifier log, the resulting
-	// [ebpf.VerifierError]'s Truncated flag will be true, and the error string
-	// will also contain a hint to that effect.
-	//
-	// Defaults to DefaultVerifierLogSize.
-	LogSize int
-
 	// Disables the verifier log completely, regardless of other options.
 	LogDisabled bool
 
@@ -262,10 +247,6 @@ func newProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, er
 		return nil, fmt.Errorf("can't load %s program on %s", spec.ByteOrder, internal.NativeEndian)
 	}
 
-	if opts.LogSize < 0 {
-		return nil, errors.New("ProgramOptions.LogSize must be a positive value; disable verifier logs using ProgramOptions.LogDisabled")
-	}
-
 	// Kernels before 5.0 (6c4fc209fcf9 "bpf: remove useless version check for prog load")
 	// require the version field to be set to the value of the KERNEL_VERSION
 	// macro for kprobe-type programs.
@@ -404,37 +385,59 @@ func newProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, er
 		}
 	}
 
-	if opts.LogSize == 0 {
-		opts.LogSize = DefaultVerifierLogSize
-	}
-
-	// The caller requested a specific verifier log level. Set up the log buffer.
+	// The caller requested a specific verifier log level. Set up the log buffer
+	// so that there is a chance of loading the program in a single shot.
 	var logBuf []byte
 	if !opts.LogDisabled && opts.LogLevel != 0 {
-		logBuf = make([]byte, opts.LogSize)
+		logBuf = make([]byte, minVerifierLogSize)
 		attr.LogLevel = opts.LogLevel
 		attr.LogSize = uint32(len(logBuf))
 		attr.LogBuf = sys.NewSlicePointer(logBuf)
 	}
 
-	fd, err := sys.ProgLoad(attr)
-	if err == nil {
-		return &Program{unix.ByteSliceToString(logBuf), fd, spec.Name, "", spec.Type}, nil
-	}
+	for {
+		var fd *sys.FD
+		fd, err = sys.ProgLoad(attr)
+		if err == nil {
+			return &Program{unix.ByteSliceToString(logBuf), fd, spec.Name, "", spec.Type}, nil
+		}
 
-	// An error occurred loading the program, but the caller did not explicitly
-	// enable the verifier log. Re-run with branch-level verifier logs enabled to
-	// obtain more info. Preserve the original error to return it to the caller.
-	// An undersized log buffer will result in ENOSPC regardless of the underlying
-	// cause.
-	var err2 error
-	if !opts.LogDisabled && opts.LogLevel == 0 {
-		logBuf = make([]byte, opts.LogSize)
-		attr.LogLevel = LogLevelBranch
-		attr.LogSize = uint32(len(logBuf))
-		attr.LogBuf = sys.NewSlicePointer(logBuf)
+		if opts.LogDisabled {
+			break
+		}
 
-		_, err2 = sys.ProgLoad(attr)
+		if attr.LogTrueSize != 0 && attr.LogSize >= attr.LogTrueSize {
+			// The log buffer already has the correct size.
+			break
+		}
+
+		if attr.LogSize != 0 && !errors.Is(err, unix.ENOSPC) {
+			// Logging is enabled and the error is not ENOSPC, so we can infer
+			// that the log buffer is large enough.
+			break
+		}
+
+		if attr.LogLevel == 0 {
+			// Logging is not enabled but loading the program failed. Enable
+			// basic logging.
+			attr.LogLevel = LogLevelBranch
+		}
+
+		// Make an educated guess how large the buffer should be. Start
+		// at minVerifierLogSize and then double the size.
+		logSize := uint32(max(len(logBuf)*2, minVerifierLogSize))
+		if int(logSize) < len(logBuf) {
+			return nil, errors.New("overflow while probing log buffer size")
+		}
+
+		if attr.LogTrueSize != 0 {
+			// The kernel has given us a hint how large the log buffer has to be.
+			logSize = attr.LogTrueSize
+		}
+
+		logBuf = make([]byte, logSize)
+		attr.LogSize = logSize
+		attr.LogBuf = sys.NewSlicePointer(logBuf)
 	}
 
 	end := bytes.IndexByte(logBuf, 0)
@@ -452,10 +455,6 @@ func newProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, er
 		}
 
 	case errors.Is(err, unix.EINVAL):
-		if opts.LogSize > maxVerifierLogSize {
-			return nil, fmt.Errorf("load program: %w (ProgramOptions.LogSize exceeds maximum value of %d)", err, maxVerifierLogSize)
-		}
-
 		if bytes.Contains(tail, coreBadCall) {
 			err = errBadRelocation
 			break
@@ -479,8 +478,7 @@ func newProgramWithOptions(spec *ProgramSpec, opts ProgramOptions) (*Program, er
 		}
 	}
 
-	truncated := errors.Is(err, unix.ENOSPC) || errors.Is(err2, unix.ENOSPC)
-	return nil, internal.ErrorWithLog("load program", err, logBuf, truncated)
+	return nil, internal.ErrorWithLog("load program", err, logBuf)
 }
 
 // NewProgramFromFD creates a program from a raw fd.


Test patch:
diff --git a/btf/btf_test.go b/btf/btf_test.go
index 222c0de..1b758f2 100644
--- a/btf/btf_test.go
+++ b/btf/btf_test.go
@@ -316,10 +316,6 @@ func TestVerifierError(t *testing.T) {
 	if !errors.As(err, &ve) {
 		t.Fatalf("expected a VerifierError, got: %v", err)
 	}
-
-	if ve.Truncated {
-		t.Fatalf("expected non-truncated verifier log: %v", err)
-	}
 }
 
 func TestGuessBTFByteOrder(t *testing.T) {
diff --git a/internal/errors_test.go b/internal/errors_test.go
index 0320d60..c01c943 100644
--- a/internal/errors_test.go
+++ b/internal/errors_test.go
@@ -20,7 +20,7 @@ func TestVerifierErrorWhitespace(t *testing.T) {
 		0, 0, // trailing NUL bytes
 	)
 
-	err := ErrorWithLog("frob", errors.New("test"), b, false)
+	err := ErrorWithLog("frob", errors.New("test"), b)
 	qt.Assert(t, qt.Equals(err.Error(), "frob: test: unreachable insn 28"))
 
 	for _, log := range [][]byte{
@@ -28,28 +28,25 @@ func TestVerifierErrorWhitespace(t *testing.T) {
 		[]byte("\x00"),
 		[]byte(" "),
 	} {
-		err = ErrorWithLog("frob", errors.New("test"), log, false)
+		err = ErrorWithLog("frob", errors.New("test"), log)
 		qt.Assert(t, qt.Equals(err.Error(), "frob: test"), qt.Commentf("empty log %q has incorrect format", log))
 	}
 }
 
 func TestVerifierErrorWrapping(t *testing.T) {
-	ve := ErrorWithLog("frob", unix.ENOENT, nil, false)
+	ve := ErrorWithLog("frob", unix.ENOENT, nil)
 	qt.Assert(t, qt.ErrorIs(ve, unix.ENOENT), qt.Commentf("should wrap provided error"))
-	qt.Assert(t, qt.IsFalse(ve.Truncated), qt.Commentf("verifier log should not be marked as truncated"))
 
-	ve = ErrorWithLog("frob", unix.EINVAL, nil, true)
+	ve = ErrorWithLog("frob", unix.EINVAL, nil)
 	qt.Assert(t, qt.ErrorIs(ve, unix.EINVAL), qt.Commentf("should wrap provided error"))
-	qt.Assert(t, qt.IsTrue(ve.Truncated), qt.Commentf("verifier log should be marked as truncated"))
 
-	ve = ErrorWithLog("frob", unix.EINVAL, []byte("foo"), false)
+	ve = ErrorWithLog("frob", unix.EINVAL, []byte("foo"))
 	qt.Assert(t, qt.ErrorIs(ve, unix.EINVAL), qt.Commentf("should wrap provided error"))
 	qt.Assert(t, qt.StringContains(ve.Error(), "foo"), qt.Commentf("verifier log should appear in error string"))
 
-	ve = ErrorWithLog("frob", unix.ENOSPC, []byte("foo"), true)
+	ve = ErrorWithLog("frob", unix.ENOSPC, []byte("foo"))
 	qt.Assert(t, qt.ErrorIs(ve, unix.ENOSPC), qt.Commentf("should wrap provided error"))
 	qt.Assert(t, qt.StringContains(ve.Error(), "foo"), qt.Commentf("verifier log should appear in error string"))
-	qt.Assert(t, qt.IsTrue(ve.Truncated), qt.Commentf("verifier log should be marked truncated"))
 }
 
 func TestVerifierErrorSummary(t *testing.T) {
@@ -84,5 +81,5 @@ func readErrorFromFile(tb testing.TB, file string) *VerifierError {
 		tb.Fatal("Read file:", err)
 	}
 
-	return ErrorWithLog("file", unix.EINVAL, contents, false)
+	return ErrorWithLog("file", unix.EINVAL, contents)
 }
diff --git a/prog_test.go b/prog_test.go
index 0e1ff3c..588ace8 100644
--- a/prog_test.go
+++ b/prog_test.go
@@ -463,31 +463,12 @@ func TestProgramVerifierOutput(t *testing.T) {
 	}
 }
 
-// Test all scenarios where the VerifierError.Truncated flag is expected to be
-// true, marked with an x. LL means ProgramOption.LogLevel.
-//
-// |      | Valid | Invalid |
-// |------|-------|---------|
-// | LL=0 |       |    x    |
-// | LL>0 |   x   |    x    |
-func TestProgramVerifierLogTruncated(t *testing.T) {
-	// Make the buffer intentionally small to coerce ENOSPC.
-	// 128 bytes is the smallest the kernel will accept.
-	logSize := 128
-
+func TestProgramVerifierLog(t *testing.T) {
 	check := func(t *testing.T, err error) {
 		t.Helper()
 
-		if err == nil {
-			t.Fatal("Expected an error")
-		}
 		var ve *internal.VerifierError
-		if !errors.As(err, &ve) {
-			t.Fatal("Error is not a VerifierError")
-		}
-		if !ve.Truncated {
-			t.Errorf("VerifierError is not truncated: %+v", ve)
-		}
+		qt.Assert(t, qt.ErrorAs(err, &ve))
 	}
 
 	// Generate a base program of sufficient size whose verifier log does not fit
@@ -515,12 +496,11 @@ func TestProgramVerifierLogTruncated(t *testing.T) {
 
 	// Set an undersized log buffer without explicitly requesting a verifier log
 	// for an invalid program.
-	_, err := NewProgramWithOptions(spec, ProgramOptions{LogSize: logSize})
+	_, err := NewProgramWithOptions(spec, ProgramOptions{})
 	check(t, err)
 
 	// Explicitly request a verifier log for an invalid program.
 	_, err = NewProgramWithOptions(spec, ProgramOptions{
-		LogSize:  logSize,
 		LogLevel: LogLevelInstruction,
 	})
 	check(t, err)
@@ -530,21 +510,17 @@ func TestProgramVerifierLogTruncated(t *testing.T) {
 
 	// Don't request a verifier log, only set LogSize. Expect the valid program to
 	// be created without errors.
-	prog, err := NewProgramWithOptions(spec, ProgramOptions{
-		LogSize: logSize,
-	})
-	if err != nil {
-		t.Fatal(err)
-	}
+	prog, err := NewProgramWithOptions(spec, ProgramOptions{})
+	qt.Assert(t, qt.IsNil(err))
 	prog.Close()
 
 	// Explicitly request verifier log for a valid program. If a log is requested
 	// and the buffer is too small, ENOSPC occurs even for valid programs.
-	_, err = NewProgramWithOptions(spec, ProgramOptions{
-		LogSize:  logSize,
+	prog, err = NewProgramWithOptions(spec, ProgramOptions{
 		LogLevel: LogLevelInstruction,
 	})
-	check(t, err)
+	qt.Assert(t, qt.IsNil(err))
+	prog.Close()
 }
 
 func TestProgramWithUnsatisfiedMap(t *testing.T) {
@@ -982,11 +958,11 @@ func TestProgramLoadErrors(t *testing.T) {
 			})
 			testutils.SkipIfNotSupported(t, err)
 
-			qt.Assert(t, qt.ErrorIs(err, test.want))
-
 			var ve *VerifierError
 			qt.Assert(t, qt.ErrorAs(err, &ve))
 			t.Logf("%-5v", ve)
+
+			qt.Assert(t, qt.ErrorIs(err, test.want))
 		})
 	}
 }
@@ -1069,32 +1045,25 @@ func ExampleVerifierError() {
 		"catastrophe",
 		syscall.ENOSPC,
 		[]byte("first\nsecond\nthird"),
-		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: 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: catastrophe: no space left on device:
 	// 	first
 	// 	(2 line(s) omitted)
-	// 	(truncated)
 	// Last two lines: catastrophe: no space left on device:
 	// 	(1 line(s) omitted)
 	// 	second
 	// 	third
-	// 	(truncated)
 }
 
 // Use NewProgramWithOptions if you'd like to get the verifier output
@@ -1112,7 +1081,6 @@ func ExampleProgram_retrieveVerifierLog() {
 
 	prog, err := NewProgramWithOptions(spec, ProgramOptions{
 		LogLevel: LogLevelInstruction,
-		LogSize:  1024,
 	})
 	if err != nil {
 		panic(err)