rust - Enabling tracing::Span per-request in Axum middleware - Stack Overflow

admin管理员组

文章数量:1406937

I have a very simple Axum middleware function where I just enter a span, do some logging and request id attachment.

async fn middleware_fn(req: Request, next: Next) -> Response {
    let start = Instant::now();

    let method = req.method();
    let uri = req.uri();
    let req_id = Uuid::now_v7();

    let span = debug_span!("request", %method, %uri, req_id = ?req_id, user = field::Empty);
    let _guard = span.enter();

    debug!("started processing request");

    let mut resp = next.run(req).instrument(span.clone()).await;

    resp.headers_mut().append(
        "x-request-id",
        HeaderValue::from_str(&req_id.to_string()).unwrap(),
    );

    debug!(latency = ?start.elapsed().as_millis(), status = ?resp.status(), "finished processing");

    resp
}

I am having problems with the span. Sometimes, finished processing log doesn't have a span, and in the next request, I see two spans in which the first span belongs to the previous request. I know that spans require care when used with async code, but I thought Instrument would be sufficient to manage the span in this simple case.

I know that tower has layers to provide both these functionalities (tracing and request id generation), but I would like to know how I can achieve this myself.

I have a very simple Axum middleware function where I just enter a span, do some logging and request id attachment.

async fn middleware_fn(req: Request, next: Next) -> Response {
    let start = Instant::now();

    let method = req.method();
    let uri = req.uri();
    let req_id = Uuid::now_v7();

    let span = debug_span!("request", %method, %uri, req_id = ?req_id, user = field::Empty);
    let _guard = span.enter();

    debug!("started processing request");

    let mut resp = next.run(req).instrument(span.clone()).await;

    resp.headers_mut().append(
        "x-request-id",
        HeaderValue::from_str(&req_id.to_string()).unwrap(),
    );

    debug!(latency = ?start.elapsed().as_millis(), status = ?resp.status(), "finished processing");

    resp
}

I am having problems with the span. Sometimes, finished processing log doesn't have a span, and in the next request, I see two spans in which the first span belongs to the previous request. I know that spans require care when used with async code, but I thought Instrument would be sufficient to manage the span in this simple case.

I know that tower has layers to provide both these functionalities (tracing and request id generation), but I would like to know how I can achieve this myself.

• rust
• rust-axum

Share Follow asked Mar 4 at 9:04 Ahmet YazıcıAhmet Yazıcı 75477 silver badges2020 bronze badges

Add a comment  | 

1 Answer 1

Sorted by: Reset to default 1

You've run afoul of (Span::enter):

Holding the drop guard returned by Span::enter across .await points will result in incorrect traces.

The tracking of the "current" span is done on a per-thread basis. Unfortunately, when an async task yields, then another span may be entered and when your original task resumes there's nothing that re-establishes what span should be "current".

You are already using .instrument() when calling next.run(req) - which is correct since it handles the async switching for you, just not after the .await finishes - but the simple solution would be to encapsulate your whole function with async { }.instrument() instead:

async fn middleware_fn(req: Request, next: Next) -> Response {
    let start = Instant::now();

    let method = req.method();
    let uri = req.uri();
    let req_id = Uuid::now_v7();

    let span = debug_span!("request", %method, %uri, req_id = ?req_id, user = field::Empty);

    async {
        debug!("started processing request");

        let mut resp = next.run(req).await;

        resp.headers_mut().append(
            "x-request-id",
            HeaderValue::from_str(&req_id.to_string()).unwrap(),
        );

        debug!(latency = ?start.elapsed().as_millis(), status = ?resp.status(), "finished processing");

        resp
    }.instrument(span).await
}

At this point, you should probably consider using #[instrument] on your function instead, but req_id is somewhat annoying so its up to you.

本文标签： rustEnabling tracingSpan perrequest in Axum middlewareStack Overflow