Unable to print Warn Logs when using logr/zapr

[warber]

HI, I am using "logr/zapr" combination and I am a bit confused because I am not able to print "WARN" level logs.
To my understanding the following code should result in a log message printed by zap with severity level "warning":

zapLogger, _ := zap.NewProduction()
logger := zapr.NewLogger(zapLogger)
logger.V(-1).Info("Hello")

However, it's still printed with INFO level.

Of course it's because the V-Level is actively set back to 0 when it is negative:

logr/logr.go

Line 312 in 1be0bc0

if level < 0 {

On the zapr side i also find a code section like that: https://github.com/go-logr/zapr/blob/544fccbab1b69101aec26b69db60f876a95e3f12/zapr.go#L187

Where it also seems that non negative numbers are expected.

That leaves me with the question: How can I print logs with Warn level?

Thanks

[pohly]

Right now you can't. As you noticed, logr doesn't have a concept of "more important than INFO = V(0)". Introducing such a concept would be a breaking change (LogSinks don't expect a negative level) that would have to be handled with care. I'm not sure whether that would be worth it.

I'd like to allow V(-1) for a different reason: making logging during a certain call chain more verbose. Right now, it can only be made less verbose via V(1).

[thockin]

I know this is philosophical but.... There's no such thing as a warning. There are only things worth logging and things not worth logging.

As for -1, that seems like it would be a race to the bottom. Every library would fight to be even more important than every other library. A major part of the design was to bound what a library can emit. "I know you think you are important, but in the larger context you're just not."

[pohly]

Every library would fight to be even more important than every other library. [...] A major part of the design was to bound what a library can emit.

I don't think that this aspect of the design is used anywhere. At one point during the contextual logging review, Jordan pointed out that if he sees a logger.(V5).Info call in the some part of the code, he wants to be sure that -v5 makes that output visible. Calling that code with a foobar(logger.V(4) /* reduce log output from foobar */) breaks that assumption.

Because this is not used, there's no incentive for library developers to do logger.V(-1).Info calls. If they did, code reviews and bug reports should be sufficient to address this.

The feature that I was thinking of is that the caller decides that they want more output. The scheduler folks had "log more information about scheduling of one pod" as one of their use cases. The pseudo-code then would be if "pod is important" { logger = logger.V(-3) }; "run scheduling cycle with that logger" .

[thockin]

The feature that I was thinking of is that the caller decides that they want more output

User can already do things like:

bias := func(v int) int { return v }
if pod.Labels["hypothetical.k8s.io/is-important"] == "true" {
    bias = func(v int) int { return v-3 }
}

logger.V(bias(2)).Info(...)

...without any support from us

[pohly]

That works if the bias is inside the code which does the log call. It does not work when code in package A is calling function DoSomething(logger logr.Logger, ...) in package B, and B.DoSomething then does a logger.V(5).Info call.

Suppose component A wants to elevate all messages in that B.DoSomething by one level (= make the call more verbose). It could do that with DoSomething(logger.V(-1), ...) - we just don't allow it.

[uablrek]

You can use negative numbers to Zap, and use positive numbers to logr. Here is my personal "standard" log code, and a unit-test:
log.go.txt
log_test.go.txt

There are some additional things to note like formatted time, and especially zc.Sampling = nil. At the time of writing, this was enabled by default, and consumed a lot of cpu.