Repository: kubernetes/klog
Pull request #397 (2024-01-11 13:55:09)

textlogger: allow caller to override stack unwinding
**What this PR does / why we need it**:

One use case is to use Ginkgo for stack unwinding. Then `ginkgo.GingkgoHelper` also works for log output, not just for E2E failures.

**Special notes for your reviewer**:

This is going to be used in extended support for test contexts. A preview of what's to come is currently in https://github.com/kubernetes/kubernetes/pull/122481/commits

**Release note**:
```release-note
textlogger: stack unwinding can be implemented outside of klog
```

k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/397#" title="Author self-approved">pohly</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/kubernetes/klog/blob/main/OWNERS)~~ [pohly]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
k8s-ci-robot: This issue is currently awaiting triage.

If klog contributors determine this is a relevant issue, they will accept it by applying the `triage/accepted` label and provide further guidance.

The `triage/accepted` label can be added by org members by writing `/triage accepted` in a comment.


<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository.
</details>
pohly: The apidiff errors is something that we can ignore:

```
 FAIL: k8s.io/klog/v2/textlogger contains incompatible changes:
- Config: old is comparable, new is not
- configOptions: old is comparable, new is not
```

We never said that the struct with no exported members is comparable and I can't think of a reason why someone would compare them anyway.
dashpole: /assign @mengjiao-liu
/triage accepted
pohly: @harshanarayana : can you perhaps take a look?

harshanarayana: @pohly ack
harshanarayana: /lgtm 

/cc @dims 
k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/397#issuecomment-1898316172" title="LGTM">harshanarayana</a>*, *<a href="https://github.com/kubernetes/klog/pull/397#" title="Author self-approved">pohly</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/kubernetes/klog/blob/main/OWNERS)~~ [pohly]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
k8s-ci-robot: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/kubernetes/klog/pull/397#issuecomment-1898359030" title="LGTM">dims</a>*, *<a href="https://github.com/kubernetes/klog/pull/397#issuecomment-1898316172" title="LGTM">harshanarayana</a>*, *<a href="https://github.com/kubernetes/klog/pull/397#" title="Author self-approved">pohly</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=kubernetes%2Fklog).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/kubernetes/klog/blob/main/OWNERS)~~ [dims,pohly]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
pohly: @dims : you might have to merge manually?


Patch:
diff --git a/textlogger/options.go b/textlogger/options.go
index a5c2530..b1c4eef 100644
--- a/textlogger/options.go
+++ b/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")
diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go
index 6200fd0..fb240c5 100644
--- a/textlogger/textlogger.go
+++ b/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()


Test patch:
diff --git a/textlogger/textlogger_test.go b/textlogger/textlogger_test.go
index 4382894..b2e15b5 100644
--- a/textlogger/textlogger_test.go
+++ b/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"
+}