Add SetLogger function to intercept klog output with logr

[munnerz]

This is an example of how we can modify klog and the work required in order to allow intercepting logs, including preserving the V level and severity.

In order to do this, I've had to change the type signature of Verbose from type Verbose bool to:

type Verbose struct {
	enabled bool
	logr    logr.InfoLogger
}

Consequently, it requires a corresponding change in k/k in the instances where if klog.V(x) { (replacing them with if klog.V(x).Enabled()).

The total changeset in k/k to get bazel build //... to pass:

 pkg/cloudprovider/providers/gce/cloud/gen.go                | 160 +++++++++++++++++++++++++++++++++++++++++++++++++--------------------------------------------------
 pkg/cloudprovider/providers/vsphere/vclib/connection.go     |   2 +-
 pkg/controller/nodelifecycle/node_lifecycle_controller.go   |   4 +--
 pkg/controller/volume/attachdetach/reconciler/reconciler.go |   6 ++--
 pkg/kubectl/cmd/util/helpers.go                             |   2 +-
 pkg/kubelet/eviction/helpers.go                             |   4 +--
 pkg/proxy/endpoints.go                                      |   2 +-
 pkg/scheduler/algorithm/predicates/predicates.go            |   8 ++---
 pkg/scheduler/algorithm/priorities/interpod_affinity.go     |   2 +-
 pkg/scheduler/algorithm/priorities/resource_allocation.go   |   2 +-
 pkg/scheduler/algorithm/priorities/resource_limits.go       |   2 +-
 pkg/scheduler/algorithm/priorities/selector_spreading.go    |   2 +-
 pkg/scheduler/core/generic_scheduler.go                     |   6 ++--
 plugin/pkg/auth/authorizer/rbac/rbac.go                     |   2 +-
 staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go  |   4 +--
 staging/src/k8s.io/apiserver/pkg/util/trace/trace.go        |   4 +--
 staging/src/k8s.io/client-go/rest/request.go                |   8 ++---
 staging/src/k8s.io/client-go/transport/round_trippers.go    |   8 ++---
 18 files changed, 114 insertions(+), 114 deletions(-)

We can still preserve the old behaviour in the k8s.io/klog/glog package, for those that are using the dep replace method to implement glog.

ref #19

[munnerz]

/cc @dims

[dims]

cc @thockin @tallclair

[neolit123]

so previously Verbose was a bool type, but now it's a struct.
isn't the compiler complaining that we are casting a bool to type Verbose here? 😬

cannot convert Enabled() (type bool) to type Verbose

https://play.golang.org/p/JxCC36UsKOn

[munnerz]

So Verbose has been changed to a struct in klog itself - this is the glog 'shim' which is provided to make transitioning to klog easier.

I've not changed the API surface of the glog package at all, meaning if someone were to use a V level, the message would actually be logged without using a klog 'Verbose'. This is not caused by this patch, rather it's how the package was originally written!

[neolit123]

got it.

[DirectXMan12]

couple of comments inline. I think this is an interesting first pass, but ideally, we'd be passing some of the information from glog to logr as structured data instead of just flat-dumping to strings. Some is also probably duplicate to what other logr implementations capture. I think we probably want to assume that the given implementation will take care of stuff like backtraces, depth, etc if it wants it, but I'm open to other interpretations.

(flat-dumping to strings also breaks stuff like Zap's optional log-line collapsing, and it thus not recommended by logr)

[DirectXMan12]

I'm not sure we actually want the header in here -- it should be the job of the logr implementation to attach that kind of information, and logging it is just going to produce noise. If it must be included, I'd leave it as a tag or tags

[neolit123]

@munnerz is this change still needed after the merge of:
https://github.com/kubernetes/klog/blob/master/klogr

[munnerz]

@neolit123 the klogr package allows you to use klog with logr like interface - this patch would, allow you to intercept klog output and pipe it back via a logr interface, in order to make it possible to 'hijack' logs from code that currently uses klog and pipe it via your own logr interface.

My use case for this, is so that I can grab all output from the k8s apimachinery and pipe it via my own logr interface (so that it can be post-processed accordingly)

[munnerz]

Is there still an interest in something like this in klog? If so, I'll pick this up again. I can address to above comments if it's likely we want to go down this route 😄

[dims]

@munnerz yes please

/assign @thockin @pohly

[munnerz]

I've added a few additional changes on top of this PR, notably:

• if klog.Errorf is called, the actual log message will be propagated to the logr implementations Error method. This is implemented in a sort-of wonky way. I've added a TODO, but if anyone has any thoughts and thinks we should implement this here, I can add it before we merge 😄

• No longer include log line headers if output is being redirected to logr

• Including file and line attributes as logr values

Hopefully that addresses the above comments 😄

[thockin]

So I can use klog as the backend for a logr or a logr as the backend for klog? Can I make a loop?

Can you show what the output here would look like?

Also, logr already suggests "caller" s a special key for the calling information (file/line) of a particular log line.

[thockin]

I'm pretty sure there's code that relies on this being a bool, isn't there?

[munnerz]

Yep, there is.

There's not really any way we can do this cleanly without this, as a bool does not contain enough information to determine which V level should be logged at when Info is called on that V.

I mentioned it in the initial PR body, but the actual changeset needed to make kubernetes/kubernetes compile is:

 pkg/cloudprovider/providers/gce/cloud/gen.go                | 160 +++++++++++++++++++++++++++++++++++++++++++++++++--------------------------------------------------
 pkg/cloudprovider/providers/vsphere/vclib/connection.go     |   2 +-
 pkg/controller/nodelifecycle/node_lifecycle_controller.go   |   4 +--
 pkg/controller/volume/attachdetach/reconciler/reconciler.go |   6 ++--
 pkg/kubectl/cmd/util/helpers.go                             |   2 +-
 pkg/kubelet/eviction/helpers.go                             |   4 +--
 pkg/proxy/endpoints.go                                      |   2 +-
 pkg/scheduler/algorithm/predicates/predicates.go            |   8 ++---
 pkg/scheduler/algorithm/priorities/interpod_affinity.go     |   2 +-
 pkg/scheduler/algorithm/priorities/resource_allocation.go   |   2 +-
 pkg/scheduler/algorithm/priorities/resource_limits.go       |   2 +-
 pkg/scheduler/algorithm/priorities/selector_spreading.go    |   2 +-
 pkg/scheduler/core/generic_scheduler.go                     |   6 ++--
 plugin/pkg/auth/authorizer/rbac/rbac.go                     |   2 +-
 staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go  |   4 +--
 staging/src/k8s.io/apiserver/pkg/util/trace/trace.go        |   4 +--
 staging/src/k8s.io/client-go/rest/request.go                |   8 ++---
 staging/src/k8s.io/client-go/transport/round_trippers.go    |   8 ++---
 18 files changed, 114 insertions(+), 114 deletions(-)

(as of a couple of months ago).

I would be keen to hear any suggestions on how we can avoid this breaking change, but I fear we don't have many options if we want to preserve V levels 🙈

[thockin]

Indeed, this is tricky. Since we more or less adopted glog->klog, we sort of committed to not breaking it.

What about something like this:

make Verbose implement logr.InfoLogger and use the bool value to determine whether to do nothing or actually call the glog method, which will call the logr method.

Ahh crud, they both define Info() with different signatures.

We could add a new Vb() method, fix our code, and leave V() users behind with some documented but wrong behavior. It could even panic() if SetLogger was called.

Alternately - are there logr changes we could make to make bridging easier?

Alternatively, fork klog2 ?

[munnerz]

So I can use klog as the backend for a logr or a logr as the backend for klog? Can I make a loop?

Yes, you can create a loop 🙈 I don't really know if there's a good way to handle this case. If you are hijacking klog output and piping via logr, then you need to make sure that logr instance isn't logging back to klog (else 🔥)

Also, logr already suggests "caller" s a special key for the calling information (file/line) of a particular log line.

Didn't realise this - I'll dig into the logr repo some more to find docs on the format of 'caller' 😄

Can you show what the output here would look like?

I'll put a demo case together shortly 😄

[dims]

/assign @DirectXMan12

[liggitt]

We'll just have to fix up users of V() as a bool. My main concern is breaking transitive users of klog. I don't know if anyone outside k/* is using it, but we should probably assert they shouldn't be. Or at least since this is pre-1.0, they shouldn't be mad when it breaks.

it's already breaking consumers in the day since this merged. are we planning to bump to k8s.io/klog/v2 for this, given this is breaking existing users of the k8s.io/klog import package who weren't pulling a specific version?

[sunnyanand17]

Can we pls fix this issue as per @liggitt suggestion.

[dims]

@sunnyanand17 wanna create a PR?

[DirectXMan12]

is it possible in general even possible to reliably use client-go without pinned deps?

klog/v2 does mean that we think klog is now stable, but it's still probably nicer to consumers to do /v2. That being said, trying to consume k8s.io/anything without is an exercise in frustration in our current state. It will break you eventually.

[gbbr]

This breaks k8s.io/client-go/transport. See kubernetes/client-go#658

[liggitt]

So I can use klog as the backend for a logr or a logr as the backend for klog? Can I make a loop?

Yes, you can create a loop 🙈 I don't really know if there's a good way to handle this case. If you are hijacking klog output and piping via logr, then you need to make sure that logr instance isn't logging back to klog (else 🔥)

Sorry for jumping in post-merge on this, but it's not clear to me why we want to enable this. If we want people to be able to plug in arbitrary log backends to kubernetes components, wouldn't it make more sense to switch all of the components to use a logging interface like go-logr first, and wire klogr up in the shipped kubernetes components' main() methods?

I didn't expect to try to change a concrete implementation like klog to be a passthrough to a generic interface. Breaking existing users of that concrete implementation in the process makes me doubly question why we're doing this this way.

[DirectXMan12]

It's two sides of things, depending on what you're looking for.

If you want klog output, you can use klogr. If you actually want some other backend, but don't want to miss out on all the useful client-go logs, you can use SetLogger to avoid just losing everything from client-go.

[DirectXMan12]

wouldn't it make more sense to switch all of the components to use a logging interface like go-logr first, and wire klogr up in the shipped kubernetes components' main() methods?

Yeah, definitely, but this fixes things in the short term, until we finish discussing a structured logging KEP for a release or two.

[dims]

@DirectXMan12 @liggitt - i filed #91 for to start a v2

[deads2k]

Sorry for jumping in post-merge on this, but it's not clear to me why we want to enable this. If we want people to be able to plug in arbitrary log backends to kubernetes components, wouldn't it make more sense to switch all of the components to use a logging interface like go-logr first, and wire klogr up in the shipped kubernetes components' main() methods?

I didn't expect to try to change a concrete implementation like klog to be a passthrough to a generic interface. Breaking existing users of that concrete implementation in the process makes me doubly question why we're doing this this way.

I just got bit too. Can we revert and then in a v2 you can break the interface?

[liggitt]

I just got bit too. Can we revert and then in a v2 you can break the interface?

I agree with this

[dims]

@munnerz can we revert this please? we can cut a release then get #91 as suggested in #91 (comment)

[DirectXMan12]

Since this is breaking so many people, I think that's a reasonable plan. We did not anticipate that anyone was actually trying to work against head (which is generally a recipe for disaster, but people seem to be doing it anyway).

[liggitt]

Revert opened in #97, can re-introduce this in a v2 stream if desired

[yiya1989]

OK, I waive my attempt to do better. We'll just have to fix up users of V() as a bool. My main concern is breaking transitive users of klog. I don't know if anyone outside k/* is using it, but we should probably assert they shouldn't be. Or at least since this is pre-1.0, they shouldn't be mad when it breaks.

Regarding logr itself, I have a few thoughts. If we don't make file/line sane then this is not really that useful. This has no way of knowing if the underlying logr impl can do file/line or if it will properly bias the callframes to accommodate. E.g. If I used this over glogr, it would always print "klog.go". glogr would need to take a parameter to handle N extra call frames to get back to the REAL caller. I can add that to glogr, and I have a stdr implementation I started and will commit.

That said, I think we should NOT add file/line or anything else here, or if we do, maybe call them "klog.severity".

Regarding reserved keys, maybe we should (in logr spec) reserve all keys starting with "_" or all keys starting with "logr." to segregate things provided by the impl from things provided by the user?

Lastly, I want to rethink InfoLogger - is it useful to differentiate, really, or should V() just return a full Logger (and make V(3).V(2).V(1) be the same as V(6) ?)

I will open logr bugs.

Currently I'm using logr.Logger interface as my logger output, but I can only deal info and error log, I want to distinguish info and fatalf log. What should i do?
Add severity starting with "__" or V(-1) V(-2) level?