Skip to content

Commit

Permalink
numeric verbosity and configurable logger behavior
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
pohly authored and thockin committed Aug 24, 2021
1 parent 6e71054 commit bc76e7d
Show file tree
Hide file tree
Showing 7 changed files with 672 additions and 27 deletions.
94 changes: 94 additions & 0 deletions example/example_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,94 @@
/*
Copyright 2021 The logr Authors.
Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

package main

import (
"errors"
"time"

"github.com/go-logr/zapr"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)

var errSome = errors.New("some error")

func encodeTime(_ time.Time, enc zapcore.PrimitiveArrayEncoder) {
// Suppress actual time to keep output constant.
enc.AppendString("TIMESTAMP")
}

func newZapLogger() *zap.Logger {
// zap gets configured to not panic on invalid log calls
// and to produce simple, deterministic output on stdout.
zc := zap.NewProductionConfig()
zc.OutputPaths = []string{"stdout"}
zc.ErrorOutputPaths = zc.OutputPaths
zc.DisableStacktrace = true
zc.DisableCaller = true
zc.EncoderConfig.EncodeTime = encodeTime
z, _ := zc.Build()
return z
}

func ExampleNewLogger() {
log := zapr.NewLogger(newZapLogger())
log.Info("info message with default options")
log.Error(errSome, "error message with default options")
log.Info("support for zap fields as key/value replacement is disabled", zap.Int("answer", 42))
log.Info("invalid key", 42, "answer")
log.Info("missing value", "answer")
// Output:
// {"level":"info","ts":"TIMESTAMP","msg":"info message with default options"}
// {"level":"error","ts":"TIMESTAMP","msg":"error message with default options","error":"some error"}
// {"level":"dpanic","ts":"TIMESTAMP","msg":"strongly-typed Zap Field passed to logr","zap field":{"Key":"answer","Type":11,"Integer":42,"String":"","Interface":null}}
// {"level":"info","ts":"TIMESTAMP","msg":"support for zap fields as key/value replacement is disabled"}
// {"level":"dpanic","ts":"TIMESTAMP","msg":"non-string key argument passed to logging, ignoring all later arguments","invalid key":42}
// {"level":"info","ts":"TIMESTAMP","msg":"invalid key"}
// {"level":"dpanic","ts":"TIMESTAMP","msg":"odd number of arguments passed as key-value pairs for logging","ignored key":"answer"}
// {"level":"info","ts":"TIMESTAMP","msg":"missing value"}
}

func ExampleLogInfoLevel() {
log := zapr.NewLoggerWithOptions(newZapLogger(), zapr.LogInfoLevel("v"))
log.Info("info message with numeric verbosity level")
log.Error(errSome, "error messages have no numeric verbosity level")
// Output:
// {"level":"info","ts":"TIMESTAMP","msg":"info message with numeric verbosity level","v":0}
// {"level":"error","ts":"TIMESTAMP","msg":"error messages have no numeric verbosity level","error":"some error"}
}

func ExampleErrorKey() {
log := zapr.NewLoggerWithOptions(newZapLogger(), zapr.ErrorKey("err"))
log.Error(errSome, "error message with non-default error key")
// Output:
// {"level":"error","ts":"TIMESTAMP","msg":"error message with non-default error key","err":"some error"}
}

func ExampleAllowZapFields() {
log := zapr.NewLoggerWithOptions(newZapLogger(), zapr.AllowZapFields(true))
log.Info("log zap field", zap.Int("answer", 42))
// Output:
// {"level":"info","ts":"TIMESTAMP","msg":"log zap field","answer":42}
}

func ExampleDPanicOnBugs() {
log := zapr.NewLoggerWithOptions(newZapLogger(), zapr.DPanicOnBugs(false))
log.Info("warnings suppressed", zap.Int("answer", 42))
// Output:
// {"level":"info","ts":"TIMESTAMP","msg":"warnings suppressed"}
}
8 changes: 7 additions & 1 deletion example/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -48,12 +48,18 @@ func main() {
example(log.WithValues("module", "example"))
}

// If this were in another package, all it would depend on in logr, not zapr.
// example only depends on logr except when explicitly breaking the
// abstraction. Even that part is written so that it works with non-zap
// loggers.
func example(log logr.Logger) {
log.Info("hello", "val1", 1, "val2", map[string]int{"k": 1})
log.V(1).Info("you should see this")
log.V(1).V(1).Info("you should NOT see this")
log.Error(nil, "uh oh", "trouble", true, "reasons", []float64{0.1, 0.11, 3.14})
log.Error(e{"an error occurred"}, "goodbye", "code", -1)
helper(log, "thru a helper")

if zapLogger, ok := log.GetSink().(zapr.Underlier); ok {
_ = zapLogger.GetUnderlying().Core().Sync()
}
}
3 changes: 2 additions & 1 deletion go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,8 @@ module github.com/go-logr/zapr
go 1.16

require (
github.com/go-logr/logr v1.0.0
github.com/go-logr/logr v1.1.0
github.com/pkg/errors v0.9.1 // indirect
github.com/stretchr/testify v1.7.0
go.uber.org/zap v1.19.0
)
17 changes: 17 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -5,14 +5,24 @@ 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/go-logr/logr v1.1.0-rc1 h1:XVIp2Gsi5tAUuqa8WmNJB6cVi4vGKPh5i/mMF/Hvk1Y=
github.com/go-logr/logr v1.1.0-rc1/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
github.com/go-logr/logr v1.1.0 h1:nAbevmWlS2Ic4m4+/An5NXkaGqlqpbBgdcuThZxnZyI=
github.com/go-logr/logr v1.1.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 h1:VkoXIwSboBpnk99O/KFauAEILuNHv5DVFKZMBN/gUgw=
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=
github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/pohly/logr v1.0.1-0.20210817184539-cf703a64e7eb h1:7sco4gU4u7n+KjeYpWeDChU7+fxmCH75kXIsn2OjFeE=
github.com/pohly/logr v1.0.1-0.20210817184539-cf703a64e7eb/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
github.com/stretchr/objx v0.1.0 h1:4G4v2dO3VZwixGIRoQ5Lfboy6nUhCyYzaqnIAPPhYs4=
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
Expand All @@ -26,19 +36,26 @@ go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
go.uber.org/zap v1.19.0 h1:mZQZefskPPCMIBCSEH0v2/iUqqLrYtaeqwD6FUGUnFE=
go.uber.org/zap v1.19.0/go.mod h1:xg/QME4nWcxGxrpdeYfq7UvYrLh66cuVKdrbD1XF/NI=
golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2 h1:VklqNMn3ovrHsnt90PveolxSbWFaJdECFbxSq0Mqo2M=
golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs=
golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
golang.org/x/net v0.0.0-20190620200207-3b0461eec859 h1:R/3boaszxrf1GEUWTVDzSKVwLmSJpwZ1yqXm8j0v2QI=
golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
golang.org/x/sync v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=
golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a h1:1BGLXjeY4akVXGgbC9HugT3Jv3hCI0z56oJR5vAMgBU=
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=
golang.org/x/tools v0.0.0-20191108193012-7d206e10da11 h1:Yq9t9jnGoR+dBuitxdo9l6Q7xh/zOyNnYUtDKaQ3x0E=
golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc=
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=
Expand Down
154 changes: 129 additions & 25 deletions zapr.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand All @@ -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
}

Expand Down Expand Up @@ -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
Expand All @@ -173,18 +226,69 @@ 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)
}

// NewLoggerWithOptions 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 disabled by
// default because it breaks implementation agnosticism.
func AllowZapFields(allowed bool) Option {
return func(zl *zapLogger) {
zl.allowZapFields = allowed
}
}

// DPanicOnBugs controls whether extra log messages are emitted for
// invalid log calls with zap's DPanic method. Depending on the
// configuration of the zap logger, the program then panics after
// emitting the log message which is useful in development because
// such invalid log calls are bugs in the program. The log messages
// explain why a call was invalid (for example, non-string
// key). Emitting them is enabled by default.
func DPanicOnBugs(enabled bool) Option {
return func(zl *zapLogger) {
zl.panicMessages = enabled
}
}

var _ logr.LogSink = &zapLogger{}
Expand Down
Loading

0 comments on commit bc76e7d

Please sign in to comment.