numeric verbosity and configurable logger behavior

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. Handling of invalid calls remains compatible
with zapr v1.0.0 (= panic log messages are emitted, strongly-type Zap
fields are not allowed), but new options allow changing those
defaults.

Those panic messages now log the source code of the caller, not the
zapr.go file where the panic message is logged.

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). New tests for WithName, WithCallDepth and
WithValues were added.

In terms of code coverage, all functions are covered 100% except for
Underlier which currently cannot be
called (go-logr/logr#63).

example/main.go

@@ -36,6 +36,11 @@ func Helper(log logr.Logger, msg string) {
 
 func helper2(log logr.Logger, msg string) {
 	log.WithCallDepth(2).Info(msg)
+
+	// Underlier is currently unusable (https://github.com/go-logr/logr/issues/63).
+	// if zaplogger, ok := log.(zapr.Underlier); ok {
+	// 	log.Info("have zap logger", "zapr", zaplogger)
+	// }
 }
 
 func main() {

go.mod

@@ -5,5 +5,6 @@ go 1.16
 require (
 	github.com/go-logr/logr v1.0.0
 	github.com/pkg/errors v0.9.1 // indirect
+	github.com/stretchr/testify v1.7.0
 	go.uber.org/zap v1.19.0
 )

go.sum

@@ -5,8 +5,10 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/go-logr/logr v1.0.0 h1:kH951GinvFVaQgy/ki/B3YYmQtRpExGigSJg6O8z5jo=
 github.com/go-logr/logr v1.0.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
+github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
+github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
 github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
@@ -39,6 +41,7 @@ golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q
 golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
 gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10=

zapr.go

@@ -70,33 +70,80 @@ type zapLogger struct {
 	// NB: this looks very similar to zap.SugaredLogger, but
 	// deals with our desire to have multiple verbosity levels.
 	l *zap.Logger
+
+	// numericLevelKey controls whether the numeric logr level is
+	// added to each Info log message and with which key.
+	numericLevelKey string
+
+	// errorKey is the field name used for the error in
+	// Logger.Error calls.
+	errorKey string
+
+	// allowZapFields enables logging of strongly-typed Zap
+	// fields. It is off by default because it breaks
+	// implementation agnosticism.
+	allowZapFields bool
+
+	// panicMessages enables log messages for invalid log calls
+	// that explain why a call was invalid (for example,
+	// non-string key). This is enabled by default.
+	panicMessages bool
 }
 
+const (
+	// noLevel tells handleFields to not inject a numeric log level field.
+	noLevel = -1
+)
+
 // handleFields converts a bunch of arbitrary key-value pairs into Zap fields.  It takes
 // additional pre-converted Zap fields, for use with automatically attached fields, like
 // `error`.
-func handleFields(l *zap.Logger, args []interface{}, additional ...zap.Field) []zap.Field {
+func (zl *zapLogger) handleFields(lvl int, args []interface{}, additional ...zap.Field) []zap.Field {
+	injectNumericLevel := zl.numericLevelKey != "" && lvl != noLevel
+
 	// a slightly modified version of zap.SugaredLogger.sweetenFields
 	if len(args) == 0 {
-		// fast-return if we have no suggared fields.
-		return additional
+		// fast-return if we have no suggared fields and no "v" field.
+		if !injectNumericLevel {
+			return additional
+		}
+		// Slightly slower fast path when we need to inject "v".
+		return append(additional, zap.Int(zl.numericLevelKey, lvl))
 	}
 
 	// unlike Zap, we can be pretty sure users aren't passing structured
 	// fields (since logr has no concept of that), so guess that we need a
 	// little less space.
-	fields := make([]zap.Field, 0, len(args)/2+len(additional))
+	numFields := len(args)/2 + len(additional)
+	if injectNumericLevel {
+		numFields++
+	}
+	fields := make([]zap.Field, 0, numFields)
+	if injectNumericLevel {
+		fields = append(fields, zap.Int(zl.numericLevelKey, lvl))
+	}
 	for i := 0; i < len(args); {
-		// check just in case for strongly-typed Zap fields, which is illegal (since
-		// it breaks implementation agnosticism), so we can give a better error message.
-		if _, ok := args[i].(zap.Field); ok {
-			l.DPanic("strongly-typed Zap Field passed to logr", zap.Any("zap field", args[i]))
+		// Check just in case for strongly-typed Zap fields,
+		// which might be illegal (since it breaks
+		// implementation agnosticism). If disabled, we can
+		// give a better error message.
+		if field, ok := args[i].(zap.Field); ok {
+			if zl.allowZapFields {
+				fields = append(fields, field)
+				i++
+				continue
+			}
+			if zl.panicMessages {
+				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("strongly-typed Zap Field passed to logr", zap.Any("zap field", args[i]))
+			}
 			break
 		}
 
 		// make sure this isn't a mismatched key
 		if i == len(args)-1 {
-			l.DPanic("odd number of arguments passed as key-value pairs for logging", zap.Any("ignored key", args[i]))
+			if zl.panicMessages {
+				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("odd number of arguments passed as key-value pairs for logging", zap.Any("ignored key", args[i]))
+			}
 			break
 		}
 
@@ -106,7 +153,9 @@ func handleFields(l *zap.Logger, args []interface{}, additional ...zap.Field) []
 		keyStr, isString := key.(string)
 		if !isString {
 			// if the key isn't a string, DPanic and stop logging
-			l.DPanic("non-string key argument passed to logging, ignoring all later arguments", zap.Any("invalid key", key))
+			if zl.panicMessages {
+				zl.l.WithOptions(zap.AddCallerSkip(1)).DPanic("non-string key argument passed to logging, ignoring all later arguments", zap.Any("invalid key", key))
+			}
 			break
 		}
 
@@ -137,28 +186,32 @@ func (zl zapLogger) Enabled(lvl int) bool {
 
 func (zl *zapLogger) Info(lvl int, msg string, keysAndVals ...interface{}) {
 	if checkedEntry := zl.l.Check(toZapLevel(lvl), msg); checkedEntry != nil {
-		checkedEntry.Write(handleFields(zl.l, keysAndVals)...)
+		checkedEntry.Write(zl.handleFields(lvl, keysAndVals)...)
 	}
 }
 
 func (zl *zapLogger) Error(err error, msg string, keysAndVals ...interface{}) {
 	if checkedEntry := zl.l.Check(zap.ErrorLevel, msg); checkedEntry != nil {
-		checkedEntry.Write(handleFields(zl.l, keysAndVals, zap.Error(err))...)
+		checkedEntry.Write(zl.handleFields(noLevel, keysAndVals, zap.NamedError(zl.errorKey, err))...)
 	}
 }
 
 func (zl *zapLogger) WithValues(keysAndValues ...interface{}) logr.LogSink {
-	newLogger := zl.l.With(handleFields(zl.l, keysAndValues)...)
-	return newLoggerWithExtraSkip(newLogger, 0)
+	newLogger := *zl
+	newLogger.l = zl.l.With(zl.handleFields(noLevel, keysAndValues)...)
+	return &newLogger
 }
 
 func (zl *zapLogger) WithName(name string) logr.LogSink {
-	newLogger := zl.l.Named(name)
-	return newLoggerWithExtraSkip(newLogger, 0)
+	newLogger := *zl
+	newLogger.l = zl.l.Named(name)
+	return &newLogger
 }
 
 func (zl *zapLogger) WithCallDepth(depth int) logr.LogSink {
-	return newLoggerWithExtraSkip(zl.l, depth)
+	newLogger := *zl
+	newLogger.l = zl.l.WithOptions(zap.AddCallerSkip(depth))
+	return &newLogger
 }
 
 // Underlier exposes access to the underlying logging implementation.  Since
@@ -173,18 +226,65 @@ func (zl *zapLogger) GetUnderlying() *zap.Logger {
 	return zl.l
 }
 
-// newLoggerWithExtraSkip allows creation of loggers with variable levels of callstack skipping
-func newLoggerWithExtraSkip(l *zap.Logger, callerSkip int) logr.LogSink {
-	log := l.WithOptions(zap.AddCallerSkip(callerSkip))
-	return &zapLogger{
+// NewLogger creates a new logr.Logger using the given Zap Logger to log.
+func NewLogger(l *zap.Logger) logr.Logger {
+	return NewLoggerWithOptions(l)
+}
+
+// NewLogger creates a new logr.Logger using the given Zap Logger to log
+// and applies additional options.
+func NewLoggerWithOptions(l *zap.Logger, opts ...Option) logr.Logger {
+	// creates a new logger skipping one level of callstack
+	log := l.WithOptions(zap.AddCallerSkip(1))
+	zl := &zapLogger{
 		l: log,
 	}
+	zl.errorKey = "error"
+	zl.panicMessages = true
+	for _, option := range opts {
+		option(zl)
+	}
+	return logr.New(zl)
 }
 
-// NewLogger creates a new logr.Logger using the given Zap Logger to log.
-func NewLogger(l *zap.Logger) logr.Logger {
-	// creates a new logger skipping one level of callstack
-	return logr.New(newLoggerWithExtraSkip(l, 1))
+// Option is one additional parameter for NewLoggerWithOptions.
+type Option func(*zapLogger)
+
+// LogInfoLevel controls whether a numeric log level is added to
+// Info log message. The empty string disables this, a non-empty
+// string is the key for the additional field. Errors and
+// internal panic messages do not have a log level and thus
+// are always logged without this extra field.
+func LogInfoLevel(key string) Option {
+	return func(zl *zapLogger) {
+		zl.numericLevelKey = key
+	}
+}
+
+// ErrorKey replaces the default "error" field name used for the error
+// in Logger.Error calls.
+func ErrorKey(key string) Option {
+	return func(zl *zapLogger) {
+		zl.errorKey = key
+	}
+}
+
+// AllowZapFields controls whether strongly-typed Zap fields may
+// be passed instead of a key/value pair. This is diabled by
+// default because it breaks implementation agnosticism.
+func AllowZapFields(allowed bool) Option {
+	return func(zl *zapLogger) {
+		zl.allowZapFields = allowed
+	}
+}
+
+// PanicMessages controls whether extra log messages are emitted for
+// invalid log calls that explain why a call was invalid (for example,
+// non-string key). This is enabled by default.
+func PanicMessages(enabled bool) Option {
+	return func(zl *zapLogger) {
+		zl.panicMessages = enabled
+	}
 }
 
 var _ logr.LogSink = &zapLogger{}