Rust Tracing Instrument and Fields
#[instrument] is an attribute that gives each call to a function a span of its own. The function's arguments ride along as fields.
A span built by hand
Without the attribute, a function builds its own span and enters it by hand:
let span = info_span!("weigh", apples = 4);
let _guard = span.enter();
info!("weighing the bag");One word adds a span
The attribute wraps the call in a span named after the function. The argument becomes a field:
#[instrument]
fn weigh(apples: u32) -> u32 {Hide a secret with skip
The PIN never reaches the span. The field list shows amount only:
#[instrument(skip(pin))]
fn pay(amount: u32, pin: u32) -> bool {Fields carry facts, not sentences
Fields can ride on any event too. They print after the message. Each one stays a separate fact:
info!(label = %label, price = 250, "new stock arrived");Fill a field in later
Some values exist only after the span starts. Leave a hole with field::Empty. Fill it with record:
let span = info_span!("delivery", van = field::Empty);
let _g = span.enter();
span.record("van", "blue van");
info!("delivery started");Let the return value speak
ret adds a closing event with the return value. Its twin err does the same for an Err, at error level:
#[instrument(ret)]
fn add(a: i32, b: i32) -> i32 {
a + b
}Example
// Cargo.toml: tracing = "0.1" (resolved 0.1.44), tracing-subscriber = "0.3" (resolved 0.3.23)
use tracing::{field, info, info_span, instrument};
#[instrument]
fn weigh(apples: u32) -> u32 {
info!("weighing the bag");
apples * 150
}
#[instrument(skip(pin))]
fn pay(amount: u32, pin: u32) -> bool {
info!("taking payment");
amount > 0 && pin == 1234
}
#[instrument(fields(shop = "corner shop"))]
fn restock(shelf: &str) {
info!(shelf, "restock started");
}
#[instrument(ret)]
fn add(a: i32, b: i32) -> i32 {
a + b
}
#[instrument(err)]
fn open_till(code: u32) -> Result<(), String> {
if code == 0 {
return Err(String::from("wrong code"));
}
Ok(())
}
fn main() {
tracing_subscriber::fmt()
.with_max_level(tracing::Level::DEBUG)
.with_target(false)
.without_time()
.with_ansi(false)
.init();
let grams = weigh(4);
println!("bag weighs {grams} g");
pay(900, 1234);
restock("fruit");
add(2, 3);
let _ = open_till(0);
let label = String::from("fresh bread");
info!(label = %label, price = 250, "new stock arrived");
info!(label = ?label, "same label with debug quotes");
let span = info_span!("delivery", van = field::Empty);
let _g = span.enter();
span.record("van", "blue van");
info!("delivery started");
}Key points
- instrument: an attribute that wraps each call in a span named after the function, with the arguments as fields
- skip(name): keep an argument out of the span โ the place for passwords, PINs and tokens
- fields(...): add your own fields to the instrument span, on top of the arguments
- A plain field = value records with Debug.
- Write %value for Display, or ?value for Debug with quotes on text
- field::Empty leaves a named hole in a span.
- span.record fills the hole when the value arrives
In this example, five small functions show the five tricks of this lesson. weigh gets a plain instrument span, and its event carries apples=4. The println! line that follows is not an event. It holds no span, and it prints on stdout beside the events. pay skips its PIN, so only amount shows. restock adds a shop field of its own, and its shelf event repeats shelf as a field as well. add returns 5, and ret turns that into a return=5 event. open_till returns an Err, and err turns it into an ERROR event with the message as a field. The two label lines show the sigils side by side: % prints the text bare, ? prints it with quotes. The last span starts with a hole named van, and record fills it before the event fires.
Note
Arguments are recorded with Debug.
A type without Debug breaks the build until you skip it or record it by hand.
Try it Yourself
Edit the code, then press Run.
Running is simulated ยท Rust Playground
Exercise
A function takes a password argument. You add #[instrument] and nothing else. What happens to the password?