uber-go / zap

Blazing fast, structured, leveled logging in Go.
https://pkg.go.dev/go.uber.org/zap
MIT License
22.05k stars 1.44k forks source link

Race using WithLazy #1426

Open markuspeloquin opened 7 months ago

markuspeloquin commented 7 months ago

Describe the bug A race exists in the WithLazy implementation. lazyWithCore's own methods are protected from it, but since Core is embedded, methods from Core (in this case, Enabled()) do an unsynchronized read.

https://github.com/uber-go/zap/blob/fcf8ee58669e358bbd6460bef5c2ee7a53c0803a/zapcore/lazy_with.go#L41-L43

The trace below is for v1.27.0.

==================
WARNING: DATA RACE
Read at 0x00c0092f6d80 by goroutine 29644:
  go.uber.org/zap/zapcore.(*lazyWithCore).Enabled()
      <autogenerated>:1 +0x35
  go.uber.org/zap/zapcore.(*lazyWithCore).Enabled()
      <autogenerated>:1 +0x4c
  go.uber.org/zap.(*Logger).check()
      [...]/go.uber.org/zap/logger.go:331 +0x90
  go.uber.org/zap.(*Logger).Error()
      [...]/go.uber.org/zap/logger.go:262 +0x4e
  [...]

Previous write at 0x00c0092f6d80 by goroutine 29645:
  go.uber.org/zap/zapcore.(*lazyWithCore).With.(*lazyWithCore).initOnce.func1()
      [...]/go.uber.org/zap/zapcore/lazy_with.go:42 +0x91
  sync.(*Once).doSlow()
      /home/markusp/.local/go1.22.1/src/sync/once.go:74 +0xf0
  sync.(*Once).Do()
      /home/markusp/.local/go1.22.1/src/sync/once.go:65 +0x44
  go.uber.org/zap/zapcore.(*lazyWithCore).initOnce()
      [...]/go.uber.org/zap/zapcore/lazy_with.go:41 +0x77
  go.uber.org/zap/zapcore.(*lazyWithCore).With()
      [...]/go.uber.org/zap/zapcore/lazy_with.go:47 +0x30
  go.uber.org/zap/zapcore.(*lazyWithCore).Check.(*lazyWithCore).initOnce.func1()
      [...]/go.uber.org/zap/zapcore/lazy_with.go:42 +0x7d
  sync.(*Once).doSlow()
      /home/markusp/.local/go1.22.1/src/sync/once.go:74 +0xf0
  sync.(*Once).Do()
      /home/markusp/.local/go1.22.1/src/sync/once.go:65 +0x44
  go.uber.org/zap/zapcore.(*lazyWithCore).initOnce()
      [...]/go.uber.org/zap/zapcore/lazy_with.go:41 +0x92
  go.uber.org/zap/zapcore.(*lazyWithCore).Check()
      [...]/go.uber.org/zap/zapcore/lazy_with.go:52 +0x3a
  go.uber.org/zap.(*Logger).check()
      [...]/go.uber.org/zap/logger.go:343 +0x21e
  go.uber.org/zap.(*Logger).Error()
      [...]/go.uber.org/zap/logger.go:262 +0x4e
  [...]
==================

To Reproduce Create a logger using WithLazy, then use it in multiple goroutines in parallel.

Expected behavior No race.

Additional context Personally I would fix by replacing the embedded Core with an atomic.Pointer (as gross as these are for holding interfaces).

type lazyWithCore struct {
    corePtr atomic.Pointer[Core]
    once sync.Once
    fields []Field
}
func NewLazyWith(core Core, fields []Field) Core {
    d := lazyWithCore{fields: fields}
    d.corePtr.Store(&core)
    return d
}
func (d *lazyWithCore) initOnce() Core { // Returning Core here to avoid a repeated Load and to contain the ugliness
    core := *d.corePtr.Load()
    d.once.Do(func() {
        core = core.With(d.fields)
        d.corePtr.Store(&core)
    })
    return core
}
func (d *lazyWithCore) Enabled() bool {
    // Init not needed
    return (*d.corePtr.Load()).Enabled()
}
func (d *lazyWithCore) Sync() error {
    // Init needed
    return d.initOnce().Sync()
}
markuspeloquin commented 7 months ago

Original implementation from #1319.

@jquirke @abhinav

jquirke commented 7 months ago

Thanks for raising this. I agree atomic load and store are one solution, but a more elegant pattern might be to just return a new Core as has been suggested before, and avoid that torn interface assignment