From 5431b3e9aad45f0774fcb6353b4da83ff4bb3e3d Mon Sep 17 00:00:00 2001 From: Stan Hu Date: Fri, 12 Feb 2021 13:47:54 -0800 Subject: [PATCH] Support customization of timestamp format By default, RFC3339 timestamps are used, but our application uses a custom format. This commit enables us to set the format in a consistent manner. Closes #131 --- logging/kit/options.go | 23 +++++--- logging/kit/server_interceptors.go | 10 ++-- logging/kit/server_interceptors_test.go | 57 ++++++++++++-------- logging/kit/shared_test.go | 7 +-- logging/logrus/options.go | 29 ++++++---- logging/logrus/server_interceptors.go | 10 ++-- logging/logrus/server_interceptors_test.go | 62 +++++++++++++--------- logging/logrus/shared_test.go | 7 +-- logging/zap/options.go | 30 +++++++---- logging/zap/server_interceptors.go | 10 ++-- logging/zap/server_interceptors_test.go | 56 +++++++++++-------- logging/zap/shared_test.go | 7 +-- 12 files changed, 191 insertions(+), 117 deletions(-) diff --git a/logging/kit/options.go b/logging/kit/options.go index c0dd542c2..c16eb8933 100644 --- a/logging/kit/options.go +++ b/logging/kit/options.go @@ -11,17 +11,19 @@ import ( var ( defaultOptions = &options{ - shouldLog: grpc_logging.DefaultDeciderMethod, - codeFunc: grpc_logging.DefaultErrorToCode, - durationFunc: DefaultDurationToField, + shouldLog: grpc_logging.DefaultDeciderMethod, + codeFunc: grpc_logging.DefaultErrorToCode, + durationFunc: DefaultDurationToField, + timestampFormat: time.RFC3339, } ) type options struct { - levelFunc CodeToLevel - shouldLog grpc_logging.Decider - codeFunc grpc_logging.ErrorToCode - durationFunc DurationToField + levelFunc CodeToLevel + shouldLog grpc_logging.Decider + codeFunc grpc_logging.ErrorToCode + durationFunc DurationToField + timestampFormat string } type Option func(*options) @@ -80,6 +82,13 @@ func WithDurationField(f DurationToField) Option { } } +// WithTimestampFormat customizes the timestamps emitted in the log fields. +func WithTimestampFormat(format string) Option { + return func(o *options) { + o.timestampFormat = format + } +} + // DefaultCodeToLevel is the default implementation of gRPC return codes and interceptor log level for server side. func DefaultCodeToLevel(code codes.Code, logger log.Logger) log.Logger { switch code { diff --git a/logging/kit/server_interceptors.go b/logging/kit/server_interceptors.go index 5d24ac262..f502c7b8e 100644 --- a/logging/kit/server_interceptors.go +++ b/logging/kit/server_interceptors.go @@ -25,7 +25,7 @@ func UnaryServerInterceptor(logger log.Logger, opts ...Option) grpc.UnaryServerI o := evaluateServerOpt(opts) return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { startTime := time.Now() - newCtx := injectLogger(ctx, logger, info.FullMethod, startTime) + newCtx := injectLogger(ctx, logger, info.FullMethod, startTime, o.timestampFormat) resp, err := handler(newCtx, req) if !o.shouldLog(info.FullMethod, err) { @@ -44,7 +44,7 @@ func StreamServerInterceptor(logger log.Logger, opts ...Option) grpc.StreamServe o := evaluateServerOpt(opts) return func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { startTime := time.Now() - newCtx := injectLogger(stream.Context(), logger, info.FullMethod, startTime) + newCtx := injectLogger(stream.Context(), logger, info.FullMethod, startTime, o.timestampFormat) wrapped := grpc_middleware.WrapServerStream(stream) wrapped.WrappedContext = newCtx @@ -61,11 +61,11 @@ func StreamServerInterceptor(logger log.Logger, opts ...Option) grpc.StreamServe } } -func injectLogger(ctx context.Context, logger log.Logger, fullMethodString string, start time.Time) context.Context { +func injectLogger(ctx context.Context, logger log.Logger, fullMethodString string, start time.Time, timestampFormat string) context.Context { f := ctxkit.TagsToFields(ctx) - f = append(f, "grpc.start_time", start.Format(time.RFC3339)) + f = append(f, "grpc.start_time", start.Format(timestampFormat)) if d, ok := ctx.Deadline(); ok { - f = append(f, "grpc.request.deadline", d.Format(time.RFC3339)) + f = append(f, "grpc.request.deadline", d.Format(timestampFormat)) } f = append(f, serverCallFields(fullMethodString)...) callLog := log.With(logger, f...) diff --git a/logging/kit/server_interceptors_test.go b/logging/kit/server_interceptors_test.go index 5032a3bfb..07b5e3c4f 100644 --- a/logging/kit/server_interceptors_test.go +++ b/logging/kit/server_interceptors_test.go @@ -33,19 +33,34 @@ func TestKitLoggingSuite(t *testing.T) { t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7") return } - opts := []grpc_kit.Option{ - grpc_kit.WithLevels(customCodeToLevel), - } - b := newKitBaseSuite(t) - b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ - grpc_middleware.WithStreamServerChain( - grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), - grpc_kit.StreamServerInterceptor(b.logger, opts...)), - grpc_middleware.WithUnaryServerChain( - grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), - grpc_kit.UnaryServerInterceptor(b.logger, opts...)), + + for _, tcase := range []struct { + timestampFormat string + }{ + { + timestampFormat: time.RFC3339, + }, + { + timestampFormat: "2006-01-02", + }, + } { + opts := []grpc_kit.Option{ + grpc_kit.WithLevels(customCodeToLevel), + grpc_kit.WithTimestampFormat(tcase.timestampFormat), + } + + b := newKitBaseSuite(t) + b.timestampFormat = tcase.timestampFormat + b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ + grpc_middleware.WithStreamServerChain( + grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), + grpc_kit.StreamServerInterceptor(b.logger, opts...)), + grpc_middleware.WithUnaryServerChain( + grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), + grpc_kit.UnaryServerInterceptor(b.logger, opts...)), + } + suite.Run(t, &kitServerSuite{b}) } - suite.Run(t, &kitServerSuite{b}) } type kitServerSuite struct { @@ -69,13 +84,13 @@ func (s *kitServerSuite) TestPing_WithCustomTags() { assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int`") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time") - _, err := time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") require.Contains(s.T(), m, "grpc.request.deadline", "all lines must contain the deadline of the call") - _, err = time.Parse(time.RFC3339, m["grpc.request.deadline"].(string)) - require.NoError(s.T(), err, "should be able to parse deadline as RFC3339") - assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(time.RFC3339), "should have the same deadline that was set by the caller") + _, err = time.Parse(s.timestampFormat, m["grpc.request.deadline"].(string)) + require.NoError(s.T(), err, "should be able to parse deadline") + assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(s.timestampFormat), "should have the same deadline that was set by the caller") } assert.Equal(s.T(), msgs[0]["msg"], "some ping", "handler's message must contain user message") @@ -129,8 +144,8 @@ func (s *kitServerSuite) TestPingError_WithCustomLevels() { assert.Equal(s.T(), m["msg"], "finished unary call with code "+tcase.code.String(), "needs the correct end message") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time") - _, err = time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err = time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") } } @@ -156,8 +171,8 @@ func (s *kitServerSuite) TestPingList_WithCustomTags() { assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int` set by AddFields") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time") - _, err := time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") } assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "handler's message must contain user message") diff --git a/logging/kit/shared_test.go b/logging/kit/shared_test.go index 7dacf30b0..d0806b081 100644 --- a/logging/kit/shared_test.go +++ b/logging/kit/shared_test.go @@ -49,9 +49,10 @@ func (s *loggingPingService) PingEmpty(ctx context.Context, empty *pb_testproto. type kitBaseSuite struct { *grpc_testing.InterceptorTestSuite - mutexBuffer *grpc_testing.MutexReadWriter - buffer *bytes.Buffer - logger log.Logger + mutexBuffer *grpc_testing.MutexReadWriter + buffer *bytes.Buffer + logger log.Logger + timestampFormat string } func newKitBaseSuite(t *testing.T) *kitBaseSuite { diff --git a/logging/logrus/options.go b/logging/logrus/options.go index 53b568f50..f6352c459 100644 --- a/logging/logrus/options.go +++ b/logging/logrus/options.go @@ -15,20 +15,22 @@ import ( var ( defaultOptions = &options{ - levelFunc: nil, - shouldLog: grpc_logging.DefaultDeciderMethod, - codeFunc: grpc_logging.DefaultErrorToCode, - durationFunc: DefaultDurationToField, - messageFunc: DefaultMessageProducer, + levelFunc: nil, + shouldLog: grpc_logging.DefaultDeciderMethod, + codeFunc: grpc_logging.DefaultErrorToCode, + durationFunc: DefaultDurationToField, + messageFunc: DefaultMessageProducer, + timestampFormat: time.RFC3339, } ) type options struct { - levelFunc CodeToLevel - shouldLog grpc_logging.Decider - codeFunc grpc_logging.ErrorToCode - durationFunc DurationToField - messageFunc MessageProducer + levelFunc CodeToLevel + shouldLog grpc_logging.Decider + codeFunc grpc_logging.ErrorToCode + durationFunc DurationToField + messageFunc MessageProducer + timestampFormat string } func evaluateServerOpt(opts []Option) *options { @@ -94,6 +96,13 @@ func WithMessageProducer(f MessageProducer) Option { } } +// WithTimestampFormat customizes the timestamps emitted in the log fields. +func WithTimestampFormat(format string) Option { + return func(o *options) { + o.timestampFormat = format + } +} + // DefaultCodeToLevel is the default implementation of gRPC return codes to log levels for server side. func DefaultCodeToLevel(code codes.Code) logrus.Level { switch code { diff --git a/logging/logrus/server_interceptors.go b/logging/logrus/server_interceptors.go index c20f80af7..f7e9fc09a 100644 --- a/logging/logrus/server_interceptors.go +++ b/logging/logrus/server_interceptors.go @@ -26,7 +26,7 @@ func UnaryServerInterceptor(entry *logrus.Entry, opts ...Option) grpc.UnaryServe o := evaluateServerOpt(opts) return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { startTime := time.Now() - newCtx := newLoggerForCall(ctx, entry, info.FullMethod, startTime) + newCtx := newLoggerForCall(ctx, entry, info.FullMethod, startTime, o.timestampFormat) resp, err := handler(newCtx, req) @@ -54,7 +54,7 @@ func StreamServerInterceptor(entry *logrus.Entry, opts ...Option) grpc.StreamSer o := evaluateServerOpt(opts) return func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { startTime := time.Now() - newCtx := newLoggerForCall(stream.Context(), entry, info.FullMethod, startTime) + newCtx := newLoggerForCall(stream.Context(), entry, info.FullMethod, startTime, o.timestampFormat) wrapped := grpc_middleware.WrapServerStream(stream) wrapped.WrappedContext = newCtx @@ -76,7 +76,7 @@ func StreamServerInterceptor(entry *logrus.Entry, opts ...Option) grpc.StreamSer } } -func newLoggerForCall(ctx context.Context, entry *logrus.Entry, fullMethodString string, start time.Time) context.Context { +func newLoggerForCall(ctx context.Context, entry *logrus.Entry, fullMethodString string, start time.Time, timestampFormat string) context.Context { service := path.Dir(fullMethodString)[1:] method := path.Base(fullMethodString) callLog := entry.WithFields( @@ -85,13 +85,13 @@ func newLoggerForCall(ctx context.Context, entry *logrus.Entry, fullMethodString KindField: "server", "grpc.service": service, "grpc.method": method, - "grpc.start_time": start.Format(time.RFC3339), + "grpc.start_time": start.Format(timestampFormat), }) if d, ok := ctx.Deadline(); ok { callLog = callLog.WithFields( logrus.Fields{ - "grpc.request.deadline": d.Format(time.RFC3339), + "grpc.request.deadline": d.Format(timestampFormat), }) } diff --git a/logging/logrus/server_interceptors_test.go b/logging/logrus/server_interceptors_test.go index ea6b1f2aa..f083f7afe 100644 --- a/logging/logrus/server_interceptors_test.go +++ b/logging/logrus/server_interceptors_test.go @@ -18,19 +18,33 @@ import ( ) func TestLogrusServerSuite(t *testing.T) { - opts := []grpc_logrus.Option{ - grpc_logrus.WithLevels(customCodeToLevel), - } - b := newLogrusBaseSuite(t) - b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ - grpc_middleware.WithStreamServerChain( - grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), - grpc_logrus.StreamServerInterceptor(logrus.NewEntry(b.logger), opts...)), - grpc_middleware.WithUnaryServerChain( - grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), - grpc_logrus.UnaryServerInterceptor(logrus.NewEntry(b.logger), opts...)), + for _, tcase := range []struct { + timestampFormat string + }{ + { + timestampFormat: time.RFC3339, + }, + { + timestampFormat: "2006-01-02", + }, + } { + opts := []grpc_logrus.Option{ + grpc_logrus.WithLevels(customCodeToLevel), + grpc_logrus.WithTimestampFormat(tcase.timestampFormat), + } + + b := newLogrusBaseSuite(t) + b.timestampFormat = tcase.timestampFormat + b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ + grpc_middleware.WithStreamServerChain( + grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), + grpc_logrus.StreamServerInterceptor(logrus.NewEntry(b.logger), opts...)), + grpc_middleware.WithUnaryServerChain( + grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), + grpc_logrus.UnaryServerInterceptor(logrus.NewEntry(b.logger), opts...)), + } + suite.Run(t, &logrusServerSuite{b}) } - suite.Run(t, &logrusServerSuite{b}) } type logrusServerSuite struct { @@ -55,13 +69,13 @@ func (s *logrusServerSuite) TestPing_WithCustomTags() { assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int`") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time of the call") - _, err := time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") require.Contains(s.T(), m, "grpc.request.deadline", "all lines must contain the deadline of the call") - _, err = time.Parse(time.RFC3339, m["grpc.request.deadline"].(string)) - require.NoError(s.T(), err, "should be able to parse deadline as RFC3339") - assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(time.RFC3339), "should have the same deadline that was set by the caller") + _, err = time.Parse(s.timestampFormat, m["grpc.request.deadline"].(string)) + require.NoError(s.T(), err, "should be able to parse deadline") + assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(s.timestampFormat), "should have the same deadline that was set by the caller") } assert.Equal(s.T(), msgs[0]["msg"], "some ping", "first message must contain the correct user message") @@ -114,12 +128,12 @@ func (s *logrusServerSuite) TestPingError_WithCustomLevels() { assert.Equal(s.T(), m["msg"], "finished unary call with code "+tcase.code.String(), "must have the correct finish message") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain a start time for the call") - _, err = time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse the start time as RFC3339") + _, err = time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse the start time") require.Contains(s.T(), m, "grpc.request.deadline", "all lines must contain the deadline of the call") - _, err = time.Parse(time.RFC3339, m["grpc.request.deadline"].(string)) - require.NoError(s.T(), err, "should be able to parse deadline as RFC3339") + _, err = time.Parse(s.timestampFormat, m["grpc.request.deadline"].(string)) + require.NoError(s.T(), err, "should be able to parse deadline") } } @@ -145,12 +159,12 @@ func (s *logrusServerSuite) TestPingList_WithCustomTags() { assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int`") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time for the call") - _, err := time.Parse(time.RFC3339, m["grpc.start_time"].(string)) + _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") require.Contains(s.T(), m, "grpc.request.deadline", "all lines must contain the deadline of the call") - _, err = time.Parse(time.RFC3339, m["grpc.request.deadline"].(string)) - require.NoError(s.T(), err, "should be able to parse deadline as RFC3339") + _, err = time.Parse(s.timestampFormat, m["grpc.request.deadline"].(string)) + require.NoError(s.T(), err, "should be able to parse deadline") } assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "msg must be the correct message") diff --git a/logging/logrus/shared_test.go b/logging/logrus/shared_test.go index 51a63022b..1c542f13e 100644 --- a/logging/logrus/shared_test.go +++ b/logging/logrus/shared_test.go @@ -57,9 +57,10 @@ func (s *loggingPingService) PingEmpty(ctx context.Context, empty *pb_testproto. type logrusBaseSuite struct { *grpc_testing.InterceptorTestSuite - mutexBuffer *grpc_testing.MutexReadWriter - buffer *bytes.Buffer - logger *logrus.Logger + mutexBuffer *grpc_testing.MutexReadWriter + buffer *bytes.Buffer + logger *logrus.Logger + timestampFormat string } func newLogrusBaseSuite(t *testing.T) *logrusBaseSuite { diff --git a/logging/zap/options.go b/logging/zap/options.go index d64882b31..9362769ab 100644 --- a/logging/zap/options.go +++ b/logging/zap/options.go @@ -13,20 +13,22 @@ import ( var ( defaultOptions = &options{ - levelFunc: DefaultCodeToLevel, - shouldLog: grpc_logging.DefaultDeciderMethod, - codeFunc: grpc_logging.DefaultErrorToCode, - durationFunc: DefaultDurationToField, - messageFunc: DefaultMessageProducer, + levelFunc: DefaultCodeToLevel, + shouldLog: grpc_logging.DefaultDeciderMethod, + codeFunc: grpc_logging.DefaultErrorToCode, + durationFunc: DefaultDurationToField, + messageFunc: DefaultMessageProducer, + timestampFormat: time.RFC3339, } ) type options struct { - levelFunc CodeToLevel - shouldLog grpc_logging.Decider - codeFunc grpc_logging.ErrorToCode - durationFunc DurationToField - messageFunc MessageProducer + levelFunc CodeToLevel + shouldLog grpc_logging.Decider + codeFunc grpc_logging.ErrorToCode + durationFunc DurationToField + messageFunc MessageProducer + timestampFormat string } func evaluateServerOpt(opts []Option) *options { @@ -36,6 +38,7 @@ func evaluateServerOpt(opts []Option) *options { for _, o := range opts { o(optCopy) } + return optCopy } @@ -92,6 +95,13 @@ func WithMessageProducer(f MessageProducer) Option { } } +// WithTimestampFormat customizes the timestamps emitted in the log fields. +func WithTimestampFormat(format string) Option { + return func(o *options) { + o.timestampFormat = format + } +} + // DefaultCodeToLevel is the default implementation of gRPC return codes and interceptor log level for server side. func DefaultCodeToLevel(code codes.Code) zapcore.Level { switch code { diff --git a/logging/zap/server_interceptors.go b/logging/zap/server_interceptors.go index 590afddae..1db035897 100644 --- a/logging/zap/server_interceptors.go +++ b/logging/zap/server_interceptors.go @@ -26,7 +26,7 @@ func UnaryServerInterceptor(logger *zap.Logger, opts ...Option) grpc.UnaryServer return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { startTime := time.Now() - newCtx := newLoggerForCall(ctx, logger, info.FullMethod, startTime) + newCtx := newLoggerForCall(ctx, logger, info.FullMethod, startTime, o.timestampFormat) resp, err := handler(newCtx, req) if !o.shouldLog(info.FullMethod, err) { @@ -46,7 +46,7 @@ func StreamServerInterceptor(logger *zap.Logger, opts ...Option) grpc.StreamServ o := evaluateServerOpt(opts) return func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error { startTime := time.Now() - newCtx := newLoggerForCall(stream.Context(), logger, info.FullMethod, startTime) + newCtx := newLoggerForCall(stream.Context(), logger, info.FullMethod, startTime, o.timestampFormat) wrapped := grpc_middleware.WrapServerStream(stream) wrapped.WrappedContext = newCtx @@ -74,11 +74,11 @@ func serverCallFields(fullMethodString string) []zapcore.Field { } } -func newLoggerForCall(ctx context.Context, logger *zap.Logger, fullMethodString string, start time.Time) context.Context { +func newLoggerForCall(ctx context.Context, logger *zap.Logger, fullMethodString string, start time.Time, timestampFormat string) context.Context { var f []zapcore.Field - f = append(f, zap.String("grpc.start_time", start.Format(time.RFC3339))) + f = append(f, zap.String("grpc.start_time", start.Format(timestampFormat))) if d, ok := ctx.Deadline(); ok { - f = append(f, zap.String("grpc.request.deadline", d.Format(time.RFC3339))) + f = append(f, zap.String("grpc.request.deadline", d.Format(timestampFormat))) } callLog := logger.With(append(f, serverCallFields(fullMethodString)...)...) return ctxzap.ToContext(ctx, callLog) diff --git a/logging/zap/server_interceptors_test.go b/logging/zap/server_interceptors_test.go index 7750ef2ad..8b0a79ab6 100644 --- a/logging/zap/server_interceptors_test.go +++ b/logging/zap/server_interceptors_test.go @@ -34,19 +34,33 @@ func TestZapLoggingSuite(t *testing.T) { t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7") return } - opts := []grpc_zap.Option{ - grpc_zap.WithLevels(customCodeToLevel), - } - b := newBaseZapSuite(t) - b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ - grpc_middleware.WithStreamServerChain( - grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), - grpc_zap.StreamServerInterceptor(b.log, opts...)), - grpc_middleware.WithUnaryServerChain( - grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), - grpc_zap.UnaryServerInterceptor(b.log, opts...)), + + for _, tcase := range []struct { + timestampFormat string + }{ + { + timestampFormat: time.RFC3339, + }, + { + timestampFormat: "2006-01-02", + }, + } { + opts := []grpc_zap.Option{ + grpc_zap.WithLevels(customCodeToLevel), + grpc_zap.WithTimestampFormat(tcase.timestampFormat), + } + b := newBaseZapSuite(t) + b.timestampFormat = tcase.timestampFormat + b.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ + grpc_middleware.WithStreamServerChain( + grpc_ctxtags.StreamServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), + grpc_zap.StreamServerInterceptor(b.log, opts...)), + grpc_middleware.WithUnaryServerChain( + grpc_ctxtags.UnaryServerInterceptor(grpc_ctxtags.WithFieldExtractor(grpc_ctxtags.CodeGenRequestFieldExtractor)), + grpc_zap.UnaryServerInterceptor(b.log, opts...)), + } + suite.Run(t, &zapServerSuite{b}) } - suite.Run(t, &zapServerSuite{b}) } type zapServerSuite struct { @@ -70,13 +84,13 @@ func (s *zapServerSuite) TestPing_WithCustomTags() { assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int`") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time") - _, err := time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") require.Contains(s.T(), m, "grpc.request.deadline", "all lines must contain the deadline of the call") - _, err = time.Parse(time.RFC3339, m["grpc.request.deadline"].(string)) - require.NoError(s.T(), err, "should be able to parse deadline as RFC3339") - assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(time.RFC3339), "should have the same deadline that was set by the caller") + _, err = time.Parse(s.timestampFormat, m["grpc.request.deadline"].(string)) + require.NoError(s.T(), err, "should be able to parse deadline") + assert.Equal(s.T(), m["grpc.request.deadline"], deadline.Format(s.timestampFormat), "should have the same deadline that was set by the caller") } assert.Equal(s.T(), msgs[0]["msg"], "some ping", "handler's message must contain user message") @@ -130,8 +144,8 @@ func (s *zapServerSuite) TestPingError_WithCustomLevels() { assert.Equal(s.T(), m["msg"], "finished unary call with code "+tcase.code.String(), "needs the correct end message") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time") - _, err = time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err = time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") } } @@ -157,8 +171,8 @@ func (s *zapServerSuite) TestPingList_WithCustomTags() { assert.Contains(s.T(), m, "custom_tags.int", "all lines must contain `custom_tags.int` set by AddFields") require.Contains(s.T(), m, "grpc.start_time", "all lines must contain the start time") - _, err := time.Parse(time.RFC3339, m["grpc.start_time"].(string)) - assert.NoError(s.T(), err, "should be able to parse start time as RFC3339") + _, err := time.Parse(s.timestampFormat, m["grpc.start_time"].(string)) + assert.NoError(s.T(), err, "should be able to parse start time") } assert.Equal(s.T(), msgs[0]["msg"], "some pinglist", "handler's message must contain user message") diff --git a/logging/zap/shared_test.go b/logging/zap/shared_test.go index a976014d1..36828faf4 100644 --- a/logging/zap/shared_test.go +++ b/logging/zap/shared_test.go @@ -75,9 +75,10 @@ func newBaseZapSuite(t *testing.T) *zapBaseSuite { type zapBaseSuite struct { *grpc_testing.InterceptorTestSuite - mutexBuffer *grpc_testing.MutexReadWriter - buffer *bytes.Buffer - log *zap.Logger + mutexBuffer *grpc_testing.MutexReadWriter + buffer *bytes.Buffer + log *zap.Logger + timestampFormat string } func (s *zapBaseSuite) SetupTest() {