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();
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.