Query Frontend: Fix slow query logging if 'LogQueriesLongerThan' is set to < 0 (#4633)

* Fix slow query log parameter if < 0

Signed-off-by: Matej Gera <[email protected]>

* Update CHANGELOG

Signed-off-by: Matej Gera <[email protected]>

* Extend the query frontend tests

Signed-off-by: Matej Gera <[email protected]>

Author: matej-g

CHANGELOG.md

@@ -26,6 +26,7 @@
 * [BUGFIX] Set appropriate `Content-Type` header for /services endpoint, which previously hard-coded `text/plain`. #4596
 * [BUGFIX] Querier: Disable query scheduler SRV DNS lookup, which removes noisy log messages about "failed DNS SRV record lookup". #4601
 * [BUGFIX] Memberlist: fixed corrupted packets when sending compound messages with more than 255 messages or messages bigger than 64KB. #4601
+* [BUGIX] Query Frontend: If 'LogQueriesLongerThan' is set to < 0, log all queries as described in the docs. #4633
 
 ## 1.11.0 2021-11-25
 

pkg/frontend/frontend_test.go

@@ -93,7 +93,7 @@ func TestFrontend_RequestHostHeaderWhenDownstreamURLIsConfigured(t *testing.T) {
 	testFrontend(t, config, nil, test, true, nil)
 }
 
-func TestFrontend_LogsSlowQueriesFormValues(t *testing.T) {
+func TestFrontend_LogsSlowQueries(t *testing.T) {
 	// Create an HTTP server listening locally. This server mocks the downstream
 	// Prometheus API-compatible server.
 	downstreamListen, err := net.Listen("tcp", "localhost:0")
@@ -109,50 +109,77 @@ func TestFrontend_LogsSlowQueriesFormValues(t *testing.T) {
 	defer downstreamServer.Shutdown(context.Background()) //nolint:errcheck
 	go downstreamServer.Serve(downstreamListen)           //nolint:errcheck
 
-	// Configure the query-frontend with the mocked downstream server.
-	config := defaultFrontendConfig()
-	config.Handler.LogQueriesLongerThan = 1 * time.Microsecond
-	config.DownstreamURL = fmt.Sprintf("http://%s", downstreamListen.Addr())
-
-	var buf concurrency.SyncBuffer
-	l := log.NewLogfmtLogger(&buf)
-
-	test := func(addr string) {
-		data := url.Values{}
-		data.Set("test", "form")
-		data.Set("issue", "3111")
-
-		req, _ := http.NewRequest(http.MethodPost, fmt.Sprintf("http://%s/?foo=bar", addr), strings.NewReader(data.Encode()))
-		req.Header.Add("Content-Type", "application/x-www-form-urlencoded")
-		req.Header.Add("Content-Length", strconv.Itoa(len(data.Encode())))
-
-		ctx := context.Background()
-		req = req.WithContext(ctx)
-		assert.NoError(t, err)
-		err = user.InjectOrgIDIntoHTTPRequest(user.InjectOrgID(ctx, "1"), req)
-		assert.NoError(t, err)
-
-		client := http.Client{
-			Transport: &nethttp.Transport{},
-		}
-
-		resp, err := client.Do(req)
-		assert.NoError(t, err)
-		b, err := ioutil.ReadAll(resp.Body)
-		resp.Body.Close()
-
-		assert.NoError(t, err)
-		assert.Equal(t, 200, resp.StatusCode, string(b))
-
-		logs := buf.String()
-		assert.NotContains(t, logs, "unable to parse form for request")
-		assert.Contains(t, logs, "msg=\"slow query detected\"")
-		assert.Contains(t, logs, "param_issue=3111")
-		assert.Contains(t, logs, "param_test=form")
-		assert.Contains(t, logs, "param_foo=bar")
+	tests := map[string]struct {
+		longerThan time.Duration
+		shouldLog  bool
+	}{
+		"longer than set to > 0": {
+			longerThan: 1 * time.Microsecond,
+			shouldLog:  true,
+		},
+		"longer than set to < 0": {
+			longerThan: -1 * time.Microsecond,
+			shouldLog:  true,
+		},
+		"logging disabled": {
+			longerThan: 0,
+			shouldLog:  false,
+		},
 	}
 
-	testFrontend(t, config, nil, test, false, l)
+	for testName, testData := range tests {
+		t.Run(testName, func(t *testing.T) {
+			// Configure the query-frontend with the mocked downstream server.
+			config := defaultFrontendConfig()
+			config.Handler.LogQueriesLongerThan = testData.longerThan
+			config.DownstreamURL = fmt.Sprintf("http://%s", downstreamListen.Addr())
+
+			var buf concurrency.SyncBuffer
+
+			test := func(addr string) {
+				// To assert form values are logged as well.
+				data := url.Values{}
+				data.Set("test", "form")
+				data.Set("issue", "3111")
+
+				req, _ := http.NewRequest(http.MethodPost, fmt.Sprintf("http://%s/?foo=bar", addr), strings.NewReader(data.Encode()))
+				req.Header.Add("Content-Type", "application/x-www-form-urlencoded")
+				req.Header.Add("Content-Length", strconv.Itoa(len(data.Encode())))
+
+				ctx := context.Background()
+				req = req.WithContext(ctx)
+				assert.NoError(t, err)
+				err = user.InjectOrgIDIntoHTTPRequest(user.InjectOrgID(ctx, "1"), req)
+				assert.NoError(t, err)
+
+				client := http.Client{
+					Transport: &nethttp.Transport{},
+				}
+
+				resp, err := client.Do(req)
+				assert.NoError(t, err)
+				b, err := ioutil.ReadAll(resp.Body)
+				resp.Body.Close()
+
+				assert.NoError(t, err)
+				assert.Equal(t, 200, resp.StatusCode, string(b))
+
+				logs := buf.String()
+				assert.NotContains(t, logs, "unable to parse form for request")
+
+				if testData.shouldLog {
+					assert.Contains(t, logs, "msg=\"slow query detected\"")
+					assert.Contains(t, logs, "param_issue=3111")
+					assert.Contains(t, logs, "param_test=form")
+					assert.Contains(t, logs, "param_foo=bar")
+				} else {
+					assert.NotContains(t, logs, "msg=\"slow query detected\"")
+				}
+			}
+
+			testFrontend(t, config, nil, test, false, log.NewLogfmtLogger(&buf))
+		})
+	}
 }
 
 func TestFrontend_ReturnsRequestBodyTooLargeError(t *testing.T) {

pkg/frontend/transport/handler.go

@@ -147,7 +147,7 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	_, _ = io.Copy(w, resp.Body)
 
 	// 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
 	if shouldReportSlowQuery || f.cfg.QueryStatsEnabled {
 		queryString = f.parseRequestQueryString(r, buf)
 	}