Resolves: #15559
As accurately noted in the issue description, the map is shared among
child loggers that get created when `WithAttr()`/`WithGroup()` are
called on the underlying handler, which happens via `log.With()` and
`log.WithGroup()` respectively.
The RW mutex was a value in the previous implementation that used
go-kit/log, and I should've updated it to use a pointer when I converted
the deduper.
Also adds a test.
Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
Resolves: #15433
When I converted prometheus to use slog in #14906, I update both the
`QueryLogger` interface, as well as how the log calls to the
`QueryLogger` were built up in `promql.Engine.exec()`. The backing
logger for the `QueryLogger` in the engine is a
`util/logging.JSONFileLogger`, and it's implementation of the `With()`
method updates the logger the logger in place with the new keyvals added
onto the underlying slog.Logger, which means they get inherited onto
everything after. All subsequent calls to `With()`, even in later
queries, would continue to then append on more and more keyvals for the
various params and fields built up in the logger. In turn, this causes
unbounded growth of the logger, leading to increased memory usage, and
in at least one report was the likely cause of an OOM kill. More
information can be found in the issue and the linked slack thread.
This commit does a few things:
- It was referenced in feedback in #14906 that it would've been better
to not change the `QueryLogger` interface if possible, this PR
proposes changes that bring it closer to alignment with the pre-3.0
`QueryLogger` interface contract
- reverts `promql.Engine.exec()`'s usage of the query logger to the
pattern of building up an array of args to pass at once to the end log
call. Avoiding the repetitious calls to `.With()` are what resolve the
issue with the logger growth/memory usage.
- updates the scrape failure logger to use the update `QueryLogger`
methods in the contract.
- updates tests accordingly
- cleans up unused methods
Builds and passes tests successfully. Tested locally and confirmed I
could no longer reproduce the issue/it resolved the issue.
Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
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 <t.hoplock@gmail.com>
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>
For: #14355
This commit updates Prometheus to adopt stdlib's log/slog package in
favor of go-kit/log. As part of converting to use slog, several other
related changes are required to get prometheus working, including:
- removed unused logging util func `RateLimit()`
- forward ported the util/logging/Deduper logging by implementing a small custom slog.Handler that does the deduping before chaining log calls to the underlying real slog.Logger
- move some of the json file logging functionality to use prom/common package functionality
- refactored some of the new json file logging for scraping
- changes to promql.QueryLogger interface to swap out logging methods for relevant slog sugar wrappers
- updated lots of tests that used/replicated custom logging functionality, attempting to keep the logical goal of the tests consistent after the transition
- added a healthy amount of `if logger == nil { $makeLogger }` type conditional checks amongst various functions where none were provided -- old code that used the go-kit/log.Logger interface had several places where there were nil references when trying to use functions like `With()` to add keyvals on the new *slog.Logger type
Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
We haven't updated golint-ci in our CI yet, but this commit prepares
for that.
There are a lot of new warnings, and it is mostly because the "revive"
linter got updated. I agree with most of the new warnings, mostly
around not naming unused function parameters (although it is justified
in some cases for documentation purposes – while things like mocks are
a good example where not naming the parameter is clearer).
I'm pretty upset about the "empty block" warning to include `for`
loops. It's such a common pattern to do something in the head of the
`for` loop and then have an empty block. There is still an open issue
about this: https://github.com/mgechev/revive/issues/810 I have
disabled "revive" altogether in files where empty blocks are used
excessively, and I have made the effort to add individual
`// nolint:revive` where empty blocks are used just once or twice.
It's borderline noisy, though, but let's go with it for now.
I should mention that none of the "empty block" warnings for `for`
loop bodies were legitimate.
Signed-off-by: beorn7 <beorn@grafana.com>
* refactor: move from io/ioutil to io and os packages
* use fs.DirEntry instead of os.FileInfo after os.ReadDir
Signed-off-by: MOREL Matthieu <matthieu.morel@cnp.fr>
This creates a new `model` directory and moves all data-model related
packages over there:
exemplar labels relabel rulefmt textparse timestamp value
All the others are more or less utilities and have been moved to `util`:
gate logging modetimevfs pool runtime
Signed-off-by: beorn7 <beorn@grafana.com>
