Tracing span doesn't include all log events

So, I'm learning axum and tracing crates by following Zero to Production in Rust book. I'm trying to add tracing to log span that will include a request id.

When I enter span outside this match statement, log messages doesn't include it, even though they are in the same async function (so there is no need for instrument). This:

let request_id = Uuid::new_v4();
let span = trace_span!("Adding a new subscriber.",
    %request_id,
    subscriber_email = %form.email,
    subscriber_name = %form.name
);
let _guard = span.enter();

match sqlx::query!(\**\).await {
    Ok(_) => {
        info!("New subscriber details saved");
        StatusCode::OK
    }
    Err(err) => {
        error!(?err, "Failed to execute query");
        StatusCode::INTERNAL_SERVER_ERROR
    }
}

Logs this:

ERROR zero2prod::routes::subscriptions: Failed to execute query

When I add span.enter inside match arms, everything works: This:

match sqlx::query!(\**\).await {
    Ok(_) => {
        let _guard = span.enter();
        info!("New subscriber details saved");
        StatusCode::OK
    }
    Err(err) => {
        let _guard = span.enter();
        error!(?err, "Failed to execute query");
        StatusCode::INTERNAL_SERVER_ERROR
    }
}

Logs this:

ERROR Adding a new subscriber.{request_id=aeafbef7-c6aa-4e8e-980f-8ebbd40e7302 subscriber_email=ursul_le_gn@gmail.com subscriber_name=le guin}: zero2prod::routes::subscriptions: Failed to execute query

Am I doing something wrong? Is this how spans supposed to work, or is there a better and easier way to do this?

Solution

From the Span::enter documentation:

In Asynchronous Code

Warning: in asynchronous code that uses async/await syntax, Span::enter should be used very carefully or avoided entirely. Holding the drop guard returned by Span::enter across .await points will result in incorrect traces. For example,
async fn my_async_function() {
    let span = info_span!("my_async_function");

    // WARNING: This span will remain entered until this
    // guard is dropped...
    let _enter = span.enter();
    // ...but the `await` keyword may yield, causing the
    // runtime to switch to another task, while remaining in
    // this span!
    some_other_async_function().await

    // ...
}
The drop guard returned by Span::enter exits the span when it is dropped. When an async function or async block yields at an .await point, the current scope is exited, but values in that scope are not dropped (because the async block will eventually resume execution from that await point). This means that another task will begin executing while remaining in the entered span. This results in an incorrect trace.

It goes on to suggest other options: Span::in_scope, .instrument(), or #[instrument]. I highly recommend encapsulating this in a function annotated with #[instrument] since (in my opinion) it yields the most ergonomic and fool proof way to ensure spans are handled correctly.

If you are only creating an span within the function so that request_id is attached to it (which is only generated within the function) and you want to avoid another helper function, you can instrument your function with the request_id field set to Empty and insert it into the span later with .record().