diff --git a/backtrace.go b/backtrace.go new file mode 100644 index 0000000..d98853e --- /dev/null +++ b/backtrace.go @@ -0,0 +1,149 @@ +/* +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 loghelper + +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 +} diff --git a/backtrace_test.go b/backtrace_test.go new file mode 100644 index 0000000..b5232d7 --- /dev/null +++ b/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 loghelper_test + +import ( + "fmt" + "regexp" + "runtime" + "strings" + "testing" + + "github.com/go-logr/loghelper" +) + +// 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 loghelper.Backtrace() }, + expected: `github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +github.com/go-logr/loghelper_test.inner(): + /zzz/backtrace_test.go:47 +github.com/go-logr/loghelper_test.outer(): + /zzz/backtrace_test.go:43 +github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "skip0": { + callback: func() interface{} { return loghelper.Backtrace(loghelper.BacktraceSkip(0)) }, + expected: `github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +github.com/go-logr/loghelper_test.inner(): + /zzz/backtrace_test.go:47 +github.com/go-logr/loghelper_test.outer(): + /zzz/backtrace_test.go:43 +github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "skip1": { + callback: func() interface{} { return loghelper.Backtrace(loghelper.BacktraceSkip(1)) }, + expected: `github.com/go-logr/loghelper_test.inner(): + /zzz/backtrace_test.go:47 +github.com/go-logr/loghelper_test.outer(): + /zzz/backtrace_test.go:43 +github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "skip2": { + callback: func() interface{} { return loghelper.Backtrace(loghelper.BacktraceSkip(2)) }, + expected: `github.com/go-logr/loghelper_test.outer(): + /zzz/backtrace_test.go:43 +github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "trace1": { + callback: func() interface{} { return loghelper.Backtrace(loghelper.BacktraceSize(1)) }, + expected: `github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "trace2": { + callback: func() interface{} { return loghelper.Backtrace(loghelper.BacktraceSize(2)) }, + expected: `github.com/go-logr/loghelper_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +github.com/go-logr/loghelper_test.inner(): + /zzz/backtrace_test.go:47 +`, + }, + + "skip1-trace1": { + callback: func() interface{} { return loghelper.Backtrace(loghelper.BacktraceSize(1), loghelper.BacktraceSkip(1)) }, + expected: `github.com/go-logr/loghelper_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 := loghelper.Backtrace(loghelper.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) + } +}