From f9a34fd4ddd26824e4653d1f473c5709f2c21bd8 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Tue, 26 Jul 2016 10:16:45 -0700 Subject: [PATCH] Clean up hooks and logger config (#102) * Add a constructor for no-op fields Add a constructor so that users can also create no-op fields. I considered calling this `Nop`, but `zap.Nop()` looks like it should return a logger instead of a Field. * Clean up hooks and logger boilerplate Reduce boilerplate by introducing an Entry struct and pulling common logger elements into a Config struct (that can be shared between Logger implementations). Along the way, start logging timestamps as floating-point seconds since epoch. * Address CR feedback * Add tests, clarify comments --- encoder.go | 8 ++-- entry.go | 62 +++++++++++++++++++++++++++++ entry_test.go | 23 +++++++++++ field.go | 11 ++++-- field_test.go | 6 +++ hook.go | 45 +++++++++++++-------- hook_test.go | 15 +++++++ json_encoder.go | 37 ++++++++++++------ json_encoder_bench_test.go | 3 +- json_encoder_test.go | 34 ++++++++++++---- logger.go | 69 ++++++++++---------------------- logger_test.go | 2 +- meta.go | 80 ++++++++++++++++++++++++++++++++++++++ options.go | 28 ++++++------- spy/logger.go | 49 +++++------------------ time.go | 28 +++++++++++++ time_test.go | 42 ++++++++++++++++++++ zwrap/sample_test.go | 2 +- 18 files changed, 395 insertions(+), 149 deletions(-) create mode 100644 entry.go create mode 100644 entry_test.go create mode 100644 meta.go create mode 100644 time.go create mode 100644 time_test.go diff --git a/encoder.go b/encoder.go index d149f22a0..d90e6b613 100644 --- a/encoder.go +++ b/encoder.go @@ -20,17 +20,15 @@ package zap -import ( - "io" - "time" -) +import "io" // encoder is a format-agnostic interface for all log field encoders. It's not // safe for concurrent use. type encoder interface { KeyValue + AddFields([]Field) Clone() encoder Free() - WriteMessage(io.Writer, string, string, time.Time) error + WriteEntry(io.Writer, *Entry) error } diff --git a/entry.go b/entry.go new file mode 100644 index 000000000..405ec8aa2 --- /dev/null +++ b/entry.go @@ -0,0 +1,62 @@ +// 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 ( + "sync" + "time" +) + +var ( + _timeNow = time.Now // for tests + _entryPool = sync.Pool{New: func() interface{} { return &Entry{} }} +) + +// An Entry represents a complete log message. The entry's structured context +// is already serialized, but the log level, time, and message are available +// for inspection and modification. +// +// Entries are pooled, so any functions that accept them must be careful not to +// retain references to them. +type Entry struct { + Level Level + Time time.Time + Message string + enc encoder +} + +func newEntry(lvl Level, msg string, enc encoder) *Entry { + e := _entryPool.Get().(*Entry) + e.Level = lvl + e.Message = msg + e.Time = _timeNow().UTC() + e.enc = enc + return e +} + +// Fields returns a mutable reference to the entry's accumulated context. +func (e *Entry) Fields() KeyValue { + return e.enc +} + +func (e *Entry) free() { + _entryPool.Put(e) +} diff --git a/entry_test.go b/entry_test.go new file mode 100644 index 000000000..6b39ebe61 --- /dev/null +++ b/entry_test.go @@ -0,0 +1,23 @@ +package zap + +import ( + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func stubNow(afterEpoch time.Duration) func() { + prev := _timeNow + t := time.Unix(0, int64(afterEpoch)) + _timeNow = func() time.Time { return t } + return func() { _timeNow = prev } +} + +func TestNewEntry(t *testing.T) { + defer stubNow(0)() + e := newEntry(DebugLevel, "hello", nil) + assert.Equal(t, DebugLevel, e.Level, "Unexpected log level.") + assert.Equal(t, time.Unix(0, 0).UTC(), e.Time, "Unexpected time.") + assert.Nil(t, e.Fields(), "Unexpected fields.") +} diff --git a/field.go b/field.go index ad46530d7..ecbb7b3b5 100644 --- a/field.go +++ b/field.go @@ -52,6 +52,11 @@ type Field struct { obj interface{} } +// Skip constructs a no-op Field. +func Skip() Field { + return Field{fieldType: skipType} +} + // Bool constructs a Field with the given key and value. func Bool(key string, val bool) Field { var ival int64 @@ -91,9 +96,9 @@ func Stringer(key string, val fmt.Stringer) Field { } // Time constructs a Field with the given key and value. It represents a -// time.Time as nanoseconds since epoch. +// time.Time as a floating-point number of seconds since epoch. func Time(key string, val time.Time) Field { - return Int64(key, val.UnixNano()) + return Float64(key, timeToSeconds(val)) } // Error constructs a Field that stores err.Error() under the key "error". This is @@ -101,7 +106,7 @@ func Time(key string, val time.Time) Field { // keystrokes, it's no different from using zap.String. func Error(err error) Field { if err == nil { - return Field{fieldType: skipType} + return Skip() } return String("error", err.Error()) } diff --git a/field_test.go b/field_test.go index 7f3d54a57..1d9924adb 100644 --- a/field_test.go +++ b/field_test.go @@ -81,6 +81,11 @@ func assertCanBeReused(t testing.TB, field Field) { wg.Wait() } +func TestSkipField(t *testing.T) { + assertFieldJSON(t, ``, Skip()) + assertCanBeReused(t, Skip()) +} + func TestTrueBoolField(t *testing.T) { assertFieldJSON(t, `"foo":true`, Bool("foo", true)) assertCanBeReused(t, Bool("foo", true)) @@ -124,6 +129,7 @@ func TestStringerField(t *testing.T) { func TestTimeField(t *testing.T) { assertFieldJSON(t, `"foo":0`, Time("foo", time.Unix(0, 0))) + assertFieldJSON(t, `"foo":1.5`, Time("foo", time.Unix(1, int64(500*time.Millisecond)))) assertCanBeReused(t, Time("foo", time.Unix(0, 0))) } diff --git a/hook.go b/hook.go index e29e5c0dc..c39bdaf4d 100644 --- a/hook.go +++ b/hook.go @@ -27,27 +27,34 @@ import ( "strconv" ) -// Skip Caller, Logger.log, and the leveled Logger method when using -// runtime.Caller. -var _callerSkip = 3 +var ( + errHookNilEntry = errors.New("can't call a hook on a nil *Entry") + errCaller = errors.New("failed to get caller") + // Skip Caller, Logger.log, and the leveled Logger method when using + // runtime.Caller. + _callerSkip = 3 +) -// A hook is executed each time the Logger writes a message. It receives the -// message's priority, the message itself, and the logging context, and it -// returns a modified message and an error. -type hook func(Level, string, KeyValue) (string, error) +// A hook is executed each time the logger writes an Entry. It can modify the +// entry, but must not retain references to the entry or any of its +// contents. Returned errors are written to the logger's error output. +type hook func(*Entry) error // apply implements the Option interface. -func (h hook) apply(jl *jsonLogger) { - jl.hooks = append(jl.hooks, h) +func (h hook) apply(m *Meta) { + m.Hooks = append(m.Hooks, h) } // AddCaller configures the Logger to annotate each message with the filename // and line number of zap's caller. func AddCaller() Option { - return hook(func(_ Level, msg string, _ KeyValue) (string, error) { + return hook(func(e *Entry) error { + if e == nil { + return errHookNilEntry + } _, filename, line, ok := runtime.Caller(_callerSkip) if !ok { - return msg, errors.New("failed to get caller") + return errCaller } // Re-use a buffer from the pool. @@ -57,11 +64,12 @@ func AddCaller() Option { buf = append(buf, ':') buf = strconv.AppendInt(buf, int64(line), 10) buf = append(buf, ':', ' ') - buf = append(buf, msg...) + buf = append(buf, e.Message...) newMsg := string(buf) enc.Free() - return newMsg, nil + e.Message = newMsg + return nil }) } @@ -69,10 +77,13 @@ func AddCaller() Option { // or above a given level. Keep in mind that this is (relatively speaking) quite // expensive. func AddStacks(lvl Level) Option { - return hook(func(msgLevel Level, msg string, kv KeyValue) (string, error) { - if msgLevel >= lvl { - Stack().AddTo(kv) + return hook(func(e *Entry) error { + if e == nil { + return errHookNilEntry + } + if e.Level >= lvl { + Stack().AddTo(e.Fields()) } - return msg, nil + return nil }) } diff --git a/hook_test.go b/hook_test.go index b8e264f14..9375c957d 100644 --- a/hook_test.go +++ b/hook_test.go @@ -68,3 +68,18 @@ func TestHookAddStacks(t *testing.T) { logger.Debug("No stacks.") assert.NotContains(t, buf.String(), "Unexpected stacktrace at Debug level.") } + +func TestHooksNilEntry(t *testing.T) { + tests := []struct { + name string + hook hook + }{ + {"AddStacks", AddStacks(InfoLevel).(hook)}, + {"AddCaller", AddCaller().(hook)}, + } + for _, tt := range tests { + assert.NotPanics(t, func() { + assert.Equal(t, errHookNilEntry, tt.hook(nil), "Expected an error running hook %s on a nil message.", tt.name) + }, "Unexpected panic running hook %s on a nil message.", tt.name) + } +} diff --git a/json_encoder.go b/json_encoder.go index c0ecdb46f..c3183a2e9 100644 --- a/json_encoder.go +++ b/json_encoder.go @@ -22,12 +22,12 @@ package zap import ( "encoding/json" + "errors" "fmt" "io" "math" "strconv" "sync" - "time" "unicode/utf8" ) @@ -38,14 +38,19 @@ const ( _initialBufSize = 1024 ) -var jsonPool = sync.Pool{ - New: func() interface{} { +var ( + // errNilEntry signals that Encoder.WriteEntry was called with a nil *Entry. + errNilEntry = errors.New("can't encode a nil *Entry") + // errNilSink signals that Encoder.WriteEntry was called with a nil WriteSyncer. + errNilSink = errors.New("can't write encoded message a nil WriteSyncer") + + jsonPool = sync.Pool{New: func() interface{} { return &jsonEncoder{ // Pre-allocate a reasonably-sized buffer for each encoder. bytes: make([]byte, 0, _initialBufSize), } - }, -} + }} +) // jsonEncoder is a logging-optimized JSON encoder. type jsonEncoder struct { @@ -151,24 +156,32 @@ func (enc *jsonEncoder) AddFields(fields []Field) { addFields(enc, fields) } -// WriteMessage writes a complete log message to the supplied writer, including +// WriteEntry writes a complete log message to the supplied writer, including // the encoder's accumulated fields. It doesn't modify or lock the encoder's // underlying byte slice. It's safe to call from multiple goroutines, but it's -// not safe to call CreateMessage while adding fields. -func (enc *jsonEncoder) WriteMessage(sink io.Writer, lvl string, msg string, ts time.Time) error { +// not safe to call WriteEntry while adding fields. +func (enc *jsonEncoder) WriteEntry(sink io.Writer, e *Entry) error { + if sink == nil { + return errNilSink + } + if e == nil { + return errNilEntry + } // Grab an encoder from the pool so that we can re-use the underlying // buffer. final := newJSONEncoder() defer final.Free() final.bytes = append(final.bytes, `{"msg":"`...) - final.safeAddString(msg) + final.safeAddString(e.Message) final.bytes = append(final.bytes, `","level":"`...) - final.bytes = append(final.bytes, lvl...) + final.bytes = append(final.bytes, e.Level.String()...) final.bytes = append(final.bytes, `","ts":`...) - final.bytes = strconv.AppendInt(final.bytes, ts.UnixNano(), 10) + final.bytes = strconv.AppendFloat(final.bytes, timeToSeconds(e.Time), 'f', -1, 64) final.bytes = append(final.bytes, `,"fields":{`...) - final.bytes = append(final.bytes, enc.bytes...) + if e.enc != nil { + final.bytes = append(final.bytes, e.enc.(*jsonEncoder).bytes...) + } final.bytes = append(final.bytes, "}}\n"...) n, err := sink.Write(final.bytes) diff --git a/json_encoder_bench_test.go b/json_encoder_bench_test.go index e29d559f6..470570e1f 100644 --- a/json_encoder_bench_test.go +++ b/json_encoder_bench_test.go @@ -53,6 +53,7 @@ func BenchmarkLogMarshalerFunc(b *testing.B) { } func BenchmarkZapJSON(b *testing.B) { + e := &Entry{Level: DebugLevel, Message: "fake", Time: time.Unix(0, 0)} b.RunParallel(func(pb *testing.PB) { for pb.Next() { enc := newJSONEncoder() @@ -65,7 +66,7 @@ func BenchmarkZapJSON(b *testing.B) { enc.AddString("string3", "🤔") enc.AddString("string4", "🙊") enc.AddBool("bool", true) - enc.WriteMessage(ioutil.Discard, "debug", "fake", time.Unix(0, 0)) + enc.WriteEntry(ioutil.Discard, e) enc.Free() } }) diff --git a/json_encoder_test.go b/json_encoder_test.go index 719b8b57d..6de153c7d 100644 --- a/json_encoder_test.go +++ b/json_encoder_test.go @@ -125,13 +125,18 @@ func TestJSONAddFloat64(t *testing.T) { }) } -func TestJSONWriteMessage(t *testing.T) { +func TestJSONWriteEntry(t *testing.T) { withJSONEncoder(func(enc *jsonEncoder) { sink := bytes.NewBuffer(nil) + assert.Equal(t, errNilSink, enc.WriteEntry(nil, &Entry{}), "Expected an error writing to a nil sink.") + + assert.Equal(t, errNilEntry, enc.WriteEntry(sink, nil), "Expected an error writing a nil message.") + assert.Equal(t, "", sink.String(), "Unexpected output after writing nil message.") + // Messages should be escaped. - err := enc.WriteMessage(sink, "info", `hello\`, time.Unix(0, 0)) - assert.NoError(t, err, "WriteMessage returned an unexpected error.") + err := enc.WriteEntry(sink, &Entry{Level: InfoLevel, Message: `hello\`, Time: time.Unix(0, 0), enc: enc}) + assert.NoError(t, err, "WriteEntry returned an unexpected error.") assert.Equal(t, `{"msg":"hello\\","level":"info","ts":0,"fields":{"foo":"bar"}}`, strings.TrimRight(sink.String(), "\n"), @@ -140,8 +145,8 @@ func TestJSONWriteMessage(t *testing.T) { // We should be able to re-use the encoder, preserving the accumulated // fields. sink.Reset() - err = enc.WriteMessage(sink, "debug", "fake msg", time.Unix(0, 100)) - assert.NoError(t, err, "WriteMessage returned an unexpected error.") + err = enc.WriteEntry(sink, &Entry{Level: DebugLevel, Message: "fake msg", Time: time.Unix(100, 0), enc: enc}) + assert.NoError(t, err, "WriteEntry returned an unexpected error.") assert.Equal(t, `{"msg":"fake msg","level":"debug","ts":100,"fields":{"foo":"bar"}}`, strings.TrimRight(sink.String(), "\n"), @@ -149,6 +154,21 @@ func TestJSONWriteMessage(t *testing.T) { }) } +func TestJSONWriteEntryLargeTimestamps(t *testing.T) { + // Ensure that we don't switch to exponential notation when encoding dates far in the future. + withJSONEncoder(func(enc *jsonEncoder) { + sink := &bytes.Buffer{} + future := time.Date(2100, time.January, 1, 0, 0, 0, 0, time.UTC) + entry := &Entry{Level: DebugLevel, Message: "fake msg", Time: future, enc: enc} + require.NoError(t, enc.WriteEntry(sink, entry)) + assert.Contains(t, + sink.String(), + `"ts":4102444800,`, + "Expected to encode large timestamps using grade-school notation.", + ) + }) +} + type loggable struct{} func (l loggable) MarshalLog(kv KeyValue) error { @@ -190,7 +210,7 @@ func TestJSONClone(t *testing.T) { assertJSON(t, `"baz":"bing"`, clone.(*jsonEncoder)) } -func TestJSONWriteMessageFailure(t *testing.T) { +func TestJSONWriteEntryFailure(t *testing.T) { withJSONEncoder(func(enc *jsonEncoder) { tests := []struct { sink io.Writer @@ -200,7 +220,7 @@ func TestJSONWriteMessageFailure(t *testing.T) { {spywrite.ShortWriter{}, "Expected an error on partial writes to sink."}, } for _, tt := range tests { - err := enc.WriteMessage(tt.sink, "info", "hello", time.Unix(0, 0)) + err := enc.WriteEntry(tt.sink, &Entry{Level: InfoLevel, Message: "hello", Time: time.Unix(0, 0), enc: enc}) assert.Error(t, err, tt.msg) } }) diff --git a/logger.go b/logger.go index 6a7cfa6f2..63e522044 100644 --- a/logger.go +++ b/logger.go @@ -24,8 +24,6 @@ import ( "fmt" "os" "time" - - "github.com/uber-go/atomic" ) // For tests. @@ -40,6 +38,7 @@ type Logger interface { // 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(...Field) Logger // StubTime stops the logger from including the current time in each @@ -72,13 +71,9 @@ type Logger interface { } type jsonLogger struct { - level *atomic.Int32 - enc encoder - hooks []hook - errW WriteSyncer - w WriteSyncer + *Meta + alwaysEpoch bool - development bool } // NewJSON returns a logger that formats its output as JSON. Zap uses a @@ -90,40 +85,19 @@ type jsonLogger struct { // Options can change the log level, the output location, or the initial // fields that should be added as context. func NewJSON(options ...Option) Logger { - defaultLevel := atomic.NewInt32(int32(InfoLevel)) - jl := &jsonLogger{ - enc: newJSONEncoder(), - level: defaultLevel, - errW: os.Stderr, - w: os.Stdout, - } - + meta := NewMeta() for _, opt := range options { - opt.apply(jl) + opt.apply(meta) } - - return jl -} - -func (jl *jsonLogger) Level() Level { - return Level(jl.level.Load()) -} - -func (jl *jsonLogger) SetLevel(lvl Level) { - jl.level.Store(int32(lvl)) + return &jsonLogger{Meta: meta} } func (jl *jsonLogger) With(fields ...Field) Logger { clone := &jsonLogger{ - level: jl.level, - enc: jl.enc.Clone(), - hooks: jl.hooks, - w: jl.w, - errW: jl.errW, + Meta: jl.Meta.Clone(), alwaysEpoch: jl.alwaysEpoch, - development: jl.development, } - clone.enc.AddFields(fields) + clone.Encoder.AddFields(fields) return clone } @@ -176,7 +150,7 @@ func (jl *jsonLogger) Fatal(msg string, fields ...Field) { } func (jl *jsonLogger) DFatal(msg string, fields ...Field) { - if jl.development { + if jl.Development { jl.Fatal(msg, fields...) } jl.Error(msg, fields...) @@ -187,33 +161,32 @@ func (jl *jsonLogger) log(lvl Level, msg string, fields []Field) { return } - temp := jl.enc.Clone() + temp := jl.Encoder.Clone() temp.AddFields(fields) - for _, hook := range jl.hooks { - newMsg, err := hook(lvl, msg, temp) - if err != nil { + entry := newEntry(lvl, msg, temp) + if jl.alwaysEpoch { + entry.Time = time.Unix(0, 0) + } + for _, hook := range jl.Hooks { + if err := hook(entry); err != nil { jl.internalError(err.Error()) } - msg = newMsg } - now := time.Now().UTC() - if jl.alwaysEpoch { - now = time.Unix(0, 0) - } - if err := temp.WriteMessage(jl.w, lvl.String(), msg, now); err != nil { + if err := temp.WriteEntry(jl.Output, entry); err != nil { jl.internalError(err.Error()) } temp.Free() + entry.free() if lvl > ErrorLevel { // Sync on Panic and Fatal, since they may crash the program. - jl.w.Sync() + jl.Output.Sync() } } func (jl *jsonLogger) internalError(msg string) { - fmt.Fprintln(jl.errW, msg) - jl.errW.Sync() + fmt.Fprintln(jl.ErrorOutput, msg) + jl.ErrorOutput.Sync() } diff --git a/logger_test.go b/logger_test.go index 087017c70..1b21127b9 100644 --- a/logger_test.go +++ b/logger_test.go @@ -235,7 +235,7 @@ func TestJSONLoggerNoOpsDisabledLevels(t *testing.T) { }) } -func TestJSONLoggerWriteMessageFailure(t *testing.T) { +func TestJSONLoggerWriteEntryFailure(t *testing.T) { errBuf := &bytes.Buffer{} errSink := &spywrite.WriteSyncer{Writer: errBuf} logger := NewJSON(DebugLevel, Output(AddSync(spywrite.FailWriter{})), ErrorOutput(errSink)) diff --git a/meta.go b/meta.go new file mode 100644 index 000000000..c048dacaa --- /dev/null +++ b/meta.go @@ -0,0 +1,80 @@ +// 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 ( + "os" + + "github.com/uber-go/atomic" +) + +// Meta is implementation-agnostic state management for Loggers. Most Logger +// implementations can reduce the required boilerplate by embedding a *Meta. +// +// Note that while the level-related fields and methods are safe for concurrent +// use, the remaining fields are not. +// +// TODO: Consider better names for this before releasing 1.0. +type Meta struct { + Development bool + Encoder encoder + Hooks []hook + Output WriteSyncer + ErrorOutput WriteSyncer + + lvl *atomic.Int32 +} + +// NewMeta returns a new meta struct with sensible defaults: logging at +// InfoLevel, a JSON encoder, development mode off, and writing to standard error +// and standard out. +func NewMeta() *Meta { + return &Meta{ + lvl: atomic.NewInt32(int32(InfoLevel)), + Encoder: newJSONEncoder(), + Output: os.Stdout, + ErrorOutput: os.Stderr, + } +} + +// Level returns the minimum enabled log level. It's safe to call concurrently. +func (m *Meta) Level() Level { + return Level(m.lvl.Load()) +} + +// SetLevel atomically alters the the logging level for this configuration and +// all its clones. +func (m *Meta) SetLevel(lvl Level) { + m.lvl.Store(int32(lvl)) +} + +// Clone creates a copy of the meta struct. It deep-copies the encoder, but +// not the hooks (since they rarely change). +func (m *Meta) Clone() *Meta { + return &Meta{ + lvl: m.lvl, + Encoder: m.Encoder.Clone(), + Development: m.Development, + Output: m.Output, + ErrorOutput: m.ErrorOutput, + Hooks: m.Hooks, + } +} diff --git a/options.go b/options.go index 2afadb64e..cfb35cae9 100644 --- a/options.go +++ b/options.go @@ -22,46 +22,46 @@ package zap // Option is used to set options for the logger. type Option interface { - apply(*jsonLogger) + apply(*Meta) } // optionFunc wraps a func so it satisfies the Option interface. -type optionFunc func(*jsonLogger) +type optionFunc func(*Meta) -func (f optionFunc) apply(jl *jsonLogger) { - f(jl) +func (f optionFunc) apply(m *Meta) { + f(m) } // This allows any Level to be used as an option. -func (l Level) apply(jl *jsonLogger) { - jl.SetLevel(l) +func (l Level) apply(m *Meta) { + m.SetLevel(l) } // Fields sets the initial fields for the logger. func Fields(fields ...Field) Option { - return optionFunc(func(jl *jsonLogger) { - jl.enc.AddFields(fields) + return optionFunc(func(m *Meta) { + m.Encoder.AddFields(fields) }) } // Output sets the destination for the logger's output. func Output(w WriteSyncer) Option { - return optionFunc(func(jl *jsonLogger) { - jl.w = w + return optionFunc(func(m *Meta) { + m.Output = w }) } // ErrorOutput sets the destination for errors generated by the logger. func ErrorOutput(w WriteSyncer) Option { - return optionFunc(func(jl *jsonLogger) { - jl.errW = w + return optionFunc(func(m *Meta) { + m.ErrorOutput = w }) } // Development puts the logger in development mode, which alters the behavior // of the DFatal method. func Development() Option { - return optionFunc(func(jl *jsonLogger) { - jl.development = true + return optionFunc(func(m *Meta) { + m.Development = true }) } diff --git a/spy/logger.go b/spy/logger.go index be591dece..cf85aeb3d 100644 --- a/spy/logger.go +++ b/spy/logger.go @@ -64,56 +64,30 @@ func (s *Sink) Logs() []Log { // Logger satisfies zap.Logger, but makes testing convenient. type Logger struct { sync.Mutex + *zap.Meta - level zap.Level - sink *Sink - context []zap.Field - development bool + sink *Sink + context []zap.Field } // New returns a new spy logger at the default level and its sink. func New() (*Logger, *Sink) { s := &Sink{} return &Logger{ - // Use the same defaults as the core logger. - level: zap.NewJSON().Level(), - sink: s, + Meta: zap.NewMeta(), + sink: s, }, s } // StubTime is a no-op, since the spy logger omits time entirely. func (l *Logger) StubTime() {} -// SetDevelopment sets the development flag. -func (l *Logger) SetDevelopment(dev bool) { - l.Lock() - l.development = dev - l.Unlock() -} - -// Level returns the currently-enabled logging level. -func (l *Logger) Level() zap.Level { - l.Lock() - defer l.Unlock() - - return l.level -} - -// SetLevel alters the enabled log level. -func (l *Logger) SetLevel(new zap.Level) { - l.Lock() - defer l.Unlock() - - l.level = new -} - // With creates a new Logger with additional fields added to the logging context. func (l *Logger) With(fields ...zap.Field) zap.Logger { return &Logger{ - level: l.level, - sink: l.sink, - context: append(l.context, fields...), - development: l.development, + Meta: l.Meta.Clone(), + sink: l.sink, + context: append(l.context, fields...), } } @@ -138,39 +112,34 @@ func (l *Logger) Debug(msg string, fields ...zap.Field) { // Info logs at the Info level. func (l *Logger) Info(msg string, fields ...zap.Field) { l.sink.WriteLog(zap.InfoLevel, msg, l.allFields(fields)) - } // Warn logs at the Warn level. func (l *Logger) Warn(msg string, fields ...zap.Field) { l.sink.WriteLog(zap.WarnLevel, msg, l.allFields(fields)) - } // Error logs at the Error level. func (l *Logger) Error(msg string, fields ...zap.Field) { l.sink.WriteLog(zap.ErrorLevel, msg, l.allFields(fields)) - } // Panic logs at the Panic level. Note that the spy Logger doesn't actually // panic. func (l *Logger) Panic(msg string, fields ...zap.Field) { l.sink.WriteLog(zap.PanicLevel, msg, l.allFields(fields)) - } // Fatal logs at the Fatal level. Note that the spy logger doesn't actuall call // os.Exit. func (l *Logger) Fatal(msg string, fields ...zap.Field) { l.sink.WriteLog(zap.FatalLevel, msg, l.allFields(fields)) - } // DFatal logs at the Fatal level if the development flag is set, and the Fatal // level otherwise. func (l *Logger) DFatal(msg string, fields ...zap.Field) { - if l.development { + if l.Development { l.sink.WriteLog(zap.FatalLevel, msg, l.allFields(fields)) } else { l.sink.WriteLog(zap.ErrorLevel, msg, l.allFields(fields)) diff --git a/time.go b/time.go new file mode 100644 index 000000000..00b1700f0 --- /dev/null +++ b/time.go @@ -0,0 +1,28 @@ +// 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 "time" + +func timeToSeconds(t time.Time) float64 { + nanos := float64(t.UnixNano()) + return nanos / float64(time.Second) +} diff --git a/time_test.go b/time_test.go new file mode 100644 index 000000000..c7f9d9150 --- /dev/null +++ b/time_test.go @@ -0,0 +1,42 @@ +// 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" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestTimeToSeconds(t *testing.T) { + tests := []struct { + t time.Time + stamp float64 + }{ + {t: time.Unix(0, 0), stamp: 0}, + {t: time.Unix(1, 0), stamp: 1}, + {t: time.Unix(1, int64(500*time.Millisecond)), stamp: 1.5}, + } + for _, tt := range tests { + assert.Equal(t, tt.stamp, timeToSeconds(tt.t), "Unexpected timestamp for time %v.", tt.t) + } +} diff --git a/zwrap/sample_test.go b/zwrap/sample_test.go index 349d984ff..91e77492b 100644 --- a/zwrap/sample_test.go +++ b/zwrap/sample_test.go @@ -39,7 +39,7 @@ func WithIter(l zap.Logger, n int) zap.Logger { func fakeSampler(tick time.Duration, first, thereafter int, development bool) (zap.Logger, *spy.Sink) { base, sink := spy.New() base.SetLevel(zap.DebugLevel) - base.SetDevelopment(development) + base.Development = development sampler := Sample(base, tick, first, thereafter) return sampler, sink }