Log failed query information in the query-frontend #3190

fayzal-g · 2022-10-11T10:58:31Z

What this PR does

Logs useful information about the query in the case of a failed query (context cancelled etc) - current logging information was making it hard for other engineers to debug issues.

Which issue(s) this PR fixes or relates to

#3146

Fixes #3146

Checklist

Tests updated
Documentation added
CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

pstibrany

Thank you.

pstibrany · 2022-10-11T12:12:45Z

pkg/frontend/transport/handler_test.go

+			handler := NewHandler(test.cfg, roundTripper, logger, reg)
+
+			ctx := user.InjectOrgID(context.Background(), "12345")
+			req := httptest.NewRequest("GET", "/api/v1/query?query=up&time=2015-07-01T20:10:51.781Z", nil)


Please add a test with no query parameters too, ie. GET /api/v1/query. That should fail and log error message.

pstibrany · 2022-10-11T12:14:08Z

pkg/frontend/transport/handler_test.go

+			roundTripper := roundTripperFunc(func(req *http.Request) (*http.Response, error) {
+				return nil, context.Canceled
+			})
+


this should only be part of "Failed round trip with context cancelled" test, not all tests.

pstibrany · 2022-10-11T12:14:57Z

pkg/frontend/transport/handler.go

@@ -145,6 +145,8 @@ func (f *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {

 	if err != nil {
 		writeError(w, err)
+		queryString = f.parseRequestQueryString(r, buf)
+		f.reportFailedQueryStats(r, queryString, queryResponseTime, stats)


can we include the error in the log message?

I also ask if we shouldn't include an err field in the log.

aknuds1

Left some questions.

CHANGELOG.md

pkg/frontend/transport/handler.go

pkg/frontend/transport/handler_test.go

pkg/frontend/transport/handler.go

pkg/frontend/transport/handler_test.go

pracucci · 2022-10-11T19:15:54Z

pkg/frontend/transport/handler.go

+func (f *Handler) reportFailedQuery(r *http.Request, queryString url.Values, queryResponseTime time.Duration, stats *querier_stats.Stats, err error) {
+	// Log failed query info
+	logMessage := append([]interface{}{
+		"msg", "failed query stats",


Instead of having a different log message, what if we just reuse reportQueryStats() (so that even partially collected information about the query complexity may be logged) and we add a status field to the log to track whether the query succeeded or failed? /cc @aknuds1 @56quarters @pstibrany

I don't feel too strongly about this either way, was thinking it might be better to keep the failed query reporting quite lightweight, but if all the additional info is going to add a lot of value I can re-use reportQueryStats()

What @pracucci says sounds reasonable. The benefit of re-using reportQueryStats (with error info) is you get all the same stats for failed queries. Is there any argument against calling reportQueryStats for failed queries?

aknuds1

See comments.

pkg/frontend/transport/handler.go

aknuds1 · 2022-10-12T09:37:29Z

pkg/frontend/transport/handler.go

+func (f *Handler) reportFailedQuery(r *http.Request, queryString url.Values, queryResponseTime time.Duration, stats *querier_stats.Stats, err error) {
+	// Log failed query info
+	logMessage := append([]interface{}{
+		"msg", "failed query stats",


What @pracucci says sounds reasonable. The benefit of re-using reportQueryStats (with error info) is you get all the same stats for failed queries. Is there any argument against calling reportQueryStats for failed queries?

pkg/frontend/transport/handler_test.go

aknuds1

Left a suggestion.

pkg/frontend/transport/handler_test.go

pkg/frontend/transport/handler.go

aknuds1

LGTM, but let's see if @pstibrany, @56quarters or @pracucci want to leave a review as well?

pstibrany · 2022-10-17T13:30:58Z

pkg/frontend/transport/handler.go

+		logMessage = append(logMessage, []interface{}{
+			"status", "failed",
+			"err", queryErr,
+		})


we want to append these values as individual values, not within a slice, right? (same for else condition)

Suggested change

logMessage = append(logMessage, []interface{}{

"status", "failed",

"err", queryErr,

})

logMessage = append(logMessage,

"status", "failed",

"err", queryErr,

)

Adding assert assert.Contains(t, strings.TrimSpace(logs.String()), "status=failed") to the test shows that this is currently broken.

Good catch, initially intended to append a slice to slice but forgot the ... i.e

logMessage = append(logMessage, []interface{}{ "status", "failed", "err", queryErr, }...)

Will update to individual values like you suggested as it looks a bit cleaner

Co-authored-by: Arve Knudsen <arve.knudsen@gmail.com>

pstibrany

Thank you!

pracucci

LGTM, thanks!

fayzal-g marked this pull request as ready for review October 11, 2022 11:53

fayzal-g requested a review from a team as a code owner October 11, 2022 11:53

aknuds1 added the component/query-frontend label Oct 11, 2022

pstibrany reviewed Oct 11, 2022

View reviewed changes

aknuds1 reviewed Oct 11, 2022

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

pkg/frontend/transport/handler.go Outdated Show resolved Hide resolved

aknuds1 reviewed Oct 11, 2022

View reviewed changes

pkg/frontend/transport/handler_test.go Outdated Show resolved Hide resolved

aknuds1 reviewed Oct 11, 2022

View reviewed changes

pkg/frontend/transport/handler.go Outdated Show resolved Hide resolved

aknuds1 reviewed Oct 11, 2022

View reviewed changes

pkg/frontend/transport/handler_test.go Outdated Show resolved Hide resolved

pracucci reviewed Oct 11, 2022

View reviewed changes

aknuds1 reviewed Oct 12, 2022

View reviewed changes

pkg/frontend/transport/handler_test.go Outdated Show resolved Hide resolved

aknuds1 reviewed Oct 12, 2022

View reviewed changes

pkg/frontend/transport/handler.go Outdated Show resolved Hide resolved

fayzal-g force-pushed the log-failed-queries branch from 2a8c0bb to 1496bd6 Compare October 12, 2022 14:52

aknuds1 reviewed Oct 13, 2022

View reviewed changes

pkg/frontend/transport/handler.go Outdated Show resolved Hide resolved

aknuds1 approved these changes Oct 13, 2022

View reviewed changes

aknuds1 requested review from pstibrany, 56quarters and pracucci October 13, 2022 11:10

pstibrany reviewed Oct 17, 2022

View reviewed changes

fayzal-g and others added 11 commits October 17, 2022 14:43

Log failed queries in the query-frontend

716ec80

Clean up test

de3ed18

Update CHANGELOG.md

0aef83e

Goimports handler_test.go

c9093bd

Address review comments

2ac3e1b

Use reportQueryStats instead

3289d2c

Update test to require instead of assert

0d50aa3

Update pkg/frontend/transport/handler.go

cca3c06

Co-authored-by: Arve Knudsen <arve.knudsen@gmail.com>

Check if stats is not nil

249e8f6

Remove comment

6218515

gofmt

db6da42

Fix error status appending

8c1878d

fayzal-g force-pushed the log-failed-queries branch from 399e095 to 8c1878d Compare October 17, 2022 13:44

pstibrany approved these changes Oct 17, 2022

View reviewed changes

pracucci approved these changes Oct 17, 2022

View reviewed changes

pracucci merged commit cf1724c into grafana:main Oct 17, 2022

stevesg mentioned this pull request Nov 3, 2022

Mixin: Enhance "Slow Queries" dashboard for generic insights into query performance #3375

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log failed query information in the query-frontend #3190

Log failed query information in the query-frontend #3190

fayzal-g commented Oct 11, 2022 •

edited by aknuds1

pstibrany left a comment

pstibrany Oct 11, 2022

pstibrany Oct 11, 2022

pstibrany Oct 11, 2022

aknuds1 Oct 11, 2022 •

edited

aknuds1 left a comment

pracucci Oct 11, 2022

fayzal-g Oct 12, 2022

aknuds1 Oct 12, 2022 •

edited

aknuds1 left a comment

aknuds1 Oct 12, 2022 •

edited

aknuds1 left a comment

aknuds1 left a comment •

edited

pstibrany Oct 17, 2022

fayzal-g Oct 17, 2022

pstibrany left a comment

pracucci left a comment

Log failed query information in the query-frontend #3190

Log failed query information in the query-frontend #3190

Conversation

fayzal-g commented Oct 11, 2022 • edited by aknuds1

What this PR does

Which issue(s) this PR fixes or relates to

Checklist

pstibrany left a comment

Choose a reason for hiding this comment

pstibrany Oct 11, 2022

Choose a reason for hiding this comment

pstibrany Oct 11, 2022

Choose a reason for hiding this comment

pstibrany Oct 11, 2022

Choose a reason for hiding this comment

aknuds1 Oct 11, 2022 • edited

Choose a reason for hiding this comment

aknuds1 left a comment

Choose a reason for hiding this comment

pracucci Oct 11, 2022

Choose a reason for hiding this comment

fayzal-g Oct 12, 2022

Choose a reason for hiding this comment

aknuds1 Oct 12, 2022 • edited

Choose a reason for hiding this comment

aknuds1 left a comment

Choose a reason for hiding this comment

aknuds1 Oct 12, 2022 • edited

Choose a reason for hiding this comment

aknuds1 left a comment

Choose a reason for hiding this comment

aknuds1 left a comment • edited

Choose a reason for hiding this comment

pstibrany Oct 17, 2022

Choose a reason for hiding this comment

fayzal-g Oct 17, 2022

Choose a reason for hiding this comment

pstibrany left a comment

Choose a reason for hiding this comment

pracucci left a comment

Choose a reason for hiding this comment

fayzal-g commented Oct 11, 2022 •

edited by aknuds1

aknuds1 Oct 11, 2022 •

edited

aknuds1 Oct 12, 2022 •

edited

aknuds1 Oct 12, 2022 •

edited

aknuds1 left a comment •

edited