add structured logging helper #269

pohly · 2021-11-12T15:21:55Z

What this PR does / why we need it:

When passing an object with complex content as a key in a key/value list, good
formatting of that object will be different for text and structured
output. Custom formatters can be provided by implementing fmt.Stringer and
logr.Marshaler, but that implies defining custom types outside of the function
which does the logging.

The new LogAs helper struct provideds the necessary boilerplate code and allows
users to keep all code inside the same function.

Which issue(s) this PR fixes:
Fixes kubernetes/kubernetes#106258

Release note:

The klog.As helper struct can be used to log values as text in the klog text output and as real structure in loggers which produce structured output (for example, JSON).

k8s-ci-robot · 2021-11-12T15:22:19Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: pohly
To complete the pull request process, please assign justinsb after the PR has been reviewed.
You can assign the PR to them by writing /assign @justinsb in a comment when ready.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

pohly · 2021-11-12T15:27:16Z

/cc @shivanshu1333 @serathius
/wg structured-logging
/sig instrumentation
/priority important-longterm
/kind feature

pohly · 2021-11-12T15:28:52Z

The test works with go test -run ExampleLogAs . but fails with go test ., probably because other tests are messing with the global state of klog.

This PR also conflicts with PR #268 (different output in the test). Let's discuss the API and later figure out how to test it.

pohly · 2021-11-12T15:32:18Z

klog.go

+// The same can be done with custom structs. The advantage of LogAs is that the
+// formatting code can be written inline in the same function that logs some
+// object.
+type LogAs struct {


LogAs is a proposal. Alternative suggestions are welcome.

I find it sounds a bit too much like "kick ass"... 😅

Note that I chose to implement this as a struct. The advantage is that the reader of code which uses LogAs gets a hint what the functions do, at least when the struct gets initialized with named fields.

The disadvantage is that users might accidentally forget to initialize one of the functions. That compiles, but then will crash when used, at least as it stands now.

What about just As? it'd read a bit more like klog.As more than klog.LogAs which stutters

I like that proposal.

I changed it.

pohly · 2021-11-12T15:33:06Z

klog.go

+}
+
+func (l LogAs) String() string          { return l.Text() }
+func (l LogAs) MarshalLog() interface{} { return l.Object() }


Here we could check for nil functions to avoid crashes. If nil, the helper functions could return "nil".

Structured logging with InfoS is formatted differently than traditional output, so it's worthwhile to have an example that demostrates that. The new example didn't compile initially because an older version of klog was used. This gets avoids by always using the source from the current directory.

pohly · 2021-12-01T13:46:36Z

The test works with go test -run ExampleLogAs . but fails with go test ., probably because other tests are messing with the global state of klog.

Solved by moving the example. The downside is that it will not appear in the API documentation anymore. I had to cherry-pick one commit from my other PR to get examples/go.mod updated without causing future conflicts.

This PR also conflicts with PR #268 (different output in the test). Let's discuss the API and later figure out how to test it.

There should be no conflict anymore because the format change will be smaller than originally proposed.

This PR is therefore ready for review and merging.

When passing an object with complex content as a key in a key/value list, good formatting of that object will be different for text and structured output. Custom formatters can be provided by implementing fmt.Stringer and logr.Marshaler, but that implies defining custom types outside of the function which does the logging. The new klog.As helper struct provideds the necessary boilerplate code and allows users to keep all code inside the same function.

pohly · 2021-12-01T13:52:54Z

.github/workflows/test.yml

        cd hack/tools && go test -v -race ./...
+    - name: Test examples


We could use cd hack/tools && go test -v -race ./... && cd ../.. and keep everything in one step. I find it cleaner to have different steps with different names.

I also tried (cd hack/tools && go test -v -race ./...). That worked on Linux, but not on Windows because cd still had an effect also after the subshell?!

Cannot find path 'D:\a\klog\klog\hack\tools\examples' because it does not exist.

pohly · 2021-12-10T08:00:01Z

/hold

Let's also consider this code here:
https://github.com/kubernetes/kubernetes/blob/cc6f12583f2b611e9469a6b2e0247f028aae246b/pkg/controller/replicaset/replica_set.go#L794-L800

Let's ignore for a second that this should be InfoS and that klog.KObjs might be useful here.

I think it would make sense to have a helper which supports writing a fmt.Stringer like this:

klog.V(2).Infof("Found %d related pods for %v %s/%s: %v", len(relatedPods), rsc.Kind, rs.Namespace, rs.Name, klog.AsText(func() string {
    var relatedNames []string
    for _, related := range relatedPods {
        relatedNames = append(relatedNames, related.Name)
    }
    return strings.Join(relatedNames, ", ")
})

klog.AsText would return a struct that implements fmt.Stringer by calling the inline function.

klog.AsObject would also make sense.

Both are special cases of klog.As. We can and should define them as equivalent to klog.As with one parameter as nil and change the semantic of that so that it only implements the interfaces for which it has functions.

pohly · 2021-12-10T09:55:17Z

We can and should define them as equivalent to klog.As with one parameter as nil and change the semantic of that so that it only implements the interfaces for which it has functions.

I forgot that klog.As isn't a function. Perhaps it should be after all?

@vincepri: are you okay with this:

klog.InfoS("hello", "world", klog.As(
    func() string {
        return "something"
    },
    func() interface{} {
        return "else"
    })

Delayed string formatting is useful also without structured logging. Several places in Kubernetes use if klog.V(2).Enabled() { <format some output as string> klog.Info(<message>) } This can be shortened to klog.V(2).Info(klog.AsString(func() string { <format and return output> }) For the sake of consistency and flexibility, klog.As then also should be a function instead of the underlying struct.

vincepri · 2021-12-10T16:12:25Z

@pohly I'd keep them separate, specifying a nil value can be confusing for users and create noise inside the codebase where you would see something like

klog.As(
    func() string {
        return "something"
    }, nil)

which could quickly lead into confusion, especially for new users reading the code.

We could just offer AsObject and AsText instead?

In most cases, do we expect folks to implement logr.Marshaler interface on an object, or potentially use one of the built-in wrappers, like the object reference one? Is that a correct assumption or am I missing something?

pohly · 2021-12-10T16:32:17Z

We cannot drop klog.As. We need it for the case where an object needs to be logged differently in text and JSON output.

What we can drop is the comment about the functions being allowed to be nil, i.e. the example you gave then should never be written like that. Should klog.As then check for nil at all or is allowed to crash when used incorrectly?

AsObject is not terribly useful for the reason given in its comment (can only be used when knowing that the logger supports it). I was undecided whether it should be part of the API at all and only kept it for the sake of completeness. If we don't allow klog.As(nil, <some object func>), then we shouldn't have AsObject either.

pohly · 2021-12-10T16:33:29Z

BTW, I am currently working on POC PR against Kubernetes where I am using the new functions. Both klog.As and klog.AsText are useful.

It is needed in Kubernetes for code like this (from k8s.io/apiserver/pkg/server/httplog/httplog.go): // Log is intended to be called once at the end of your request handler, via defer func (rl *respLogger) Log() { ... klog.V(withLoggingLevel).InfoSDepth(1, "HTTP", keysAndValues...) } Without InfoSDepth as method for Verbose, such code has to use klog.InfoSDepth, which records the message with v=0 in JSON output. This is the wrong verbosity for this debug message. We don't need Verbose.ErrorSDepth (error messages have no verbosity) and also no Verbose.Info[f]Depth (when touching code, it should be rewritten to use Verbose.InfoSDepth instead)

pohly · 2021-12-13T15:34:21Z

I am currently working on POC PR against Kubernetes where I am using the new functions. Both klog.As and klog.AsText are useful.

See kubernetes/kubernetes#106978

thockin · 2021-12-13T17:24:14Z

examples/klog_as/klog_as_test.go

+	}
+	klog.InfoS("No formatting", "item", item)
+
+	as := klog.As(


I don't think I understand the intermediate structs. I thought about something like this in th past but let it slip. Why is it more complex than:

// maybe in logr? func AsString(fn func() string) fmt.Stringer { return asString{fn} } func AsStruct(fn func() logr.PseudoStruct { return asStruct{fn} }

// in caller log.V(3).Info("the message", "arg", logr.AsText(func() string { // complex or expensive or hyper-local logic })

I'm not even sure we need different functions? Why not:

type LogFunc func() interface{}

and

log.V(3).Info("the message", "arg", logr.LogFunc(func() interface{}) { return expensiveProcessing(obj) }

and handle LogFunc as a parallel to Stringer and LogMarshaller

log.V(3).Info("the message", "arg", logr.AsText(func() string

This will always be rendered as text, both in text output and JSON. Such a call can be useful to avoid extra Enabled() calls. It's not absolutely required.

log.V(3).Info("the message", "arg", logr.LogFunc(func() interface{})

This has two problems:

only loggers which support logr.Marshaler will invoke the function; the klog text format will call fmt.Sprintf("%v", <proxy object>), which then renders as object(0x<address>)

if it gets called, the function cannot decide whether the caller wants a human-readable string (text format) or machine-readable struct (JSON)

thockin · 2021-12-13T17:50:49Z

e.g.

diff --git a/logr.go b/logr.go
index c05482a..707f7ac 100644
--- a/logr.go
+++ b/logr.go
@@ -499,3 +499,5 @@ type Marshaler interface {
        // It may return any value of any type.
        MarshalLog() interface{}
 }
+
+type Callback func() interface{}
diff --git a/funcr/example_test.go b/funcr/example_test.go
index 53373a2..3800f97 100644
--- a/funcr/example_test.go
+++ b/funcr/example_test.go
@@ -45,6 +45,16 @@ func ExampleNewJSON() {
        // Output: {"logger":"MyLogger","level":0,"msg":"the message","savedKey":"savedValue","key":"value"}
 }
 
+func ExampleCallback() {
+       var log logr.Logger = funcr.NewJSON(func(obj string) {
+               fmt.Println(obj)
+       }, funcr.Options{})
+
+       log = log.WithName("MyLogger")
+       log.Info("the message", "key", logr.Callback(func() interface{} { return funcr.PseudoStruct{"v1", 1, "v2", 2} }))
+       // Output: {"logger":"MyLogger","level":0,"msg":"the message","key":{"v1":1,"v2":2}}
+}
+
 func ExampleUnderlier() {
        var log logr.Logger = funcr.New(func(prefix, args string) {
                fmt.Println(prefix, args)
diff --git a/funcr/funcr.go b/funcr/funcr.go
index b23ab96..bef2c34 100644
--- a/funcr/funcr.go
+++ b/funcr/funcr.go
@@ -352,6 +352,11 @@ func (f Formatter) prettyWithFlags(value interface{}, flags uint32, depth int) s
                // Replace the value with what the type wants to get logged.
                // That then gets handled below via reflection.
                value = v.MarshalLog()
+       } else if v, ok := value.(logr.Callback); ok {
+               //FIXME: define the semantics in logr - should this be an else-if or if?
+               // Replace the value with what the callsite wants to get logged.
+               // That then gets handled below via reflection.
+               value = v()
        }
 
        // Handle types that want to format themselves.

pohly · 2021-12-13T18:16:49Z

logr.go: type Callback func() interface{}

This is semantically equivalent to the existing logr.Marshaler interface except that it works for stand-alone functions (and only for those). I don't think we need another, less flexible way of doing the same thing.

thockin · 2021-12-13T19:19:04Z

Maybe I am missing the point. If I have to define an "as" struct and 2 "methods" why would I not just define a real type? It's just a few LoC more but is more reusable and understandable. I proposed Callback as hyper-local thing, but now I am not sure we need anything...

…

On Mon, Dec 13, 2021, 10:17 AM Patrick Ohly ***@***.***> wrote: logr.go: type Callback func() interface{} This is semantically equivalent to the existing logr.Marshaler interface except that it works for stand-alone functions (and only for those). I don't think we need another, less flexible way of doing the same thing. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#269 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABKWAVH3UHCDJH2SX3LNBILUQY2BZANCNFSM5H5CQL7Q> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

pohly · 2021-12-13T19:31:20Z

Maybe I am missing the point. If I have to define an "as" struct and 2
"methods" why would I not just define a real type? It's just a few LoC
more but is more reusable and understandable.

The type and it's methods have to be defined outside of the function which wants to log values. Then the struct has to be initialized explicitly with all values that are going to be needed by the methods, which makes both the struct and its construction longer. Or is there a way to do that inside a function, with variables inside that function available inside the local type's methods?

I can use kubernetes/kubernetes#106978 (review) as example to show how an actual log call can be converted when klog.As isn't available, but probably won't get to it anymore today.

@thockin: what do you think about klog.AsText and the examples where it is used in kubernetes/kubernetes#106978? Is that useful?

thockin · 2021-12-14T00:00:41Z

Maybe I am missing the point. If I have to define an "as" struct and 2
"methods" why would I not just define a real type? It's just a few LoC
more but is more reusable and understandable.

The type and it's methods have to be defined outside of the function which wants to log values. Then the struct has to be initialized explicitly with all values that are going to be needed by the methods, which makes both the struct and its construction longer. Or is there a way to do that inside a function, with variables inside that function available inside the local type's methods?

Let's back up a second.

For hyper-local use-cases (e.g. "I have a thing I want to log, but I want to
log it differently this ONE TIME" you can maybe make the argument that defining
a new type and methods (which do need to be defined outside this function) is
cumbersome. In that case, it doesn't seem like a stretch to say "do it
yourself". e.g.

	rendered := ""
	if log.V(5).Enabled() {
		if rendered == "" {
			rendered = expensiveFunc(obj)
		}
		log.V(5).Info("message", "obj", rendered)
	}

But if you are going to do that more than one place, it makes sense to go
define the wrapper type.

My Callback proposal was really just about deferring expensive ops until they
are actually needed (and not calling them at all if the log is not enabled).

	log.V(5).Info("message", "obj",
		logr.Callback(func() interface{} { return expensiveFunc(obj)}))

@thockin: what do you think about klog.AsText and the examples where it is used in kubernetes/kubernetes#106978? Is that useful?

In pretty much every case it seems the structured output would be an acceptable replacement for the text output, so I don't think you need the stringer part (it doesn't seem to pay for itself). If you remove that, you are more or less back to Callback and then we can argue about where it fits in the API layering.

But I feel like I am still missing your point

pohly · 2021-12-14T07:27:12Z

My Callback proposal was really just about deferring expensive ops until they
are actually needed (and not calling them at all if the log is not enabled).

That's the same goal that I have with AsText.

In pretty much every case it seems the structured output would be an acceptable replacement for the text output, so I don't think you need the stringer part (it doesn't seem to pay for itself).

Here I disagree. I think there are several places in Kubernetes were developers use custom code to prepare a text dump with information that they need for debugging. Turning that dump into a structure will make it less readable in text output (fmt.Sprintf("%v")!).

But for such a case the if klog.V(5).Enabled() { <prepare text>; klog.V(5).InfoS(..., <text>) } pattern can be used, so klog.AsText isn't really needed.

I'll rewrite kubernetes/kubernetes#106978 without these helpers.

pohly · 2021-12-14T14:39:59Z

If you have a hammer, the world looks like a nail... and all I did was hit my own finger.

After taking another stab at kubernetes/kubernetes#106978 without the helper functions, the result turned out to be quite okay. In one place I managed to convince myself that a struct will be okay also for text output.

Let's close this one and continue the review of the resulting code patterns in kubernetes/kubernetes#106978

/close

k8s-ci-robot · 2021-12-14T14:40:25Z

@pohly: Closed this PR.

In response to this:

If you have a hammer, the world looks like a nail... and all I did was hit my own finger.

After taking another stab at kubernetes/kubernetes#106978 without the helper functions, the result turned out to be quite okay. In one place I managed to convince myself that a struct will be okay also for text output.

Let's close this one and continue the review of the resulting code patterns in kubernetes/kubernetes#106978

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Nov 12, 2021

k8s-ci-robot requested review from jayunit100 and vincepri November 12, 2021 15:22

k8s-ci-robot requested review from serathius and shivanshuraj1333 November 12, 2021 15:27

pohly commented Nov 12, 2021

View reviewed changes

pohly mentioned this pull request Nov 12, 2021

structured logging: helper struct for formatting an object kubernetes/kubernetes#106258

Closed

pohly commented Nov 12, 2021

View reviewed changes

pohly force-pushed the log-format-helper branch from 3ac7a02 to 11ec4e3 Compare December 1, 2021 13:40

k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Dec 1, 2021

pohly force-pushed the log-format-helper branch from 11ec4e3 to 0b2388e Compare December 1, 2021 13:44

pohly changed the title ~~RFC: add structured logging helper~~ add structured logging helper Dec 1, 2021

pohly force-pushed the log-format-helper branch from 0b2388e to b6266e9 Compare December 1, 2021 13:50

pohly commented Dec 1, 2021

View reviewed changes

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Dec 10, 2021

pohly force-pushed the log-format-helper branch from 587b288 to 7c3ad19 Compare December 10, 2021 14:13

pohly added 2 commits December 11, 2021 11:14

As requires both functions, remove AsObject

15761d1

pohly force-pushed the log-format-helper branch from c76b8d9 to 6564c1b Compare December 11, 2021 10:37

thockin reviewed Dec 13, 2021

View reviewed changes

k8s-ci-robot closed this Dec 14, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add structured logging helper #269

add structured logging helper #269

pohly commented Nov 12, 2021 •

edited

k8s-ci-robot commented Nov 12, 2021

pohly commented Nov 12, 2021

pohly commented Nov 12, 2021

pohly Nov 12, 2021

vincepri Nov 15, 2021 •

edited

pohly Nov 16, 2021

pohly Dec 1, 2021

pohly Nov 12, 2021

pohly Dec 1, 2021

pohly commented Dec 1, 2021

pohly Dec 1, 2021 •

edited

pohly commented Dec 10, 2021 •

edited

pohly commented Dec 10, 2021

vincepri commented Dec 10, 2021 •

edited

pohly commented Dec 10, 2021

pohly commented Dec 10, 2021

pohly commented Dec 13, 2021

thockin Dec 13, 2021 •

edited

pohly Dec 13, 2021

thockin commented Dec 13, 2021 •

edited

pohly commented Dec 13, 2021

thockin commented Dec 13, 2021 via email

pohly commented Dec 13, 2021 •

edited

thockin commented Dec 14, 2021

pohly commented Dec 14, 2021

pohly commented Dec 14, 2021

k8s-ci-robot commented Dec 14, 2021

		cd hack/tools && go test -v -race ./...
		- name: Test examples

add structured logging helper #269

add structured logging helper #269

Conversation

pohly commented Nov 12, 2021 • edited

k8s-ci-robot commented Nov 12, 2021

pohly commented Nov 12, 2021

pohly commented Nov 12, 2021

pohly Nov 12, 2021

Choose a reason for hiding this comment

vincepri Nov 15, 2021 • edited

Choose a reason for hiding this comment

pohly Nov 16, 2021

Choose a reason for hiding this comment

pohly Dec 1, 2021

Choose a reason for hiding this comment

pohly Nov 12, 2021

Choose a reason for hiding this comment

pohly Dec 1, 2021

Choose a reason for hiding this comment

pohly commented Dec 1, 2021

pohly Dec 1, 2021 • edited

Choose a reason for hiding this comment

pohly commented Dec 10, 2021 • edited

pohly commented Dec 10, 2021

vincepri commented Dec 10, 2021 • edited

pohly commented Dec 10, 2021

pohly commented Dec 10, 2021

pohly commented Dec 13, 2021

thockin Dec 13, 2021 • edited

Choose a reason for hiding this comment

pohly Dec 13, 2021

Choose a reason for hiding this comment

thockin commented Dec 13, 2021 • edited

pohly commented Dec 13, 2021

thockin commented Dec 13, 2021 via email

pohly commented Dec 13, 2021 • edited

thockin commented Dec 14, 2021

pohly commented Dec 14, 2021

pohly commented Dec 14, 2021

k8s-ci-robot commented Dec 14, 2021

pohly commented Nov 12, 2021 •

edited

vincepri Nov 15, 2021 •

edited

pohly Dec 1, 2021 •

edited

pohly commented Dec 10, 2021 •

edited

vincepri commented Dec 10, 2021 •

edited

thockin Dec 13, 2021 •

edited

thockin commented Dec 13, 2021 •

edited

pohly commented Dec 13, 2021 •

edited