From f902f4d0066893c02cd33493da8f84e763574b96 Mon Sep 17 00:00:00 2001 From: Fuyang Liu Date: Wed, 25 Oct 2023 21:26:45 +0200 Subject: [PATCH 1/6] fix(otelgrpc): correctly assign grpc status code --- CHANGELOG.md | 2 + .../grpc/otelgrpc/interceptor.go | 17 ++++--- .../grpc/otelgrpc/test/interceptor_test.go | 50 +++++++++++++++++-- 3 files changed, 58 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 75798dfaa49..258142c567d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,8 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm ### Fixed - The `go.opentelemetry.io/contrib/samplers/jaegerremote` sampler does not panic when the default HTTP round-tripper (`http.DefaultTransport`) is not `*http.Transport`. (#4045) +- The `UnaryServerInterceptor` in `go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc` +- does not set gRPC status code correctly for metric `rpcServerDuration` (#4481) ## [1.20.0/0.45.0/0.14.0] - 2023-09-28 diff --git a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go index 4b7b48a456d..66a7306389d 100644 --- a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go +++ b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go @@ -366,17 +366,13 @@ func UnaryServerInterceptor(opts ...Option) grpc.UnaryServerInterceptor { messageReceived.Event(ctx, 1, req) } - var statusCode grpc_codes.Code - defer func(t time.Time) { - elapsedTime := time.Since(t) / time.Millisecond - attr = append(attr, semconv.RPCGRPCStatusCodeKey.Int64(int64(statusCode))) - o := metric.WithAttributes(attr...) - cfg.rpcServerDuration.Record(ctx, int64(elapsedTime), o) - }(time.Now()) + before := time.Now() + var grpcStatusCode grpc_codes.Code resp, err := handler(ctx, req) if err != nil { s, _ := status.FromError(err) + grpcStatusCode = s.Code() statusCode, msg := serverStatus(s) span.SetStatus(statusCode, msg) span.SetAttributes(statusCodeAttr(s.Code())) @@ -384,13 +380,18 @@ func UnaryServerInterceptor(opts ...Option) grpc.UnaryServerInterceptor { messageSent.Event(ctx, 1, s.Proto()) } } else { - statusCode = grpc_codes.OK + grpcStatusCode = grpc_codes.OK span.SetAttributes(statusCodeAttr(grpc_codes.OK)) if cfg.SentEvent { messageSent.Event(ctx, 1, resp) } } + elapsedTime := time.Since(before).Milliseconds() + attr = append(attr, semconv.RPCGRPCStatusCodeKey.Int64(int64(grpcStatusCode))) + o := metric.WithAttributes(attr...) + cfg.rpcServerDuration.Record(ctx, elapsedTime, o) + return resp, err } } diff --git a/instrumentation/google.golang.org/grpc/otelgrpc/test/interceptor_test.go b/instrumentation/google.golang.org/grpc/otelgrpc/test/interceptor_test.go index 5369afd4682..d661ec86e5a 100644 --- a/instrumentation/google.golang.org/grpc/otelgrpc/test/interceptor_test.go +++ b/instrumentation/google.golang.org/grpc/otelgrpc/test/interceptor_test.go @@ -26,6 +26,8 @@ import ( "go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/sdk/trace/tracetest" semconv "go.opentelemetry.io/otel/semconv/v1.17.0" @@ -52,6 +54,19 @@ func getSpanFromRecorder(sr *tracetest.SpanRecorder, name string) (trace.ReadOnl return nil, false } +func getMetricFromData(data metricdata.Histogram[int64], name string) (*metricdata.HistogramDataPoint[int64], bool) { + for _, d := range data.DataPoints { + v, ok := d.Attributes.Value(semconv.RPCMethodKey) + if !ok { + return nil, false + } + if semconv.RPCMethod(name).Value == v { + return &d, true + } + } + return nil, false +} + type mockUICInvoker struct { ctx context.Context } @@ -867,24 +882,34 @@ func assertServerSpan(t *testing.T, wantSpanCode codes.Code, wantSpanStatusDescr func TestUnaryServerInterceptor(t *testing.T) { sr := tracetest.NewSpanRecorder() tp := trace.NewTracerProvider(trace.WithSpanProcessor(sr)) + mr := metric.NewManualReader() + mp := metric.NewMeterProvider(metric.WithReader(mr)) usi := otelgrpc.UnaryServerInterceptor( otelgrpc.WithTracerProvider(tp), + otelgrpc.WithMeterProvider(mp), ) + for _, check := range serverChecks { name := check.grpcCode.String() t.Run(name, func(t *testing.T) { + serviceName := "TestGrpcService" + methodName := serviceName + "/" + name + fullMethodName := "/" + methodName // call the unary interceptor grpcErr := status.Error(check.grpcCode, check.grpcCode.String()) handler := func(_ context.Context, _ interface{}) (interface{}, error) { return nil, grpcErr } - _, err := usi(context.Background(), &grpc_testing.SimpleRequest{}, &grpc.UnaryServerInfo{FullMethod: name}, handler) + _, err := usi(context.Background(), &grpc_testing.SimpleRequest{}, &grpc.UnaryServerInfo{FullMethod: fullMethodName}, handler) assert.Equal(t, grpcErr, err) // validate span - span, ok := getSpanFromRecorder(sr, name) - require.True(t, ok, "missing span %s", name) + span, ok := getSpanFromRecorder(sr, methodName) + require.True(t, ok, "missing span %s", methodName) assertServerSpan(t, check.wantSpanCode, check.wantSpanStatusDescription, check.grpcCode, span) + + // validate metric + checkManualReaderRecords(t, mr, serviceName, name, check.grpcCode) }) } } @@ -1069,3 +1094,22 @@ func TestStreamServerInterceptorEvents(t *testing.T) { }) } } + +func checkManualReaderRecords(t *testing.T, reader metric.Reader, serviceName, name string, code grpc_codes.Code) { + rm := metricdata.ResourceMetrics{} + err := reader.Collect(context.Background(), &rm) + assert.NoError(t, err) + require.Len(t, rm.ScopeMetrics, 1) + require.Len(t, rm.ScopeMetrics[0].Metrics, 1) + require.IsType(t, rm.ScopeMetrics[0].Metrics[0].Data, metricdata.Histogram[int64]{}) + data := rm.ScopeMetrics[0].Metrics[0].Data.(metricdata.Histogram[int64]) + dpt, ok := getMetricFromData(data, name) + assert.True(t, ok) + attr := dpt.Attributes.ToSlice() + assert.ElementsMatch(t, []attribute.KeyValue{ + semconv.RPCMethod(name), + semconv.RPCService(serviceName), + otelgrpc.RPCSystemGRPC, + otelgrpc.GRPCStatusCodeKey.Int64(int64(code)), + }, attr) +} From 1516270f04ce656606eee7cf1b77e5c1f2db3a8a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Paj=C4=85k?= Date: Thu, 26 Oct 2023 08:07:49 +0200 Subject: [PATCH 2/6] Update CHANGELOG.md --- CHANGELOG.md | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 258142c567d..0390688e6ce 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,8 +28,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm ### Fixed - The `go.opentelemetry.io/contrib/samplers/jaegerremote` sampler does not panic when the default HTTP round-tripper (`http.DefaultTransport`) is not `*http.Transport`. (#4045) -- The `UnaryServerInterceptor` in `go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc` -- does not set gRPC status code correctly for metric `rpcServerDuration` (#4481) +- The `UnaryServerInterceptor` in `go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc` does not set gRPC status code correctly for metric `rpcServerDuration` (#4481) ## [1.20.0/0.45.0/0.14.0] - 2023-09-28 From 0bf1d59a2f2b914d1b83f512bb025eb790b5b570 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Robert=20Paj=C4=85k?= Date: Thu, 26 Oct 2023 08:10:14 +0200 Subject: [PATCH 3/6] Update CHANGELOG.md --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0390688e6ce..85047db8419 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,7 +28,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm ### Fixed - The `go.opentelemetry.io/contrib/samplers/jaegerremote` sampler does not panic when the default HTTP round-tripper (`http.DefaultTransport`) is not `*http.Transport`. (#4045) -- The `UnaryServerInterceptor` in `go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc` does not set gRPC status code correctly for metric `rpcServerDuration` (#4481) +- The `UnaryServerInterceptor` in `go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc` now sets gRPC status code correctly for the `rpc.server.duration` metric. (#4481) ## [1.20.0/0.45.0/0.14.0] - 2023-09-28 From 72a4588df5d91e529ec157647d0c1b1908178a13 Mon Sep 17 00:00:00 2001 From: Fuyang Liu Date: Thu, 26 Oct 2023 10:21:56 +0200 Subject: [PATCH 4/6] fix: minor fix for easier reading --- .../google.golang.org/grpc/otelgrpc/interceptor.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go index 66a7306389d..d421e95945f 100644 --- a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go +++ b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go @@ -388,9 +388,8 @@ func UnaryServerInterceptor(opts ...Option) grpc.UnaryServerInterceptor { } elapsedTime := time.Since(before).Milliseconds() - attr = append(attr, semconv.RPCGRPCStatusCodeKey.Int64(int64(grpcStatusCode))) - o := metric.WithAttributes(attr...) - cfg.rpcServerDuration.Record(ctx, elapsedTime, o) + attr = append(attr, statusCodeAttr(grpcStatusCode)) + cfg.rpcServerDuration.Record(ctx, elapsedTime, metric.WithAttributes(attr...)) return resp, err } From 0fecb46728112c7c4e496f6d0cdfd0f49c87c36f Mon Sep 17 00:00:00 2001 From: Fuyang Liu Date: Thu, 26 Oct 2023 22:54:00 +0200 Subject: [PATCH 5/6] fix: minor code fix up --- .../google.golang.org/grpc/otelgrpc/interceptor.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go index d421e95945f..34048605d54 100644 --- a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go +++ b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go @@ -375,13 +375,13 @@ func UnaryServerInterceptor(opts ...Option) grpc.UnaryServerInterceptor { grpcStatusCode = s.Code() statusCode, msg := serverStatus(s) span.SetStatus(statusCode, msg) - span.SetAttributes(statusCodeAttr(s.Code())) + span.SetAttributes(statusCodeAttr(grpcStatusCode)) if cfg.SentEvent { messageSent.Event(ctx, 1, s.Proto()) } } else { grpcStatusCode = grpc_codes.OK - span.SetAttributes(statusCodeAttr(grpc_codes.OK)) + span.SetAttributes(statusCodeAttr(grpcStatusCode)) if cfg.SentEvent { messageSent.Event(ctx, 1, resp) } From cff17fa7e14e010b9695c2fdbe62876784c0fb4c Mon Sep 17 00:00:00 2001 From: Fuyang Liu Date: Fri, 27 Oct 2023 00:14:51 +0200 Subject: [PATCH 6/6] fix: minor code fix up --- .../google.golang.org/grpc/otelgrpc/interceptor.go | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go index 34048605d54..815eabb907e 100644 --- a/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go +++ b/instrumentation/google.golang.org/grpc/otelgrpc/interceptor.go @@ -367,28 +367,26 @@ func UnaryServerInterceptor(opts ...Option) grpc.UnaryServerInterceptor { } before := time.Now() - var grpcStatusCode grpc_codes.Code resp, err := handler(ctx, req) + + s, _ := status.FromError(err) if err != nil { - s, _ := status.FromError(err) - grpcStatusCode = s.Code() statusCode, msg := serverStatus(s) span.SetStatus(statusCode, msg) - span.SetAttributes(statusCodeAttr(grpcStatusCode)) if cfg.SentEvent { messageSent.Event(ctx, 1, s.Proto()) } } else { - grpcStatusCode = grpc_codes.OK - span.SetAttributes(statusCodeAttr(grpcStatusCode)) if cfg.SentEvent { messageSent.Event(ctx, 1, resp) } } + grpcStatusCodeAttr := statusCodeAttr(s.Code()) + span.SetAttributes(grpcStatusCodeAttr) elapsedTime := time.Since(before).Milliseconds() - attr = append(attr, statusCodeAttr(grpcStatusCode)) + attr = append(attr, grpcStatusCodeAttr) cfg.rpcServerDuration.Record(ctx, elapsedTime, metric.WithAttributes(attr...)) return resp, err