Skip to content

Commit d6b395b

Browse files
authored
Update lazy logger not to materialize unless it's being written to (#1519)
Lazy logger is frequently used to delay (expensive) logger initialization unless we actually write to it. This works for a pattern like: ```golang logger := logger.With(.../*fields) err := foo() if err != nil { logger.Info("foo: %w, err) } ``` Another common pattern, though, is ```golang logger := logger.With(.../*fields) // a lot of code logger.Debug("something happened") // only Info is enabled ``` Here, despite the logs being discarded, we still initialize the logger even though it might be expensive. This diff attempts to mitigate this by using the original core for level checking. This, afaiu, should be safe as `With` is only for field creation, and should not be changing log levels. Preserving the original core to avoid race conditions (torn interfaces) on actual `With` initialization.
1 parent 4b9cea0 commit d6b395b

File tree

2 files changed

+48
-7
lines changed

2 files changed

+48
-7
lines changed

zapcore/lazy_with.go

Lines changed: 14 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,8 @@ package zapcore
2323
import "sync"
2424

2525
type lazyWithCore struct {
26-
core Core
26+
core Core
27+
originalCore Core
2728
sync.Once
2829
fields []Field
2930
}
@@ -32,14 +33,15 @@ type lazyWithCore struct {
3233
// the logger is written to (or is further chained in a lon-lazy manner).
3334
func NewLazyWith(core Core, fields []Field) Core {
3435
return &lazyWithCore{
35-
core: core,
36-
fields: fields,
36+
core: nil, // core is allocated once `initOnce` is called.
37+
originalCore: core,
38+
fields: fields,
3739
}
3840
}
3941

4042
func (d *lazyWithCore) initOnce() {
4143
d.Once.Do(func() {
42-
d.core = d.core.With(d.fields)
44+
d.core = d.originalCore.With(d.fields)
4345
})
4446
}
4547

@@ -49,13 +51,19 @@ func (d *lazyWithCore) With(fields []Field) Core {
4951
}
5052

5153
func (d *lazyWithCore) Check(e Entry, ce *CheckedEntry) *CheckedEntry {
54+
// This is safe because `lazyWithCore` doesn't change the level.
55+
// So we can delagate the level check, any not `initOnce`
56+
// just for the check.
57+
if !d.originalCore.Enabled(e.Level) {
58+
return ce
59+
}
5260
d.initOnce()
5361
return d.core.Check(e, ce)
5462
}
5563

5664
func (d *lazyWithCore) Enabled(level Level) bool {
57-
d.initOnce()
58-
return d.core.Enabled(level)
65+
// Like above, this is safe because `lazyWithCore` doesn't change the level.
66+
return d.originalCore.Enabled(level)
5967
}
6068

6169
func (d *lazyWithCore) Write(e Entry, fields []Field) error {

zapcore/lazy_with_test.go

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,7 @@ func TestLazyCore(t *testing.T) {
6565
initialFields []zapcore.Field
6666
withChains [][]zapcore.Field
6767
wantLogs []observer.LoggedEntry
68+
wantSkipInit bool
6869
}{
6970
{
7071
name: "no logging, no with, inner core with never called, inner core check never called",
@@ -94,6 +95,38 @@ func TestLazyCore(t *testing.T) {
9495
},
9596
wantLogs: []observer.LoggedEntry{},
9697
},
98+
{
99+
name: "1 log, discarded, no-chains, inner core with never called",
100+
entries: []zapcore.Entry{
101+
{Level: zapcore.DebugLevel, Message: "log-at-debug"},
102+
},
103+
initialFields: []zapcore.Field{
104+
makeInt64Field("a", 11), makeInt64Field("b", 22),
105+
},
106+
wantLogs: []observer.LoggedEntry{},
107+
wantSkipInit: true,
108+
},
109+
{
110+
name: "1 log, logged, no-chains, inner core with called",
111+
entries: []zapcore.Entry{
112+
{Level: zapcore.WarnLevel, Message: "log-at-warn"},
113+
},
114+
initialFields: []zapcore.Field{
115+
makeInt64Field("a", 11), makeInt64Field("b", 22),
116+
},
117+
wantLogs: []observer.LoggedEntry{
118+
{
119+
Entry: zapcore.Entry{
120+
Level: zapcore.WarnLevel,
121+
Message: "log-at-warn",
122+
},
123+
Context: []zapcore.Field{
124+
makeInt64Field("a", 11),
125+
makeInt64Field("b", 22),
126+
},
127+
},
128+
},
129+
},
97130
{
98131
name: "2 logs, 1 dropped, 2-chained with, inner core with called once, inner core check never called",
99132
entries: []zapcore.Entry{
@@ -142,7 +175,7 @@ func TestLazyCore(t *testing.T) {
142175
ce.Write()
143176
}
144177
}
145-
if len(tt.entries) > 0 || len(tt.withChains) > 0 {
178+
if !tt.wantSkipInit && (len(tt.entries) > 0 || len(tt.withChains) > 0) {
146179
checkCounts(1, "expected with calls because the logger had entries or with chains")
147180
} else {
148181
checkCounts(0, "expected no with calls because the logger is not used yet")

0 commit comments

Comments
 (0)