From 3ade00c067599e45664a46dabe922c8d32b32ddd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?V=C3=ADctor=20Rold=C3=A1n=20Betancort?= Date: Tue, 31 Oct 2023 17:11:45 +0000 Subject: [PATCH] adds custom durationFieldFunc to request/response log entries (#670) 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. --- interceptors/logging/interceptors.go | 4 ++++ interceptors/logging/interceptors_test.go | 5 +++++ 2 files changed, 9 insertions(+) diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go index 125028c78..45a546b70 100644 --- a/interceptors/logging/interceptors.go +++ b/interceptors/logging/interceptors.go @@ -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) @@ -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...) } } @@ -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) @@ -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...) } } diff --git a/interceptors/logging/interceptors_test.go b/interceptors/logging/interceptors_test.go index 85eb8a6ac..c137ef157 100644 --- a/interceptors/logging/interceptors_test.go +++ b/interceptors/logging/interceptors_test.go @@ -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()) } @@ -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()) } @@ -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"}`) @@ -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 @@ -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"}`)