Rust logging and tracing.rs

February 10th, 2021: WIP

Let's take a dive into how to use the tracing.rs logging framework in a single-process application. There are some very good articles on this, such as the announcement post on the tokio blog Diagnostics with Tracing by Eliza Weisman, and Production-Grade Logging in Rust Applications by Ecky Putrady. You should also, if you have not done so already, watch Eliza's excellent presentation of tracing.rs at RustConf 2019.

These are great for getting started but tracing.rs has a lot of moving parts and we want to understand how they connect. In addition, I don't just want to show how certain things are done with tracing.rs, but also walk through the mental process and skills involved in learning and researching a Rust library.

Table of Contents:

• Logging and tracing.rs basics
• Starting out
• Logging levels
• Using tracing with the log and env-logger crates
• Beyond the tracing::fmt subscriber defaults
• Using the RUST_LOG environment variable
• Structured logging
• Using spans manually
• Using the #[tracing::instrument] attribute
• Using tracing-tree
• Using async
• Changing the filter at run-time
• Logging in a library
• Logging in an actix application
• Conclusions

Logging and tracing.rs basics

In case you haven't already read those articles, or don't have half a decade of caring for production systems serving network traffic, we'll go over some basic concepts, but if you've read them and seen the tracing documentation, you can skip this section.

As the documentation states:

tracing is a framework for instrumenting Rust programs to collect structured, event-based diagnostic information.

What does all this mean?

TODO: reiterate a summary of tracing's core concepts.

Starting out

We need a playground, so create a new binary create with cargo:

$ cargo new testapp
$ cd testapp

Edit your Cargo.tomland add the tracing dependency. As of January 2021, the latest version is 0.1.22.

$ cat Cargo.toml

...
[dependencies]
tracing = "0.1.22"

Edit your default src/main.rs file so that it looks like this:

use tracing;

fn main() {
    debug!("Hello, world!");
}

And now build and run:

$ cargo build
    Updating crates.io index
    ...
    Finished dev [unoptimized + debuginfo] target(s) in 9.36s
$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.07s
     Running `target/debug/testapp`

Nothing happened! This is because tracing, by itself, doesn't provide or say anything about how log events should be collected, processed, formatted, written to disk or sent over the network, nothing. That's a lot of design decisions which change depending on your logging needs, and in order to be flexible, tracing just provides an interface with which we can specify events and spans, and talk to subscribers which do all of the above.

TODO: WIP

The most basic logging, what would be functionally equivalent to using println!, would be to install a

To get some method of doing

Let's add the tracing-subscriber dependency to our Cargo.toml:

tracing-subscriber = "0.2.15"

We'll have to import it and call a function in main.rs:

use tracing::debug;
use tracing_subscriber;

fn main() {
    tracing_subscriber::fmt::init();
    debug!("Hello, world!");
}

$ cargo run

Still nothing! This is rather unfortunate, but what's happening is that we are the victims of our own doing, because we didn't quite read the documentation, did we? Let's go on over to docs.rs and search for the tracing_subscriber crate docs. If we type fmt::init in the search box, we get the result we wanted: the init function documentation.

Which state that this functions will:

Install a global tracing subscriber that listens for events and filters based
on the value of the RUST_LOG environment variable.
If the tracing-log feature is enabled, this will also install the LogTracer
to convert Log records into tracing Events.

So now we know that the subscriber we installed is controlled by the value of a RUST_LOGenvironment variable, which is a common way of specifying the logging level. Since we did not set it's value, and can assume that it will have a default value, we can theorize that perhaps if we did set it to some appropriate value, we would get output. It would be nice if these default values were documented.

$ RUST_LOG=debug cargo run
Jan 03 19:55:00.784 DEBUG testapp: Hello, world!

Aha! Finally some output

Logging levels

Great, so now we can emit information to the console as with println!, and we get some more stuff for our trouble: timestamps, the logging level, and nice colors. Let's see what else we can use.

tracing provides the trace, debug, info, warning, and error logging levels, which you can see in the Level documentation.

Let's edit our main.rs:

use tracing::{trace, debug, info, warn, error};
use tracing_subscriber;

fn main() {
    tracing_subscriber::fmt::init();
    trace!("trace");
    debug!("debug");
    info!("info");
    warn!("warn");
    error!("error");
}

% RUST_LOG=trace cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
     Running `target/debug/testapp`
Jan 03 20:13:55.633 TRACE testapp: trace
Jan 03 20:13:55.633 DEBUG testapp: debug
Jan 03 20:13:55.633  INFO testapp: info
Jan 03 20:13:55.633  WARN testapp: warn
Jan 03 20:13:55.633 ERROR testapp: error

% RUST_LOG=debug cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
     Running `target/debug/testapp`
Jan 03 20:13:55.633 DEBUG testapp: debug
Jan 03 20:13:55.633  INFO testapp: info
Jan 03 20:13:55.633  WARN testapp: warn
Jan 03 20:13:55.633 ERROR testapp: error

% RUST_LOG=info cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
     Running `target/debug/testapp`
Jan 03 20:13:55.633  INFO testapp: info
Jan 03 20:13:55.633  WARN testapp: warn
Jan 03 20:13:55.633 ERROR testapp: error

% RUST_LOG=warn cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
     Running `target/debug/testapp`
Jan 03 20:13:55.633  WARN testapp: warn
Jan 03 20:13:55.633 ERROR testapp: error

% RUST_LOG=error cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
     Running `target/debug/testapp`
Jan 03 20:13:55.633 ERROR testapp: error

Using tracing with the log and env-logger crates

So to recap so far, to get our logging we had to

1. Include the tracing crate as a dependency
2. Declare we wanted to use it
3. Install a subscriber to actually do something to the events we emit.

TODO: explain how to use env-logger instead of tracing-subscriber.

Beyond the tracing::fmt subscriber defaults

TODO: explain the defaults that fmt brings and how to change them

Using the RUST_LOG environment variable

TODO: explain env-loggers filtering syntax and tracing's extensions

Structured logging

TODO: explain how to include type-safe data in the log events.

Using spans manually

TODO: explain how to use manual spans and their use cases vs the instrument attribute.

Using the #[tracing::instrument] attribute

TODO: explain how to use the instrument attribute instead of doing it manually for functions.

Using tracing-tree

TODO: explain how to use the tracing-tree dependency and subcriber implementation to log execution traces in tree formats, for understanding code flow.

Using async

TODO

Changing the filter at run-time

TODO

Logging in a library

TODO

Logging in an actix application

TODO

Conclusions

TODO