Skip to content

Commit

Permalink
textlogger: allow caller to override stack unwinding
Browse files Browse the repository at this point in the history
One use case is to use Ginkgo for stack unwinding. Then `ginkgo.GingkgoHelper`
also works for log output, not just for E2E failures.
  • Loading branch information
pohly authored and dims committed Jan 18, 2024
1 parent 2d08296 commit 007e661
Show file tree
Hide file tree
Showing 3 changed files with 67 additions and 7 deletions.
21 changes: 21 additions & 0 deletions textlogger/options.go
Expand Up @@ -58,6 +58,7 @@ type configOptions struct {
vmoduleFlagName string
verbosityDefault int
fixedTime *time.Time
unwind func(int) (string, int)
output io.Writer
}

Expand Down Expand Up @@ -105,6 +106,21 @@ func FixedTime(ts time.Time) ConfigOption {
}
}

// Backtrace overrides the default mechanism for determining the call site.
// The callback is invoked with the number of function calls between itself
// and the call site. It must return the file name and line number. An empty
// file name indicates that the information is unknown.
//
// # Experimental
//
// Notice: This function is EXPERIMENTAL and may be changed or removed in a
// later release.
func Backtrace(unwind func(skip int) (filename string, line int)) ConfigOption {
return func(co *configOptions) {
co.unwind = unwind
}
}

// NewConfig returns a configuration with recommended defaults and optional
// modifications. Command line flags are not bound to any FlagSet yet.
func NewConfig(opts ...ConfigOption) *Config {
Expand All @@ -114,6 +130,7 @@ func NewConfig(opts ...ConfigOption) *Config {
verbosityFlagName: "v",
vmoduleFlagName: "vmodule",
verbosityDefault: 0,
unwind: runtimeBacktrace,
output: os.Stderr,
},
}
Expand All @@ -127,6 +144,10 @@ func NewConfig(opts ...ConfigOption) *Config {
}

// AddFlags registers the command line flags that control the configuration.
//
// The default flag names are the same as in klog, so unless those defaults
// are changed, either klog.InitFlags or Config.AddFlags can be used for the
// same flag set, but not both.
func (c *Config) AddFlags(fs *flag.FlagSet) {
fs.Var(c.Verbosity(), c.co.verbosityFlagName, "number for the log level verbosity of the testing logger")
fs.Var(c.VModule(), c.co.vmoduleFlagName, "comma-separated list of pattern=N log level settings for files matching the patterns")
Expand Down
20 changes: 13 additions & 7 deletions textlogger/textlogger.go
Expand Up @@ -94,19 +94,25 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) {
func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []interface{}) {
// Determine caller.
// +1 for this frame, +1 for Info/Error.
_, file, line, ok := runtime.Caller(l.callDepth + 2)
if !ok {
skip := l.callDepth + 2
file, line := l.config.co.unwind(skip)
if file == "" {
file = "???"
line = 1
} else {
if slash := strings.LastIndex(file, "/"); slash >= 0 {
file = file[slash+1:]
}
} else if slash := strings.LastIndex(file, "/"); slash >= 0 {
file = file[slash+1:]
}

l.printWithInfos(file, line, time.Now(), err, s, msg, kvList)
}

func runtimeBacktrace(skip int) (string, int) {
_, file, line, ok := runtime.Caller(skip + 1)
if !ok {
return "", 0
}
return file, line
}

func (l *tlogger) printWithInfos(file string, line int, now time.Time, err error, s severity.Severity, msg string, kvList []interface{}) {
// Only create a new buffer if we don't have one cached.
b := buffer.GetBuffer()
Expand Down
33 changes: 33 additions & 0 deletions textlogger/textlogger_test.go
Expand Up @@ -75,3 +75,36 @@ func ExampleNewLogger() {
func someHelper(logger klog.Logger, msg string) {
logger.WithCallDepth(1).Info(msg)
}

func ExampleBacktrace() {
ts, _ := time.Parse(time.RFC3339, "2000-12-24T12:30:40Z")
internal.Pid = 123 // To get consistent output for each run.
backtraceCounter := 0
config := textlogger.NewConfig(
textlogger.FixedTime(ts), // To get consistent output for each run.
textlogger.Backtrace(func(skip int) (filename string, line int) {
backtraceCounter++
if backtraceCounter == 1 {
// Simulate "missing information".
return "", 0
}
return "fake.go", 42

// A real implementation could use Ginkgo:
//
// import ginkgotypes "github.com/onsi/ginkgo/v2/types"
//
// location := ginkgotypes.NewCodeLocation(skip + 1)
// return location.FileName, location.LineNumber
}),
textlogger.Output(os.Stdout),
)
logger := textlogger.NewLogger(config)

logger.Info("First message")
logger.Info("Second message")

// Output:
// I1224 12:30:40.000000 123 ???:1] "First message"
// I1224 12:30:40.000000 123 fake.go:42] "Second message"
}

0 comments on commit 007e661

Please sign in to comment.