fix: avoid data race in log deduper

This change should have been included in the initial prometheus slog
conversion, but I must've lost track of it in all the rebases involved
in that PR.

This changes the dedupe logger so that the only method that needs to use
the lock is the `Handle()` method that actually interacts with the
deduplication map.

Ex:
```
==================
WARNING: DATA RACE
Write at 0x00c000518bc0 by goroutine 29481:
  github.com/prometheus/prometheus/util/logging.(*Deduper).WithAttrs()
      /home/tjhop/go/src/github.com/prometheus/prometheus/util/logging/dedupe.go:89 +0xef
  log/slog.(*Logger).With()
      /home/tjhop/.asdf/installs/golang/1.23.1/go/src/log/slog/logger.go:132 +0x106
  github.com/prometheus/prometheus/storage/remote.NewQueueManager()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/queue_manager.go:483 +0x7a9
  github.com/prometheus/prometheus/storage/remote.(*WriteStorage).ApplyConfig()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/write.go:201 +0x102c
  github.com/prometheus/prometheus/storage/remote.(*Storage).ApplyConfig()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage.go:92 +0xfd
  github.com/prometheus/prometheus/storage/remote.TestWriteStorageApplyConfigsDuringCommit.func1()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage_test.go:172 +0x3e4
  github.com/prometheus/prometheus/storage/remote.TestWriteStorageApplyConfigsDuringCommit.gowrap1()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage_test.go:174 +0x41

Previous read at 0x00c000518bc0 by goroutine 31261:
  github.com/prometheus/prometheus/util/logging.(*Deduper).Handle()
      /home/tjhop/go/src/github.com/prometheus/prometheus/util/logging/dedupe.go:82 +0x2b1
  log/slog.(*Logger).log()
      /home/tjhop/.asdf/installs/golang/1.23.1/go/src/log/slog/logger.go:257 +0x228
  log/slog.(*Logger).Error()
      /home/tjhop/.asdf/installs/golang/1.23.1/go/src/log/slog/logger.go:230 +0x3d4
  github.com/prometheus/prometheus/tsdb/wlog.(*Watcher).loop()
      /home/tjhop/go/src/github.com/prometheus/prometheus/tsdb/wlog/watcher.go:254 +0x2db
  github.com/prometheus/prometheus/tsdb/wlog.(*Watcher).Start.gowrap1()
      /home/tjhop/go/src/github.com/prometheus/prometheus/tsdb/wlog/watcher.go:227 +0x33

Goroutine 29481 (running) created at:
  github.com/prometheus/prometheus/storage/remote.TestWriteStorageApplyConfigsDuringCommit()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage_test.go:164 +0xe4
  testing.tRunner()
      /home/tjhop/.asdf/installs/golang/1.23.1/go/src/testing/testing.go:1690 +0x226
  testing.(*T).Run.gowrap1()
      /home/tjhop/.asdf/installs/golang/1.23.1/go/src/testing/testing.go:1743 +0x44

Goroutine 31261 (running) created at:
  github.com/prometheus/prometheus/tsdb/wlog.(*Watcher).Start()
      /home/tjhop/go/src/github.com/prometheus/prometheus/tsdb/wlog/watcher.go:227 +0x177
  github.com/prometheus/prometheus/storage/remote.(*QueueManager).Start()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/queue_manager.go:934 +0x304
  github.com/prometheus/prometheus/storage/remote.(*WriteStorage).ApplyConfig()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/write.go:232 +0x151b
  github.com/prometheus/prometheus/storage/remote.(*Storage).ApplyConfig()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage.go:92 +0xfd
  github.com/prometheus/prometheus/storage/remote.TestWriteStorageApplyConfigsDuringCommit.func1()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage_test.go:172 +0x3e4
  github.com/prometheus/prometheus/storage/remote.TestWriteStorageApplyConfigsDuringCommit.gowrap1()
      /home/tjhop/go/src/github.com/prometheus/prometheus/storage/remote/storage_test.go:174 +0x41
==================
--- FAIL: TestWriteStorageApplyConfigsDuringCommit (2.26s)
    testing.go:1399: race detected during execution of test
FAIL
FAIL    github.com/prometheus/prometheus/storage/remote 68.321s
```

Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
This commit is contained in:
TJ Hoplock 2024-10-24 01:01:25 -04:00
parent 3cb09acb21
commit b602393473

View file

@ -51,11 +51,7 @@ func Dedupe(next *slog.Logger, repeat time.Duration) *Deduper {
// provided context and log level, and returns false otherwise. It implements
// slog.Handler.
func (d *Deduper) Enabled(ctx context.Context, level slog.Level) bool {
d.mtx.RLock()
enabled := d.next.Enabled(ctx, level)
d.mtx.RUnlock()
return enabled
return d.next.Enabled(ctx, level)
}
// Handle uses the provided context and slog.Record to deduplicate messages
@ -85,19 +81,27 @@ func (d *Deduper) Handle(ctx context.Context, r slog.Record) error {
// WithAttrs adds the provided attributes to the Deduper's internal
// slog.Logger. It implements slog.Handler.
func (d *Deduper) WithAttrs(attrs []slog.Attr) slog.Handler {
d.mtx.Lock()
d.next = slog.New(d.next.Handler().WithAttrs(attrs))
d.mtx.Unlock()
return d
return &Deduper{
next: slog.New(d.next.Handler().WithAttrs(attrs)),
repeat: d.repeat,
quit: d.quit,
seen: d.seen,
}
}
// WithGroup adds the provided group name to the Deduper's internal
// slog.Logger. It implements slog.Handler.
func (d *Deduper) WithGroup(name string) slog.Handler {
d.mtx.Lock()
d.next = slog.New(d.next.Handler().WithGroup(name))
d.mtx.Unlock()
if name == "" {
return d
}
return &Deduper{
next: slog.New(d.next.Handler().WithGroup(name)),
repeat: d.repeat,
quit: d.quit,
seen: d.seen,
}
}
// Info logs the provided message and key-value arguments using the Deduper's