Allow mapping between logr V() and zap log levels

[nmiculinic]

In k8s it's common to use relatively high V(2, 4, 6, 9) etc.

        l // zap logger at debug level
	zaprLogger := zapr.NewLogger(l)
	log.SetLogger(zaprLogger)
	fs := flag.NewFlagSet("dummy", flag.ContinueOnError)
	klog.InitFlags(fs)
	if err := fs.Lookup("v").Value.Set("9"); err != nil {
		panic(err)
	}
	klog.SetLogger(zaprLogger.WithName("klog"))

	klog.V(0).Infof("v: 0")
	klog.V(2).Infof("v: 2")
	klog.V(4).Infof("v: 4")
	klog.V(9).Infof("v: 9")

The only thing outputed is:

2021-08-04T20:40:00.933+0200    INFO    klog    v: 0

---

However I see kubernetes logs being outputted with the right V() all being info level:

2021-08-04T20:40:01.909+0200    INFO    klog    GET https://82281D6D2F9D29E40D559B8DC3DFAD76.gr7.us-east-1.eks.amazonaws.com/api?timeout=32s 200 OK in 972 milliseconds

2021-08-04T20:40:02.037+0200    INFO    klog    GET https://82281D6D2F9D29E40D559B8DC3DFAD76.gr7.us-east-1.eks.amazonaws.com/apis?timeout=32s 200 OK in 127 milliseconds

2021-08-04T20:40:02.166+0200    INFO    klog    GET https://82281D6D2F9D29E40D559B8DC3DFAD76.gr7.us-east-1.eks.amazonaws.com/apis/apps/v1?timeout=32s 200 OK in 127 milliseconds

2021-08-04T20:40:02.167+0200    INFO    klog    GET https://82281D6D2F9D29E40D559B8DC3DFAD76.gr7.us-east-1.eks.amazonaws.com/apis/coordination.k8s.io/v1?timeout=32s 200 OK in 128 milliseconds

2021-08-04T20:40:02.167+0200    INFO    klog    GET https://82281D6D2F9D29E40D559B8DC3DFAD76.gr7.us-east-1.eks.amazonaws.com/apis/apiregistration.k8s.io/v1beta1?timeout=32s 200 OK in 128 milliseconds

(I'm not entirely sure what's happening within that code).

What I'd like to have custom function/mapping how V(...) map to zap log levels, and even have filtering capabilities from provided function.

[thockin]

logr defines V levels numerically. zap defines them semantically (named). zap's "debug" level (literally int value -1) is equivalent to logr V(1), so it's not surprising that you don't see levels 2+.

The zap project has reasons why they don't want to officially support arbitrary numeric levels, BUT ... it's possible to sort of fake it, or it will be soon.

I sent a PR (uber-go/zap#975) to them recently (which they helped refine and merged) which enables you to set the zap level to larger negative values, which means "more verbose". Today, zap 1.18.1 (the latest tag) will crash if you do that, but after my PR you can, for example, set it to -10 which should give you all the logs up to V(10).

I'm just waiting for them to tag a new release, at which point I'll update zapr's go.mod. Does this get you what you need?

I thought about biasing the mapping, so V(0) == warn, V(1) == info, V(2) == debug, but that just gives you one extra V level and sort of breaks the semantic - V(0) is not necessarily a warning.

[nmiculinic]

Thank you for taking the time to explain this nicely to me :-)

hmmm.....for my usecase, that is klog, I'd probably configure it to map V(0) == info, everything else debug...or not...I'd have to investigate for the concrete usecase where do I want to draw the line.

What do you think about allowing user's to pass in function mapping V(x) -> zap log level?

Something like:

// NewLogger creates a new logr.Logger using the given Zap Logger to log.
func NewLogger(l *zap.Logger, options....Option) logr.Logger {
	// creates a new logger skipping one level of callstack
	l := logr.New(newLoggerWithExtraSkip(l, 1))
        for _, f := range options {
           f(l)
        }
        return l
}

func WithMappingFunc(func(lvl int) zapcore.Level) Option {
    ...
}

Instead of having hard-coded:

// Zap levels are int8 - make sure we stay in bounds.  logr itself should
// ensure we never get negative values.
func toZapLevel(lvl int) zapcore.Level {
	if lvl > 127 {
		lvl = 127
	}
	// zap levels are inverted.
	return 0 - zapcore.Level(lvl)
}

Does this design makes sense? Does it make good trade-off between complexity & features?

[thockin]

If we did this it would either look like: - a constant bias (always subract 2, so V(0) == zap.Error and V(1) == zap.Warn and V(2) == Zap.Info) - a conflation of multiple levels (V(0) - V(3) are zap.Info, V(4) - V(6) are zap.Debug, and V(5) on are ignored The latter doesn't sound too bad, but since there's already a patch to allow arbitrary negative zap levels, is it really worthwhile?

…

On Thu, Aug 5, 2021 at 12:44 PM Neven Miculinic ***@***.***> wrote: Thank you for taking the time to explain this nicely to me :-) hmmm.....for my usecase, that is klog, I'd probably configure it to map V(0) == info, everything else debug...or not...I'd have to investigate for the concrete usecase where do I want to draw the line. What do you think about allowing user's to pass in function mapping V(x) -> zap log level? Something like: // NewLogger creates a new logr.Logger using the given Zap Logger to log. func NewLogger(l *zap.Logger, options....Option) logr.Logger { // creates a new logger skipping one level of callstack l := logr.New(newLoggerWithExtraSkip(l, 1)) for _, f := range options { f(l) } return l } func WithMappingFunc(func(lvl int) zapcore.Level) Option { ... } Instead of having hard-coded: // Zap levels are int8 - make sure we stay in bounds. logr itself should // ensure we never get negative values. func toZapLevel(lvl int) zapcore.Level { if lvl > 127 { lvl = 127 } // zap levels are inverted. return 0 - zapcore.Level(lvl) } Does this design makes sense? Does it make good trade-off between complexity & features? — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub <#35 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABKWAVAUGHQZ42SVQ7TFQD3T3LSZHANCNFSM5BRYKSYQ> . 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&utm_campaign=notification-email> .

[nmiculinic]

• a conflation of multiple levels (V(0) - V(3) are zap.Info, V(4) - V(6)
  are zap.Debug, and V(5) on are ignored

this option looks better.

I'd probably use 0 - X -> info, X + 1, ... -> debug. Just the distinction between the two...when I determine what the best X is...probably around 2-4 judging by recent issue I've had in code, and certain log not being printed which would helped quite a bit

[nmiculinic]

btw, maybe I've missed it, but are you attaching verbosity field to underlying zap? That I can filter that in the log management system?

[thockin]

zap itself logs the "level" but I think that can be turned off. There was a discussion in klog somewhere about making a zapr option to log the "v" itself instead of zap. I still question whether the mapping func you propose is worthwhile. Assume 1.18.2 is tagged and the negative index bug is fixed - would you still want the mapping func?

…

On Thu, Aug 5, 2021 at 1:03 PM Neven Miculinic ***@***.***> wrote: btw, maybe I've missed it, but are you attaching verbosity field to underlying zap? That I can filter that in the log management system? — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub <#35 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABKWAVHV3MFAVSX3OEMAQV3T3LVCLANCNFSM5BRYKSYQ> . 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&utm_campaign=notification-email> .

[nmiculinic]

I'd like to try it out....but I realized I cannot yet use v1, but have to use v0.4.0 due to logr adding new function to the interface, and controller runtime doesn't yet support this new interface.

I think it'll be fine without custom mapping function now that I think about it a bit more.