diff --git a/backtrace.go b/backtrace.go new file mode 100644 index 000000000..5243829d5 --- /dev/null +++ b/backtrace.go @@ -0,0 +1,129 @@ +/* +Copyright 2022 The Kubernetes 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 klog + +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 = 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 +} diff --git a/backtrace_test.go b/backtrace_test.go new file mode 100644 index 000000000..2554337ea --- /dev/null +++ b/backtrace_test.go @@ -0,0 +1,185 @@ +/* +Copyright 2022 The Kubernetes 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 klog_test + +import ( + "fmt" + "regexp" + "runtime" + "strings" + "testing" + + "k8s.io/klog/v2" +) + +// 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 klog.Backtrace() }, + expected: `k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +k8s.io/klog/v2_test.inner(): + /zzz/backtrace_test.go:47 +k8s.io/klog/v2_test.outer(): + /zzz/backtrace_test.go:43 +k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "skip0": { + callback: func() interface{} { return klog.Backtrace(klog.BacktraceSkip(0)) }, + expected: `k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +k8s.io/klog/v2_test.inner(): + /zzz/backtrace_test.go:47 +k8s.io/klog/v2_test.outer(): + /zzz/backtrace_test.go:43 +k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "skip1": { + callback: func() interface{} { return klog.Backtrace(klog.BacktraceSkip(1)) }, + expected: `k8s.io/klog/v2_test.inner(): + /zzz/backtrace_test.go:47 +k8s.io/klog/v2_test.outer(): + /zzz/backtrace_test.go:43 +k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "skip2": { + callback: func() interface{} { return klog.Backtrace(klog.BacktraceSkip(2)) }, + expected: `k8s.io/klog/v2_test.outer(): + /zzz/backtrace_test.go:43 +k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "trace1": { + callback: func() interface{} { return klog.Backtrace(klog.BacktraceSize(1)) }, + expected: `k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +`, + }, + + "trace2": { + callback: func() interface{} { return klog.Backtrace(klog.BacktraceSize(2)) }, + expected: `k8s.io/klog/v2_test.TestBacktrace.funcX(): + /zzz/backtrace_test.go:xxx +k8s.io/klog/v2_test.inner(): + /zzz/backtrace_test.go:47 +`, + }, + + "skip1-trace1": { + callback: func() interface{} { return klog.Backtrace(klog.BacktraceSize(1), klog.BacktraceSkip(1)) }, + expected: `k8s.io/klog/v2_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 { + str := backtrace.(fmt.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) + actual := klog.Backtrace(klog.BacktraceAll(true)).(fmt.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) + } +}