diff --git a/docs-website/router/configuration/template-expressions.mdx b/docs-website/router/configuration/template-expressions.mdx index 9b901873d1..5b1f7aeb76 100644 --- a/docs-website/router/configuration/template-expressions.mdx +++ b/docs-website/router/configuration/template-expressions.mdx @@ -71,6 +71,11 @@ The `request` object is a read-only entity that provides details about the incom - `request.operation.normalizationTime` (time.Duration) - `request.operation.validationTime` (time.Duration) - `request.operation.planningTime` (time.Duration) +- `request.operation.normalizationCacheHit` (bool) +- `request.operation.variablesNormalizationCacheHit` (bool) +- `request.operation.variablesRemappingCacheHit` (bool) +- `request.operation.persistedOperationCacheHit` (bool) +- `request.operation.planCacheHit` (bool) #### Example expressions @@ -78,6 +83,7 @@ The `request` object is a read-only entity that provides details about the incom hasPrefix(request.operation.name, 'Delete') == true request.operation.sha256Hash != '' request.operation.persistedId != '' +request.operation.planCacheHit == true ``` ### Client Object diff --git a/router-tests/observability/structured_logging_test.go b/router-tests/observability/structured_logging_test.go index f6b7885d4f..8b056720b5 100644 --- a/router-tests/observability/structured_logging_test.go +++ b/router-tests/observability/structured_logging_test.go @@ -2912,6 +2912,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) }) }) + }) t.Run("verify error codes from engine and not subgraph", func(t *testing.T) { @@ -3976,6 +3977,232 @@ func TestFlakyAccessLogs(t *testing.T) { } +func TestAccessLogs(t *testing.T) { + t.Parallel() + + t.Run("expression field logging", func(t *testing.T) { + t.Parallel() + + t.Run("validate request.operation.normalizationCacheHit expression", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "normalization_cache_hit", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.normalizationCacheHit", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + }, + func(t *testing.T, xEnv *testenv.Environment) { + // First request: cache miss + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog := xEnv.Observer().FilterMessage("/graphql") + requestContext := requestLog.All()[0].ContextMap() + val, ok := requestContext["normalization_cache_hit"].(bool) + require.True(t, ok) + require.False(t, val) + + // Second request: cache hit + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog = xEnv.Observer().FilterMessage("/graphql") + requestContext = requestLog.All()[1].ContextMap() + val, ok = requestContext["normalization_cache_hit"].(bool) + require.True(t, ok) + require.True(t, val) + }, + ) + }) + + t.Run("validate request.operation.variablesNormalizationCacheHit expression", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "variables_normalization_cache_hit", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.variablesNormalizationCacheHit", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + }, + func(t *testing.T, xEnv *testenv.Environment) { + // First request: cache miss + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog := xEnv.Observer().FilterMessage("/graphql") + requestContext := requestLog.All()[0].ContextMap() + val, ok := requestContext["variables_normalization_cache_hit"].(bool) + require.True(t, ok) + require.False(t, val) + + // Second request: cache hit + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog = xEnv.Observer().FilterMessage("/graphql") + requestContext = requestLog.All()[1].ContextMap() + val, ok = requestContext["variables_normalization_cache_hit"].(bool) + require.True(t, ok) + require.True(t, val) + }, + ) + }) + + t.Run("validate request.operation.variablesRemappingCacheHit expression", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "variables_remapping_cache_hit", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.variablesRemappingCacheHit", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + }, + func(t *testing.T, xEnv *testenv.Environment) { + // First request: cache miss + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog := xEnv.Observer().FilterMessage("/graphql") + requestContext := requestLog.All()[0].ContextMap() + val, ok := requestContext["variables_remapping_cache_hit"].(bool) + require.True(t, ok) + require.False(t, val) + + // Second request: cache hit + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog = xEnv.Observer().FilterMessage("/graphql") + requestContext = requestLog.All()[1].ContextMap() + val, ok = requestContext["variables_remapping_cache_hit"].(bool) + require.True(t, ok) + require.True(t, val) + }, + ) + }) + + t.Run("validate request.operation.persistedOperationCacheHit expression", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + Key: "persisted_operation_cache_hit", + ValueFrom: &config.CustomDynamicAttribute{ + Expression: "request.operation.persistedOperationCacheHit", + }, + }, + }, + LogObservation: testenv.LogObservationConfig{ + Enabled: true, + LogLevel: zapcore.InfoLevel, + }, + }, + func(t *testing.T, xEnv *testenv.Environment) { + // First request with persisted operation: cache miss + res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{ + OperationName: []byte(`"Employees"`), + Extensions: []byte(`{"persistedQuery": {"version": 1, "sha256Hash": "dc67510fb4289672bea757e862d6b00e83db5d3cbbcfb15260601b6f29bb2b8f"}}`), + Header: map[string][]string{"graphql-client-name": {"my-client"}}, + }) + require.NoError(t, err) + require.JSONEq(t, testutils.EmployeesIDData, res.Body) + requestLog := xEnv.Observer().FilterMessage("/graphql") + requestContext := requestLog.All()[0].ContextMap() + val, ok := requestContext["persisted_operation_cache_hit"].(bool) + require.True(t, ok) + require.False(t, val) + + // Second request: cache hit + res, err = xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{ + OperationName: []byte(`"Employees"`), + Extensions: []byte(`{"persistedQuery": {"version": 1, "sha256Hash": "dc67510fb4289672bea757e862d6b00e83db5d3cbbcfb15260601b6f29bb2b8f"}}`), + Header: map[string][]string{"graphql-client-name": {"my-client"}}, + }) + require.NoError(t, err) + require.JSONEq(t, testutils.EmployeesIDData, res.Body) + requestLog = xEnv.Observer().FilterMessage("/graphql") + requestContext = requestLog.All()[1].ContextMap() + val, ok = requestContext["persisted_operation_cache_hit"].(bool) + require.True(t, ok) + require.True(t, val) + }, + ) + }) + + t.Run("validate request.operation.planCacheHit expression", func(t *testing.T) { + t.Parallel() + + testenv.Run(t, + &testenv.Config{ + AccessLogFields: []config.CustomAttribute{ + { + 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) { + // First request: cache miss + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog := xEnv.Observer().FilterMessage("/graphql") + requestContext := requestLog.All()[0].ContextMap() + val, ok := requestContext["plan_cache_hit"].(bool) + require.True(t, ok) + require.False(t, val) + + // Second request: cache hit + xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{ + Query: `query employees { employees { id } }`, + }) + requestLog = xEnv.Observer().FilterMessage("/graphql") + requestContext = requestLog.All()[1].ContextMap() + val, ok = requestContext["plan_cache_hit"].(bool) + require.True(t, ok) + require.True(t, val) + }, + ) + }) + }) +} + func checkValues(t *testing.T, requestContext map[string]interface{}, expectedValues map[string]interface{}, additionalExpectedKeys []string) { t.Helper() diff --git a/router/core/graphql_prehandler.go b/router/core/graphql_prehandler.go index c0098cd3d3..443b0430e5 100644 --- a/router/core/graphql_prehandler.go +++ b/router/core/graphql_prehandler.go @@ -628,6 +628,7 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera span.End() requestContext.operation.persistedOperationCacheHit = operationKit.parsedOperation.PersistedOperationCacheHit + requestContext.expressionContext.Request.Operation.PersistedOperationCacheHit = operationKit.parsedOperation.PersistedOperationCacheHit } // If the persistent operation is already in the cache, we skip the parse step @@ -810,6 +811,7 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera engineNormalizeSpan.SetAttributes(otel.WgNormalizationCacheHit.Bool(cached)) requestContext.operation.normalizationCacheHit = operationKit.parsedOperation.NormalizationCacheHit + requestContext.expressionContext.Request.Operation.NormalizationCacheHit = operationKit.parsedOperation.NormalizationCacheHit /** * Normalize the variables @@ -832,6 +834,7 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera } engineNormalizeSpan.SetAttributes(otel.WgVariablesNormalizationCacheHit.Bool(cached)) requestContext.operation.variablesNormalizationCacheHit = cached + requestContext.expressionContext.Request.Operation.VariablesNormalizationCacheHit = cached // Update file upload paths if they were used in the nested field of the extracted variables. for mapping := range slices.Values(uploadsMapping) { @@ -883,6 +886,7 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera engineNormalizeSpan.SetAttributes(otel.WgVariablesRemappingCacheHit.Bool(cached)) requestContext.operation.variablesRemappingCacheHit = cached + requestContext.expressionContext.Request.Operation.VariablesRemappingCacheHit = cached requestContext.operation.hash = operationKit.parsedOperation.ID requestContext.operation.internalHash = operationKit.parsedOperation.InternalID requestContext.operation.remapVariables = operationKit.parsedOperation.RemapVariables @@ -1100,6 +1104,7 @@ func (h *PreHandler) handleOperation(req *http.Request, httpOperation *httpOpera requestContext.expressionContext.Request.Operation.PlanningTime = requestContext.operation.planningTime setTelemetryAttributes(planCtx, requestContext, expr.BucketPlanningTime) + requestContext.expressionContext.Request.Operation.PlanCacheHit = requestContext.operation.planCacheHit enginePlanSpan.SetAttributes(otel.WgEnginePlanCacheHit.Bool(requestContext.operation.planCacheHit)) enginePlanSpan.End() diff --git a/router/internal/expr/expr.go b/router/internal/expr/expr.go index 64f3324958..e0f9b1ad33 100644 --- a/router/internal/expr/expr.go +++ b/router/internal/expr/expr.go @@ -88,6 +88,12 @@ type Operation struct { Hash string `expr:"hash"` ValidationTime time.Duration `expr:"validationTime"` PlanningTime time.Duration `expr:"planningTime"` + + NormalizationCacheHit bool `expr:"normalizationCacheHit"` + VariablesNormalizationCacheHit bool `expr:"variablesNormalizationCacheHit"` + VariablesRemappingCacheHit bool `expr:"variablesRemappingCacheHit"` + PersistedOperationCacheHit bool `expr:"persistedOperationCacheHit"` + PlanCacheHit bool `expr:"planCacheHit"` } type Client struct {