Task id is always 0

[najamelan]

Modifying the trace example like this:

use async_log::{span};
use log::info;

fn setup_logger() {
    let logger = femme::pretty::Logger::new();
    async_log::Logger::wrap(logger, || /* get the task id here */ 0)
        .start(log::LevelFilter::Trace)
        .unwrap();
}

fn main() {
    setup_logger();

    let task1 = async { span!( "level {}", 1,
    {
        info!( "From task 1" );

    })};

    let task2 = async { span!( "level {}", 1,
    {
        info!( "From task 2" );

    })};

    let task3 = async { span!( "level {}", 1,
    {
        info!( "From task 3" );

    })};

    async_std::task::spawn( task1 );
    async_std::task::spawn( task2 );
    async_std::task::spawn( task3 );

    std::thread::sleep( std::time::Duration::from_millis( 500 ) );
}

I get the following output (as you can see, the task_id is always 0 for the relevant log messages, and log messages from async-std have task_id twice):

car --example trace
   Compiling async-log v2.0.0 (/data/doc/code/RUST/async-log)
    Finished dev [unoptimized + debuginfo] target(s) in 0.80s
     Running `/tmp/rs/debug/examples/trace`
●  spawn
   /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.5.0/src/task/builder.rs:41
   › task_id: 1
   › parent_task_id: 0
   › thread_id: 1
   › task_id: 0

●  spawn
   /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.5.0/src/task/builder.rs:41
   › task_id: 2
   › parent_task_id: 0
   › thread_id: 1
   › task_id: 0

◯  level 1
   src/lib.rs:188
   › span_mark: "start"
   › thread_id: 4
   › task_id: 0

●  spawn
   /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.5.0/src/task/builder.rs:41
   › task_id: 3
   › parent_task_id: 0
   › thread_id: 1
   › task_id: 0

◯  level 1
   src/lib.rs:188
   › span_mark: "start"
   › thread_id: 18
   › task_id: 0

●  From task 1
   examples/trace.rs:16
   › thread_id: 4
   › task_id: 0

◯  level 1
   src/lib.rs:188
   › span_mark: "start"
   › thread_id: 21
   › task_id: 0

●  From task 2
   examples/trace.rs:22
   › thread_id: 18
   › task_id: 0

◯  level 1
   src/lib.rs:188
   › span_mark: "end"
   › thread_id: 4
   › task_id: 0

●  From task 3
   examples/trace.rs:28
   › thread_id: 21
   › task_id: 0

◯  level 1
   src/lib.rs:188
   › span_mark: "end"
   › thread_id: 18
   › task_id: 0

●  completed
   /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.5.0/src/task/builder.rs:57
   › task_id: 1
   › thread_id: 4
   › task_id: 0

◯  level 1
   src/lib.rs:188
   › span_mark: "end"
   › thread_id: 21
   › task_id: 0

●  completed
   /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.5.0/src/task/builder.rs:57
   › task_id: 2
   › thread_id: 18
   › task_id: 0

●  completed
   /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.5.0/src/task/builder.rs:57
   › task_id: 3
   › thread_id: 21
   › task_id: 0

[najamelan]

I missed the /* get the task id here */ part. Didn't realize that getting the task Id was not included in the crate.

[yoshuawuyts]

@najamelan I started a patch to make it work out of the box in https://github.com/async-rs/async-log/pull/9, but never saw it through to completion. Still unsure if it's a good idea.

[najamelan]

Looks like that is async-std specific? I found a solution that works for me with tracing-futures. The Instrumented type wraps futures and executors to set the right span in the poll function. Thus it works even when using join. Everything that runs concurrently can be detected in the logs, making it possible to create a gui that puts the log statements in columns side by side. Haven't made such a gui yet, but I will soon.

[najamelan]

Oh, and as an added advantage, that allows you to set any structured data, like a name instead of a numeric task id, which is to be preferred I think.