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