`#instrument` attribute not working as expected

I have the following function:

#[tracing::instrument(skip_all)]
pub(crate) async fn blocks_with_triggers(
    adapter: Arc<EthereumAdapter>,
    logger: Logger,
    chain_store: Arc<dyn ChainStore>,
    subgraph_metrics: Arc<SubgraphEthRpcMetrics>,
    from: BlockNumber,
    to: BlockNumber,
    filter: &TriggerFilter,
    unified_api_version: UnifiedMappingApiVersion,
) -> Result<Vec<BlockWithTriggers<crate::Chain>>, Error> {

    // lots of stuff

    let to_hash_fut = eth.block_hash_by_block_number(&logger, to)
        .and_then(|hash| match hash {
            Some(hash) => Ok(hash),
            None => {
                warn!(logger,
                      "Ethereum endpoint is behind";
                      "url" => eth.provider()
                );
                bail!("Block {} not found in the chain", to)
            }
        })
        .compat();

    // lots more stuff, eventually I wait on the above future
}

The block_hash_by_block_number is declared like this:

#[tracing::instrument(skip_all)]
fn block_hash_by_block_number(
    &self,
    logger: &Logger,
    block_number: BlockNumber,
) -> Box<dyn Future<Item = Option<H256>, Error = Error> + Send> {
    // code that uses https://crates.io/crates/reqwest-tracing
}

When I run this program, the traces that are emitted don't have spans name block_hash_by_block_number under the blocks_with_triggers span. Instead, I see POST spans as direct children of blocks_with_triggers which isn't desirable. However, if I change the invocation to be

let to_hash_span = info_span!("to_hash_future");
let to_hash_fut = {
    eth.block_hash_by_block_number(&logger, to)
        .and_then(|hash| match hash {
            Some(hash) => Ok(hash),
            None => {
                warn!(logger,
                      "Ethereum endpoint is behind";
                      "url" => eth.provider()
                );
                bail!("Block {} not found in the chain", to)
            }
        })
        .compat()
        .instrument(to_hash_span)
};

Then I see the to_hash_future as a direct child of blocks_with_triggers and the old POST spans are now children of to_hash_future (but I still don't see block_hash_by_block_number as a child of to_hash_future).

It seems that in this particular code path, the #instrument attribute isn't correctly instrumenting the block_hash_by_block_number function.

Here's how the spans are being assembled by datadog. What I would expect is that the parent-child relationships would be to_hash_future -> block_hash_by_block_number -> POST -> yellow stuff but instead we see that to_hash_future and block_hash_by_block_number are siblings.

Here's how I declare the filter for my application:

        let filter_layer =
            EnvFilter::try_new("graph_chain_ethereum,reqwest_tracing::reqwest_otel_span_builder")
                .unwrap();

Solution

Events in tracing don't "capture" spans when a future is created, they only check what's the current span when they are invoked.

When using the instrument macro on a function, the created span is entered only inside that function.

The block_hash_by_block_number is not an async function, but is instead a regular function returning a future, which you then execute, after the span has been exited.

While those two cases are semantically the same most of the time, the instrument macro acts different depending on if the function is a regular sync function, or an async function.

The instrument macro on a regular function works like this:

#[instrument]
fn foo() { /* fn body */ }
// gets turned into 
//    |
//    V
fn foo() { 
    let foo_span = info_span!("foo");
    let _guard = foo_span.enter();
    /* fn body */
    // span exits here
}

While on async functions it works like this (I'm not sure if this is exactly what is produced, but most likely it is a good approximation):

#[instrument]
async fn foo() { /* fn body */ }
// gets turned into 
//    |
//    V
fn foo() -> impl Future<...> { 
    let foo_span = info_span!("foo");
    let future = async { /* fn body */ }; 
    // span gets attached to the future, and is exited when that future completes
    return future.instrument(foo_span);
}

If you want to have all events in this future be inside the span, but still return a Box<dyn Future<...>>, you should either create a new span or get the current span with tracing::Span::current() and call .instrument(span) before returning that future from block_hash_by_block_number.

I think it's important to note, that block_hash_by_block_number returns a future from a crate futures 0.1. This means that if it's not acceptable to add a span at the call site either block_hash_by_block_number will have to change signature to return a std-compliant future or a new function (e.g. block_hash_by_block_number_compat) will have to be added to call compat and then add the span.