textlogger: allow caller to override stack unwinding

One use case is to use Ginkgo for stack unwinding. Then `ginkgo.GingkgoHelper`
also works for log output, not just for E2E failures.

Author: pohly

textlogger/options.go

@@ -58,6 +58,7 @@ type configOptions struct {
 	vmoduleFlagName   string
 	verbosityDefault  int
 	fixedTime         *time.Time
+	unwind            func(int) (string, int)
 	output            io.Writer
 }
 
@@ -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 {
@@ -114,6 +130,7 @@ func NewConfig(opts ...ConfigOption) *Config {
 			verbosityFlagName: "v",
 			vmoduleFlagName:   "vmodule",
 			verbosityDefault:  0,
+			unwind:            runtimeBacktrace,
 			output:            os.Stderr,
 		},
 	}
@@ -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")

textlogger/textlogger.go

@@ -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()

textlogger/textlogger_test.go

@@ -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"
+}