diff --git a/router-tests/structured_logging_test.go b/router-tests/structured_logging_test.go index 79477c4234..6b1ca9f136 100644 --- a/router-tests/structured_logging_test.go +++ b/router-tests/structured_logging_test.go @@ -403,7 +403,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -439,7 +439,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -537,7 +537,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -598,7 +598,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -643,7 +643,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -758,7 +758,7 @@ func TestFlakyAccessLogs(t *testing.T) { require.NoError(t, err) require.Equal(t, `{"errors":[{"message":"unexpected token - got: EOF want one of: [RBRACE IDENT SPREAD]","locations":[{"line":0,"column":0}]}]}`, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 7) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -877,7 +877,7 @@ func TestFlakyAccessLogs(t *testing.T) { require.NoError(t, err) require.Equal(t, `{"errors":[{"message":"Cannot query field \"notExists\" on type \"Query\".","path":["query"]}]}`, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 7) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -1010,7 +1010,7 @@ func TestFlakyAccessLogs(t *testing.T) { require.NoError(t, err) require.Equal(t, "", res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("[Recovery from panic]") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -1041,7 +1041,7 @@ func TestFlakyAccessLogs(t *testing.T) { "validation_time", } - require.NotEmpty(t, logEntries[6].Stack) + require.NotEmpty(t, logEntries[7].Stack) checkValues(t, requestContext, expectedValues, additionalExpectedKeys) }) @@ -1147,7 +1147,7 @@ func TestFlakyAccessLogs(t *testing.T) { require.NoError(t, err) require.Equal(t, "", res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 8) requestLog := xEnv.Observer().FilterMessage("[Recovery from panic]") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -1178,7 +1178,7 @@ func TestFlakyAccessLogs(t *testing.T) { "validation_time", } - require.NotEmpty(t, logEntries[6].Stack) + require.NotEmpty(t, logEntries[7].Stack) checkValues(t, requestContext, expectedValues, additionalExpectedKeys) }) @@ -1236,7 +1236,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.Equal(t, `{"errors":[{"message":"Failed to fetch from Subgraph 'products' at Path 'employees'.","extensions":{"errors":[{"message":"Unauthorized","extensions":{"code":"UNAUTHORIZED"}}],"statusCode":403}}],"data":{"employees":[{"id":1,"details":{"forename":"Jens","surname":"Neuse"},"notes":null},{"id":2,"details":{"forename":"Dustin","surname":"Deus"},"notes":null},{"id":3,"details":{"forename":"Stefan","surname":"Avram"},"notes":null},{"id":4,"details":{"forename":"Björn","surname":"Schwenzer"},"notes":null},{"id":5,"details":{"forename":"Sergiy","surname":"Petrunin"},"notes":null},{"id":7,"details":{"forename":"Suvij","surname":"Surya"},"notes":null},{"id":8,"details":{"forename":"Nithin","surname":"Kumar"},"notes":null},{"id":10,"details":{"forename":"Eelco","surname":"Wiersma"},"notes":null},{"id":11,"details":{"forename":"Alexandra","surname":"Neuse"},"notes":null},{"id":12,"details":{"forename":"David","surname":"Stutt"},"notes":null}]}}`, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 6) + require.Len(t, logEntries, 9) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 1) requestContext := requestLog.All()[0].ContextMap() @@ -1281,7 +1281,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 9) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 2) @@ -1332,7 +1332,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 9) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 2) requestContext := requestLog.All()[0].ContextMap() @@ -1437,7 +1437,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 9) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 2) requestContext := requestLog.All()[0].ContextMap() @@ -1524,7 +1524,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.JSONEq(t, employeesIDData, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 9) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 2) requestContext := requestLog.All()[0].ContextMap() @@ -1619,7 +1619,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.Equal(t, `{"errors":[{"message":"Failed to fetch from Subgraph 'products' at Path 'employees'.","extensions":{"errors":[{"message":"Unauthorized","extensions":{"code":"UNAUTHORIZED"}}],"statusCode":403}}],"data":{"employees":[{"id":1,"details":{"forename":"Jens","surname":"Neuse"},"notes":null},{"id":2,"details":{"forename":"Dustin","surname":"Deus"},"notes":null},{"id":3,"details":{"forename":"Stefan","surname":"Avram"},"notes":null},{"id":4,"details":{"forename":"Björn","surname":"Schwenzer"},"notes":null},{"id":5,"details":{"forename":"Sergiy","surname":"Petrunin"},"notes":null},{"id":7,"details":{"forename":"Suvij","surname":"Surya"},"notes":null},{"id":8,"details":{"forename":"Nithin","surname":"Kumar"},"notes":null},{"id":10,"details":{"forename":"Eelco","surname":"Wiersma"},"notes":null},{"id":11,"details":{"forename":"Alexandra","surname":"Neuse"},"notes":null},{"id":12,"details":{"forename":"David","surname":"Stutt"},"notes":null}]}}`, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 8) + require.Len(t, logEntries, 11) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 3) @@ -1802,7 +1802,7 @@ func TestFlakyAccessLogs(t *testing.T) { require.NoError(t, err) require.Equal(t, `{"data":{"employees":[{"id":1},{"id":2},{"id":3},{"id":4},{"id":5},{"id":7},{"id":8},{"id":10},{"id":11},{"id":12}]}}`, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 7) + require.Len(t, logEntries, 9) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 2) requestContext := requestLog.All()[0].ContextMap() @@ -1895,7 +1895,7 @@ func TestFlakyAccessLogs(t *testing.T) { }) require.Equal(t, `{"errors":[{"message":"Failed to fetch from Subgraph 'products' at Path 'employees'."}],"data":{"employees":[{"id":1,"details":{"forename":"Jens","surname":"Neuse"},"notes":null},{"id":2,"details":{"forename":"Dustin","surname":"Deus"},"notes":null},{"id":3,"details":{"forename":"Stefan","surname":"Avram"},"notes":null},{"id":4,"details":{"forename":"Björn","surname":"Schwenzer"},"notes":null},{"id":5,"details":{"forename":"Sergiy","surname":"Petrunin"},"notes":null},{"id":7,"details":{"forename":"Suvij","surname":"Surya"},"notes":null},{"id":8,"details":{"forename":"Nithin","surname":"Kumar"},"notes":null},{"id":10,"details":{"forename":"Eelco","surname":"Wiersma"},"notes":null},{"id":11,"details":{"forename":"Alexandra","surname":"Neuse"},"notes":null},{"id":12,"details":{"forename":"David","surname":"Stutt"},"notes":null}]}}`, res.Body) logEntries := xEnv.Observer().All() - require.Len(t, logEntries, 8) + require.Len(t, logEntries, 11) requestLog := xEnv.Observer().FilterMessage("/graphql") require.Equal(t, requestLog.Len(), 3) diff --git a/router/core/engine_loader_hooks.go b/router/core/engine_loader_hooks.go index fb4f5f09fa..f9a3c3cef0 100644 --- a/router/core/engine_loader_hooks.go +++ b/router/core/engine_loader_hooks.go @@ -47,21 +47,14 @@ type engineLoaderHooks struct { metricAttributeExpressions *attributeExpressions storeSubgraphResponseBody bool + appLogger *zap.Logger } type engineLoaderHooksRequestContext struct { startTime time.Time } -func NewEngineRequestHooks( - metricStore metric.Store, - logger *requestlogger.SubgraphAccessLogger, - tracerProvider *sdktrace.TracerProvider, - tracingAttributes *attributeExpressions, - telemetryAttributes *attributeExpressions, - metricAttributes *attributeExpressions, - storeSubgraphResponseBody bool, -) resolve.LoaderHooks { +func NewEngineRequestHooks(metricStore metric.Store, logger *requestlogger.SubgraphAccessLogger, appLogger *zap.Logger, tracerProvider *sdktrace.TracerProvider, tracingAttributes *attributeExpressions, telemetryAttributes *attributeExpressions, metricAttributes *attributeExpressions, storeSubgraphResponseBody bool) resolve.LoaderHooks { var tracer trace.Tracer if tracerProvider != nil { tracer = tracerProvider.Tracer( @@ -75,6 +68,10 @@ func NewEngineRequestHooks( ) } + if appLogger == nil { + appLogger = zap.NewNop() + } + return &engineLoaderHooks{ tracer: tracer, metricStore: metricStore, @@ -82,6 +79,7 @@ func NewEngineRequestHooks( tracingAttributeExpressions: tracingAttributes, metricAttributeExpressions: metricAttributes, accessLogger: logger, + appLogger: appLogger, storeSubgraphResponseBody: storeSubgraphResponseBody, } } @@ -284,9 +282,14 @@ func (f *engineLoaderHooks) OnFinished(ctx context.Context, ds resolve.DataSourc metricAttrs = append(metricAttrs, rotel.WgRequestError.Bool(true)) attrOpt := otelmetric.WithAttributeSet(attribute.NewSet(metricAttrs...)) + + f.appLogger.Info("logging metrics with attributes a", zap.Any("attributes", metricAttrs)) + f.metricStore.MeasureRequestCount(ctx, metricSliceAttrs, attrOpt) f.metricStore.MeasureLatency(ctx, latency, metricSliceAttrs, attrOpt) } else { + f.appLogger.Info("logging metrics with attributes b", zap.Any("attributes", metricAttrs)) + f.metricStore.MeasureRequestCount(ctx, reqContext.telemetry.metricSliceAttrs, metricAddOpt) f.metricStore.MeasureLatency(ctx, latency, reqContext.telemetry.metricSliceAttrs, metricAddOpt) } diff --git a/router/core/graph_server.go b/router/core/graph_server.go index d20fd59146..c7f094770c 100644 --- a/router/core/graph_server.go +++ b/router/core/graph_server.go @@ -1411,6 +1411,7 @@ func (s *graphServer) buildGraphMux( loaderHooks := NewEngineRequestHooks( gm.metricStore, subgraphAccessLogger, + s.logger, s.tracerProvider, tracingAttExpressions, telemetryAttExpressions, diff --git a/router/core/operation_metrics.go b/router/core/operation_metrics.go index 1cf9683f2d..b4cd41f7b8 100644 --- a/router/core/operation_metrics.go +++ b/router/core/operation_metrics.go @@ -64,9 +64,13 @@ func (m *OperationMetrics) Finish(reqContext *requestContext, statusCode int, re attrs = append(attrs, rotel.WgRequestError.Bool(true)) attrOpt := otelmetric.WithAttributeSet(attribute.NewSet(attrs...)) + m.logger.Info("logging metrics with attributes 1", zap.Any("attributes", attrs)) + rm.MeasureRequestCount(ctx, sliceAttrs, attrOpt) rm.MeasureLatency(ctx, latency, sliceAttrs, attrOpt) } else { + m.logger.Info("logging metrics with attributes 2", zap.Any("attributes", attrs)) + rm.MeasureRequestCount(ctx, sliceAttrs, o) rm.MeasureLatency(ctx, latency, sliceAttrs, o) } @@ -104,6 +108,11 @@ type OperationMetricsOptions struct { func newOperationMetrics(opts OperationMetricsOptions) *OperationMetrics { operationStartTime := time.Now() + logger := opts.Logger + if logger == nil { + logger = zap.NewNop() + } + inflightMetric := opts.RouterMetrics.MetricStore().MeasureInFlight(context.Background(), opts.SliceAttributes, opts.InFlightAddOption) return &OperationMetrics{ requestContentLength: opts.RequestContentLength, @@ -111,7 +120,7 @@ func newOperationMetrics(opts OperationMetricsOptions) *OperationMetrics { inflightMetric: inflightMetric, routerConfigVersion: opts.RouterConfigVersion, routerMetrics: opts.RouterMetrics, - logger: opts.Logger, + logger: logger, trackUsageInfo: opts.TrackUsageInfo, prometheusTrackUsageInfo: opts.PrometheusTrackUsageInfo, }