diff --git a/grpcutil/logging.go b/grpcutil/logging.go index 6f80fa02..2ed8121d 100644 --- a/grpcutil/logging.go +++ b/grpcutil/logging.go @@ -3,6 +3,7 @@ package grpcutil import ( "context" + "errors" "time" cli "github.com/peterebden/go-cli-init/v4/logging" @@ -73,10 +74,10 @@ func LogUnaryRequests(ctx context.Context, req interface{}, info *grpc.UnaryServ start := time.Now() resp, err := handler(ctx, req) if err != nil { - if status.Code(err) != codes.NotFound { - log.Error("Error handling %s: %s", info.FullMethod, err) + if hasGRPCCode(err, codes.NotFound) { + log.Debug("Not found on %s: %v", info.FullMethod, err) } else { - log.Debug("Not found on %s: %s", info.FullMethod, err) + log.Error("Error handling %s: %v", info.FullMethod, err) } } else { log.Debug("Handled %s successfully in %s", info.FullMethod, time.Since(start)) @@ -89,13 +90,32 @@ func LogStreamRequests(srv interface{}, ss grpc.ServerStream, info *grpc.StreamS start := time.Now() err := handler(srv, ss) if err != nil { - if status.Code(err) != codes.NotFound { - log.Error("Error handling %s: %s", info.FullMethod, err) + if hasGRPCCode(err, codes.NotFound) { + log.Debug("Not found on %s: %v", info.FullMethod, err) } else { - log.Debug("Not found on %s: %s", info.FullMethod, err) + log.Error("Error handling %s: %v", info.FullMethod, err) } } else { log.Debug("Handled %s successfully in %s", info.FullMethod, time.Since(start)) } return err } + +// grpcStatusError is the interface implemented by gRPC status errors. +type grpcStatusError interface { + GRPCStatus() *status.Status +} + +// hasGRPCCode reports whether err or any error in its tree has the given gRPC +// status code. This handles errors wrapped by multierror or fmt.Errorf("%w") +// where status.Code() alone would return codes.Unknown. +func hasGRPCCode(err error, code codes.Code) bool { + if status.Code(err) == code { + return true + } + var se grpcStatusError + if errors.As(err, &se) { + return se.GRPCStatus().Code() == code + } + return false +} diff --git a/grpcutil/logging_test.go b/grpcutil/logging_test.go new file mode 100644 index 00000000..7a6ee76e --- /dev/null +++ b/grpcutil/logging_test.go @@ -0,0 +1,49 @@ +package grpcutil + +import ( + "fmt" + "testing" + + "github.com/hashicorp/go-multierror" + "github.com/stretchr/testify/assert" + "google.golang.org/grpc/codes" + "google.golang.org/grpc/status" +) + +func TestHasGRPCCode_DirectStatus(t *testing.T) { + err := status.Errorf(codes.NotFound, "blob not found") + assert.True(t, hasGRPCCode(err, codes.NotFound)) + assert.False(t, hasGRPCCode(err, codes.Internal)) +} + +func TestHasGRPCCode_MultierrorWrapped(t *testing.T) { + // With multiple errors, multierror wraps them in a way that loses the + // gRPC status code from status.Code's perspective. + inner1 := status.Errorf(codes.NotFound, "blob abc123 not found") + inner2 := status.Errorf(codes.NotFound, "blob def456 not found") + var multi error + multi = multierror.Append(multi, inner1, inner2) + // status.Code sees NotFound because multierror implements Unwrap + // but the important thing is hasGRPCCode finds it either way + assert.True(t, hasGRPCCode(multi, codes.NotFound)) + assert.False(t, hasGRPCCode(multi, codes.Internal)) +} + +func TestHasGRPCCode_MultierrorGroup(t *testing.T) { + // This mirrors how elan's getTree uses multierror.Group + var g multierror.Group + g.Go(func() error { + return status.Errorf(codes.NotFound, "blob def456 not found") + }) + err := g.Wait().ErrorOrNil() + assert.True(t, hasGRPCCode(err, codes.NotFound)) +} + +func TestHasGRPCCode_NonGRPCError(t *testing.T) { + err := fmt.Errorf("some random error") + assert.False(t, hasGRPCCode(err, codes.NotFound)) +} + +func TestHasGRPCCode_Nil(t *testing.T) { + assert.False(t, hasGRPCCode(nil, codes.NotFound)) +}