Add Backtrace API

The backtrace APIs allows a developer to embed backtraces in a log entry
aiding debugging.

Signed-off-by: Patrick Ohly <patrick.ohly@intel.com>

Copied from kubernetes/klog#323

dbg/backtrace.go

@@ -0,0 +1,152 @@
+/*
+Copyright 2022 The logr Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+// Package dbg contains helper code for storing a stack backtrace in a value
+// that can be used in a logr key/value pair or be formatted with %s in a
+// fmt.Printf call.
+package dbg
+
+import (
+	"fmt"
+	"runtime"
+)
+
+// numTotalFrames specifies the maximum number of frames that are supported by
+// backtrace APIs.
+const numTotalFrames = 100
+
+type traceT struct {
+	buf       []byte
+	all       bool
+	skip      int
+	numframes int
+}
+
+func (t traceT) String() string {
+	return string(t.buf)
+}
+
+// BacktraceOption provides functional parameters for Backtrace.
+type BacktraceOption func(*traceT)
+
+// BacktraceAll returns backtraces for all goroutines.
+// Note: This is incompatible with other options like skip/size.
+// Those will be ignored when tracing all goroutines.
+func BacktraceAll(all bool) BacktraceOption {
+	return func(t *traceT) {
+		t.all = all
+	}
+}
+
+// BacktraceSkip is like Backtrace except that it skips some stack levels.
+// BacktraceSkip(0) is equivalent to Backtrace(). Has no effect when
+// combined with BacktraceAll(true).
+func BacktraceSkip(depth int) BacktraceOption {
+	return func(t *traceT) {
+		t.skip = depth
+	}
+}
+
+// BacktraceSize will limit how far the unwinding goes, i.e. specify
+// how many stack frames will be printed. Has no effect when
+// combined with BacktraceAll(true).
+func BacktraceSize(numFrames int) BacktraceOption {
+	return func(t *traceT) {
+		if numFrames > 0 {
+			t.numframes = numFrames
+		}
+	}
+}
+
+// Backtrace returns an object that as default represents the stack backtrace of the calling
+// goroutine. That object can be used as value in a structured logging call.
+// It supports printing as string or as structured output via logr.MarshalLog.
+// The behavior can be modified via options.
+func Backtrace(opts ...BacktraceOption) interface{} {
+
+	trace := traceT{skip: 0, numframes: 0}
+
+	for _, opt := range opts {
+		opt(&trace)
+	}
+
+	// 'All' supersedes skip/size etc
+	if trace.all {
+		trace.buf = stacks(true)
+		return trace
+	}
+
+	pc := make([]uintptr, numTotalFrames)
+	// skip runtime.Callers and the klog.Backtrace API
+	n := runtime.Callers(trace.skip+2, pc)
+
+	if n == 0 {
+		// No PCs available. This can happen if the first argument to
+		// runtime.Callers is large.
+		//
+		// Return now to avoid processing the zero Frame that would
+		// otherwise be returned by frames.Next below.
+		return nil
+	}
+
+	if n > numTotalFrames {
+		fmt.Printf("error: runtime.Callers returned too many pcs (>%v)\n", numTotalFrames)
+		return nil
+	}
+
+	// pass only valid pcs to runtime.CallersFrames (remove goexit..)
+	pc = pc[:n-1]
+
+	// Account for "size" parameter
+	if trace.numframes > 0 && trace.numframes < n {
+		pc = pc[:trace.numframes]
+	}
+
+	frames := runtime.CallersFrames(pc)
+
+	var s string
+	for {
+		frame, more := frames.Next()
+		s += fmt.Sprintf("%s():\n\t%s:%v\n", frame.Function, frame.File, frame.Line)
+		if !more {
+			break
+		}
+	}
+	if s != "" {
+		trace.buf = []byte(s)
+	}
+
+	return trace
+}
+
+// stacks is a wrapper for runtime.Stack that attempts to recover the data for all goroutines.
+func stacks(all bool) []byte {
+	// We don't know how big the traces are, so grow a few times if they don't fit. Start large, though.
+	n := 10000
+	if all {
+		n = 100000
+	}
+	var trace []byte
+	for i := 0; i < 5; i++ {
+		trace = make([]byte, n)
+		nbytes := runtime.Stack(trace, all)
+		if nbytes < len(trace) {
+			return trace[:nbytes]
+		}
+		n *= 2
+	}
+	return trace
+}

dbg/backtrace_test.go

@@ -0,0 +1,193 @@
+/*
+Copyright 2022 The logr Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package dbg_test
+
+import (
+	"fmt"
+	"regexp"
+	"runtime"
+	"strings"
+	"testing"
+
+	"github.com/go-logr/lib/dbg"
+)
+
+// The tests are sensitive to line changes in the following code. Here are some
+// lines that can be added or removed to compensate for import statement
+// changes.
+//
+//
+//
+//
+//
+//
+//
+//
+// This must be line 40 (first line is 1).
+
+func outer(callback func() interface{}) interface{} {
+	return inner(callback)
+}
+
+func inner(callback func() interface{}) interface{} {
+	return callback()
+}
+
+//
+//
+//
+//
+//
+//
+//
+//
+//
+//
+// This must be line 60. Any line number higher than that gets ignored by normalizeBacktrace.
+
+func TestBacktrace(t *testing.T) {
+	for name, tt := range map[string]struct {
+		callback func() interface{}
+		expected string
+	}{
+		"simple": {
+			callback: func() interface{} { return dbg.Backtrace() },
+			expected: `github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+github.com/go-logr/lib/dbg_test.inner():
+	/zzz/backtrace_test.go:47
+github.com/go-logr/lib/dbg_test.outer():
+	/zzz/backtrace_test.go:43
+github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+`,
+		},
+
+		"skip0": {
+			callback: func() interface{} { return dbg.Backtrace(dbg.BacktraceSkip(0)) },
+			expected: `github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+github.com/go-logr/lib/dbg_test.inner():
+	/zzz/backtrace_test.go:47
+github.com/go-logr/lib/dbg_test.outer():
+	/zzz/backtrace_test.go:43
+github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+`,
+		},
+
+		"skip1": {
+			callback: func() interface{} { return dbg.Backtrace(dbg.BacktraceSkip(1)) },
+			expected: `github.com/go-logr/lib/dbg_test.inner():
+	/zzz/backtrace_test.go:47
+github.com/go-logr/lib/dbg_test.outer():
+	/zzz/backtrace_test.go:43
+github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+`,
+		},
+
+		"skip2": {
+			callback: func() interface{} { return dbg.Backtrace(dbg.BacktraceSkip(2)) },
+			expected: `github.com/go-logr/lib/dbg_test.outer():
+	/zzz/backtrace_test.go:43
+github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+`,
+		},
+
+		"trace1": {
+			callback: func() interface{} { return dbg.Backtrace(dbg.BacktraceSize(1)) },
+			expected: `github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+`,
+		},
+
+		"trace2": {
+			callback: func() interface{} { return dbg.Backtrace(dbg.BacktraceSize(2)) },
+			expected: `github.com/go-logr/lib/dbg_test.TestBacktrace.funcX():
+	/zzz/backtrace_test.go:xxx
+github.com/go-logr/lib/dbg_test.inner():
+	/zzz/backtrace_test.go:47
+`,
+		},
+
+		"skip1-trace1": {
+			callback: func() interface{} { return dbg.Backtrace(dbg.BacktraceSize(1), dbg.BacktraceSkip(1)) },
+			expected: `github.com/go-logr/lib/dbg_test.inner():
+	/zzz/backtrace_test.go:47
+`,
+		},
+	} {
+		t.Run(name, func(t *testing.T) {
+			backtrace := outer(tt.callback)
+			actual := normalizeBacktrace(t, backtrace)
+			if actual != tt.expected {
+				t.Errorf("Wrong backtrace. Expected:\n%s\nActual:\n%s\n", tt.expected, actual)
+			}
+		})
+	}
+}
+
+func normalizeBacktrace(t *testing.T, backtrace interface{}) string {
+	stringer, ok := backtrace.(fmt.Stringer)
+	if !ok {
+		t.Fatal("expected fmt.Stringer")
+	}
+	str := stringer.String()
+
+	// This matches the stack entry for the testing package:
+	// testing.tRunner():
+	//     /nvme/gopath/go-1.18.1/src/testing/testing.go:1439
+	//
+	// It and all following entries vary and get removed.
+	end := regexp.MustCompile(`(?m)^testing\.`).FindStringIndex(str)
+	if end != nil {
+		str = str[:end[0]]
+	}
+
+	// Remove varying line numbers.
+	str = regexp.MustCompile(`(?m):([67890][0-9]|[1-9][0-9][0-9])$`).ReplaceAllString(str, ":xxx")
+
+	// Remove varying anonymous function numbers.
+	str = regexp.MustCompile(`\.func[[:digit:]]+`).ReplaceAllString(str, ".funcX")
+
+	// Remove varying path names
+	str = regexp.MustCompile(`([[:blank:]]+)[[:^blank:]]*(backtrace_test.go:.*)`).ReplaceAllString(str, "$1/zzz/$2")
+
+	return str
+}
+
+func TestBacktraceAll(t *testing.T) {
+	_, callerFile, _, _ := runtime.Caller(0)
+	stringer, ok := dbg.Backtrace(dbg.BacktraceAll(true)).(fmt.Stringer)
+	if !ok {
+		t.Fatal("expected fmt.Stringer")
+	}
+	actual := stringer.String()
+	t.Logf("Backtrace:\n%s\n", actual)
+
+	if strings.Contains(actual, callerFile) == false {
+		t.Errorf("Expected to see %q in trace:\n%s", callerFile, actual)
+	}
+
+	// Pattern: goroutine 7 [running]:
+	p := regexp.MustCompile(`(?m)(^goroutine [0-9]*.\[.*\]*:)`)
+	if len(p.FindAllString(actual, -1)) < 2 {
+		t.Errorf("Expected more than 1 goroutine stack to be printed, got:\n%s", actual)
+	}
+}