Prevent verbose error reporting from grpc logging

By default, for errors that implement fmt.Formatter, zap will add a verboseError field that includes the '%+v' formatted error in the log record. This is really cool and useful but it can be noisy. In order to prevent this noise in the grpc interceptors, we can embed the errors we're logging in a struct; the result is that the struct satisfies the error interface without implementing fmt.Formatter. FAB-12953 #done Change-Id: I312a70a0bc0c0ac88765de319ba67c8ee8c1e3cd Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>
hyperledger · Nov 27, 2018 · 2f02a32 · 2f02a32
1 parent 6922e14
commit 2f02a32
Show file tree

Hide file tree

Showing 4 changed files with 93 additions and 51 deletions.
diff --git a/common/grpclogging/fields.go b/common/grpclogging/fields.go
@@ -32,3 +32,14 @@ func ProtoMessage(key string, val interface{}) zapcore.Field {
 	}
 	return zap.Any(key, val)
 }
+
+func Error(err error) zapcore.Field {
+	if err == nil {
+		return zap.Skip()
+	}
+
+	// Wrap the error so it no longer implements fmt.Formatter. This will prevent
+	// zap from adding the "verboseError" field to the log record that includes a
+	// full stack trace.
+	return zap.Error(struct{ error }{err})
+}
diff --git a/common/grpclogging/fields_test.go b/common/grpclogging/fields_test.go
@@ -8,74 +8,105 @@ package grpclogging_test
 
 import (
 	"encoding/json"
-	"errors"
 
 	"github.com/golang/protobuf/jsonpb"
 	"github.com/hyperledger/fabric/common/grpclogging"
 	"github.com/hyperledger/fabric/common/grpclogging/testpb"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
+	"github.com/pkg/errors"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
 
-var _ = Describe("ProtoMessage", func() {
-	var message *testpb.Message
+var _ = Describe("Fields", func() {
+	Describe("ProtoMessage", func() {
+		var message *testpb.Message
 
-	BeforeEach(func() {
-		message = &testpb.Message{
-			Message:  "Je suis une pizza avec du fromage.",
-			Sequence: 1337,
-		}
-	})
+		BeforeEach(func() {
+			message = &testpb.Message{
+				Message:  "Je suis une pizza avec du fromage.",
+				Sequence: 1337,
+			}
+		})
 
-	It("creates a reflect field for zap", func() {
-		field := grpclogging.ProtoMessage("field-key", message)
-		Expect(field.Key).To(Equal("field-key"))
-		_, ok := field.Interface.(json.Marshaler)
-		Expect(ok).To(BeTrue())
-	})
+		It("creates a reflect field for zap", func() {
+			field := grpclogging.ProtoMessage("field-key", message)
+			Expect(field.Key).To(Equal("field-key"))
+			_, ok := field.Interface.(json.Marshaler)
+			Expect(ok).To(BeTrue())
+		})
 
-	It("marshals messages compatible with jsonpb", func() {
-		field := grpclogging.ProtoMessage("field-key", message)
-		marshaler := field.Interface.(json.Marshaler)
+		It("marshals messages compatible with jsonpb", func() {
+			field := grpclogging.ProtoMessage("field-key", message)
+			marshaler := field.Interface.(json.Marshaler)
 
-		marshaled, err := marshaler.MarshalJSON()
-		Expect(err).NotTo(HaveOccurred())
+			marshaled, err := marshaler.MarshalJSON()
+			Expect(err).NotTo(HaveOccurred())
 
-		protoMarshaler := &jsonpb.Marshaler{}
-		protoJson, err := protoMarshaler.MarshalToString(message)
-		Expect(err).NotTo(HaveOccurred())
+			protoMarshaler := &jsonpb.Marshaler{}
+			protoJson, err := protoMarshaler.MarshalToString(message)
+			Expect(err).NotTo(HaveOccurred())
 
-		Expect(marshaled).To(MatchJSON(protoJson))
-	})
+			Expect(marshaled).To(MatchJSON(protoJson))
+		})
 
-	It("works with zap's json encoder", func() {
-		encoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{
-			MessageKey: "message",
+		It("works with zap's json encoder", func() {
+			encoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{
+				MessageKey: "message",
+			})
+			buf, err := encoder.EncodeEntry(
+				zapcore.Entry{Message: "Oh là là"},
+				[]zapcore.Field{grpclogging.ProtoMessage("proto-message", message)},
+			)
+			Expect(err).NotTo(HaveOccurred())
+			Expect(buf.String()).To(MatchJSON(`{"message": "Oh là là", "proto-message": {"message": "Je suis une pizza avec du fromage.", "sequence": 1337}}`))
 		})
-		buf, err := encoder.EncodeEntry(
-			zapcore.Entry{Message: "Oh là là"},
-			[]zapcore.Field{grpclogging.ProtoMessage("proto-message", message)},
-		)
-		Expect(err).NotTo(HaveOccurred())
-		Expect(buf.String()).To(MatchJSON(`{"message": "Oh là là", "proto-message": {"message": "Je suis une pizza avec du fromage.", "sequence": 1337}}`))
-	})
 
-	Context("when marshaling the message fails", func() {
-		It("it returns the error from marshaling", func() {
-			field := grpclogging.ProtoMessage("field-key", badProto{err: errors.New("Boom!")})
-			marshaler := field.Interface.(json.Marshaler)
+		Context("when marshaling the message fails", func() {
+			It("it returns the error from marshaling", func() {
+				field := grpclogging.ProtoMessage("field-key", badProto{err: errors.New("Boom!")})
+				marshaler := field.Interface.(json.Marshaler)
+
+				_, err := marshaler.MarshalJSON()
+				Expect(err).To(MatchError("Boom!"))
+			})
+		})
 
-			_, err := marshaler.MarshalJSON()
-			Expect(err).To(MatchError("Boom!"))
+		Context("when something other than a proto.Message is provided", func() {
+			It("creates an any field", func() {
+				field := grpclogging.ProtoMessage("field-key", "Je ne suis pas une pizza.")
+				Expect(field).To(Equal(zap.Any("field-key", "Je ne suis pas une pizza.")))
+			})
 		})
 	})
 
-	Context("when something other than a proto.Message is provided", func() {
-		It("creates an any field", func() {
-			field := grpclogging.ProtoMessage("field-key", "Je ne suis pas une pizza.")
-			Expect(field).To(Equal(zap.Any("field-key", "Je ne suis pas une pizza.")))
+	Describe("Error", func() {
+		It("creates an error field for zap", func() {
+			err := errors.New("error")
+			field := grpclogging.Error(err)
+			Expect(field.Key).To(Equal("error"))
+			Expect(field.Type).To(Equal(zapcore.ErrorType))
+			Expect(field.Interface).To(Equal(struct{ error }{err}))
+		})
+
+		Context("when the error is nil", func() {
+			It("creates a skip field", func() {
+				field := grpclogging.Error(nil)
+				Expect(field.Type).To(Equal(zapcore.SkipType))
+			})
+		})
+
+		It("omits the verboseError field", func() {
+			encoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{
+				MessageKey: "message",
+			})
+			buf, err := encoder.EncodeEntry(
+				zapcore.Entry{Message: "the message"},
+				[]zapcore.Field{grpclogging.Error(errors.New("the error"))},
+			)
+			Expect(err).NotTo(HaveOccurred())
+			Expect(buf.String()).To(MatchJSON(`{"message": "the message", "error": "the error"}`))
 		})
 	})
 })

diff --git a/common/grpclogging/server.go b/common/grpclogging/server.go
@@ -96,7 +96,7 @@ func UnaryServerInterceptor(logger *zap.Logger, opts ...Option) grpc.UnaryServer
 
 		if ce := logger.Check(o.Level(ctx, info.FullMethod), "unary call completed"); ce != nil {
 			ce.Write(
-				zap.Error(err),
+				Error(err),
 				zap.Stringer("grpc.code", grpc.Code(err)),
 				zap.Duration("grpc.call_duration", time.Since(startTime)),
 			)
@@ -128,7 +128,7 @@ func StreamServerInterceptor(logger *zap.Logger, opts ...Option) grpc.StreamServ
 		err := handler(service, wrappedStream)
 		if ce := logger.Check(o.Level(ctx, info.FullMethod), "streaming call completed"); ce != nil {
 			ce.Write(
-				zap.Error(err),
+				Error(err),
 				zap.Stringer("grpc.code", grpc.Code(err)),
 				zap.Duration("grpc.call_duration", time.Since(startTime)),
 			)

diff --git a/common/grpclogging/server_test.go b/common/grpclogging/server_test.go
@@ -255,7 +255,7 @@ var _ = Describe("Server", func() {
 			})
 
 			It("logs the error", func() {
-				entries := observed.FilterMessage("unary call completed").FilterField(zap.Error(expectedErr)).AllUntimed()
+				entries := observed.FilterMessage("unary call completed").FilterField(grpclogging.Error(expectedErr)).AllUntimed()
 				Expect(entries).To(HaveLen(1))
 			})
 		})
@@ -277,7 +277,7 @@ var _ = Describe("Server", func() {
 			})
 
 			It("logs the error", func() {
-				entries := observed.FilterMessage("unary call completed").FilterField(zap.Error(expectedErr)).AllUntimed()
+				entries := observed.FilterMessage("unary call completed").FilterField(grpclogging.Error(expectedErr)).AllUntimed()
 				Expect(entries).To(HaveLen(1))
 			})
 		})
@@ -551,7 +551,7 @@ var _ = Describe("Server", func() {
 			})
 
 			It("logs the error", func() {
-				entries := observed.FilterMessage("streaming call completed").FilterField(zap.Error(expectedErr)).AllUntimed()
+				entries := observed.FilterMessage("streaming call completed").FilterField(grpclogging.Error(expectedErr)).AllUntimed()
 				Expect(entries).To(HaveLen(1))
 			})
 		})
@@ -578,7 +578,7 @@ var _ = Describe("Server", func() {
 			})
 
 			It("logs the error", func() {
-				entries := observed.FilterMessage("streaming call completed").FilterField(zap.Error(expectedErr)).AllUntimed()
+				entries := observed.FilterMessage("streaming call completed").FilterField(grpclogging.Error(expectedErr)).AllUntimed()
 				Expect(entries).To(HaveLen(1))
 			})
 		})