Skip to content

Commit

Permalink
Compromise on message type
Browse files Browse the repository at this point in the history 
Compromise on the type of the message: for the context-adding methods, accept
only strings, but also provide Sprint-style methods that take ...interface{}.
  • Loading branch information
Akshay Shah committed Jan 18, 2017
1 parent 41649e4 commit 2482f20
Show file tree
Hide file tree
Showing 4 changed files with 169 additions and 96 deletions.
4 changes: 2 additions & 2 deletions benchmarks/zap_sugar_bench_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info("Should be discarded.", fakeSugarFields()...)
logger.Infow("Should be discarded.", fakeSugarFields()...)
}
})
}
Expand All @@ -88,7 +88,7 @@ func BenchmarkZapSugarAddingFields(b *testing.B) {
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
logger.Info("Go fast.", fakeSugarFields()...)
logger.Infow("Go fast.", fakeSugarFields()...)
}
})
}
Expand Down
165 changes: 98 additions & 67 deletions sugar.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,10 @@ import (
"go.uber.org/zap/zapcore"
)

const _oddNumberErrMsg = "Passed an odd number of keys and values to SugaredLogger, ignoring last."
const (
_oddNumberErrMsg = "Passed an odd number of keys and values to SugaredLogger, ignoring last."
_nonStringKeyErrMsg = "Passed a non-string key."
)

// A SugaredLogger wraps the core Logger functionality in a slower, but less
// verbose, API.
Expand Down Expand Up @@ -69,93 +72,117 @@ func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger {
return &SugaredLogger{core: s.core.With(s.sweetenFields(args)...)}
}

// Debug logs a message and some key-value pairs at DebugLevel. Keys and values
// are treated as they are in the With method.
func (s *SugaredLogger) Debug(msg interface{}, keysAndValues ...interface{}) {
s.log(DebugLevel, sweetenMsg(msg), keysAndValues)
// Debug uses fmt.Sprint to construct and log a message.
func (s *SugaredLogger) Debug(args ...interface{}) {
s.log(DebugLevel, fmt.Sprint(args...), nil)
}

// Debugf uses fmt.Sprintf to construct a dynamic message and logs it at
// DebugLevel. It doesn't add to the message's structured context.
func (s *SugaredLogger) Debugf(template string, args ...interface{}) {
s.log(DebugLevel, fmt.Sprintf(template, args...), nil)
// Info uses fmt.Sprint to construct and log a message.
func (s *SugaredLogger) Info(args ...interface{}) {
s.log(InfoLevel, fmt.Sprint(args...), nil)
}

// Info logs a message and some key-value pairs at InfoLevel. Keys and values
// are treated as they are in the With method.
func (s *SugaredLogger) Info(msg interface{}, keysAndValues ...interface{}) {
s.log(InfoLevel, sweetenMsg(msg), keysAndValues)
// Warn uses fmt.Sprint to construct and log a message.
func (s *SugaredLogger) Warn(args ...interface{}) {
s.log(WarnLevel, fmt.Sprint(args...), nil)
}

// Infof uses fmt.Sprintf to construct a dynamic message and logs it at
// InfoLevel. It doesn't add to the message's structured context.
func (s *SugaredLogger) Infof(template string, args ...interface{}) {
s.log(InfoLevel, fmt.Sprintf(template, args...), nil)
// Error uses fmt.Sprint to construct and log a message.
func (s *SugaredLogger) Error(args ...interface{}) {
s.log(ErrorLevel, fmt.Sprint(args...), nil)
}

// Warn logs a message and some key-value pairs at WarnLevel. Keys and values
// are treated as they are in the With method.
func (s *SugaredLogger) Warn(msg interface{}, keysAndValues ...interface{}) {
s.log(WarnLevel, sweetenMsg(msg), keysAndValues)
// DPanic uses fmt.Sprint to construct and log a message. In development, the
// logger then panics. (See DPanicLevel for details.)
func (s *SugaredLogger) DPanic(args ...interface{}) {
s.log(DPanicLevel, fmt.Sprint(args...), nil)
}

// Warnf uses fmt.Sprintf to construct a dynamic message and logs it at
// WarnLevel. It doesn't add to the message's structured context.
func (s *SugaredLogger) Warnf(template string, args ...interface{}) {
s.log(WarnLevel, fmt.Sprintf(template, args...), nil)
// Panic uses fmt.Sprint to construct and log a message, then panics.
func (s *SugaredLogger) Panic(args ...interface{}) {
s.log(PanicLevel, fmt.Sprint(args...), nil)
}

// Error logs a message and some key-value pairs at ErrorLevel. Keys and values
// are treated as they are in the With method.
func (s *SugaredLogger) Error(msg interface{}, keysAndValues ...interface{}) {
s.log(ErrorLevel, sweetenMsg(msg), keysAndValues)
// Fatal uses fmt.Sprint to construct and log a message, then calls os.Exit.
func (s *SugaredLogger) Fatal(args ...interface{}) {
s.log(FatalLevel, fmt.Sprint(args...), nil)
}

// Errorf uses fmt.Sprintf to construct a dynamic message and logs it at
// ErrorLevel. It doesn't add to the message's structured context.
func (s *SugaredLogger) Errorf(template string, args ...interface{}) {
s.log(ErrorLevel, fmt.Sprintf(template, args...), nil)
// Debugf uses fmt.Sprintf to log a templated message.
func (s *SugaredLogger) Debugf(template string, args ...interface{}) {
s.log(DebugLevel, fmt.Sprintf(template, args...), nil)
}

// DPanic logs a message and some key-value pairs using the underlying logger's
// DPanic method. Keys and values are treated as they are in the With
// method. (See Logger.DPanic for details.)
func (s *SugaredLogger) DPanic(msg interface{}, keysAndValues ...interface{}) {
s.log(DPanicLevel, sweetenMsg(msg), keysAndValues)
// Infof uses fmt.Sprintf to log a templated message.
func (s *SugaredLogger) Infof(template string, args ...interface{}) {
s.log(InfoLevel, fmt.Sprintf(template, args...), nil)
}

// DPanicf uses fmt.Sprintf to construct a dynamic message, which is passed to
// the underlying Logger's DPanic method. (See Logger.DPanic for details.) It
// doesn't add to the message's structured context.
func (s *SugaredLogger) DPanicf(template string, args ...interface{}) {
s.log(DPanicLevel, fmt.Sprintf(template, args...), nil)
// Warnf uses fmt.Sprintf to log a templated message.
func (s *SugaredLogger) Warnf(template string, args ...interface{}) {
s.log(WarnLevel, fmt.Sprintf(template, args...), nil)
}

// Panic logs a message and some key-value pairs at PanicLevel, then panics.
// Keys and values are treated as they are in the With method.
func (s *SugaredLogger) Panic(msg interface{}, keysAndValues ...interface{}) {
s.log(PanicLevel, sweetenMsg(msg), keysAndValues)
// Errorf uses fmt.Sprintf to log a templated message.
func (s *SugaredLogger) Errorf(template string, args ...interface{}) {
s.log(ErrorLevel, fmt.Sprintf(template, args...), nil)
}

// Panicf uses fmt.Sprintf to construct a dynamic message and logs it at
// PanicLevel, then panics. It doesn't add to the message's structured context.
func (s *SugaredLogger) Panicf(template string, args ...interface{}) {
s.log(PanicLevel, fmt.Sprintf(template, args...), nil)
// DPanicf uses fmt.Sprintf to log a templated message. In development, the
// logger then panics. (See DPanicLevel for details.)
func (s *SugaredLogger) DPanicf(template string, args ...interface{}) {
s.log(DPanicLevel, fmt.Sprintf(template, args...), nil)
}

// Fatal logs a message and some key-value pairs at FatalLevel, then calls
// os.Exit(1). Keys and values are treated as they are in the With method.
func (s *SugaredLogger) Fatal(msg interface{}, keysAndValues ...interface{}) {
s.log(FatalLevel, sweetenMsg(msg), keysAndValues)
// Panicf uses fmt.Sprintf to log a templated message, then panics.
func (s *SugaredLogger) Panicf(template string, args ...interface{}) {
s.log(PanicLevel, fmt.Sprintf(template, args...), nil)
}

// Fatalf uses fmt.Sprintf to construct a dynamic message and logs it at
// FatalLevel, then calls os.Exit(1). It doesn't add to the message's
// structured context.
// Fatalf uses fmt.Sprintf to log a templated message, then calls os.Exit.
func (s *SugaredLogger) Fatalf(template string, args ...interface{}) {
s.log(FatalLevel, fmt.Sprintf(template, args...), nil)
}

// Debugw logs a message with some additional context.
//
// When debug-level logging is disabled, this is much faster than
// s.With(keysAndValues).Debug(msg)
func (s *SugaredLogger) Debugw(msg string, keysAndValues ...interface{}) {
s.log(DebugLevel, msg, keysAndValues)
}

// Infow logs a message with some additional context.
func (s *SugaredLogger) Infow(msg string, keysAndValues ...interface{}) {
s.log(InfoLevel, msg, keysAndValues)
}

// Warnw logs a message with some additional context.
func (s *SugaredLogger) Warnw(msg string, keysAndValues ...interface{}) {
s.log(WarnLevel, msg, keysAndValues)
}

// Errorw logs a message with some additional context.
func (s *SugaredLogger) Errorw(msg string, keysAndValues ...interface{}) {
s.log(ErrorLevel, msg, keysAndValues)
}

// DPanicw logs a message with some additional context. In development, the
// logger then panics. (See DPanicLevel for details.)
func (s *SugaredLogger) DPanicw(msg string, keysAndValues ...interface{}) {
s.log(DPanicLevel, msg, keysAndValues)
}

// Panicw logs a message with some additional context, then panics.
func (s *SugaredLogger) Panicw(msg string, keysAndValues ...interface{}) {
s.log(PanicLevel, msg, keysAndValues)
}

// Fatalw logs a message with some additional context, then calls os.Exit.
func (s *SugaredLogger) Fatalw(msg string, keysAndValues ...interface{}) {
s.log(FatalLevel, msg, keysAndValues)
}

func (s *SugaredLogger) log(lvl zapcore.Level, msg string, context []interface{}) {
if ce := s.core.Check(lvl, msg); ce != nil {
ce.Write(s.sweetenFields(context)...)
Expand All @@ -172,15 +199,19 @@ func (s *SugaredLogger) sweetenFields(args []interface{}) []zapcore.Field {

fields := make([]zapcore.Field, len(args)/2)
for i := range fields {
key := sweetenMsg(args[2*i])
fields[i] = Any(key, args[2*i+1])
keyIdx := 2 * i
val := args[keyIdx+1]
key, ok := args[keyIdx].(string)
if !ok {
s.core.DPanic(
_nonStringKeyErrMsg,
Int("position", keyIdx),
Any("key", args[keyIdx]),
Any("value", val),
)
key = fmt.Sprint(args[keyIdx])
}
fields[i] = Any(key, val)
}
return fields
}

func sweetenMsg(msg interface{}) string {
if str, ok := msg.(string); ok {
return str
}
return fmt.Sprint(msg)
}
2 changes: 1 addition & 1 deletion sugar_bench_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ func withBenchedSugar(b *testing.B, f func(*SugaredLogger)) {

func Benchmark10FieldsSugar(b *testing.B) {
withBenchedSugar(b, func(logger *SugaredLogger) {
logger.Info("Ten fields, passed at the log site.",
logger.Infow("Ten fields, passed at the log site.",
"one", 1,
"two", 2,
"three", 3,
Expand Down
94 changes: 68 additions & 26 deletions sugar_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -35,31 +35,36 @@ func TestSugarWith(t *testing.T) {
Entry: zapcore.Entry{Level: DPanicLevel, Message: _oddNumberErrMsg},
Context: []zapcore.Field{Any("ignored", "should ignore")},
}

tests := []struct {
args []interface{}
expected []zapcore.Field
errLogs []observer.LoggedEntry
}{
{nil, []zapcore.Field{}},
{[]interface{}{}, []zapcore.Field{}},
{[]interface{}{"foo", 42, true, "bar"}, []zapcore.Field{Int("foo", 42), String("true", "bar")}},
{nil, []zapcore.Field{}, nil},
{[]interface{}{}, []zapcore.Field{}, nil},
{[]interface{}{"should ignore"}, []zapcore.Field{}, []observer.LoggedEntry{ignored}},
{[]interface{}{"foo", 42, "true", "bar"}, []zapcore.Field{Int("foo", 42), String("true", "bar")}, nil},
{
args: []interface{}{"foo", 42, true, "bar"},
expected: []zapcore.Field{Int("foo", 42), String("true", "bar")},
errLogs: []observer.LoggedEntry{observer.LoggedEntry{
Entry: zapcore.Entry{Level: DPanicLevel, Message: _nonStringKeyErrMsg},
Context: []zapcore.Field{Int("position", 2), Any("key", true), Any("value", "bar")},
}},
},
}

for _, tt := range tests {
withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) {
logger.With(tt.args...).Info("")
output := logs.AllUntimed()
assert.Equal(t, 1, len(output), "Expected only one message to be logged.")
assert.Equal(t, tt.expected, output[0].Context, "Unexpected message context.")
})

withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) {
oddArgs := append(tt.args, "should ignore")
logger.With(oddArgs...).Info("")
output := logs.AllUntimed()
assert.Equal(t, 2, len(output), "Expected an error to be logged along with the intended message.")
assert.Equal(t, ignored, output[0], "Expected the first message to be an error.")
assert.Equal(t, tt.expected, output[1].Context, "Unexpected context on intended message.")
if len(tt.errLogs) > 0 {
for i := range tt.errLogs {
assert.Equal(t, tt.errLogs[i], output[i], "Unexpected error log at position %d.", i)
}
}
assert.Equal(t, len(tt.errLogs)+1, len(output), "Expected only one message to be logged.")
assert.Equal(t, tt.expected, output[len(tt.errLogs)].Context, "Unexpected message context.")
})
}
}
Expand All @@ -70,26 +75,25 @@ func (f stringerF) String() string { return f() }

func TestSugarStructuredLogging(t *testing.T) {
tests := []struct {
msg interface{}
msg string
expectMsg string
}{
{"foo", "foo"},
{true, "true"},
{stringerF(func() string { return "hello" }), "hello"},
{"", ""},
}

// Common to all test cases.
context := []interface{}{"foo", "bar"}
extra := []interface{}{true, false}
expectedFields := []zapcore.Field{String("foo", "bar"), Bool("true", false)}
extra := []interface{}{"baz", false}
expectedFields := []zapcore.Field{String("foo", "bar"), Bool("baz", false)}

for _, tt := range tests {
withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) {
logger.With(context...).Debug(tt.msg, extra...)
logger.With(context...).Info(tt.msg, extra...)
logger.With(context...).Warn(tt.msg, extra...)
logger.With(context...).Error(tt.msg, extra...)
logger.With(context...).DPanic(tt.msg, extra...)
logger.With(context...).Debugw(tt.msg, extra...)
logger.With(context...).Infow(tt.msg, extra...)
logger.With(context...).Warnw(tt.msg, extra...)
logger.With(context...).Errorw(tt.msg, extra...)
logger.With(context...).DPanicw(tt.msg, extra...)

expected := make([]observer.LoggedEntry, 5)
for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} {
Expand All @@ -103,7 +107,39 @@ func TestSugarStructuredLogging(t *testing.T) {
}
}

func TestSugarFormattedLogging(t *testing.T) {
func TestSugarConcatenatingLogging(t *testing.T) {
tests := []struct {
args []interface{}
expect string
}{
{[]interface{}{nil}, "<nil>"},
}

// Common to all test cases.
context := []interface{}{"foo", "bar"}
expectedFields := []zapcore.Field{String("foo", "bar")}

for _, tt := range tests {
withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) {
logger.With(context...).Debug(tt.args...)
logger.With(context...).Info(tt.args...)
logger.With(context...).Warn(tt.args...)
logger.With(context...).Error(tt.args...)
logger.With(context...).DPanic(tt.args...)

expected := make([]observer.LoggedEntry, 5)
for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} {
expected[i] = observer.LoggedEntry{
Entry: zapcore.Entry{Message: tt.expect, Level: lvl},
Context: expectedFields,
}
}
assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.")
})
}
}

func TestSugarTemplatedLogging(t *testing.T) {
tests := []struct {
format string
args []interface{}
Expand Down Expand Up @@ -150,6 +186,9 @@ func TestSugarPanicLogging(t *testing.T) {
{FatalLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, ""},
{PanicLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, "foo"},
{DebugLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, "foo"},
{FatalLevel, func(s *SugaredLogger) { s.Panicw("foo") }, ""},
{PanicLevel, func(s *SugaredLogger) { s.Panicw("foo") }, "foo"},
{DebugLevel, func(s *SugaredLogger) { s.Panicw("foo") }, "foo"},
}

for _, tt := range tests {
Expand Down Expand Up @@ -179,6 +218,9 @@ func TestSugarFatalLogging(t *testing.T) {
{FatalLevel + 1, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, ""},
{FatalLevel, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, "foo"},
{DebugLevel, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, "foo"},
{FatalLevel + 1, func(s *SugaredLogger) { s.Fatalw("foo") }, ""},
{FatalLevel, func(s *SugaredLogger) { s.Fatalw("foo") }, "foo"},
{DebugLevel, func(s *SugaredLogger) { s.Fatalw("foo") }, "foo"},
}

for _, tt := range tests {
Expand Down

0 comments on commit 2482f20

Please sign in to comment.