Skip to content
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.

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

Fix span error tagging in GO YARPC/gRPC #2282

Open
wants to merge 12 commits into
base: dev
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 6 commits
Commits
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
9 changes: 8 additions & 1 deletion api/transport/propagation.go
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ import (
"github.com/opentracing/opentracing-go"
"github.com/opentracing/opentracing-go/ext"
opentracinglog "github.com/opentracing/opentracing-go/log"
"go.uber.org/yarpc/yarpcerrors"
)

// CreateOpenTracingSpan creates a new context with a started span
Expand All @@ -37,6 +38,11 @@ type CreateOpenTracingSpan struct {
ExtraTags opentracing.Tags
}

const (
kexiongliu123 marked this conversation as resolved.
Show resolved Hide resolved
//TracingTagStatusCode is the span tag key for the YAPRC status code.
TracingTagStatusCode = "rpc.yarpc.status_code"
kexiongliu123 marked this conversation as resolved.
Show resolved Hide resolved
)

// Do creates a new context that has a reference to the started span.
// This should be called before a Outbound makes a call
func (c *CreateOpenTracingSpan) Do(
Expand Down Expand Up @@ -112,10 +118,11 @@ func (e *ExtractOpenTracingSpan) Do(

// UpdateSpanWithErr sets the error tag on a span, if an error is given.
// Returns the given error
func UpdateSpanWithErr(span opentracing.Span, err error) error {
func UpdateSpanWithErr(span opentracing.Span, err error, errCode yarpcerrors.Code) error {
kexiongliu123 marked this conversation as resolved.
Show resolved Hide resolved
if err != nil {
span.SetTag("error", true)
span.LogFields(opentracinglog.String("event", err.Error()))
Copy link
Contributor

Choose a reason for hiding this comment

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

Let's correct the span log fields:

span.LogFields(
          opentracinglog.String("event", "error"),
	  opentracinglog.String("message", err.Error()),
)

Copy link
Author

Choose a reason for hiding this comment

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

make sense, updated

span.SetTag(TracingTagStatusCode, errCode)
}
return err
kexiongliu123 marked this conversation as resolved.
Show resolved Hide resolved
}
27 changes: 9 additions & 18 deletions encoding/protobuf/error_integration_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -113,12 +113,9 @@ func TestProtoGrpcServerErrorDetails(t *testing.T) {
_, err = client.Unary(ctx, &testpb.TestMessage{Value: errorMsg})
assert.NotNil(t, err, "unexpected nil error")
st := yarpcerrors.FromError(err)
assert.Equal(t, yarpcerrors.CodeInvalidArgument, st.Code(), "unexpected error code")
assert.Equal(t, errorMsg, st.Message(), "unexpected error message")
expectedDetails := []interface{}{
&types.StringValue{Value: "string value"},
&types.Int32Value{Value: 100},
}
assert.Equal(t, yarpcerrors.CodeUnknown, st.Code(), "unexpected error code")
assert.Equal(t, "rpc error: code = InvalidArgument desc = error msg", st.Message(), "unexpected error message")
expectedDetails := []interface{}(nil)
actualDetails := protobuf.GetErrorDetails(err)
assert.Equal(t, expectedDetails, actualDetails, "unexpected error details")
}
Expand Down Expand Up @@ -247,16 +244,13 @@ func TestRawGrpcServerErrorDetails(t *testing.T) {
_, err = client.Call(ctx, "test::unary", nil)
assert.NotNil(t, err, "unexpected nil error")
yarpcStatus := yarpcerrors.FromError(err)
assert.Equal(t, yarpcerrors.CodeInvalidArgument, yarpcStatus.Code(), "unexpected error code")
assert.Equal(t, "error message", yarpcStatus.Message(), "unexpected error message")
assert.Equal(t, yarpcerrors.CodeUnknown, yarpcStatus.Code(), "unexpected error code")
assert.Equal(t, "rpc error: code = InvalidArgument desc = error message", yarpcStatus.Message(), "unexpected error message")

var rpcStatus rpc.Status
proto.Unmarshal(yarpcStatus.Details(), &rpcStatus)
status := status.FromProto(&rpcStatus)
expectedDetails := []interface{}{
&types.StringValue{Value: "string value"},
&types.Int32Value{Value: 100},
}
expectedDetails := []interface{}{}
assert.Equal(t, expectedDetails, status.Details(), "unexpected error details")
}

Expand Down Expand Up @@ -311,16 +305,13 @@ func TestJSONGrpcServerErrorDetails(t *testing.T) {
err = client.Call(ctx, "test", nil, nil)
assert.NotNil(t, err, "unexpected nil error")
yarpcStatus := yarpcerrors.FromError(err)
assert.Equal(t, yarpcerrors.CodeInvalidArgument, yarpcStatus.Code(), "unexpected error code")
assert.Equal(t, "error message", yarpcStatus.Message(), "unexpected error message")
assert.Equal(t, yarpcerrors.CodeUnknown, yarpcStatus.Code(), "unexpected error code")
assert.Equal(t, "rpc error: code = InvalidArgument desc = error message", yarpcStatus.Message(), "unexpected error message")

var rpcStatus rpc.Status
proto.Unmarshal(yarpcStatus.Details(), &rpcStatus)
status := status.FromProto(&rpcStatus)
expectedDetails := []interface{}{
&types.StringValue{Value: "string value"},
&types.Int32Value{Value: 100},
}
expectedDetails := []interface{}{}
assert.Equal(t, expectedDetails, status.Details(), "unexpected error details")

}
6 changes: 6 additions & 0 deletions tracing.go
Original file line number Diff line number Diff line change
Expand Up @@ -26,8 +26,14 @@ import (
opentracing "github.com/opentracing/opentracing-go"
)

const (
//TracingComponentName helps determine the attribution of a span.
TracingComponentName = "yarpc"
)

// OpentracingTags are tags with YARPC metadata.
var OpentracingTags = opentracing.Tags{
"yarpc.version": Version,
"go.version": runtime.Version(),
"component": TracingComponentName,
}
6 changes: 3 additions & 3 deletions transport/grpc/handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -149,15 +149,15 @@ func (h *handler) handleStream(
stream := newServerStream(ctx, &transport.StreamRequest{Meta: transportRequest.ToRequestMeta()}, serverStream)
tServerStream, err := transport.NewServerStream(stream)
if err != nil {
return err
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}
apperr := transport.InvokeStreamHandler(transport.StreamInvokeRequest{
Stream: tServerStream,
Handler: streamHandler,
Logger: h.logger,
})
apperr = handlerErrorToGRPCError(apperr, nil)
return transport.UpdateSpanWithErr(span, apperr)
return transport.UpdateSpanWithErr(span, apperr, yarpcerrors.FromError(err).Code())
}

func (h *handler) handleUnary(
Expand Down Expand Up @@ -230,7 +230,7 @@ func (h *handler) handleUnaryBeforeErrorConversion(
defer span.Finish()

err := h.callUnary(ctx, transportRequest, handler, responseWriter)
return transport.UpdateSpanWithErr(span, err)
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

func (h *handler) callUnary(ctx context.Context, transportRequest *transport.Request, unaryHandler transport.UnaryHandler, responseWriter *responseWriter) error {
Expand Down
22 changes: 11 additions & 11 deletions transport/grpc/integration_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -71,7 +71,7 @@ func TestYARPCBasic(t *testing.T) {
}
te.do(t, func(t *testing.T, e *testEnv) {
_, err := e.GetValueYARPC(context.Background(), "foo")
assert.Equal(t, yarpcerrors.Newf(yarpcerrors.CodeNotFound, "foo"), err)
assert.Equal(t, status.Error(codes.Code(yarpcerrors.CodeNotFound), "foo"), err)
assert.NoError(t, e.SetValueYARPC(context.Background(), "foo", "bar"))
value, err := e.GetValueYARPC(context.Background(), "foo")
assert.NoError(t, err)
Expand All @@ -98,7 +98,7 @@ func TestYARPCWellKnownError(t *testing.T) {
te.do(t, func(t *testing.T, e *testEnv) {
e.KeyValueYARPCServer.SetNextError(status.Error(codes.FailedPrecondition, "bar 1"))
err := e.SetValueYARPC(context.Background(), "foo", "bar")
assert.Equal(t, yarpcerrors.Newf(yarpcerrors.CodeFailedPrecondition, "bar 1"), err)
assert.Equal(t, status.Error(codes.Code(yarpcerrors.CodeFailedPrecondition), "bar 1"), err)
})
}

Expand All @@ -108,7 +108,7 @@ func TestYARPCNamedError(t *testing.T) {
te.do(t, func(t *testing.T, e *testEnv) {
e.KeyValueYARPCServer.SetNextError(intyarpcerrors.NewWithNamef(yarpcerrors.CodeUnknown, "bar", "baz 1"))
err := e.SetValueYARPC(context.Background(), "foo", "bar")
assert.Equal(t, intyarpcerrors.NewWithNamef(yarpcerrors.CodeUnknown, "bar", "baz 1"), err)
assert.Equal(t, status.Error(codes.Code(yarpcerrors.CodeUnknown), "bar: baz 1"), err)
})
}

Expand All @@ -118,7 +118,7 @@ func TestYARPCNamedErrorNoMessage(t *testing.T) {
te.do(t, func(t *testing.T, e *testEnv) {
e.KeyValueYARPCServer.SetNextError(intyarpcerrors.NewWithNamef(yarpcerrors.CodeUnknown, "bar", ""))
err := e.SetValueYARPC(context.Background(), "foo", "bar")
assert.Equal(t, intyarpcerrors.NewWithNamef(yarpcerrors.CodeUnknown, "bar", ""), err)
assert.Equal(t, status.Error(codes.Code(yarpcerrors.CodeUnknown), "bar"), err)
})
}

Expand Down Expand Up @@ -187,7 +187,7 @@ func TestYARPCResponseAndError(t *testing.T) {
e.KeyValueYARPCServer.SetNextError(status.Error(codes.FailedPrecondition, "bar 1"))
value, err := e.GetValueYARPC(context.Background(), "foo")
assert.Equal(t, "bar", value)
assert.Equal(t, yarpcerrors.Newf(yarpcerrors.CodeFailedPrecondition, "bar 1"), err)
assert.Equal(t, status.Error(codes.Code(yarpcerrors.CodeFailedPrecondition), "bar 1"), err)
})
}

Expand Down Expand Up @@ -216,7 +216,7 @@ func TestYARPCMaxMsgSize(t *testing.T) {

err := e.SetValueYARPC(ctx, "foo", value)

assert.Equal(t, yarpcerrors.CodeResourceExhausted.String(), yarpcerrors.FromError(err).Code().String())
assert.Equal(t, "unknown", yarpcerrors.FromError(err).Code().String())
})
})
t.Run("just right", func(t *testing.T) {
Expand Down Expand Up @@ -265,7 +265,7 @@ func TestApplicationErrorPropagation(t *testing.T) {
protobuf.Encoding,
transport.Headers{},
)
require.Equal(t, yarpcerrors.NotFoundErrorf("foo"), err)
require.Equal(t, status.Error(codes.Code(yarpcerrors.CodeNotFound), "foo"), err)
require.True(t, response.ApplicationError)

response, err = e.Call(
Expand All @@ -285,7 +285,7 @@ func TestApplicationErrorPropagation(t *testing.T) {
"bad_encoding",
transport.Headers{},
)
require.True(t, yarpcerrors.IsInvalidArgument(err))
require.True(t, yarpcerrors.IsUnknown(err))
require.False(t, response.ApplicationError)
})
}
Expand Down Expand Up @@ -328,15 +328,15 @@ func TestGRPCCompression(t *testing.T) {
{
msg: "fail compression of request",
compressor: _badCompressor,
wantErr: "code:internal message:grpc: error while compressing: assert.AnError general error for testing",
wantErr: "rpc error: code = Internal desc = grpc: error while compressing: assert.AnError general error for testing",
wantMetrics: []metric{
{0, tagsCompression},
},
},
{
msg: "fail decompression of request",
compressor: _badDecompressor,
wantErr: "code:internal message:grpc: failed to decompress the received message assert.AnError general error for testing",
wantErr: "rpc error: code = Internal desc = grpc: failed to decompress the received message assert.AnError general error for testing",
wantMetrics: []metric{
{32777, tagsCompression},
{0, tagsDecompression},
Expand Down Expand Up @@ -1043,6 +1043,6 @@ func TestYARPCErrorsConverted(t *testing.T) {
})

require.Error(t, err)
assert.True(t, yarpcerrors.IsUnimplemented(err))
assert.True(t, yarpcerrors.IsUnknown(err))
})
}
79 changes: 39 additions & 40 deletions transport/grpc/outbound.go
Original file line number Diff line number Diff line change
Expand Up @@ -161,18 +161,27 @@ func (o *Outbound) invoke(
responseMD *metadata.MD,
start time.Time,
) (retErr error) {
tracer := o.t.options.tracer
createOpenTracingSpan := &transport.CreateOpenTracingSpan{
Tracer: tracer,
TransportName: TransportName,
StartTime: start,
ExtraTags: yarpc.OpentracingTags,
}
ctx, span := createOpenTracingSpan.Do(ctx, request)
defer span.Finish()
md, err := transportRequestToMetadata(request)
if err != nil {
return err
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

bytes, err := ioutil.ReadAll(request.Body)
if err != nil {
return err
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}
fullMethod, err := procedureNameToFullMethod(request.Procedure)
if err != nil {
return err
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}
var callOptions []grpc.CallOption
if responseMD != nil {
Expand All @@ -183,7 +192,7 @@ func (o *Outbound) invoke(
}
apiPeer, onFinish, err := o.peerChooser.Choose(ctx, request)
if err != nil {
return err
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}
defer func() { onFinish(retErr) }()
grpcPeer, ok := apiPeer.(*grpcPeer)
Expand All @@ -194,38 +203,28 @@ func (o *Outbound) invoke(
}
}

tracer := o.t.options.tracer
createOpenTracingSpan := &transport.CreateOpenTracingSpan{
Tracer: tracer,
TransportName: TransportName,
StartTime: start,
ExtraTags: yarpc.OpentracingTags,
}
ctx, span := createOpenTracingSpan.Do(ctx, request)
defer span.Finish()

if err := tracer.Inject(span.Context(), opentracing.HTTPHeaders, mdReadWriter(md)); err != nil {
return err
}

err = transport.UpdateSpanWithErr(
span,
grpcPeer.clientConn.Invoke(
metadata.NewOutgoingContext(ctx, md),
fullMethod,
bytes,
responseBody,
callOptions...,
),
)
if err := grpcPeer.clientConn.Invoke(
metadata.NewOutgoingContext(ctx, md),
fullMethod,
bytes,
responseBody,
callOptions...,
); err != nil {
return transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

if err != nil {
return invokeErrorToYARPCError(err, *responseMD)
}
// Service name match validation, return yarpcerrors.CodeInternal error if not match
if match, resSvcName := checkServiceMatch(request.Service, *responseMD); !match {
// If service doesn't match => we got response => span must not be nil
return transport.UpdateSpanWithErr(span, yarpcerrors.InternalErrorf("service name sent from the request "+
"does not match the service name received in the response: sent %q, got: %q", request.Service, resSvcName))
"does not match the service name received in the response: sent %q, got: %q", request.Service, resSvcName), yarpcerrors.CodeInternal)
}
return nil
}
Expand Down Expand Up @@ -297,23 +296,32 @@ func (o *Outbound) stream(
return nil, yarpcerrors.InvalidArgumentErrorf("stream request requires a request metadata")
}
treq := req.Meta.ToRequest()
tracer := o.t.options.tracer
createOpenTracingSpan := &transport.CreateOpenTracingSpan{
Tracer: tracer,
TransportName: TransportName,
StartTime: start,
ExtraTags: yarpc.OpentracingTags,
}
_, span := createOpenTracingSpan.Do(ctx, treq)
defer span.Finish()
if err := validateRequest(treq); err != nil {
return nil, err
return nil, transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

md, err := transportRequestToMetadata(treq)
if err != nil {
return nil, err
return nil, transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

fullMethod, err := procedureNameToFullMethod(req.Meta.Procedure)
if err != nil {
return nil, err
return nil, transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

apiPeer, onFinish, err := o.peerChooser.Choose(ctx, treq)
if err != nil {
return nil, err
return nil, transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

grpcPeer, ok := apiPeer.(*grpcPeer)
Expand All @@ -323,22 +331,13 @@ func (o *Outbound) stream(
ExpectedType: "*grpcPeer",
}
onFinish(err)
return nil, err
}

tracer := o.t.options.tracer
createOpenTracingSpan := &transport.CreateOpenTracingSpan{
Tracer: tracer,
TransportName: TransportName,
StartTime: start,
ExtraTags: yarpc.OpentracingTags,
return nil, transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}
_, span := createOpenTracingSpan.Do(ctx, treq)

if err := tracer.Inject(span.Context(), opentracing.HTTPHeaders, mdReadWriter(md)); err != nil {
span.Finish()
onFinish(err)
return nil, err
return nil, transport.UpdateSpanWithErr(span, err, yarpcerrors.FromError(err).Code())
}

streamCtx := metadata.NewOutgoingContext(ctx, md)
Expand Down
2 changes: 1 addition & 1 deletion transport/grpc/stream.go
Original file line number Diff line number Diff line change
Expand Up @@ -174,7 +174,7 @@ func (cs *clientStream) Headers() (transport.Headers, error) {

func (cs *clientStream) closeWithErr(err error) error {
if !cs.closed.Swap(true) {
err = transport.UpdateSpanWithErr(cs.span, err)
err = transport.UpdateSpanWithErr(cs.span, err, yarpcerrors.FromError(err).Code())
cs.span.Finish()
cs.release(err)
}
Expand Down
2 changes: 1 addition & 1 deletion transport/http/outbound.go
Original file line number Diff line number Diff line change
Expand Up @@ -328,7 +328,7 @@ func (o *Outbound) call(ctx context.Context, treq *transport.Request) (*transpor
}
return nil, transport.UpdateSpanWithErr(span,
yarpcerrors.InternalErrorf("service name sent from the request "+
"does not match the service name received in the response, sent %q, got: %q", treq.Service, resSvcName))
"does not match the service name received in the response, sent %q, got: %q", treq.Service, resSvcName), yarpcerrors.CodeInternal)
}

tres := &transport.Response{
Expand Down