From e0104a6b7e8a7250c8b96a7026a633b650013f36 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Sat, 23 Nov 2024 23:30:23 -0500 Subject: [PATCH 1/3] ref: JSONFileLogger slog handler, add scrape.FailureLogger interface Improves upon #15434, better resolves #15433. This commit introduces a few changes to ensure safer handling of the JSONFileLogger: - the JSONFileLogger struct now implements the slog.Handler interface, so it can directly be used to create slog Loggers. This pattern more closely aligns with upstream slog usage (which is generally based around handlers), as well as making it clear that devs are creating a whole new logger when interacting with it (vs silently modifying internal configs like it did previously). - updates the `promql.QueryLogger` interface to be a union of the methods of both the `io.Closer` interface and the `slog.Handler` interface. This allows for plugging in/using slog-compatible loggers other than the JSONFileLogger, if desired (ie, for downstream projects). - introduces new `scrape.FailureLogger` interface; just like `promql.QueryLogger`, it is a union of `io.Closer` and `slog.Handler` interfaces. Similar logic applies to reasoning. - updates tests where needed; have the `FakeQueryLogger` from promql's engine_test implement the `slog.Handler`, improve JSONFileLogger test suite, etc. Signed-off-by: TJ Hoplock --- promql/engine.go | 15 ++++++--- promql/engine_test.go | 44 ++++++++++++++++++++------ scrape/manager.go | 6 ++-- scrape/scrape.go | 27 ++++++++++------ scrape/scrape_test.go | 3 +- util/logging/file.go | 57 +++++++++++++++++++++++++--------- util/logging/file_test.go | 65 +++++++++++++++++++++++---------------- 7 files changed, 148 insertions(+), 69 deletions(-) diff --git a/promql/engine.go b/promql/engine.go index 13f8b06972..2ef0fabe7c 100644 --- a/promql/engine.go +++ b/promql/engine.go @@ -47,6 +47,7 @@ import ( "github.com/prometheus/prometheus/storage" "github.com/prometheus/prometheus/tsdb/chunkenc" "github.com/prometheus/prometheus/util/annotations" + "github.com/prometheus/prometheus/util/logging" "github.com/prometheus/prometheus/util/stats" "github.com/prometheus/prometheus/util/zeropool" ) @@ -123,12 +124,13 @@ type QueryEngine interface { NewRangeQuery(ctx context.Context, q storage.Queryable, opts QueryOpts, qs string, start, end time.Time, interval time.Duration) (Query, error) } +var _ QueryLogger = (*logging.JSONFileLogger)(nil) + // QueryLogger is an interface that can be used to log all the queries logged // by the engine. type QueryLogger interface { - Log(context.Context, slog.Level, string, ...any) - With(args ...any) - Close() error + slog.Handler + io.Closer } // A Query is derived from an a raw query string and can be run against an engine @@ -626,6 +628,9 @@ func (ng *Engine) exec(ctx context.Context, q *query) (v parser.Value, ws annota defer func() { ng.queryLoggerLock.RLock() if l := ng.queryLogger; l != nil { + logger := slog.New(l) + f := make([]any, 0, 16) // Probably enough up front to not need to reallocate on append. + params := make(map[string]interface{}, 4) params["query"] = q.q if eq, ok := q.Statement().(*parser.EvalStmt); ok { @@ -634,7 +639,7 @@ func (ng *Engine) exec(ctx context.Context, q *query) (v parser.Value, ws annota // The step provided by the user is in seconds. params["step"] = int64(eq.Interval / (time.Second / time.Nanosecond)) } - f := []interface{}{"params", params} + f = append(f, "params", params) if err != nil { f = append(f, "error", err) } @@ -647,7 +652,7 @@ func (ng *Engine) exec(ctx context.Context, q *query) (v parser.Value, ws annota f = append(f, k, v) } } - l.Log(context.Background(), slog.LevelInfo, "promql query logged", f...) + logger.Info("promql query logged", f...) // TODO: @tjhop -- do we still need this metric/error log if logger doesn't return errors? // ng.metrics.queryLogFailures.Inc() // ng.logger.Error("can't log query", "err", err) diff --git a/promql/engine_test.go b/promql/engine_test.go index 8b8dc3909c..b8e7cd71c3 100644 --- a/promql/engine_test.go +++ b/promql/engine_test.go @@ -17,6 +17,7 @@ import ( "context" "errors" "fmt" + "io" "log/slog" "math" "sort" @@ -2147,9 +2148,13 @@ func TestSubquerySelector(t *testing.T) { } } +var _ io.Closer = (*FakeQueryLogger)(nil) + +var _ slog.Handler = (*FakeQueryLogger)(nil) + type FakeQueryLogger struct { closed bool - logs []interface{} + logs []any attrs []any } @@ -2161,26 +2166,47 @@ func NewFakeQueryLogger() *FakeQueryLogger { } } -// It implements the promql.QueryLogger interface. func (f *FakeQueryLogger) Close() error { f.closed = true return nil } -// It implements the promql.QueryLogger interface. -func (f *FakeQueryLogger) Log(ctx context.Context, level slog.Level, msg string, args ...any) { +func (f *FakeQueryLogger) Enabled(ctx context.Context, level slog.Level) bool { + return true +} + +func (f *FakeQueryLogger) Handle(ctx context.Context, r slog.Record) error { // Test usage only really cares about existence of keyvals passed in // via args, just append in the log message before handling the // provided args and any embedded kvs added via `.With()` on f.attrs. - log := append([]any{msg}, args...) - log = append(log, f.attrs...) + log := append([]any{r.Message}, f.attrs...) f.attrs = f.attrs[:0] + + r.Attrs(func(a slog.Attr) bool { + log = append(log, a.Key, a.Value.Any()) + return true + }) + f.logs = append(f.logs, log...) + return nil } -// It implements the promql.QueryLogger interface. -func (f *FakeQueryLogger) With(args ...any) { - f.attrs = append(f.attrs, args...) +func (f *FakeQueryLogger) WithAttrs(attrs []slog.Attr) slog.Handler { + attrPairs := []any{} + for _, a := range attrs { + attrPairs = append(attrPairs, a.Key, a.Value.Any()) + } + + return &FakeQueryLogger{ + closed: f.closed, + logs: f.logs, + attrs: append(f.attrs, attrPairs...), + } +} + +func (f *FakeQueryLogger) WithGroup(name string) slog.Handler { + // We don't need to support groups for this fake handler in testing. + return f } func TestQueryLogger_basic(t *testing.T) { diff --git a/scrape/manager.go b/scrape/manager.go index 04da3162e6..5ef5dccb99 100644 --- a/scrape/manager.go +++ b/scrape/manager.go @@ -107,7 +107,7 @@ type Manager struct { scrapeConfigs map[string]*config.ScrapeConfig scrapePools map[string]*scrapePool newScrapeFailureLogger func(string) (*logging.JSONFileLogger, error) - scrapeFailureLoggers map[string]*logging.JSONFileLogger + scrapeFailureLoggers map[string]FailureLogger targetSets map[string][]*targetgroup.Group buffers *pool.Pool @@ -249,7 +249,7 @@ func (m *Manager) ApplyConfig(cfg *config.Config) error { } c := make(map[string]*config.ScrapeConfig) - scrapeFailureLoggers := map[string]*logging.JSONFileLogger{ + scrapeFailureLoggers := map[string]FailureLogger{ "": nil, // Emptying the file name sets the scrape logger to nil. } for _, scfg := range scfgs { @@ -257,7 +257,7 @@ func (m *Manager) ApplyConfig(cfg *config.Config) error { if _, ok := scrapeFailureLoggers[scfg.ScrapeFailureLogFile]; !ok { // We promise to reopen the file on each reload. var ( - logger *logging.JSONFileLogger + logger FailureLogger err error ) if m.newScrapeFailureLogger != nil { diff --git a/scrape/scrape.go b/scrape/scrape.go index eeab208d65..f445e8d2df 100644 --- a/scrape/scrape.go +++ b/scrape/scrape.go @@ -61,6 +61,15 @@ var AlignScrapeTimestamps = true var errNameLabelMandatory = fmt.Errorf("missing metric name (%s label)", labels.MetricName) +var _ FailureLogger = (*logging.JSONFileLogger)(nil) + +// FailureLogger is an interface that can be used to log all failed +// scrapes. +type FailureLogger interface { + slog.Handler + io.Closer +} + // scrapePool manages scrapes for sets of targets. type scrapePool struct { appendable storage.Appendable @@ -90,7 +99,7 @@ type scrapePool struct { metrics *scrapeMetrics - scrapeFailureLogger *logging.JSONFileLogger + scrapeFailureLogger FailureLogger scrapeFailureLoggerMtx sync.RWMutex } @@ -223,11 +232,11 @@ func (sp *scrapePool) DroppedTargetsCount() int { return sp.droppedTargetsCount } -func (sp *scrapePool) SetScrapeFailureLogger(l *logging.JSONFileLogger) { +func (sp *scrapePool) SetScrapeFailureLogger(l FailureLogger) { sp.scrapeFailureLoggerMtx.Lock() defer sp.scrapeFailureLoggerMtx.Unlock() if l != nil { - l.With("job_name", sp.config.JobName) + l = slog.New(l).With("job_name", sp.config.JobName).Handler().(FailureLogger) } sp.scrapeFailureLogger = l @@ -238,7 +247,7 @@ func (sp *scrapePool) SetScrapeFailureLogger(l *logging.JSONFileLogger) { } } -func (sp *scrapePool) getScrapeFailureLogger() *logging.JSONFileLogger { +func (sp *scrapePool) getScrapeFailureLogger() FailureLogger { sp.scrapeFailureLoggerMtx.RLock() defer sp.scrapeFailureLoggerMtx.RUnlock() return sp.scrapeFailureLogger @@ -860,7 +869,7 @@ func (s *targetScraper) readResponse(ctx context.Context, resp *http.Response, w type loop interface { run(errc chan<- error) setForcedError(err error) - setScrapeFailureLogger(*logging.JSONFileLogger) + setScrapeFailureLogger(FailureLogger) stop() getCache() *scrapeCache disableEndOfRunStalenessMarkers() @@ -876,7 +885,7 @@ type cacheEntry struct { type scrapeLoop struct { scraper scraper l *slog.Logger - scrapeFailureLogger *logging.JSONFileLogger + scrapeFailureLogger FailureLogger scrapeFailureLoggerMtx sync.RWMutex cache *scrapeCache lastScrapeSize int @@ -1267,11 +1276,11 @@ func newScrapeLoop(ctx context.Context, return sl } -func (sl *scrapeLoop) setScrapeFailureLogger(l *logging.JSONFileLogger) { +func (sl *scrapeLoop) setScrapeFailureLogger(l FailureLogger) { sl.scrapeFailureLoggerMtx.Lock() defer sl.scrapeFailureLoggerMtx.Unlock() if ts, ok := sl.scraper.(fmt.Stringer); ok && l != nil { - l.With("target", ts.String()) + l = slog.New(l).With("target", ts.String()).Handler().(FailureLogger) } sl.scrapeFailureLogger = l } @@ -1421,7 +1430,7 @@ func (sl *scrapeLoop) scrapeAndReport(last, appendTime time.Time, errc chan<- er sl.l.Debug("Scrape failed", "err", scrapeErr) sl.scrapeFailureLoggerMtx.RLock() if sl.scrapeFailureLogger != nil { - sl.scrapeFailureLogger.Log(context.Background(), slog.LevelError, scrapeErr.Error()) + slog.New(sl.scrapeFailureLogger).Error(scrapeErr.Error()) } sl.scrapeFailureLoggerMtx.RUnlock() if errc != nil { diff --git a/scrape/scrape_test.go b/scrape/scrape_test.go index ce1686feca..571b27086c 100644 --- a/scrape/scrape_test.go +++ b/scrape/scrape_test.go @@ -55,7 +55,6 @@ import ( "github.com/prometheus/prometheus/model/value" "github.com/prometheus/prometheus/storage" "github.com/prometheus/prometheus/tsdb/chunkenc" - "github.com/prometheus/prometheus/util/logging" "github.com/prometheus/prometheus/util/pool" "github.com/prometheus/prometheus/util/teststorage" "github.com/prometheus/prometheus/util/testutil" @@ -252,7 +251,7 @@ type testLoop struct { timeout time.Duration } -func (l *testLoop) setScrapeFailureLogger(*logging.JSONFileLogger) { +func (l *testLoop) setScrapeFailureLogger(FailureLogger) { } func (l *testLoop) run(errc chan<- error) { diff --git a/util/logging/file.go b/util/logging/file.go index 9db7fb722b..27fdec2758 100644 --- a/util/logging/file.go +++ b/util/logging/file.go @@ -16,16 +16,22 @@ package logging import ( "context" "fmt" + "io" "log/slog" "os" "github.com/prometheus/common/promslog" ) -// JSONFileLogger represents a logger that writes JSON to a file. It implements the promql.QueryLogger interface. +var _ slog.Handler = (*JSONFileLogger)(nil) + +var _ io.Closer = (*JSONFileLogger)(nil) + +// JSONFileLogger represents a logger that writes JSON to a file. It implements +// the slog.Handler interface, as well as the io.Closer interface. type JSONFileLogger struct { - logger *slog.Logger - file *os.File + handler slog.Handler + file *os.File } // NewJSONFileLogger returns a new JSONFileLogger. @@ -42,24 +48,47 @@ func NewJSONFileLogger(s string) (*JSONFileLogger, error) { jsonFmt := &promslog.AllowedFormat{} _ = jsonFmt.Set("json") return &JSONFileLogger{ - logger: promslog.New(&promslog.Config{Format: jsonFmt, Writer: f}), - file: f, + handler: promslog.New(&promslog.Config{Format: jsonFmt, Writer: f}).Handler(), + file: f, }, nil } -// Close closes the underlying file. It implements the promql.QueryLogger interface. +// Close closes the underlying file. It implements the io.Closer interface. func (l *JSONFileLogger) Close() error { return l.file.Close() } -// With calls the `With()` method on the underlying `log/slog.Logger` with the -// provided msg and args. It implements the promql.QueryLogger interface. -func (l *JSONFileLogger) With(args ...any) { - l.logger = l.logger.With(args...) +// Enabled returns true if and only if the internal slog.Handler is enabled. It +// implements the slog.Handler interface. +func (l *JSONFileLogger) Enabled(ctx context.Context, level slog.Level) bool { + return l.handler.Enabled(ctx, level) } -// Log calls the `Log()` method on the underlying `log/slog.Logger` with the -// provided msg and args. It implements the promql.QueryLogger interface. -func (l *JSONFileLogger) Log(ctx context.Context, level slog.Level, msg string, args ...any) { - l.logger.Log(ctx, level, msg, args...) +// Handle takes record created by an slog.Logger and forwards it to the +// internal slog.Handler for dispatching the log call to the backing file. It +// implements the slog.Handler interface. +func (l *JSONFileLogger) Handle(ctx context.Context, r slog.Record) error { + return l.handler.Handle(ctx, r.Clone()) +} + +// WithAttrs returns a new *JSONFileLogger with a new internal handler that has +// the provided attrs attached as attributes on all further log calls. It +// implements the slog.Handler interface. +func (l *JSONFileLogger) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return l + } + + return &JSONFileLogger{file: l.file, handler: l.handler.WithAttrs(attrs)} +} + +// WithGroup returns a new *JSONFileLogger with a new internal handler that has +// the provided group name attached, to group all other attributes added to the +// logger. It implements the slog.Handler interface. +func (l *JSONFileLogger) WithGroup(name string) slog.Handler { + if name == "" { + return l + } + + return &JSONFileLogger{file: l.file, handler: l.handler.WithGroup(name)} } diff --git a/util/logging/file_test.go b/util/logging/file_test.go index c9f7240fee..bd34bc2a3a 100644 --- a/util/logging/file_test.go +++ b/util/logging/file_test.go @@ -14,7 +14,6 @@ package logging import ( - "context" "log/slog" "os" "strings" @@ -24,6 +23,19 @@ import ( "github.com/stretchr/testify/require" ) +func getLogLines(t *testing.T, name string) []string { + content, err := os.ReadFile(name) + require.NoError(t, err) + + lines := strings.Split(string(content), "\n") + for i := len(lines) - 1; i >= 0; i-- { + if lines[i] == "" { + lines = append(lines[:i], lines[i+1:]...) + } + } + return lines +} + func TestJSONFileLogger_basic(t *testing.T) { f, err := os.CreateTemp("", "logging") require.NoError(t, err) @@ -32,24 +44,23 @@ func TestJSONFileLogger_basic(t *testing.T) { require.NoError(t, os.Remove(f.Name())) }() - l, err := NewJSONFileLogger(f.Name()) + logHandler, err := NewJSONFileLogger(f.Name()) require.NoError(t, err) - require.NotNil(t, l, "logger can't be nil") + require.NotNil(t, logHandler, "logger handler can't be nil") - l.Log(context.Background(), slog.LevelInfo, "test", "hello", "world") - require.NoError(t, err) - r := make([]byte, 1024) - _, err = f.Read(r) - require.NoError(t, err) + logger := slog.New(logHandler) + logger.Info("test", "hello", "world") - result, err := regexp.Match(`^{"time":"[^"]+","level":"INFO","source":"file.go:\d+","msg":"test","hello":"world"}\n`, r) + r := getLogLines(t, f.Name()) + require.Len(t, r, 1, "expected 1 log line") + result, err := regexp.Match(`^{"time":"[^"]+","level":"INFO","source":"\w+.go:\d+","msg":"test","hello":"world"}`, []byte(r[0])) require.NoError(t, err) require.True(t, result, "unexpected content: %s", r) - err = l.Close() + err = logHandler.Close() require.NoError(t, err) - err = l.file.Close() + err = logHandler.file.Close() require.Error(t, err) require.True(t, strings.HasSuffix(err.Error(), os.ErrClosed.Error()), "file not closed") } @@ -62,31 +73,31 @@ func TestJSONFileLogger_parallel(t *testing.T) { require.NoError(t, os.Remove(f.Name())) }() - l, err := NewJSONFileLogger(f.Name()) + logHandler, err := NewJSONFileLogger(f.Name()) require.NoError(t, err) - require.NotNil(t, l, "logger can't be nil") + require.NotNil(t, logHandler, "logger handler can't be nil") - l.Log(context.Background(), slog.LevelInfo, "test", "hello", "world") + logger := slog.New(logHandler) + logger.Info("test", "hello", "world") + + logHandler2, err := NewJSONFileLogger(f.Name()) + require.NoError(t, err) + require.NotNil(t, logHandler2, "logger handler can't be nil") + + logger2 := slog.New(logHandler2) + logger2.Info("test", "hello", "world") + + err = logHandler.Close() require.NoError(t, err) - l2, err := NewJSONFileLogger(f.Name()) - require.NoError(t, err) - require.NotNil(t, l, "logger can't be nil") - - l2.Log(context.Background(), slog.LevelInfo, "test", "hello", "world") - require.NoError(t, err) - - err = l.Close() - require.NoError(t, err) - - err = l.file.Close() + err = logHandler.file.Close() require.Error(t, err) require.True(t, strings.HasSuffix(err.Error(), os.ErrClosed.Error()), "file not closed") - err = l2.Close() + err = logHandler2.Close() require.NoError(t, err) - err = l2.file.Close() + err = logHandler2.file.Close() require.Error(t, err) require.True(t, strings.HasSuffix(err.Error(), os.ErrClosed.Error()), "file not closed") } From 4d54c304f8fa7359a2f62250f15a7b3b25e8dd2b Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Mon, 2 Dec 2024 00:57:33 -0500 Subject: [PATCH 2/3] ref: make query logger more efficient by building list of attrs Addresses PR feedback to make query logger more efficient. Signed-off-by: TJ Hoplock --- promql/engine.go | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/promql/engine.go b/promql/engine.go index 2ef0fabe7c..00a142b0c0 100644 --- a/promql/engine.go +++ b/promql/engine.go @@ -629,7 +629,7 @@ func (ng *Engine) exec(ctx context.Context, q *query) (v parser.Value, ws annota ng.queryLoggerLock.RLock() if l := ng.queryLogger; l != nil { logger := slog.New(l) - f := make([]any, 0, 16) // Probably enough up front to not need to reallocate on append. + f := make([]slog.Attr, 0, 16) // Probably enough up front to not need to reallocate on append. params := make(map[string]interface{}, 4) params["query"] = q.q @@ -639,20 +639,20 @@ func (ng *Engine) exec(ctx context.Context, q *query) (v parser.Value, ws annota // The step provided by the user is in seconds. params["step"] = int64(eq.Interval / (time.Second / time.Nanosecond)) } - f = append(f, "params", params) + f = append(f, slog.Any("params", params)) if err != nil { - f = append(f, "error", err) + f = append(f, slog.Any("error", err)) } - f = append(f, "stats", stats.NewQueryStats(q.Stats())) + f = append(f, slog.Any("stats", stats.NewQueryStats(q.Stats()))) if span := trace.SpanFromContext(ctx); span != nil { - f = append(f, "spanID", span.SpanContext().SpanID()) + f = append(f, slog.Any("spanID", span.SpanContext().SpanID())) } if origin := ctx.Value(QueryOrigin{}); origin != nil { for k, v := range origin.(map[string]interface{}) { - f = append(f, k, v) + f = append(f, slog.Any(k, v)) } } - logger.Info("promql query logged", f...) + logger.LogAttrs(context.Background(), slog.LevelInfo, "promql query logged", f...) // TODO: @tjhop -- do we still need this metric/error log if logger doesn't return errors? // ng.metrics.queryLogFailures.Inc() // ng.logger.Error("can't log query", "err", err) From 53eb1fe71f4c22c6687200c2faa66bfc6c37e0ac Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Mon, 2 Dec 2024 09:21:56 -0500 Subject: [PATCH 3/3] test: make promql engine_test use files to exercise query logger Signed-off-by: TJ Hoplock --- promql/engine_test.go | 139 ++++++++++++++++++------------------------ 1 file changed, 59 insertions(+), 80 deletions(-) diff --git a/promql/engine_test.go b/promql/engine_test.go index b8e7cd71c3..f0a76ecc4d 100644 --- a/promql/engine_test.go +++ b/promql/engine_test.go @@ -17,9 +17,9 @@ import ( "context" "errors" "fmt" - "io" - "log/slog" "math" + "os" + "path/filepath" "sort" "strings" "sync" @@ -39,6 +39,7 @@ import ( "github.com/prometheus/prometheus/storage" "github.com/prometheus/prometheus/tsdb/chunkenc" "github.com/prometheus/prometheus/util/annotations" + "github.com/prometheus/prometheus/util/logging" "github.com/prometheus/prometheus/util/stats" "github.com/prometheus/prometheus/util/testutil" ) @@ -2148,65 +2149,17 @@ func TestSubquerySelector(t *testing.T) { } } -var _ io.Closer = (*FakeQueryLogger)(nil) +func getLogLines(t *testing.T, name string) []string { + content, err := os.ReadFile(name) + require.NoError(t, err) -var _ slog.Handler = (*FakeQueryLogger)(nil) - -type FakeQueryLogger struct { - closed bool - logs []any - attrs []any -} - -func NewFakeQueryLogger() *FakeQueryLogger { - return &FakeQueryLogger{ - closed: false, - logs: make([]interface{}, 0), - attrs: make([]any, 0), + lines := strings.Split(string(content), "\n") + for i := len(lines) - 1; i >= 0; i-- { + if lines[i] == "" { + lines = append(lines[:i], lines[i+1:]...) + } } -} - -func (f *FakeQueryLogger) Close() error { - f.closed = true - return nil -} - -func (f *FakeQueryLogger) Enabled(ctx context.Context, level slog.Level) bool { - return true -} - -func (f *FakeQueryLogger) Handle(ctx context.Context, r slog.Record) error { - // Test usage only really cares about existence of keyvals passed in - // via args, just append in the log message before handling the - // provided args and any embedded kvs added via `.With()` on f.attrs. - log := append([]any{r.Message}, f.attrs...) - f.attrs = f.attrs[:0] - - r.Attrs(func(a slog.Attr) bool { - log = append(log, a.Key, a.Value.Any()) - return true - }) - - f.logs = append(f.logs, log...) - return nil -} - -func (f *FakeQueryLogger) WithAttrs(attrs []slog.Attr) slog.Handler { - attrPairs := []any{} - for _, a := range attrs { - attrPairs = append(attrPairs, a.Key, a.Value.Any()) - } - - return &FakeQueryLogger{ - closed: f.closed, - logs: f.logs, - attrs: append(f.attrs, attrPairs...), - } -} - -func (f *FakeQueryLogger) WithGroup(name string) slog.Handler { - // We don't need to support groups for this fake handler in testing. - return f + return lines } func TestQueryLogger_basic(t *testing.T) { @@ -2231,32 +2184,45 @@ func TestQueryLogger_basic(t *testing.T) { // promql.Query works without query log initialized. queryExec() - f1 := NewFakeQueryLogger() + tmpDir := t.TempDir() + ql1File := filepath.Join(tmpDir, "query1.log") + f1, err := logging.NewJSONFileLogger(ql1File) + require.NoError(t, err) + engine.SetQueryLogger(f1) queryExec() - require.Contains(t, f1.logs, `params`) - require.Contains(t, f1.logs, map[string]interface{}{"query": "test statement"}) + logLines := getLogLines(t, ql1File) + require.Contains(t, logLines[0], "params", map[string]interface{}{"query": "test statement"}) + require.Len(t, logLines, 1) - l := len(f1.logs) + l := len(logLines) queryExec() - require.Len(t, f1.logs, 2*l) + logLines = getLogLines(t, ql1File) + l2 := len(logLines) + require.Equal(t, l2, 2*l) - // Test that we close the query logger when unsetting it. - require.False(t, f1.closed, "expected f1 to be open, got closed") + // Test that we close the query logger when unsetting it. The following + // attempt to close the file should error. engine.SetQueryLogger(nil) - require.True(t, f1.closed, "expected f1 to be closed, got open") + err = f1.Close() + require.ErrorContains(t, err, "file already closed", "expected f1 to be closed, got open") queryExec() // Test that we close the query logger when swapping. - f2 := NewFakeQueryLogger() - f3 := NewFakeQueryLogger() + ql2File := filepath.Join(tmpDir, "query2.log") + f2, err := logging.NewJSONFileLogger(ql2File) + require.NoError(t, err) + ql3File := filepath.Join(tmpDir, "query3.log") + f3, err := logging.NewJSONFileLogger(ql3File) + require.NoError(t, err) engine.SetQueryLogger(f2) - require.False(t, f2.closed, "expected f2 to be open, got closed") queryExec() engine.SetQueryLogger(f3) - require.True(t, f2.closed, "expected f2 to be closed, got open") - require.False(t, f3.closed, "expected f3 to be open, got closed") + err = f2.Close() + require.ErrorContains(t, err, "file already closed", "expected f2 to be closed, got open") queryExec() + err = f3.Close() + require.NoError(t, err) } func TestQueryLogger_fields(t *testing.T) { @@ -2268,7 +2234,14 @@ func TestQueryLogger_fields(t *testing.T) { } engine := promqltest.NewTestEngineWithOpts(t, opts) - f1 := NewFakeQueryLogger() + tmpDir := t.TempDir() + ql1File := filepath.Join(tmpDir, "query1.log") + f1, err := logging.NewJSONFileLogger(ql1File) + require.NoError(t, err) + t.Cleanup(func() { + require.NoError(t, f1.Close()) + }) + engine.SetQueryLogger(f1) ctx, cancelCtx := context.WithCancel(context.Background()) @@ -2281,8 +2254,8 @@ func TestQueryLogger_fields(t *testing.T) { res := query.Exec(ctx) require.NoError(t, res.Err) - require.Contains(t, f1.logs, `foo`) - require.Contains(t, f1.logs, `bar`) + logLines := getLogLines(t, ql1File) + require.Contains(t, logLines[0], "foo", "bar") } func TestQueryLogger_error(t *testing.T) { @@ -2294,7 +2267,14 @@ func TestQueryLogger_error(t *testing.T) { } engine := promqltest.NewTestEngineWithOpts(t, opts) - f1 := NewFakeQueryLogger() + tmpDir := t.TempDir() + ql1File := filepath.Join(tmpDir, "query1.log") + f1, err := logging.NewJSONFileLogger(ql1File) + require.NoError(t, err) + t.Cleanup(func() { + require.NoError(t, f1.Close()) + }) + engine.SetQueryLogger(f1) ctx, cancelCtx := context.WithCancel(context.Background()) @@ -2308,10 +2288,9 @@ func TestQueryLogger_error(t *testing.T) { res := query.Exec(ctx) require.Error(t, res.Err, "query should have failed") - require.Contains(t, f1.logs, `params`) - require.Contains(t, f1.logs, map[string]interface{}{"query": "test statement"}) - require.Contains(t, f1.logs, `error`) - require.Contains(t, f1.logs, testErr) + logLines := getLogLines(t, ql1File) + require.Contains(t, logLines[0], "error", testErr) + require.Contains(t, logLines[0], "params", map[string]interface{}{"query": "test statement"}) } func TestPreprocessAndWrapWithStepInvariantExpr(t *testing.T) {