Interleaved futures don't work properly if I specify with_span_retrace and don't specify with_deferred_spans

[safinaskar]

Consider this code:

#[tracing::instrument]
async fn a1() {
}

#[tracing::instrument]
async fn a2() {
}

#[tracing::instrument]
async fn t1() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    a1().await;
}

#[tracing::instrument]
async fn t2() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    a2().await;
}

#[tokio::main]
async fn main() {
    use tracing_subscriber::layer::SubscriberExt;
    use tracing_subscriber::util::SubscriberInitExt;
    tracing_subscriber::Registry::default()
        .with(tracing_tree::HierarchicalLayer::new(4)
            .with_span_retrace(true)
        )
        .init();
    tokio::spawn(t1());
    tokio::time::sleep(std::time::Duration::from_secs(1)).await;
    tokio::spawn(t2());
    tokio::time::sleep(std::time::Duration::from_secs(10)).await;
}

Versions:

├── tracing v0.1.40
│   ├── tracing-attributes v0.1.27 (proc-macro)
│   └── tracing-core v0.1.32
├── tracing-subscriber v0.3.17
│   ├── tracing-core v0.1.32 (*)
│   └── tracing-log v0.1.4
│       └── tracing-core v0.1.32 (*)
└── tracing-tree v0.2.5
    ├── tracing-core v0.1.32 (*)
    ├── tracing-log v0.1.4 (*)
    └── tracing-subscriber v0.3.17 (*)

Here is what I see:

 t1 
 t2 
     a1 
     a2

Here is what I expected to see:

 t1
 t2
 t1
     a1
 t2
     a2

Current output implies that a1 and a2 are both children of t2, which is wrong.

I need support for interleaved futures in my actual application. Examples ( https://github.com/davidbarsky/tracing-tree/blob/8723df3e66d9e244760ece546f7f1ce415a2c953/examples/concurrent.rs ) suggest that I need to add with_span_retrace. As you can see, I added this option, and still get wrong output. That example also suggest with_deferred_spans, but if I add it, I get no output at all, so I omitted this option. I need to see creation of spans

[safinaskar]

Also let me describe what I actually want. This will not be quite bug report, this will be more like feature request. I want creating of spans (not to be confused with entering) to be proper log entries with timestamps. When you merely show current active span, then, of course, this is not full-blown log entry, and thus should not have timestamp. But it should have "-----" instead of timestamp for proper visual alignment. In other words, this is how output of this example should look at my opinion (timestamps are faked here):

2023-10-30T16:48:00Z t1
2023-10-30T16:48:00Z t2
-------------------- t1
    2023-10-30T16:48:00Z a1
-------------------- t2
    2023-10-30T16:48:00Z a2

You may say: "Just insert events (i. e. info!) in the beginning of every span". Well, this defeats purpose of #[tracing::instrument]. The whole purpose of this macro is that I don't need to insert artificial events in the begin and end of async function.

You may say: "Use with_verbose_entry". Well, adding with_verbose_entry really fixes this example. But it doesn't work in more complicated cases. Consider this code:

#[tracing::instrument]
async fn b1() {
}

#[tracing::instrument]
async fn b2() {
}

#[tracing::instrument]
async fn a1() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    b1().await;
}

#[tracing::instrument]
async fn a2() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    b2().await;
}

#[tracing::instrument]
async fn t1() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    a1().await;
}

#[tracing::instrument]
async fn t2() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    a2().await;
}

#[tokio::main]
async fn main() {
    use tracing_subscriber::layer::SubscriberExt;
    use tracing_subscriber::util::SubscriberInitExt;
    tracing_subscriber::Registry::default()
        .with(tracing_tree::HierarchicalLayer::new(4)
            .with_span_retrace(true)
            .with_verbose_entry(true)
        )
        .init();
    tokio::spawn(t1());
    tokio::time::sleep(std::time::Duration::from_secs(1)).await;
    tokio::spawn(t2());
    tokio::time::sleep(std::time::Duration::from_secs(10)).await;
}

This is what I see:

 t1 
 t2 
 t1 
     a1 
 t2 
     a2 
     a1 
         b1 
     a2 
         b2

The output is wrong, because it suggests that a1 and a2 are both children of t2, which is wrong.

Moreover, I don't understand why with_span_retrace is separate option. Whole purpose of tracing ecosystem is proper support for concurrent async code. This is the reason described in introductory post https://tokio.rs/blog/2019-08-tracing . So, of course, with_span_retrace, which supposedly adds support for concurrent code, should be default and only supported mode. This will reduce combinatoric explosion of test modes

[ten3roberts]

I agree, it would be better if it was default, it was just to not break backwards compatibility.

The default behavior just treats span as always active until they close, which is wrong in a concurrent or multithreaded scenario.

I'll see what I can do regarding the non-lazy span retrace, and try to reproduce it 😄