Logging/Tracing Support

[theduke]

This issue aims to discuss the design of logging and tracing support in Juniper.

Requirements:

• Minimal performance impact (potentially completely disabled with a feature)
• Backend-independet, so users can utilize log/tracing data the way they want to
• offer fine-grained (request + resolver based) tracing information
• have a good out-of-the-box experience (ideas? slow resolver warnings, ...)

Crates to consider:

• tracing
• tracing_log

[theduke]

@mwilliammyers happy to hear your thoughts.

I didn't know about tracing_log before, so I'll have to investigate. The reason I'm leaning towards tracing is that it is designed for metrics as much as it is for logging, is fast, has a subscriber pattern that can be adapted at runtime, and supports structured data. ( I know log is also gaining structured data support, but it is moving along veeery slowly, and we'll need a solution fairly soon )

[mwilliammyers]

Ahh, having structured logging makes sense. I completely agree with all of your feature requirements.

I am totally fine with creating a PR using something other than log so we can get something out of the door.

I would hope though that we would be open to the possibility of refactoring all of our logging to log when/if https://github.com/rust-lang-nursery/log/issues/328 lands. (It probably wouldn't be very hard and I would volunteer to do it).

[archseer]

I'm coming from the elixir ecosystem that had a recent push towards adopting a single telemetry facade across the ecosystem. It's already been paying off because I can instrument or log data from any part of our stack (DB driver, GraphQL, HTTP client, etc) through the same interface, without having to fork the libraries.

For me, the push towards adopting tracing across the ecosystem isn't just about structured logging, but about emitting spans that can then be processed for tracing/metrics, doing all sorts of things like timing requests or integrating with OpenTracing/OpenTelemetry.

See also carllerche's comment

Q: How does this differ from slog/structured logging in general?

There's currently (slow) momentum behind adding structured logging to log itself, and structured logging maps super well onto futures/tasks, even as they move between execution threads.

A: First, it is tracing, not just logging. So, instead of just outputting an event (the structured log message), you specify a start and a stop (a span). By doing this, you can notice the hierarchical structure of events. If a span is fully contained by another, then it is a child.

Beyond that, tracing is designed to make it highly efficient for subscribers to watch for individual fields of an event. A subscriber is able to match a received field value without doing a string comparison. The intent is that subscribers will be used to aggregate metrics and do more with the data than just report it.

tracing has quite a number of other cool features, but I don't know enough about slog to compare.

tracing and log aren't mutually exclusive but could/should be used in tandem: the library itself should emit spans with various information, then the user can subscribe and log out whatever data they want. (So tracing_log is also just an adapter that helps us achieve that)

To provide a good out-of-the-box experience we can add logging similar to #370 by tapping into those spans via our own subscriber (or better yet, use the tracing_log::TraceLogger which is a subscriber that uses log to output the spans) under a default feature called log. That way the user gets logging by default, but they can always turn the feature off and build their own custom logging via the traces.