numeric verbosity and configurable error field name

[pohly]

This is needed to make zapr usable for Kubernetes. Currently
Kubernetes uses a forked zapr with "v" for the numeric verbosity and
"err" for Logger.Error. Compared to the implementation in Kubernetes
there's one functional difference: Logger.Error is logged with v=-1
and internal panics with v=-2 to distinguish the log messages from
normal info messages where v >= 0.

The unit tests were derived from
https://github.com/kubernetes/kubernetes/blob/cff40a7bcc170c473c223081fd0103fd042dc44b/staging/src/k8s.io/component-base/logs/json/json_test.go
and both modified (better error messages, t.Run for each test case)
and extended to enhance coverage.

Several new edge cases are now covered (for example, error logging
at non-zero verbosity levels) and new tests for WithName,
WithCallDepth and WithValues were added.

Fixes #36

[pohly]

@serathius: do you agree with the decision to use -1 for Logger.Error and -2 for panics?

I have tested this updated zapr in Kubernetes (see kubernetes/kubernetes#104103) and it passes the existing tests with only minor changes to those tests (v=-1/-2, additional fields, different (correct?) source location for panics).

[serathius]

I don't think we should mix verbosity and log type (info vs error). My understanding is that logr uses Info and Error to allow attaching additional information like stack trace. https://github.com/go-logr/logr/blob/622c97b4eb90a99cc628f4773662eb0015ce0f2a/logr.go#L45-L47

I don't treat Error as log more important then Info with V(0). Both are logged always and should be always useful to operator. Difference is that administrator might prefer to send Errors to error tracking systems like Sentry.

As for dPanic, they should not be treated as panics with higher verbosity. dPanic method is way for zap to report internal errors that need to be handled more carefully. It's different call path as you cannot just log internal log as a normal log, that would lead to recursion :P. I would also not treat them as more critical than errors reported by caller.

Refering to @thockin to get authoritative response.

[pohly]

I don't think we should mix verbosity and log type (info vs error). My understanding is that logr uses Info and Error to allow attaching additional information as stack trace.

Errors have a different verbosity semantic than info messages. They always get logged regardless of the current verbosity level of the logger, in contrast to info messages:

https://github.com/go-logr/logr/blob/622c97b4eb90a99cc628f4773662eb0015ce0f2a/logr.go#L206-L210
vs.
https://github.com/go-logr/logr/blob/622c97b4eb90a99cc628f4773662eb0015ce0f2a/logr.go#L220-L222

Logging an error with v=5 therefore doesn't make sense to me.

I don't treat Error as log more important then Info with V(0). Both are logged always and should be always useful to operator.

Both are logged only if the threshold is >=0. Theoretically a logger could also be configured with -1 as threshold and then only log errors, but not V(0) info messages. Therefore I think that one can argue that errors have either "higher" verbosity than info messages or no verbosity at all.

Panics are yet another thing. They are not errors encountered by the application nor info messages. Therefore it seemed useful to log them differently. We can also always log them without numeric verbosity.

[serathius]

As Error can also be used with verbosity, it would be good to agree on how it should work. Some examples about my expectation:

For Info with verbosity

err := fmt.Errorf("Error")
logger.V(2).Info("Something happen", "err", err)

Should write:

{"v": 2, "msg": "Something happen", "err": "Error"}

Same with Error

err := fmt.Errorf("Error")
logger.V(2).Error(err, "Something happen")

Should write:

{"v": 2, "msg": "Something happen", "err": "Error"}

They are exactly the same, difference is that we might decide to add a flag to enable adding stacktrace information to Error.

[pohly]

As Error can also be used with verbosity,

You can write code like that, but semantically logger.V(5).Error and logger.Error are exactly the same. That's simply how logr works.

[pohly]

logger.V(2).Error(err, "Something happen")
Should write:
{"v": 2, "msg": "Something happen", "err": "Error"}

That was possible in logr v0.4.0, but is not possible anymore with v1.0.0 because LogSink.Error isn't passed any verbosity level.

[pohly]

That's simply how logr works.

... and is intended to work. Looking at the API documentation for Logger.Error, it's probably something that should be called out explicitly. it's currently not documented there.

[pohly]

FWIW, I don't care too much about v=-1 and v=-2. It just seemed to be useful to use that field to distinguish between the three different sources of log messages because the field otherwise has no meaning for errors and panics. I'm also fine with not adding v to errors and panics.

[thockin]

Why print a "lvl" on errors? Using negative values feels like a hack. Would it be better to have 2 keys, like "is-error" and "lvl" or something?

I don't follow the dpanic - how would a user get dpanic into the LogSink in the first place if we map log.Error() to zap.ErrorLevel?

[thockin]

Using With*() here feels confusing. I'd make this sound imperative. e.g. LogNumericLevel(key) or LogInfoLevel(key)

[pohly]

I'm influenced by gRPC here. It uses the With prefix for options. https://dave.cheney.net/2014/10/17/functional-options-for-friendly-apis doesn't use it and in logr we have some other convention around With, so I agree, let's simplify.

[thockin]

This is wordy for not much value. I'd streamline the name like numericLevelKey or levelKey

[thockin]

ErrorKey(key) ?

[thockin]

On negative V() levels. The doc-comments for V says 2 things of note:

1. "V-levels are additive."

2. "Negative V-levels are treated as 0."

The code backs this up:

func (l Logger) V(level int) Logger {
	if level < 0 {
		level = 0
	}
	l.level += level

The idea here is that I might pass a Logger to some other function with a bias in its V(). E.g.

// libfoo logs too much, so make it's notion of V(0) => my V(1).
foo := libfoo.NewFoo(log.V(1))

...and that other function can't undo what I have done.

Regarding V(4).Error(), yeah it's a little confusing, but it doesn't mean error verbosity, it just happens to fall out from the API. Historical note: at some point we had type Logger and type InfoLogger but it was clumsy when doing the above bias. Happy to take a PR to clean up the comments there.

[pohly]

Why print a "lvl" on errors? Using negative values feels like a hack.

Okay, I'll drop that.

Would it be better to have 2 keys, like "is-error" and "lvl" or something?

That's basically a new feature request ("distinguish between error and info messages"). Let's postpone that until someone actually needs it and the criteria "only info messages have v" is not enough.

I don't follow the dpanic - how would a user get dpanic into the LogSink in the first place if we map log.Error() to zap.ErrorLevel?

It's the log sink itself which generates a panic log message and sends it to the underlying zap logger. As for errors let's simply not add a "v" field to those messages.

[pohly]

I've force-pushed an update. Key changes:

• rebased to resolve conflict in go.mod
• errors and panics never get the extra numeric level field
• options for panic messages and allowing strongly-typed Zap fields
• names simplified as suggested by @thockin

[thockin]

mostly typos, a few small things.

[thockin]

This is a pretty complex test. I won't demand it now, since I know it is ported, but it would be nice to have 1 test that proves Info() works with no options. Then a test that proves that LogInfoLevel works. Then a test that proves ErrorKey works. etc. I feel like each test should be much simpler to comprehend

[thockin]

I'm willing to merge as-is, one point to discuss (naming, optional change IMO)

[thockin]

As a followup, maybe change the example to use these properly?

[pohly]

This PR depends on a logr release with go-logr/logr#74 logr v1.1.0-rc1.

[pohly]

As a followup, maybe change the example to use these properly?

Added that as example/example_test.go. I'm just not sure whether godoc will pick up the example code there or whether it needs to be one level up in the same package?

[pohly]

It turned out that they are not found inside the example directory.

It worked for funcr when in the same directory as the code (https://pkg.go.dev/github.com/go-logr/[email protected]/funcr#pkg-examples) but not for zapr (https://pkg.go.dev/github.com/go-logr/[email protected]).

I'll move the file in a new PR.

[thockin]

1.1.0 is tagged

[thockin]

LGTM