#[instrument] doesn't get send to jaeger/opentelemetry when used on rocket.rs request handlers

MTRNord commented 4 years ago

Bug Report

Version

├── tracing v0.1.14 () ├── tracing-attributes v0.1.8 () ├── tracing-futures v0.2.4 () ├── tracing-opentelemetry v0.4.0 () └── tracing-subscriber v0.2.5 (*)

As well as the rocket-middleware (which works)

├── rocket-tracing v0.1.0 (https://github.com/Nordgedanken/rocket-tracing.git#0c166efc) │ ├── opentelemetry v0.5.0 () │ ├── tracing v0.1.14 │ │ ├── tracing-attributes v0.1.8 │ │ └── tracing-core v0.1.10 │ ├── tracing-futures v0.2.4 │ │ └── tracing v0.1.14 () │ └── tracing-opentelemetry v0.4.0 │ ├── opentelemetry v0.5.0 () │ ├── rand v0.7.3 () │ ├── tracing v0.1.14 () │ ├── tracing-core v0.1.10 () │ └── tracing-subscriber v0.2.5 │ └── tracing-core v0.1.10 (*)

As well as opentracing-jaeger: v0.4.0

And as well as rocket v0.5.0-dev (branch "async" commit "78c8ac8c"

Platform

Windows 10 64-bit

Description

Using the tracing lib with rocket seems to make problems with #[instrument].

It doesn't come up in the jaeger overview while a manually created span does show up just fine.

use tracing_opentelemetry::OpenTelemetryLayer;
use tracing_subscriber::Registry;
use opentelemetry::sdk::Tracer;
use rocket::get;
use rocket::routes;

#[get("/world")]
#[tracing::instrument]
fn world() -> &'static str {
    "hello, world!"
}

fn init_tracer() -> std::result::Result<(), Box<dyn std::error::Error>> {
    use opentelemetry::api::Provider;
    use opentelemetry::sdk;
    use tracing_subscriber::prelude::*;

    let exporter = opentelemetry_jaeger::Exporter::builder()
        .with_agent_endpoint("127.0.0.1:6831".parse().unwrap())
        .with_process(opentelemetry_jaeger::Process {
            service_name: "conduit".to_string(),
            tags: Vec::new(),
        })
        .init()?;
    let provider = sdk::Provider::builder()
        .with_simple_exporter(exporter)
        .with_config(sdk::Config {
            default_sampler: Box::new(sdk::Sampler::Always),
            ..Default::default()
        })
        .build();
    let tracer = provider.get_tracer("tracing");

    let opentelemetry: OpenTelemetryLayer<Registry, Tracer> =
        tracing_opentelemetry::layer().with_tracer(tracer);
    tracing_subscriber::registry()
        .with(opentelemetry)
        .try_init()?;

    Ok(())
}

fn main() -> std::result::Result<(), Box<dyn std::error::Error>> {
    init_tracer()?;
    rocket::ignite().mount("/", routes![world]).launch.unwrap();
    Ok(())
}

I made sure to also check the proc macro order. Both don't seem to work.

Adding a rocket middleware/fairing and adding the proc macro to "on_request" or "on_response" in it does work with this code. It only seems to happen on the request handlers

jtescher commented 4 years ago

Hm @MTRNord could this be a windows-specific issue? I see a span in jaeger when I run your example on that commit of rocket (aside from fixing launch.unwrap() to launch().unwrap()) on a mac. Unfortunately I do not currently have a windows machine to test on.

hawkw commented 4 years ago

It could be helpful to try to isolate the problem, since this seems to involve rocket, multiple parts of tracing, and OpenTelemetry.

What happens if you use tracing_subscriber::fmt as the subscriber, rather than tracing_opentelemetry? If you put an event in the handler function, does tracing_subscriber::fmt log that event annotated with the the instrument-generated span, or not?

I think the first step is figuring out whether the issue is an interaction between #[instrument] and Rocket's proc macros, or if this is a tracing-opentelemetry issue.

MTRNord commented 4 years ago

@jtescher I double check with the example I sent. It was a pretty minified example of the real code. Might be a problem combined with states used in the real code.

@hawkw I will check that.

(Going to check both tommorow german time. Its really late/early in the morning here)

jebrosen commented 4 years ago

@hawkw and I took a look at this in the tokio Discord. I am not yet very familiar with tracing works, but I think the root of the issue is that this line:

https://github.com/Nordgedanken/rocket-tracing/blob/0c166efce7716b9288963e0ae35c5ebab74688d8/src/lib.rs#L79

enters but then immediately exits the trace. Fixing this might be non-trivial, if I understand the constraints correctly:

That span must be alive for the whole request. This could be done by putting the span into request-local state, for example.
That span must be "hooked up" with something like instrument() in order to automatically handle crossing await points. Since rocket's interfaces are all callbacks (i.e. not nested futures), I believe this has to be done by rocket (but I would be happy to be wrong about this!)

Improving logging in rocket (replacing log) is a long-open issue, and tracing looks like a viable option. So tracing may end up being "built-in", at least to some degree.

This is a pretty rough idea of the problem and I am just starting to learn tracing's API, so it's likely that I missed an option here.

MTRNord commented 4 years ago

@jebrosen that line was taken from the tokio-tower example. So not sure about it entirely. But local state didn't really work (it didn't allow to pass the context to parent it (not remembering the error. Will try again to get the error.)) And passing the span didn't work either. But it is obviously wanted. But that might be an issue over at rocket instead. Might have to look there what exactly went wrong with the passing of the span/context.

About the second point, you mentioned: I don't have enough knowledge about rocket to answer that ^^ I mainly did start to implement this as a contribution to a specific server implementation. I only know very roughly how rocket works.

jtescher commented 4 years ago

@MTRNord looping back to this, did you get your issue resolved?

MTRNord commented 4 years ago

I have to admit I didn't Check yet. I am currently at a Meeting of the Company I work for over the weekend. I can I think try to check this after Wednesday.

hawkw commented 4 years ago

@MTRNord looping back to this, did you get your issue resolved?

I spoke to @jebrosen a bit about this on Discord, and our conclusion was that Rocket's middleware model doesn't really work too nicely with tracing's requirements for async code (that the future must be wrapped to instrument it with a span correctly). Fortunately, I've spent some time working on migrating Rocket to use tracing as its default logging system (https://github.com/SergioBenitez/Rocket/issues/21#issuecomment-662181870) and that should hopefully be landing soon. I imagine a follow-up would be providing built-in integration for a tracing middleware or similar in Rocket.

tokio-rs / tracing