refactor(http1): Quite trace in opentelemetry contexts

[taqtiqa-mark]

Setting up tracing+opentelemetry+jaeger, with only a root span, produces
no trace data except for output produced by these two trace_span! usages.
The test stack was an application using Tokio+Hyper so there either should
have been a lot or no trace output.

[taqtiqa-mark]

I should note I've proposed this change because it appears to be the only place in hyper where the *_span! flavor of these macros is used.

However, it would, IMO, be preferable to use the *_span! macros. There very likely are side effects I'm ignorant of hence this PR lands first.

The reason to use *_span! is to provide a seamless experience when migrating from tracing via std/files to tracing via opentelemetry+jaeger etc.
Right now, by using the "tracing" defaults, you can experience going from receiveing full trace data from Hyper in your stdout/console to getting nothing via opentelemetry+jaeger.

Unless there is a trick I'm missing in setting up tracing+opentelemetry+jaeger ?

[seanmonstar]

I'm not familiar with how tracing works with Jaeger, but the point of these spans is to allow people to view the timing of parsing and encoding headers. The change proposed here removes that.

[taqtiqa-mark]

@seanmonstar I found this comment from Eliza Wiesman interesting on discord

if a span is below the max level, instrument just won't generate any of the code for recording the span
the point i'm making is that you can afford to be fairly generous with #[instrument]
If a lot of them are debug or trace, and you enable info by default, even without using the max-level features, the overhead should be minimal-to-nonexistent i guess a rule of thumb is just, "if some event is logged, would i want to know that it was in this function when it was logged?"

Perhaps a better avenue to explore is use of #[instrument]?

[taqtiqa-mark]

two other examples from eliza on discord regarding spans across await points

let span = debug_span!("request", ?request).entered();
debug!("sending request");
client.send_request(request)
    .instrument(span.exit())
    .await; 

And

you could also write
let span = debug_span!("request", ?request).;
debug!(parent: &span, "sending request");
client.send_request(request)
    .instrument(span)
    .await; 

Apologies for formatting sent from my phone sans glasses :)

[taqtiqa-mark]

Also possibly of interest going forward
tokio-rs/tracing#1668

[taqtiqa-mark]

I'm not familiar with how tracing works with Jaeger,

I wasn't either until yesterday ;)
It is more a question of how the tracing crate works with -> tracing-subscriber -> tracing-opentelemetry -> opentelemetry -> opentelemetry-jaeger crates.

but the point of these spans is to allow people to view the timing of parsing and encoding headers

Yes that is true, but also in a distributed tracing context (OT+tool) spans are the only output visible for Hyper, and currently we see only these two.

The change proposed here removes that.

Yes, but only because I assumed the absence of *_span use elsewhere was deliberate (performance reasons?), and this seemed likely an oversight.

To be clear: My preference is to switch from events everywhere (info/warn/debug/trace) to using spans.

You may need a tracing crate guru to give you advice on best practices around how to set up Hyper to support distributed and localhost debugging scenarios?

However, my understanding is that you can only setup a root span once you have the initialized some subscriber, hence it isn't possible for Hyper to be released with a root span in place where by all info/warn/debug/trace output fall under that span.

Instead, it seems to me, the root span (hence subscriber choice) are the scope of an application and the libraries that want to be async tracing friendly use *_span variants of info/warn/debug/trace. However, I don't recall seeing that statement made so distinctly, so I'm cautious - my understanding could be wrong.

My understanding is that if Hyper used the *_span variants wherever info/warn/debug/trace are used then the 'volume' of output that greets me when I have:

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::TRACE)
        .try_init()
        .expect("Global default subscriber");
    trace!("my_app_start");
...

Will be the same 'volume' of output that greets me when I have:

async fn main() {
    // Build a Jaeger batch span processor
    // Setup Tracer Provider
    // Get new Tracer from TracerProvider
    // Create a layer ( `layer`) with the configured Tracer
     tracing_subscriber::registry()
                        .with(layer)
                        .try_init()
                        .expect("Global default subscriber.");
     let root = trace_span!("my_app_start").entered();
...

Right now, in the first case I see lots of data. In the second case I see only output from the two spans the subject of this PR, nothing else.

Not sure if that helps or makes sense?

[taqtiqa-mark]

@seanmonstar to offer some positive feedback - Hyper's current debugging story isn't exactly terrible,

Yes that is true, but also in a distributed tracing context (OT+tool) spans are the only output visible for Hyper, and currently we see only these two.

In order to get visibility into Hyper events we have to #[instrument] the application code that in turn calls those Hyper functions.

Right now this is what a adding #[instrument] to my functions looks like in Jaeger:

Obviously, make_stream is doing alot.
If we expand that we do see the Hyper generated events (128 of them). I do believe Eliza's recommendation regarding #[instrument]ing functions will be a quick win. I also think a clear delineation can be set out for PR's. The public functions are #[instrument]ed at the debug level, and all other functions are #[instrument]ed at trace. This way when you compile a release you should incur no overhead - if I understand correctly?

[taqtiqa-mark]

Adding evidence the current spans are not behaving as one might expect. Currently they sit un-tethered to any parent span. In practice, that looks like below, they should be included within the 52 span parent, run_stream:

[taqtiqa-mark]

Closing. This issue is discussed/tracked in #2577. Further, the existing PR #2261 is more advanced, and has Eliza Weisman's input who appears to be authoritative on Tracing.