Skip to content

fix(debug): log information for debugging purposes #2501

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
SkArchon wants to merge 2 commits into from
Closed

fix(debug): log information for debugging purposes #2501

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
d36340e
fix: log information
SkArchon Feb 12, 2026
1276734
fix: tests
SkArchon Feb 12, 2026
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
38 changes: 19 additions & 19 deletions router-tests/structured_logging_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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)
})
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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)
})
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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)

Expand Down
21 changes: 12 additions & 9 deletions router/core/engine_loader_hooks.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand All @@ -75,13 +68,18 @@ func NewEngineRequestHooks(
)
}

if appLogger == nil {
appLogger = zap.NewNop()
}

return &engineLoaderHooks{
tracer: tracer,
metricStore: metricStore,
telemetryAttributeExpressions: telemetryAttributes,
tracingAttributeExpressions: tracingAttributes,
metricAttributeExpressions: metricAttributes,
accessLogger: logger,
appLogger: appLogger,
storeSubgraphResponseBody: storeSubgraphResponseBody,
}
}
Expand Down Expand Up @@ -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)
}
Comment on lines +285 to 295
Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai Bot Feb 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major

Same issue: These appear to be debug logs that should be removed or improved.

Similar to the logs in operation_metrics.go, the messages "logging metrics with attributes a" and "logging metrics with attributes b" are vague and use letter identifiers typical of temporary debugging.

The inconsistent naming convention across files (numbers "1", "2" in operation_metrics.go vs letters "a", "b" here) further suggests these are ad-hoc debugging statements rather than intentional production logging.

Please either:

  1. Remove these debug logs before merging, or
  2. Replace with meaningful, production-quality log messages at an appropriate level
🤖 Prompt for AI Agents 
In `@router/core/engine_loader_hooks.go` around lines 285 - 295, The two vague
debug log calls using f.appLogger.Info("logging metrics with attributes a"/"b")
should be removed or replaced with meaningful production logs; locate the block
around the calls to metricStore.MeasureRequestCount and MeasureLatency
(references: f.appLogger.Info, metricAttrs,
reqContext.telemetry.metricSliceAttrs, metricSliceAttrs, metricAddOpt/attrOpt)
and either delete the Info lines or change them to a clear message (e.g.,
indicate which metrics are being recorded and which attribute set is used) at an
appropriate log level, keeping the surrounding measurement calls unchanged.

Expand Down
1 change: 1 addition & 0 deletions router/core/graph_server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1411,6 +1411,7 @@ func (s *graphServer) buildGraphMux(
loaderHooks := NewEngineRequestHooks(
gm.metricStore,
subgraphAccessLogger,
s.logger,
s.tracerProvider,
tracingAttExpressions,
telemetryAttExpressions,
Expand Down
11 changes: 10 additions & 1 deletion router/core/operation_metrics.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
Comment on lines +67 to 76
Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai Bot Feb 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major

These appear to be debug/development logs that should be removed or improved.

The log messages "logging metrics with attributes 1" and "logging metrics with attributes 2" are vague and use numeric identifiers typical of temporary debugging. If these logs are intended for production:

  1. Use descriptive messages (e.g., "Recording request metrics with error" vs "Recording request metrics")
  2. Consider using Debug level instead of Info to reduce noise
  3. Logging full attribute sets may be verbose and could potentially expose sensitive data

If these are debugging artifacts, please remove them before merging.

🤖 Prompt for AI Agents 
In `@router/core/operation_metrics.go` around lines 67 - 76, Replace the two
temporary Info logs ("logging metrics with attributes 1"/"2") in the block that
calls rm.MeasureRequestCount and rm.MeasureLatency: either remove them if they
were debug artifacts, or change them to descriptive, non-sensitive Debug-level
messages (e.g., "Recording request metrics" and "Recording request metrics with
error") and avoid logging the full attrs payload; update calls around
m.logger.Info, and ensure you only reference safe fields (or omit attrs) while
leaving MeasureRequestCount, MeasureLatency, sliceAttrs, attrOpt and o usage
unchanged.

Expand Down Expand Up @@ -104,14 +108,19 @@ 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,
operationStartTime: operationStartTime,
inflightMetric: inflightMetric,
routerConfigVersion: opts.RouterConfigVersion,
routerMetrics: opts.RouterMetrics,
logger: opts.Logger,
logger: logger,
trackUsageInfo: opts.TrackUsageInfo,
prometheusTrackUsageInfo: opts.PrometheusTrackUsageInfo,
}
Expand Down
Loading