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
11 changes: 9 additions & 2 deletions interceptors/logging/interceptors.go
Original file line number Diff line number Diff line change
Expand Up @@ -141,8 +141,15 @@
kind = KindClientFieldValue
}

// Field dups from context override the common fields.
fields := newCommonFields(kind, c).WithUnique(ExtractFields(ctx))
fields := Fields{}

Check failure on line 144 in interceptors/logging/interceptors.go

View workflow job for this annotation

GitHub Actions / Linters (Static Analysis) for Go

SA4006: this value of `fields` is never used (staticcheck)
if opts.disableGrpcLogFields != nil {
fields = disableCommonLoggingFields(kind, c, opts.disableGrpcLogFields)
} else {
// Field dups from context override the common fields.
fields = newCommonFields(kind, c)
}
coleenquadros marked this conversation as resolved.
Show resolved Hide resolved
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
24 changes: 24 additions & 0 deletions interceptors/logging/logging.go
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,30 @@
}
}

// 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{}
coleenquadros marked this conversation as resolved.
Show resolved Hide resolved
i := commonFields.Iterator()
for i.Next() {
k, v := i.At()
existing[k] = v
}

for _, key := range disableFields {
if _, ok := existing[key]; ok {

Check failure on line 53 in interceptors/logging/logging.go

View workflow job for this annotation

GitHub Actions / Linters (Static Analysis) for Go

S1033: unnecessary guard around call to delete (gosimple)
delete(existing, key)
}
coleenquadros marked this conversation as resolved.
Show resolved Hide resolved
}

newFields := make(Fields, 0, len(existing))
for k, v := range existing {
newFields = append(newFields, k, v)
}
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
Expand Down
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