diff --git a/CHANGELOG.md b/CHANGELOG.md index 3e1314b242..da53c4e9e2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,7 @@ We use *breaking :warning:* to mark changes that are not backward compatible (re - [#7814](https://github.com/thanos-io/thanos/pull/7814) Store: label_values: if matchers contain **name**=="something", do not add != "" to fetch less postings. - [#7679](https://github.com/thanos-io/thanos/pull/7679) Query: respect store.limit.* flags when evaluating queries - [#7821](https://github.com/thanos-io/thanos/pull/7679) Query/Receive: Fix coroutine leak introduced in https://github.com/thanos-io/thanos/pull/7796. +- [#7843](https://github.com/thanos-io/thanos/pull/7843) Query Frontend: fix slow query logging for non-query endpoints. ### Added - [#7763](https://github.com/thanos-io/thanos/pull/7763) Ruler: use native histograms for client latency metrics. diff --git a/internal/cortex/frontend/transport/handler.go b/internal/cortex/frontend/transport/handler.go index 8c3020a6d9..ab968eee36 100644 --- a/internal/cortex/frontend/transport/handler.go +++ b/internal/cortex/frontend/transport/handler.go @@ -148,7 +148,9 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } // Check whether we should parse the query string. - shouldReportSlowQuery := f.cfg.LogQueriesLongerThan != 0 && queryResponseTime > f.cfg.LogQueriesLongerThan + shouldReportSlowQuery := f.cfg.LogQueriesLongerThan != 0 && + queryResponseTime > f.cfg.LogQueriesLongerThan && + isQueryEndpoint(r.URL.Path) if shouldReportSlowQuery || f.cfg.QueryStatsEnabled { queryString = f.parseRequestQueryString(r, buf) } @@ -161,6 +163,13 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } } +// isQueryEndpoint returns true if the path is any of the Prometheus HTTP API, +// query-related endpoints. +// Example: /api/v1/query, /api/v1/query_range, /api/v1/series, /api/v1/label, /api/v1/labels +func isQueryEndpoint(path string) bool { + return strings.HasPrefix(path, "/api/v1") +} + // reportSlowQuery reports slow queries. func (f *Handler) reportSlowQuery(r *http.Request, responseHeaders http.Header, queryString url.Values, queryResponseTime time.Duration) { // NOTE(GiedriusS): see https://github.com/grafana/grafana/pull/60301 for more info. diff --git a/internal/cortex/frontend/transport/handler_test.go b/internal/cortex/frontend/transport/handler_test.go new file mode 100644 index 0000000000..b5899c2d8d --- /dev/null +++ b/internal/cortex/frontend/transport/handler_test.go @@ -0,0 +1,112 @@ +// Copyright (c) The Cortex Authors. +// Licensed under the Apache License 2.0. + +package transport + +import ( + "bytes" + "io" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/go-kit/log" + "github.com/prometheus/client_golang/prometheus" + "github.com/stretchr/testify/require" +) + +type fakeRoundTripper struct { + response *http.Response + err error + requestLatency time.Duration +} + +func (f *fakeRoundTripper) RoundTrip(_ *http.Request) (*http.Response, error) { + time.Sleep(f.requestLatency) + return f.response, f.err +} + +func TestHandler_SlowQueryLog(t *testing.T) { + t.Parallel() + + cfg := HandlerConfig{ + QueryStatsEnabled: true, + LogQueriesLongerThan: 1 * time.Microsecond, + } + + tests := []struct { + name string + url string + logParts []string + }{ + { + name: "Basic query", + url: "/api/v1/query?query=absent(up)&start=1714262400&end=1714266000", + logParts: []string{ + "slow query detected", + "time_taken=", + "path=/api/v1/query", + "param_query=absent(up)", + "param_start=1714262400", + "param_end=1714266000", + }, + }, + { + name: "Series call", + url: "/api/v1/series?match[]={__name__=~\"up\"}", + logParts: []string{ + "slow query detected", + "time_taken=", + "path=/api/v1/series", + }, + }, + { + name: "Query with different parameters", + url: "/api/v1/query_range?query=rate(http_requests_total[5m])&start=1714262400&end=1714266000&step=15", + logParts: []string{ + "slow query detected", + "time_taken=", + "path=/api/v1/query_range", + "param_query=rate(http_requests_total[5m])", + "param_start=1714262400", + "param_end=1714266000", + "param_step=15", + }, + }, + { + name: "Non-query endpoint", + url: "/favicon.ico", + // No slow query log for non-query endpoints + logParts: []string{}, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + fakeRoundTripper := &fakeRoundTripper{ + requestLatency: 2 * time.Microsecond, + response: &http.Response{ + StatusCode: http.StatusOK, + Header: http.Header{ + "Content-Type": []string{"application/json"}, + "Server-Timing": []string{"querier;dur=1.23"}, + }, + Body: io.NopCloser(bytes.NewBufferString(`{}`)), + }, + } + + logWriter := &bytes.Buffer{} + logger := log.NewLogfmtLogger(log.NewSyncWriter(logWriter)) + + handler := NewHandler(cfg, fakeRoundTripper, logger, prometheus.NewRegistry()) + + handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", tt.url, nil)) + + for _, part := range tt.logParts { + require.Contains(t, logWriter.String(), part) + } + }) + } +}