Skip to content

Commit

Permalink
adds custom durationFieldFunc to request/response log entries (#670)
Browse files Browse the repository at this point in the history
the request and response log messages include a duration string,
but does not make use of the `durationFieldFunc` like other
parts of the request lifecycle.

The `durationFieldFunc` function is useful when conducting log analysis
with log aggregator tools out there, because it normalizes the value
to a number that can be filtered by or compared to. For example,
a GCP Log Explorer does not support converting log field types like
a duration to an integer, so you cannot run queries like "give me
all logs that took more than 50ms" because it would be interpreted
as a string comparison. This makes very tedious to audit application logs
that log API calls using this gRPC middleware.

The perhaps controversial part of this change is that request/response
logs have a different naming convention for the duration. I personally
don't find use for a different field name - grpc.time and grpc.time_ms
would seem expressive enough to support the 4 logged entries, but maybe
I'm missing something here. I would suggest to rename those fields as well,
but I understand that may be a "breaking change", if we consider the log fields
a contract.
  • Loading branch information
vroldanbet authored Oct 31, 2023
1 parent 9a90441 commit 3ade00c
Show file tree
Hide file tree
Showing 2 changed files with 9 additions and 0 deletions.
4 changes: 4 additions & 0 deletions interceptors/logging/interceptors.go
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,7 @@ func (c *reporter) PostMsgSend(payload any, err error, duration time.Duration) {
}

fields = fields.AppendUnique(Fields{"grpc.send.duration", duration.String(), "grpc.request.content", p})
fields = fields.AppendUnique(c.opts.durationFieldFunc(duration))
c.logger.Log(c.ctx, logLvl, "request sent", fields...)
} else {
p, ok := payload.(proto.Message)
Expand All @@ -85,6 +86,7 @@ func (c *reporter) PostMsgSend(payload any, err error, duration time.Duration) {
}

fields = fields.AppendUnique(Fields{"grpc.send.duration", duration.String(), "grpc.response.content", p})
fields = fields.AppendUnique(c.opts.durationFieldFunc(duration))
c.logger.Log(c.ctx, logLvl, "response sent", fields...)
}
}
Expand Down Expand Up @@ -116,6 +118,7 @@ func (c *reporter) PostMsgReceive(payload any, err error, duration time.Duration
}

fields = fields.AppendUnique(Fields{"grpc.recv.duration", duration.String(), "grpc.request.content", p})
fields = fields.AppendUnique(c.opts.durationFieldFunc(duration))
c.logger.Log(c.ctx, logLvl, "request received", fields...)
} else {
p, ok := payload.(proto.Message)
Expand All @@ -130,6 +133,7 @@ func (c *reporter) PostMsgReceive(payload any, err error, duration time.Duration
}

fields = fields.AppendUnique(Fields{"grpc.recv.duration", duration.String(), "grpc.response.content", p})
fields = fields.AppendUnique(c.opts.durationFieldFunc(duration))
c.logger.Log(c.ctx, logLvl, "response received", fields...)
}
}
Expand Down
5 changes: 5 additions & 0 deletions interceptors/logging/interceptors_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -537,6 +537,7 @@ func (s *loggingPayloadSuite) TestPingError_LogsOnlyRequestsOnError() {

clientRequestFields.AssertFieldNotEmpty(s.T(), "grpc.start_time").
AssertFieldNotEmpty(s.T(), "grpc.send.duration").
AssertFieldNotEmpty(s.T(), "grpc.time_ms").
AssertField(s.T(), "grpc.request.content", `{"value":"something","errorCodeReturned":4}`).
AssertFieldNotEmpty(s.T(), "grpc.request.deadline").AssertNoMoreTags(s.T())
}
Expand Down Expand Up @@ -580,6 +581,7 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me
clientRequestFields := assertStandardFields(s.T(), logging.KindClientFieldValue, clientRequestLogLine.fields, method, typ)
clientRequestFields.AssertFieldNotEmpty(s.T(), "grpc.start_time").
AssertFieldNotEmpty(s.T(), "grpc.send.duration").
AssertFieldNotEmpty(s.T(), "grpc.time_ms").
AssertField(s.T(), "grpc.request.content", `{"value":"something","sleepTimeMs":9999}`).
AssertFieldNotEmpty(s.T(), "grpc.request.deadline").AssertNoMoreTags(s.T())
}
Expand All @@ -591,6 +593,7 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me
clientResponseFields := assertStandardFields(s.T(), logging.KindClientFieldValue, clientResponseLogLine.fields, method, typ)
clientResponseFields = clientResponseFields.AssertFieldNotEmpty(s.T(), "grpc.start_time").
AssertFieldNotEmpty(s.T(), "grpc.recv.duration").
AssertFieldNotEmpty(s.T(), "grpc.time_ms").
AssertFieldNotEmpty(s.T(), "grpc.request.deadline")
if i-curr == 0 {
clientResponseFields = clientResponseFields.AssertField(s.T(), "grpc.response.content", `{"value":"something"}`)
Expand All @@ -609,6 +612,7 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me
AssertFieldNotEmpty(s.T(), "grpc.start_time").
AssertFieldNotEmpty(s.T(), "grpc.recv.duration").
AssertFieldNotEmpty(s.T(), "grpc.request.deadline").
AssertFieldNotEmpty(s.T(), "grpc.time_ms").
AssertField(s.T(), "grpc.request.content", `{"value":"something","sleepTimeMs":9999}`).AssertNoMoreTags(s.T())
}
curr += repetitions
Expand All @@ -620,6 +624,7 @@ func (s *loggingPayloadSuite) assertPayloadLogLinesForMessage(lines LogLines, me
serverResponseFields = serverResponseFields.AssertFieldNotEmpty(s.T(), "peer.address").
AssertFieldNotEmpty(s.T(), "grpc.start_time").
AssertFieldNotEmpty(s.T(), "grpc.send.duration").
AssertFieldNotEmpty(s.T(), "grpc.time_ms").
AssertFieldNotEmpty(s.T(), "grpc.request.deadline")
if i-curr == 0 {
serverResponseFields = serverResponseFields.AssertField(s.T(), "grpc.response.content", `{"value":"something"}`)
Expand Down

0 comments on commit 3ade00c

Please sign in to comment.