Tracing Introduction
Tracing
Tracing is an instrumentation library that makes it easy to add traceable spans to your rust code.
Just Print It
The simplest example is to just log your tracing output, that will result in the same as using a logging crate, like slog.
[dependencies]
tracing = "0.1"
use tracing::info;
fn main() {
info!("hello world");
}
When we run this...
❯ cargo run -p just-print-it Finished dev [unoptimized + debuginfo] target(s) in 0.01s Running `target/debug/just-print-it`
Nothing happens.
But that's easy to solve, if we look at the tracing examples, we will realize that we need an subscriber to receive the tracing events.
Let's add the new dependency
[dependencies]
tracing = "0.1"
tracing-subscriber = "0.2"
Setup the subscriber
use tracing::info;
use tracing_subscriber;
fn main() {
tracing_subscriber::fmt::init();
info!("hello world");
}
And now...
❯ cargo run -p just-print-it Finished dev [unoptimized + debuginfo] target(s) in 0.02s Running `target/debug/just-print-it`
Still nothing...
Oh, turns out we need to set the RUST_LOG environment variable to info, by
default the subscriber is printing only messages with level error and above.
❯ RUST_LOG=info cargo run -p just-print-it Finished dev [unoptimized + debuginfo] target(s) in 0.02s Running `target/debug/just-print-it` Dec 09 09:03:18.860 INFO just_print_it: hello world
Lets add some functions
use tracing::{error, info};
use tracing_subscriber;
fn fn_a () {
info!("hello from fn_a");
for i in (0..3).rev() {
let res = sub_one(i);
info!(num=i, res, "{}-1={}", i, res);
}
}
fn sub_one (value: u8) -> u8 {
info!("hello from sub_one");
match value.checked_sub(1) {
Some(i) => i,
None => {
error!("subtraction failed!");
0
},
}
}
fn main() {
tracing_subscriber::fmt::init();
info!("hello from main");
fn_a();
}
❯ RUST_LOG=info cargo run -p just-print-it Finished dev [unoptimized + debuginfo] target(s) in 0.02s Running `target/debug/just-print-it` Dec 09 09:05:32.934 INFO just_print_it: hello from main Dec 09 09:05:32.934 INFO just_print_it: hello from fn_a Dec 09 09:05:32.934 INFO just_print_it: hello from sub_one Dec 09 09:05:32.934 INFO just_print_it: 2-1=1 num=2 res=1 Dec 09 09:05:32.934 INFO just_print_it: hello from sub_one Dec 09 09:05:32.934 INFO just_print_it: 1-1=0 num=1 res=0 Dec 09 09:05:32.934 INFO just_print_it: hello from sub_one Dec 09 09:05:32.934 ERROR just_print_it: subtraction failed! Dec 09 09:05:32.934 INFO just_print_it: 0-1=0 num=0 res=0
Using tracing::instrument
use tracing::{error, info};
use tracing_subscriber;
#[tracing::instrument]
fn fn_a () {
info!("hello from fn_a");
for i in (0..3).rev() {
let res = sub_one(i);
info!(num=i, res, "{}-1={}", i, res);
}
}
#[tracing::instrument]
fn sub_one (value: u8) -> u8 {
info!("hello from sub_one");
match value.checked_sub(1) {
Some(i) => i,
None => {
error!("subtraction failed!");
0
},
}
}
fn main() {
tracing_subscriber::fmt::init();
info!("hello from main");
fn_a();
}
❯ RUST_LOG=info cargo run -p just-print-it Finished dev [unoptimized + debuginfo] target(s) in 0.02s Running `target/debug/just-print-it` Dec 09 09:07:08.406 INFO just_print_it: hello from main Dec 09 09:07:08.406 INFO fn_a: just_print_it: hello from fn_a Dec 09 09:07:08.406 INFO fn_a:sub_one{value=2}: just_print_it: hello from sub_one Dec 09 09:07:08.406 INFO fn_a: just_print_it: 2-1=1 num=2 res=1 Dec 09 09:07:08.406 INFO fn_a:sub_one{value=1}: just_print_it: hello from sub_one Dec 09 09:07:08.406 INFO fn_a: just_print_it: 1-1=0 num=1 res=0 Dec 09 09:07:08.406 INFO fn_a:sub_one{value=0}: just_print_it: hello from sub_one Dec 09 09:07:08.406 ERROR fn_a:sub_one{value=0}: just_print_it: subtraction failed! Dec 09 09:07:08.407 INFO fn_a: just_print_it: 0-1=0 num=0 res=0
❯ RUST_LOG=info cargo run -p just-print-it Compiling just-print-it v0.1.0 (/home/peer/Development/rust/tracing-the-tracer/just-print-it) Finished dev [unoptimized + debuginfo] target(s) in 0.98s Running `target/debug/just-print-it` Dec 09 09:08:47.666 INFO just_print_it: hello from main Dec 09 09:08:47.666 INFO fn_a: just_print_it: hello from fn_a Dec 09 09:08:47.666 INFO fn_a:sub_one{value=2 secret="some secret"}: just_print_it: hello from sub_one Dec 09 09:08:47.667 INFO fn_a: just_print_it: 2-1=1 num=2 res=1 Dec 09 09:08:47.667 INFO fn_a:sub_one{value=1 secret="some secret"}: just_print_it: hello from sub_one Dec 09 09:08:47.667 INFO fn_a: just_print_it: 1-1=0 num=1 res=0 Dec 09 09:08:47.667 INFO fn_a:sub_one{value=0 secret="some secret"}: just_print_it: hello from sub_one Dec 09 09:08:47.667 ERROR fn_a:sub_one{value=0 secret="some secret"}: just_print_it: subtraction failed! Dec 09 09:08:47.667 INFO fn_a: just_print_it: 0-1=0 num=0 res=0
❯ RUST_LOG=info cargo run -p just-print-it Compiling just-print-it v0.1.0 (/home/peer/Development/rust/tracing-the-tracer/just-print-it) warning: unused variable: `secret` --> just-print-it/src/main.rs:16:24 | 16 | fn sub_one (value: u8, secret: &str) -> u8 { | ^^^^^^ help: if this is intentional, prefix it with an underscore: `_secret` | = note: `#[warn(unused_variables)]` on by default warning: `just-print-it` (bin "just-print-it") generated 1 warning Finished dev [unoptimized + debuginfo] target(s) in 0.97s Running `target/debug/just-print-it` Dec 09 09:09:32.513 INFO just_print_it: hello from main Dec 09 09:09:32.514 INFO fn_a: just_print_it: hello from fn_a Dec 09 09:09:32.514 INFO fn_a:sub_one{value=2}: just_print_it: hello from sub_one Dec 09 09:09:32.514 INFO fn_a: just_print_it: 2-1=1 num=2 res=1 Dec 09 09:09:32.514 INFO fn_a:sub_one{value=1}: just_print_it: hello from sub_one Dec 09 09:09:32.515 INFO fn_a: just_print_it: 1-1=0 num=1 res=0 Dec 09 09:09:32.515 INFO fn_a:sub_one{value=0}: just_print_it: hello from sub_one Dec 09 09:09:32.515 ERROR fn_a:sub_one{value=0}: just_print_it: subtraction failed! Dec 09 09:09:32.515 INFO fn_a: just_print_it: 0-1=0 num=0 res=0
❯ RUST_LOG=info cargo run -p just-print-it Finished dev [unoptimized + debuginfo] target(s) in 0.02s Running `target/debug/just-print-it` Dec 09 09:11:39.232 INFO just_print_it: hello from main Dec 09 09:11:39.233 INFO fn_a: just_print_it: hello from fn_a Dec 09 09:11:39.233 INFO fn_a:decrement{value=2 secret=*******}: just_print_it: hello from sub_one Dec 09 09:11:39.233 INFO fn_a: just_print_it: 2-1=1 num=2 res=1 Dec 09 09:11:39.233 INFO fn_a:decrement{value=1 secret=*******}: just_print_it: hello from sub_one Dec 09 09:11:39.233 INFO fn_a: just_print_it: 1-1=0 num=1 res=0 Dec 09 09:11:39.233 INFO fn_a:decrement{value=0 secret=*******}: just_print_it: hello from sub_one Dec 09 09:11:39.233 ERROR fn_a:decrement{value=0 secret=*******}: just_print_it: subtraction failed! Dec 09 09:11:39.233 INFO fn_a: just_print_it: 0-1=0 num=0 res=0
{% term() %} {% end %}