#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