How to use the tracing library?

Question

I have a very simple code example here which just wants to get the first item of a list I pass in. I have been trying to instrument the code with tracing to help debug the application but frankly the documentation is too sophisticated for me to completely understand.

use std::fmt::Debug;
use tracing::{span, Level, event};

fn main() {
    pub fn calculate<T: Debug, const N: usize>(data_set: [T; N]) -> (i32, i32) {

        // Tracing BoilerPlate
        event!(Level::INFO, "something happened");
        let span = span!(Level::INFO, "my_span");
        let _guard = span.enter();
        
        // Key Code 
        let _var = data_set.get(0);
        println!("Output_1: {:?}", data_set.get(0)); 
        
        event!(Level::DEBUG, "something happened inside my_span");
        
        // Ignore
        return (0, 0)
    }

    let data = [1509, 1857, 1736, 1815, 1576];
    let _result = calculate(data);
}

Specifically here, I don't understand where I can view the event! logs. They don't seem to print out to any window or file or anything.

Can someone direct me as to where to find these debug logs or provide me with a simplified explanation of how to use the tracing crate?

Answer 1

Here is a basic implementation of tracing which outputs information to a log file (debug.log in repository root) and/or stdout (with more code) using the partner crate called tracing-subscriber

To find these tangible examples of how to bring tracing and tracing-subscriber together, you have to go very deep into the docs: go to the tracing-subscriber crate, then go to the Layer trait, then go to Module level documentation. Here is an alternative link.

frankly the documentation is too sophisticated for me to completely understand.

I'd argue there is significant work to be done for the documentation of these two crates. Objectively, it does not make it easy for beginners to understand what is happening. The docs describe the crate in highly sophisticated language but fail to properly teach newcomers the basics. More complete resources or quick start guides need to be created on this topic.

More simpler debugging tools are available which properly teach how you how to use it's crate. Flexi-logger provides a code examples documentation page which explains proficiently how to use the crate. Flexi-logger works in tandem with the Log crate to output log files as well as to stdout and stderr.

Here is the Tracing Implementation

use tracing_subscriber::{filter, prelude::*};
use std::{fs::File, sync::Arc};

// A layer that logs events to stdout using the human-readable "pretty"
// format.
fn main() {
    let stdout_log = tracing_subscriber::fmt::layer()
        .pretty();

    // A layer that logs events to a file.
    let file = File::create("debug.log");
    let file = match file  {Ok(file) => file,Err(error) => panic!("Error: {:?}",error),};
    let debug_log = tracing_subscriber::fmt::layer()
        .with_writer(Arc::new(file));

    // A layer that collects metrics using specific events.
    let metrics_layer = /* ... */ filter::LevelFilter::INFO;

    tracing_subscriber::registry()
        .with(
            stdout_log
                // Add an `INFO` filter to the stdout logging layer
                .with_filter(filter::LevelFilter::INFO)
                // Combine the filtered `stdout_log` layer with the
                // `debug_log` layer, producing a new `Layered` layer.
                .and_then(debug_log)
                // Add a filter to *both* layers that rejects spans and
                // events whose targets start with `metrics`.
                .with_filter(filter::filter_fn(|metadata| {
                    !metadata.target().starts_with("metrics")
                }))
        )
        .with(
            // Add a filter to the metrics label that *only* enables
            // events whose targets start with `metrics`.
            metrics_layer.with_filter(filter::filter_fn(|metadata| {
                metadata.target().starts_with("metrics")
            }))
        )
        .init();

    // This event will *only* be recorded by the metrics layer.
    tracing::info!(target: "metrics::cool_stuff_count", value = 42);

    // This event will only be seen by the debug log file layer:
    tracing::debug!("this is a message, and part of a system of messages");

    // This event will be seen by both the stdout log layer *and*
    // the debug log file layer, but not by the metrics layer.
    tracing::warn!("the message is a warning about danger!");

}

Answer 2

The tracing library itself does not display any output or write to any files. It is simply a facade that is designed to allow developers to fire events that are grouped into spans in an agnostic way that is separate from how those events and spans are handled. The library is complicated because there are a multitude of ways to track spans and consume events and they need to be supported in a lightweight infrastructure.

However, as a user you don't need to really worry about any of that. All you need to do is use the trace!, debug!, info!, warn!, error! and #[instrument] macros to describe what your code is doing. Then if you're writing a program that should do something with those events and spans, you should set up a Subscriber.

The simplest way to get up and running with logs printed to the console is using the basic formatting subscriber from the tracing-subscriber crate, and then you'll see events logged to the console:

use tracing::{info, debug};

#[tracing::instrument(ret)]
fn calculate(data_set: &[i32]) -> i32 {
    info!("starting calculations");

    let first = data_set.first();
    debug!("received {:?} as first element", first);
    
    let last = data_set.last();
    debug!("received {:?} as last element", last);

    first.unwrap_or(&0) + last.unwrap_or(&0)
}

fn main() {
    tracing_subscriber::fmt().init();

    // start running your code
    calculate(&[1509, 1857, 1736, 1815, 1576]);
}

2022-09-15T16:11:47.830218Z  INFO calculate{data_set=[1509, 1857, 1736, 1815, 1576]}: mycrate: starting calculations
2022-09-15T16:11:47.830545Z  INFO calculate{data_set=[1509, 1857, 1736, 1815, 1576]}: mycrate: return=3085

So fmt().init() can get you going in a hurry; it does the job of creating a Subscriber with a bunch of sensible defaults and registers itself as the global subscriber. It is very flexible too, you may note the output above doesn't include the debug! events, and you may not care about showing the crate name in every message. That can be configured:

tracing_subscriber::fmt()
    .with_max_level(tracing::Level::DEBUG)
    .with_target(false)
    .init();

2022-09-15T16:18:51.316695Z  INFO calculate{data_set=[1509, 1857, 1736, 1815, 1576]}: starting calculations
2022-09-15T16:18:51.316970Z DEBUG calculate{data_set=[1509, 1857, 1736, 1815, 1576]}: received Some(1509) as first element
2022-09-15T16:18:51.317214Z DEBUG calculate{data_set=[1509, 1857, 1736, 1815, 1576]}: received Some(1576) as last element
2022-09-15T16:18:51.317381Z  INFO calculate{data_set=[1509, 1857, 1736, 1815, 1576]}: return=3085

Everything is designed to be flexible: If you want to send to a file instead of stdout, there's .with_writer(). If you want to send logs to multiple locations, you can compose multiple subscribers with a Registry. If you want to filter only certain events based on their level, source, or content, there's .with_filter. If you want to log in a JSON format instead of human readable text, you can use .json().

A common next step would be to set up EnvFilter which would allow you to configure what events to log based on an environment variable instead of trying to configure it in-code. It can be as simple as "info"/"trace" to set a max level, or it could be complicated like "warn,mycrate=debug" (log debug events from my crate, only log warnings for anything else).

Beyond that, you're probably looking for something a bit more focused. Like you need to log in a specific format. Or you need to send events directly to an external provider. Or you're simply looking for a different way to view your data. Look in tracing's Related Crates section for other Subscribers that will hopefully suit your needs.