Add tracing support

[mihai-dinculescu]

This is a stab at #713.

Considerations:

• following the tracing guidelines we should add a dependency only on tracing,
• because we want to have this behind a feature toggle, I've figured that it might be worth to create a couple of macros to facilitate the use of tracing, so that we don't have to repeat #[cfg(feature = "tracing")]
• I've added a section to the docs on how juniper can be instrumented along with a web framework that will either use tracing or log
• instrumentation points should eventually be added, but that will require the parameters of the functions that are instrumented to implement Debug

[LegNeato]

This is awesome, thanks! Is there any way to unit test the traces? This is simple but in the future we want to add spans and the like.

[mihai-dinculescu]

This is awesome, thanks! Is there any way to unit test the traces? This is simple but in the future we want to add spans and the like.

Unit test the proc macros or the actual traces?

[LegNeato]

This is awesome, thanks! Is there any way to unit test the traces? This is simple but in the future we want to add spans and the like.

Unit test the proc macros or the actual traces?

The actual traces...if people are relying on tracing support I want to make sure we don't break it in the future.

[LegNeato]

Would be sweet to integrate https://docs.rs/tracing-futures/0.2.4/tracing_futures/. Actually, looks like it may not be needed soon:

https://github.com/tokio-rs/tracing/pull/808

[LegNeato]

Ah, it looks like the test harness will be usable soon:

https://github.com/tokio-rs/tracing/pull/793

[LegNeato]

Note this can't land yet as it is pointing to a random git repo. Once the PR lands and a release is cut this can land.

[mihai-dinculescu]

Great stuff, thanks for the help with the PR!

I don't think that the span can be created with a declarative macro. Because the macro has to return a block, the span guard goes out of scope immediately, thus ending the span.

I'll look into creating a proc macro instead.

I'll also look into writing unit tests.

[LegNeato]

If you'll see, the sync span macro doesn't create a block so it doesn't get dropped immediately. For the async case, it gets attached to a future and works fine.

There is already a proc macro in tracing but it requires all args to be Debug.

[mihai-dinculescu]

If you'll see, the sync span macro doesn't create a block so it doesn't get dropped immediately. For the async Alan, it gets attached to a future and works fine.

There is already a proc macro in tracing but it requires all args to be Debug.

If in the tracing example the queries are made to fail, the following output is given:

Jul 29 18:37:29.810 TRACE rule_validation: juniper: new
Jul 29 18:37:29.811 TRACE rule_validation: juniper: enter
Jul 29 18:37:29.812 TRACE rule_validation: juniper: exit
Jul 29 18:37:29.812 TRACE rule_validation: juniper: close time.busy=278µs time.idle=1.26ms
Jul 29 18:37:29.813 TRACE juniper: GraphQLError: ValidationError([RuleError { locations: [SourcePosition { index: 2, line: 0, col: 2 }], message: "Unknown field \"users1\" on type \"Query\"" }])

Expected:

Jul 29 18:40:29.765 TRACE rule_validation: juniper: new
Jul 29 18:40:29.766 TRACE rule_validation: juniper: enter
Jul 29 18:40:29.767 TRACE rule_validation: juniper: GraphQLError: ValidationError([RuleError { locations: [SourcePosition { index: 2, line: 0, col: 2 }], message: "Unknown field \"users1\" on type \"Query\"" }])
Jul 29 18:40:29.767 TRACE rule_validation: juniper: exit
Jul 29 18:40:29.768 TRACE rule_validation: juniper: close time.busy=1.03ms time.idle=1.36ms

[LegNeato]

Ah, my mistake! We can totally do a proc macro.

[LegNeato]

Ok, it should be all working now...there were some extra scope blocks causing the span to get dropped previously.

[LegNeato]

FWIW I can't quite yet figure out how to attach structured data to traces...it would be nice to attach the document to the execution span.

[LegNeato]

Still waiting on https://github.com/tokio-rs/tracing/pull/808 to land this.

[LegNeato]

Ugh, I think I screwed git up here.

[fourbytes]

Just curious what the state of landing this PR is? This would be great to have. Looks like tokio-rs/tracing#808 was merged in September.

[mihai-dinculescu]

Just curious what the state of landing this PR is? This would be great to have. Looks like tokio-rs/tracing#808 was merged in September.

Still waiting for https://github.com/tokio-rs/tracing/pull/793 for the tests, but I'm not sure if that should be a blocker considering that that PR has been open for a long time and it doesn't look like it's gonna be completed anytime soon.

@LegNeato are you aware of something else that's outstanding? Anything I can help with?

[fourbytes]

I'd also be happy to help out on this PR if there's anything I can help with.