diff --git a/logger.go b/logger.go index 9b45b07b0..475a4801e 100644 --- a/logger.go +++ b/logger.go @@ -184,6 +184,23 @@ func (log *Logger) With(fields ...Field) *Logger { return l } +// WithLazy creates a child logger and lazily encodes structured context if the +// child logger is ever further chained with With() or is written to with any +// of the log level methods. Until the occurs, the logger may retain references +// to references in objects, etc, and logging will reflect the state of an object +// at the time of logging, not the time of WithLazy(). However, is a worthwhile +// performance optimisation if one creates a contextual logger and the likelihood +// of using it is low (e.g. in error or rarely taken branches). +// Fields added to the child don't affect the parent, and vice versa. +func (log *Logger) WithLazy(fields ...Field) *Logger { + if len(fields) == 0 { + return log + } + return log.WithOptions(WrapCore(func(core zapcore.Core) zapcore.Core { + return zapcore.NewLazyWith(core, fields) + })) +} + // Level reports the minimum enabled level for this logger. // // For NopLoggers, this is [zapcore.InvalidLevel]. diff --git a/logger_bench_test.go b/logger_bench_test.go index c7207afd5..431cce529 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -199,17 +199,28 @@ func BenchmarkAddCallerAndStacktrace(b *testing.B) { } }) } + func Benchmark5WithsUsed(b *testing.B) { - benchmarkWithUsed(b, 5, true) + benchmarkWithUsed(b, (*Logger).With, 5, true) } // This benchmark will be used in future as a // baseline for improving func Benchmark5WithsNotUsed(b *testing.B) { - benchmarkWithUsed(b, 5, false) + benchmarkWithUsed(b, (*Logger).With, 5, false) +} + +func Benchmark5WithLazysUsed(b *testing.B) { + benchmarkWithUsed(b, (*Logger).WithLazy, 5, true) +} + +// This benchmark will be used in future as a +// baseline for improving +func Benchmark5WithLazysNotUsed(b *testing.B) { + benchmarkWithUsed(b, (*Logger).WithLazy, 5, false) } -func benchmarkWithUsed(b *testing.B, N int, use bool) { +func benchmarkWithUsed(b *testing.B, withMethodExpr func(*Logger, ...zapcore.Field) *Logger, N int, use bool) { keys := make([]string, N) values := make([]string, N) for i := 0; i < N; i++ { @@ -221,7 +232,7 @@ func benchmarkWithUsed(b *testing.B, N int, use bool) { withBenchedLogger(b, func(log *Logger) { for i := 0; i < N; i++ { - log = log.With(String(keys[i], values[i])) + log = withMethodExpr(log, String(keys[i], values[i])) } if use { log.Info("used") diff --git a/logger_test.go b/logger_test.go index 5b1d77b97..43ac2b43b 100644 --- a/logger_test.go +++ b/logger_test.go @@ -125,57 +125,105 @@ func TestLoggerInitialFields(t *testing.T) { func TestLoggerWith(t *testing.T) { fieldOpts := opts(Fields(Int("foo", 42))) - withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) { - // Child loggers should have copy-on-write semantics, so two children - // shouldn't stomp on each other's fields or affect the parent's fields. - logger.With(String("one", "two")).Info("") - logger.With(String("three", "four")).Info("") - logger.With(String("five", "six")).With(String("seven", "eight")).Info("") - logger.Info("") - - assert.Equal(t, []observer.LoggedEntry{ - {Context: []Field{Int("foo", 42), String("one", "two")}}, - {Context: []Field{Int("foo", 42), String("three", "four")}}, - {Context: []Field{Int("foo", 42), String("five", "six"), String("seven", "eight")}}, - {Context: []Field{Int("foo", 42)}}, - }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") - }) + for _, tt := range []struct { + name string + withMethodExpr func(*Logger, ...Field) *Logger + }{ + { + "regular non lazy logger", + (*Logger).With, + }, + { + "lazy with logger", + (*Logger).WithLazy, + }, + } { + t.Run(tt.name, func(t *testing.T) { + withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) { + // Child loggers should have copy-on-write semantics, so two children + // shouldn't stomp on each other's fields or affect the parent's fields. + tt.withMethodExpr(logger, String("one", "two")).Info("") + tt.withMethodExpr(logger, String("three", "four")).Info("") + tt.withMethodExpr(logger, String("five", "six")).With(String("seven", "eight")).Info("") + logger.Info("") + + assert.Equal(t, []observer.LoggedEntry{ + {Context: []Field{Int("foo", 42), String("one", "two")}}, + {Context: []Field{Int("foo", 42), String("three", "four")}}, + {Context: []Field{Int("foo", 42), String("five", "six"), String("seven", "eight")}}, + {Context: []Field{Int("foo", 42)}}, + }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") + }) + }) + } } func TestLoggerWithCaptures(t *testing.T) { - enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{ - MessageKey: "m", - }) + for _, tt := range []struct { + name string + withMethodExpr func(*Logger, ...Field) *Logger + wantJSON [2]string + }{ + { + name: "regular with captures arguments at time of With", + withMethodExpr: (*Logger).With, + wantJSON: [2]string{ + `{ + "m": "hello", + "a": [0], + "b": [1] + }`, + `{ + "m": "world", + "a": [0], + "c": [2] + }`, + }, + }, + { + name: "lazy with captures arguments at time of With or Logging", + withMethodExpr: (*Logger).WithLazy, + wantJSON: [2]string{ + `{ + "m": "hello", + "a": [1], + "b": [1] + }`, + `{ + "m": "world", + "a": [1], + "c": [2] + }`, + }, + }, + } { + t.Run(tt.name, func(t *testing.T) { + enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{ + MessageKey: "m", + }) - var bs ztest.Buffer - logger := New(zapcore.NewCore(enc, &bs, DebugLevel)) + var bs ztest.Buffer + logger := New(zapcore.NewCore(enc, &bs, DebugLevel)) - x := 0 - arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error { - enc.AppendInt(x) - return nil - }) + x := 0 + arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error { + enc.AppendInt(x) + return nil + }) - // Demonstrate the arguments are captured when With() and Info() are invoked. - logger = logger.With(Array("a", arr)) - x = 1 - logger.Info("hello", Array("b", arr)) - x = 2 - logger = logger.With(Array("c", arr)) - logger.Info("world") - - if lines := bs.Lines(); assert.Len(t, lines, 2) { - assert.JSONEq(t, `{ - "m": "hello", - "a": [0], - "b": [1] - }`, lines[0], "Unexpected output from first log.") - - assert.JSONEq(t, `{ - "m": "world", - "a": [0], - "c": [2] - }`, lines[1], "Unexpected output from second log.") + // Demonstrate the arguments are captured when With() and Info() are invoked. + logger = tt.withMethodExpr(logger, Array("a", arr)) + x = 1 + logger.Info("hello", Array("b", arr)) + x = 2 + logger = tt.withMethodExpr(logger, Array("c", arr)) + logger.Info("world") + + if lines := bs.Lines(); assert.Len(t, lines, 2) { + assert.JSONEq(t, tt.wantJSON[0], lines[0], "Unexpected output from first log.") + assert.JSONEq(t, tt.wantJSON[1], lines[1], "Unexpected output from second log.") + } + }) } } diff --git a/zapcore/lazy_with.go b/zapcore/lazy_with.go new file mode 100644 index 000000000..62df8dc26 --- /dev/null +++ b/zapcore/lazy_with.go @@ -0,0 +1,56 @@ +// Copyright (c) 2023 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 zapcore + +import "sync" + +type lazyWithCore struct { + Core + sync.Once + fields []Field +} + +var _ Core = (*lazyWithCore)(nil) + +// NewLazyWith wraps a Core with a "lazy" Core that will only encode fields if +// the logger is written to (or is further chained in a lon-lazy manner). +func NewLazyWith(core Core, fields []Field) Core { + return &lazyWithCore{ + Core: core, + fields: fields, + } +} + +func (d *lazyWithCore) initOnce() { + d.Once.Do(func() { + d.Core = d.Core.With(d.fields) + }) +} + +func (d *lazyWithCore) With(fields []Field) Core { + d.initOnce() + return d.Core.With(fields) +} + +func (d *lazyWithCore) Check(e Entry, ce *CheckedEntry) *CheckedEntry { + d.initOnce() + return d.Core.Check(e, ce) +} diff --git a/zapcore/lazy_with_test.go b/zapcore/lazy_with_test.go new file mode 100644 index 000000000..fca16f36f --- /dev/null +++ b/zapcore/lazy_with_test.go @@ -0,0 +1,149 @@ +// Copyright (c) 2023 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 zapcore_test + +import ( + "sync/atomic" + "testing" + + "github.com/stretchr/testify/assert" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +type proxyCore struct { + zapcore.Core + + withCount atomic.Int64 + checkCount atomic.Int64 +} + +func newProxyCore(inner zapcore.Core) *proxyCore { + return &proxyCore{Core: inner} +} + +func (p *proxyCore) With(fields []zapcore.Field) zapcore.Core { + p.withCount.Add(1) + return p.Core.With(fields) +} + +func (p *proxyCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + p.checkCount.Add(1) + return p.Core.Check(e, ce) +} + +func withLazyCore(f func(zapcore.Core, *proxyCore, *observer.ObservedLogs), initialFields ...zapcore.Field) { + infoLogger, infoLogs := observer.New(zapcore.InfoLevel) + proxyCore := newProxyCore(infoLogger) + lazyCore := zapcore.NewLazyWith(proxyCore, initialFields) + f(lazyCore, proxyCore, infoLogs) +} + +func TestLazyCore(t *testing.T) { + for _, tt := range []struct { + name string + entries []zapcore.Entry + initialFields []zapcore.Field + withChains [][]zapcore.Field + wantLogs []observer.LoggedEntry + }{ + { + name: "no logging, no with, inner core with never called, inner core check never called", + wantLogs: []observer.LoggedEntry{}, + }, + { + name: "2 logs, 1 dropped, no with, inner core with called once, inner core check never called", + entries: []zapcore.Entry{ + {Level: zapcore.DebugLevel, Message: "log-at-debug"}, + {Level: zapcore.WarnLevel, Message: "log-at-warn"}, + }, + wantLogs: []observer.LoggedEntry{ + {Entry: zapcore.Entry{ + Level: zapcore.WarnLevel, + Message: "log-at-warn"}, + Context: []zapcore.Field{}, + }, + }, + }, + { + name: "no logs, 2-chained with, inner core with called once, inner core check never called", + withChains: [][]zapcore.Field{ + {makeInt64Field("a", 11), makeInt64Field("b", 22)}, + {makeInt64Field("c", 33), makeInt64Field("d", 44)}, + }, + wantLogs: []observer.LoggedEntry{}, + }, + { + name: "2 logs, 1 dropped, 2-chained with, inner core with called once, inner core check never called", + entries: []zapcore.Entry{ + {Level: zapcore.DebugLevel, Message: "log-at-debug"}, + {Level: zapcore.WarnLevel, Message: "log-at-warn"}, + }, + withChains: [][]zapcore.Field{ + {makeInt64Field("a", 11), makeInt64Field("b", 22)}, + {makeInt64Field("c", 33), makeInt64Field("d", 44)}, + }, + wantLogs: []observer.LoggedEntry{ + {Entry: zapcore.Entry{ + Level: zapcore.WarnLevel, + Message: "log-at-warn"}, + Context: []zapcore.Field{ + makeInt64Field("a", 11), + makeInt64Field("b", 22), + makeInt64Field("c", 33), + makeInt64Field("d", 44), + }, + }, + }, + }, + } { + t.Run(tt.name, func(t *testing.T) { + withLazyCore(func(lazy zapcore.Core, proxy *proxyCore, logs *observer.ObservedLogs) { + checkCounts := func(withCount int64, msg string) { + assert.Equal(t, withCount, proxy.withCount.Load(), msg) + } + checkCounts(0, "expected no with calls because the logger is not used yet") + + for _, chain := range tt.withChains { + lazy = lazy.With(chain) + } + if len(tt.withChains) > 0 { + checkCounts(1, "expected with calls because the logger was with-chained") + } else { + checkCounts(0, "expected no with calls because the logger is not used yet") + } + + for _, ent := range tt.entries { + if ce := lazy.Check(ent, nil); ce != nil { + ce.Write() + } + } + if len(tt.entries) > 0 || len(tt.withChains) > 0 { + checkCounts(1, "expected with calls because the logger had entries or with chains") + } else { + checkCounts(0, "expected no with calls because the logger is not used yet") + } + assert.Zero(t, proxy.checkCount.Load(), "expected no check calls because the inner core is copied") + assert.Equal(t, tt.wantLogs, logs.AllUntimed()) + }, tt.initialFields...) + }) + } +}