Tracing Crate, an Introduction
tracing crate provides an API to record log messages. When considering what kind of labels to log with the messages, I recommend you take into consideration the importance of omitting sensitive information from the long term storage. If I was an infiltrator in your network, one of the first prizes I'd look the learn more about your network is DNS. The second most valuable prize on your network is a SIEM
UUIDs offer a natural obfuscation for your labels as they're generally randomly generated or can be constructed to mean something defined somewhere the SIEM doesn't have access to. Additionally you could correlate the UUIDs with primary keys in a database
Let's get into it with example followed up by description of what's going on
#[instrument(name="operate", skip(_option))]
pub async fn operate_pepper(_option: PepperOption) -> Result<(), PepperError> {
tracing::info!("Hello, World");
Ok(())
}
instrument
had two parameters passed into it. name
which creates then enters a span and skip
which tells which method or function parameters to not include in fields. trace level could also be set, but probably isn't necessary because we'll primarily be using tracing::info!
. In the function body of operate_pepper
a single log message is recorded: Hello, World
A single log message is fairly straightforward. I could have used println!
, but that would lock up the execution of the program. Reason being, stdout is a globally shared resource. tracing
however doesn't have a semaphore to a single resource, which makes it ideal for concurrent programs. It does have some interesting design patterns around atomics which provides an interesting read
Let's take a look at a program with some concurrency
#[instrument(name="sitemap", skip(_option))]
pub async fn operate_sitemap(_option: SitemapOption) -> Result<(), SitemapError> {
let mut join_set = JoinSet::new();
for idx in 0..10 {
join_set.spawn(async move {
tracing::info!("Task {idx}");
}.instrument(tracing::info_span!("Spawned", idx=&idx)));
}
tracing::info!("SiteMap Hello World");
let _ = join_set.join_all().await;
Ok(())
}
There is quite a bit going on in the above example. Creating a JoinSet takes care of scheduling the Tokio Tasks. A closure is used to create a 'static
lifetime for the task compatible with Tokio's Spawning API. The async
keyword should be intuitive enough to omit immediate explanation. move
is used to move idx
into the spawned thread which is than rendered in a log message using info!
. Finally attach a new info_span! using the extension trait instrument
along with adding idx
field to capture program state
INFO sitemap: sitemap::opt: SiteMap Hello World
INFO sitemap:Spawned{idx=4}: sitemap::opt: Task 4
INFO sitemap:Spawned{idx=6}: sitemap::opt: Task 6
INFO sitemap:Spawned{idx=3}: sitemap::opt: Task 3
INFO sitemap:Spawned{idx=8}: sitemap::opt: Task 8
INFO sitemap:Spawned{idx=7}: sitemap::opt: Task 7
INFO sitemap:Spawned{idx=0}: sitemap::opt: Task 0
INFO sitemap:Spawned{idx=2}: sitemap::opt: Task 2
INFO sitemap:Spawned{idx=5}: sitemap::opt: Task 5
INFO sitemap:Spawned{idx=9}: sitemap::opt: Task 9
INFO sitemap:Spawned{idx=1}: sitemap::opt: Task 1
Fairly intuitive once you develop a feeling for the tracing API