Grpc-go: Use structured logging

[aybabtme]

This package emits a lot of logs when it encounters errors. It would be nice if the logging could be done in a structured manner, so that machine be able to parse them and make sense of the various piece of information found in them.

For instance, at DigitalOcean we log everything in JSON and send all the logs to a centralized store, where we can perform query and analyse our logs in bulk. We structure our logs in a manner such that this log entry:

log.WithFields(log.Fields{
   "err":       err,
   "peer.addr": peerAddr,
   "timeout_s": timeout.Seconds(),
}).Error("timeout connecting to remote peer")

Prints something like:

{"time":"2015-08-12T23:31:10-04:00","level":"fatal","err":"grpc: timed out trying to connect","peer.addr":"10.0.0.1:6767", "timeout_s":29.1,"msg":"timeout connecting to remote peer"}

We can then run queries about the most frequent errors involving peer.addr = "some address".

So essentially I'm proposing modifying grpc-go/grpclog to match another interface, and then modifying all log sites to leverage structured logging patterns. There's a standard structured logger coming up in the community:

• https://godoc.org/github.com/go-kit/kit/log

If you're interested, I could work on a patch.

[aybabtme]

I have this insane grpclog implementation for now :P https://github.com/aybabtme/grpclogrus

[iamqizhao]

The idea sounds fine to me. Thanks for contribution.

[aybabtme]

@peter-edge I guess that could be 1 implementation among many, my idea here is to use a structured logging interface instead of printf-logging. The backing implementation isn't really something important to me =P.

[aybabtme]

I prepared this deck about why structured logging matters, could help motivate why we'd like to see GRPC use it somehow:

https://docs.google.com/presentation/d/1SnjZpcfJq9r6OpgsjsX9ExCFTQgpXsSjD--Y3PPDiAQ/edit?usp=sharing

It's a bit annoying that a library be logging on it's own, with its own means. At least logging to key-values would leave the choice to users to printf the stuff together as needed (and a default grpclog), or keep the key-value mappings and do nice parseable logs.

[hsaliak]

I do not believe we have plans to do structured logging at the moment. @menghanl @dfawley could you take a look and see what to do with this proposed enhancement.

[aybabtme]

hi @hsaliak, @menghanl and @dfawley ! I haven't contributed to the discussion for a while, but I think the need is still very present. If we can agree on an interface, I'm happy to do the work myself.

[hsaliak]

Sounds good, this may make a good gRFC proposal. I'll defer to @dfawley though

[dfawley]

We're open to this idea, but we would like to see a design proposal first (either as a grfc or a write-up in this bug), and would need a contribution to implement it as well.