feat: add cache hit statuses to expr context

docs-website/router/configuration/template-expressions.mdx

@@ -71,13 +71,19 @@ 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
 
 ```bash
 hasPrefix(request.operation.name, 'Delete') == true
 request.operation.sha256Hash != ''
 request.operation.persistedId != ''
+request.operation.planCacheHit == true
 ```
 
 ### Client Object

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

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

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 {