From b602393473ac8ddceb9c3de308643414f8d2b531 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Thu, 24 Oct 2024 01:01:25 -0400 Subject: [PATCH 1/2] 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 From 4f9e4dc0165e3a7d818f2933c80aaa9c2097b3c5 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Thu, 24 Oct 2024 01:31:21 -0400 Subject: [PATCH 2/2] ref: remove unused deduper log wrapper methods I used these wrapper methods during initial development of the custom handler that the deduper now implements. Since the deduper implements slog.Handler and can be used directly as a logger, these wrapper methods are no longer needed. Signed-off-by: TJ Hoplock --- util/logging/dedupe.go | 24 ------------------------ 1 file changed, 24 deletions(-) diff --git a/util/logging/dedupe.go b/util/logging/dedupe.go index b08b80a853..d5aee5c095 100644 --- a/util/logging/dedupe.go +++ b/util/logging/dedupe.go @@ -104,30 +104,6 @@ func (d *Deduper) WithGroup(name string) slog.Handler { } } -// Info logs the provided message and key-value arguments using the Deduper's -// internal slog.Logger. It is simply a wrapper around slog.Logger.Info(). -func (d *Deduper) Info(msg string, args ...any) { - d.next.Info(msg, args...) -} - -// Warn logs the provided message and key-value arguments using the Deduper's -// internal slog.Logger. It is simply a wrapper around slog.Logger.Warn(). -func (d *Deduper) Warn(msg string, args ...any) { - d.next.Warn(msg, args...) -} - -// Error logs the provided message and key-value arguments using the Deduper's -// internal slog.Logger. It is simply a wrapper around slog.Logger.Error(). -func (d *Deduper) Error(msg string, args ...any) { - d.next.Error(msg, args...) -} - -// Debug logs the provided message and key-value arguments using the Deduper's -// internal slog.Logger. It is simply a wrapper around slog.Logger.Debug(). -func (d *Deduper) Debug(msg string, args ...any) { - d.next.Debug(msg, args...) -} - // Stop the Deduper. func (d *Deduper) Stop() { close(d.quit)