Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add logging option to disable fields in log entry #631

Merged
merged 12 commits into from
Sep 19, 2023
10 changes: 5 additions & 5 deletions interceptors/logging/examples/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
)
Expand All @@ -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 => ../../../
5 changes: 5 additions & 0 deletions interceptors/logging/examples/go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand All @@ -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=
Expand Down
7 changes: 6 additions & 1 deletion interceptors/logging/interceptors.go
Original file line number Diff line number Diff line change
Expand Up @@ -142,7 +142,12 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc
}

// Field dups from context override the common fields.
fields := newCommonFields(kind, c).WithUnique(ExtractFields(ctx))
fields := newCommonFields(kind, c)
if opts.disableGrpcLogFields != nil {
fields = disableCommonLoggingFields(kind, c, opts.disableGrpcLogFields)
}
fields = fields.WithUnique(ExtractFields(ctx))

if !c.IsClient {
if peer, ok := peer.FromContext(ctx); ok {
fields = append(fields, "peer.address", peer.Addr.String())
Expand Down
143 changes: 143 additions & 0 deletions interceptors/logging/interceptors_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -630,6 +630,149 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me
}
}

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.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.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)
}

// 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.LevelInfo, 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.LevelInfo, 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.LevelInfo, 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.LevelInfo, 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)
Expand Down
27 changes: 27 additions & 0 deletions interceptors/logging/logging.go
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,21 @@ func newCommonFields(kind string, c interceptors.CallMeta) Fields {
}
}

// disableCommonLoggingFields returns copy of newCommonFields with disabled fields removed from the following
// 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 {
commonFields.Delete(key)
}
return commonFields
}

// 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
Expand Down Expand Up @@ -76,6 +91,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 {
Expand Down
10 changes: 10 additions & 0 deletions interceptors/logging/logging_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
13 changes: 11 additions & 2 deletions interceptors/logging/options.go
Original file line number Diff line number Diff line change
Expand Up @@ -48,8 +48,9 @@ var (
codeFunc: DefaultErrorToCode,
durationFieldFunc: DefaultDurationToFields,
// levelFunc depends if it's client or server.
levelFunc: nil,
timestampFormat: time.RFC3339,
levelFunc: nil,
timestampFormat: time.RFC3339,
disableGrpcLogFields: nil,
}
)

Expand All @@ -60,6 +61,7 @@ type options struct {
durationFieldFunc DurationToFields
timestampFormat string
fieldsFromCtxCallMetaFn fieldsFromCtxCallMetaFn
disableGrpcLogFields []string
}

type Option func(*options)
Expand Down Expand Up @@ -204,3 +206,10 @@ func WithTimestampFormat(format string) Option {
o.timestampFormat = format
}
}

// WithDisableLoggingFields disables logging of gRPC fields provided.
coleenquadros marked this conversation as resolved.
Show resolved Hide resolved
func WithDisableLoggingFields(disableGrpcLogFields ...string) Option {
return func(o *options) {
o.disableGrpcLogFields = disableGrpcLogFields
}
}
Loading