Rust: Into tracing world

#Rust
## tracing 
https://crates.io/crates/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
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/533536/998e8f57-7e61-eaa8-40b6-20e1e1594d2f.png)

##Cargo.toml
```toml
tracing = "0.1.21"
tracing-subscriber = "0.2"
```
## A minimal example
```rust
use tracing_subscriber;

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

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

## Output
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/533536/e7949657-2fea-3529-6b00-36d0af83939f.png)


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


## Printing in a cool way
```rust
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 
```rust
// print function name for every info!() 
#[tracing::instrument()] 
fn demo_2(order_no: usize) {
    info!("enter");
    info!("doing something..");
    info!("end");
}
```

```terminal
// 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

```rust
#[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");
}
```
```terminal
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
// rust
#[tracing::instrument()]
fn demo_3(arg: usize) {
    inner(); // 
}

fn inner() {
    info!("in inner");
}
```
```terminal
// terminal
Dec 03 19:20:33.617  INFO demo_3{arg=3}: tracing_practice: in inner
```

## concating span 

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

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


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

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

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

## `tokio::spawn`

```rust
// 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;
}
```

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

# Don't do this 

```rust
#[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");
}
```

```terminal
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