Logging interceptor does not correctly log client calls sent from a server

[jalaziz]

Go version used: 1.20

What happened:

While testing the logging interceptor, I noticed duplicate logs at different levels. In trying to debug the issue, I realized that the issue was occurring because the logging interceptor does not override context keys that already exist and the server handler was calling a client method, passing through the context.

Sample logs:

2023-08-14T04:27:04.859Z	INFO	logging/interceptors.go:100	started call	{"protocol": "grpc", "grpc.component": "server", "grpc.service": "foo.v1.Foo", "grpc.method": "CreateBaz", "grpc.method_type": "unary", "peer.address": "127.0.0.1:32966", "grpc.start_time": "2023-08-14T04:27:04Z", "grpc.time_ms": "0.023"}
2023-08-14T04:27:04.860380669Z 2023-08-14T04:27:04.859Z	DEBUG	logging/interceptors.go:55	started call	{"protocol": "grpc", "grpc.component": "server", "grpc.service": "foo.v1.Foo", "grpc.method": "CreateBaz", "grpc.method_type": "unary", "peer.address": "127.0.0.1:32966", "grpc.start_time": "2023-08-14T04:27:04Z", "grpc.time_ms": "0.018"}
2023-08-14T04:27:04.891378877Z 2023-08-14T04:27:04.891Z	DEBUG	logging/interceptors.go:44	finished call	{"protocol": "grpc", "grpc.component": "server", "grpc.service": "foo.v1.Foo", "grpc.method": "CreateBaz", "grpc.method_type": "unary", "peer.address": "127.0.0.1:32966", "grpc.start_time": "2023-08-14T04:27:04Z", "grpc.code": "OK", "grpc.time_ms": "31.513"}
2023-08-14T04:27:04.891432002Z 2023-08-14T04:27:04.891Z	INFO	logging/interceptors.go:44	finished call	{"protocol": "grpc", "grpc.component": "server", "grpc.service": "foo.v1.Foo", "grpc.method": "CreateBaz", "grpc.method_type": "unary", "peer.address": "127.0.0.1:32966", "grpc.start_time": "2023-08-14T04:27:04Z", "grpc.code": "OK", "grpc.time_ms": "32.124"}

What you expected to happen:

I expect the client logs to expose client request metadata, not server metadata.

How to reproduce it (as minimally and precisely as possible):

1. Create two gRPC server (A and B) applications.
2. Implement a method handler on server A that calls a method on server B.
3. Add the logging interceptor to both the servers and the client.
4. Call the method on server A.

[jalaziz]

I'm happy to contribute a fix, but I'm not sure what the best solution is.

The simplest solution would be to override the fields in the context, but this would break the current API which allows you to manually override fields by setting them in the context before the logger is called.

Another solution could be to support multiple context markers, one for the default context and another for the user-provided context.

[johanbrandhorst]

@bwplotka refactored these for the v2 release, unfortunately I don't know what the best solution is here either.

[bwplotka]

Thanks for reporting--especially before 2.0!

This is indeed surprising and wrong. We have to establish a policy for inheriting & overriding the fields from context. Initially I thought it would be easier if those would be immutable, but for such cases it's clearly wrong idea as e.g. component is changing all the time depends where we log from. Flipped in #616

[jalaziz]

Thanks for reporting--especially before 2.0!

Just glad I caught it in our logs 🙏🏼 .

This is indeed surprising and wrong. We have to establish a policy for inheriting & overriding the fields from context. Initially I thought it would be easier if those would be immutable, but for such cases it's clearly wrong idea as e.g. component is changing all the time depends where we log from. Flipped in #616

The more I think about it, the more I agree that new should override old (that's generally what you'd expect from Context anyway). That being said, if support for overriding the fields is necessary, then I think the best option is to allow that to occur is via the WithFieldsFromContext option.