Skip to content

Commit

Permalink
Add WithLazy Logger method (#1319)
Browse files Browse the repository at this point in the history 
As per internal Uber discussion

---------

Co-authored-by: Abhinav Gupta <mail@abhinavg.net>
  • Loading branch information
@jquirke @abhinav
jquirke and abhinav authored Sep 14, 2023
1 parent 99f1811 commit c17272e
Show file tree
Hide file tree
Showing 5 changed files with 480 additions and 49 deletions.
22 changes: 22 additions & 0 deletions logger.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -185,6 +185,28 @@ func (log *Logger) With(fields ...Field) *Logger {
return l
}

// WithLazy creates a child logger and adds structured context to it lazily.
//
// The fields are evaluated only if the logger is further chained with [With]
// or is written to with any of the log level methods.
// Until that occurs, the logger may retain references to objects inside the fields,
// and logging will reflect the state of an object at the time of logging,
// not the time of WithLazy().
//
// WithLazy provides a worthwhile performance optimization for contextual loggers
// when the likelihood of using the child logger is low,
// such as error paths and rarely taken branches.
//
// Similar to [With], 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
View file
Original file line number Diff line number Diff line change
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, withMethod 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 = withMethod(log, String(keys[i], values[i]))
}
if use {
log.Info("used")
Expand Down
284 changes: 239 additions & 45 deletions logger_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,8 @@ package zap

import (
"errors"
"fmt"
"strconv"
"sync"
"sync/atomic"
"testing"
Expand Down Expand Up @@ -124,58 +126,250 @@ 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.")
})
tests := []struct {
name string
initialFields []Field
withMethod func(*Logger, ...Field) *Logger
}{
{
"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,
},
}
for _, tt := range tests {
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.withMethod(logger).Info("")
tt.withMethod(logger, String("one", "two")).Info("")
tt.withMethod(logger, String("three", "four")).Info("")
tt.withMethod(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",
})
type withF func(*Logger, ...Field) *Logger
tests := []struct {
name string
withMethods []withF
wantJSON []string
}{
{
name: "regular with captures arguments at time of With",
withMethods: []withF{(*Logger).With},
wantJSON: []string{
`{
"m": "hello 0",
"a0": [0],
"b0": [1]
}`,
`{
"m": "world 0",
"a0": [0],
"c0": [2]
}`,
},
},
{
name: "lazy with captures arguments at time of With or Logging",
withMethods: []withF{(*Logger).WithLazy},
wantJSON: []string{
`{
"m": "hello 0",
"a0": [1],
"b0": [1]
}`,
`{
"m": "world 0",
"a0": [1],
"c0": [2]
}`,
},
},
{
name: "2x With captures arguments at time of each With",
withMethods: []withF{(*Logger).With, (*Logger).With},
wantJSON: []string{
`{
"m": "hello 0",
"a0": [0],
"b0": [1]
}`,
`{
"m": "world 0",
"a0": [0],
"c0": [2]
}`,
`{
"m": "hello 1",
"a0": [0],
"c0": [2],
"a1": [10],
"b1": [11]
}`,
`{
"m": "world 1",
"a0": [0],
"c0": [2],
"a1": [10],
"c1": [12]
}`,
},
},
{
name: "2x WithLazy. Captures arguments only at logging time.",
withMethods: []withF{(*Logger).WithLazy, (*Logger).WithLazy},
wantJSON: []string{
`{
"m": "hello 0",
"a0": [1],
"b0": [1]
}`,
`{
"m": "world 0",
"a0": [1],
"c0": [2]
}`,
`{
"m": "hello 1",
"a0": [1],
"c0": [2],
"a1": [11],
"b1": [11]
}`,
`{
"m": "world 1",
"a0": [1],
"c0": [2],
"a1": [11],
"c1": [12]
}`,
},
},
{
name: "WithLazy then With",
withMethods: []withF{(*Logger).WithLazy, (*Logger).With},
wantJSON: []string{
`{
"m": "hello 0",
"a0": [1],
"b0": [1]
}`,
`{
"m": "world 0",
"a0": [1],
"c0": [2]
}`,
`{
"m": "hello 1",
"a0": [1],
"c0": [2],
"a1": [10],
"b1": [11]
}`,
`{
"m": "world 1",
"a0": [1],
"c0": [2],
"a1": [10],
"c1": [12]
}`,
},
},
{
name: "With then WithLazy",
withMethods: []withF{(*Logger).With, (*Logger).WithLazy},
wantJSON: []string{
`{
"m": "hello 0",
"a0": [0],
"b0": [1]
}`,
`{
"m": "world 0",
"a0": [0],
"c0": [2]
}`,
`{
"m": "hello 1",
"a0": [0],
"c0": [2],
"a1": [11],
"b1": [11]
}`,
`{
"m": "world 1",
"a0": [0],
"c0": [2],
"a1": [11],
"c1": [12]
}`,
},
},
}

var bs ztest.Buffer
logger := New(zapcore.NewCore(enc, &bs, DebugLevel))
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{
MessageKey: "m",
})

x := 0
arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error {
enc.AppendInt(x)
return nil
})
var bs ztest.Buffer
logger := New(zapcore.NewCore(enc, &bs, DebugLevel))

for i, withMethod := range tt.withMethods {

iStr := strconv.Itoa(i)
x := 10 * i
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 = withMethod(logger, Array("a"+iStr, arr))
x++
logger.Info(fmt.Sprintf("hello %d", i), Array("b"+iStr, arr))
x++
logger = withMethod(logger, Array("c"+iStr, arr))
logger.Info(fmt.Sprintf("world %d", i))
}

// 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.")
if lines := bs.Lines(); assert.Len(t, lines, len(tt.wantJSON)) {
for i, want := range tt.wantJSON {
assert.JSONEq(t, want, lines[i], "Unexpected output from the %d'th log.", i)
}
}
})
}
}

Expand Down
Loading

0 comments on commit c17272e

Please sign in to comment.