From b602393473ac8ddceb9c3de308643414f8d2b531 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Thu, 24 Oct 2024 01:01:25 -0400 Subject: [PATCH] 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 --- util/logging/dedupe.go | 30 +++++++++++++++++------------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/util/logging/dedupe.go b/util/logging/dedupe.go index 37b345b395..b08b80a853 100644 --- a/util/logging/dedupe.go +++ b/util/logging/dedupe.go @@ -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() - return d + 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