Skip to content
Merged
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
214 changes: 214 additions & 0 deletions router-tests/observability/structured_logging_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -4200,6 +4200,220 @@ func TestAccessLogs(t *testing.T) {
},
)
})

t.Run("validate normalizedHash and variablesHash differ 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: "normalized_hash",
ValueFrom: &config.CustomDynamicAttribute{
Expression: "request.operation.normalizedHash",
},
},
{
Key: "variables_hash",
ValueFrom: &config.CustomDynamicAttribute{
Expression: "request.operation.variablesHash",
},
},
{
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 (changes variablesHash but not normalizedHash)
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")

// normalizedHash should differ between request 1 and 2 (different skip/include values)
normalizedHash1, ok := ctx1["normalized_hash"].(string)
require.True(t, ok)
require.NotEmpty(t, normalizedHash1)
normalizedHash2, ok := ctx2["normalized_hash"].(string)
require.True(t, ok)
require.NotEmpty(t, normalizedHash2)
require.NotEqual(t, normalizedHash1, normalizedHash2, "normalizedHash should differ when skip/include variables change")

// normalizedHash should be the same for request 1 and 3 (same skip/include values)
normalizedHash3, ok := ctx3["normalized_hash"].(string)
require.True(t, ok)
require.Equal(t, normalizedHash1, normalizedHash3, "normalizedHash should be the same for identical skip/include values")

// normalizedHash should be the same for request 1 and 4 (same skip/include, different id)
normalizedHash4, ok := ctx4["normalized_hash"].(string)
require.True(t, ok)
require.Equal(t, normalizedHash1, normalizedHash4, "normalizedHash should be the same when only non-skip/include variables change")

// variablesHash should differ between request 1 and 4 (different id value)
variablesHash1, ok := ctx1["variables_hash"].(string)
require.True(t, ok)
require.NotEmpty(t, variablesHash1)
variablesHash4, ok := ctx4["variables_hash"].(string)
require.True(t, ok)
require.NotEmpty(t, variablesHash4)
require.NotEqual(t, variablesHash1, variablesHash4, "variablesHash should differ when variable values change")

// variablesHash should be the same for request 1 and 3 (same variable values)
variablesHash3, ok := ctx3["variables_hash"].(string)
require.True(t, ok)
require.Equal(t, variablesHash1, variablesHash3, "variablesHash should be the same for identical variable values")

// Third request should be a plan cache hit (same normalizedHash 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 normalizedHash 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: "normalized_hash",
ValueFrom: &config.CustomDynamicAttribute{
Expression: "request.operation.normalizedHash",
},
},
},
LogObservation: testenv.LogObservationConfig{
Enabled: true,
LogLevel: zapcore.InfoLevel,
},
}, func(t *testing.T, xEnv *testenv.Environment) {
// Two queries with different variable names but identical structure.
// hash is computed before variable remapping, so different variable names produce different hashes.
// normalizedHash 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}`),
})
Comment thread
coderabbitai[bot] marked this conversation as resolved.

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")

// normalizedHash should match (post-remapping: both $myId and $eid become $0)
normalizedHashA, ok := ctxA["normalized_hash"].(string)
require.True(t, ok)
require.NotEmpty(t, normalizedHashA)
normalizedHashB, ok := ctxB["normalized_hash"].(string)
require.True(t, ok)
require.NotEmpty(t, normalizedHashB)
require.Equal(t, normalizedHashA, normalizedHashB, "normalizedHash should match because variable names are remapped to canonical names")
})
})
})
}

Expand Down
4 changes: 4 additions & 0 deletions router/core/graphql_prehandler.go
Original file line number Diff line number Diff line change
Expand Up @@ -962,6 +962,7 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera
requestContext.operation.rawContent = operationKit.parsedOperation.Request.Query
requestContext.operation.content = operationKit.parsedOperation.NormalizedRepresentation
requestContext.operation.variablesHash = operationKit.parsedOperation.VariablesHash
requestContext.expressionContext.Request.Operation.VariablesHash = strconv.FormatUint(requestContext.operation.variablesHash, 10)
requestContext.operation.variables, err = astjson.ParseBytes(operationKit.parsedOperation.Request.Variables)
if err != nil {
rtrace.AttachErrToSpan(engineNormalizeSpan, err)
Expand All @@ -978,6 +979,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.NormalizedHash = strconv.FormatUint(requestContext.operation.internalHash, 10)
setTelemetryAttributes(normalizeCtx, requestContext, expr.BucketNormalizedHash)

if !requestContext.operation.traceOptions.ExcludeNormalizeStats {
httpOperation.traceTimings.EndNormalize()
}
Expand Down
2 changes: 2 additions & 0 deletions router/internal/expr/expr.go
Original file line number Diff line number Diff line change
Expand Up @@ -86,6 +86,8 @@ type Operation struct {
PersistedID string `expr:"persistedId"`
NormalizationTime time.Duration `expr:"normalizationTime"`
Hash string `expr:"hash"`
NormalizedHash string `expr:"normalizedHash"`
VariablesHash string `expr:"variablesHash"`
ValidationTime time.Duration `expr:"validationTime"`
PlanningTime time.Duration `expr:"planningTime"`

Expand Down
7 changes: 5 additions & 2 deletions router/internal/expr/request_operation_bucket_visitor.go
Original file line number Diff line number Diff line change
Expand Up @@ -16,14 +16,15 @@ const (
BucketPersistedID
BucketNormalizationTime
BucketHash
BucketNormalizedHash
BucketValidationTime
BucketPlanningTime
BucketSubgraph
)

// 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/variablesHash, normalizedHash, validationTime, planningTime, subgraph
type RequestOperationBucketVisitor struct {
Bucket AttributeBucket
}
Expand Down Expand Up @@ -88,8 +89,10 @@ func (v *RequestOperationBucketVisitor) Visit(baseNode *ast.Node) {
v.setBucketIfHigher(BucketPersistedID)
case "normalizationTime":
v.setBucketIfHigher(BucketNormalizationTime)
case "hash":
case "hash", "variablesHash":
v.setBucketIfHigher(BucketHash)
case "normalizedHash":
v.setBucketIfHigher(BucketNormalizedHash)
case "validationTime":
v.setBucketIfHigher(BucketValidationTime)
case "planningTime":
Expand Down
33 changes: 32 additions & 1 deletion router/internal/expr/request_operation_bucket_visitor_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -152,6 +152,34 @@ func TestRequestOperationBucketVisitor(t *testing.T) {
description: "Hash with bracket notation should use hash bucket",
},

// BucketNormalizedHash - request.operation.normalizedHash
{
name: "operation normalizedHash",
expression: `request.operation.normalizedHash == "12345"`,
expectedBucket: BucketNormalizedHash,
description: "Normalized hash access should use normalized hash bucket",
},
{
name: "normalizedHash with bracket notation",
expression: `request["operation"]["normalizedHash"]`,
expectedBucket: BucketNormalizedHash,
description: "Normalized hash with bracket notation should use normalized hash bucket",
},

// BucketHash - request.operation.variablesHash
{
name: "operation variablesHash",
expression: `request.operation.variablesHash == "67890"`,
expectedBucket: BucketHash,
description: "Variables hash access should use hash bucket",
},
{
name: "variablesHash with bracket notation",
expression: `request["operation"]["variablesHash"]`,
expectedBucket: BucketHash,
description: "Variables hash with bracket notation should use hash bucket",
},
Comment thread
SkArchon marked this conversation as resolved.
Outdated

// BucketValidationTime - request.operation.validationTime
{
name: "validationTime",
Expand Down Expand Up @@ -335,6 +363,8 @@ func bucketName(bucket AttributeBucket) string {
return "BucketNormalizationTime"
case BucketHash:
return "BucketHash"
case BucketNormalizedHash:
return "BucketNormalizedHash"
case BucketValidationTime:
return "BucketValidationTime"
case BucketPlanningTime:
Expand All @@ -360,7 +390,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 < BucketNormalizedHash, "Hash should be lower priority than NormalizedHash")
assert.True(t, BucketNormalizedHash < BucketValidationTime, "NormalizedHash 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")
}
Expand Down
Loading