[FAB-13598] remove grpc_start_time from logs

Since we have the duration in the log record and the log record includes
a time stamp, determining the start time is trivial relative to the
amount of text produced when formatting a time stamp.

Change-Id: I37e926ffd8402400c58e3bffabc217efc749717c
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>

common/grpclogging/server.go

@@ -78,7 +78,7 @@ func UnaryServerInterceptor(logger *zap.Logger, opts ...Option) grpc.UnaryServer
 		logger := logger
 		startTime := time.Now()
 
-		fields := getFields(ctx, startTime, info.FullMethod)
+		fields := getFields(ctx, info.FullMethod)
 		logger = logger.With(fields...)
 		ctx = WithFields(ctx, fields)
 
@@ -114,7 +114,7 @@ func StreamServerInterceptor(logger *zap.Logger, opts ...Option) grpc.StreamServ
 		ctx := stream.Context()
 		startTime := time.Now()
 
-		fields := getFields(ctx, startTime, info.FullMethod)
+		fields := getFields(ctx, info.FullMethod)
 		logger = logger.With(fields...)
 		ctx = WithFields(ctx, fields)
 
@@ -137,8 +137,8 @@ func StreamServerInterceptor(logger *zap.Logger, opts ...Option) grpc.StreamServ
 	}
 }
 
-func getFields(ctx context.Context, startTime time.Time, method string) []zapcore.Field {
-	fields := []zap.Field{zap.Time("grpc.start_time", startTime)}
+func getFields(ctx context.Context, method string) []zapcore.Field {
+	var fields []zap.Field
 	if parts := strings.Split(method, "/"); len(parts) == 3 {
 		fields = append(fields, zap.String("grpc.service", parts[1]), zap.String("grpc.method", parts[2]))
 	}

common/grpclogging/server_test.go

@@ -135,11 +135,9 @@ var _ = Describe("Server", func() {
 			ctx, cancel := context.WithTimeout(context.Background(), time.Hour)
 			defer cancel()
 
-			startTime := time.Now()
 			resp, err := echoServiceClient.Echo(ctx, &testpb.Message{Message: "hi"})
 			Expect(err).NotTo(HaveOccurred())
 			Expect(resp).To(Equal(&testpb.Message{Message: "hi", Sequence: 1}))
-			endTime := time.Now()
 
 			var logMessages []string
 			for _, entry := range observed.AllUntimed() {
@@ -160,12 +158,12 @@ var _ = Describe("Server", func() {
 				switch entry.LoggerName {
 				case "test-logger":
 					Expect(entry.Level).To(Equal(zapcore.InfoLevel))
-					Expect(entry.Context).To(HaveLen(9))
-					Expect(keyNames).To(HaveLen(9))
+					Expect(entry.Context).To(HaveLen(8))
+					Expect(keyNames).To(HaveLen(8))
 				case "test-logger.payload":
 					Expect(entry.Level).To(Equal(zapcore.DebugLevel - 1))
-					Expect(entry.Context).To(HaveLen(7))
-					Expect(keyNames).To(HaveLen(7))
+					Expect(entry.Context).To(HaveLen(6))
+					Expect(keyNames).To(HaveLen(6))
 				default:
 					Fail("unexpected logger name: " + entry.LoggerName)
 				}
@@ -179,10 +177,6 @@ var _ = Describe("Server", func() {
 					case "grpc.call_duration":
 						Expect(field.Type).To(Equal(zapcore.DurationType))
 						Expect(field.Integer).NotTo(BeZero())
-					case "grpc.start_time":
-						Expect(field.Type).To(Equal(zapcore.TimeType))
-						Expect(field.Integer).NotTo(BeZero())
-						Expect(time.Unix(0, field.Integer)).To(BeTemporally("~", startTime, endTime.Sub(startTime)))
 					case "grpc.service":
 						Expect(field.Type).To(Equal(zapcore.StringType))
 						Expect(field.String).To(Equal("testpb.EchoService"))
@@ -229,7 +223,6 @@ var _ = Describe("Server", func() {
 				keyNames = append(keyNames, field.Key)
 			}
 			Expect(keyNames).To(ConsistOf(
-				"grpc.start_time",
 				"grpc.service",
 				"grpc.method",
 				"grpc.request_deadline",
@@ -367,7 +360,6 @@ var _ = Describe("Server", func() {
 			streamClient, err := echoServiceClient.EchoStream(ctx)
 			Expect(err).NotTo(HaveOccurred())
 
-			startTime := time.Now()
 			err = streamClient.Send(&testpb.Message{Message: "hello"})
 			Expect(err).NotTo(HaveOccurred())
 
@@ -377,7 +369,6 @@ var _ = Describe("Server", func() {
 
 			err = streamClient.CloseSend()
 			Expect(err).NotTo(HaveOccurred())
-			endTime := time.Now()
 
 			Eventually(observed.AllUntimed).Should(HaveLen(3))
 			var logMessages []string
@@ -399,12 +390,12 @@ var _ = Describe("Server", func() {
 				switch entry.LoggerName {
 				case "test-logger":
 					Expect(entry.Level).To(Equal(zapcore.InfoLevel))
-					Expect(entry.Context).To(HaveLen(9))
-					Expect(keyNames).To(HaveLen(9))
+					Expect(entry.Context).To(HaveLen(8))
+					Expect(keyNames).To(HaveLen(8))
 				case "test-logger.payload":
 					Expect(entry.Level).To(Equal(zapcore.DebugLevel - 1))
-					Expect(entry.Context).To(HaveLen(7))
-					Expect(keyNames).To(HaveLen(7))
+					Expect(entry.Context).To(HaveLen(6))
+					Expect(keyNames).To(HaveLen(6))
 				default:
 					Fail("unexpected logger name: " + entry.LoggerName)
 				}
@@ -418,10 +409,6 @@ var _ = Describe("Server", func() {
 					case "grpc.call_duration":
 						Expect(field.Type).To(Equal(zapcore.DurationType))
 						Expect(field.Integer).NotTo(BeZero())
-					case "grpc.start_time":
-						Expect(field.Type).To(Equal(zapcore.TimeType))
-						Expect(field.Integer).NotTo(BeZero())
-						Expect(time.Unix(0, field.Integer)).To(BeTemporally("~", startTime, endTime.Sub(startTime)))
 					case "grpc.service":
 						Expect(field.Type).To(Equal(zapcore.StringType))
 						Expect(field.String).To(Equal("testpb.EchoService"))
@@ -478,7 +465,6 @@ var _ = Describe("Server", func() {
 				keyNames = append(keyNames, field.Key)
 			}
 			Expect(keyNames).To(ConsistOf(
-				"grpc.start_time",
 				"grpc.service",
 				"grpc.method",
 				"grpc.request_deadline",