From 03138b5a5afe144b0e4f7c5f6e09da5beb3f1068 Mon Sep 17 00:00:00 2001 From: didier amyot Date: Mon, 3 Aug 2026 13:05:36 -0400 Subject: [PATCH 1/2] fix: fixed race condition in clone --- encoder.go | 6 +----- encoder_concurrency_test.go | 32 ++++++++++++++++++++++++++++++++ 2 files changed, 33 insertions(+), 5 deletions(-) create mode 100644 encoder_concurrency_test.go diff --git a/encoder.go b/encoder.go index 1841d2c..bfa0697 100644 --- a/encoder.go +++ b/encoder.go @@ -281,10 +281,6 @@ var _jsonPool = sync.Pool{New: func() interface{} { return &jsonEncoder{} }} -func getJSONEncoder() *jsonEncoder { - return _jsonPool.Get().(*jsonEncoder) -} - func putJSONEncoder(enc *jsonEncoder) { if enc.reflectBuf != nil { enc.reflectBuf.Free() @@ -546,7 +542,7 @@ func (enc *jsonEncoder) Clone() zapcore.Encoder { } func (enc *jsonEncoder) clone() *jsonEncoder { - clone := getJSONEncoder() + clone := &jsonEncoder{} clone.EncoderConfig = enc.EncoderConfig clone.spaced = enc.spaced clone.openNamespaces = enc.openNamespaces diff --git a/encoder_concurrency_test.go b/encoder_concurrency_test.go new file mode 100644 index 0000000..cdd5dce --- /dev/null +++ b/encoder_concurrency_test.go @@ -0,0 +1,32 @@ +package logging + +import ( + "io" + "sync" + "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// Regression test for a data race in jsonEncoder.clone(): getJSONEncoder() +// hands out a pooled *jsonEncoder that a concurrent clone() call is still +// mutating. Triggered by concurrent Logger.With + log emission on the same +// base logger (the pattern loopagent's Thread.log exercised). Run with -race. +func TestEncoderConcurrentWithAndLog(t *testing.T) { + core := zapcore.NewCore(NewEncoder(1, false), zapcore.AddSync(io.Discard), zap.DebugLevel) + base := zap.New(core).Named("base").With(zap.String("thread_id", "t-1"), zap.String("agent_id", "a-1")) + + var wg sync.WaitGroup + for i := 0; i < 8; i++ { + wg.Add(1) + go func(n int) { + defer wg.Done() + for j := 0; j < 2000; j++ { + derived := base.With(zap.Int("n", n)) + derived.Info("hello", zap.String("j", string(rune(j)))) + } + }(i) + } + wg.Wait() +} From 38ea66c382fc2934e0db36b19e74b858593100e4 Mon Sep 17 00:00:00 2001 From: Matthieu Vachon Date: Sun, 9 Aug 2026 10:01:20 -0400 Subject: [PATCH 2/2] perf: release reflection buffer and drop dead encoder pools The `zap.Any`/`zap.Reflect` reflection buffer was never returned to the buffer pool. Its only release point, `putJSONEncoder`, is unreachable: `Encoder.EncodeEntry` shadows the embedded `jsonEncoder.EncodeEntry`, so that code never runs. Every log line carrying a reflected field therefore allocated a fresh buffer (1451 B/op, 13 allocs/op down to 392 B/op, 11 allocs/op, ~17% faster). For the same reason nothing ever fed `_jsonPool`, so `Get` always fell through to `New` and the pool could not have produced the clone race the previous commit targeted. Allocating explicitly is also measurably cheaper on the `Clone` path, which never hands its encoder back. Remove `_jsonPool`, `_loggerPool`, `putJSONEncoder` and the unused `truncate` / `ptrIntToString` helpers, and release the reflection buffer through a small `free` method instead. The concurrency test now asserts that every entry reaches the syncer and no longer claims to reproduce a race that it does not reproduce. --- CHANGELOG.md | 10 +++++++ core_v2.go | 9 ------ encoder.go | 53 ++++++++++++++++------------------ encoder_concurrency_test.go | 57 +++++++++++++++++++++++++++++++------ 4 files changed, 83 insertions(+), 46 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 5e037f8..661df3f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,16 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## Unreleased + +### Fixed + +* Fixed the reflection buffer used by `zap.Any`/`zap.Reflect` fields never being returned to the buffer pool by the developer-friendly `Encoder`, which made every such log line allocate a fresh 1 KiB buffer (measured 1451 B/op down to 392 B/op, 13 allocs down to 11). + +### Removed + +* Removed the unused `_jsonPool`/`_loggerPool` encoder pools. Nothing ever returned an encoder to them, so they only ever allocated; `jsonEncoder.clone` now allocates directly, which also removes a shared mutable state hazard. No API change. + ## v1.2.2 ### Added diff --git a/core_v2.go b/core_v2.go index aafe032..1806099 100644 --- a/core_v2.go +++ b/core_v2.go @@ -6,7 +6,6 @@ import ( "net/http" "os" "path/filepath" - "strconv" "strings" "time" @@ -698,14 +697,6 @@ func ptrBoolToString(value *bool) string { } } -func ptrIntToString(value *int) string { - if value == nil { - return "" - } - - return strconv.FormatInt(int64(*value), 10) -} - func ptrStringToString(value *string) string { if value == nil { return "" diff --git a/encoder.go b/encoder.go index bfa0697..65d3ed3 100644 --- a/encoder.go +++ b/encoder.go @@ -20,7 +20,6 @@ import ( "math" "path" "strings" - "sync" "time" "unicode/utf8" @@ -41,10 +40,6 @@ var bufferpool = buffer.NewPool() var levelToColor map[zapcore.Level]Color var levelToShort map[zapcore.Level]string -var _loggerPool = sync.Pool{New: func() interface{} { - return &Encoder{} -}} - func init() { levelToColor = make(map[zapcore.Level]Color, 7) levelToColor[zap.DebugLevel] = MagentaFg @@ -243,7 +238,10 @@ func maybeRemovePackageVersion(input string) string { func (c Encoder) writeJSONFields(line *buffer.Buffer, extra []zapcore.Field) { context := c.Clone().(*Encoder) - defer context.buf.Free() + defer func() { + context.buf.Free() + context.free() + }() addFields(context, extra) context.closeOpenNamespaces() @@ -277,23 +275,6 @@ func addFields(enc zapcore.ObjectEncoder, fields []zapcore.Field) { // For JSON-escaping; see jsonEncoder.safeAddString below. const _hex = "0123456789abcdef" -var _jsonPool = sync.Pool{New: func() interface{} { - return &jsonEncoder{} -}} - -func putJSONEncoder(enc *jsonEncoder) { - if enc.reflectBuf != nil { - enc.reflectBuf.Free() - } - enc.EncoderConfig = nil - enc.buf = nil - enc.spaced = false - enc.openNamespaces = 0 - enc.reflectBuf = nil - enc.reflectEnc = nil - _jsonPool.Put(enc) -} - type jsonEncoder struct { *zapcore.EncoderConfig buf *buffer.Buffer @@ -541,6 +522,12 @@ func (enc *jsonEncoder) Clone() zapcore.Encoder { return clone } +// clone allocates a fresh encoder instead of drawing one from a `sync.Pool` like +// upstream zap does. Pooling only pays off when every clone is handed back, and +// most of ours are not: `Encoder.Clone` (through `zapcore.Core.With`) keeps its +// clone alive for the lifetime of the derived logger. Benchmarked, the pool saved +// one 48 byte allocation per log line with no measurable latency change, while +// costing ~33% on the never-returned `Clone` path. Not worth the extra state. func (enc *jsonEncoder) clone() *jsonEncoder { clone := &jsonEncoder{} clone.EncoderConfig = enc.EncoderConfig @@ -550,6 +537,20 @@ func (enc *jsonEncoder) clone() *jsonEncoder { return clone } +// free returns the encoder's lazily allocated reflection buffer to the buffer +// pool. It must be called when a short-lived encoder is discarded, otherwise the +// buffer behind `zap.Any`/`zap.Reflect` fields is never recycled. +// +// The encoder's main `buf` is deliberately left alone: ownership of it is passed +// to the caller in `EncodeEntry`, and callers that keep it free it themselves. +func (enc *jsonEncoder) free() { + if enc.reflectBuf != nil { + enc.reflectBuf.Free() + enc.reflectBuf = nil + enc.reflectEnc = nil + } +} + func (enc *jsonEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) { final := enc.clone() final.buf.AppendByte('{') @@ -616,14 +617,10 @@ func (enc *jsonEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) ( } ret := final.buf - putJSONEncoder(final) + final.free() return ret, nil } -func (enc *jsonEncoder) truncate() { - enc.buf.Reset() -} - func (enc *jsonEncoder) closeOpenNamespaces() { for i := 0; i < enc.openNamespaces; i++ { enc.buf.AppendByte('}') diff --git a/encoder_concurrency_test.go b/encoder_concurrency_test.go index cdd5dce..bc7798e 100644 --- a/encoder_concurrency_test.go +++ b/encoder_concurrency_test.go @@ -1,32 +1,71 @@ package logging import ( - "io" + "strconv" "sync" "testing" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" "go.uber.org/zap" "go.uber.org/zap/zapcore" ) -// Regression test for a data race in jsonEncoder.clone(): getJSONEncoder() -// hands out a pooled *jsonEncoder that a concurrent clone() call is still -// mutating. Triggered by concurrent Logger.With + log emission on the same -// base logger (the pattern loopagent's Thread.log exercised). Run with -race. +// countingSyncer is a `zapcore.WriteSyncer` that only records how many lines it +// received, so the concurrency test can assert nothing was dropped without +// serializing the encoder behind a shared buffer's growth. +type countingSyncer struct { + mu sync.Mutex + lines int + bytes int +} + +func (s *countingSyncer) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + + s.lines++ + s.bytes += len(p) + + return len(p), nil +} + +func (s *countingSyncer) Sync() error { return nil } + +// TestEncoderConcurrentWithAndLog exercises `Encoder.Clone` and +// `Encoder.EncodeEntry` from several goroutines sharing one base logger, which is +// how `zapcore.Core.With` and log emission interleave in practice. +// +// It is a guard against shared mutable state creeping back into the encoder (a +// pooled or otherwise reused `jsonEncoder`), not a reproduction of a known race: +// it passes on the pooled implementation too, because that pool was never fed. +// Meaningful under `-race`. func TestEncoderConcurrentWithAndLog(t *testing.T) { - core := zapcore.NewCore(NewEncoder(1, false), zapcore.AddSync(io.Discard), zap.DebugLevel) + const goroutines = 8 + const iterations = 2000 + + syncer := &countingSyncer{} + core := zapcore.NewCore(NewEncoder(1, false), syncer, zap.DebugLevel) base := zap.New(core).Named("base").With(zap.String("thread_id", "t-1"), zap.String("agent_id", "a-1")) var wg sync.WaitGroup - for i := 0; i < 8; i++ { + for i := range goroutines { wg.Add(1) go func(n int) { defer wg.Done() - for j := 0; j < 2000; j++ { + + for j := range iterations { + // `With` clones the encoder, the log call clones it again while encoding. derived := base.With(zap.Int("n", n)) - derived.Info("hello", zap.String("j", string(rune(j)))) + + // `zap.Any` on a non-primitive goes through the encoder's lazily allocated + // reflection buffer, covering that path too. + derived.Info("hello", zap.String("j", strconv.Itoa(j)), zap.Any("payload", map[string]int{"j": j})) } }(i) } wg.Wait() + + require.Equal(t, goroutines*iterations, syncer.lines, "every log entry should reach the syncer exactly once") + assert.Positive(t, syncer.bytes, "encoded entries should not be empty") }