Tracing creating nested spans

help
1

I'm using tracing and async_std to iterate over a Stream:

    messages
        .for_each(|delivery| {
            async_std::task::spawn(async {
                let span = span!(
                    Level::INFO,
                    "rabbit_mq",
                    msg = delivery.as_ref().unwrap().delivery_tag
                );
                let _enter = span.enter();
                ...do stuff...

But it is creating randomly nested spans like this:

Nov 15 15:35:21.080 DEBUG rabbit_mq{msg=13}: log message goes here
Nov 15 15:35:21.139 DEBUG rabbit_mq{msg=8}:rabbit_mq{msg=21}:rabbit_mq{msg=27}: log message goes here
Nov 15 15:35:21.205 DEBUG rabbit_mq{msg=9}:rabbit_mq{msg=22}: log message goes here
Nov 15 15:35:21.267 DEBUG rabbit_mq{msg=10}:rabbit_mq{msg=23}: log message goes here
Nov 15 15:35:21.322 DEBUG rabbit_mq{msg=11}:rabbit_mq{msg=24}: log message goes here
Nov 15 15:35:21.376 DEBUG rabbit_mq{msg=12}:rabbit_mq{msg=25}: log message goes here
Nov 15 15:35:21.442 DEBUG rabbit_mq{msg=13}: log message goes here
Nov 15 15:35:21.505 DEBUG rabbit_mq{msg=1}:rabbit_mq{msg=14}: log message goes here
Nov 15 15:35:21.569 DEBUG rabbit_mq{msg=2}:rabbit_mq{msg=15}:rabbit_mq{msg=33}: log message goes here
Nov 15 15:35:21.622 DEBUG rabbit_mq{msg=3}:rabbit_mq{msg=16}:rabbit_mq{msg=28}:rabbit_mq{msg=34}: log message goes here

It is even worse when I use StreamExt's for_each_concurrent because they pile up like a pyramid instead of randomly nesting.

Any idea what is going on here? I've used tracing before on async code without it having any issues like this, only that time I was using Tokio, but that shouldn't make a difference, should it?

2

I'm not familiar with tracing, but could it perhaps be caused by objects existing through an await point? This could result in creating a span, pausing that function, creating a span somewhere else, which might be the reason?

3

That sounds like what it's doing from looking at the output logs, but I have no idea why. tracing was designed to be used with async code and is part of the tokio project, but it says it can be used with other runtimes. The only thing I can think of is maybe there is some compatibility issue with it and async_std...

4

Update: it turned out I had to use tracing_futures::instrument to get it to work with async code.

1 Like
5

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.