QFE: only log slow query, if it is a query endpoint

Signed-off-by: Pedro Tanaka <[email protected]>

Author: pedro-stanaka

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/query") || strings.HasPrefix(path, "/api/v1/series") || strings.HasPrefix(path, "/api/v1/label")
+}
+
 // 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.

internal/cortex/frontend/transport/handler_test.go

@@ -0,0 +1,96 @@
+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) {
+	cfg := HandlerConfig{
+		QueryStatsEnabled:    true,
+		LogQueriesLongerThan: 1 * time.Second,
+	}
+	fakeRoundTripper := &fakeRoundTripper{
+		requestLatency: 2 * time.Second,
+		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(`{}`)),
+		},
+	}
+
+	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=2",
+				"path=/api/v1/query",
+				"param_query=absent(up)",
+				"param_start=1714262400",
+				"param_end=1714266000",
+			},
+		},
+		{
+			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=2",
+				"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:  "/api/v1/status/config",
+			// No slow query log for non-query endpoints
+			logParts: []string{},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			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)
+			}
+		})
+	}
+}