diff --git a/docs-website/router/configuration/template-expressions.mdx b/docs-website/router/configuration/template-expressions.mdx index 5b1f7aeb76..7ba3c5bfd6 100644 --- a/docs-website/router/configuration/template-expressions.mdx +++ b/docs-website/router/configuration/template-expressions.mdx @@ -64,8 +64,9 @@ The `request` object is a read-only entity that provides details about the incom - `request.operation` - `request.operation.name` - `request.operation.type` (possible values: `mutation` or `query` ) -- `request.operation.hash` -- `request.operation.sha256Hash` +- `request.operation.hash` - Hash of the normalized operation. Computed before variable remapping, so queries with different variable names produce different hashes. Identical queries with different skip/include variable values also produce different hashes because normalization inlines those directives. +- `request.operation.queryPlanHash` - The Hash used as the query plan cache key. Computed after variable remapping (e.g. `$myId` and `$eid` both become `$0`) and includes skip/include variable values. Two requests share the same `queryPlanHash` when they resolve to the same query plan. +- `request.operation.sha256Hash` - SHA-256 hash of the original operation query string sent by the client. Identical for all requests that send the same raw query body, regardless of variable values. - `request.operation.parsingTime` (time.Duration) - `request.operation.persistedId` - `request.operation.normalizationTime` (time.Duration) diff --git a/router-tests/observability/structured_logging_test.go b/router-tests/observability/structured_logging_test.go index 8b056720b5..cb586086b8 100644 --- a/router-tests/observability/structured_logging_test.go +++ b/router-tests/observability/structured_logging_test.go @@ -4200,6 +4200,202 @@ func TestAccessLogs(t *testing.T) { }, ) }) + + t.Run("validate queryPlanHash differs with skip/include variations", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "sha256_hash", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.sha256Hash", + }, + }, + { + Key: "operation_hash", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.hash", + }, + }, + { + Key: "query_plan_hash", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryPlanHash", + }, + }, + { + Key: "plan_cache_hit", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.planCacheHit", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + }, func(t *testing.T, xEnv *testenv.Environment) { + query := `query Employee( $id: Int! = 4 $withAligators: Boolean! $withCats: Boolean! $skipDogs:Boolean! $skipMouses:Boolean! ) { employee(id: $id) { details { pets { name __typename ...AlligatorFields @include(if: $withAligators) ...CatFields @include(if: $withCats) ...DogFields @skip(if: $skipDogs) ...MouseFields @skip(if: $skipMouses) ...PonyFields @include(if: false) } } } } fragment AlligatorFields on Alligator { __typename class dangerous gender name } fragment CatFields on Cat { __typename class gender name type } fragment DogFields on Dog { __typename breed class gender name } fragment MouseFields on Mouse { __typename class gender name } fragment PonyFields on Pony { __typename class gender name }` + + // First request: skipMouses=true, id=4 + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + OperationName: []byte(`"Employee"`), + Query: query, + Variables: []byte(`{"id": 4,"withAligators": true,"withCats": true,"skipDogs": false,"skipMouses": true}`), + }) + + // Second request: skipMouses=false (same query body, different skip/include variable) + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + OperationName: []byte(`"Employee"`), + Query: query, + Variables: []byte(`{"id": 4,"withAligators": true,"withCats": true,"skipDogs": false,"skipMouses": false}`), + }) + + // Third request: same as first (should be plan cache hit) + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + OperationName: []byte(`"Employee"`), + Query: query, + Variables: []byte(`{"id": 4,"withAligators": true,"withCats": true,"skipDogs": false,"skipMouses": true}`), + }) + + // Fourth request: different id (same queryPlanHash as first, different non-skip/include variable) + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + OperationName: []byte(`"Employee"`), + Query: query, + Variables: []byte(`{"id": 3,"withAligators": true,"withCats": true,"skipDogs": false,"skipMouses": true}`), + }) + + requestLogs := xEnv.Observer().FilterMessage("/graphql").All() + require.Len(t, requestLogs, 4) + + ctx1 := requestLogs[0].ContextMap() + ctx2 := requestLogs[1].ContextMap() + ctx3 := requestLogs[2].ContextMap() + ctx4 := requestLogs[3].ContextMap() + + // All four requests use the same query body, so sha256Hash must be identical + sha256First, ok := ctx1["sha256_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, sha256First) + sha256Second, ok := ctx2["sha256_hash"].(string) + require.True(t, ok) + require.Equal(t, sha256First, sha256Second, "sha256Hash should be the same for identical query bodies") + sha256Third, ok := ctx3["sha256_hash"].(string) + require.True(t, ok) + require.Equal(t, sha256First, sha256Third, "sha256Hash should be the same for identical query bodies") + sha256Fourth, ok := ctx4["sha256_hash"].(string) + require.True(t, ok) + require.Equal(t, sha256First, sha256Fourth, "sha256Hash should be the same for identical query bodies") + + // hash (analytics hash of normalized operation) differs with skip/include + // because normalization produces different operations for different skip/include values + hash1, ok := ctx1["operation_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, hash1) + hash2, ok := ctx2["operation_hash"].(string) + require.True(t, ok) + require.NotEqual(t, hash1, hash2, "hash should differ when skip/include variables change") + hash3, ok := ctx3["operation_hash"].(string) + require.True(t, ok) + require.Equal(t, hash1, hash3, "hash should be the same for identical skip/include values") + // hash should be the same for request 1 and 4 (same skip/include, different id) + hash4, ok := ctx4["operation_hash"].(string) + require.True(t, ok) + require.Equal(t, hash1, hash4, "hash should be the same when only non-skip/include variables change") + + // queryPlanHash should differ between request 1 and 2 (different skip/include values) + queryPlanHash1, ok := ctx1["query_plan_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, queryPlanHash1) + queryPlanHash2, ok := ctx2["query_plan_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, queryPlanHash2) + require.NotEqual(t, queryPlanHash1, queryPlanHash2, "queryPlanHash should differ when skip/include variables change") + + // queryPlanHash should be the same for request 1 and 3 (same skip/include values) + queryPlanHash3, ok := ctx3["query_plan_hash"].(string) + require.True(t, ok) + require.Equal(t, queryPlanHash1, queryPlanHash3, "queryPlanHash should be the same for identical skip/include values") + + // queryPlanHash should be the same for request 1 and 4 (same skip/include, different id) + queryPlanHash4, ok := ctx4["query_plan_hash"].(string) + require.True(t, ok) + require.Equal(t, queryPlanHash1, queryPlanHash4, "queryPlanHash should be the same when only non-skip/include variables change") + + // Third request should be a plan cache hit (same queryPlanHash as first) + planCacheHit3, ok := ctx3["plan_cache_hit"].(bool) + require.True(t, ok) + require.True(t, planCacheHit3, "third request should be a plan cache hit") + }) + }) + + t.Run("validate hash differs but queryPlanHash matches for queries with different variable names", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "operation_hash", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.hash", + }, + }, + { + Key: "query_plan_hash", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryPlanHash", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + }, func(t *testing.T, xEnv *testenv.Environment) { + // Two queries with different variable names but identical structure. + // The operation names differ but hash is computed with a static empty name, + // so operation name does not affect hash — only the variable names ($myId vs $eid) do. + // hash is computed before variable remapping, so different variable names produce different hashes. + // queryPlanHash is computed after variable remapping ($myId/$eid both become $0), so they match. + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + OperationName: []byte(`"EmployeeA"`), + Query: `query EmployeeA($myId: Int!) { employee(id: $myId) { id } }`, + Variables: []byte(`{"myId": 4}`), + }) + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + OperationName: []byte(`"EmployeeB"`), + Query: `query EmployeeB($eid: Int!) { employee(id: $eid) { id } }`, + Variables: []byte(`{"eid": 4}`), + }) + + requestLogs := xEnv.Observer().FilterMessage("/graphql").All() + require.Len(t, requestLogs, 2) + + ctxA := requestLogs[0].ContextMap() + ctxB := requestLogs[1].ContextMap() + + // hash should differ (pre-remapping: different variable names $myId vs $eid) + hashA, ok := ctxA["operation_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, hashA) + hashB, ok := ctxB["operation_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, hashB) + require.NotEqual(t, hashA, hashB, "hash should differ because variable names differ before remapping") + + // queryPlanHash should match (post-remapping: both $myId and $eid become $0) + queryPlanHashA, ok := ctxA["query_plan_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, queryPlanHashA) + queryPlanHashB, ok := ctxB["query_plan_hash"].(string) + require.True(t, ok) + require.NotEmpty(t, queryPlanHashB) + require.Equal(t, queryPlanHashA, queryPlanHashB, "queryPlanHash should match because variable names are remapped to canonical names") + }) + }) }) } diff --git a/router/core/graphql_prehandler.go b/router/core/graphql_prehandler.go index 122f848cd0..8c6bbb0af6 100644 --- a/router/core/graphql_prehandler.go +++ b/router/core/graphql_prehandler.go @@ -978,6 +978,9 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera requestContext.expressionContext.Request.Operation.Hash = operationHash setTelemetryAttributes(normalizeCtx, requestContext, expr.BucketHash) + requestContext.expressionContext.Request.Operation.QueryPlanHash = strconv.FormatUint(requestContext.operation.internalHash, 10) + setTelemetryAttributes(normalizeCtx, requestContext, expr.BucketQueryPlanHash) + if !requestContext.operation.traceOptions.ExcludeNormalizeStats { httpOperation.traceTimings.EndNormalize() } diff --git a/router/internal/expr/expr.go b/router/internal/expr/expr.go index e0f9b1ad33..1434a83114 100644 --- a/router/internal/expr/expr.go +++ b/router/internal/expr/expr.go @@ -86,6 +86,7 @@ type Operation struct { PersistedID string `expr:"persistedId"` NormalizationTime time.Duration `expr:"normalizationTime"` Hash string `expr:"hash"` + QueryPlanHash string `expr:"queryPlanHash"` ValidationTime time.Duration `expr:"validationTime"` PlanningTime time.Duration `expr:"planningTime"` diff --git a/router/internal/expr/request_operation_bucket_visitor.go b/router/internal/expr/request_operation_bucket_visitor.go index 9e64106683..75765d2f37 100644 --- a/router/internal/expr/request_operation_bucket_visitor.go +++ b/router/internal/expr/request_operation_bucket_visitor.go @@ -16,6 +16,7 @@ const ( BucketPersistedID BucketNormalizationTime BucketHash + BucketQueryPlanHash BucketValidationTime BucketPlanningTime BucketSubgraph @@ -23,7 +24,7 @@ const ( // RequestOperationBucketVisitor inspects nodes and sets Bucket to the highest-priority match // Priority (low -> high): any, auth, sha256, parsingTime, name/type, persistedId, normalizationTime, -// hash, validationTime, planningTime, subgraph +// hash, queryPlanHash, validationTime, planningTime, subgraph type RequestOperationBucketVisitor struct { Bucket AttributeBucket } @@ -90,6 +91,8 @@ func (v *RequestOperationBucketVisitor) Visit(baseNode *ast.Node) { v.setBucketIfHigher(BucketNormalizationTime) case "hash": v.setBucketIfHigher(BucketHash) + case "queryPlanHash": + v.setBucketIfHigher(BucketQueryPlanHash) case "validationTime": v.setBucketIfHigher(BucketValidationTime) case "planningTime": diff --git a/router/internal/expr/request_operation_bucket_visitor_test.go b/router/internal/expr/request_operation_bucket_visitor_test.go index 9e4989b09e..5ba1a77574 100644 --- a/router/internal/expr/request_operation_bucket_visitor_test.go +++ b/router/internal/expr/request_operation_bucket_visitor_test.go @@ -152,6 +152,20 @@ func TestRequestOperationBucketVisitor(t *testing.T) { description: "Hash with bracket notation should use hash bucket", }, + // BucketQueryPlanHash - request.operation.queryPlanHash + { + name: "operation queryPlanHash", + expression: `request.operation.queryPlanHash == "12345"`, + expectedBucket: BucketQueryPlanHash, + description: "Query plan hash access should use query plan hash bucket", + }, + { + name: "queryPlanHash with bracket notation", + expression: `request["operation"]["queryPlanHash"]`, + expectedBucket: BucketQueryPlanHash, + description: "Query plan hash with bracket notation should use query plan hash bucket", + }, + // BucketValidationTime - request.operation.validationTime { name: "validationTime", @@ -335,6 +349,8 @@ func bucketName(bucket AttributeBucket) string { return "BucketNormalizationTime" case BucketHash: return "BucketHash" + case BucketQueryPlanHash: + return "BucketQueryPlanHash" case BucketValidationTime: return "BucketValidationTime" case BucketPlanningTime: @@ -360,7 +376,8 @@ func TestBucketPriority(t *testing.T) { assert.True(t, BucketNameOrType < BucketPersistedID, "NameOrType should be lower priority than PersistedID") assert.True(t, BucketPersistedID < BucketNormalizationTime, "PersistedID should be lower priority than NormalizationTime") assert.True(t, BucketNormalizationTime < BucketHash, "NormalizationTime should be lower priority than Hash") - assert.True(t, BucketHash < BucketValidationTime, "Hash should be lower priority than ValidationTime") + assert.True(t, BucketHash < BucketQueryPlanHash, "Hash should be lower priority than QueryPlanHash") + assert.True(t, BucketQueryPlanHash < BucketValidationTime, "QueryPlanHash should be lower priority than ValidationTime") assert.True(t, BucketValidationTime < BucketPlanningTime, "ValidationTime should be lower priority than PlanningTime") assert.True(t, BucketPlanningTime < BucketSubgraph, "PlanningTime should be lower priority than Subgraph") }