Issue 2678: Span PoC - direction/feedback

[taqtiqa-mark]

Seeking feedback on the approach:

TLDR;

podman run -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in-one:latest
cargo run --features="full tracing/max_level_trace" --example client_json_tracing_otel
firefox http://localhost:16686
# See also stdout

• Use of a feature flag layers, adding the flag to full and placing tracing logic behind that flag. See issue RFC: Debug/tracing feature flags #2698

• Use OpenTelemetry semantic conventions as the starting point.

• The initial documentation is in src/common/layers/mod.rs

• [src/proto/h1/role.rs]: Server::encode span (328-470) is the most complete and serves point of reference. We start here because these are the functions the the subject of spans in the current code base:

  • The cfg_attr is a template I propose to use elsewhere: Acceptable?
  • The use of tracing::Span::current().record(...): Acceptable?
  • The cfg!(feature = ~~"layers"~~ TBD) guard: Acceptable?
  • I suggest using the tracing-error crate, so I don't propose to do too much around the errors: Acceptable?
  • Function arguments that require a tracing Value trait are skipped. The proposed workaround until the Value trait is unsealed is to impl Debug for ... and impl Display for ... in src/common/layers/values/*.rs: Acceptable?
  • Move all debug!(..) and trace!(..) either into a span field, or if not appropriate, behind a cfg!(feature = "layers") guard, leave all other levels alone: Acceptable?

Once these four spans (Client:encode, Client:parse, Server:encode, Server:parse) are stabilized and merged:

• Propose additional functions to add spans for, per @seanmonstar 's suggestion finangle guide
• Once all spans are in place, rationalize the fields (and their updating) across/between spans
• Add tracing-error

[hawkw]

i have some concerns about the current approach here. i don't really understand why it's necessary for hyper itself to implement its own Layers for recording tracing data. as far as i can tell, these don't implement any hyper-specific behaviors, and are better off implemented outside of hyper.

if there is a compelling reason for hyper to provide hyper-specific tracing layers that implement behaviors tightly coupled with hyper, I think those probably ought to go in a separate crate, rather than within the hyper crate. since the tracing facade allows a loose coupling between instrumentation and subscribers, there shouldn't be any reason for any hyper layers to need to access hyper's internals.

also, if there is some reason these layers need to be defined within hyper itself...they almost certainly should be enabled by a separate feature flag than the tracing spans and events exposed by hyper. if i want to use tracing-subscriber::fmt to record those spans and events, i might want to enable that feature flag...but i don't need any of the hyper layers and their (often heavyweight) dependencies. there should be a separate feature flag for instrumentation in hyper.

[hawkw]

why is the feature flag to enable tracing support called layers? i would expect it to be called tracing or something...

[taqtiqa-mark]

why is the feature flag to enable tracing support called layers? i would expect it to be called tracing or something...

I believe that is where I started - again from memory - you can't have a feature name that is congruent to a crate name - but I'm not a Rust expert

[hawkw]

you can't have a feature name that is congruent to a crate name - but I'm not a Rust expert

An optional dependency is equivalent to a feature flag that only enables one dependency. I think that tracing should just be an optional dependency and the instrumentation points should all be flagged with #[cfg(feature = "tracing")]. If we do end up exposing other functionality, like the OpenTelemetry layer you've implemented, it should be under a separate feature flag.

[taqtiqa-mark]

the instrumentation points should all be flagged with #[cfg(feature = "tracing")]

What do you think of using two flags debug and trace or some such. Where the use cases are distinct, Use debug when if you are investigating the integration of your app and hyper.
Use trace when you are investigating hyper internals.
The debug spans would then be constrained to around only public functions.

Not sure if that type of distinction can work out?

If we do end up exposing other functionality, like the OpenTelemetry layer you've implemented, it should be under a separate feature flag.

Agreed, or probably better to have a separate crate

[hawkw]

why is there now a dependency on the log crate?

[taqtiqa-mark]

why is there now a dependency on the log crate?

Is required to turn off tracing in an app that uses hyper (the example).
also from memory I believe the dependency was already there but just not surfaced/explicit. May be wrong in that recollection.

[hawkw]

i don't think that the feature that enables tracing instrumentation in Hyper should enable all of these dependencies. suppose I want to log tracing spans from hyper using tracing-subscriber, in the plaintext format. in that case, i would want to enable tracing instrumentation in hyper...but i would not want hyper to suddenly depend on log, serde_json, reqwest, tracing_opentelemetry, opentelemetry, opentelemetry-jaeger, and tracing-tree.

[taqtiqa-mark]

i don't think that the feature that enables tracing instrumentation in Hyper should enable all of these dependencies. suppose I want to log tracing spans from hyper using tracing-subscriber, in the plaintext format. in that case, i would want to enable tracing instrumentation in hyper...but i would not want hyper to suddenly depend on log, serde_json, reqwest, tracing_opentelemetry, opentelemetry, opentelemetry-jaeger, and tracing-tree.

Summarizing - response to the question of introducing a feature: No objection, in fact please consider features that allow more fine grained control. Accurate summary?

[hawkw]

take it or leave it: i think it might be worth putting all the tracing examples in a examples/tracing directory, so it's clear they're all related to various tracing-related configurations?

[taqtiqa-mark]

take it or leave it: i think it might be worth putting all the tracing examples in a examples/tracing directory, so it's clear they're all related to various tracing-related configurations?

OT but I'll take it into account closer to the time a final PR is ready.

[hawkw]

this is incorrect. Span::in_scope here is not instrumenting the async block, but the closure that returns it...which, in this case, doesn't contain any tracing events, as it immediately returns the async block. So, calling in_scope here is not doing anything. instead, these events occur within root_span's scope because of the Span::entered call prior to the closure...but entered should not be used in asynchronous code. see the documentation for details on why.

instead, this should be:

Suggested change

	let root_span = tracing::span!(tracing::Level::INFO, "root_span_echo").entered();
	root_span.in_scope(|| async {
	// Log a `tracing` "event".
	info!(status = true, answer = 42, message = "first event");
	let url = "http://jsonplaceholder.typicode.com/users".parse().unwrap();
	let users = fetch_json(url).await.expect("Vector of user data");
	// print users
	println!("users: {:#?}", users);
	// print the sum of ids
	let sum = users.iter().fold(0, |acc, user| acc + user.id);
	println!("sum of ids: {}", sum);
	// ...but, it can also be exited explicitly, returning the `Span`
	// struct:
	//let _root_span = root_span.exit();
	}).await;
	use tracing::instrument::Instrument;
	let root_span = tracing::span!(tracing::Level::INFO, "root_span_echo);
	async {
	// Log a `tracing` "event".
	info!(status = true, answer = 42, message = "first event");
	let url = "http://jsonplaceholder.typicode.com/users".parse().unwrap();
	let users = fetch_json(url).await.expect("Vector of user data");
	// print users
	println!("users: {:#?}", users);
	// print the sum of ids
	let sum = users.iter().fold(0, |acc, user| acc + user.id);
	println!("sum of ids: {}", sum);
	}
	.instrument(root_span)
	.await;

[taqtiqa-mark]

Thanks for the correction. I think this makes the point that examples are required - ideally someone should be able to get tracing without having to become an expert in the tracing stack - 80/20 rule - some standard boiler plate setup should suffice for 80%+ of use cases.

[hawkw]

it's probably more efficient to avoid getting the current span multiple times ---Span::current performs a thread-local storage access. prefer:

Suggested change

	tracing::Span::current()
	.record("http.method", &format!("{:?}", msg.req_method).as_str());
	tracing::Span::current().record(
	let span = tracing::Span::current();
	span.record("http.method", &format!("{:?}", msg.req_method).as_str());
	span.record(

also, we should record the method as a Debug trait object, in order to avoid allocating a string here:

Suggested change

	tracing::Span::current()
	.record("http.method", &format!("{:?}", msg.req_method).as_str());
	tracing::Span::current().record(
	let span = tracing::Span::current();
	span.record("http.method", &msg.req_method as &dyn std::fmt::Debug));
	span.record(

[taqtiqa-mark]

also, we should record the method as a Debug trait object, in order to avoid allocating a string here:

Thanks, that is way beyond my ken at this point.

[hawkw]

Suggested change

	&format!("{:?}", msg.head.subject).as_str(),
	&msg.head.subject as &dyn std::fmt::Debug

[taqtiqa-mark]

@hawkw I've tried these suggestions with no luck:

span.as_ref()
        .unwrap()
        .record("http.method", &msg.req_method as &dyn std::fmt::Debug);

gives this error:

the size for values of type `dyn std::fmt::Debug` cannot be known at compilation time
the trait `Sized` is not implemented for `dyn std::fmt::Debug`

I tried some suggestion by David Barsky (via Discord) which gives different errors.
I've also tried umpteen variations I'd come up with in partnership with the compiler... which I won't bore you with.

Consequently, the follow up PR will use what I have here, pending a working alternative.

[taqtiqa-mark]

From memory... this is what led me to add layers, likely incorrectly. I'd come across some blogs that made me think any logic around value processing belonged in a layer.

For what it is worth: I've removed all layers, and if they are appropriate, we'd need to discuss where they live - a proc-macro-attribute crate doesn't appear to allow modules to be exported - so they don't/can't live in the proc-macro crate I've created as part of the follow-up PR.

[hawkw]

prefer structured fields:

Suggested change

	trace!("Server::encode body={:?}", msg.body);
	trace!(body = ?msg.body);

[taqtiqa-mark]

prefer structured fields:

I'm pretty much leaving existing code unchanged where it is not fully replaced by some span/event structure. If I was to propose changing this it would be to storing the byte count in one of the span fields.

[taqtiqa-mark]

On further reflection I've followed this suggestion - if the proposed approach in the PR gets rejected it won't be because of this :)

[hawkw]

again, we probably want to avoid getting the current span twice if we don't have to...

[hawkw]

probably also don't want to record dst here...

Suggested change

	skip(msg),
	skip(msg, dst),

[seanmonstar]

Thanks for the PR! I appreciate your effort to improve tracing in hyper.

I agree with several of Eliza's points:

• We shouldn't need any new dependencies.
• I'd probably lean towards not having any new example files. Maybe one if the existing ones don't do a good job of letting you use tracing, but ideally they all do.
• Any layers should be possible in a separate crate. The point of a layer is to allow someone to define what information that is emitted they want to serialize somewhere. All hyper should be doing is emitting all the useful information.

This isn't to say that the layers here aren't useful, I'm sure they are from an open telemetry perspective. Likely, building them and the examples can help you come up with what exact events and spans you actually need to serialize. I'd say keep experimenting with the examples, but in the goal of doing as I mentioned in #2678:

Determine what spans, events, and fields that absolutely need to be inside hyper (as opposed to ones that can occur outside hyper, in a custom impl Service), and propose them. I'd start with a list in a new issue. Those from finagle might be useful, but also from your examples you might find what is missing.

The point is that hyper should emit spans and events that a user couldn't figure out from outside hyper. I assume this will most often be timing related. Most of the other information can be recorded at the start of an impl Service.

[taqtiqa-mark]

i have some concerns about the current approach here. i don't really understand why it's necessary for hyper itself to implement its own Layers for recording tracing data. as far as i can tell, these don't implement any hyper-specific behaviors, and are better off implemented outside of hyper.

if there is a compelling reason for hyper to provide hyper-specific tracing layers that implement behaviors tightly coupled with hyper, I think those probably ought to go in a separate crate, rather than within the hyper crate. since the tracing facade allows a loose coupling between instrumentation and subscribers, there shouldn't be any reason for any hyper layers to need to access hyper's internals.

also, if there is some reason these layers need to be defined within hyper itself...they almost certainly should be enabled by a separate feature flag than the tracing spans and events exposed by hyper. if i want to use tracing-subscriber::fmt to record those spans and events, i might want to enable that feature flag...but i don't need any of the hyper layers and their (often heavyweight) dependencies. there should be a separate feature flag for instrumentation in hyper.

Overall I agree. I don't believe I proposed examples or layers in the questions I posed. Would appreciate your feedback on the questions raised.

[taqtiqa-mark]

i have some concerns about the current approach here. i don't really understand why it's necessary for hyper itself to implement its own Layers for recording tracing data. as far as i can tell, these don't implement any hyper-specific behaviors, and are better off implemented outside of hyper.

if there is a compelling reason for hyper to provide hyper-specific tracing layers that implement behaviors tightly coupled with hyper, I think those probably ought to go in a separate crate, rather than within the hyper crate. since the tracing facade allows a loose coupling between instrumentation and subscribers, there shouldn't be any reason for any hyper layers to need to access hyper's internals.

also, if there is some reason these layers need to be defined within hyper itself...they almost certainly should be enabled by a separate feature flag than the tracing spans and events exposed by hyper. if i want to use tracing-subscriber::fmt to record those spans and events, i might want to enable that feature flag...but i don't need any of the hyper layers and their (often heavyweight) dependencies. there should be a separate feature flag for instrumentation in hyper.

Largely agree with these points. I'm trying to check how these spans 'look' in different contexts and to decide whether any changes are required - as temporary workarounds. Still exploring/experimenting. any layers in hyper would be proposed separately.

Apologies if the questions I posed gave the impression I was wanting to bring these layers in.
That was not my intention.

[taqtiqa-mark]

Thanks for the PR! I appreciate your effort to improve tracing in hyper.

I agree with several of Eliza's points:

* We shouldn't need any new dependencies.

I understand the concern. The issue is: getting debug/trace output in a usable form should be off-the-shelf functionality. IMO, the Hyper instructions need not be more complex than this:

podman run -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in-one:latest
cargo run --features="some thing tracing/max_level_trace" --example client_json_tracing_otel
firefox http://localhost:16686

or some such.
Can that be done without any dependencies?
I agree the feature flag is not right as it stands right now. See below for a proposal.

* I'd probably lean towards not having any new example files. Maybe one if the existing ones don't do a good job of letting you use tracing, but ideally they all do.

See @hawkw 's earlier comment on the subtleties of setting up tracing for async. IMO, debug output should just work and not require you to spend more than 2 minutes on setup.

Adding spans/events, and nothing more, is just throwing the same problem onto every user to keep solving.
Perhaps we can come up with some boiler plate that will solve 80% of the problems.

To make it concrete:
In issues reporting bugs there should be a set of one/two commands that a user is asked to run and provides output that identifies the issue.

* Any layers should be possible in a separate crate. The point of a layer is to allow someone to define what information that is emitted they want to serialize somewhere. All hyper should be doing is emitting all the useful information.

Right now it isn't clear to me that some layer is/isn't required - even as a workaround - to get the full output to solve the problems.
I think it is axiomatic that any layer in hyper would have to add value not available elsewhere.

This isn't to say that the layers here aren't useful, I'm sure they are from an open telemetry perspective. Likely, building them and the examples can help you come up with what exact events and spans you actually need to serialize.

Correct. They've exposed several things that need to be addressed, but that is likely my ignorance, and may be non-issues.

I'd say keep experimenting with the examples, but in the goal of doing as I mentioned in #2678:

Determine what spans, events, and fields that absolutely need to be inside hyper (as opposed to ones that can occur outside hyper, in a custom impl Service), and propose them.

Isn't this that?

I'd start with a list in a new issue.

Ditto.

Also bear in mind:

1. We can conditionally add spans/events/logs behind some feature flag
2. Even if we add that feature flag as default we can compile out the same.

I think this means erring on the side of being liberal in extracting information - there is no runtime performance penalty and we need debug output that doesn't result in issues sitting open for >1 month (ideally)?

Those from finagle might be useful, but also from your examples you might find what is missing.

The point is that hyper should emit spans and events that a user couldn't figure out from outside hyper. I assume this will most often be timing related. Most of the other information can be recorded at the start of an impl Service.

OK, the impl Service is a new idea - can you elaborate how you see it working here. Is there prior art I can look at to get my head around what you have in mind.

I take your point about the finangle structure being proven prior-art.
It does still leave the question of what functions get spans/events/logs added, but this isn't abstract, we have something concrete guiding how we proceed - initially at least:

There are two reports of hang behavior that we are blind about. I'm not even sure if they have the same root cause.

The spans/events required, as a first step, are those that expose the cause of the problem - the finangle guide is one useful way to organize them. However,

Determine what spans, events, and fields that absolutely need to be inside hyper (

I don't want to get to the point of finding out what spans/events/logs are needed to identify the issue in my repro only to find out that the approach taken is totally unacceptable, e.g. think your impl Service but after everything is 'done' - being done in terms of solving the problems we have open issues about. Where solving could mean establishing the problem lies outside of Hyper (i.e. in want, mio etc).

[davidbarsky]

OK, the impl Service is a new idea - can you elaborate how you see it working here. Is there prior art I can look at to get my head around what you have in mind.

I apologize, I should've been more clear when I mentioned tower_http on Discord. tower_http's trace module allows you to instrument and trace a Hyper server and client by passing through an impl tower::Service. I think that's one of the reasons that there's been not-as-much pressure to instrument Hyper directly with tracing, since tower_http::trace can handle a surprising amount.

[hawkw]

@taqtiqa-mark, re:

I understand the concern. The issue is: getting debug/trace output in a usable form should be off-the-shelf functionality. IMO, the Hyper instructions need not be more complex than this:

podman run -p6831:6831/udp -p6832:6832/udp -p16686:16686 jaegertracing/all-in-one:latest
cargo run --features="some thing tracing/max_level_trace" --example client_json_tracing_otel
firefox http://localhost:16686

or some such.
Can that be done without any dependencies?
I agree the feature flag is not right as it stands right now. See below for a proposal.

* I'd probably lean towards not having any new example files. Maybe one if the existing ones don't do a good job of letting you use tracing, but ideally they all do.

See @hawkw 's earlier comment on the subtleties of setting up tracing for async. IMO, debug output should just work and not require you to spend more than 2 minutes on setup.

Adding spans/events, and nothing more, is just throwing the same problem onto every user to keep solving.
Perhaps we can come up with some boiler plate that will solve 80% of the problems.

I understand your motivation here. The point I've been trying to make, though, is that enabling logging, and determining how it's formatted, is an application-level concern. The general consensus in the Rust library ecosystem is that library crates (almost) never print anything to standard out by default, and don't have opinions about how logs should be formatted. Instead, the log and tracing crates provide facade layers that allow libraries to emit diagnostics that are collected by a Logger or Subscriber that's configured in application code. The idea is that the user of a library should always be the one who decides what diagnostics to opt in to, and how they should be recorded. If hyper provided its own opinions about how traces are recorded, or about what traces should be enabled by default, it would be diverging from what every other crate that uses the tracing and log facade layers does.

If users need to enable logging in a new application or in a reproduction of a bug report or something, they can just paste

tracing_subscriber::fmt::init();

into their main function to get traces output to stdout using a default format.

If users developing a production application want to use OpenTelemetry, they can configure tracing-opentelemetry to suit their use case. If users want JSON output that's compatible with a particular log processing system, there's a large number of crates that provide formatters for various JSON formats. If (for some reason) they want to send logs to a Slack channel...they can do that, too. And so on. It's way out of scope for hyper to implement any of that functionality. Rather, it's hyper's job to play nice with the rest of the ecosystem and behave the way users expect, by providing opt-in diagnostics like every other Rust library.

[taqtiqa-mark]

Thanks for engaging - I agree with all of that. Also to my mind, providing a default does not necessarily constrain you outside of the default case.
However, I do wonder, in this context, about how bright the line is between opinionated and agnosticism on what hyper span output is and what the user does with that output.

I have in mind only debug and trace level spans, etc. I also think they should be off by default, so not under the full feature - see issue #2698

This comment is why I sought early feedback:

If users developing a production application want to use OpenTelemetry, they can configure tracing-opentelemetry to suit their use case.
...<snip>...
Rather, it's hyper's job to play nice with the rest of the ecosystem and behave the way users expect, by providing opt-in diagnostics like every other Rust library.

Buying into OpenTelemetry means you can format for stdout, JSON, Jaeger, OTLP, Prometheus, etc.
However, you are constrained (as much as any convention is a constraint) to OpenTelemetry diagnostics, and its semantic conventions.

I just want to make sure whether you're suggesting, say, a hyper-opentelemetry crate?

In particular how would that work w.r.t. empty fields being populated at runtime - it seems there the OTel details would still leak into the hyper crate?

[davidpdrsn]

For a while I've wanted to add support for OpenTelemetry's conventional span field names, to tower-http's Trace middleware. I haven't read the code very closely but from the discussion it feels this might be related, as Trace can be used to instrument hyper compatible tower::Services. I have opened a draft PR to tower-http tower-rs/tower-http#180 if someone is interested.

Using that with axum (or any other tower compatible framework) could look something like this:

use axum::{routing::get, Router};
use tower_http::trace::TraceLayer;
use tracing_subscriber::{fmt, prelude::*, EnvFilter};

#[tokio::main]
async fn main() {
    opentelemetry::global::set_text_map_propagator(
        opentelemetry::sdk::propagation::TraceContextPropagator::new(),
    );
    let tracer = opentelemetry_jaeger::new_pipeline()
        .with_service_name("server")
        .install_batch(opentelemetry::runtime::Tokio)
        .unwrap();

    tracing_subscriber::registry()
        .with(fmt::layer().pretty())
        .with(tracing_opentelemetry::layer().with_tracer(tracer))
        .with(
            EnvFilter::default()
                .add_directive("tower_http=trace".parse().unwrap())
        )
        .init();

    let app = Router::new()
        .route("/", get(|| async { "Hello, World!" }))
        // install the middleware and opt in to opentelemetry
        .layer(TraceLayer::new_for_http().opentelemetry_server());

    axum::Server::bind(&"0.0.0.0:3000".parse().unwrap())
        .serve(app.into_make_service())
        .await
        .unwrap();

    opentelemetry::global::shutdown_tracer_provider();
}

[taqtiqa-mark]

Thanks @davidpdrsn I'll take a look at that. Right now I think I have enough feedback to make a meaningfully different second iteration to try address some of the issues raised.