contextual logging #296

pohly · 2022-02-16T08:03:47Z

What this PR does / why we need it:

Contextual logging enables several new use cases as shown in https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/3077-contextual-logging.

This PR is an implementation of the logging side of the revised KEP (currently pending in review). A PR with the logcheck changes will be filed separately.

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Related-to: kubernetes/enhancements#3077

Special notes for your reviewer:

We probably should merge the KEP change first.

This PR is best looked at commit-by-commit.

Release note:

Additional API calls for [contextual logging](https://github.com/kubernetes/enhancements/tree/master/keps/sig-instrumentation/3077-contextual-logging).

pohly · 2022-02-16T08:10:25Z

contextual.go

+// SetLogger sets a Logger implementation that will be used in two different
+// ways:
+// - as backing implementation of the traditional klog log calls
+// - for direct log calls afer retrieving it with FromContext, TODO, or


I need to call out one thing here: this requirement that direct log calls are also okay is new. Some loggers that were installed with SetLogger for use as backend might not work as expected because they don't check verbosity.

For example, the original JSON logger from component-base/logs didn't check verbosity and instead relied entirely on klog to do that for it. If called directly, all log entries would have gotten emitted.

Given that SetLogger is still relatively new, I feel that this change of semantics is acceptable. But if we want to be absolutely sure about not breaking anyone, we can also do this instead:

keep SetLogger as it is (i.e. loggers will only be called as backend)

add a new SetContextualLogger (same semantic as described here)

both functions set globalLogger, but also a boolean

Background returns klogr (i.e. logging goes through klog) when SetLogger was used, otherwise the logger

@serathius pointed out that SetLogger actually predates structured logging and was used already earlier to redirect Kubernetes output into other loggers.

A code search indeed finds users who rely on verbosity filtering in klog:

https://github.com/projectcontour/contour/blob/b9413e8851be0ff8dfb230ef872a015b168e990b/internal/k8s/log.go#L78-L84

https://github.com/Azure/secrets-store-csi-driver-provider-azure/blob/07b6ace393f32fd57a0c1f51e62155e4c2fc499a/cmd/main.go#L56 (the old JSON logger without verbosity)

Let's play it safe and use SetContextualLogger.

klogr.go

dims · 2022-03-02T11:50:41Z

/assign @thockin @serathius

serathius · 2022-03-03T11:40:47Z

contextual.go

+// logger may also get called directly by code that retrieves it
+// with FromContext, TODO or Background. The logger therefore must
+// implements its own verbosity checking.
+func SetContextualLogger(logger logr.Logger) {


Why have two different way to switch contextualLogger on? I think that having one switch like EnableContextualLogging is enough. Having two ways makes creates inconsistency and needless discussion on which option should be used.

It's just a feeling, but replacing klog.SetContextualLogger(logger) with

klog.SetLogger(logger) klog.EnableContextualLogging(true)

doesn't send a clear message to me that logger must meet certain criteria for this to work.

Also, EnableContextualLogging as it is defined right now is about something else and cannot be used to enable the additional usage of the logger.

It's on by default and controls the behavior of calls like FromContext. It's meaning is not "the logger can be used as contextual logger". We would need a separate klog.UseLoggerAsContextualLogger call for that - or something like that. I can't think of a good name and prefer to keep SetContextualLogger.

It's just a feeling, but replacing klog.SetContextualLogger(logger) with

klog.SetLogger(logger) klog.EnableContextualLogging(true)

doesn't send a clear message to me that logger must meet certain criteria for this to work.

If I remember this criteria, it was that provided logger needs to execute verbosity checks for itself. Right? I think the logr interface already expects that. I don't think we should be guided by rushed implementation for K8s json logging that skipped this.

Just want to make sure we don't bring old baggage to the API.

If I remember this criteria, it was that provided logger needs to execute verbosity checks for itself. Right?

Correct.

I don't think we should be guided by rushed implementation for K8s json logging that skipped this.

We can't be sure that other implementations didn't do the same. Searching for it with https://grep.app/search?q=klog.SetLogger finds several places that'll get broken if we change the requirements for the logger passed to SetLogger:

https://github.com/projectcontour/contour/blob/d231033fc25e8caf1137282ae8d49cbab562160f/internal/k8s/log.go#L78-L83

https://github.com/cri-o/cri-o/blob/f1d3a46642377d9bf4cb79255020b07578023540/internal/log/klog.go#L77

I think the logr interface already expects that.

The interface only expects that there is an Enabled function. It does not specify a specific semantic like "compare against your verbosity threshold", therefore an implementation that always returns true is valid. klog did specify a semantic ("verbosity check done by klog, logger should always log what it gets") and we shouldn't change that for SetLogger.

hmm. i keep forgetting that. how about the LogSink? roughly

func SetLogger(logger logr.Logger) { // call logger.GetSink() and do the // interface/method check here } func AddSupportsContext(logger logr.Logger) logr.Logger { sink := logger.GetSink() return logger.WithSink(wrapper{logger}) } type wrapper struct { logr.LogSink } func (w wrapper) SupportsContext() bool { return true } // usage: klog.SetLogger(klog.AddSupportsContext(logger))

That works. See additional commit for the result.

I find it rather ugly and it's also fragile (wrapping doesn't survive a logger.WithValues, for example), but it gets the job done. I can live with this.

As I noticed while working on this, wrapping like this is dropping the hidden logr.Logger.level field. To me this looks more and more like a hack.

Make SetContextualLogger an experimental/temporary function that will be removed.

Identify and file issue to github projects that didn't implement proper verbosity checking.

Remove SetContextualLogger when all the cases are fixed.

That means whoever wants two use contextual logging and directly call the logger must migrate twice: first to SetContextualLogger because SetLogger will not do what they want, then back to SetLogger once we have changed it. That doesn't sound appealling.

Another alternative is:

introduce SetContextualLogger as experimental (state of this PR before removing it)

when we consider it stable, remove the "experimental" tag

at the same time or later, mark SetLogger as deprecated

remove it when it no longer seems to be used

I don't know whether we can do that within the klog/v2. I'm also not sure whether "clean API" is worth all the trouble for the community.

Yet another alternative: adding optional functional parameters to SetLogger, without adding SetContextualLogger. The only parameter will be ContextualLogger(enabled bool). This is an API break in theory (function signature changes, so code which uses it for a function pointer breaks), but in practice the only usage seem to be direct calls and those continue to work without changes.

Another alternative is: [...] remove SetLogger when it no longer seems to be used

This implies that downstream users must change their code although it currently works fine for them. If they are happy with the current approach (klog flags + verbosity checks, Logger without verbosity check as backend), why should they change? Do we gain that much from the removal that it is worth breaking working code? I don't think so.

helpers.go

serathius · 2022-03-03T11:51:11Z

ktesting/options.go

+	}
+}
+
+// Verbosity overrides the default verbosity level of 5.


When we changed the default? I thought it was 0, or I misunderstand something?
Why have different default for testing?

Only the testing logger has a higher verbosity. klog still has 0.

The rationale is explained in the next sentence: at that level we get messages that will be useful to understand a failed test.

I've extended the explanations in the comment.

I understand the motivation, I'm not sure if this is new, have been discussed before or we are just adding in this PR because we can.

I don't think that increasing default verbosity is not a simple enough change that we can do it here. For example without understanding the impact of log volume on test infrastructure. I'm also not sure that a dependency should decide on changing the default logging verbosity for testing of k/k repo.

I think there is a misunderstanding. This klog/ktesting Logger is not changing anything in existing tests. Only unit tests that get converted as explained in the KEP and in the example in this repo are going to use it.

Unmodified tests will continue to log through the global klog logger, with the same verbosity as before.

Here's the example: https://github.com/kubernetes/klog/pull/296/files#diff-91dbb7e2e5d41b12cfae2565e8d22d69e19d403d850a6686ca7f786c6f605a28

pohly · 2022-03-08T15:17:52Z

/hold

Let's conclude the API discussion here, then update and merge the KEP first (kubernetes/enhancements#3222) before this one.

This logr implementation can be used in tests to ensure that output is associated with the currently running test. Compared to using the global klog instance in a standard Go test that has some advantages: - Log messages are associated with the currently running test. Tests can run in parallel without interleaving their output. - Log output is only printed when a test fails, unless "go test -v" is used. - Because of that, the logger can print more log messages by default, with 5 being used because that is recommended for debugging in https://github.com/kubernetes/community/blob/fbc5ca53d6bfd8388b335f7d0198b67a14b99d91/contributors/devel/sig-instrumentation/logging.md?plain=1#L34-L36 That threshold can be changed via -testing.v after registering that flag by importing k8s.io/klog/v2/ktesting/init. The motivation for hosting this logger in klog is that it shares the formatting code with klogr. Conceptually this is identical to go-logr/logr/testing, just the output is different (klog text format vs. JSON). $ go test -v ./testinglogger/example/ === RUN TestKlog example_test.go:69: INFO hello world example_test.go:70: ERROR failed err="failed: some error" example_test.go:71: INFO verbosity 1 example_test.go:72: INFO main/helper: with prefix example_test.go:73: INFO key/value pairs int=1 float=2 pair="(1, 2)" kobj="kube-system/sally" --- PASS: TestKlog (0.00s) The corresponding output from go-logr/logr/testing would be: === RUN TestLogr example_test.go:69: "ts"="2021-09-07 16:44:54.307551" "level"=0 "msg"="hello world" example_test.go:70: "ts"="2021-09-07 16:44:54.307664" "msg"="failed" "error"="failed: some error" example_test.go:71: "ts"="2021-09-07 16:44:54.307686" "level"=1 "msg"="verbosity 1" example_test.go:72: main/helper: "ts"="2021-09-07 16:44:54.307703" "level"=0 "msg"="with prefix" example_test.go:73: "ts"="2021-09-07 16:44:54.307733" "level"=0 "msg"="key/value pairs" "int"=1 "float"=2 "pair"={} "kobj"={"name":"sally","namespace":"kube-system"} --- PASS: TestLogr (0.00s)

The goal is to have only "legacy" code in klog.go.

As discussed in kubernetes/enhancements#3078, enabling code that only imports klog for all logging makes life simpler for developers. This was also the reason why KObj was added to klog instead of a separate helper package.

serathius · 2022-03-10T10:19:06Z

ktesting/init/init.go

+)
+
+func init() {
+	ktesting.DefaultConfig.AddFlags(flag.CommandLine)


I'm not sure about registering testing flags in init. Have we talked with SIG testing about what is the best way to integrate logging into test framework?

This is a Golang problem, not a SIG Testing problem. I asked Tim and he suggested to ask on golang-nuts. I did that but got no responses.

I've also asked on SIG Testing, just in case that someone there has an opinion: https://kubernetes.slack.com/archives/C09QZ4DQB/p1646918432994899

We can avoid the variant of SetLogger by indicating support via an additional interface that the LogSink must implement. This was seen as a cleaner approach (kubernetes#296 (comment)).

dims · 2022-03-10T16:18:37Z

contextual.go

+// application code. Only the LogSink seen by SetLogger needs to implement
+// this, clones of it as they occur during logger.V, logger.WithName or
+// logger.WithValues don't need it.
+type ContextualLogSink interface {


Do we need this to be public?

Only if we expect some LogSinks to implement it directly. They'll need it for compile-time checks that they implement the interface.

I'm fine with saying that only wrapping is supported.

I've pushed an update which doesn't have such an interface at all anymore.

dims · 2022-03-10T16:21:14Z

contextual_test.go

+	equal := logger == klog.Background()
+	fmt.Printf("original logr.Discard logger can be used directly: %v\n", equal)
+
+	logger = klog.AddSupportsContext(logger)


instead of this:

logger = klog.AddSupportsContext(logger) klog.SetLogger(logger)

could we do this?:

klog.SetLogger(klog.WithContextLogging(logger))

I then need to change how the result of klog.Background is checked. It's doable.

pohly · 2022-03-10T16:48:11Z

contextual.go

+// AddSupportsContext wraps a logger that doesn't know about ContextualLogSink
+// so that SetLogger knows that it can also be called directly.
+func AddSupportsContext(logger logr.Logger) logr.Logger {
+	return logr.New(contextualLogSinkWrapper{logger.GetSink()})


This is slightly broken: we loose the level field.

If someone does SetLogger(AddSupportsContext(logger.V(1))), then what we do instead is SetLogger(AddSupportedContext(logger)).

I can see a way around that, but it's going to be very ugly.

No, my idea doesn't work. I wanted to call logger.Enabled and then see how LogSink.Enabled is called (it gets a level), but it's not possible to intercept that call.

dims · 2022-03-11T11:58:26Z

@pohly after sleeping on it, i am ok with adding SetContextualLogger one question i had was

should SetLogger be deprecated
if we do deprecate and remove SetLogger, how would people get the functionality they do with SetLogger? Should we add an additional parameter to SetContextualLogger?

thanks!

pohly · 2022-03-11T13:29:23Z

should SetLogger be deprecated

It serves a particular purpose (use Logger as backend, and only as backend) which is a valid use case. If we deprecate it, then we need a replacement. I don't see a need for deprecating it, but don't feel strongly about it.

if we do deprecate and remove SetLogger, how would people get the functionality they do with SetLogger? Should we add an additional parameter to SetContextualLogger?

If we do that, then I prefer a different name. Currently the name implies a certain semantic, it would be odd to use it when that semantic is not desired.

The alternative is SetLoggerWithOptions(logger logr.Logger, opts ...klog.LoggerOptions), i.e. functional parameters, with an option ContextualLogger(enabled bool). It could be off by default, then SetLoggerWithOptions(logger) will be a direct replacement for a deprecated SetLogger.

dims · 2022-03-11T13:46:54Z

The alternative is SetLoggerWithOptions(logger logr.Logger, opts ...klog.LoggerOptions), i.e. functional parameters, with an option ContextualLogger(enabled bool). It could be off by default, then SetLoggerWithOptions(logger) will be a direct replacement for a deprecated SetLogger.

So ... i really like this approach! +1 from me.

pohly · 2022-03-11T15:07:26Z

I also like SetLoggerWithOptions best. Implemented.

dims · 2022-03-11T15:14:58Z

Squash please @pohly

dims · 2022-03-11T15:16:24Z

contextual.go

+//
+// Notice: This function is EXPERIMENTAL and may be changed or removed in a
+// later release.
+func EnableContextualLogging(enabled bool) {


Do we really need this?

It was an explicit request during the KEP review that Kubernetes must have a feature gate for the new functionality. This call here is needed for that feature gate.

The effect is IMHO minimal, but we still need it to comply with the Kubernetes policies.

dims · 2022-03-11T15:18:30Z

@thockin we worked through a bunch of things here, Can you please review now?

This moves the global logger into a separate file together with the functions that implement contextual logging. The advantage of SetLoggerWithOptions over alternatives like a SetContextualLogger without options is that it can be used as a drop-in replacement for SetLogger. This allows us to deprecate SetLogger. Whether we actually do that is kept open for now.

pohly · 2022-03-11T15:36:56Z

I squashed into stand-alone commits where each of them makes sense by itself.

I also update the corresponding KEP to match the API that we agreed upon here: kubernetes/enhancements#3222

@thockin if you agree with this PR, can you also review that KEP update?

thockin · 2022-03-14T23:23:47Z

KEP approved. I didn't read this code too deeply because I lack context on it, but it seems roughly the right shape and form.

dims · 2022-03-14T23:24:48Z

/approve
/lgtm

k8s-ci-robot · 2022-03-14T23:25:13Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, pohly

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

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [dims]

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

pohly · 2022-03-15T06:46:33Z

/hold cancel

KEP pending approval, but that's just a matter of getting the right okays now.

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. labels Feb 16, 2022

k8s-ci-robot requested review from detiber and neolit123 February 16, 2022 08:04

pohly commented Feb 16, 2022

View reviewed changes

This was referenced Feb 16, 2022

logcheck: contextual logging + enhanced checks #297

Merged

contextual logging kubernetes/enhancements#3077

Open

pohly force-pushed the contextual-logging branch from 74cfba6 to 56f831b Compare February 21, 2022 12:23

sbueringer mentioned this pull request Feb 23, 2022

Consider handling values that implement the Stringer interface when logging values #302

Closed

pohly commented Feb 23, 2022

View reviewed changes

klogr.go Outdated Show resolved Hide resolved

pohly force-pushed the contextual-logging branch from 56f831b to 78b7efe Compare February 23, 2022 13:26

sbueringer mentioned this pull request Feb 23, 2022

Tasks for Kubernetes v1.24 kubernetes-sigs/cluster-api#5968

Closed

33 tasks

k8s-ci-robot assigned serathius and thockin Mar 2, 2022

serathius reviewed Mar 3, 2022

View reviewed changes

helpers.go Outdated Show resolved Hide resolved

serathius reviewed Mar 3, 2022

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 Mar 8, 2022

pohly added 3 commits March 10, 2022 07:56

move Kubernetes helper code into separate file

64be563

The goal is to have only "legacy" code in klog.go.

make klog sufficient for working with logr

d888550

As discussed in kubernetes/enhancements#3078, enabling code that only imports klog for all logging makes life simpler for developers. This was also the reason why KObj was added to klog instead of a separate helper package.

pohly force-pushed the contextual-logging branch from 78b7efe to df761fd Compare March 10, 2022 06:56

serathius reviewed Mar 10, 2022

View reviewed changes

pohly force-pushed the contextual-logging branch from f6c3d15 to 1f82192 Compare March 10, 2022 15:41

dims reviewed Mar 10, 2022

View reviewed changes

pohly commented Mar 10, 2022

View reviewed changes

pohly force-pushed the contextual-logging branch 2 times, most recently from f4b4499 to 4dc1bbf Compare March 10, 2022 17:07

pohly force-pushed the contextual-logging branch from 4dc1bbf to 9bfd948 Compare March 11, 2022 15:07

pohly force-pushed the contextual-logging branch from 9bfd948 to e9f7846 Compare March 11, 2022 15:10

dims reviewed Mar 11, 2022

View reviewed changes

pohly force-pushed the contextual-logging branch from e9f7846 to 260ac21 Compare March 11, 2022 15:30

k8s-ci-robot assigned dims Mar 14, 2022

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 14, 2022

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Mar 14, 2022

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 15, 2022

k8s-ci-robot merged commit 6631b8c into kubernetes:main Mar 15, 2022

contextual logging #296

contextual logging #296

Conversation

pohly commented Feb 16, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dims commented Mar 2, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

serathius Mar 3, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly commented Mar 8, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly Mar 10, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dims commented Mar 11, 2022

pohly commented Mar 11, 2022

dims commented Mar 11, 2022

pohly commented Mar 11, 2022

dims commented Mar 11, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dims commented Mar 11, 2022

pohly commented Mar 11, 2022

thockin commented Mar 14, 2022

dims commented Mar 14, 2022

k8s-ci-robot commented Mar 14, 2022

pohly commented Mar 15, 2022

serathius Mar 3, 2022 •

edited

Loading

pohly Mar 10, 2022 •

edited

Loading