diff --git a/docs-website/router/access-logs.mdx b/docs-website/router/access-logs.mdx index 8cf7c1f31..2300ac979 100644 --- a/docs-website/router/access-logs.mdx +++ b/docs-website/router/access-logs.mdx @@ -296,6 +296,41 @@ The response type of the expression is validated upon startup. You should ensure Note that while `subgraph` attributes can be accessed in the request logger, it will always have "zero" values. +#### Logging operation complexity + +Router access-log expressions can record the operation complexity values that are also attached to validation traces. Configure `security.complexity_limits` first. Use `measure` mode to calculate the values without rejecting operations. + +```yaml +security: + complexity_calculation_cache: + enabled: true + size: 1024 + complexity_limits: + mode: measure + +access_logs: + enabled: true + router: + fields: + - key: "query_depth" + value_from: + expression: "request.operation.queryDepth" + - key: "query_total_fields" + value_from: + expression: "request.operation.queryTotalFields" + - key: "query_root_fields" + value_from: + expression: "request.operation.queryRootFields" + - key: "query_root_field_aliases" + value_from: + expression: "request.operation.queryRootFieldAliases" + - key: "query_complexity_cache_hit" + value_from: + expression: "request.operation.queryComplexityCacheHit" +``` + +The numeric values are logged as integers and the cache status as a boolean. See [Template Expressions](/router/configuration/template-expressions#operation-object) for field definitions and lifecycle limitations. + #### Subgraph Access Log Expressions diff --git a/docs-website/router/configuration.mdx b/docs-website/router/configuration.mdx index 0a5b720fc..1b6b5e9c9 100644 --- a/docs-website/router/configuration.mdx +++ b/docs-website/router/configuration.mdx @@ -2508,6 +2508,8 @@ security: operation_name_length_limit: 1024 ``` +Both complexity modes calculate and expose operation complexity. `measure` reports the values without rejecting requests. `enforce` reports the same values and rejects requests that exceed enabled limits. The calculated values and cache status can be seen on the traces or added to router access logs with [operation complexity expressions](/router/access-logs#logging-operation-complexity). + Query Depth is now deprecated. We recommend using the `security.complexity_calculation_cache` and `security.complexity_limits` diff --git a/docs-website/router/configuration/template-expressions.mdx b/docs-website/router/configuration/template-expressions.mdx index 596503f25..627a7ee75 100644 --- a/docs-website/router/configuration/template-expressions.mdx +++ b/docs-website/router/configuration/template-expressions.mdx @@ -78,8 +78,14 @@ The `request` object is a read-only entity that provides details about the incom - `request.operation.variablesRemappingCacheHit` (bool) - `request.operation.persistedOperationCacheHit` (bool) - `request.operation.planCacheHit` (bool) +- `request.operation.queryDepth` (int) - Maximum nesting depth calculated for the operation. +- `request.operation.queryTotalFields` (int) - Calculated total-fields complexity value evaluated against `security.complexity_limits.total_fields`. +- `request.operation.queryRootFields` (int) - Number of root fields without aliases. +- `request.operation.queryRootFieldAliases` (int) - Number of root fields that use aliases. +- `request.operation.queryComplexityCacheHit` (bool) - Whether all four query complexity values were reused from the complexity calculation cache. - `request.operation.variables` - The operation variables sent with the request, as a JSON string. The value can contain sensitive data and can be large, so log it with care. It is only serialized when an expression references it, so configurations that do not use it pay no cost. +The query complexity fields are calculated during validation when `security.complexity_limits` is configured. They remain zero-valued when complexity limits are not configured or a request exits before validation. Use `mode: measure` to collect them without rejecting operations. Aliased root fields are counted in `queryRootFieldAliases`, not `queryRootFields`. The serialization of `request.operation.variables` is decided once per request across the whole configuration. If any access log, metric, telemetry, tracing, or rate-limiter expression references it, it is serialized; otherwise it is skipped. @@ -94,6 +100,8 @@ hasPrefix(request.operation.name, 'Delete') == true request.operation.sha256Hash != '' request.operation.persistedId != '' request.operation.planCacheHit == true +request.operation.queryDepth > 5 +request.operation.queryComplexityCacheHit == true # Log the variables only when the variable remapping cache missed. request.operation.variablesRemappingCacheHit ? '' : request.operation.variables ``` diff --git a/router-tests/observability/structured_logging_test.go b/router-tests/observability/structured_logging_test.go index 929e523db..7abd8ef94 100644 --- a/router-tests/observability/structured_logging_test.go +++ b/router-tests/observability/structured_logging_test.go @@ -4358,6 +4358,104 @@ func TestAccessLogs(t *testing.T) { t.Run("expression field logging", func(t *testing.T) { t.Parallel() + t.Run("validate query complexity expressions for successful, rejected, and cached operations", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "query_depth", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryDepth", + }, + }, + { + Key: "query_total_fields", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryTotalFields", + }, + }, + { + Key: "query_root_fields", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryRootFields", + }, + }, + { + Key: "query_root_field_aliases", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryRootFieldAliases", + }, + }, + { + Key: "query_complexity_cache_hit", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.queryComplexityCacheHit", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + ModifySecurityConfiguration: func(securityConfiguration *config.SecurityConfiguration) { + securityConfiguration.ComplexityLimits = &config.ComplexityLimits{ + Mode: config.ComplexityLimitsModeEnforce, + Depth: &config.ComplexityLimit{ + Enabled: true, + Limit: 3, + }, + } + securityConfiguration.ComplexityCalculationCache = &config.ComplexityCalculationCache{ + Enabled: true, + CacheSize: 1024, + } + }, + ModifyEngineExecutionConfiguration: func(engineExecutionConfiguration *config.EngineExecutionConfiguration) { + engineExecutionConfiguration.Debug.SynchronousCacheWrites = true + }, + }, + func(t *testing.T, xEnv *testenv.Environment) { + successfulQuery := `query { + first: employee(id: 1) { id details { forename surname } } + employee(id: 2) { id details { forename } } + employees { id } + }` + rejectedQuery := `query { + employee(id: 1) { details { pets { name } } } + }` + + makeRequest := func(query string, expectedStatus int) { + t.Helper() + res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{Query: query}) + require.NoError(t, err) + require.Equal(t, expectedStatus, res.Response.StatusCode) + } + + makeRequest(successfulQuery, http.StatusOK) + makeRequest(successfulQuery, http.StatusOK) + makeRequest(rejectedQuery, http.StatusBadRequest) + + requestLogs := xEnv.Observer().FilterMessage("/graphql").All() + require.Len(t, requestLogs, 3) + + assertComplexityFields := func(logContext map[string]interface{}, depth, totalFields, rootFields, rootFieldAliases int64, cacheHit bool) { + t.Helper() + require.Equal(t, depth, logContext["query_depth"]) + require.Equal(t, totalFields, logContext["query_total_fields"]) + require.Equal(t, rootFields, logContext["query_root_fields"]) + require.Equal(t, rootFieldAliases, logContext["query_root_field_aliases"]) + require.Equal(t, cacheHit, logContext["query_complexity_cache_hit"]) + } + + assertComplexityFields(requestLogs[0].ContextMap(), 3, 5, 2, 1, false) + assertComplexityFields(requestLogs[1].ContextMap(), 3, 5, 2, 1, true) + assertComplexityFields(requestLogs[2].ContextMap(), 4, 3, 1, 0, false) + }, + ) + }) + t.Run("validate request.operation.normalizationCacheHit expression", func(t *testing.T) { t.Parallel() diff --git a/router-tests/telemetry/telemetry_test.go b/router-tests/telemetry/telemetry_test.go index 68e0d9db7..db664495b 100644 --- a/router-tests/telemetry/telemetry_test.go +++ b/router-tests/telemetry/telemetry_test.go @@ -10980,6 +10980,48 @@ func TestFlakyTelemetry(t *testing.T) { }) }) + t.Run("verify query complexity expression attribute", func(t *testing.T) { + t.Parallel() + + exporter := tracetest.NewInMemoryExporter(t) + + key := "custom.attribute" + + testenv.Run(t, &testenv.Config{ + TraceExporter: exporter, + CustomTracingAttributes: []config.CustomAttribute{ + { + Key: key, + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "string(request.operation.queryDepth)", + }, + }, + }, + ModifySecurityConfiguration: func(securityConfiguration *config.SecurityConfiguration) { + securityConfiguration.ComplexityLimits = &config.ComplexityLimits{ + Mode: config.ComplexityLimitsModeEnforce, + Depth: &config.ComplexityLimit{ + Enabled: true, + Limit: 2, + }, + } + }, + }, func(t *testing.T, xEnv *testenv.Environment) { + res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{ + Query: `query { employee(id: 1) { details { forename } } }`, + }) + require.NoError(t, err) + require.Equal(t, http.StatusBadRequest, res.Response.StatusCode) + + customAttribute := attribute.String(key, "3") + normalizeSpan := testutils.RequireSpanWithName(t, exporter, "Operation - Normalize") + require.NotContains(t, normalizeSpan.Attributes(), customAttribute) + + validateSpan := testutils.RequireSpanWithName(t, exporter, "Operation - Validate") + require.Contains(t, validateSpan.Attributes(), customAttribute) + }) + }) + t.Run("verify validationTime expression attribute", func(t *testing.T) { t.Parallel() diff --git a/router/core/graph_server.go b/router/core/graph_server.go index 6746fab2a..2d4229a7b 100644 --- a/router/core/graph_server.go +++ b/router/core/graph_server.go @@ -896,6 +896,9 @@ func (s *graphMux) waitForCaches() { if s.operationHashCache != nil { s.operationHashCache.Wait() } + if s.complexityCalculationCache != nil { + s.complexityCalculationCache.Wait() + } } // configureCacheMetrics sets up the cache metrics for this mux if enabled in the config. diff --git a/router/core/graphql_prehandler.go b/router/core/graphql_prehandler.go index 9c237a4ec..8a02ffecc 100644 --- a/router/core/graphql_prehandler.go +++ b/router/core/graphql_prehandler.go @@ -1065,11 +1065,18 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera // This check runs if they've configured a max query depth, and it can optionally be turned off for persisted operations if h.complexityLimits != nil { cacheHit, complexityCalcs, queryDepthErr := operationKit.ValidateQueryComplexity() + requestContext.expressionContext.Request.Operation.QueryDepth = complexityCalcs.Depth engineValidateSpan.SetAttributes(otel.WgQueryDepth.Int(complexityCalcs.Depth)) + requestContext.expressionContext.Request.Operation.QueryTotalFields = complexityCalcs.TotalFields engineValidateSpan.SetAttributes(otel.WgQueryTotalFields.Int(complexityCalcs.TotalFields)) + requestContext.expressionContext.Request.Operation.QueryRootFields = complexityCalcs.RootFields engineValidateSpan.SetAttributes(otel.WgQueryRootFields.Int(complexityCalcs.RootFields)) + requestContext.expressionContext.Request.Operation.QueryRootFieldAliases = complexityCalcs.RootFieldAliases engineValidateSpan.SetAttributes(otel.WgQueryRootFieldAliases.Int(complexityCalcs.RootFieldAliases)) + requestContext.expressionContext.Request.Operation.QueryComplexityCacheHit = cacheHit engineValidateSpan.SetAttributes(otel.WgQueryDepthCacheHit.Bool(cacheHit)) + setTelemetryAttributes(validationCtx, requestContext, expr.BucketQueryComplexity) + if queryDepthErr != nil { rtrace.AttachErrToSpan(engineValidateSpan, err) diff --git a/router/internal/expr/expr.go b/router/internal/expr/expr.go index 1a540df16..c470812fd 100644 --- a/router/internal/expr/expr.go +++ b/router/internal/expr/expr.go @@ -96,6 +96,11 @@ type Operation struct { VariablesRemappingCacheHit bool `expr:"variablesRemappingCacheHit"` PersistedOperationCacheHit bool `expr:"persistedOperationCacheHit"` PlanCacheHit bool `expr:"planCacheHit"` + QueryDepth int `expr:"queryDepth"` + QueryTotalFields int `expr:"queryTotalFields"` + QueryRootFields int `expr:"queryRootFields"` + QueryRootFieldAliases int `expr:"queryRootFieldAliases"` + QueryComplexityCacheHit bool `expr:"queryComplexityCacheHit"` // Variables is the JSON string of the operation variables sent with the request. It is only // populated when an expression references it, to avoid the serialization cost on every request. diff --git a/router/internal/expr/request_operation_bucket_visitor.go b/router/internal/expr/request_operation_bucket_visitor.go index 200f2fdee..dc5378e98 100644 --- a/router/internal/expr/request_operation_bucket_visitor.go +++ b/router/internal/expr/request_operation_bucket_visitor.go @@ -17,6 +17,7 @@ const ( BucketNormalizationTime BucketHash BucketQueryPlanHash + BucketQueryComplexity BucketValidationTime BucketPlanningTime BucketSubgraph @@ -24,7 +25,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, queryPlanHash, validationTime, planningTime, subgraph +// hash, queryPlanHash, query complexity, validationTime, planningTime, subgraph type RequestOperationBucketVisitor struct { Bucket AttributeBucket } @@ -97,6 +98,12 @@ func (v *RequestOperationBucketVisitor) Visit(baseNode *ast.Node) { v.setBucketIfHigher(BucketHash) case "queryPlanHash": v.setBucketIfHigher(BucketQueryPlanHash) + case "queryDepth", + "queryTotalFields", + "queryRootFields", + "queryRootFieldAliases", + "queryComplexityCacheHit": + v.setBucketIfHigher(BucketQueryComplexity) 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 88c365373..6bf883518 100644 --- a/router/internal/expr/request_operation_bucket_visitor_test.go +++ b/router/internal/expr/request_operation_bucket_visitor_test.go @@ -11,7 +11,7 @@ import ( // based on the attributes they access. // // Priority (low → high): Default < Auth < Sha256 < ParsingTime < NameOrType < PersistedID < -// NormalizationTime < Hash < ValidationTime < PlanningTime < Subgraph +// NormalizationTime < Hash < QueryPlanHash < QueryComplexity < ValidationTime < PlanningTime < Subgraph func TestRequestOperationBucketVisitor(t *testing.T) { t.Parallel() @@ -186,6 +186,50 @@ func TestRequestOperationBucketVisitor(t *testing.T) { description: "Query plan hash with bracket notation should use query plan hash bucket", }, + // BucketQueryComplexity - request.operation query complexity fields + { + name: "query depth", + expression: `request.operation.queryDepth`, + expectedBucket: BucketQueryComplexity, + description: "Query depth should use the query complexity bucket", + }, + { + name: "query total fields", + expression: `request.operation.queryTotalFields`, + expectedBucket: BucketQueryComplexity, + description: "Query total fields should use the query complexity bucket", + }, + { + name: "query root fields", + expression: `request.operation.queryRootFields`, + expectedBucket: BucketQueryComplexity, + description: "Query root fields should use the query complexity bucket", + }, + { + name: "query root field aliases", + expression: `request.operation.queryRootFieldAliases`, + expectedBucket: BucketQueryComplexity, + description: "Query root field aliases should use the query complexity bucket", + }, + { + name: "query complexity cache hit", + expression: `request.operation.queryComplexityCacheHit`, + expectedBucket: BucketQueryComplexity, + description: "Query complexity cache status should use the query complexity bucket", + }, + { + name: "query complexity with bracket notation", + expression: `request["operation"]["queryDepth"]`, + expectedBucket: BucketQueryComplexity, + description: "Query complexity with bracket notation should use the query complexity bucket", + }, + { + name: "query plan hash and query complexity", + expression: `request.operation.queryPlanHash != "" && request.operation.queryDepth > 0`, + expectedBucket: BucketQueryComplexity, + description: "Query complexity is higher priority than query plan hash", + }, + // BucketValidationTime - request.operation.validationTime { name: "validationTime", @@ -199,6 +243,12 @@ func TestRequestOperationBucketVisitor(t *testing.T) { expectedBucket: BucketValidationTime, description: "Validation time is higher priority than hash", }, + { + name: "validationTime and query complexity", + expression: `request.operation.validationTime.Nanoseconds() > 0 && request.operation.queryDepth > 0`, + expectedBucket: BucketValidationTime, + description: "Validation time is higher priority than query complexity", + }, // BucketPlanningTime - request.operation.planningTime { @@ -213,6 +263,12 @@ func TestRequestOperationBucketVisitor(t *testing.T) { expectedBucket: BucketPlanningTime, description: "Planning time is higher priority than validation time", }, + { + name: "planningTime and query complexity", + expression: `request.operation.planningTime.Nanoseconds() > 0 && request.operation.queryDepth > 0`, + expectedBucket: BucketPlanningTime, + description: "Planning time is higher priority than query complexity", + }, // BucketSubgraph - subgraph or subgraph.* (highest priority) { @@ -371,6 +427,8 @@ func bucketName(bucket AttributeBucket) string { return "BucketHash" case BucketQueryPlanHash: return "BucketQueryPlanHash" + case BucketQueryComplexity: + return "BucketQueryComplexity" case BucketValidationTime: return "BucketValidationTime" case BucketPlanningTime: @@ -397,7 +455,8 @@ func TestBucketPriority(t *testing.T) { 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 < BucketQueryPlanHash, "Hash should be lower priority than QueryPlanHash") - assert.True(t, BucketQueryPlanHash < BucketValidationTime, "QueryPlanHash should be lower priority than ValidationTime") + assert.True(t, BucketQueryPlanHash < BucketQueryComplexity, "QueryPlanHash should be lower priority than QueryComplexity") + assert.True(t, BucketQueryComplexity < BucketValidationTime, "QueryComplexity 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") }