prometheus/util/logging/dedupe.go

132 lines
3.2 KiB
Go
Raw Normal View History

// Copyright 2019 The Prometheus Authors
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package logging
import (
"context"
"log/slog"
"sync"
"time"
)
const (
garbageCollectEvery = 10 * time.Second
expireEntriesAfter = 1 * time.Minute
maxEntries = 1024
)
// Deduper implements *slog.Handler, dedupes log lines based on a time duration.
type Deduper struct {
next *slog.Logger
repeat time.Duration
quit chan struct{}
mtx sync.RWMutex
seen map[string]time.Time
}
// Dedupe log lines to next, only repeating every repeat duration.
func Dedupe(next *slog.Logger, repeat time.Duration) *Deduper {
d := &Deduper{
next: next,
repeat: repeat,
quit: make(chan struct{}),
seen: map[string]time.Time{},
}
go d.run()
return d
}
// Enabled returns true if the Deduper's internal slog.Logger is enabled at the
// provided context and log level, and returns false otherwise. It implements
// slog.Handler.
func (d *Deduper) Enabled(ctx context.Context, level slog.Level) bool {
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>
2024-10-23 22:01:25 -07:00
return d.next.Enabled(ctx, level)
}
// Handle uses the provided context and slog.Record to deduplicate messages
// every 1m. Log records received within the interval are not acted on, and
// thus dropped. Log records that pass deduplication and need action invoke the
// Handle() method on the Deduper's internal slog.Logger's handler, effectively
// chaining log calls to the internal slog.Logger.
func (d *Deduper) Handle(ctx context.Context, r slog.Record) error {
line := r.Message
d.mtx.RLock()
last, ok := d.seen[line]
d.mtx.RUnlock()
if ok && time.Since(last) < d.repeat {
return nil
}
d.mtx.Lock()
if len(d.seen) < maxEntries {
d.seen[line] = time.Now()
}
d.mtx.Unlock()
return d.next.Handler().Handle(ctx, r.Clone())
}
// 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 {
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>
2024-10-23 22:01:25 -07:00
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 {
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>
2024-10-23 22:01:25 -07:00
if name == "" {
return d
}
return &Deduper{
next: slog.New(d.next.Handler().WithGroup(name)),
repeat: d.repeat,
quit: d.quit,
seen: d.seen,
}
}
// Stop the Deduper.
func (d *Deduper) Stop() {
close(d.quit)
}
func (d *Deduper) run() {
ticker := time.NewTicker(garbageCollectEvery)
defer ticker.Stop()
for {
select {
case <-ticker.C:
d.mtx.Lock()
now := time.Now()
for line, seen := range d.seen {
if now.Sub(seen) > expireEntriesAfter {
delete(d.seen, line)
}
}
d.mtx.Unlock()
case <-d.quit:
return
}
}
}