Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add WithLazy Logger method #1319

Merged
merged 8 commits into from Sep 14, 2023
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
17 changes: 17 additions & 0 deletions logger.go
Expand Up @@ -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].
Expand Down
19 changes: 15 additions & 4 deletions logger_bench_test.go
Expand Up @@ -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++ {
Expand All @@ -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")
Expand Down
153 changes: 108 additions & 45 deletions logger_test.go
Expand Up @@ -124,58 +124,121 @@ 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
initialFields []Field
withMethodExpr func(*Logger, ...Field) *Logger
}{
jquirke marked this conversation as resolved.
Show resolved Hide resolved
{
"regular non lazy logger",
[]Field{Int("foo", 42)},
(*Logger).With,
},
{
"regular non lazy logger no initial fields",
[]Field{},
(*Logger).With,
},
{
"lazy with logger",
[]Field{Int("foo", 42)},
(*Logger).WithLazy,
},
{
"lazy with logger no initial fields",
[]Field{},
(*Logger).WithLazy,
},
} {
t.Run(tt.name, func(t *testing.T) {
withLogger(t, DebugLevel, opts(Fields(tt.initialFields...)), 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).Info("")
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: tt.initialFields},
{Context: append(tt.initialFields, String("one", "two"))},
{Context: append(tt.initialFields, String("three", "four"))},
{Context: append(tt.initialFields, String("five", "six"), String("seven", "eight"))},
{Context: tt.initialFields},
}, 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.")
}
})
}
}

Expand Down
54 changes: 54 additions & 0 deletions zapcore/lazy_with.go
@@ -0,0 +1,54 @@
// 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
}

// 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)
}