feat: add query user and query source to "executing query" log lines (#…

…14320) Signed-off-by: Callum Styan <[email protected]>
grafana · Sep 30, 2024 · 4d69929 · 4d69929
1 parent 38b01c9
commit 4d69929
Show file tree

Hide file tree

Showing 2 changed files with 21 additions and 20 deletions.
diff --git a/pkg/logql/engine.go b/pkg/logql/engine.go
@@ -241,11 +241,21 @@ func (q *query) Exec(ctx context.Context) (logqlmodel.Result, error) {
 
 	if q.logExecQuery {
 		queryHash := util.HashedQuery(q.params.QueryString())
+
+		logValues := []interface{}{
+			"msg", "executing query",
+			"query", q.params.QueryString(),
+			"query_hash", queryHash,
+		}
+		tags := httpreq.ExtractQueryTagsFromContext(ctx)
+		tagValues := tagsToKeyValues(tags)
 		if GetRangeType(q.params) == InstantType {
-			level.Info(logutil.WithContext(ctx, q.logger)).Log("msg", "executing query", "type", "instant", "query", q.params.QueryString(), "query_hash", queryHash)
+			logValues = append(logValues, "type", "instant")
 		} else {
-			level.Info(logutil.WithContext(ctx, q.logger)).Log("msg", "executing query", "type", "range", "query", q.params.QueryString(), "length", q.params.End().Sub(q.params.Start()), "step", q.params.Step(), "query_hash", queryHash)
+			logValues = append(logValues, "type", "range", "length", q.params.End().Sub(q.params.Start()), "step", q.params.Step())
 		}
+		logValues = append(logValues, tagValues...)
+		level.Info(logutil.WithContext(ctx, q.logger)).Log(logValues...)
 	}
 
 	rangeType := GetRangeType(q.params)
@@ -265,6 +275,7 @@ func (q *query) Exec(ctx context.Context) (logqlmodel.Result, error) {
 	sp.LogKV(statResult.KVList()...)
 
 	status, _ := server.ClientHTTPStatusAndError(err)
+
 	if q.record {
 		RecordRangeAndInstantQueryMetrics(ctx, q.logger, q.params, strconv.Itoa(status), statResult, data)
 	}

diff --git a/pkg/logql/engine_test.go b/pkg/logql/engine_test.go
@@ -6,7 +6,6 @@ import (
 	"errors"
 	"fmt"
 	"math"
-	"regexp"
 	"strings"
 	"testing"
 	"time"
@@ -2618,23 +2617,14 @@ func TestHashingStability(t *testing.T) {
 		expectedQueryHash := util.HashedQuery(test.qs)
 
 		// check that both places will end up having the same query hash, even though they're emitting different log lines.
-		require.Regexp(t,
-			regexp.MustCompile(
-				fmt.Sprintf(
-					`level=info org_id=fake msg="executing query" type=range query=.* length=5s step=1m0s query_hash=%d.*`, expectedQueryHash,
-				),
-			),
-			queryWithEngine(),
-		)
-
-		require.Regexp(t,
-			regexp.MustCompile(
-				fmt.Sprintf(
-					`level=info org_id=fake latency=slow query=".*" query_hash=%d query_type=metric range_type=range.*\n`, expectedQueryHash,
-				),
-			),
-			queryDirectly(),
-		)
+		withEngine := queryWithEngine()
+		require.Contains(t, withEngine, fmt.Sprintf("query_hash=%d", expectedQueryHash))
+		require.Contains(t, withEngine, "step=1m0s")
+
+		directly := queryDirectly()
+		require.Contains(t, directly, fmt.Sprintf("query_hash=%d", expectedQueryHash))
+		require.Contains(t, directly, "length=5s")
+		require.Contains(t, directly, "latency=slow")
 	}
 }