Repository: grpc-ecosystem/go-grpc-middleware
Pull request #670 (2023-10-31 10:35:21)

adds fields from durationFieldFunc to request/response log entries
👋🏻 Hai good people of the `go-grpc-middleware`

## Changes

This PR adds the fields resulting from invoking `durationFieldFunc` to request and response log messages 

## Why

the request and response log messages include a duration string but do not use the `durationFieldFunc` like other parts of the request lifecycle.

The `durationFieldFunc` function is useful when conducting log analysis with log aggregator tools 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 duration to an integer](https://stackoverflow.com/a/63746056), 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 it 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 can't find a use for a different field name - `grpc.time` and `grpc.time_ms` would seem expressive enough to support the 4 logged entries, but I'm likely missing something here. I would suggest renaming those fields as well, but I understand that may be a "breaking change", if we consider the log fields a contract.

## Verification

The unit tests failed immediately and I then updated them.

johanbrandhorst: I agree that we should not rename the existing default fields as it may break users.

Patch:
diff --git a/interceptors/logging/interceptors.go b/interceptors/logging/interceptors.go
index 125028c..45a546b 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...)
 	}
 }


Test patch:
diff --git a/interceptors/logging/interceptors_test.go b/interceptors/logging/interceptors_test.go
index 85eb8a6..c137ef1 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"}`)