Tracing of middleware doesn't join together.

[zishon]

I am doing some practice with axum.
I built an app with an simple middleware.
below is the Cargo.toml

[package]
name = "rust-axum"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
axum = {version="0.5.16", features=["headers"]}
hyper = {version="0.14.20", features=["full"]}
tokio = { version = "1.21.1", features = ["full"] }
tower = "0.4.13"
tracing = "0.1.36"
tracing-attributes = "0.1.18"
tracing-subscriber = { version = "0.3.15", features = ["env-filter"] }
opentelemetry-jaeger = { version = "0.16.0", features = ["isahc_collector_client", "rt-tokio"] }
opentelemetry = { version = "0.17.0", features = ["rt-tokio"] }
opentelemetry-http = "0.6.0"
tracing-opentelemetry = "0.17.4"
tower-http = "0.3.4"
futures = "0.3.24"

below is main.rs

use std::error::Error;
use std::task::Poll;

use axum::{Router, routing::get};
use axum::response::Response;
use futures::future::BoxFuture;
use hyper::Body;
use hyper::http::Request;
use opentelemetry::{Context, global};
use opentelemetry::propagation::TextMapPropagator;
use opentelemetry::sdk::propagation::TraceContextPropagator;
use opentelemetry::trace::TraceContextExt;
use opentelemetry_http::HeaderExtractor;
use tower::Service;
use tower::layer::layer_fn;
use tracing::span;
use tracing_attributes::instrument;
use tracing_opentelemetry::OpenTelemetrySpanExt;
use tracing_subscriber::prelude::*;

#[derive(Clone)]
struct HelloMiddleware<S> {
    inner: S,
}

impl<S, ReqBody, ResBody> Service<Request<ReqBody>> for HelloMiddleware<S>
    where
        S: Service<Request<ReqBody>, Response=Response<ResBody>> + Clone + Send + 'static,
        S::Future: Send + 'static,
        ReqBody: Send + 'static,
        ResBody: Send + 'static,
{
    type Response = S::Response;
    type Error = S::Error;
    type Future = BoxFuture<'static, Result<Self::Response, Self::Error>>;

    fn poll_ready(&mut self, _cx: &mut std::task::Context<'_>) -> Poll<Result<(), Self::Error>> {
        Poll::Ready(Ok(()))
    }

    fn call(&mut self, req: Request<ReqBody>) -> Self::Future {
        let propagator = TraceContextPropagator::new();
        let parent_context = propagator.extract(&HeaderExtractor(req.headers()));
        let app_root_span = tracing::span!(tracing::Level::INFO, "request start");
        app_root_span.set_parent(parent_context);
        app_root_span.in_scope(|| {
            let f = self.inner.call(req);
            Box::pin(f)
        })
    }
}

async fn process() -> &'static str {
    let process_span = tracing::span!(tracing::Level::INFO, "process start.");
    let _ = process_span.enter();
    "result"
}

//#[tokio::main]
#[tokio::main(flavor = "current_thread")]
async fn main() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
    let tracer = opentelemetry_jaeger::new_pipeline()
        .with_service_name("axum.demo")
        .install_batch(opentelemetry::runtime::Tokio)?;

    let opentelemetry = tracing_opentelemetry::layer().with_tracer(tracer);
    global::set_text_map_propagator(TraceContextPropagator::new());
    tracing_subscriber::Registry::default()
        .with(opentelemetry)
        .try_init()?;
    let hello = layer_fn(|inner| HelloMiddleware {
        inner
    });

    let app = Router::new()
        .route("/", get(process))
        .layer(hello);

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

    Ok(())
}

start the jaeger with command:

docker run -d -p6831:6831/udp -p6832:6832/udp -p16686:16686 -p14268:14268 jaegertracing/all-in-one:latest
after make a request by curl

curl http://127.0.0.1:3000/
visit the jaeger UI http://127.0.0.1:16686/
I got the result

But I expect some result like this

└── request start
└── process start.
have I done something wrong, why the handler's span and middleware's span don't join together? In some way, they must be child-parent relation.

rustup 1.24.3
rustc 1.60.0
axum 0.5.6

[davidbarsky]

By doing span!(...), you're only creating the spans, but not actually entering the span. Consider reading https://docs.rs/tracing/latest/tracing/span/index.html#the-span-lifecycle and editing your code accordingly.

[zishon]

I had updated my code.
what I'm wondering is: why process_span is not child of app_root_span?