From ccd2c798c34825dbb947b8695f1505f309b0f108 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Thu, 22 Sep 2016 17:38:38 +0300 Subject: [PATCH 01/31] Refs: #138 --- sugar.go | 169 ++++++++++++++++++++++++++++++++++++++++++++++++++ sugar_test.go | 95 ++++++++++++++++++++++++++++ 2 files changed, 264 insertions(+) create mode 100644 sugar.go create mode 100644 sugar_test.go diff --git a/sugar.go b/sugar.go new file mode 100644 index 000000000..4c9693166 --- /dev/null +++ b/sugar.go @@ -0,0 +1,169 @@ +// Copyright (c) 2016 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zap + +import ( + "errors" + "fmt" + "time" +) + +// Sugar is a wrapper around core logger whith less verbose API +type Sugar interface { + // Check the minimum enabled log level. + Level() Level + // Change the level of this logger, as well as all its ancestors and + // descendants. This makes it easy to change the log level at runtime + // without restarting your application. + SetLevel(Level) + + // Create a child logger, and optionally add some context to that logger. + With(...interface{}) (Sugar, error) + + // Log a message at the given level. Messages include any context that's + // accumulated on the logger, as well as any fields added at the log site. + Log(Level, string, ...interface{}) error + Debug(string, ...interface{}) error + Info(string, ...interface{}) error + Warn(string, ...interface{}) error + Error(string, ...interface{}) error + Panic(string, ...interface{}) error + Fatal(string, ...interface{}) error + // If the logger is in development mode (via the Development option), DFatal + // logs at the Fatal level. Otherwise, it logs at the Error level. + DFatal(string, ...interface{}) error +} + +type sugar struct { + core Logger +} + +// NewSugar is a constructor for Sugar +func NewSugar(core Logger) Sugar { + return &sugar{core} +} + +func (s *sugar) Level() Level { + return s.core.Level() +} + +func (s *sugar) SetLevel(lvl Level) { + s.core.SetLevel(lvl) +} + +func (s *sugar) With(args ...interface{}) (Sugar, error) { + fields, err := getSugarFields(args...) + if err != nil { + return nil, err + } + return NewSugar(s.core.With(fields...)), nil +} + +func getSugarFields(args ...interface{}) ([]Field, error) { + if (len(args) % 2) != 0 { + return nil, errors.New("invalid number of arguments") + } + var ( + fields []Field + ii int + key string + value interface{} + ) + for ii, value = range args { + if (ii % 2) == 0 { + switch value.(type) { + case string: + key = value.(string) + default: + return nil, errors.New("field name must be string") + } + } else { + switch value.(type) { + case bool: + fields = append(fields, Bool(key, value.(bool))) + case float64: + fields = append(fields, Float64(key, value.(float64))) + case int: + fields = append(fields, Int(key, value.(int))) + case int64: + fields = append(fields, Int64(key, value.(int64))) + case uint: + fields = append(fields, Uint(key, value.(uint))) + case uint64: + fields = append(fields, Uint64(key, value.(uint64))) + case string: + fields = append(fields, String(key, value.(string))) + case time.Time: + fields = append(fields, Time(key, value.(time.Time))) + case time.Duration: + fields = append(fields, Duration(key, value.(time.Duration))) + case fmt.Stringer: + fields = append(fields, Stringer(key, value.(fmt.Stringer))) + default: + return nil, errors.New("invalid argument type") + } + } + } + return fields, nil +} + +// Log ... +func (s *sugar) Log(lvl Level, msg string, args ...interface{}) error { + fields, err := getSugarFields(args...) + if err != nil { + return err + } + s.core.Log(lvl, msg, fields...) + return nil +} + +func (s *sugar) Debug(msg string, args ...interface{}) error { + return s.Log(DebugLevel, msg, args...) +} + +func (s *sugar) Info(msg string, args ...interface{}) error { + return s.Log(InfoLevel, msg, args...) +} + +func (s *sugar) Warn(msg string, args ...interface{}) error { + return s.Log(WarnLevel, msg, args...) +} + +func (s *sugar) Error(msg string, args ...interface{}) error { + return s.Log(ErrorLevel, msg, args...) +} + +func (s *sugar) Panic(msg string, args ...interface{}) error { + return s.Log(PanicLevel, msg, args...) +} + +func (s *sugar) Fatal(msg string, args ...interface{}) error { + return s.Log(FatalLevel, msg, args...) +} + +func (s *sugar) DFatal(msg string, args ...interface{}) error { + fields, err := getSugarFields(args...) + if err != nil { + return err + } + s.core.DFatal(msg, fields...) + return nil +} diff --git a/sugar_test.go b/sugar_test.go new file mode 100644 index 000000000..95aec19ba --- /dev/null +++ b/sugar_test.go @@ -0,0 +1,95 @@ +// Copyright (c) 2016 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zap + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestSugarGetSugarFields(t *testing.T) { + // logger := NewSugar(New(NewJSONEncoder())) + // assert.Error(t, logger.getFields("test"), ) + + var ( + fields []Field + err error + ) + + _, err = getSugarFields("test") + assert.Error(t, err, "Should return error on invalid number of arguments") + + _, err = getSugarFields("test1", 1, "test2") + assert.Error(t, err, "Should return error on invalid number of arguments") + + _, err = getSugarFields("test1", nil) + assert.Error(t, err, "Should return error on argument of unknown type") + + _, err = getSugarFields(1, 1) + assert.Error(t, err, "Should return error on non-string field name") + + fields, _ = getSugarFields("test", 1) + assert.Equal(t, 1, len(fields), "Should return 1 field") + + fields, _ = getSugarFields("test1", 1, "test2", 2) + assert.Equal(t, 2, len(fields), "Should return 2 fields") +} + +func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { + sink := &testBuffer{} + errSink := &testBuffer{} + + allOpts := make([]Option, 0, 3+len(opts)) + allOpts = append(allOpts, DebugLevel, Output(sink), ErrorOutput(errSink)) + allOpts = append(allOpts, opts...) + logger := New(newJSONEncoder(NoTime()), allOpts...) + sugar := NewSugar(logger) + + f(sugar, sink) +} + +func TestSugarLog(t *testing.T) { + opts := opts(Fields(Int("foo", 42))) + withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { + logger.Debug("debug message", "a", "b") + logger.Info("info message", "c", "d") + logger.Warn("warn message", "e", "f") + logger.Error("error message", "g", "h") + assert.Equal(t, []string{ + `{"level":"debug","msg":"debug message","foo":42,"a":"b"}`, + `{"level":"info","msg":"info message","foo":42,"c":"d"}`, + `{"level":"warn","msg":"warn message","foo":42,"e":"f"}`, + `{"level":"error","msg":"error message","foo":42,"g":"h"}`, + }, buf.Lines(), "Incorrect output from logger") + }) +} + +func TestSugarWith(t *testing.T) { + opts := opts() + withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { + child, _ := logger.With("a", "b") + child.Debug("debug message", "c", "d") + assert.Equal(t, []string{ + `{"level":"debug","msg":"debug message","a":"b","c":"d"}`, + }, buf.Lines(), "Incorrect output from logger") + }) +} From 2f7195916d400946f83727fa9bb3c69947911b36 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Thu, 22 Sep 2016 18:09:59 +0300 Subject: [PATCH 02/31] added benchmark --- sugar_bench_test.go | 54 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 54 insertions(+) create mode 100644 sugar_bench_test.go diff --git a/sugar_bench_test.go b/sugar_bench_test.go new file mode 100644 index 000000000..60f52ad6e --- /dev/null +++ b/sugar_bench_test.go @@ -0,0 +1,54 @@ +// Copyright (c) 2016 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zap + +import "testing" + +func withBenchedSugar(b *testing.B, f func(Sugar)) { + logger := NewSugar(New( + NewJSONEncoder(), + DebugLevel, + DiscardOutput, + )) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + f(logger) + } + }) +} + +func Benchmark10FieldsSugar(b *testing.B) { + withBenchedSugar(b, func(log Sugar) { + log.Info("Ten fields, passed at the log site.", + "one", 1, + "two", 2, + "three", 3, + "four", 4, + "five", 5, + "six", 6, + "seven", 7, + "eight", 8, + "nine", 9, + "ten", 10, + ) + }) +} From f83f8a7789a22a382440cb3de4db67bc3a22352e Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Thu, 22 Sep 2016 18:48:07 +0300 Subject: [PATCH 03/31] improved test coverage --- sugar_test.go | 83 +++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 83 insertions(+) diff --git a/sugar_test.go b/sugar_test.go index 95aec19ba..d11b067c0 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -22,6 +22,7 @@ package zap import ( "testing" + "time" "github.com/stretchr/testify/assert" ) @@ -54,6 +55,17 @@ func TestSugarGetSugarFields(t *testing.T) { assert.Equal(t, 2, len(fields), "Should return 2 fields") } +func TestSugarLevel(t *testing.T) { + assert.Equal(t, DebugLevel, NewSugar(New(NewJSONEncoder(), DebugLevel)).Level()) + assert.Equal(t, FatalLevel, NewSugar(New(NewJSONEncoder(), FatalLevel)).Level()) +} + +func TestSugarSetLevel(t *testing.T) { + sugar := NewSugar(New(NewJSONEncoder())) + sugar.SetLevel(FatalLevel) + assert.Equal(t, FatalLevel, sugar.Level()) +} + func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { sink := &testBuffer{} errSink := &testBuffer{} @@ -83,6 +95,71 @@ func TestSugarLog(t *testing.T) { }) } +func TestSugarLogTypes(t *testing.T) { + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Debug("", "bool", true) + logger.Debug("", "float64", float64(1.23456789)) + logger.Debug("", "int", int(-1)) + logger.Debug("", "int64", int64(-1)) + logger.Debug("", "uint", uint(1)) + logger.Debug("", "uint64", uint64(1)) + logger.Debug("", "string", "") + logger.Debug("", "time", time.Unix(0, 0)) + logger.Debug("", "duration", time.Second) + logger.Debug("", "stringer", DebugLevel) + assert.Equal(t, []string{ + `{"level":"debug","msg":"","bool":true}`, + `{"level":"debug","msg":"","float64":1.23456789}`, + `{"level":"debug","msg":"","int":-1}`, + `{"level":"debug","msg":"","int64":-1}`, + `{"level":"debug","msg":"","uint":1}`, + `{"level":"debug","msg":"","uint64":1}`, + `{"level":"debug","msg":"","string":""}`, + `{"level":"debug","msg":"","time":0}`, + `{"level":"debug","msg":"","duration":1000000000}`, + `{"level":"debug","msg":"","stringer":"debug"}`, + }, buf.Lines(), "Incorrect output from logger") + }) +} + +func TestSugarPanic(t *testing.T) { + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + assert.Panics(t, func() { logger.Panic("foo") }, "Expected logging at Panic level to panic.") + assert.Equal(t, `{"level":"panic","msg":"foo"}`, buf.Stripped(), "Unexpected output from panic-level Log.") + }) +} + +func TestSugarFatal(t *testing.T) { + stub := stubExit() + defer stub.Unstub() + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Fatal("foo") + assert.Equal(t, `{"level":"fatal","msg":"foo"}`, buf.Stripped(), "Unexpected output from fatal-level Log.") + stub.AssertStatus(t, 1) + }) +} + +func TestSugarDFatal(t *testing.T) { + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.DFatal("foo") + assert.Equal(t, `{"level":"error","msg":"foo"}`, buf.Stripped(), "Unexpected output from dfatal") + }) + + stub := stubExit() + defer stub.Unstub() + opts := opts(Development()) + withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { + logger.DFatal("foo") + assert.Equal(t, `{"level":"fatal","msg":"foo"}`, buf.Stripped(), "Unexpected output from DFatal in dev mode") + stub.AssertStatus(t, 1) + }) +} + +func TestSugarLogFails(t *testing.T) { + sugar := NewSugar(New(NewJSONEncoder())) + assert.Error(t, sugar.Log(DebugLevel, "message", "a"), "Should fail with invalid args") +} + func TestSugarWith(t *testing.T) { opts := opts() withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { @@ -93,3 +170,9 @@ func TestSugarWith(t *testing.T) { }, buf.Lines(), "Incorrect output from logger") }) } + +func TestSugarWithFails(t *testing.T) { + sugar := NewSugar(New(NewJSONEncoder())) + _, err := sugar.With("a") + assert.Error(t, err, "Should fail with invalid args") +} From d19b6d2b8fe13ffbd113dc3749c7146fcffd43e8 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Thu, 22 Sep 2016 21:24:56 +0300 Subject: [PATCH 04/31] improved test coverage even more --- sugar_test.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/sugar_test.go b/sugar_test.go index d11b067c0..028a13086 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -145,6 +145,11 @@ func TestSugarDFatal(t *testing.T) { assert.Equal(t, `{"level":"error","msg":"foo"}`, buf.Stripped(), "Unexpected output from dfatal") }) + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + err := logger.DFatal("foo", "a") + assert.Error(t, err, "DFatal should fail with invalid arguments") + }) + stub := stubExit() defer stub.Unstub() opts := opts(Development()) From 3e840ad3872d00dd04d92399de7d0446fd3c4937 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Fri, 23 Sep 2016 14:07:50 +0300 Subject: [PATCH 05/31] accept error as the first of variadic arguments --- sugar.go | 40 ++++++++++++++++++++++++++++++++-------- sugar_test.go | 22 ++++++++++++++++++++++ 2 files changed, 54 insertions(+), 8 deletions(-) diff --git a/sugar.go b/sugar.go index 4c9693166..f884b1697 100644 --- a/sugar.go +++ b/sugar.go @@ -77,17 +77,39 @@ func (s *sugar) With(args ...interface{}) (Sugar, error) { return NewSugar(s.core.With(fields...)), nil } +const ( + expectFirst = iota + expectString + expectValue +) + func getSugarFields(args ...interface{}) ([]Field, error) { - if (len(args) % 2) != 0 { - return nil, errors.New("invalid number of arguments") - } var ( - fields []Field - ii int - key string - value interface{} + noErrArgs []interface{} + fields []Field + + ii int + key string + value interface{} ) - for ii, value = range args { + + if len(args) == 0 { + return fields, nil + } + + switch args[0].(type) { + case error: + fields = append(fields, Error(args[0].(error))) + noErrArgs = args[1:] + default: + noErrArgs = args + } + + if (len(noErrArgs) % 2) != 0 { + return nil, errors.New("invalid number of arguments") + } + + for ii, value = range noErrArgs { if (ii % 2) == 0 { switch value.(type) { case string: @@ -117,6 +139,8 @@ func getSugarFields(args ...interface{}) ([]Field, error) { fields = append(fields, Duration(key, value.(time.Duration))) case fmt.Stringer: fields = append(fields, Stringer(key, value.(fmt.Stringer))) + case error: + return nil, errors.New("error can only be the first argument") default: return nil, errors.New("invalid argument type") } diff --git a/sugar_test.go b/sugar_test.go index 028a13086..37fd81a34 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -21,6 +21,7 @@ package zap import ( + "errors" "testing" "time" @@ -53,6 +54,9 @@ func TestSugarGetSugarFields(t *testing.T) { fields, _ = getSugarFields("test1", 1, "test2", 2) assert.Equal(t, 2, len(fields), "Should return 2 fields") + + fields, _ = getSugarFields(errors.New("error"), "test1", 1) + assert.Equal(t, 2, len(fields), "Should return 2 fields") } func TestSugarLevel(t *testing.T) { @@ -122,6 +126,24 @@ func TestSugarLogTypes(t *testing.T) { }) } +func TestSugarLogNoArgs(t *testing.T) { + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Debug("no args message") + assert.Equal(t, []string{ + `{"level":"debug","msg":"no args message"}`, + }, buf.Lines(), "Incorrect output from logger") + }) +} + +func TestSugarLogError(t *testing.T) { + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Debug("with error", errors.New("this is a error")) + assert.Equal(t, []string{ + `{"level":"debug","msg":"with error","error":"this is a error"}`, + }, buf.Lines(), "Incorrect output from logger") + }) +} + func TestSugarPanic(t *testing.T) { withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { assert.Panics(t, func() { logger.Panic("foo") }, "Expected logging at Panic level to panic.") From e05c0236c969c58e134231acb43647dd00f12333 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Fri, 23 Sep 2016 14:12:36 +0300 Subject: [PATCH 06/31] cleanup --- sugar.go | 6 ------ 1 file changed, 6 deletions(-) diff --git a/sugar.go b/sugar.go index f884b1697..d6460aa04 100644 --- a/sugar.go +++ b/sugar.go @@ -77,12 +77,6 @@ func (s *sugar) With(args ...interface{}) (Sugar, error) { return NewSugar(s.core.With(fields...)), nil } -const ( - expectFirst = iota - expectString - expectValue -) - func getSugarFields(args ...interface{}) ([]Field, error) { var ( noErrArgs []interface{} From f2a8f56b996d544332b2cfc23569ec16088b0f81 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Fri, 23 Sep 2016 14:12:57 +0300 Subject: [PATCH 07/31] improved coverage --- sugar_test.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/sugar_test.go b/sugar_test.go index 37fd81a34..a2aa9be92 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -46,6 +46,9 @@ func TestSugarGetSugarFields(t *testing.T) { _, err = getSugarFields("test1", nil) assert.Error(t, err, "Should return error on argument of unknown type") + _, err = getSugarFields("test1", 1, "error", errors.New("")) + assert.Error(t, err, "Should return error when error passed as value (special case of unknown type)") + _, err = getSugarFields(1, 1) assert.Error(t, err, "Should return error on non-string field name") From 9c9b46b59b21c55c78f7c2d6465e4c8cc9d9f674 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Fri, 23 Sep 2016 16:12:21 +0300 Subject: [PATCH 08/31] mirrored relevant core logger benchmarks --- benchmarks/zap_sugar_bench_test.go | 162 +++++++++++++++++++++++++++++ 1 file changed, 162 insertions(+) create mode 100644 benchmarks/zap_sugar_bench_test.go diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go new file mode 100644 index 000000000..bd9ff9fcf --- /dev/null +++ b/benchmarks/zap_sugar_bench_test.go @@ -0,0 +1,162 @@ +// Copyright (c) 2016 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package benchmarks + +import ( + "testing" + "time" + + "github.com/uber-go/zap" + "github.com/uber-go/zap/zwrap" +) + +func fakeSugarFields() []interface{} { + return []interface{}{ + errExample, + "int", 1, + "int64", 2, + "float", 3.0, + "string", "four!", + "stringer", zap.DebugLevel, + "bool", true, + "time", time.Unix(0, 0), + "duration", time.Second, + "another string", "done!", + } +} + +func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { + logger := zap.NewSugar(zap.New(zap.NewJSONEncoder(), zap.ErrorLevel, zap.DiscardOutput)) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + logger.Info("Should be discarded.") + } + }) +} + +func BenchmarkZapSugarDisabledLevelsAccumulatedContext(b *testing.B) { + context := fakeFields() + logger := zap.NewSugar(zap.New( + zap.NewJSONEncoder(), + zap.ErrorLevel, + zap.DiscardOutput, + zap.Fields(context...), + )) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + logger.Info("Should be discarded.") + } + }) +} + +func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) { + logger := zap.NewSugar(zap.New( + zap.NewJSONEncoder(), + zap.ErrorLevel, + zap.DiscardOutput, + )) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + logger.Info("Should be discarded.", fakeSugarFields()...) + } + }) +} + +func BenchmarkZapSugarAddingFields(b *testing.B) { + logger := zap.NewSugar(zap.New( + zap.NewJSONEncoder(), + zap.DebugLevel, + zap.DiscardOutput, + )) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + logger.Info("Go fast.", fakeSugarFields()...) + } + }) +} + +func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { + logger, _ := zap.NewSugar(zap.New( + zap.NewJSONEncoder(), + zap.DebugLevel, + zap.DiscardOutput, + )).With(fakeSugarFields()...) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + logger.Info("Go really fast.") + } + }) +} + +func BenchmarkZapSugarWithoutFields(b *testing.B) { + logger := zap.New( + zap.NewJSONEncoder(), + zap.DebugLevel, + zap.DiscardOutput, + ) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + logger.Info("Go fast.") + } + }) +} + +func BenchmarkZapSugarSampleWithoutFields(b *testing.B) { + messages := fakeMessages(1000) + base := zap.New( + zap.NewJSONEncoder(), + zap.DebugLevel, + zap.DiscardOutput, + ) + logger := zap.NewSugar(zwrap.Sample(base, time.Second, 10, 10000)) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + i := 0 + for pb.Next() { + i++ + logger.Info(messages[i%1000]) + } + }) +} + +func BenchmarkZapSugarSampleAddingFields(b *testing.B) { + messages := fakeMessages(1000) + base := zap.New( + zap.NewJSONEncoder(), + zap.DebugLevel, + zap.DiscardOutput, + ) + logger := zap.NewSugar(zwrap.Sample(base, time.Second, 10, 10000)) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + i := 0 + for pb.Next() { + i++ + logger.Info(messages[i%1000], fakeSugarFields()...) + } + }) +} From 73a65b2502e914c642e9727bca94e50245d8483a Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Fri, 23 Sep 2016 16:27:54 +0300 Subject: [PATCH 09/31] use CheckedMessage to cut off expensive argument parsing --- sugar.go | 19 ++++++++++--------- sugar_test.go | 16 ++++++++++++++-- 2 files changed, 24 insertions(+), 11 deletions(-) diff --git a/sugar.go b/sugar.go index d6460aa04..4d01d7a39 100644 --- a/sugar.go +++ b/sugar.go @@ -145,11 +145,13 @@ func getSugarFields(args ...interface{}) ([]Field, error) { // Log ... func (s *sugar) Log(lvl Level, msg string, args ...interface{}) error { - fields, err := getSugarFields(args...) - if err != nil { - return err + if cm := s.core.Check(lvl, msg); cm.OK() { + fields, err := getSugarFields(args...) + if err != nil { + return err + } + cm.Write(fields...) } - s.core.Log(lvl, msg, fields...) return nil } @@ -178,10 +180,9 @@ func (s *sugar) Fatal(msg string, args ...interface{}) error { } func (s *sugar) DFatal(msg string, args ...interface{}) error { - fields, err := getSugarFields(args...) - if err != nil { - return err + lvl := ErrorLevel + if s.core.(*logger).Development { + lvl = FatalLevel } - s.core.DFatal(msg, fields...) - return nil + return s.Log(lvl, msg, args...) } diff --git a/sugar_test.go b/sugar_test.go index a2aa9be92..8bdaceb9e 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -186,8 +186,20 @@ func TestSugarDFatal(t *testing.T) { } func TestSugarLogFails(t *testing.T) { - sugar := NewSugar(New(NewJSONEncoder())) - assert.Error(t, sugar.Log(DebugLevel, "message", "a"), "Should fail with invalid args") + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + assert.Error(t, logger.Log(DebugLevel, "message", "a"), "Should fail with invalid args") + }) +} + +func TestSugarLogDiscards(t *testing.T) { + withSugarLogger(t, opts(InfoLevel), func(logger Sugar, buf *testBuffer) { + logger.Debug("should be discarded") + logger.Debug("should be discarded even with invalid arg count", "bla") + logger.Info("should be logged") + assert.Equal(t, []string{ + `{"level":"info","msg":"should be logged"}`, + }, buf.Lines(), "") + }) } func TestSugarWith(t *testing.T) { From 859883aeac149d4dbb6a350ed11086098a0de98d Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Tue, 4 Oct 2016 16:53:52 +0300 Subject: [PATCH 10/31] used another form of type switch --- sugar.go | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/sugar.go b/sugar.go index 4d01d7a39..db6e326b1 100644 --- a/sugar.go +++ b/sugar.go @@ -112,27 +112,27 @@ func getSugarFields(args ...interface{}) ([]Field, error) { return nil, errors.New("field name must be string") } } else { - switch value.(type) { + switch value := value.(type) { case bool: - fields = append(fields, Bool(key, value.(bool))) + fields = append(fields, Bool(key, value)) case float64: - fields = append(fields, Float64(key, value.(float64))) + fields = append(fields, Float64(key, value)) case int: - fields = append(fields, Int(key, value.(int))) + fields = append(fields, Int(key, value)) case int64: - fields = append(fields, Int64(key, value.(int64))) + fields = append(fields, Int64(key, value)) case uint: - fields = append(fields, Uint(key, value.(uint))) + fields = append(fields, Uint(key, value)) case uint64: - fields = append(fields, Uint64(key, value.(uint64))) + fields = append(fields, Uint64(key, value)) case string: - fields = append(fields, String(key, value.(string))) + fields = append(fields, String(key, value)) case time.Time: - fields = append(fields, Time(key, value.(time.Time))) + fields = append(fields, Time(key, value)) case time.Duration: - fields = append(fields, Duration(key, value.(time.Duration))) + fields = append(fields, Duration(key, value)) case fmt.Stringer: - fields = append(fields, Stringer(key, value.(fmt.Stringer))) + fields = append(fields, Stringer(key, value)) case error: return nil, errors.New("error can only be the first argument") default: From f869f0dc0fe622ef7a7fe2e92d7a2b0ccf561847 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Tue, 4 Oct 2016 16:54:32 +0300 Subject: [PATCH 11/31] fixed typo --- sugar.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sugar.go b/sugar.go index db6e326b1..6c01bdb56 100644 --- a/sugar.go +++ b/sugar.go @@ -26,7 +26,7 @@ import ( "time" ) -// Sugar is a wrapper around core logger whith less verbose API +// Sugar is a wrapper around core logger with less verbose API type Sugar interface { // Check the minimum enabled log level. Level() Level From 3786a4aabbe0437a3135494c1d1881c28c676813 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Wed, 5 Oct 2016 10:07:34 +0300 Subject: [PATCH 12/31] getSugarFields errors are logged rather then returned --- sugar.go | 59 +++++++++++++++++++++++++++------------------------ sugar_test.go | 25 +++++++++++++--------- 2 files changed, 46 insertions(+), 38 deletions(-) diff --git a/sugar.go b/sugar.go index 6c01bdb56..406a5a3de 100644 --- a/sugar.go +++ b/sugar.go @@ -40,16 +40,16 @@ type Sugar interface { // Log a message at the given level. Messages include any context that's // accumulated on the logger, as well as any fields added at the log site. - Log(Level, string, ...interface{}) error - Debug(string, ...interface{}) error - Info(string, ...interface{}) error - Warn(string, ...interface{}) error - Error(string, ...interface{}) error - Panic(string, ...interface{}) error - Fatal(string, ...interface{}) error + Log(Level, string, ...interface{}) + Debug(string, ...interface{}) + Info(string, ...interface{}) + Warn(string, ...interface{}) + Error(string, ...interface{}) + Panic(string, ...interface{}) + Fatal(string, ...interface{}) // If the logger is in development mode (via the Development option), DFatal // logs at the Fatal level. Otherwise, it logs at the Error level. - DFatal(string, ...interface{}) error + DFatal(string, ...interface{}) } type sugar struct { @@ -91,9 +91,9 @@ func getSugarFields(args ...interface{}) ([]Field, error) { return fields, nil } - switch args[0].(type) { + switch err := args[0].(type) { case error: - fields = append(fields, Error(args[0].(error))) + fields = append(fields, Error(err)) noErrArgs = args[1:] default: noErrArgs = args @@ -144,45 +144,48 @@ func getSugarFields(args ...interface{}) ([]Field, error) { } // Log ... -func (s *sugar) Log(lvl Level, msg string, args ...interface{}) error { +func (s *sugar) Log(lvl Level, msg string, args ...interface{}) { + var ( + fields []Field + err error + ) if cm := s.core.Check(lvl, msg); cm.OK() { - fields, err := getSugarFields(args...) + fields, err = getSugarFields(args...) if err != nil { - return err + fields = []Field{Error(err)} } cm.Write(fields...) } - return nil } -func (s *sugar) Debug(msg string, args ...interface{}) error { - return s.Log(DebugLevel, msg, args...) +func (s *sugar) Debug(msg string, args ...interface{}) { + s.Log(DebugLevel, msg, args...) } -func (s *sugar) Info(msg string, args ...interface{}) error { - return s.Log(InfoLevel, msg, args...) +func (s *sugar) Info(msg string, args ...interface{}) { + s.Log(InfoLevel, msg, args...) } -func (s *sugar) Warn(msg string, args ...interface{}) error { - return s.Log(WarnLevel, msg, args...) +func (s *sugar) Warn(msg string, args ...interface{}) { + s.Log(WarnLevel, msg, args...) } -func (s *sugar) Error(msg string, args ...interface{}) error { - return s.Log(ErrorLevel, msg, args...) +func (s *sugar) Error(msg string, args ...interface{}) { + s.Log(ErrorLevel, msg, args...) } -func (s *sugar) Panic(msg string, args ...interface{}) error { - return s.Log(PanicLevel, msg, args...) +func (s *sugar) Panic(msg string, args ...interface{}) { + s.Log(PanicLevel, msg, args...) } -func (s *sugar) Fatal(msg string, args ...interface{}) error { - return s.Log(FatalLevel, msg, args...) +func (s *sugar) Fatal(msg string, args ...interface{}) { + s.Log(FatalLevel, msg, args...) } -func (s *sugar) DFatal(msg string, args ...interface{}) error { +func (s *sugar) DFatal(msg string, args ...interface{}) { lvl := ErrorLevel if s.core.(*logger).Development { lvl = FatalLevel } - return s.Log(lvl, msg, args...) + s.Log(lvl, msg, args...) } diff --git a/sugar_test.go b/sugar_test.go index 8bdaceb9e..046bd30c0 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -29,9 +29,6 @@ import ( ) func TestSugarGetSugarFields(t *testing.T) { - // logger := NewSugar(New(NewJSONEncoder())) - // assert.Error(t, logger.getFields("test"), ) - var ( fields []Field err error @@ -170,11 +167,6 @@ func TestSugarDFatal(t *testing.T) { assert.Equal(t, `{"level":"error","msg":"foo"}`, buf.Stripped(), "Unexpected output from dfatal") }) - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { - err := logger.DFatal("foo", "a") - assert.Error(t, err, "DFatal should fail with invalid arguments") - }) - stub := stubExit() defer stub.Unstub() opts := opts(Development()) @@ -185,9 +177,22 @@ func TestSugarDFatal(t *testing.T) { }) } -func TestSugarLogFails(t *testing.T) { +func TestSugarLogErrors(t *testing.T) { + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Log(InfoLevel, "foo", "a") + assert.Equal(t, `{"level":"info","msg":"foo","error":"invalid number of arguments"}`, buf.Stripped(), "Should log invalid number of arguments") + }) + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Log(InfoLevel, "foo", 1, "foo") + assert.Equal(t, `{"level":"info","msg":"foo","error":"field name must be string"}`, buf.Stripped(), "Should log invalid name type") + }) + withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Log(InfoLevel, "foo", "foo", errors.New("b")) + assert.Equal(t, `{"level":"info","msg":"foo","error":"error can only be the first argument"}`, buf.Stripped(), "Should log error argument position is invalid") + }) withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { - assert.Error(t, logger.Log(DebugLevel, "message", "a"), "Should fail with invalid args") + logger.Log(InfoLevel, "foo", "bar", nil) + assert.Equal(t, `{"level":"info","msg":"foo","error":"invalid argument type"}`, buf.Stripped(), "Should log invalid argument type") }) } From 276f67790acfbaf816842914f032708d5deadd33 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Wed, 5 Oct 2016 10:37:58 +0300 Subject: [PATCH 13/31] added support for Marshaler field, changed fallback from error to object field --- sugar.go | 30 ++++++++++++++++-------------- sugar_test.go | 39 ++++++++++++++++++++------------------- 2 files changed, 36 insertions(+), 33 deletions(-) diff --git a/sugar.go b/sugar.go index 406a5a3de..cbb57a44e 100644 --- a/sugar.go +++ b/sugar.go @@ -112,31 +112,33 @@ func getSugarFields(args ...interface{}) ([]Field, error) { return nil, errors.New("field name must be string") } } else { - switch value := value.(type) { + switch v := value.(type) { + case error: + return nil, errors.New("error can only be the first argument") case bool: - fields = append(fields, Bool(key, value)) + fields = append(fields, Bool(key, v)) case float64: - fields = append(fields, Float64(key, value)) + fields = append(fields, Float64(key, v)) case int: - fields = append(fields, Int(key, value)) + fields = append(fields, Int(key, v)) case int64: - fields = append(fields, Int64(key, value)) + fields = append(fields, Int64(key, v)) case uint: - fields = append(fields, Uint(key, value)) + fields = append(fields, Uint(key, v)) case uint64: - fields = append(fields, Uint64(key, value)) + fields = append(fields, Uint64(key, v)) case string: - fields = append(fields, String(key, value)) + fields = append(fields, String(key, v)) case time.Time: - fields = append(fields, Time(key, value)) + fields = append(fields, Time(key, v)) case time.Duration: - fields = append(fields, Duration(key, value)) + fields = append(fields, Duration(key, v)) case fmt.Stringer: - fields = append(fields, Stringer(key, value)) - case error: - return nil, errors.New("error can only be the first argument") + fields = append(fields, Stringer(key, v)) + case LogMarshaler: + fields = append(fields, Marshaler(key, v)) default: - return nil, errors.New("invalid argument type") + fields = append(fields, Object(key, value)) } } } diff --git a/sugar_test.go b/sugar_test.go index 046bd30c0..04fab005b 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -40,9 +40,6 @@ func TestSugarGetSugarFields(t *testing.T) { _, err = getSugarFields("test1", 1, "test2") assert.Error(t, err, "Should return error on invalid number of arguments") - _, err = getSugarFields("test1", nil) - assert.Error(t, err, "Should return error on argument of unknown type") - _, err = getSugarFields("test1", 1, "error", errors.New("")) assert.Error(t, err, "Should return error when error passed as value (special case of unknown type)") @@ -50,13 +47,13 @@ func TestSugarGetSugarFields(t *testing.T) { assert.Error(t, err, "Should return error on non-string field name") fields, _ = getSugarFields("test", 1) - assert.Equal(t, 1, len(fields), "Should return 1 field") + assert.Len(t, fields, 1, "Should return 1 field") fields, _ = getSugarFields("test1", 1, "test2", 2) - assert.Equal(t, 2, len(fields), "Should return 2 fields") + assert.Len(t, fields, 2, "Should return 2 fields") fields, _ = getSugarFields(errors.New("error"), "test1", 1) - assert.Equal(t, 2, len(fields), "Should return 2 fields") + assert.Len(t, fields, 2, "Should return 2 fields") } func TestSugarLevel(t *testing.T) { @@ -83,6 +80,17 @@ func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { f(sugar, sink) } +type m9e struct { + Foo int `json:"foo"` + Bar bool `json:"bar"` +} + +func (m *m9e) MarshalLog(kv KeyValue) error { + kv.AddInt("foo", m.Foo) + kv.AddBool("bar", m.Bar) + return nil +} + func TestSugarLog(t *testing.T) { opts := opts(Fields(Int("foo", 42))) withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { @@ -101,6 +109,7 @@ func TestSugarLog(t *testing.T) { func TestSugarLogTypes(t *testing.T) { withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + logger.Debug("") logger.Debug("", "bool", true) logger.Debug("", "float64", float64(1.23456789)) logger.Debug("", "int", int(-1)) @@ -111,7 +120,10 @@ func TestSugarLogTypes(t *testing.T) { logger.Debug("", "time", time.Unix(0, 0)) logger.Debug("", "duration", time.Second) logger.Debug("", "stringer", DebugLevel) + logger.Debug("", "marshaler", m9e{1, true}) + logger.Debug("", "object", []string{"foo", "bar"}) assert.Equal(t, []string{ + `{"level":"debug","msg":""}`, `{"level":"debug","msg":"","bool":true}`, `{"level":"debug","msg":"","float64":1.23456789}`, `{"level":"debug","msg":"","int":-1}`, @@ -122,15 +134,8 @@ func TestSugarLogTypes(t *testing.T) { `{"level":"debug","msg":"","time":0}`, `{"level":"debug","msg":"","duration":1000000000}`, `{"level":"debug","msg":"","stringer":"debug"}`, - }, buf.Lines(), "Incorrect output from logger") - }) -} - -func TestSugarLogNoArgs(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { - logger.Debug("no args message") - assert.Equal(t, []string{ - `{"level":"debug","msg":"no args message"}`, + `{"level":"debug","msg":"","marshaler":{"foo":1,"bar":true}}`, + `{"level":"debug","msg":"","object":["foo","bar"]}`, }, buf.Lines(), "Incorrect output from logger") }) } @@ -190,10 +195,6 @@ func TestSugarLogErrors(t *testing.T) { logger.Log(InfoLevel, "foo", "foo", errors.New("b")) assert.Equal(t, `{"level":"info","msg":"foo","error":"error can only be the first argument"}`, buf.Stripped(), "Should log error argument position is invalid") }) - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { - logger.Log(InfoLevel, "foo", "bar", nil) - assert.Equal(t, `{"level":"info","msg":"foo","error":"invalid argument type"}`, buf.Stripped(), "Should log invalid argument type") - }) } func TestSugarLogDiscards(t *testing.T) { From 79c05a64a20eb4816e63814e4c4d310385877a58 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Wed, 5 Oct 2016 10:43:23 +0300 Subject: [PATCH 14/31] pre-allocate fields slice --- sugar.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sugar.go b/sugar.go index cbb57a44e..ed201f494 100644 --- a/sugar.go +++ b/sugar.go @@ -80,12 +80,12 @@ func (s *sugar) With(args ...interface{}) (Sugar, error) { func getSugarFields(args ...interface{}) ([]Field, error) { var ( noErrArgs []interface{} - fields []Field ii int key string value interface{} ) + fields := make([]Field, 0, len(args)/2) if len(args) == 0 { return fields, nil From a0a3ee677d2213bc35b01af29351ab55aef6afe7 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Wed, 5 Oct 2016 11:50:37 +0300 Subject: [PATCH 15/31] made test to fail if Object field is used in place of Marshaler --- sugar_test.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/sugar_test.go b/sugar_test.go index 04fab005b..fcaf3a2c3 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -81,13 +81,13 @@ func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { } type m9e struct { - Foo int `json:"foo"` - Bar bool `json:"bar"` + foo int + bar bool } func (m *m9e) MarshalLog(kv KeyValue) error { - kv.AddInt("foo", m.Foo) - kv.AddBool("bar", m.Bar) + kv.AddInt("foo", m.foo) + kv.AddBool("bar", m.bar) return nil } From 7bb19f1baffba6a508b25a8b9634b2a143b2edc5 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Mon, 10 Oct 2016 11:04:25 +0300 Subject: [PATCH 16/31] Removed LogMarshaler handling --- sugar.go | 5 +++-- sugar_test.go | 13 ------------- 2 files changed, 3 insertions(+), 15 deletions(-) diff --git a/sugar.go b/sugar.go index ed201f494..aca6d19cb 100644 --- a/sugar.go +++ b/sugar.go @@ -112,6 +112,9 @@ func getSugarFields(args ...interface{}) ([]Field, error) { return nil, errors.New("field name must be string") } } else { + // TODO: Add LogMarshaler support, it once been here, but + // had to be removed because type switch won't catch + // this intarface properly for some mystical reason. switch v := value.(type) { case error: return nil, errors.New("error can only be the first argument") @@ -135,8 +138,6 @@ func getSugarFields(args ...interface{}) ([]Field, error) { fields = append(fields, Duration(key, v)) case fmt.Stringer: fields = append(fields, Stringer(key, v)) - case LogMarshaler: - fields = append(fields, Marshaler(key, v)) default: fields = append(fields, Object(key, value)) } diff --git a/sugar_test.go b/sugar_test.go index fcaf3a2c3..1fc0a1df7 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -80,17 +80,6 @@ func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { f(sugar, sink) } -type m9e struct { - foo int - bar bool -} - -func (m *m9e) MarshalLog(kv KeyValue) error { - kv.AddInt("foo", m.foo) - kv.AddBool("bar", m.bar) - return nil -} - func TestSugarLog(t *testing.T) { opts := opts(Fields(Int("foo", 42))) withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { @@ -120,7 +109,6 @@ func TestSugarLogTypes(t *testing.T) { logger.Debug("", "time", time.Unix(0, 0)) logger.Debug("", "duration", time.Second) logger.Debug("", "stringer", DebugLevel) - logger.Debug("", "marshaler", m9e{1, true}) logger.Debug("", "object", []string{"foo", "bar"}) assert.Equal(t, []string{ `{"level":"debug","msg":""}`, @@ -134,7 +122,6 @@ func TestSugarLogTypes(t *testing.T) { `{"level":"debug","msg":"","time":0}`, `{"level":"debug","msg":"","duration":1000000000}`, `{"level":"debug","msg":"","stringer":"debug"}`, - `{"level":"debug","msg":"","marshaler":{"foo":1,"bar":true}}`, `{"level":"debug","msg":"","object":["foo","bar"]}`, }, buf.Lines(), "Incorrect output from logger") }) From ef67c8817f24f233337845068f93a5ca1d6b5aff Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Mon, 10 Oct 2016 11:30:50 +0300 Subject: [PATCH 17/31] added some benchamrk helpers to reduce repeats --- benchmarks/zap_sugar_bench_test.go | 63 ++++++++++++------------------ 1 file changed, 24 insertions(+), 39 deletions(-) diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go index bd9ff9fcf..b97ab26fc 100644 --- a/benchmarks/zap_sugar_bench_test.go +++ b/benchmarks/zap_sugar_bench_test.go @@ -43,8 +43,22 @@ func fakeSugarFields() []interface{} { } } +var newCoreLoggerDefaults = []zap.Option{ + zap.ErrorLevel, + zap.DiscardOutput, +} + +func newCoreLogger(options ...zap.Option) zap.Logger { + options = append(newCoreLoggerDefaults, options...) + return zap.New(zap.NewJSONEncoder(), options...) +} + +func newSugarLogger(options ...zap.Option) zap.Sugar { + return zap.NewSugar(newCoreLogger(options...)) +} + func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { - logger := zap.NewSugar(zap.New(zap.NewJSONEncoder(), zap.ErrorLevel, zap.DiscardOutput)) + logger := newSugarLogger() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -55,12 +69,7 @@ func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { func BenchmarkZapSugarDisabledLevelsAccumulatedContext(b *testing.B) { context := fakeFields() - logger := zap.NewSugar(zap.New( - zap.NewJSONEncoder(), - zap.ErrorLevel, - zap.DiscardOutput, - zap.Fields(context...), - )) + logger := newSugarLogger(zap.Fields(context...)) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -70,11 +79,7 @@ func BenchmarkZapSugarDisabledLevelsAccumulatedContext(b *testing.B) { } func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) { - logger := zap.NewSugar(zap.New( - zap.NewJSONEncoder(), - zap.ErrorLevel, - zap.DiscardOutput, - )) + logger := newSugarLogger() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -84,11 +89,7 @@ func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) { } func BenchmarkZapSugarAddingFields(b *testing.B) { - logger := zap.NewSugar(zap.New( - zap.NewJSONEncoder(), - zap.DebugLevel, - zap.DiscardOutput, - )) + logger := newSugarLogger() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -98,11 +99,7 @@ func BenchmarkZapSugarAddingFields(b *testing.B) { } func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { - logger, _ := zap.NewSugar(zap.New( - zap.NewJSONEncoder(), - zap.DebugLevel, - zap.DiscardOutput, - )).With(fakeSugarFields()...) + logger, _ := newSugarLogger().With(fakeSugarFields()...) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -112,11 +109,7 @@ func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { } func BenchmarkZapSugarWithoutFields(b *testing.B) { - logger := zap.New( - zap.NewJSONEncoder(), - zap.DebugLevel, - zap.DiscardOutput, - ) + logger := newSugarLogger() b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -127,12 +120,8 @@ func BenchmarkZapSugarWithoutFields(b *testing.B) { func BenchmarkZapSugarSampleWithoutFields(b *testing.B) { messages := fakeMessages(1000) - base := zap.New( - zap.NewJSONEncoder(), - zap.DebugLevel, - zap.DiscardOutput, - ) - logger := zap.NewSugar(zwrap.Sample(base, time.Second, 10, 10000)) + core := newCoreLogger() + logger := zap.NewSugar(zwrap.Sample(core, time.Second, 10, 10000)) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { i := 0 @@ -145,12 +134,8 @@ func BenchmarkZapSugarSampleWithoutFields(b *testing.B) { func BenchmarkZapSugarSampleAddingFields(b *testing.B) { messages := fakeMessages(1000) - base := zap.New( - zap.NewJSONEncoder(), - zap.DebugLevel, - zap.DiscardOutput, - ) - logger := zap.NewSugar(zwrap.Sample(base, time.Second, 10, 10000)) + core := newCoreLogger() + logger := zap.NewSugar(zwrap.Sample(core, time.Second, 10, 10000)) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { i := 0 From 3311b28f1fcb23572ad48236afbd389770b44d85 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Mon, 10 Oct 2016 11:37:44 +0300 Subject: [PATCH 18/31] updated comments --- sugar.go | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/sugar.go b/sugar.go index aca6d19cb..36a755b4b 100644 --- a/sugar.go +++ b/sugar.go @@ -28,14 +28,16 @@ import ( // Sugar is a wrapper around core logger with less verbose API type Sugar interface { - // Check the minimum enabled log level. + // Level returns the minimum enabled log level Level() Level - // Change the level of this logger, as well as all its ancestors and - // descendants. This makes it easy to change the log level at runtime + + // SetLevel changes the level of this logger, as well as all its ancestors + // and descendants. This makes it easy to change the log level at runtime // without restarting your application. SetLevel(Level) - // Create a child logger, and optionally add some context to that logger. + // With creates a child logger, and optionally add some context to that + // logger With(...interface{}) (Sugar, error) // Log a message at the given level. Messages include any context that's @@ -47,8 +49,9 @@ type Sugar interface { Error(string, ...interface{}) Panic(string, ...interface{}) Fatal(string, ...interface{}) - // If the logger is in development mode (via the Development option), DFatal - // logs at the Fatal level. Otherwise, it logs at the Error level. + + // DFatal logs at the Fatal level if the logger is in development mode (via + // the Development option), otherwise it logs at the Error level. DFatal(string, ...interface{}) } @@ -146,7 +149,6 @@ func getSugarFields(args ...interface{}) ([]Field, error) { return fields, nil } -// Log ... func (s *sugar) Log(lvl Level, msg string, args ...interface{}) { var ( fields []Field From 3cc2db37947f2c77272ffd5a1e3f9e29ba8450d7 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Mon, 10 Oct 2016 12:18:21 +0300 Subject: [PATCH 19/31] handle errors same way core logger does --- sugar.go | 14 +++++++---- sugar_test.go | 65 +++++++++++++++++++++++++++------------------------ 2 files changed, 44 insertions(+), 35 deletions(-) diff --git a/sugar.go b/sugar.go index 36a755b4b..b36f43ccf 100644 --- a/sugar.go +++ b/sugar.go @@ -38,7 +38,7 @@ type Sugar interface { // With creates a child logger, and optionally add some context to that // logger - With(...interface{}) (Sugar, error) + With(...interface{}) Sugar // Log a message at the given level. Messages include any context that's // accumulated on the logger, as well as any fields added at the log site. @@ -59,6 +59,10 @@ type sugar struct { core Logger } +func (s *sugar) internalError(msg string) { + s.core.(*logger).internalError(msg) +} + // NewSugar is a constructor for Sugar func NewSugar(core Logger) Sugar { return &sugar{core} @@ -72,12 +76,12 @@ func (s *sugar) SetLevel(lvl Level) { s.core.SetLevel(lvl) } -func (s *sugar) With(args ...interface{}) (Sugar, error) { +func (s *sugar) With(args ...interface{}) Sugar { fields, err := getSugarFields(args...) if err != nil { - return nil, err + s.internalError(err.Error()) } - return NewSugar(s.core.With(fields...)), nil + return NewSugar(s.core.With(fields...)) } func getSugarFields(args ...interface{}) ([]Field, error) { @@ -157,7 +161,7 @@ func (s *sugar) Log(lvl Level, msg string, args ...interface{}) { if cm := s.core.Check(lvl, msg); cm.OK() { fields, err = getSugarFields(args...) if err != nil { - fields = []Field{Error(err)} + s.internalError(err.Error()) } cm.Write(fields...) } diff --git a/sugar_test.go b/sugar_test.go index 1fc0a1df7..6fcb7f813 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -67,7 +67,7 @@ func TestSugarSetLevel(t *testing.T) { assert.Equal(t, FatalLevel, sugar.Level()) } -func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { +func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer, *testBuffer)) { sink := &testBuffer{} errSink := &testBuffer{} @@ -77,12 +77,12 @@ func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) { logger := New(newJSONEncoder(NoTime()), allOpts...) sugar := NewSugar(logger) - f(sugar, sink) + f(sugar, sink, errSink) } func TestSugarLog(t *testing.T) { opts := opts(Fields(Int("foo", 42))) - withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, opts, func(logger Sugar, out *testBuffer, _ *testBuffer) { logger.Debug("debug message", "a", "b") logger.Info("info message", "c", "d") logger.Warn("warn message", "e", "f") @@ -92,12 +92,12 @@ func TestSugarLog(t *testing.T) { `{"level":"info","msg":"info message","foo":42,"c":"d"}`, `{"level":"warn","msg":"warn message","foo":42,"e":"f"}`, `{"level":"error","msg":"error message","foo":42,"g":"h"}`, - }, buf.Lines(), "Incorrect output from logger") + }, out.Lines(), "Incorrect output from logger") }) } func TestSugarLogTypes(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { logger.Debug("") logger.Debug("", "bool", true) logger.Debug("", "float64", float64(1.23456789)) @@ -123,69 +123,72 @@ func TestSugarLogTypes(t *testing.T) { `{"level":"debug","msg":"","duration":1000000000}`, `{"level":"debug","msg":"","stringer":"debug"}`, `{"level":"debug","msg":"","object":["foo","bar"]}`, - }, buf.Lines(), "Incorrect output from logger") + }, out.Lines(), "Incorrect output from logger") }) } func TestSugarLogError(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { logger.Debug("with error", errors.New("this is a error")) assert.Equal(t, []string{ `{"level":"debug","msg":"with error","error":"this is a error"}`, - }, buf.Lines(), "Incorrect output from logger") + }, out.Lines(), "Incorrect output from logger") }) } func TestSugarPanic(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { assert.Panics(t, func() { logger.Panic("foo") }, "Expected logging at Panic level to panic.") - assert.Equal(t, `{"level":"panic","msg":"foo"}`, buf.Stripped(), "Unexpected output from panic-level Log.") + assert.Equal(t, `{"level":"panic","msg":"foo"}`, out.Stripped(), "Unexpected output from panic-level Log.") }) } func TestSugarFatal(t *testing.T) { stub := stubExit() defer stub.Unstub() - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { logger.Fatal("foo") - assert.Equal(t, `{"level":"fatal","msg":"foo"}`, buf.Stripped(), "Unexpected output from fatal-level Log.") + assert.Equal(t, `{"level":"fatal","msg":"foo"}`, out.Stripped(), "Unexpected output from fatal-level Log.") stub.AssertStatus(t, 1) }) } func TestSugarDFatal(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { logger.DFatal("foo") - assert.Equal(t, `{"level":"error","msg":"foo"}`, buf.Stripped(), "Unexpected output from dfatal") + assert.Equal(t, `{"level":"error","msg":"foo"}`, out.Stripped(), "Unexpected output from dfatal") }) stub := stubExit() defer stub.Unstub() opts := opts(Development()) - withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, opts, func(logger Sugar, out *testBuffer, _ *testBuffer) { logger.DFatal("foo") - assert.Equal(t, `{"level":"fatal","msg":"foo"}`, buf.Stripped(), "Unexpected output from DFatal in dev mode") + assert.Equal(t, `{"level":"fatal","msg":"foo"}`, out.Stripped(), "Unexpected output from DFatal in dev mode") stub.AssertStatus(t, 1) }) } func TestSugarLogErrors(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { logger.Log(InfoLevel, "foo", "a") - assert.Equal(t, `{"level":"info","msg":"foo","error":"invalid number of arguments"}`, buf.Stripped(), "Should log invalid number of arguments") + assert.Equal(t, `{"level":"info","msg":"foo"}`, out.Stripped(), "Should log invalid number of arguments") + assert.Equal(t, `invalid number of arguments`, err.Stripped(), "Should log invalid number of arguments") }) - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { logger.Log(InfoLevel, "foo", 1, "foo") - assert.Equal(t, `{"level":"info","msg":"foo","error":"field name must be string"}`, buf.Stripped(), "Should log invalid name type") + assert.Equal(t, `{"level":"info","msg":"foo"}`, out.Stripped(), "Should log invalid name type") + assert.Equal(t, `field name must be string`, err.Stripped(), "Should log invalid name type") }) - withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { logger.Log(InfoLevel, "foo", "foo", errors.New("b")) - assert.Equal(t, `{"level":"info","msg":"foo","error":"error can only be the first argument"}`, buf.Stripped(), "Should log error argument position is invalid") + assert.Equal(t, `{"level":"info","msg":"foo"}`, out.Stripped(), "Should log error argument position is invalid") + assert.Equal(t, `error can only be the first argument`, err.Stripped(), "Should log error argument position is invalid") }) } func TestSugarLogDiscards(t *testing.T) { - withSugarLogger(t, opts(InfoLevel), func(logger Sugar, buf *testBuffer) { + withSugarLogger(t, opts(InfoLevel), func(logger Sugar, buf *testBuffer, _ *testBuffer) { logger.Debug("should be discarded") logger.Debug("should be discarded even with invalid arg count", "bla") logger.Info("should be logged") @@ -197,17 +200,19 @@ func TestSugarLogDiscards(t *testing.T) { func TestSugarWith(t *testing.T) { opts := opts() - withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) { - child, _ := logger.With("a", "b") + withSugarLogger(t, opts, func(logger Sugar, out *testBuffer, _ *testBuffer) { + child := logger.With("a", "b") child.Debug("debug message", "c", "d") assert.Equal(t, []string{ `{"level":"debug","msg":"debug message","a":"b","c":"d"}`, - }, buf.Lines(), "Incorrect output from logger") + }, out.Lines(), "Incorrect output from logger") }) } -func TestSugarWithFails(t *testing.T) { - sugar := NewSugar(New(NewJSONEncoder())) - _, err := sugar.With("a") - assert.Error(t, err, "Should fail with invalid args") +func TestSugarWithErrors(t *testing.T) { + opts := opts() + withSugarLogger(t, opts, func(logger Sugar, _ *testBuffer, err *testBuffer) { + logger.With("a") + assert.Equal(t, "invalid number of arguments", err.Stripped(), "Should log invalid number of arguments") + }) } From 40bb388d6244f86f7c0d1e5bd884505bbac24866 Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Mon, 10 Oct 2016 12:52:19 +0300 Subject: [PATCH 20/31] relay DFatal directly to core logger --- sugar.go | 8 ++++---- sugar_test.go | 8 ++++++++ 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/sugar.go b/sugar.go index b36f43ccf..728320808 100644 --- a/sugar.go +++ b/sugar.go @@ -192,9 +192,9 @@ func (s *sugar) Fatal(msg string, args ...interface{}) { } func (s *sugar) DFatal(msg string, args ...interface{}) { - lvl := ErrorLevel - if s.core.(*logger).Development { - lvl = FatalLevel + fields, err := getSugarFields(args...) + if err != nil { + s.internalError(err.Error()) } - s.Log(lvl, msg, args...) + s.core.DFatal(msg, fields...) } diff --git a/sugar_test.go b/sugar_test.go index 6fcb7f813..e0c1469f4 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -169,6 +169,14 @@ func TestSugarDFatal(t *testing.T) { }) } +func TestSugarDFatalErrors(t *testing.T) { + opts := opts() + withSugarLogger(t, opts, func(logger Sugar, _ *testBuffer, err *testBuffer) { + logger.DFatal("foo", "bar") + assert.Equal(t, "invalid number of arguments", err.Stripped(), "Should log invalid number of arguments") + }) +} + func TestSugarLogErrors(t *testing.T) { withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { logger.Log(InfoLevel, "foo", "a") From 6e41219cecd57b651af4a1fbb0a98d99361e523f Mon Sep 17 00:00:00 2001 From: Mikhail Lukyanchenko Date: Mon, 10 Oct 2016 12:53:16 +0300 Subject: [PATCH 21/31] benchmark fix --- benchmarks/zap_sugar_bench_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go index b97ab26fc..8ee703a2a 100644 --- a/benchmarks/zap_sugar_bench_test.go +++ b/benchmarks/zap_sugar_bench_test.go @@ -99,7 +99,7 @@ func BenchmarkZapSugarAddingFields(b *testing.B) { } func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { - logger, _ := newSugarLogger().With(fakeSugarFields()...) + logger := newSugarLogger().With(fakeSugarFields()...) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { From a5a3dacd4a2eb85f34bdb0b2f4aab348546893e0 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Mon, 21 Nov 2016 09:36:28 -0800 Subject: [PATCH 22/31] WIP, addressing comments on @akabos's PR --- benchmarks/zap_sugar_bench_test.go | 3 + sugar.go | 303 ++++++++++++++++------------- sugar_bench_test.go | 8 +- sugar_test.go | 49 +---- 4 files changed, 176 insertions(+), 187 deletions(-) diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go index 8ee703a2a..405e6b17b 100644 --- a/benchmarks/zap_sugar_bench_test.go +++ b/benchmarks/zap_sugar_bench_test.go @@ -20,6 +20,8 @@ package benchmarks +/* FIXME (shah): Update to match new APIs. + import ( "testing" "time" @@ -145,3 +147,4 @@ func BenchmarkZapSugarSampleAddingFields(b *testing.B) { } }) } +*/ diff --git a/sugar.go b/sugar.go index 728320808..78778c44d 100644 --- a/sugar.go +++ b/sugar.go @@ -21,180 +21,209 @@ package zap import ( - "errors" "fmt" "time" ) -// Sugar is a wrapper around core logger with less verbose API -type Sugar interface { - // Level returns the minimum enabled log level - Level() Level - - // SetLevel changes the level of this logger, as well as all its ancestors - // and descendants. This makes it easy to change the log level at runtime - // without restarting your application. - SetLevel(Level) - - // With creates a child logger, and optionally add some context to that - // logger - With(...interface{}) Sugar - - // Log a message at the given level. Messages include any context that's - // accumulated on the logger, as well as any fields added at the log site. - Log(Level, string, ...interface{}) - Debug(string, ...interface{}) - Info(string, ...interface{}) - Warn(string, ...interface{}) - Error(string, ...interface{}) - Panic(string, ...interface{}) - Fatal(string, ...interface{}) +// A SugaredLogger wraps the core Logger functionality in a slower, but less +// verbose, API. +type SugaredLogger struct { + core Logger +} - // DFatal logs at the Fatal level if the logger is in development mode (via - // the Development option), otherwise it logs at the Error level. - DFatal(string, ...interface{}) +// Sugar converts a Logger to a SugaredLogger. +func Sugar(core Logger) *SugaredLogger { + return &SugaredLogger{core} } -type sugar struct { - core Logger +// Desugar unwraps a SugaredLogger, exposing the original Logger. +func Desugar(s *SugaredLogger) Logger { + return s.core } -func (s *sugar) internalError(msg string) { - s.core.(*logger).internalError(msg) +// With adds a variadic number of key-value pairs to the logging context. +// Even-indexed arguments are treated as keys, and are converted to strings +// (with fmt.Sprint) if necessary. The keys are then zipped with the +// odd-indexed values into typed fields, falling back to a reflection-based +// encoder if necessary. +// +// For example, +// sugaredLogger.With( +// "hello", "world", +// "failure", errors.New("oh no"), +// "count", 42, +// "user", User{name: "alice"}, +// ) +// is the equivalent of +// coreLogger.With( +// String("hello", "world"), +// String("failure", "oh no"), +// Int("count", 42), +// Object("user", User{name: "alice"}), +// ) +func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger { + return &SugaredLogger{core: s.core.With(sweetenFields(args, s.core)...)} } -// NewSugar is a constructor for Sugar -func NewSugar(core Logger) Sugar { - return &sugar{core} +// WithStack adds a complete stack trace to the logger's context, using the key +// "stacktrace". +func (s *SugaredLogger) WithStack() *SugaredLogger { + return &SugaredLogger{core: s.core.With(Stack())} } -func (s *sugar) Level() Level { - return s.core.Level() +// 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.core.Debug(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) } -func (s *sugar) SetLevel(lvl Level) { - s.core.SetLevel(lvl) +// 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.Debug(fmt.Sprintf(template, args...)) } -func (s *sugar) With(args ...interface{}) Sugar { - fields, err := getSugarFields(args...) - if err != nil { - s.internalError(err.Error()) - } - return NewSugar(s.core.With(fields...)) +// 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.core.Info(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) } -func getSugarFields(args ...interface{}) ([]Field, error) { - var ( - noErrArgs []interface{} +// 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.Info(fmt.Sprintf(template, args...)) +} - ii int - key string - value interface{} - ) - fields := make([]Field, 0, len(args)/2) +// 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.core.Warn(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) +} - if len(args) == 0 { - return fields, 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.Warn(fmt.Sprintf(template, args...)) +} - switch err := args[0].(type) { - case error: - fields = append(fields, Error(err)) - noErrArgs = args[1:] - default: - noErrArgs = args - } +// 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.core.Error(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) +} - if (len(noErrArgs) % 2) != 0 { - return nil, errors.New("invalid number of arguments") - } +// 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.Error(fmt.Sprintf(template, args...)) +} - for ii, value = range noErrArgs { - if (ii % 2) == 0 { - switch value.(type) { - case string: - key = value.(string) - default: - return nil, errors.New("field name must be string") - } - } else { - // TODO: Add LogMarshaler support, it once been here, but - // had to be removed because type switch won't catch - // this intarface properly for some mystical reason. - switch v := value.(type) { - case error: - return nil, errors.New("error can only be the first argument") - case bool: - fields = append(fields, Bool(key, v)) - case float64: - fields = append(fields, Float64(key, v)) - case int: - fields = append(fields, Int(key, v)) - case int64: - fields = append(fields, Int64(key, v)) - case uint: - fields = append(fields, Uint(key, v)) - case uint64: - fields = append(fields, Uint64(key, v)) - case string: - fields = append(fields, String(key, v)) - case time.Time: - fields = append(fields, Time(key, v)) - case time.Duration: - fields = append(fields, Duration(key, v)) - case fmt.Stringer: - fields = append(fields, Stringer(key, v)) - default: - fields = append(fields, Object(key, value)) - } - } - } - return fields, nil -} - -func (s *sugar) Log(lvl Level, msg string, args ...interface{}) { - var ( - fields []Field - err error - ) - if cm := s.core.Check(lvl, msg); cm.OK() { - fields, err = getSugarFields(args...) - if err != nil { - s.internalError(err.Error()) - } - cm.Write(fields...) - } +// 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.core.Panic(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) } -func (s *sugar) Debug(msg string, args ...interface{}) { - s.Log(DebugLevel, msg, args...) +// 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.Panic(fmt.Sprintf(template, args...)) } -func (s *sugar) Info(msg string, args ...interface{}) { - s.Log(InfoLevel, msg, args...) +// 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.core.Fatal(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) } -func (s *sugar) Warn(msg string, args ...interface{}) { - s.Log(WarnLevel, msg, args...) +// 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. +func (s *SugaredLogger) Fatalf(template string, args ...interface{}) { + s.Fatal(fmt.Sprintf(template, args...)) } -func (s *sugar) Error(msg string, args ...interface{}) { - s.Log(ErrorLevel, msg, args...) +// DFatal logs a message and some key-value pairs using the underlying logger's +// DFatal method. Keys and values are treated as they are in the With +// method. (See Logger.DFatal for details.) +func (s *SugaredLogger) DFatal(msg interface{}, keysAndValues ...interface{}) { + s.core.DFatal(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) } -func (s *sugar) Panic(msg string, args ...interface{}) { - s.Log(PanicLevel, msg, args...) +// DFatalf uses fmt.Sprintf to construct a dynamic message, which is passed to +// the underlying Logger's DFatal method. (See Logger.DFatal for details.) It +// doesn't add to the message's structured context. +func (s *SugaredLogger) DFatalf(template string, args ...interface{}) { + s.DFatal(fmt.Sprintf(template, args...)) } -func (s *sugar) Fatal(msg string, args ...interface{}) { - s.Log(FatalLevel, msg, args...) +func sweetenFields(args []interface{}, errLogger Logger) []Field { + if len(args) == 0 { + return nil + } + if len(args)%2 == 1 { + errLogger.DFatal( + "Passed an odd number of keys and values to SugaredLogger, ignoring last.", + Object("ignored", args[len(args)-1]), + ) + } + + fields := make([]Field, len(args)/2) + for i := range fields { + key := sweetenMsg(args[2*i]) + + switch val := args[2*i+1].(type) { + case LogMarshaler: + fields[i] = Marshaler(key, val) + case bool: + fields[i] = Bool(key, val) + case float64: + fields[i] = Float64(key, val) + case float32: + fields[i] = Float64(key, float64(val)) + case int: + fields[i] = Int(key, val) + case int64: + fields[i] = Int64(key, val) + case int32: + fields[i] = Int64(key, int64(val)) + case int16: + fields[i] = Int64(key, int64(val)) + case int8: + fields[i] = Int64(key, int64(val)) + case uint: + fields[i] = Uint(key, val) + case uint64: + fields[i] = Uint64(key, val) + case uint32: + fields[i] = Uint64(key, uint64(val)) + case uint16: + fields[i] = Uint64(key, uint64(val)) + case uint8: + fields[i] = Uint64(key, uint64(val)) + case uintptr: + fields[i] = Uintptr(key, val) + case string: + fields[i] = String(key, val) + case time.Time: + fields[i] = Time(key, val) + case time.Duration: + fields[i] = Duration(key, val) + case error: + fields[i] = String(key, val.Error()) + case fmt.Stringer: + fields[i] = String(key, val.String()) + default: + fields[i] = Object(key, val) + } + } + return fields } -func (s *sugar) DFatal(msg string, args ...interface{}) { - fields, err := getSugarFields(args...) - if err != nil { - s.internalError(err.Error()) +func sweetenMsg(msg interface{}) string { + if m, ok := msg.(string); ok { + return m } - s.core.DFatal(msg, fields...) + return fmt.Sprint(msg) } diff --git a/sugar_bench_test.go b/sugar_bench_test.go index 60f52ad6e..e5d67896a 100644 --- a/sugar_bench_test.go +++ b/sugar_bench_test.go @@ -22,8 +22,8 @@ package zap import "testing" -func withBenchedSugar(b *testing.B, f func(Sugar)) { - logger := NewSugar(New( +func withBenchedSugar(b *testing.B, f func(*SugaredLogger)) { + logger := Sugar(New( NewJSONEncoder(), DebugLevel, DiscardOutput, @@ -37,8 +37,8 @@ func withBenchedSugar(b *testing.B, f func(Sugar)) { } func Benchmark10FieldsSugar(b *testing.B) { - withBenchedSugar(b, func(log Sugar) { - log.Info("Ten fields, passed at the log site.", + withBenchedSugar(b, func(logger *SugaredLogger) { + logger.Info("Ten fields, passed at the log site.", "one", 1, "two", 2, "three", 3, diff --git a/sugar_test.go b/sugar_test.go index e0c1469f4..ba3bf97df 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -20,53 +20,9 @@ package zap -import ( - "errors" - "testing" - "time" - - "github.com/stretchr/testify/assert" -) - -func TestSugarGetSugarFields(t *testing.T) { - var ( - fields []Field - err error - ) - - _, err = getSugarFields("test") - assert.Error(t, err, "Should return error on invalid number of arguments") - - _, err = getSugarFields("test1", 1, "test2") - assert.Error(t, err, "Should return error on invalid number of arguments") - - _, err = getSugarFields("test1", 1, "error", errors.New("")) - assert.Error(t, err, "Should return error when error passed as value (special case of unknown type)") - - _, err = getSugarFields(1, 1) - assert.Error(t, err, "Should return error on non-string field name") - - fields, _ = getSugarFields("test", 1) - assert.Len(t, fields, 1, "Should return 1 field") - - fields, _ = getSugarFields("test1", 1, "test2", 2) - assert.Len(t, fields, 2, "Should return 2 fields") - - fields, _ = getSugarFields(errors.New("error"), "test1", 1) - assert.Len(t, fields, 2, "Should return 2 fields") -} - -func TestSugarLevel(t *testing.T) { - assert.Equal(t, DebugLevel, NewSugar(New(NewJSONEncoder(), DebugLevel)).Level()) - assert.Equal(t, FatalLevel, NewSugar(New(NewJSONEncoder(), FatalLevel)).Level()) -} - -func TestSugarSetLevel(t *testing.T) { - sugar := NewSugar(New(NewJSONEncoder())) - sugar.SetLevel(FatalLevel) - assert.Equal(t, FatalLevel, sugar.Level()) -} +/* FIXME (shah): Update to match new APIs. +// FIXME: add tests for trailing keys in key-value pairs. func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer, *testBuffer)) { sink := &testBuffer{} errSink := &testBuffer{} @@ -224,3 +180,4 @@ func TestSugarWithErrors(t *testing.T) { assert.Equal(t, "invalid number of arguments", err.Stripped(), "Should log invalid number of arguments") }) } +*/ From 55b87184c9b8fb8992ec6a923532ce1346d8fef8 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 12 Jan 2017 16:54:01 -0800 Subject: [PATCH 23/31] Finish sugared logger, update tests & benchmarks --- common_test.go | 4 + field.go | 50 +++++++ sugar.go | 157 ++++++++++----------- sugar_bench_test.go | 14 +- sugar_test.go | 323 ++++++++++++++++++++++++-------------------- 5 files changed, 310 insertions(+), 238 deletions(-) diff --git a/common_test.go b/common_test.go index cf4b06918..69431c4ab 100644 --- a/common_test.go +++ b/common_test.go @@ -41,6 +41,10 @@ func withLogger(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(Logg f(log, &logs) } +func withSugar(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(*SugaredLogger, *zapcore.ObservedLogs)) { + withLogger(t, e, opts, func(logger Logger, logs *zapcore.ObservedLogs) { f(Sugar(logger), logs) }) +} + func runConcurrently(goroutines, iterations int, wg *sync.WaitGroup, f func()) { wg.Add(goroutines) for g := 0; g < goroutines; g++ { diff --git a/field.go b/field.go index fc6b4ee86..7e737c373 100644 --- a/field.go +++ b/field.go @@ -156,3 +156,53 @@ func Reflect(key string, val interface{}) zapcore.Field { func Nest(key string, fields ...zapcore.Field) zapcore.Field { return zapcore.Field{Key: key, Type: zapcore.ObjectMarshalerType, Interface: zapcore.Fields(fields)} } + +// Any takes a key and an arbitrary value and chooses the best way to represent +// them as a field, falling back to a reflection-based approach only if +// necessary. +func Any(key string, value interface{}) zapcore.Field { + switch val := value.(type) { + case zapcore.ObjectMarshaler: + return Object(key, val) + case bool: + return Bool(key, val) + case float64: + return Float64(key, val) + case float32: + return Float64(key, float64(val)) + case int: + return Int(key, val) + case int64: + return Int64(key, val) + case int32: + return Int64(key, int64(val)) + case int16: + return Int64(key, int64(val)) + case int8: + return Int64(key, int64(val)) + case uint: + return Uint(key, val) + case uint64: + return Uint64(key, val) + case uint32: + return Uint64(key, uint64(val)) + case uint16: + return Uint64(key, uint64(val)) + case uint8: + return Uint64(key, uint64(val)) + case uintptr: + return Uintptr(key, val) + case string: + return String(key, val) + case error: + return String(key, val.Error()) + case time.Time: + return Time(key, val) + case time.Duration: + return Duration(key, val) + case fmt.Stringer: + return String(key, val.String()) + default: + return Reflect(key, val) + } +} diff --git a/sugar.go b/sugar.go index 78778c44d..466e44c94 100644 --- a/sugar.go +++ b/sugar.go @@ -22,9 +22,12 @@ package zap import ( "fmt" - "time" + + "go.uber.org/zap/zapcore" ) +const oddNumberErrMsg = "Passed an odd number of keys and values to SugaredLogger, ignoring last." + // A SugaredLogger wraps the core Logger functionality in a slower, but less // verbose, API. type SugaredLogger struct { @@ -33,19 +36,20 @@ type SugaredLogger struct { // Sugar converts a Logger to a SugaredLogger. func Sugar(core Logger) *SugaredLogger { + // TODO: increment caller skip. return &SugaredLogger{core} } // Desugar unwraps a SugaredLogger, exposing the original Logger. func Desugar(s *SugaredLogger) Logger { + // TODO: decrement caller skip. return s.core } // With adds a variadic number of key-value pairs to the logging context. // Even-indexed arguments are treated as keys, and are converted to strings // (with fmt.Sprint) if necessary. The keys are then zipped with the -// odd-indexed values into typed fields, falling back to a reflection-based -// encoder if necessary. +// odd-indexed values into typed fields using the Any field constructor. // // For example, // sugaredLogger.With( @@ -65,165 +69,146 @@ func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger { return &SugaredLogger{core: s.core.With(sweetenFields(args, s.core)...)} } -// WithStack adds a complete stack trace to the logger's context, using the key -// "stacktrace". -func (s *SugaredLogger) WithStack() *SugaredLogger { - return &SugaredLogger{core: s.core.With(Stack())} +// WithFields adds structured fields to the logger's context, just like the +// standard Logger's With method. +func (s *SugaredLogger) WithFields(fs ...zapcore.Field) *SugaredLogger { + return &SugaredLogger{core: s.core.With(fs...)} } // 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.core.Debug(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) + if ce := s.core.Check(DebugLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } } // 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.Debug(fmt.Sprintf(template, args...)) + if ce := s.core.Check(DebugLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } } // 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.core.Info(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) + if ce := s.core.Check(InfoLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } } // 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.Info(fmt.Sprintf(template, args...)) + if ce := s.core.Check(InfoLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } } // 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.core.Warn(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) + if ce := s.core.Check(WarnLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } } // 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.Warn(fmt.Sprintf(template, args...)) + if ce := s.core.Check(WarnLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } } // 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.core.Error(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) + if ce := s.core.Check(ErrorLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } } // 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.Error(fmt.Sprintf(template, args...)) + if ce := s.core.Check(ErrorLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } +} + +// 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{}) { + if ce := s.core.Check(DPanicLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } +} + +// 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{}) { + if ce := s.core.Check(DPanicLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } } // 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.core.Panic(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) + if ce := s.core.Check(PanicLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } } // 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.Panic(fmt.Sprintf(template, args...)) + if ce := s.core.Check(PanicLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } } // 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.core.Fatal(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) + if ce := s.core.Check(FatalLevel, sweetenMsg(msg)); ce != nil { + ce.Write(sweetenFields(keysAndValues, s.core)...) + } } // 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. func (s *SugaredLogger) Fatalf(template string, args ...interface{}) { - s.Fatal(fmt.Sprintf(template, args...)) -} - -// DFatal logs a message and some key-value pairs using the underlying logger's -// DFatal method. Keys and values are treated as they are in the With -// method. (See Logger.DFatal for details.) -func (s *SugaredLogger) DFatal(msg interface{}, keysAndValues ...interface{}) { - s.core.DFatal(sweetenMsg(msg), sweetenFields(keysAndValues, s.core)...) -} - -// DFatalf uses fmt.Sprintf to construct a dynamic message, which is passed to -// the underlying Logger's DFatal method. (See Logger.DFatal for details.) It -// doesn't add to the message's structured context. -func (s *SugaredLogger) DFatalf(template string, args ...interface{}) { - s.DFatal(fmt.Sprintf(template, args...)) + if ce := s.core.Check(FatalLevel, fmt.Sprintf(template, args...)); ce != nil { + ce.Write() + } } -func sweetenFields(args []interface{}, errLogger Logger) []Field { +func sweetenFields(args []interface{}, errLogger Logger) []zapcore.Field { if len(args) == 0 { return nil } if len(args)%2 == 1 { - errLogger.DFatal( - "Passed an odd number of keys and values to SugaredLogger, ignoring last.", - Object("ignored", args[len(args)-1]), - ) + errLogger.DPanic(oddNumberErrMsg, Any("ignored", args[len(args)-1])) } - fields := make([]Field, len(args)/2) + fields := make([]zapcore.Field, len(args)/2) for i := range fields { key := sweetenMsg(args[2*i]) - - switch val := args[2*i+1].(type) { - case LogMarshaler: - fields[i] = Marshaler(key, val) - case bool: - fields[i] = Bool(key, val) - case float64: - fields[i] = Float64(key, val) - case float32: - fields[i] = Float64(key, float64(val)) - case int: - fields[i] = Int(key, val) - case int64: - fields[i] = Int64(key, val) - case int32: - fields[i] = Int64(key, int64(val)) - case int16: - fields[i] = Int64(key, int64(val)) - case int8: - fields[i] = Int64(key, int64(val)) - case uint: - fields[i] = Uint(key, val) - case uint64: - fields[i] = Uint64(key, val) - case uint32: - fields[i] = Uint64(key, uint64(val)) - case uint16: - fields[i] = Uint64(key, uint64(val)) - case uint8: - fields[i] = Uint64(key, uint64(val)) - case uintptr: - fields[i] = Uintptr(key, val) - case string: - fields[i] = String(key, val) - case time.Time: - fields[i] = Time(key, val) - case time.Duration: - fields[i] = Duration(key, val) - case error: - fields[i] = String(key, val.Error()) - case fmt.Stringer: - fields[i] = String(key, val.String()) - default: - fields[i] = Object(key, val) - } + fields[i] = Any(key, args[2*i+1]) } return fields } func sweetenMsg(msg interface{}) string { - if m, ok := msg.(string); ok { - return m + if str, ok := msg.(string); ok { + return str } return fmt.Sprint(msg) } diff --git a/sugar_bench_test.go b/sugar_bench_test.go index e5d67896a..68da6dc8e 100644 --- a/sugar_bench_test.go +++ b/sugar_bench_test.go @@ -20,14 +20,18 @@ package zap -import "testing" +import ( + "testing" + + "go.uber.org/zap/testutils" + "go.uber.org/zap/zapcore" +) func withBenchedSugar(b *testing.B, f func(*SugaredLogger)) { - logger := Sugar(New( - NewJSONEncoder(), + logger := Sugar(New(zapcore.WriterFacility(zapcore.NewJSONEncoder(defaultEncoderConfig()), + &testutils.Discarder{}, DebugLevel, - DiscardOutput, - )) + ))) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/sugar_test.go b/sugar_test.go index ba3bf97df..d9dfa4e68 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -20,164 +20,193 @@ package zap -/* FIXME (shah): Update to match new APIs. +import ( + "testing" -// FIXME: add tests for trailing keys in key-value pairs. -func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer, *testBuffer)) { - sink := &testBuffer{} - errSink := &testBuffer{} + "github.com/stretchr/testify/assert" - allOpts := make([]Option, 0, 3+len(opts)) - allOpts = append(allOpts, DebugLevel, Output(sink), ErrorOutput(errSink)) - allOpts = append(allOpts, opts...) - logger := New(newJSONEncoder(NoTime()), allOpts...) - sugar := NewSugar(logger) + "go.uber.org/zap/internal/exit" + "go.uber.org/zap/zapcore" +) - f(sugar, sink, errSink) -} - -func TestSugarLog(t *testing.T) { - opts := opts(Fields(Int("foo", 42))) - withSugarLogger(t, opts, func(logger Sugar, out *testBuffer, _ *testBuffer) { - logger.Debug("debug message", "a", "b") - logger.Info("info message", "c", "d") - logger.Warn("warn message", "e", "f") - logger.Error("error message", "g", "h") - assert.Equal(t, []string{ - `{"level":"debug","msg":"debug message","foo":42,"a":"b"}`, - `{"level":"info","msg":"info message","foo":42,"c":"d"}`, - `{"level":"warn","msg":"warn message","foo":42,"e":"f"}`, - `{"level":"error","msg":"error message","foo":42,"g":"h"}`, - }, out.Lines(), "Incorrect output from logger") - }) -} - -func TestSugarLogTypes(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { - logger.Debug("") - logger.Debug("", "bool", true) - logger.Debug("", "float64", float64(1.23456789)) - logger.Debug("", "int", int(-1)) - logger.Debug("", "int64", int64(-1)) - logger.Debug("", "uint", uint(1)) - logger.Debug("", "uint64", uint64(1)) - logger.Debug("", "string", "") - logger.Debug("", "time", time.Unix(0, 0)) - logger.Debug("", "duration", time.Second) - logger.Debug("", "stringer", DebugLevel) - logger.Debug("", "object", []string{"foo", "bar"}) - assert.Equal(t, []string{ - `{"level":"debug","msg":""}`, - `{"level":"debug","msg":"","bool":true}`, - `{"level":"debug","msg":"","float64":1.23456789}`, - `{"level":"debug","msg":"","int":-1}`, - `{"level":"debug","msg":"","int64":-1}`, - `{"level":"debug","msg":"","uint":1}`, - `{"level":"debug","msg":"","uint64":1}`, - `{"level":"debug","msg":"","string":""}`, - `{"level":"debug","msg":"","time":0}`, - `{"level":"debug","msg":"","duration":1000000000}`, - `{"level":"debug","msg":"","stringer":"debug"}`, - `{"level":"debug","msg":"","object":["foo","bar"]}`, - }, out.Lines(), "Incorrect output from logger") - }) -} - -func TestSugarLogError(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { - logger.Debug("with error", errors.New("this is a error")) - assert.Equal(t, []string{ - `{"level":"debug","msg":"with error","error":"this is a error"}`, - }, out.Lines(), "Incorrect output from logger") - }) -} - -func TestSugarPanic(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { - assert.Panics(t, func() { logger.Panic("foo") }, "Expected logging at Panic level to panic.") - assert.Equal(t, `{"level":"panic","msg":"foo"}`, out.Stripped(), "Unexpected output from panic-level Log.") - }) -} - -func TestSugarFatal(t *testing.T) { - stub := stubExit() - defer stub.Unstub() - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { - logger.Fatal("foo") - assert.Equal(t, `{"level":"fatal","msg":"foo"}`, out.Stripped(), "Unexpected output from fatal-level Log.") - stub.AssertStatus(t, 1) - }) -} - -func TestSugarDFatal(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, _ *testBuffer) { - logger.DFatal("foo") - assert.Equal(t, `{"level":"error","msg":"foo"}`, out.Stripped(), "Unexpected output from dfatal") - }) - - stub := stubExit() - defer stub.Unstub() - opts := opts(Development()) - withSugarLogger(t, opts, func(logger Sugar, out *testBuffer, _ *testBuffer) { - logger.DFatal("foo") - assert.Equal(t, `{"level":"fatal","msg":"foo"}`, out.Stripped(), "Unexpected output from DFatal in dev mode") - stub.AssertStatus(t, 1) - }) +func TestSugarWith(t *testing.T) { + ignored := zapcore.ObservedLog{ + Entry: zapcore.Entry{Level: DPanicLevel, Message: oddNumberErrMsg}, + Context: []zapcore.Field{Any("ignored", "should ignore")}, + } + + tests := []struct { + args []interface{} + expected []zapcore.Field + }{ + {nil, []zapcore.Field{}}, + {[]interface{}{}, []zapcore.Field{}}, + {[]interface{}{"foo", 42, true, "bar"}, []zapcore.Field{Int("foo", 42), String("true", "bar")}}, + } + + for _, tt := range tests { + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.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 *zapcore.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.") + }) + } } -func TestSugarDFatalErrors(t *testing.T) { - opts := opts() - withSugarLogger(t, opts, func(logger Sugar, _ *testBuffer, err *testBuffer) { - logger.DFatal("foo", "bar") - assert.Equal(t, "invalid number of arguments", err.Stripped(), "Should log invalid number of arguments") - }) +func TestSugarWithFields(t *testing.T) { + tests := [][]zapcore.Field{ + {}, + {String("foo", "bar"), Int("baz", 42)}, + } + for _, fields := range tests { + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.ObservedLogs) { + logger.WithFields(fields...).Info("") + output := logs.AllUntimed() + assert.Equal(t, 1, len(output), "Expected only one message to be logged.") + assert.Equal(t, fields, output[0].Context, "Unexpected message context.") + }) + } } -func TestSugarLogErrors(t *testing.T) { - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { - logger.Log(InfoLevel, "foo", "a") - assert.Equal(t, `{"level":"info","msg":"foo"}`, out.Stripped(), "Should log invalid number of arguments") - assert.Equal(t, `invalid number of arguments`, err.Stripped(), "Should log invalid number of arguments") - }) - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { - logger.Log(InfoLevel, "foo", 1, "foo") - assert.Equal(t, `{"level":"info","msg":"foo"}`, out.Stripped(), "Should log invalid name type") - assert.Equal(t, `field name must be string`, err.Stripped(), "Should log invalid name type") - }) - withSugarLogger(t, nil, func(logger Sugar, out *testBuffer, err *testBuffer) { - logger.Log(InfoLevel, "foo", "foo", errors.New("b")) - assert.Equal(t, `{"level":"info","msg":"foo"}`, out.Stripped(), "Should log error argument position is invalid") - assert.Equal(t, `error can only be the first argument`, err.Stripped(), "Should log error argument position is invalid") - }) +type stringerF func() string + +func (f stringerF) String() string { return f() } + +func TestSugarStructuredLogging(t *testing.T) { + tests := []struct { + msg interface{} + 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)} + + for _, tt := range tests { + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.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...) + + expected := make([]zapcore.ObservedLog, 5) + for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { + expected[i] = zapcore.ObservedLog{ + Entry: zapcore.Entry{Message: tt.expectMsg, Level: lvl}, + Context: expectedFields, + } + } + assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") + }) + } } -func TestSugarLogDiscards(t *testing.T) { - withSugarLogger(t, opts(InfoLevel), func(logger Sugar, buf *testBuffer, _ *testBuffer) { - logger.Debug("should be discarded") - logger.Debug("should be discarded even with invalid arg count", "bla") - logger.Info("should be logged") - assert.Equal(t, []string{ - `{"level":"info","msg":"should be logged"}`, - }, buf.Lines(), "") - }) +func TestSugarFormattedLogging(t *testing.T) { + tests := []struct { + format string + args []interface{} + expect string + }{ + {"", nil, ""}, + {"foo", nil, "foo"}, + {"", []interface{}{"foo"}, "%!(EXTRA string=foo)"}, + } + + // 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 *zapcore.ObservedLogs) { + logger.With(context...).Debugf(tt.format, tt.args...) + logger.With(context...).Infof(tt.format, tt.args...) + logger.With(context...).Warnf(tt.format, tt.args...) + logger.With(context...).Errorf(tt.format, tt.args...) + logger.With(context...).DPanicf(tt.format, tt.args...) + + expected := make([]zapcore.ObservedLog, 5) + for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { + expected[i] = zapcore.ObservedLog{ + Entry: zapcore.Entry{Message: tt.expect, Level: lvl}, + Context: expectedFields, + } + } + assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") + }) + } } -func TestSugarWith(t *testing.T) { - opts := opts() - withSugarLogger(t, opts, func(logger Sugar, out *testBuffer, _ *testBuffer) { - child := logger.With("a", "b") - child.Debug("debug message", "c", "d") - assert.Equal(t, []string{ - `{"level":"debug","msg":"debug message","a":"b","c":"d"}`, - }, out.Lines(), "Incorrect output from logger") - }) +func TestSugarPanicLogging(t *testing.T) { + tests := []struct { + loggerLevel zapcore.Level + f func(*SugaredLogger) + expectedMsg string + }{ + {FatalLevel, func(s *SugaredLogger) { s.Panic("foo") }, ""}, + {PanicLevel, func(s *SugaredLogger) { s.Panic("foo") }, "foo"}, + {DebugLevel, func(s *SugaredLogger) { s.Panic("foo") }, "foo"}, + {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"}, + } + + for _, tt := range tests { + withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *zapcore.ObservedLogs) { + assert.Panics(t, func() { tt.f(sugar) }, "Expected panic-level logger calls to panic.") + if tt.expectedMsg != "" { + assert.Equal(t, []zapcore.ObservedLog{{ + Context: []zapcore.Field{}, + Entry: zapcore.Entry{Message: tt.expectedMsg, Level: PanicLevel}, + }}, logs.AllUntimed(), "Unexpected log output.") + } else { + assert.Equal(t, 0, logs.Len(), "Didn't expect any log output.") + } + }) + } } -func TestSugarWithErrors(t *testing.T) { - opts := opts() - withSugarLogger(t, opts, func(logger Sugar, _ *testBuffer, err *testBuffer) { - logger.With("a") - assert.Equal(t, "invalid number of arguments", err.Stripped(), "Should log invalid number of arguments") - }) +func TestSugarFatalLogging(t *testing.T) { + tests := []struct { + loggerLevel zapcore.Level + f func(*SugaredLogger) + expectedMsg string + }{ + {FatalLevel + 1, func(s *SugaredLogger) { s.Fatal("foo") }, ""}, + {FatalLevel, func(s *SugaredLogger) { s.Fatal("foo") }, "foo"}, + {DebugLevel, func(s *SugaredLogger) { s.Fatal("foo") }, "foo"}, + {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"}, + } + + for _, tt := range tests { + withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *zapcore.ObservedLogs) { + stub := exit.WithStub(func() { tt.f(sugar) }) + assert.True(t, stub.Exited, "Expected all calls to fatal logger methods to exit process.") + if tt.expectedMsg != "" { + assert.Equal(t, []zapcore.ObservedLog{{ + Context: []zapcore.Field{}, + Entry: zapcore.Entry{Message: tt.expectedMsg, Level: FatalLevel}, + }}, logs.AllUntimed(), "Unexpected log output.") + } else { + assert.Equal(t, 0, logs.Len(), "Didn't expect any log output.") + } + }) + } } -*/ From 96da7762b68e16578bd6cd0b4b2cc0b374a2e4c3 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 12 Jan 2017 17:02:46 -0800 Subject: [PATCH 24/31] Update the benchmarks --- benchmarks/zap_sugar_bench_test.go | 54 +++++------------------------- 1 file changed, 9 insertions(+), 45 deletions(-) diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go index 405e6b17b..986f522ab 100644 --- a/benchmarks/zap_sugar_bench_test.go +++ b/benchmarks/zap_sugar_bench_test.go @@ -20,14 +20,13 @@ package benchmarks -/* FIXME (shah): Update to match new APIs. - import ( "testing" "time" - "github.com/uber-go/zap" - "github.com/uber-go/zap/zwrap" + "go.uber.org/zap" + "go.uber.org/zap/testutils" + "go.uber.org/zap/zapcore" ) func fakeSugarFields() []interface{} { @@ -45,18 +44,12 @@ func fakeSugarFields() []interface{} { } } -var newCoreLoggerDefaults = []zap.Option{ - zap.ErrorLevel, - zap.DiscardOutput, -} - -func newCoreLogger(options ...zap.Option) zap.Logger { - options = append(newCoreLoggerDefaults, options...) - return zap.New(zap.NewJSONEncoder(), options...) -} - -func newSugarLogger(options ...zap.Option) zap.Sugar { - return zap.NewSugar(newCoreLogger(options...)) +func newSugarLogger(options ...zap.Option) *zap.SugaredLogger { + return zap.Sugar(zap.New(zapcore.WriterFacility( + benchEncoder(), + &testutils.Discarder{}, + zap.ErrorLevel, + ))) } func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { @@ -119,32 +112,3 @@ func BenchmarkZapSugarWithoutFields(b *testing.B) { } }) } - -func BenchmarkZapSugarSampleWithoutFields(b *testing.B) { - messages := fakeMessages(1000) - core := newCoreLogger() - logger := zap.NewSugar(zwrap.Sample(core, time.Second, 10, 10000)) - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - i := 0 - for pb.Next() { - i++ - logger.Info(messages[i%1000]) - } - }) -} - -func BenchmarkZapSugarSampleAddingFields(b *testing.B) { - messages := fakeMessages(1000) - core := newCoreLogger() - logger := zap.NewSugar(zwrap.Sample(core, time.Second, 10, 10000)) - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - i := 0 - for pb.Next() { - i++ - logger.Info(messages[i%1000], fakeSugarFields()...) - } - }) -} -*/ From ceba4545aa666e61a2b664bb2b69507abdb3bfd0 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 12 Jan 2017 21:10:26 -0800 Subject: [PATCH 25/31] Fix benchmarks The sugared logger benchmarks were artificially good because we weren't logging anything :/ --- benchmarks/zap_sugar_bench_test.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go index 986f522ab..84cb7db38 100644 --- a/benchmarks/zap_sugar_bench_test.go +++ b/benchmarks/zap_sugar_bench_test.go @@ -44,16 +44,16 @@ func fakeSugarFields() []interface{} { } } -func newSugarLogger(options ...zap.Option) *zap.SugaredLogger { +func newSugarLogger(lvl zapcore.Level, options ...zap.Option) *zap.SugaredLogger { return zap.Sugar(zap.New(zapcore.WriterFacility( benchEncoder(), &testutils.Discarder{}, - zap.ErrorLevel, - ))) + lvl, + ), options...)) } func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { - logger := newSugarLogger() + logger := newSugarLogger(zap.ErrorLevel) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -64,7 +64,7 @@ func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { func BenchmarkZapSugarDisabledLevelsAccumulatedContext(b *testing.B) { context := fakeFields() - logger := newSugarLogger(zap.Fields(context...)) + logger := newSugarLogger(zap.ErrorLevel, zap.Fields(context...)) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -74,7 +74,7 @@ func BenchmarkZapSugarDisabledLevelsAccumulatedContext(b *testing.B) { } func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) { - logger := newSugarLogger() + logger := newSugarLogger(zap.ErrorLevel) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -84,7 +84,7 @@ func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) { } func BenchmarkZapSugarAddingFields(b *testing.B) { - logger := newSugarLogger() + logger := newSugarLogger(zap.DebugLevel) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -94,7 +94,7 @@ func BenchmarkZapSugarAddingFields(b *testing.B) { } func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { - logger := newSugarLogger().With(fakeSugarFields()...) + logger := newSugarLogger(zap.DebugLevel).With(fakeSugarFields()...) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -104,7 +104,7 @@ func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { } func BenchmarkZapSugarWithoutFields(b *testing.B) { - logger := newSugarLogger() + logger := newSugarLogger(zap.DebugLevel) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { From 3c9b89e6affcc1f1cb74cd604204b0d8c2922062 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Fri, 13 Jan 2017 11:12:39 -0800 Subject: [PATCH 26/31] Add test coverage for zap.Any --- field.go | 2 +- field_test.go | 24 ++++++++++++++++++++++++ 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/field.go b/field.go index 7e737c373..7dcec50d8 100644 --- a/field.go +++ b/field.go @@ -201,7 +201,7 @@ func Any(key string, value interface{}) zapcore.Field { case time.Duration: return Duration(key, val) case fmt.Stringer: - return String(key, val.String()) + return Stringer(key, val) default: return Reflect(key, val) } diff --git a/field_test.go b/field_test.go index e0001fb3e..10bb93007 100644 --- a/field_test.go +++ b/field_test.go @@ -99,6 +99,30 @@ func TestFieldConstructors(t *testing.T) { {"Object", zapcore.Field{Key: "k", Type: zapcore.ObjectMarshalerType, Interface: name}, Object("k", name)}, {"Reflect", zapcore.Field{Key: "k", Type: zapcore.ReflectType, Interface: ints}, Reflect("k", ints)}, {"Nest", zapcore.Field{Key: "k", Type: zapcore.ObjectMarshalerType, Interface: nested}, Nest("k", nested...)}, + {"Any:ObjectMarshaler", Any("k", name), Object("k", name)}, + {"Any:Bool", Any("k", true), Bool("k", true)}, + {"Any:Float64", Any("k", 3.14), Float64("k", 3.14)}, + // TODO (v1.0): We could use some approximately-equal logic here, but it's + // not worth it to test this one line. Before 1.0, we'll need to support + // float32s explicitly, which will make this test pass. + // {"Any:Float32", Any("k", float32(3.14)), Float32("k", 3.14)}, + {"Any:Int", Any("k", 1), Int("k", 1)}, + {"Any:Int64", Any("k", int64(1)), Int64("k", 1)}, + {"Any:Int32", Any("k", int32(1)), Int64("k", 1)}, + {"Any:Int16", Any("k", int16(1)), Int64("k", 1)}, + {"Any:Int8", Any("k", int8(1)), Int64("k", 1)}, + {"Any:Uint", Any("k", uint(1)), Uint("k", 1)}, + {"Any:Uint64", Any("k", uint64(1)), Uint64("k", 1)}, + {"Any:Uint32", Any("k", uint32(1)), Uint64("k", 1)}, + {"Any:Uint16", Any("k", uint16(1)), Uint64("k", 1)}, + {"Any:Uint8", Any("k", uint8(1)), Uint64("k", 1)}, + {"Any:Uintptr", Any("k", uintptr(1)), Uintptr("k", 1)}, + {"Any:String", Any("k", "v"), String("k", "v")}, + {"Any:Error", Any("k", errors.New("v")), String("k", "v")}, + {"Any:Time", Any("k", time.Unix(0, 0)), Time("k", time.Unix(0, 0))}, + {"Any:Duration", Any("k", time.Second), Duration("k", time.Second)}, + {"Any:Stringer", Any("k", addr), Stringer("k", addr)}, + {"Any:Fallback", Any("k", struct{}{}), Reflect("k", struct{}{})}, } for _, tt := range tests { From c4c498f8ed9e463f0dd8256c8351ba6a835e5efb Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Fri, 13 Jan 2017 14:56:14 -0800 Subject: [PATCH 27/31] With should dispatch to WithFields --- sugar.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sugar.go b/sugar.go index 466e44c94..98a916cd3 100644 --- a/sugar.go +++ b/sugar.go @@ -66,7 +66,7 @@ func Desugar(s *SugaredLogger) Logger { // Object("user", User{name: "alice"}), // ) func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger { - return &SugaredLogger{core: s.core.With(sweetenFields(args, s.core)...)} + return s.WithFields(sweetenFields(args, s.core)...) } // WithFields adds structured fields to the logger's context, just like the From 1e2740dd2ffffd757764146a9d3f2f2a0aa8d8f0 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Fri, 13 Jan 2017 15:54:17 -0800 Subject: [PATCH 28/31] Update to use internal observer package --- common_test.go | 4 ++-- sugar_test.go | 29 +++++++++++++++-------------- 2 files changed, 17 insertions(+), 16 deletions(-) diff --git a/common_test.go b/common_test.go index 69431c4ab..a09de4696 100644 --- a/common_test.go +++ b/common_test.go @@ -41,8 +41,8 @@ func withLogger(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(Logg f(log, &logs) } -func withSugar(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(*SugaredLogger, *zapcore.ObservedLogs)) { - withLogger(t, e, opts, func(logger Logger, logs *zapcore.ObservedLogs) { f(Sugar(logger), logs) }) +func withSugar(t testing.TB, e zapcore.LevelEnabler, opts []Option, f func(*SugaredLogger, *observer.ObservedLogs)) { + withLogger(t, e, opts, func(logger Logger, logs *observer.ObservedLogs) { f(Sugar(logger), logs) }) } func runConcurrently(goroutines, iterations int, wg *sync.WaitGroup, f func()) { diff --git a/sugar_test.go b/sugar_test.go index d9dfa4e68..a20d9fddc 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -26,11 +26,12 @@ import ( "github.com/stretchr/testify/assert" "go.uber.org/zap/internal/exit" + "go.uber.org/zap/internal/observer" "go.uber.org/zap/zapcore" ) func TestSugarWith(t *testing.T) { - ignored := zapcore.ObservedLog{ + ignored := observer.LoggedEntry{ Entry: zapcore.Entry{Level: DPanicLevel, Message: oddNumberErrMsg}, Context: []zapcore.Field{Any("ignored", "should ignore")}, } @@ -45,14 +46,14 @@ func TestSugarWith(t *testing.T) { } for _, tt := range tests { - withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.ObservedLogs) { + 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 *zapcore.ObservedLogs) { + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { oddArgs := append(tt.args, "should ignore") logger.With(oddArgs...).Info("") output := logs.AllUntimed() @@ -69,7 +70,7 @@ func TestSugarWithFields(t *testing.T) { {String("foo", "bar"), Int("baz", 42)}, } for _, fields := range tests { - withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.ObservedLogs) { + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { logger.WithFields(fields...).Info("") output := logs.AllUntimed() assert.Equal(t, 1, len(output), "Expected only one message to be logged.") @@ -98,16 +99,16 @@ func TestSugarStructuredLogging(t *testing.T) { expectedFields := []zapcore.Field{String("foo", "bar"), Bool("true", false)} for _, tt := range tests { - withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.ObservedLogs) { + 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...) - expected := make([]zapcore.ObservedLog, 5) + expected := make([]observer.LoggedEntry, 5) for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { - expected[i] = zapcore.ObservedLog{ + expected[i] = observer.LoggedEntry{ Entry: zapcore.Entry{Message: tt.expectMsg, Level: lvl}, Context: expectedFields, } @@ -133,16 +134,16 @@ func TestSugarFormattedLogging(t *testing.T) { expectedFields := []zapcore.Field{String("foo", "bar")} for _, tt := range tests { - withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *zapcore.ObservedLogs) { + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { logger.With(context...).Debugf(tt.format, tt.args...) logger.With(context...).Infof(tt.format, tt.args...) logger.With(context...).Warnf(tt.format, tt.args...) logger.With(context...).Errorf(tt.format, tt.args...) logger.With(context...).DPanicf(tt.format, tt.args...) - expected := make([]zapcore.ObservedLog, 5) + expected := make([]observer.LoggedEntry, 5) for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { - expected[i] = zapcore.ObservedLog{ + expected[i] = observer.LoggedEntry{ Entry: zapcore.Entry{Message: tt.expect, Level: lvl}, Context: expectedFields, } @@ -167,10 +168,10 @@ func TestSugarPanicLogging(t *testing.T) { } for _, tt := range tests { - withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *zapcore.ObservedLogs) { + withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *observer.ObservedLogs) { assert.Panics(t, func() { tt.f(sugar) }, "Expected panic-level logger calls to panic.") if tt.expectedMsg != "" { - assert.Equal(t, []zapcore.ObservedLog{{ + assert.Equal(t, []observer.LoggedEntry{{ Context: []zapcore.Field{}, Entry: zapcore.Entry{Message: tt.expectedMsg, Level: PanicLevel}, }}, logs.AllUntimed(), "Unexpected log output.") @@ -196,11 +197,11 @@ func TestSugarFatalLogging(t *testing.T) { } for _, tt := range tests { - withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *zapcore.ObservedLogs) { + withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *observer.ObservedLogs) { stub := exit.WithStub(func() { tt.f(sugar) }) assert.True(t, stub.Exited, "Expected all calls to fatal logger methods to exit process.") if tt.expectedMsg != "" { - assert.Equal(t, []zapcore.ObservedLog{{ + assert.Equal(t, []observer.LoggedEntry{{ Context: []zapcore.Field{}, Entry: zapcore.Entry{Message: tt.expectedMsg, Level: FatalLevel}, }}, logs.AllUntimed(), "Unexpected log output.") From 2698ecac739eb45c8f0e3dd0a5af74635ed1aa66 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Fri, 13 Jan 2017 17:05:26 -0800 Subject: [PATCH 29/31] Some CR --- field.go | 6 ++++-- field_test.go | 7 +++---- sugar.go | 22 +++++++++++----------- sugar_test.go | 2 +- 4 files changed, 19 insertions(+), 18 deletions(-) diff --git a/field.go b/field.go index 7dcec50d8..32c60896f 100644 --- a/field.go +++ b/field.go @@ -164,6 +164,8 @@ func Any(key string, value interface{}) zapcore.Field { switch val := value.(type) { case zapcore.ObjectMarshaler: return Object(key, val) + case zapcore.ArrayMarshaler: + return Array(key, val) case bool: return Bool(key, val) case float64: @@ -194,12 +196,12 @@ func Any(key string, value interface{}) zapcore.Field { return Uintptr(key, val) case string: return String(key, val) - case error: - return String(key, val.Error()) case time.Time: return Time(key, val) case time.Duration: return Duration(key, val) + case error: + return String(key, val.Error()) case fmt.Stringer: return Stringer(key, val) default: diff --git a/field_test.go b/field_test.go index 10bb93007..e10bf0b8b 100644 --- a/field_test.go +++ b/field_test.go @@ -22,16 +22,14 @@ package zap import ( "errors" + "math" "net" "sync" "testing" "time" - "go.uber.org/zap/zapcore" - - "math" - "github.com/stretchr/testify/assert" + "go.uber.org/zap/zapcore" ) var ( @@ -100,6 +98,7 @@ func TestFieldConstructors(t *testing.T) { {"Reflect", zapcore.Field{Key: "k", Type: zapcore.ReflectType, Interface: ints}, Reflect("k", ints)}, {"Nest", zapcore.Field{Key: "k", Type: zapcore.ObjectMarshalerType, Interface: nested}, Nest("k", nested...)}, {"Any:ObjectMarshaler", Any("k", name), Object("k", name)}, + {"Any:ArrayMarshaler", Any("k", bools([]bool{true})), Array("k", bools([]bool{true}))}, {"Any:Bool", Any("k", true), Bool("k", true)}, {"Any:Float64", Any("k", 3.14), Float64("k", 3.14)}, // TODO (v1.0): We could use some approximately-equal logic here, but it's diff --git a/sugar.go b/sugar.go index 98a916cd3..e92f0e551 100644 --- a/sugar.go +++ b/sugar.go @@ -26,7 +26,7 @@ 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." // A SugaredLogger wraps the core Logger functionality in a slower, but less // verbose, API. @@ -66,7 +66,7 @@ func Desugar(s *SugaredLogger) Logger { // Object("user", User{name: "alice"}), // ) func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger { - return s.WithFields(sweetenFields(args, s.core)...) + return s.WithFields(s.sweetenFields(args)...) } // WithFields adds structured fields to the logger's context, just like the @@ -79,7 +79,7 @@ func (s *SugaredLogger) WithFields(fs ...zapcore.Field) *SugaredLogger { // are treated as they are in the With method. func (s *SugaredLogger) Debug(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(DebugLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -95,7 +95,7 @@ func (s *SugaredLogger) Debugf(template string, args ...interface{}) { // are treated as they are in the With method. func (s *SugaredLogger) Info(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(InfoLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -111,7 +111,7 @@ func (s *SugaredLogger) Infof(template string, args ...interface{}) { // are treated as they are in the With method. func (s *SugaredLogger) Warn(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(WarnLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -127,7 +127,7 @@ func (s *SugaredLogger) Warnf(template string, args ...interface{}) { // are treated as they are in the With method. func (s *SugaredLogger) Error(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(ErrorLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -144,7 +144,7 @@ func (s *SugaredLogger) Errorf(template string, args ...interface{}) { // method. (See Logger.DPanic for details.) func (s *SugaredLogger) DPanic(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(DPanicLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -161,7 +161,7 @@ func (s *SugaredLogger) DPanicf(template string, args ...interface{}) { // Keys and values are treated as they are in the With method. func (s *SugaredLogger) Panic(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(PanicLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -177,7 +177,7 @@ func (s *SugaredLogger) Panicf(template string, args ...interface{}) { // os.Exit(1). Keys and values are treated as they are in the With method. func (s *SugaredLogger) Fatal(msg interface{}, keysAndValues ...interface{}) { if ce := s.core.Check(FatalLevel, sweetenMsg(msg)); ce != nil { - ce.Write(sweetenFields(keysAndValues, s.core)...) + ce.Write(s.sweetenFields(keysAndValues)...) } } @@ -190,12 +190,12 @@ func (s *SugaredLogger) Fatalf(template string, args ...interface{}) { } } -func sweetenFields(args []interface{}, errLogger Logger) []zapcore.Field { +func (s *SugaredLogger) sweetenFields(args []interface{}) []zapcore.Field { if len(args) == 0 { return nil } if len(args)%2 == 1 { - errLogger.DPanic(oddNumberErrMsg, Any("ignored", args[len(args)-1])) + s.core.DPanic(_oddNumberErrMsg, Any("ignored", args[len(args)-1])) } fields := make([]zapcore.Field, len(args)/2) diff --git a/sugar_test.go b/sugar_test.go index a20d9fddc..3273273aa 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -32,7 +32,7 @@ import ( func TestSugarWith(t *testing.T) { ignored := observer.LoggedEntry{ - Entry: zapcore.Entry{Level: DPanicLevel, Message: oddNumberErrMsg}, + Entry: zapcore.Entry{Level: DPanicLevel, Message: _oddNumberErrMsg}, Context: []zapcore.Field{Any("ignored", "should ignore")}, } From bc38c5c041478d1cc4436cf6408320bb6c5ef15e Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Mon, 16 Jan 2017 11:57:09 -0800 Subject: [PATCH 30/31] Pivot to a map-based sugared logger Switch from a varargs-based approach to sugaring to a map-based approach. This avoids allocations to convert strings to `interface{}`. --- benchmarks/zap_sugar_bench_test.go | 33 ++-- level.go | 4 +- sugar.go | 244 +++++++++++++++-------------- sugar_bench_test.go | 24 +-- sugar_test.go | 128 +++++++-------- 5 files changed, 210 insertions(+), 223 deletions(-) diff --git a/benchmarks/zap_sugar_bench_test.go b/benchmarks/zap_sugar_bench_test.go index 84cb7db38..631c60cbc 100644 --- a/benchmarks/zap_sugar_bench_test.go +++ b/benchmarks/zap_sugar_bench_test.go @@ -29,18 +29,18 @@ import ( "go.uber.org/zap/zapcore" ) -func fakeSugarFields() []interface{} { - return []interface{}{ - errExample, - "int", 1, - "int64", 2, - "float", 3.0, - "string", "four!", - "stringer", zap.DebugLevel, - "bool", true, - "time", time.Unix(0, 0), - "duration", time.Second, - "another string", "done!", +func fakeSugarFields() zap.Ctx { + return zap.Ctx{ + "error": errExample, + "int": 1, + "int64": 2, + "float": 3.0, + "string": "four!", + "stringer": zap.DebugLevel, + "bool": true, + "time": time.Unix(0, 0), + "duration": time.Second, + "another string": "done!", } } @@ -63,8 +63,7 @@ func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) { } func BenchmarkZapSugarDisabledLevelsAccumulatedContext(b *testing.B) { - context := fakeFields() - logger := newSugarLogger(zap.ErrorLevel, zap.Fields(context...)) + logger := newSugarLogger(zap.ErrorLevel, zap.Fields(fakeFields()...)) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -78,7 +77,7 @@ func BenchmarkZapSugarDisabledLevelsAddingFields(b *testing.B) { b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { - logger.Info("Should be discarded.", fakeSugarFields()...) + logger.InfoWith("Should be discarded.", fakeSugarFields()) } }) } @@ -88,13 +87,13 @@ func BenchmarkZapSugarAddingFields(b *testing.B) { b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { - logger.Info("Go fast.", fakeSugarFields()...) + logger.InfoWith("Go fast.", fakeSugarFields()) } }) } func BenchmarkZapSugarWithAccumulatedContext(b *testing.B) { - logger := newSugarLogger(zap.DebugLevel).With(fakeSugarFields()...) + logger := newSugarLogger(zap.DebugLevel, zap.Fields(fakeFields()...)) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { diff --git a/level.go b/level.go index c858af866..3e55a9f38 100644 --- a/level.go +++ b/level.go @@ -39,8 +39,8 @@ const ( // ErrorLevel logs are high-priority. If an application is running smoothly, // it shouldn't generate any error-level logs. ErrorLevel = zapcore.ErrorLevel - // DPanicLevel logs are particularly important errors. In development the - // logger panics after writing the message. + // DPanicLevel logs are particularly important errors. In development mode, + // the logger panics after writing the message. DPanicLevel = zapcore.DPanicLevel // PanicLevel logs a message, then panics. PanicLevel = zapcore.PanicLevel diff --git a/sugar.go b/sugar.go index e92f0e551..95debe46b 100644 --- a/sugar.go +++ b/sugar.go @@ -26,10 +26,12 @@ import ( "go.uber.org/zap/zapcore" ) -const _oddNumberErrMsg = "Passed an odd number of keys and values to SugaredLogger, ignoring last." +// A Ctx is a loosely-typed collection of structured log fields. It's a simple +// alias to reduce the wordiness of log sites. +type Ctx map[string]interface{} -// A SugaredLogger wraps the core Logger functionality in a slower, but less -// verbose, API. +// A SugaredLogger wraps the core Logger functionality in a slightly slower, +// but less verbose, API. type SugaredLogger struct { core Logger } @@ -46,169 +48,171 @@ func Desugar(s *SugaredLogger) Logger { return s.core } -// With adds a variadic number of key-value pairs to the logging context. -// Even-indexed arguments are treated as keys, and are converted to strings -// (with fmt.Sprint) if necessary. The keys are then zipped with the -// odd-indexed values into typed fields using the Any field constructor. +// With adds a loosely-typed collection of key-value pairs to the logging +// context. // // For example, -// sugaredLogger.With( -// "hello", "world", -// "failure", errors.New("oh no"), -// "count", 42, -// "user", User{name: "alice"}, -// ) -// is the equivalent of -// coreLogger.With( +// sugaredLogger.With(zap.Ctx{ +// "hello": "world", +// "count": 42, +// "user": User{name: "alice"}, +// }) +// is equivalent to +// logger.With( // String("hello", "world"), -// String("failure", "oh no"), // Int("count", 42), -// Object("user", User{name: "alice"}), +// Any("user", User{name: "alice"}), // ) -func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger { - return s.WithFields(s.sweetenFields(args)...) +func (s *SugaredLogger) With(fields Ctx) *SugaredLogger { + return &SugaredLogger{core: s.core.With(s.sweeten(fields)...)} } -// WithFields adds structured fields to the logger's context, just like the -// standard Logger's With method. -func (s *SugaredLogger) WithFields(fs ...zapcore.Field) *SugaredLogger { - return &SugaredLogger{core: s.core.With(fs...)} +// Debug logs a message, along with any context accumulated on the logger, at +// DebugLevel. +func (s *SugaredLogger) Debug(msg string) { + s.log(DebugLevel, msg, nil) } -// 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{}) { - if ce := s.core.Check(DebugLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// DebugWith adds to the logger's context, then logs a message and the combined +// context at DebugLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).Debug(msg). +func (s *SugaredLogger) DebugWith(msg string, fields Ctx) { + s.log(DebugLevel, msg, fields) } -// Debugf uses fmt.Sprintf to construct a dynamic message and logs it at -// DebugLevel. It doesn't add to the message's structured context. +// Debugf uses fmt.Sprintf to construct a templated message, then passes it to +// Debug. func (s *SugaredLogger) Debugf(template string, args ...interface{}) { - if ce := s.core.Check(DebugLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } + s.Debug(fmt.Sprintf(template, args...)) } -// 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{}) { - if ce := s.core.Check(InfoLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// Info logs a message, along with any context accumulated on the logger, at +// InfoLevel. +func (s *SugaredLogger) Info(msg string) { + s.log(InfoLevel, msg, nil) +} + +// InfoWith adds to the logger's context, then logs a message and the combined +// context at InfoLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).Info(msg). +func (s *SugaredLogger) InfoWith(msg string, fields Ctx) { + s.log(InfoLevel, msg, fields) } -// Infof uses fmt.Sprintf to construct a dynamic message and logs it at -// InfoLevel. It doesn't add to the message's structured context. +// Infof uses fmt.Sprintf to construct a templated message, then passes it to +// Info. func (s *SugaredLogger) Infof(template string, args ...interface{}) { - if ce := s.core.Check(InfoLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } + s.Info(fmt.Sprintf(template, args...)) } -// 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{}) { - if ce := s.core.Check(WarnLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// Warn logs a message, along with any context accumulated on the logger, at +// WarnLevel. +func (s *SugaredLogger) Warn(msg string) { + s.log(WarnLevel, msg, nil) +} + +// WarnWith adds to the logger's context, then logs a message and the combined +// context at WarnLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).Warn(msg). +func (s *SugaredLogger) WarnWith(msg string, fields Ctx) { + s.log(WarnLevel, msg, fields) } -// Warnf uses fmt.Sprintf to construct a dynamic message and logs it at -// WarnLevel. It doesn't add to the message's structured context. +// Warnf uses fmt.Sprintf to construct a templated message, then passes it to +// Warn. func (s *SugaredLogger) Warnf(template string, args ...interface{}) { - if ce := s.core.Check(WarnLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } + s.Warn(fmt.Sprintf(template, args...)) } -// 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{}) { - if ce := s.core.Check(ErrorLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// Error logs a message, along with any context accumulated on the logger, at +// ErrorLevel. +func (s *SugaredLogger) Error(msg string) { + s.log(ErrorLevel, msg, nil) +} + +// ErrorWith adds to the logger's context, then logs a message and the combined +// context at ErrorLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).Error(msg). +func (s *SugaredLogger) ErrorWith(msg string, fields Ctx) { + s.log(ErrorLevel, msg, fields) } -// Errorf uses fmt.Sprintf to construct a dynamic message and logs it at -// ErrorLevel. It doesn't add to the message's structured context. +// Errorf uses fmt.Sprintf to construct a templated message, then passes it to +// Error. func (s *SugaredLogger) Errorf(template string, args ...interface{}) { - if ce := s.core.Check(ErrorLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } + s.Error(fmt.Sprintf(template, args...)) } -// 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{}) { - if ce := s.core.Check(DPanicLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// DPanic logs a message, along with any context accumulated on the logger, at +// DPanicLevel. +func (s *SugaredLogger) DPanic(msg string) { + s.log(DPanicLevel, msg, nil) +} + +// DPanicWith adds to the logger's context, then logs a message and the combined +// context at DPanicLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).DPanic(msg). +func (s *SugaredLogger) DPanicWith(msg string, fields Ctx) { + s.log(DPanicLevel, msg, fields) } -// 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. +// DPanicf uses fmt.Sprintf to construct a templated message, then passes it to +// DPanic. func (s *SugaredLogger) DPanicf(template string, args ...interface{}) { - if ce := s.core.Check(DPanicLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } + s.DPanic(fmt.Sprintf(template, args...)) } -// 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{}) { - if ce := s.core.Check(PanicLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// Panic logs a message, along with any context accumulated on the logger, at +// PanicLevel. +func (s *SugaredLogger) Panic(msg string) { + s.log(PanicLevel, msg, nil) +} + +// PanicWith adds to the logger's context, then logs a message and the combined +// context at PanicLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).Panic(msg). +func (s *SugaredLogger) PanicWith(msg string, fields Ctx) { + s.log(PanicLevel, msg, fields) } -// 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. +// Panicf uses fmt.Sprintf to construct a templated message, then passes it to +// Panic. func (s *SugaredLogger) Panicf(template string, args ...interface{}) { - if ce := s.core.Check(PanicLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } + s.Panic(fmt.Sprintf(template, args...)) } -// 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{}) { - if ce := s.core.Check(FatalLevel, sweetenMsg(msg)); ce != nil { - ce.Write(s.sweetenFields(keysAndValues)...) - } +// Fatal logs a message, along with any context accumulated on the logger, at +// FatalLevel. +func (s *SugaredLogger) Fatal(msg string) { + s.log(FatalLevel, msg, 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. -func (s *SugaredLogger) Fatalf(template string, args ...interface{}) { - if ce := s.core.Check(FatalLevel, fmt.Sprintf(template, args...)); ce != nil { - ce.Write() - } +// FatalWith adds to the logger's context, then logs a message and the combined +// context at FatalLevel. For context that's only relevant at one log site, +// it's faster than logger.With(ctx).Fatal(msg). +func (s *SugaredLogger) FatalWith(msg string, fields Ctx) { + s.log(FatalLevel, msg, fields) } -func (s *SugaredLogger) sweetenFields(args []interface{}) []zapcore.Field { - if len(args) == 0 { - return nil - } - if len(args)%2 == 1 { - s.core.DPanic(_oddNumberErrMsg, Any("ignored", args[len(args)-1])) - } +// Fatalf uses fmt.Sprintf to construct a templated message, then passes it to +// Fatal. +func (s *SugaredLogger) Fatalf(template string, args ...interface{}) { + s.Fatal(fmt.Sprintf(template, args...)) +} - fields := make([]zapcore.Field, len(args)/2) - for i := range fields { - key := sweetenMsg(args[2*i]) - fields[i] = Any(key, args[2*i+1]) +func (s *SugaredLogger) log(lvl zapcore.Level, msg string, fields Ctx) { + if ce := s.core.Check(lvl, msg); ce != nil { + ce.Write(s.sweeten(fields)...) } - return fields } -func sweetenMsg(msg interface{}) string { - if str, ok := msg.(string); ok { - return str +func (s *SugaredLogger) sweeten(fields Ctx) []zapcore.Field { + if len(fields) == 0 { + return nil + } + fs := make([]zapcore.Field, 0, len(fields)) + for key := range fields { + fs = append(fs, Any(key, fields[key])) } - return fmt.Sprint(msg) + return fs } diff --git a/sugar_bench_test.go b/sugar_bench_test.go index 68da6dc8e..2f5e47ce8 100644 --- a/sugar_bench_test.go +++ b/sugar_bench_test.go @@ -42,17 +42,17 @@ 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.", - "one", 1, - "two", 2, - "three", 3, - "four", 4, - "five", 5, - "six", 6, - "seven", 7, - "eight", 8, - "nine", 9, - "ten", 10, - ) + logger.InfoWith("Ten fields.", Ctx{ + "one": 1, + "two": 2, + "three": 3, + "four": 4, + "five": 5, + "six": 6, + "seven": 7, + "eight": 8, + "nine": 9, + "ten": 10, + }) }) } diff --git a/sugar_test.go b/sugar_test.go index 3273273aa..79abf6441 100644 --- a/sugar_test.go +++ b/sugar_test.go @@ -21,6 +21,7 @@ package zap import ( + "sort" "testing" "github.com/stretchr/testify/assert" @@ -30,52 +31,31 @@ import ( "go.uber.org/zap/zapcore" ) -func TestSugarWith(t *testing.T) { - ignored := observer.LoggedEntry{ - Entry: zapcore.Entry{Level: DPanicLevel, Message: _oddNumberErrMsg}, - Context: []zapcore.Field{Any("ignored", "should ignore")}, - } +type sortedFields []zapcore.Field + +func (sf sortedFields) Len() int { return len(sf) } +func (sf sortedFields) Less(i, j int) bool { return sf[i].Key < sf[j].Key } +func (sf sortedFields) Swap(i, j int) { sf[i], sf[j] = sf[j], sf[i] } +func TestSugarWith(t *testing.T) { tests := []struct { - args []interface{} + ctx Ctx expected []zapcore.Field }{ {nil, []zapcore.Field{}}, - {[]interface{}{}, []zapcore.Field{}}, - {[]interface{}{"foo", 42, true, "bar"}, []zapcore.Field{Int("foo", 42), String("true", "bar")}}, + {Ctx{}, []zapcore.Field{}}, + {Ctx{"foo": 42, "bar": "baz"}, []zapcore.Field{Int("foo", 42), String("bar", "baz")}}, } for _, tt := range tests { withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { - logger.With(tt.args...).Info("") + logger.With(tt.ctx).Info("") output := logs.AllUntimed() assert.Equal(t, 1, len(output), "Expected only one message to be logged.") + sort.Sort(sortedFields(tt.expected)) + sort.Sort(sortedFields(output[0].Context)) 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.") - }) - } -} - -func TestSugarWithFields(t *testing.T) { - tests := [][]zapcore.Field{ - {}, - {String("foo", "bar"), Int("baz", 42)}, - } - for _, fields := range tests { - withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { - logger.WithFields(fields...).Info("") - output := logs.AllUntimed() - assert.Equal(t, 1, len(output), "Expected only one message to be logged.") - assert.Equal(t, fields, output[0].Context, "Unexpected message context.") - }) } } @@ -83,42 +63,40 @@ type stringerF func() string func (f stringerF) String() string { return f() } -func TestSugarStructuredLogging(t *testing.T) { - tests := []struct { - msg interface{} - 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)} - - 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...) - - 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.expectMsg, Level: lvl}, - Context: expectedFields, - } +func TestSugarUntemplatedLogging(t *testing.T) { + context := Ctx{"foo": "bar"} + extra := Ctx{"baz": "quux"} + expectedCtx := []zapcore.Field{String("foo", "bar")} + expectedCtxExtra := []zapcore.Field{String("foo", "bar"), String("baz", "quux")} + + withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { + logger.With(context).Debug("msg") + logger.With(context).DebugWith("msg", extra) + logger.With(context).Info("msg") + logger.With(context).InfoWith("msg", extra) + logger.With(context).Warn("msg") + logger.With(context).WarnWith("msg", extra) + logger.With(context).Error("msg") + logger.With(context).ErrorWith("msg", extra) + logger.With(context).DPanic("msg") + logger.With(context).DPanicWith("msg", extra) + + expectedLogs := make([]observer.LoggedEntry, 10) + for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { + expectedLogs[i*2] = observer.LoggedEntry{ + Entry: zapcore.Entry{Message: "msg", Level: lvl}, + Context: expectedCtx, } - assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") - }) - } + expectedLogs[i*2+1] = observer.LoggedEntry{ + Entry: zapcore.Entry{Message: "msg", Level: lvl}, + Context: expectedCtxExtra, + } + } + assert.Equal(t, expectedLogs, logs.AllUntimed(), "Unexpected log output.") + }) } -func TestSugarFormattedLogging(t *testing.T) { +func TestSugarTemplatedLogging(t *testing.T) { tests := []struct { format string args []interface{} @@ -130,16 +108,16 @@ func TestSugarFormattedLogging(t *testing.T) { } // Common to all test cases. - context := []interface{}{"foo", "bar"} + context := Ctx{"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...).Debugf(tt.format, tt.args...) - logger.With(context...).Infof(tt.format, tt.args...) - logger.With(context...).Warnf(tt.format, tt.args...) - logger.With(context...).Errorf(tt.format, tt.args...) - logger.With(context...).DPanicf(tt.format, tt.args...) + logger.With(context).Debugf(tt.format, tt.args...) + logger.With(context).Infof(tt.format, tt.args...) + logger.With(context).Warnf(tt.format, tt.args...) + logger.With(context).Errorf(tt.format, tt.args...) + logger.With(context).DPanicf(tt.format, tt.args...) expected := make([]observer.LoggedEntry, 5) for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { @@ -165,6 +143,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.PanicWith("foo", nil) }, ""}, + {PanicLevel, func(s *SugaredLogger) { s.PanicWith("foo", nil) }, "foo"}, + {DebugLevel, func(s *SugaredLogger) { s.PanicWith("foo", nil) }, "foo"}, } for _, tt := range tests { @@ -194,6 +175,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.FatalWith("foo", nil) }, ""}, + {FatalLevel, func(s *SugaredLogger) { s.FatalWith("foo", nil) }, "foo"}, + {DebugLevel, func(s *SugaredLogger) { s.FatalWith("foo", nil) }, "foo"}, } for _, tt := range tests { From 989ecab5842368cb63429b46d5ceb7bf163c18e4 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Tue, 17 Jan 2017 15:40:46 -0800 Subject: [PATCH 31/31] Keep skip level constant --- sugar.go | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/sugar.go b/sugar.go index 95debe46b..1573db76f 100644 --- a/sugar.go +++ b/sugar.go @@ -83,7 +83,7 @@ func (s *SugaredLogger) DebugWith(msg string, fields Ctx) { // Debugf uses fmt.Sprintf to construct a templated message, then passes it to // Debug. func (s *SugaredLogger) Debugf(template string, args ...interface{}) { - s.Debug(fmt.Sprintf(template, args...)) + s.log(DebugLevel, fmt.Sprintf(template, args...), nil) } // Info logs a message, along with any context accumulated on the logger, at @@ -102,7 +102,7 @@ func (s *SugaredLogger) InfoWith(msg string, fields Ctx) { // Infof uses fmt.Sprintf to construct a templated message, then passes it to // Info. func (s *SugaredLogger) Infof(template string, args ...interface{}) { - s.Info(fmt.Sprintf(template, args...)) + s.log(InfoLevel, fmt.Sprintf(template, args...), nil) } // Warn logs a message, along with any context accumulated on the logger, at @@ -121,7 +121,7 @@ func (s *SugaredLogger) WarnWith(msg string, fields Ctx) { // Warnf uses fmt.Sprintf to construct a templated message, then passes it to // Warn. func (s *SugaredLogger) Warnf(template string, args ...interface{}) { - s.Warn(fmt.Sprintf(template, args...)) + s.log(WarnLevel, fmt.Sprintf(template, args...), nil) } // Error logs a message, along with any context accumulated on the logger, at @@ -140,7 +140,7 @@ func (s *SugaredLogger) ErrorWith(msg string, fields Ctx) { // Errorf uses fmt.Sprintf to construct a templated message, then passes it to // Error. func (s *SugaredLogger) Errorf(template string, args ...interface{}) { - s.Error(fmt.Sprintf(template, args...)) + s.log(ErrorLevel, fmt.Sprintf(template, args...), nil) } // DPanic logs a message, along with any context accumulated on the logger, at @@ -159,7 +159,7 @@ func (s *SugaredLogger) DPanicWith(msg string, fields Ctx) { // DPanicf uses fmt.Sprintf to construct a templated message, then passes it to // DPanic. func (s *SugaredLogger) DPanicf(template string, args ...interface{}) { - s.DPanic(fmt.Sprintf(template, args...)) + s.log(DPanicLevel, fmt.Sprintf(template, args...), nil) } // Panic logs a message, along with any context accumulated on the logger, at @@ -178,7 +178,7 @@ func (s *SugaredLogger) PanicWith(msg string, fields Ctx) { // Panicf uses fmt.Sprintf to construct a templated message, then passes it to // Panic. func (s *SugaredLogger) Panicf(template string, args ...interface{}) { - s.Panic(fmt.Sprintf(template, args...)) + s.log(PanicLevel, fmt.Sprintf(template, args...), nil) } // Fatal logs a message, along with any context accumulated on the logger, at @@ -197,7 +197,7 @@ func (s *SugaredLogger) FatalWith(msg string, fields Ctx) { // Fatalf uses fmt.Sprintf to construct a templated message, then passes it to // Fatal. func (s *SugaredLogger) Fatalf(template string, args ...interface{}) { - s.Fatal(fmt.Sprintf(template, args...)) + s.log(FatalLevel, fmt.Sprintf(template, args...), nil) } func (s *SugaredLogger) log(lvl zapcore.Level, msg string, fields Ctx) {