Tracing

The slides for this workshop can be found here: https://docs.google.com/presentation/d/1YvQUVijlscxucTafr7l7fog6JISXZnYxnJq_jZ-mMHI/edit#slide=id.g13e3b087794_0_2

There are also runnable code examples found here:

https://gitlab.ii.zone/lukas.hozda/workshop-tracing

As mentioned in the previous workshop, tracing is our framework of choice for our logging needs. In this text, we will look over the major concepts of tracing you are likely to encounter when developing applications at Braiins.

First of,

the documentation of the tracing crate can be found here: https://docs.rs/tracing/0.1.37/tracing/

and the source code is here: https://github.com/tokio-rs/tracing

Tracing is a part of the Tokio project and it was originally released under the name tokio-trace, so you may find references to it under this name as well. If you watch the talk about the framework's release, you will find that the authors really dislike calling it a logging library.

According to the official documentation, tracing is a framework for instrumenting Rust programs to collect structured, event-based diagnostic information. While tracing is part of the Tokio project, and is async-aware, it is not async-exclusive, nor does it require the Tokio runtime. Tracing can be used in any library or application regardless of if it is async or not.

The equivalent of log messages are called events in tracing, and each event might be a part of one or more spans. Processing of the logging messages is decoupled from their production, and on the processing/collecting side, you compose layers to form a subscriber.

Events

Events are structured records representing a point in time. Generally, you will produce them using macro shorthands, but technically speaking, you can produce them directly too. This will be rarely useful though.

The basic syntax of creating an event is as such:

#![allow(unused)]
fn main() {
use tracing::{event, Level};

event!(Level::INFO, "hello, Braiins!");
}

Shorthands that you may be used to from other logging crates are available too, and are typically the main tool developers use to create events:

#![allow(unused)]
fn main() {
use tracing::*;

debug!("This is a debug message");
info!("This is a info message");
error!("This is a error message");
warn!("This is a warn message");
trace!("This is a trace message");
}

While you often see these used with string messages, events are structured, and you can log any data that implements the tracing::Value trait, or Debug, or Display.

#![allow(unused)]
fn main() {
debug!(first_name = "Franta", middle_name = "Pepa", surname = "Jednička");
}

For types that only implement Display and/or Debug, you choose by using either the ? symbol in front of the value for Debug, or the % symbol for Display.

For example:

#![allow(unused)]
fn main() {
use std::fmt;

#[derive(Debug)]
struct TestStruct;

impl fmt::Display for TestStruct {
    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
        write!(f, "TestStruct but via Display")
    }
}

info!(
    test_debug = ?TestStruct, // -> prints test_debug = TestStruct
    test_display = %TestStruct, // -> prints test_display = TestStruct but via Display
);
}

Of course, you can combine it:

#![allow(unused)]
fn main() {
info!("This is a message with a funny number attached", funny_number = 420);
}

The macros support all of the syntax you know from format_args!() macros, such as println!, writeln!, eprint!, and so on, and they also support all of the features of the log facade crate macros. For example:

#![allow(unused)]
fn main() {
trace!(
    "inserting values into message with {}, like in println!()",
    "brackets"
);
}

Spans

Spans represent a time range. Every span has a beginning and end, which is tracked by tracing. Each span can be entered and exited multiple times during their existence.

Just like events, spans have a Level. The level of a span is independent from the level of an event, and if the currently displayed level of a span is lower than the enabled ones, it's info won't be attached to the event.

You can create spans similarly to how you can create events, using the appropriate macro:

#![allow(unused)]
fn main() {
let my_span = span!(Level::INFO, "name_of_span", attached_data = 4);
}

You can also use shorthand macros for each level:

#![allow(unused)]
fn main() {
let my_span = info_span!("name_of_span", attached_data = 4);
}

Like this, the span isn't good for anything, and it either has to be entered, or statements must be executed in scope:

#![allow(unused)]
fn main() {
let _guard = my_span.enter();

info!("this event has my span attached");
}

or:

#![allow(unused)]
fn main() {
my_span.in_scope(|| {
    info!("this event has my span attached");
});
}

Spans form a tree, by default, every new span inherits the current span as a parent. This lets you attach increasingly specific contenxtual information without having to push it inside functions if you don't need it for anything else than logging the information.

If you want to break the span tree for any reason, you can do so by overriding the parent property:

#![allow(unused)]
fn main() {
let new_root_span = info_span!(parent: None, "new_root_span");
}

As previously mentioned, tracing is async-aware, so spans are entered and exited as the async runtime schedules task. It also means that you can instrument futures with spans:

#![allow(unused)]
fn main() {
use tracing_futures::Instrument;

let my_future = async { info!("hello, world")! };
let my_span = debug_span!("hello");

let my_future_instrumented = my_future.instrument(my_span);

my_future_instrumented.await; // will print with span attached
}

Spans can also be used to filter images you are interested in, therefore they are great for attaching information such as task / user / etc IDs you may want to filter on, as opposed to shoving them into every event message.

The authors of tracing proclaim that if you ever need to grep through tracing output, you are using tracing wrong. While that is most certainly hyperbole, it can't be denied that the filtering features are powerful enough to fit most use cases. We will take a look at how to do this when discussing the Fmt layer and subscriber.

Lastly, functions can be instrumented with spans too using the #[instrument(name = <name>, ...)] attribute.

For example:

#![allow(unused)]
fn main() {
#[instrument(name = "cokoliv", fields(id = id))]
fn instrumented_fn(id: i32) {
    info!("hello {id}");
}
}

It stands to reason that you may want to include data in span that's not immediately available. You can use the .record method on a span, to record the value of a particular field. This can also be used in case that a span field already has a value, but you want to change the value.

Subscribers and layers

Now we are getting to the subcriber and layer part. Setting up a subscriber is the job of the application, not the library, just like it is with most logging frameworks.

In the simplest form, you can just take the basic Fmt subscriber and go with it:

#![allow(unused)]
fn main() {
tracing_subscriber::fmt().init();
}

You may also choose to use less shorthand, more verbose variant:

#![allow(unused)]
fn main() {
let subscriber = tracing_subscriber::FmtSubscriber::new();
tracing::subscriber::set_global_default(subscriber)?;
}

This is all that is necessary to initialize it. As you can see from the code snippet, subscribers live in different crates from the main tracing one so that you don't have to import them into your libraries unnecesarily.

The subscriber we just created is pretty stupid, for lack of a better word, and will display all events and spans with the default formatting to stdout, regardless of any environment variables, and thus you can't filter through it. However, it will still respect the rules set forth by the tracing crate regarding which tracing levels should be compiled in. You can check the tracing crate manifest for the current set of these compile-time level-limiting features.

If we want to be able to control tracing levels and filter based on other things, we need to include the env filter.

You can do it simply like this:

#![allow(unused)]
fn main() {
tracing_subscriber::registry()
    .with(tracing_subscriber::fmt::layer())
    .with(tracing_subscriber::EnvFilter::from_default_env())
    .init();
}

This uses the tracing_subscriber registry to compose a slightly more involved subscriber, which uses a filtering layer on top of the fmt layer. Layers can write into a multitude of things, you may find layers that write events into ELK, honeycomb, Grafana Loki, the network, HTTP server, or others, but also can pass messages onto other layers and change filter settings, which is what the EnvFilter layer essentially does.

Subscribers can be compared to tower services and layers to tower Layers, in that they have similar semantics, just that tracing composes a logger and tower a generic service.

Here is an example, which uses the tracing_appender crate to create a non-blocking hourly log rotate:

#![allow(unused)]
fn main() {
let env_filter = EnvFilter::try_from_default_env()
    .unwrap_or_else(|_| EnvFilter::default().add_directive(Level::INFO.into()));

let stdio_layer = tracing_subscriber::fmt::layer().with_filter(env_filter);

let file_appender = tracing_appender::rolling::hourly(".", "prefix.log");
let (writer, _lock) = tracing_appender::non_blocking(file_appender);
let file_layer = tracing_subscriber::fmt::layer().with_writer(writer.make_writer());

tracing_subscriber::registry()
    .with(stdio_layer)
    .with(file_layer)
    .init();

trace!("test trace");
info!("test info");
debug!("test debug");
error!("test error");
}

If you were to run this snippet, you would see that the file contains all of the log messages, but the stdio output only by default shows INFO level and higher.

For inspiration, you can find the subscriber we use in bosminer here: https://gitlab.ii.zone/pool/bos-main/-/blob/master/open/bosminer/bosminer/src/lib.rs#L170-206

You can filter on the command line using the RUST_LOG variable, by specifying levels (ranging from trace to off) for particcular code paths or span-based filters:

#![allow(unused)]
fn main() {
env RUST_LOG="[cokoliv{id=2}]=off,trace" cargo run
}

Try this in the span-demo example from the example repo. It will show all messages except messages with the cokoliv span, if the span field of id equals 2.

The full syntax is documented here: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html