Consider handling values that implement the Stringer interface when logging values

[sbueringer]

/kind feature

Context

When using klog today values are formatted like this: (as far as I'm aware)

values are formatted using %q fmt logic, except for number and boolean
kubernetes-sigs/controller-runtime#1811

This means the following log statement:

log.Info("message", "pod", klog.KRef("default", "pod-1"))

Leads to ~ this log:

I0222 15:47:40.088475 90786 cluster_controller.go:107] "msg"="message" "pod"={"name":"pod-1","namespace":"default"}

The following log statement will lead to a correct log:

log.Info("message", "pod", klog.KRef("default", "pod-1").String())

log:

I0222 15:47:40.088475 90786 cluster_controller.go:107] "msg"="message" "pod"="default/pod-1"}

Describe the solution you'd like

I think it would be great if the .String() call is not necessary, so it cannot be forgotten.

To make this possible klog would have to treat either klog.ObjectRef or values implementing fmt.Stringer differently (i.e. calling their String() func).

Anything else you would like to add:
[Miscellaneous information that will assist in solving the issue.]

[pohly]

log.Info("message", "pod", klog.KRef("default", "pod-1"))

What is log here?

[pohly]

I have a suspicion: are you using klogr with FormatSerialize (the default)? I think that one tries to produce JSON-like output.

Try using FormatKlog. Then key/value pairs are passed through to klog.InfoS and that output format will call Stringer.

[sbueringer]

The logger is the same as described on my previous issue: #294

We are currently using the Serialize format for logging-format=json and Klog for logging-format=text.
(we have to do this because otherwise we get "double-serialization" with json).

I could observe the issue with both, though. I'll update my minimal example here (https://github.com/sbueringer/cr-klog-issue) to reproduce.

I'll post an update once I've done that.

[sbueringer]

I can reproduce it with both:

• --logging-format = json (from component-base/logs) => with klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
• --logging-format = text (from component-base/logs) => klogr.New()

json:

{"ts":1645545586459.258,"caller":"cr-klog-issue/main.go:93","msg":"controller/pod: Test log","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capd-controller-manager-7dfb468fdc-74fps","namespace":"capd-system","pod":{"name":"pod-1","namespace":"default"}}
{"ts":1645545586459.389,"caller":"cr-klog-issue/main.go:94","msg":"controller/pod: Test log with .String()","v":0,"reconciler group":"","reconciler kind":"Pod","name":"capd-controller-manager-7dfb468fdc-74fps","namespace":"capd-system","pod":"default/pod-1"}

text:

I0222 17:00:39.171014   33977 main.go:93] controller/pod "msg"="Test log" "name"="kube-proxy-45dqb" "namespace"="kube-system" "reconciler group"="" "reconciler kind"="Pod" "pod"={"name":"pod-1","namespace":"default"}
I0222 17:00:39.171073   33977 main.go:94] controller/pod "msg"="Test log with .String()" "name"="kube-proxy-45dqb" "namespace"="kube-system" "reconciler group"="" "reconciler kind"="Pod" "pod"="default/pod-1"

Code: https://github.com/sbueringer/cr-klog-issue/blob/main/main.go#L93-L94

EDIT: Upgraded to latest commit on klog main, but same result.

[sbueringer]

If I see correctly:

• FormatSerialize just renders the value via json.NewEncoder().Encode() in pretty (in flatten)
• FormatKlog passes the values through as klog.ObjectRef to zap (in case of component-base/logs as they've implemented a backing JSON logger with zap).

[pohly]

This line is what I suspected:
https://github.com/sbueringer/cr-klog-issue/blob/a15fa1bea6cc56ad21b6a4a648e67f00ca507700/main.go#L57

You end up using the klogr output format, which is yet another way to format things. We kept it for backward-compatiblity and also couldn't change the default for klogr.New, but IMHO it is obsolete and shouldn't be used anymore.

When I use klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)), I get:

$ go run .
...
I0223 08:04:56.169807   18772 main.go:89] "controller/pod: Test log" reconciler group="" reconciler kind="Pod" name="kube-proxy-mfl9j" namespace="kube-system" pod="default/pod-1"
I0223 08:04:56.169828   18772 main.go:90] "controller/pod: Test log with .String()" reconciler group="" reconciler kind="Pod" name="kube-proxy-mfl9j" namespace="kube-system" pod="default/pod-1"

$ go run . --logging-format=json
...
{"ts":1645600108676.6528,"caller":"cr-klog-issue/main.go:89","msg":"controller/pod: Test log","v":0,"reconciler group":"","reconciler kind":"Pod","name":"coredns-558bd4d5db-l2hfb","namespace":"kube-system","pod":{"name":"pod-1","namespace":"default"}}
{"ts":1645600108676.6807,"caller":"cr-klog-issue/main.go:90","msg":"controller/pod: Test log with .String()","v":0,"reconciler group":"","reconciler kind":"Pod","name":"coredns-558bd4d5db-l2hfb","namespace":"kube-system","pod":"default/pod-1"}

This is what you want, right?

Here's the patch:

diff --git a/main.go b/main.go
index 8b4203e..64f9c7a 100644
--- a/main.go
+++ b/main.go
@@ -48,14 +48,10 @@ func main() {
 		os.Exit(1)
 	}
 
-	// The JSON log format requires the Klog format in klog, otherwise log lines
-	// are serialized twice, e.g.:
-	// { ... "msg":"controller/cluster \"msg\"=\"Starting workers\"\n"}
-	if logOptions.Config.Format == logs.JSONLogFormat {
-		ctrl.SetLogger(klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)))
-	} else {
-		ctrl.SetLogger(klogr.New())
-	}
+	// We log like this:
+	// klogr (FormatKlog) -> klog --> zapr (JSON format)
+	//                            \-> klog text format
+	ctrl.SetLogger(klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)))
 
 	mgr, err := ctrl.NewManager(ctrl.GetConfigOrDie(), ctrl.Options{
 		Scheme: scheme,

[sbueringer]

Ah thx for the background information.

Up until now, I only switched to FormatKlog for the JSON logging format because I definitely had to for JSON logging, but I wasn't aware that I should have used it for both logging formats.

I think it makes sense to use it for both logging formats consistently and looks like I have to for correct formatting.
Just out of curiosity, are there other reasons why the Serialize format is obsolete and shouldn't be used anymore?

Just took another look at the KEP and realized that with JSON format the rendered JSON object is the expected output (https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/1602-structured-logging#serialization-strategy). I missed that before. I thought it should be namespace/name for both logging formats.
(cc @fabriziopandini)

P.S. Overall our goal is only to align ClusterAPI to the structured logging KEP. But as I now realized, that can be done by just specifying the right klog format.

[pohly]

Just out of curiosity, are there other reasons why the Serialize format is obsolete and shouldn't be used anymore?

It doesn't provide any advantages over the other formats and is worse:

• it's not machine readable (in contrast to pure JSON via zapr)
• IMHO it's less readable for humans (in contrast to the original klog text format)

Overall our goal is only to align ClusterAPI to the structured logging KEP. But as I now realized, that can be done by just specifying the right klog format.

You might also want to look at kubernetes/enhancements#3222. I think your current approach will continue to work, but there is an opportunity to simplify logging by using ctrl.SetLogger(klog.Background()) after the logOptions.ValidateAndApply(): klog.Background() will return the underlying zapr logger when using JSON, so your log.Info calls then go directly to the logging backend, without the detour through klogr->klog. For text output, you get a klogr, just as you do yourself right now.

[sbueringer]

Thank you very much!

I assume this PR implements the KEP: #296. Tried it for my use case and it looks good overall.

Just fyi. It looks like with JSON the level is currently not preserved. I think it get's lost here:

klog/klogr.go

Lines 38 to 44 in 56f831b

	func (l klogger) Info(level int, msg string, kvList ...interface{}) {
	trimmed := serialize.TrimDuplicates(l.values, kvList)
	if l.prefix != "" {
	msg = l.prefix + ": " + msg
	}
	InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...)
	}

{"ts":1645610830835.741,"caller":"cr-klog-issue/main.go:95","msg":"controller/pod: Verbosity 0","v":0,"reconciler group":"","reconciler kind":"Pod","name":"coredns-558bd4d5db-nsm7l","namespace":"kube-system"}
{"ts":1645610830835.762,"caller":"cr-klog-issue/main.go:96","msg":"controller/pod: Verbosity 1","v":0,"reconciler group":"","reconciler kind":"Pod","name":"coredns-558bd4d5db-nsm7l","namespace":"kube-system"}

(updated https://github.com/sbueringer/cr-klog-issue accordingly)

(This issue can be closed as it's already possible today / just a matter of using the right klog format)

[pohly]

It looks like with JSON the level is currently not preserved.

Thanks for testing, I'll update the PR.

This issue can be closed as it's already possible today

/close

[k8s-ci-robot]

@pohly: Closing this issue.

In response to this:

It looks like with JSON the level is currently not preserved.

Thanks for testing, I'll update the PR.

This issue can be closed as it's already possible today

/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.

[fabriziopandini]

@pohly many thanks for the quick and detailed answers, really appreaciated!

[sbueringer]

@pohly many thanks for the quick and detailed answers, really appreaciated!

Yup absolutely, thank you very much!
I hope we can contribute more than just testing either to klog or to component-base/logs in the future :)

[pohly]

You are more than welcome to join us in the structured logging working group 😄