Tracing of middleware doesn't join together. #1351

zishon · 2022-09-06T18:05:42Z

zishon
Sep 6, 2022

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="*", features=["headers"]}
hyper = {version="*", features=["full"]}
tokio = { version = "*", features = ["full"] }
tower = "*"
tracing = "*"
tracing-attributes = "0.1.18"
tracing-subscriber = { version = "*", features = ["env-filter"] }
opentelemetry-jaeger = { version = "*", features = ["isahc_collector_client", "rt-tokio"] }
opentelemetry = { version = "*", features = ["rt-tokio"] }
opentelemetry-http = "0.6.0"
tracing-opentelemetry = "*"
tower-http = "*"
futures = "*"

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::global;
use opentelemetry::propagation::TextMapPropagator;
use opentelemetry::sdk::propagation::TraceContextPropagator;
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::*;

#[instrument]
async fn process(request: Request<Body>) -> &'static str {
    tracing::span!(tracing::Level::INFO, "process start.");
    let result = some_io().await;
    tracing::span!(tracing::Level::INFO, "process end.");
    result
}

#[instrument]
async fn some_io() -> &'static str {
    span!(tracing::Level::INFO, "io start.");
    span!(tracing::Level::INFO, "io end.");
    "io result"
}

#[tokio::main]
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(())
}


#[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 = tracing::span!(tracing::Level::INFO, "request start");
        app_root.set_parent(parent_context.clone());
        let _enter = app_root.enter();

        let f = self.inner.call(req);
        Box::pin(f)
    }
}

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
        ├── process start.
        ├── some_io
        │   ├── io start.
        │   └── io end.
        └── process end.

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

davidpdrsn · 2022-09-06T19:36:11Z

davidpdrsn
Sep 6, 2022
Collaborator

No idea, not really related to axum 🤷 Try asking in #tracing-users in the tokio discord.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Tracing of middleware doesn't join together. #1351

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 1 comment

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Tracing of middleware doesn't join together. #1351

Uh oh!

Uh oh!

zishon Sep 6, 2022

Replies: 1 comment

Uh oh!

davidpdrsn Sep 6, 2022 Collaborator

zishon
Sep 6, 2022

davidpdrsn
Sep 6, 2022
Collaborator