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
andenv-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.toml
and 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_LOG
environment 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
- Include the tracing crate as a dependency
- Declare we wanted to use it
- 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