Skip to content

fix: fixed race condition in clone - #11

Open
didiercrunch wants to merge 1 commit into
streamingfast:developfrom
didiercrunch:develop
Open

fix: fixed race condition in clone#11
didiercrunch wants to merge 1 commit into
streamingfast:developfrom
didiercrunch:develop

Conversation

@didiercrunch

Copy link
Copy Markdown

Fix data race in jsonEncoder.clone() due to pooled struct reuse

Problem

go test -race reports a data race inside the encoder under concurrent
zapcore.Encoder.Clone() / EncodeEntry calls, e.g. two goroutines calling
Logger.With(...) on the same base logger while log lines are emitted:

WARNING: DATA RACE
Read at 0x00c000750060 by goroutine 25:
  github.com/streamingfast/logging.(*jsonEncoder).clone()
      encoder.go:550  // clone.EncoderConfig = enc.EncoderConfig
  ...
Previous write at 0x00c000750060 by goroutine 31:
  github.com/streamingfast/logging._jsonPool.New
      encoder.go:281  // return &jsonEncoder{}
  ...

Root cause

jsonEncoder.clone() fetches its receiver from a sync.Pool (_jsonPool)
and then mutates it in place:

clone := getJSONEncoder()          // _jsonPool.Get()
clone.EncoderConfig = enc.EncoderConfig
clone.spaced = enc.spaced
clone.openNamespaces = enc.openNamespaces
clone.buf = bufferpool.Get()
return clone

zapcore.Encoder.Clone() must return a deep, independent copy — zap may hand
the same encoder to several Clone() callers concurrently, and the whole
point of Clone is that the returned encoder is not shared with the source.
Reusing pooled structs breaks that contract: a struct that is still in use
as a live encoder can be handed out again by the pool and mutated, racing
the reads performed by the caller that still holds it.

The upstream zap implementation pools the same struct type, but its
EncodeEntry returns every clone to the pool (putJSONEncoder(final)) in
the same goroutine that created it, so the reuse is tightly paired. Here the
outer Encoder.Clone() allocates a fresh *Encoder anyway, so the inner
pool provides no meaningful allocation win while introducing a shared
mutable state hazard.

Fix

Allocate a fresh *jsonEncoder in clone() and drop the now-unused
getJSONEncoder():

func (enc *jsonEncoder) clone() *jsonEncoder {
	clone := &jsonEncoder{}
	clone.EncoderConfig = enc.EncoderConfig
	clone.spaced = enc.spaced
	clone.openNamespaces = enc.openNamespaces
	clone.buf = bufferpool.Get()
	return clone
}

The buffer pool (bufferpool) is untouched: each clone still gets its own
buffer via bufferpool.Get(), which is safe.

Verification

  • go test -race ./... passes (added TestEncoderConcurrentWithAndLog,
    which hammers Logger.With + log emission from 8 goroutines on a shared
    base logger).
  • Repro: without the fix, -race flags the _jsonPool.New / clone()
    race under that pattern (and in a downstream consumer doing concurrent
    .With() + log emission).

Comment thread encoder.go
}}

func getJSONEncoder() *jsonEncoder {
return _jsonPool.Get().(*jsonEncoder)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this means then that the whole pool is now useless?

Ill need to verify if still used, otherwise we maybe better removing it entierly.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants