`#instrument` attribute not making new spans

[paymog]

Bug Report

Version

 ❯❯❯ cargo tree | grep tracing
│   │   │   └── tracing v0.1.40
│   │   │       ├── tracing-attributes v0.1.27 (proc-macro)
│   │   │       └── tracing-core v0.1.32
│   │   └── tracing v0.1.40 (*)
│   │   └── tracing v0.1.40 (*)
│   └── tracing v0.1.40 (*)
│   │   │   └── tracing v0.1.40 (*)
│   │   ├── tracing v0.1.40 (*)
│   ├── tracing v0.1.40 (*)
│   ├── tracing v0.1.40 (*)
│   └── tracing-futures v0.2.5
│       └── tracing v0.1.40 (*)
└── web3 v0.19.0-graph (https://github.com/goldsky-io/rust-web3?branch=goldsky-reqwest-tracing#dc8bff2f)
├── reqwest-tracing v0.4.8
│   ├── tracing v0.1.40 (*)
│   └── tracing-opentelemetry v0.23.0
│       ├── tracing v0.1.40 (*)
│       ├── tracing-core v0.1.32 (*)
│       ├── tracing-log v0.2.0
│       │   └── tracing-core v0.1.32 (*)
│       └── tracing-subscriber v0.3.15
│           ├── tracing v0.1.40 (*)
│           ├── tracing-core v0.1.32 (*)
│           └── tracing-log v0.1.4
│               └── tracing-core v0.1.32 (*)
├── tracing v0.1.40 (*)
└── tracing-futures v0.2.5 (*)
    └── tracing v0.1.40 (*)
│       │   ├── tracing v0.1.40 (*)
│   │   │   │   └── tracing v0.1.40 (*)
│   │   │   ├── tracing v0.1.40 (*)
│   │   │   ├── tracing v0.1.40 (*)
│   │   │   └── tracing-futures v0.2.5 (*)
├── tracing v0.1.40 (*)
├── tracing-futures v0.2.5 (*)
├── tracing-opentelemetry v0.23.0 (*)
├── tracing-subscriber v0.3.15 (*)

Platform

 ❯❯❯ uname -a
Darwin pokebook 23.5.0 Darwin Kernel Version 23.5.0: Wed May  1 20:12:58 PDT 2024; root:xnu-10063.121.3~5/RELEASE_ARM64_T6000 arm64

Description

I'm finding the new spans are not being created in a specific part of my application. I have the following function

    #[tracing::instrument(skip_all, name = "PollingBlockIngestor::latest_block")]
    async fn latest_block(&self) -> Result<BlockPtr, IngestorError> {
        self.eth_adapter
            .latest_block_header(&self.logger)
            .compat()
            .await
            .map(|block| block.into())
    }

The above functions calls the following function

    #[instrument(skip_all, name = "latest_block_header")]
    fn latest_block_header(
        &self,
        logger: &Logger,
    ) -> Box<dyn Future<Item = web3::types::Block<H256>, Error = IngestorError> + Send> {
        let main_span = tracing::Span::current();
        let main_metadata = main_span.metadata().unwrap();
        info!(
            logger,
            "main span info";
            "span_id" => main_span.id().unwrap().into_u64(),
            "is_disabled" => main_span.is_disabled(),
            "name" => main_metadata.name(),
        );
        let web3 = self.web3.clone();

        Box::new(
            retry("eth_getBlockByNumber(latest) no txs RPC call", logger)
                .no_limit()
                .timeout_secs(ENV_VARS.json_rpc_timeout.as_secs())
                .run(move || {
                    let web3 = web3.cheap_clone();
                    async move {
                        let block_opt = web3
                            .eth()
                            .block(Web3BlockNumber::Latest.into())
                            .await
                            .map_err(|e| {
                                anyhow!("could not get latest block from Ethereum: {}", e)
                            })?;

                        block_opt
                            .ok_or_else(|| anyhow!("no latest block returned from Ethereum").into())
                    }
                })
                .map_err(move |e| {
                    e.into_inner().unwrap_or_else(move || {
                        anyhow!("Ethereum node took too long to return latest block").into()
                    })
                })
                .boxed()
                .compat(),
        )
    }

When I run my application, I see the following log lines

Jul 29 11:52:36.475 INFO main span info, name: PollingBlockIngestor::latest_block, is_disabled: false, span_id: 824633720838, provider: mainnet-default, component: EthereumPollingBlockIngestor
Jul 29 11:52:37.629 INFO main span info, name: PollingBlockIngestor::latest_block, is_disabled: false, span_id: 1099511627779, provider: mainnet-default, component: EthereumPollingBlockIngestor
Jul 29 11:52:38.778 INFO main span info, name: PollingBlockIngestor::latest_block, is_disabled: false, span_id: 1099511627782, provider: mainnet-default, component: EthereumPollingBlockIngestor

This suggests to me that the #instrument attribute isn't being correctly applied.

I've also tried the following variant where I use the .instrument combinator, but that also doesn't seem to work based on the spans I see exported to Jaeger (I see neither the outer_span nor the inner_span nor the latest_block_header spans exported to Jaeger).

    #[instrument(skip_all, name = "latest_block_header")]
    fn latest_block_header(
        &self,
        logger: &Logger,
    ) -> Box<dyn Future<Item = web3::types::Block<H256>, Error = IngestorError> + Send> {
        let main_span = tracing::Span::current();
        let main_metadata = main_span.metadata().unwrap();
        info!(
            logger,
            "main span info";
            "span_id" => main_span.id().unwrap().into_u64(),
            "is_disabled" => main_span.is_disabled(),
            "name" => main_metadata.name(),
        );
        let web3 = self.web3.clone();

        let outer_span = info_span!("outer_span");

        Box::new(
            retry("eth_getBlockByNumber(latest) no txs RPC call", logger)
                .no_limit()
                .timeout_secs(ENV_VARS.json_rpc_timeout.as_secs())
                .run(move || {
                    let web3 = web3.cheap_clone();
                    let inner_span = info_span!("inner_span");
                    async move {
                        let block_opt = web3
                            .eth()
                            .block(Web3BlockNumber::Latest.into())
                            .await
                            .map_err(|e| {
                                anyhow!("could not get latest block from Ethereum: {}", e)
                            })?;

                        block_opt
                            .ok_or_else(|| anyhow!("no latest block returned from Ethereum").into())
                    }.instrument(inner_span) // <------------- instrument combinator
                })
                .instrument(outer_span) // <------------- instrument combinator
                .map_err(move |e| {
                    e.into_inner().unwrap_or_else(move || {
                        anyhow!("Ethereum node took too long to return latest block").into()
                    })
                })
                .boxed()
                .compat(),
        )
    }

[paymog]

I tried removing all spans except for #[instrument(skip_all, name = "latest_block_header")] (which is the span that doesn't seem to get generated) and now trying to unwrap the metadata or the span id results in an error. I guess this is another piece of evidence of this instrumentation not working properly.

[paymog]

I'm an idiot, it was because I had my filters set up incorrectly.