Rust: Into tracing world

Rust

tracing

This article is about

showcasing tracing with useful examples

This article is for

People who know some basic of Rust and the rust log crate

My Background was

1.5 years for rust coding and 8+ years c++

Import

Cargo.toml

tracing = "0.1.21"
tracing-subscriber = "0.2"

A minimal example

use tracing_subscriber;

fn main() {
    tracing_subscriber::fmt::init(); // without this, can't print anything even it compiles
    tracing::info!("Hello world");
}

Running

// terminal
$ RUST_LOG=info cargo run # without RUST_LOG=info, nothing was printed

Output

At this point, tracing is acting just like our old friend log, however

Printing in a cool way

fn demo_1() {
    use tracing::info;
    info!("================ primitive number type  =====================");
    let u = 32; // usize, u8, i8, u16, i16 ..... etc
    info!(u); // u=32,
    info!(%u); // u=32, if impl Display trait
    info!(?u); // u=32, if impl Debug trait
    info!(some_name = u); // some_name=32
    info!(some_name=%u); // some_name=32
    info!(some_name=?u); // some_name=32

    info!("================ str =====================");
    let s = "abc";
    info!(s); // s="abc"
    info!(%s); // s=abc   , if impl Display trait
    info!(?s); // s="abc" , if impl Debug trait
    info!(some_name = s); // some_name="abc"
    info!(some_name=%s); // some_name=abc
    info!(some_name=?s); // some_name="abc"

    info!("================ String  ==================");
    let s = "abc".to_string();
    // info!(s); // compiler error
    info!(%s); // s=abc   , if impl Display trait
    info!(?s); // s="abc" , if impl Debug trait
    // info!(some_name=s);       // compiler error
    info!(some_name = s.as_str()); // some_name="abc"
    info!(some_name=?s); // some_name="abc"

    info!("================ my struct ===============");

    #[derive(Debug)]
    struct Gem {
        a: usize,
    }
    // for latter use
    impl std::fmt::Display for Gem {
        fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> 
    std::fmt::Result {
            write!(f, "{}", self.a)
       }
    }

    let g = Gem { a: 1 };
    //info!(g);  // compiler error
    info!(%g); // g=1             , if impl Display trait
    info!(?g); // g=Gem { a: 1 }  , if impl Debug trait
    //info!(some_name=g); // error
    info!(some_name=%g); // g=1             , if impl Display trait
    info!(some_name=?g); // g=Gem { a: 1 }  , if impl Debug trati
}

Instrument Basic

instrument is to let tracing create a span for us in a convenient way

// print function name for every info!() 
#[tracing::instrument()] 
fn demo_2(order_no: usize) {
    info!("enter");
    info!("doing something..");
    info!("end");
}

// terminal, 
Dec 03 18:35:53.311  INFO demo_2{order_no=12345}: tracing_practice: enter
Dec 03 18:35:53.312  INFO demo_2{order_no=12345}: tracing_practice: doing something
Dec 03 18:35:53.312  INFO demo_2{order_no=12345}: tracing_practice: end

As we can see above, order_no is printed automatically so that it saves times to type manually for every single info!()

What's more, we can have customized naming
(#[instrument(name = "PS5")])

Instrument, more attributes

level, skip, fields

#[tracing::instrument(level = "error", skip(i_want_skip_this), fields(plus_one=order_no+1, late_inited=tracing::field::Empty))]
fn demo_2(order_no: usize, i_want_skip_this: bool) {
    info!("enter");
    tracing::Span::current().record("late_inited", &"yes");
    info!("doing something");
    info!("end");
}

Dec 03 18:52:45.827  INFO demo_2{order_no=12345 plus_one=12346}: tracing_practice: enter
Dec 03 18:52:45.827  INFO demo_2{order_no=12345 plus_one=12346 late_inited="yes"}: tracing_practice: doing something
Dec 03 18:52:45.827  INFO demo_2{order_no=12345 plus_one=12346 late_inited="yes"}: tracing_practice: end

skip

From output above, we can see that it skip i_want_skip_this but still printed order_no

fields

we can add more fields to collect extra info for debugging

level

level = "error" indicates that this instrument is enabled for error!(), warn!(), info!(), debug!(), trace!()

Span can be passed down to inner function

// rust
#[tracing::instrument()]
fn demo_3(arg: usize) {
    inner(); // 
}

fn inner() {
    info!("in inner");
}

// terminal
Dec 03 19:20:33.617  INFO demo_3{arg=3}: tracing_practice: in inner

concating span

// rust
#[tracing::instrument()]
fn demo_3(arg: usize) {
    inner(1);
}

#[tracing::instrument()]
fn inner(inner_arg: usize) {
    info!("in inner");
}

// terminal
Dec 03 19:24:11.707  INFO demo_3{arg=3}:inner{inner_arg=1}: tracing_practice: in inner

Working with Future

# Cargo.toml
tracing = "0.1.21"
tracing-subscriber = "0.2"
tracing-futures = "0.2" # new crate

// rust
#[tracing::instrument()]
async fn demo_4(arg: usize) {
    info!("also work with future !");
}

tokio::spawn

// rust
#[tracing::instrument()]
async fn demo_4(arg: usize) {
    let h = tokio::spawn(
        async move {
            info!("from spawn");
        }
        //.instrument(tracing::Span::current()), // use parent's span
        //.instrument(tracing::error_span!(parent: tracing::Span::none(), "notifier", "arg"=arg+1)),  // cut-off from parent's span and create our own span as root span
        .instrument(tracing::error_span!("my own span", "arg" = arg + 1)), // inherit parent's and concat with our own span
    );

    h.await;
}

Dec 03 19:26:50.922  INFO demo_4{arg=4}:my own span{arg=5}: tracing_practice: from spawn

Don't do this

#[tracing::instrument(level = "error", skip(i_want_skip_this), fields(plus_one=order_no+1, late_inited=tracing::field::Empty))]
fn demo_2(order_no: usize, i_want_skip_this: bool) {

    tracing::Span::current().record("late_inited", &"yes 1");
    info!("doing something 1");

    // it's not overwriting but appending !
    tracing::Span::current().record("late_inited", &"yes 2");
    info!("doing something 2");

    // it's not overwriting but appending !
    tracing::Span::current().record("late_inited", &"yes 3");
    info!("doing something 3");
}

Dec 03 19:39:32.103  INFO demo_2{order_no=12345 plus_one=12346 late_inited="yes 1"}: tracing_practice: doing something 1
Dec 03 19:39:32.104  INFO demo_2{order_no=12345 plus_one=12346 late_inited="yes 1" late_inited="yes 2"}: tracing_practice: doing something 2
Dec 03 19:39:32.104  INFO demo_2{order_no=12345 plus_one=12346 late_inited="yes 1" late_inited="yes 2" late_inited="yes 3"}: tracing_practice: doing something 3

Summary

The examples above should cover most of our daily log, though tracing has its own learning curve, still it's worthy spending time

Imo, it's a replacement of log crate and offers more flexibility and convenience to simply the way we log,

More

tracing is not only an idea but also a huge eco-system, tracing crate is just a good start. If we feel comfortable with tracing and wanna explore more inside tracing world, I'd suggest tracing-subscriber to create our own subscriber and output log in the way we want