From e7586b7c71d73e2c77a81e3534cc1f79ec9c190a Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 5 Sep 2023 16:38:23 +0200 Subject: [PATCH 01/12] add option to choose grpc log fields Signed-off-by: Coleen Iona Quadros --- interceptors/logging/interceptors.go | 10 +- interceptors/logging/interceptors_test.go | 149 ++++++++++++++++++++++ interceptors/logging/logging.go | 22 ++++ interceptors/logging/options.go | 20 +++ testing/testpb/test.pb.go | 5 +- testing/testpb/test_grpc.pb.go | 1 - 6 files changed, 201 insertions(+), 6 deletions(-) diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go index 7161dacbb..ce932a10f 100644 --- a/interceptors/logging/interceptors.go +++ b/interceptors/logging/interceptors.go @@ -141,8 +141,14 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc kind = KindClientFieldValue } - // Field dups from context override the common fields. - fields := newCommonFields(kind, c).WithUnique(ExtractFields(ctx)) + fields := Fields{} + if opts.grpcLogFields != nil { + fields = fields.WithUnique(customCommonFields(kind, c, opts.grpcLogFields())) + } else { + // Field dups from context override the common fields. + fields = newCommonFields(kind, c).WithUnique(ExtractFields(ctx)) + } + if !c.IsClient { if peer, ok := peer.FromContext(ctx); ok { fields = append(fields, "peer.address", peer.Addr.String()) diff --git a/interceptors/logging/interceptors_test.go b/interceptors/logging/interceptors_test.go index 3dbc69354..866e86109 100644 --- a/interceptors/logging/interceptors_test.go +++ b/interceptors/logging/interceptors_test.go @@ -630,6 +630,155 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me } } +func addGrpcLogFields() []string { + return []string{ + logging.MethodFieldKey, logging.ServiceFieldKey, "should-not-be-added", + } +} + +type loggingCustomGrpcLogFieldsSuite struct { + *baseLoggingSuite +} + +func TestCustomGrpcLogFieldsSuite(t *testing.T) { + if strings.HasPrefix(runtime.Version(), "go1.7") { + t.Skipf("Skipping due to json.RawMessage incompatibility with go1.7") + return + } + s := &loggingCustomGrpcLogFieldsSuite{ + baseLoggingSuite: &baseLoggingSuite{ + logger: newMockLogger(), + InterceptorTestSuite: &testpb.InterceptorTestSuite{ + TestService: &testpb.TestPingService{}, + }, + }, + } + s.InterceptorTestSuite.ClientOpts = []grpc.DialOption{ + grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), + } + s.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ + grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), + } + suite.Run(t, s) +} + +// Test that fields are added to logs using withGrpcLogFields. +func (s *loggingCustomGrpcLogFieldsSuite) TestCustomGrpcLogFieldsWithPing() { + _, err := s.Client.Ping(s.SimpleCtx(), testpb.GoodPing) + assert.NoError(s.T(), err, "there must be not be an on a successful call") + + lines := s.logger.o.Lines() + sort.Sort(lines) + require.Len(s.T(), lines, 4) + + clientStartCallLogLine := lines[2] + assert.Equal(s.T(), logging.LevelDebug, clientStartCallLogLine.lvl) + assert.Equal(s.T(), "started call", clientStartCallLogLine.msg) + clientStartCallFields := clientStartCallLogLine.fields + clientStartCallFields.AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "Ping"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) + + serverStartCallLogLine := lines[3] + assert.Equal(s.T(), logging.LevelDebug, serverStartCallLogLine.lvl) + assert.Equal(s.T(), "started call", serverStartCallLogLine.msg) + serverStartCallFields := serverStartCallLogLine.fields + serverStartCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). + AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "Ping"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) + + serverFinishCallLogLine := lines[0] + assert.Equal(s.T(), logging.LevelDebug, serverFinishCallLogLine.lvl) + assert.Equal(s.T(), "finished call", serverFinishCallLogLine.msg) + serverFinishCallFields := serverFinishCallLogLine.fields + serverFinishCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). + AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertField(s.T(), "grpc.code", "OK"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "Ping"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) + + clientFinishCallLogLine := lines[1] + assert.Equal(s.T(), logging.LevelDebug, clientFinishCallLogLine.lvl) + assert.Equal(s.T(), "finished call", clientFinishCallLogLine.msg) + + clientFinishCallFields := clientFinishCallLogLine.fields + clientFinishCallFields.AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertField(s.T(), "grpc.code", "OK"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "Ping"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) +} + +func (s *loggingCustomGrpcLogFieldsSuite) TestCustomGrpcLogFieldsWithPingList() { + stream, err := s.Client.PingList(s.SimpleCtx(), testpb.GoodPingList) + require.NoError(s.T(), err, "should not fail on establishing the stream") + for { + _, err := stream.Recv() + if err == io.EOF { + break + } + require.NoError(s.T(), err, "reading stream should not fail") + } + lines := s.logger.o.Lines() + sort.Sort(lines) + require.Len(s.T(), lines, 4) + + clientStartCallLogLine := lines[2] + assert.Equal(s.T(), logging.LevelDebug, clientStartCallLogLine.lvl) + assert.Equal(s.T(), "started call", clientStartCallLogLine.msg) + clientStartCallFields := clientStartCallLogLine.fields + clientStartCallFields.AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "PingList"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) + + serverStartCallLogLine := lines[3] + assert.Equal(s.T(), logging.LevelDebug, serverStartCallLogLine.lvl) + assert.Equal(s.T(), "started call", serverStartCallLogLine.msg) + serverStartCallFields := serverStartCallLogLine.fields + serverStartCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). + AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "PingList"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) + + serverFinishCallLogLine := lines[0] + assert.Equal(s.T(), logging.LevelDebug, serverFinishCallLogLine.lvl) + assert.Equal(s.T(), "finished call", serverFinishCallLogLine.msg) + serverFinishCallFields := serverFinishCallLogLine.fields + serverFinishCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). + AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertField(s.T(), "grpc.code", "OK"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "PingList"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) + + clientFinishCallLogLine := lines[1] + assert.Equal(s.T(), logging.LevelDebug, clientFinishCallLogLine.lvl) + assert.Equal(s.T(), "finished call", clientFinishCallLogLine.msg) + + clientFinishCallFields := clientFinishCallLogLine.fields + clientFinishCallFields.AssertFieldNotEmpty(s.T(), "grpc.start_time"). + AssertFieldNotEmpty(s.T(), "grpc.request.deadline"). + AssertField(s.T(), "grpc.code", "OK"). + AssertFieldNotEmpty(s.T(), "grpc.time_ms"). + AssertField(s.T(), logging.MethodFieldKey, "PingList"). + AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) +} + // waitUntil executes f every interval seconds until timeout or no error is returned from f. func waitUntil(interval time.Duration, stopc <-chan struct{}, f func() error) error { tick := time.NewTicker(interval) diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index 4b0247862..51ddc1d6d 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -38,6 +38,28 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { } } +func customCommonFields(kind string, c interceptors.CallMeta, customFields []string) Fields { + commonFields := Fields{ + SystemTag[0], SystemTag[1], + ComponentFieldKey, kind, + ServiceFieldKey, c.Service, + MethodFieldKey, c.Method, + MethodTypeFieldKey, string(c.Typ), + } + + newFields := Fields{} + for _, key := range customFields { + commonFieldIterator := commonFields.Iterator() + for commonFieldIterator.Next() { + ck, cv := commonFieldIterator.At() + if ck == key { + newFields = append(newFields, ck, cv) + } + } + } + return newFields +} + // Fields loosely represents key value pairs that adds context to log lines. The key has to be type of string, whereas // value can be an arbitrary object. type Fields []any diff --git a/interceptors/logging/options.go b/interceptors/logging/options.go index 4b9d082e6..9bcd72399 100644 --- a/interceptors/logging/options.go +++ b/interceptors/logging/options.go @@ -50,6 +50,7 @@ var ( // levelFunc depends if it's client or server. levelFunc: nil, timestampFormat: time.RFC3339, + grpcLogFields: nil, } ) @@ -60,6 +61,7 @@ type options struct { durationFieldFunc DurationToFields timestampFormat string fieldsFromCtxCallMetaFn fieldsFromCtxCallMetaFn + grpcLogFields AddGrpcLogFields } type Option func(*options) @@ -204,3 +206,21 @@ func WithTimestampFormat(format string) Option { o.timestampFormat = format } } + +// AddGrpcLogFields customizes the function for adding gRPC fields to the log entry from the below list. +// +// -SystemTag[0], +// -ComponentFieldKey, +// -ServiceFieldKey, +// -MethodFieldKey, +// -MethodTypeFieldKey, +// +// If not provided default fields will be used. +type AddGrpcLogFields func() []string + +// WithAddGrpcLogFields customizes the function for adding gRPC fields to the log entry. +func WithGrpcLogFields(f AddGrpcLogFields) Option { + return func(o *options) { + o.grpcLogFields = f + } +} diff --git a/testing/testpb/test.pb.go b/testing/testpb/test.pb.go index 83b5de05c..5e99f0e4e 100644 --- a/testing/testpb/test.pb.go +++ b/testing/testpb/test.pb.go @@ -7,11 +7,10 @@ package testpb import ( - reflect "reflect" - sync "sync" - protoreflect "google.golang.org/protobuf/reflect/protoreflect" protoimpl "google.golang.org/protobuf/runtime/protoimpl" + reflect "reflect" + sync "sync" ) const ( diff --git a/testing/testpb/test_grpc.pb.go b/testing/testpb/test_grpc.pb.go index effb0e2a4..27ed06c2d 100644 --- a/testing/testpb/test_grpc.pb.go +++ b/testing/testpb/test_grpc.pb.go @@ -4,7 +4,6 @@ package testpb import ( context "context" - grpc "google.golang.org/grpc" codes "google.golang.org/grpc/codes" status "google.golang.org/grpc/status" From 95849e2b243bb677105586409cd23f94398ded8b Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 5 Sep 2023 16:52:37 +0200 Subject: [PATCH 02/12] test changes Signed-off-by: Coleen Iona Quadros --- interceptors/logging/interceptors_test.go | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/interceptors/logging/interceptors_test.go b/interceptors/logging/interceptors_test.go index 866e86109..94ecd21ff 100644 --- a/interceptors/logging/interceptors_test.go +++ b/interceptors/logging/interceptors_test.go @@ -654,12 +654,12 @@ func TestCustomGrpcLogFieldsSuite(t *testing.T) { }, } s.InterceptorTestSuite.ClientOpts = []grpc.DialOption{ - grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), - grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), } s.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ - grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), - grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), } suite.Run(t, s) } @@ -684,7 +684,7 @@ func (s *loggingCustomGrpcLogFieldsSuite) TestCustomGrpcLogFieldsWithPing() { AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) serverStartCallLogLine := lines[3] - assert.Equal(s.T(), logging.LevelDebug, serverStartCallLogLine.lvl) + assert.Equal(s.T(), logging.LevelInfo, serverStartCallLogLine.lvl) assert.Equal(s.T(), "started call", serverStartCallLogLine.msg) serverStartCallFields := serverStartCallLogLine.fields serverStartCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). @@ -695,7 +695,7 @@ func (s *loggingCustomGrpcLogFieldsSuite) TestCustomGrpcLogFieldsWithPing() { AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) serverFinishCallLogLine := lines[0] - assert.Equal(s.T(), logging.LevelDebug, serverFinishCallLogLine.lvl) + assert.Equal(s.T(), logging.LevelInfo, serverFinishCallLogLine.lvl) assert.Equal(s.T(), "finished call", serverFinishCallLogLine.msg) serverFinishCallFields := serverFinishCallLogLine.fields serverFinishCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). @@ -744,7 +744,7 @@ func (s *loggingCustomGrpcLogFieldsSuite) TestCustomGrpcLogFieldsWithPingList() AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) serverStartCallLogLine := lines[3] - assert.Equal(s.T(), logging.LevelDebug, serverStartCallLogLine.lvl) + assert.Equal(s.T(), logging.LevelInfo, serverStartCallLogLine.lvl) assert.Equal(s.T(), "started call", serverStartCallLogLine.msg) serverStartCallFields := serverStartCallLogLine.fields serverStartCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). @@ -755,7 +755,7 @@ func (s *loggingCustomGrpcLogFieldsSuite) TestCustomGrpcLogFieldsWithPingList() AssertField(s.T(), logging.ServiceFieldKey, testpb.TestServiceFullName).AssertNoMoreTags(s.T()) serverFinishCallLogLine := lines[0] - assert.Equal(s.T(), logging.LevelDebug, serverFinishCallLogLine.lvl) + assert.Equal(s.T(), logging.LevelInfo, serverFinishCallLogLine.lvl) assert.Equal(s.T(), "finished call", serverFinishCallLogLine.msg) serverFinishCallFields := serverFinishCallLogLine.fields serverFinishCallFields.AssertFieldNotEmpty(s.T(), "peer.address"). From 6ff63c5c695442afc6259fae42f067d4cc34b910 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 5 Sep 2023 17:42:25 +0200 Subject: [PATCH 03/12] use existing func Signed-off-by: Coleen Iona Quadros --- interceptors/logging/logging.go | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index 51ddc1d6d..53eb1ce20 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -39,13 +39,7 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { } func customCommonFields(kind string, c interceptors.CallMeta, customFields []string) Fields { - commonFields := Fields{ - SystemTag[0], SystemTag[1], - ComponentFieldKey, kind, - ServiceFieldKey, c.Service, - MethodFieldKey, c.Method, - MethodTypeFieldKey, string(c.Typ), - } + commonFields := newCommonFields(kind, c) newFields := Fields{} for _, key := range customFields { From 9d37da0ab1be9c8f5e0e6b6bc4309ffeb2c60e81 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 5 Sep 2023 18:23:17 +0200 Subject: [PATCH 04/12] lint Signed-off-by: Coleen Iona Quadros --- testing/testpb/test.pb.go | 5 +++-- testing/testpb/test_grpc.pb.go | 1 + 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/testing/testpb/test.pb.go b/testing/testpb/test.pb.go index 5e99f0e4e..83b5de05c 100644 --- a/testing/testpb/test.pb.go +++ b/testing/testpb/test.pb.go @@ -7,10 +7,11 @@ package testpb import ( - protoreflect "google.golang.org/protobuf/reflect/protoreflect" - protoimpl "google.golang.org/protobuf/runtime/protoimpl" reflect "reflect" sync "sync" + + protoreflect "google.golang.org/protobuf/reflect/protoreflect" + protoimpl "google.golang.org/protobuf/runtime/protoimpl" ) const ( diff --git a/testing/testpb/test_grpc.pb.go b/testing/testpb/test_grpc.pb.go index 27ed06c2d..effb0e2a4 100644 --- a/testing/testpb/test_grpc.pb.go +++ b/testing/testpb/test_grpc.pb.go @@ -4,6 +4,7 @@ package testpb import ( context "context" + grpc "google.golang.org/grpc" codes "google.golang.org/grpc/codes" status "google.golang.org/grpc/status" From c8c5b974a0c0c848a25c850c1d860a2a3cf15a2d Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Wed, 6 Sep 2023 10:52:47 +0200 Subject: [PATCH 05/12] refactor Signed-off-by: Coleen Iona Quadros --- interceptors/logging/interceptors.go | 3 ++- interceptors/logging/logging.go | 15 +++++++++------ 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go index ce932a10f..c073d34a7 100644 --- a/interceptors/logging/interceptors.go +++ b/interceptors/logging/interceptors.go @@ -146,8 +146,9 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc fields = fields.WithUnique(customCommonFields(kind, c, opts.grpcLogFields())) } else { // Field dups from context override the common fields. - fields = newCommonFields(kind, c).WithUnique(ExtractFields(ctx)) + fields = newCommonFields(kind, c) } + fields = fields.WithUnique(ExtractFields(ctx)) if !c.IsClient { if peer, ok := peer.FromContext(ctx); ok { diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index 53eb1ce20..5f0ce05f1 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -41,14 +41,17 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { func customCommonFields(kind string, c interceptors.CallMeta, customFields []string) Fields { commonFields := newCommonFields(kind, c) + existing := map[any]any{} + i := commonFields.Iterator() + for i.Next() { + k, v := i.At() + existing[k] = v + } + newFields := Fields{} for _, key := range customFields { - commonFieldIterator := commonFields.Iterator() - for commonFieldIterator.Next() { - ck, cv := commonFieldIterator.At() - if ck == key { - newFields = append(newFields, ck, cv) - } + if _, ok := existing[key]; ok { + newFields = append(newFields, key, existing[key]) } } return newFields From ff52335b8b560e18d9f568ac2f64b7480a94eecf Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Mon, 11 Sep 2023 11:30:10 +0200 Subject: [PATCH 06/12] refactor adding log fields Signed-off-by: Coleen Iona Quadros --- interceptors/logging/examples/go.mod | 10 +++++----- interceptors/logging/examples/go.sum | 5 +++++ interceptors/logging/interceptors.go | 2 +- interceptors/logging/interceptors_test.go | 14 ++++---------- interceptors/logging/options.go | 17 +++-------------- 5 files changed, 18 insertions(+), 30 deletions(-) diff --git a/interceptors/logging/examples/go.mod b/interceptors/logging/examples/go.mod index 49d4a3e2c..984e9c48f 100644 --- a/interceptors/logging/examples/go.mod +++ b/interceptors/logging/examples/go.mod @@ -10,7 +10,7 @@ require ( github.com/rs/zerolog v1.29.0 github.com/sirupsen/logrus v1.9.0 go.uber.org/zap v1.24.0 - golang.org/x/exp v0.0.0-20230321023759-10a507213a29 + golang.org/x/exp v0.0.0-20230522175609-2e198f4a06a1 google.golang.org/grpc v1.53.0 k8s.io/klog/v2 v2.90.1 ) @@ -22,11 +22,11 @@ require ( github.com/mattn/go-isatty v0.0.14 // indirect go.uber.org/atomic v1.7.0 // indirect go.uber.org/multierr v1.6.0 // indirect - golang.org/x/net v0.8.0 // indirect - golang.org/x/sys v0.6.0 // indirect - golang.org/x/text v0.8.0 // indirect + golang.org/x/net v0.14.0 // indirect + golang.org/x/sys v0.11.0 // indirect + golang.org/x/text v0.12.0 // indirect google.golang.org/genproto v0.0.0-20230110181048-76db0878b65f // indirect - google.golang.org/protobuf v1.30.0 // indirect + google.golang.org/protobuf v1.31.0 // indirect ) replace github.com/grpc-ecosystem/go-grpc-middleware/v2 => ../../../ diff --git a/interceptors/logging/examples/go.sum b/interceptors/logging/examples/go.sum index 04c905451..ff873eb00 100644 --- a/interceptors/logging/examples/go.sum +++ b/interceptors/logging/examples/go.sum @@ -44,15 +44,19 @@ go.uber.org/zap v1.24.0 h1:FiJd5l1UOLj0wCgbSE0rwwXHzEdAZS6hiiSnxJN/D60= go.uber.org/zap v1.24.0/go.mod h1:2kMP+WWQ8aoFoedH3T2sq6iJ2yDWpHbP0f6MQbS9Gkg= golang.org/x/exp v0.0.0-20230321023759-10a507213a29 h1:ooxPy7fPvB4kwsA2h+iBNHkAbp/4JxTSwCmvdjEYmug= golang.org/x/exp v0.0.0-20230321023759-10a507213a29/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc= +golang.org/x/exp v0.0.0-20230522175609-2e198f4a06a1/go.mod h1:V1LtkGg67GoY2N1AnLN78QLrzxkLyJw7RJb1gzOOz9w= golang.org/x/net v0.8.0 h1:Zrh2ngAOFYneWTAIAPethzeaQLuHwhuBkuV6ZiRnUaQ= golang.org/x/net v0.8.0/go.mod h1:QVkue5JL9kW//ek3r6jTKnTFis1tRmNAW2P1shuFdJc= +golang.org/x/net v0.14.0/go.mod h1:PpSgVXXLK0OxS0F31C1/tv6XNguvCrnXIDrFMspZIUI= golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0 h1:MVltZSvRTcU2ljQOhs94SXPftV6DCNnZViHeQps87pQ= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/text v0.8.0 h1:57P1ETyNKtuIjB4SRd15iJxuhj8Gc416Y78H3qgMh68= golang.org/x/text v0.8.0/go.mod h1:e1OnstbJyHTd6l/uOt8jFFHp6TRDWZR/bV3emEE/zU8= +golang.org/x/text v0.12.0/go.mod h1:TvPlkZtksWOMsz7fbANvkp4WM8x/WCo/om8BMLbz+aE= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= google.golang.org/genproto v0.0.0-20230110181048-76db0878b65f h1:BWUVssLB0HVOSY78gIdvk1dTVYtT1y8SBWtPYuTJ/6w= google.golang.org/genproto v0.0.0-20230110181048-76db0878b65f/go.mod h1:RGgjbofJ8xD9Sq1VVhDM1Vok1vRONV+rg+CjzG4SZKM= @@ -62,6 +66,7 @@ google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp0 google.golang.org/protobuf v1.26.0/go.mod h1:9q0QmTI4eRPtz6boOQmLYwt+qCgq0jsYwAQnmE0givc= google.golang.org/protobuf v1.30.0 h1:kPPoIgf3TsEvrm0PFe15JQ+570QVxYzEvvHqChK+cng= google.golang.org/protobuf v1.30.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I= +google.golang.org/protobuf v1.31.0/go.mod h1:HV8QOd/L58Z+nl8r43ehVNZIU/HEI6OcFqwMG9pJV4I= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go index c073d34a7..28c88991d 100644 --- a/interceptors/logging/interceptors.go +++ b/interceptors/logging/interceptors.go @@ -143,7 +143,7 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc fields := Fields{} if opts.grpcLogFields != nil { - fields = fields.WithUnique(customCommonFields(kind, c, opts.grpcLogFields())) + fields = fields.WithUnique(customCommonFields(kind, c, opts.grpcLogFields)) } else { // Field dups from context override the common fields. fields = newCommonFields(kind, c) diff --git a/interceptors/logging/interceptors_test.go b/interceptors/logging/interceptors_test.go index 94ecd21ff..48b7eae85 100644 --- a/interceptors/logging/interceptors_test.go +++ b/interceptors/logging/interceptors_test.go @@ -630,12 +630,6 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me } } -func addGrpcLogFields() []string { - return []string{ - logging.MethodFieldKey, logging.ServiceFieldKey, "should-not-be-added", - } -} - type loggingCustomGrpcLogFieldsSuite struct { *baseLoggingSuite } @@ -654,12 +648,12 @@ func TestCustomGrpcLogFieldsSuite(t *testing.T) { }, } s.InterceptorTestSuite.ClientOpts = []grpc.DialOption{ - grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), - grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), + grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), } s.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ - grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), - grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithGrpcLogFields(addGrpcLogFields))), + grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), + grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), } suite.Run(t, s) } diff --git a/interceptors/logging/options.go b/interceptors/logging/options.go index 9bcd72399..c1ba1d0d6 100644 --- a/interceptors/logging/options.go +++ b/interceptors/logging/options.go @@ -61,7 +61,7 @@ type options struct { durationFieldFunc DurationToFields timestampFormat string fieldsFromCtxCallMetaFn fieldsFromCtxCallMetaFn - grpcLogFields AddGrpcLogFields + grpcLogFields []string } type Option func(*options) @@ -207,20 +207,9 @@ func WithTimestampFormat(format string) Option { } } -// AddGrpcLogFields customizes the function for adding gRPC fields to the log entry from the below list. -// -// -SystemTag[0], -// -ComponentFieldKey, -// -ServiceFieldKey, -// -MethodFieldKey, -// -MethodTypeFieldKey, -// -// If not provided default fields will be used. -type AddGrpcLogFields func() []string - // WithAddGrpcLogFields customizes the function for adding gRPC fields to the log entry. -func WithGrpcLogFields(f AddGrpcLogFields) Option { +func WithGrpcLogFields(enableGrpcLogFields ...string) Option { return func(o *options) { - o.grpcLogFields = f + o.grpcLogFields = enableGrpcLogFields } } From fae477590ed1b3c42fb86220d999801f6f416cb2 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 12 Sep 2023 13:25:44 +0200 Subject: [PATCH 07/12] change to disable logging fields Signed-off-by: Coleen Iona Quadros --- interceptors/logging/interceptors.go | 4 ++-- interceptors/logging/interceptors_test.go | 8 ++++---- interceptors/logging/logging.go | 13 +++++++++---- interceptors/logging/options.go | 14 +++++++------- 4 files changed, 22 insertions(+), 17 deletions(-) diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go index 28c88991d..435467220 100644 --- a/interceptors/logging/interceptors.go +++ b/interceptors/logging/interceptors.go @@ -142,8 +142,8 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc } fields := Fields{} - if opts.grpcLogFields != nil { - fields = fields.WithUnique(customCommonFields(kind, c, opts.grpcLogFields)) + if opts.disableGrpcLogFields != nil { + fields = disableCommonLoggingFields(kind, c, opts.disableGrpcLogFields) } else { // Field dups from context override the common fields. fields = newCommonFields(kind, c) diff --git a/interceptors/logging/interceptors_test.go b/interceptors/logging/interceptors_test.go index 48b7eae85..85eb8a6ac 100644 --- a/interceptors/logging/interceptors_test.go +++ b/interceptors/logging/interceptors_test.go @@ -648,12 +648,12 @@ func TestCustomGrpcLogFieldsSuite(t *testing.T) { }, } s.InterceptorTestSuite.ClientOpts = []grpc.DialOption{ - grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), - grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), + grpc.WithUnaryInterceptor(logging.UnaryClientInterceptor(s.logger, logging.WithDisableLoggingFields(logging.ComponentFieldKey, logging.MethodTypeFieldKey, logging.SystemTag[0], "custom-field-should-be-ignored"))), + grpc.WithStreamInterceptor(logging.StreamClientInterceptor(s.logger, logging.WithDisableLoggingFields(logging.ComponentFieldKey, logging.MethodTypeFieldKey, logging.SystemTag[0], "custom-field-should-be-ignored"))), } s.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{ - grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), - grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithGrpcLogFields(logging.MethodFieldKey, logging.ServiceFieldKey, "custom-field-should-not-be-added"))), + grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithDisableLoggingFields(logging.ComponentFieldKey, logging.MethodTypeFieldKey, logging.SystemTag[0], "custom-field-should-be-ignored"))), + grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithDisableLoggingFields(logging.ComponentFieldKey, logging.MethodTypeFieldKey, logging.SystemTag[0], "custom-field-should-be-ignore"))), } suite.Run(t, s) } diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index 5f0ce05f1..ebc6e532a 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -38,7 +38,8 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { } } -func customCommonFields(kind string, c interceptors.CallMeta, customFields []string) Fields { +// disableCommonLoggingFields returns copy of common fields with disabled fields removed. +func disableCommonLoggingFields(kind string, c interceptors.CallMeta, disableFields []string) Fields { commonFields := newCommonFields(kind, c) existing := map[any]any{} @@ -48,12 +49,16 @@ func customCommonFields(kind string, c interceptors.CallMeta, customFields []str existing[k] = v } - newFields := Fields{} - for _, key := range customFields { + for _, key := range disableFields { if _, ok := existing[key]; ok { - newFields = append(newFields, key, existing[key]) + delete(existing, key) } } + + newFields := make(Fields, 0, len(existing)) + for k, v := range existing { + newFields = append(newFields, k, v) + } return newFields } diff --git a/interceptors/logging/options.go b/interceptors/logging/options.go index c1ba1d0d6..5308d8b3f 100644 --- a/interceptors/logging/options.go +++ b/interceptors/logging/options.go @@ -48,9 +48,9 @@ var ( codeFunc: DefaultErrorToCode, durationFieldFunc: DefaultDurationToFields, // levelFunc depends if it's client or server. - levelFunc: nil, - timestampFormat: time.RFC3339, - grpcLogFields: nil, + levelFunc: nil, + timestampFormat: time.RFC3339, + disableGrpcLogFields: nil, } ) @@ -61,7 +61,7 @@ type options struct { durationFieldFunc DurationToFields timestampFormat string fieldsFromCtxCallMetaFn fieldsFromCtxCallMetaFn - grpcLogFields []string + disableGrpcLogFields []string } type Option func(*options) @@ -207,9 +207,9 @@ func WithTimestampFormat(format string) Option { } } -// WithAddGrpcLogFields customizes the function for adding gRPC fields to the log entry. -func WithGrpcLogFields(enableGrpcLogFields ...string) Option { +// WithDisableLoggingFields disables logging of gRPC fields provided. +func WithDisableLoggingFields(disableGrpcLogFields ...string) Option { return func(o *options) { - o.grpcLogFields = enableGrpcLogFields + o.disableGrpcLogFields = disableGrpcLogFields } } From bae1847f9e3f4d7ca930ce7e11e95f374512b982 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Fri, 15 Sep 2023 09:59:47 +0200 Subject: [PATCH 08/12] refactor and add comment Signed-off-by: Coleen Iona Quadros --- interceptors/logging/interceptors.go | 6 ++---- interceptors/logging/logging.go | 13 +++++++++---- 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go index 435467220..125028c78 100644 --- a/interceptors/logging/interceptors.go +++ b/interceptors/logging/interceptors.go @@ -141,12 +141,10 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc kind = KindClientFieldValue } - fields := Fields{} + // Field dups from context override the common fields. + fields := newCommonFields(kind, c) if opts.disableGrpcLogFields != nil { fields = disableCommonLoggingFields(kind, c, opts.disableGrpcLogFields) - } else { - // Field dups from context override the common fields. - fields = newCommonFields(kind, c) } fields = fields.WithUnique(ExtractFields(ctx)) diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index ebc6e532a..2ec95ab1e 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -38,7 +38,14 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { } } -// disableCommonLoggingFields returns copy of common fields with disabled fields removed. +// disableCommonLoggingFields returns copy of fields with disabled fields removed from the following +// default list. +// +// -SystemTag[0], +// -ComponentFieldKey, +// -ServiceFieldKey, +// -MethodFieldKey, +// -MethodTypeFieldKey, func disableCommonLoggingFields(kind string, c interceptors.CallMeta, disableFields []string) Fields { commonFields := newCommonFields(kind, c) @@ -50,9 +57,7 @@ func disableCommonLoggingFields(kind string, c interceptors.CallMeta, disableFie } for _, key := range disableFields { - if _, ok := existing[key]; ok { - delete(existing, key) - } + delete(existing, key) } newFields := make(Fields, 0, len(existing)) From 7688057ce70fca9ba96052c2d02580899b794bbe Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Fri, 15 Sep 2023 10:04:16 +0200 Subject: [PATCH 09/12] comment Signed-off-by: Coleen Iona Quadros --- interceptors/logging/logging.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index 2ec95ab1e..ee0b525b8 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -38,7 +38,7 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { } } -// disableCommonLoggingFields returns copy of fields with disabled fields removed from the following +// disableCommonLoggingFields returns copy of newCommonFields with disabled fields removed from the following // default list. // // -SystemTag[0], From b0d9c3cc4fe4e4cf1b45c05c1e937cea7fc005c8 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Mon, 18 Sep 2023 10:42:21 +0200 Subject: [PATCH 10/12] refactor deleting Signed-off-by: Coleen Iona Quadros --- interceptors/logging/logging.go | 29 ++++++++++++++--------------- 1 file changed, 14 insertions(+), 15 deletions(-) diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index ee0b525b8..eb922036a 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -48,23 +48,10 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { // -MethodTypeFieldKey, func disableCommonLoggingFields(kind string, c interceptors.CallMeta, disableFields []string) Fields { commonFields := newCommonFields(kind, c) - - existing := map[any]any{} - i := commonFields.Iterator() - for i.Next() { - k, v := i.At() - existing[k] = v - } - for _, key := range disableFields { - delete(existing, key) + commonFields.Delete(key) } - - newFields := make(Fields, 0, len(existing)) - for k, v := range existing { - newFields = append(newFields, k, v) - } - return newFields + return commonFields } // Fields loosely represents key value pairs that adds context to log lines. The key has to be type of string, whereas @@ -105,6 +92,18 @@ func (i *iter) At() (k string, v any) { return i.f[i.i].(string), i.f[i.i+1] } +func (f *Fields) Delete(key string) { + i := f.Iterator() + for i.Next() { + k, _ := i.At() + if k != key { + continue + } + *f = append((*f)[:i.i], (*f)[i.i+2:]...) + return + } +} + // WithUnique returns copy of fields which is the union of all unique keys. // Any duplicates in the added or current fields will be deduplicated where first occurrence takes precedence. func (f Fields) WithUnique(add Fields) Fields { From ce3ef08768a33ab588a48f9e4b391f83782bda02 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 19 Sep 2023 10:09:51 +0200 Subject: [PATCH 11/12] Update interceptors/logging/logging.go Co-authored-by: Johan Brandhorst-Satzkorn --- interceptors/logging/logging.go | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/interceptors/logging/logging.go b/interceptors/logging/logging.go index eb922036a..510344fd7 100644 --- a/interceptors/logging/logging.go +++ b/interceptors/logging/logging.go @@ -39,13 +39,12 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields { } // disableCommonLoggingFields returns copy of newCommonFields with disabled fields removed from the following -// default list. -// -// -SystemTag[0], -// -ComponentFieldKey, -// -ServiceFieldKey, -// -MethodFieldKey, -// -MethodTypeFieldKey, +// default list. The following are the default logging fields: +// - SystemTag[0] +// - ComponentFieldKey +// - ServiceFieldKey +// - MethodFieldKey +// - MethodTypeFieldKey func disableCommonLoggingFields(kind string, c interceptors.CallMeta, disableFields []string) Fields { commonFields := newCommonFields(kind, c) for _, key := range disableFields { From 4694257e4471ef59fc25dbbceae8691d3c7aa480 Mon Sep 17 00:00:00 2001 From: Coleen Iona Quadros Date: Tue, 19 Sep 2023 10:36:01 +0200 Subject: [PATCH 12/12] add test case for Delete(k string) --- interceptors/logging/logging_test.go | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/interceptors/logging/logging_test.go b/interceptors/logging/logging_test.go index 2a6cfa45c..150186f1f 100644 --- a/interceptors/logging/logging_test.go +++ b/interceptors/logging/logging_test.go @@ -39,3 +39,13 @@ func TestFieldsInjectExtractFromContext(t *testing.T) { f = ExtractFields(c3) require.Equal(t, Fields{"a", "changed", "b", "2"}, f) } + +func TestFieldsDelete(t *testing.T) { + f := Fields{"a", "1", "b", "2"} + f.Delete("a") + require.Equal(t, Fields{"b", "2"}, f) + f.Delete("b") + require.Equal(t, Fields{}, f) + f.Delete("c") + require.Equal(t, Fields{}, f) +}