Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

Logging

Getting started with logging in Rust

Mastering logging can help you save a lot of time both during development and later when there are problems in production.

  • log
  • trace!
  • debug!
  • info!
  • warn!
  • error!
  • simple_logger
  • init_with_env

One of the ancient debugging techniques is adding print-statements to the code, running the code and observing which part of the code is executed and what are the values of various variables. The big problem with this is that once the issue was fixed we need to remove, or at least comment-out the print statements.

Then, when we encounter a new issue we will have to add back or re-enable the print-statements. A lot of waste of time.

In addition, we don't have any of the print statements while the code is in production.

What is Logging

Logging is a simple technique that helps solving this problem. Basically we add conditional print-statements to the code that we can then enable or disable externally. It goes beyond that simple on/off. In logging we can also control the verbosity of the program. In logging have levels and we can control which levels are printed. So we can have debug! messages that contain a lot of very detailed information. We can have info! messages with more high-level information. We can also have warn! or error! messages that would give warnings or report errors.

The levels are in this order:

  • error!
  • warn!
  • info!
  • debug!
  • trace!

Besides controlling which level of messages to print, in logging we can also control where to print them. On the screen? In a file? Into a database? etc.

Add log messages

The logging system in Rust has two major parts. One part is implemented in the log crate. It provides the macros that you can use to embed the logging statements in your code. For this you need to add the log crate to your code either by running

cargo add log

or by editing the Cargo.toml file and adding the dependency manually:

[dependencies]
log = "0.4"

Of course by the time you read this, there might be a newer version of the crate, so set the number accordingly.

Then we can add the logging calls to our code in the src/main.rs file.

We can either use the full name of the macros:

#![allow(unused)]
fn main() {
log::trace!("This is a sample trace.");
log::debug!("This is a sample debug.");
log::info!("This is a sample info.");
log::warn!("This is a sample warn.");
log::error!("This is a sample error.");
}

Or we can import the necessary macro:

#![allow(unused)]
fn main() {
use log::error;
}

Or the necessary macros, if we need more of them:

#![allow(unused)]
fn main() {
use log::{debug, info};
}

Then we can use the short name of the macros that we have imported:

debug!("Another debug.");
info!("Another info.");
error!("Another error.");

Now we can run our program

cargo run

and we will see that "nothing happens". More precisely, we'll see the "Hello, world!" on the screen, but none of the logging statements.

That's because we still need to add a logger implementation. Several of these implementations are mentioned on the page about the log crate.

The code with log only

[package]
name = "log-demo"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
log = "0.4"

use log::error;
use log::{debug, info};

fn main() {
    println!("Hello, world!");

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");

    debug!("Another debug.");
    info!("Another info.");
    error!("Another error.");
}

Simple logger

Add the simple_logger by running:

cargo add simple_logger

or by manually editing the Cargo.toml file to include both log and simple_logger.

[dependencies]
log = "0.4"
simple_logger = "4.3"

Also edit the src/main.rs file and add

#![allow(unused)]
fn main() {
simple_logger::SimpleLogger::new().init().unwrap();
}

as the first statement of the main function.

If we run

cargo run

again we get the following output:

Hello, world!
2023-12-04T07:42:02.858Z TRACE [simple_log_demo] This is a sample trace.
2023-12-04T07:42:02.858Z DEBUG [simple_log_demo] This is a sample debug.
2023-12-04T07:42:02.858Z INFO  [simple_log_demo] This is a sample info.
2023-12-04T07:42:02.858Z WARN  [simple_log_demo] This is a sample warn.
2023-12-04T07:42:02.858Z ERROR [simple_log_demo] This is a sample error.
2023-12-04T07:42:02.858Z DEBUG [simple_log_demo] Another debug.
2023-12-04T07:42:02.858Z INFO  [simple_log_demo] Another info.
2023-12-04T07:42:02.858Z ERROR [simple_log_demo] Another error.

In each line we can see the time of logging, the logging level in capital letters (TRACE, DEBUG, etc.) then the name of our crate (I used a crate called simple_log_demo for this example) and then the actual logging message.

If your terminal supports colors then each one of the capitalized logging levels will have a different color.

By default all the lines are printed to Standard Output (STDOUT) together with the regular output of the code. This is usually not very good as it does not allow the user to separately redirect the regular output and the logging messages, but this is the default.

Change the output to STDERR

We can enable the stderr feature by changing the Cargo.toml to include

simple_logger = { version = "4.3", features = ["stderr"] }

Running cargo run we won't see a difference, but we can now redirect the logging to a file:

cargo run 2> log.txt

This will only print "Hello, world!". All the logging messages were saved in the "log.txt" file.

Set the minimum logging level

In the src/main.rs file we can replace the code that initialized the simple_logger by this line:

#![allow(unused)]
fn main() {
simple_logger::init_with_level(log::Level::Warn).unwrap();
}

This too will initialized the simple_logger, but will set the minimum logging level to be warnings. This means that every log message of warning and higher (that is error) will be printed. The lower level messages won't.

This is what we'll see:

Hello, world!
2023-12-04T08:04:53.482Z WARN  [simple_log_demo] This is a sample warn.
2023-12-04T08:04:53.482Z ERROR [simple_log_demo] This is a sample error.
2023-12-04T08:04:53.482Z ERROR [simple_log_demo] Another error.

Setting the minimum level hard-coded in the code is not really ideal. Luckily there are alternatives:

Set the minimum using environment variables

Simple logger provides another way to initialize the logging level using an environment variable.

For this we need to replace the line that initializes the logger with this line:

#![allow(unused)]
fn main() {
simple_logger::init_with_env().unwrap();
}

Then we can set the minimum level using the RUST_LOG environment variable.

On Linux and macOS this would set the minimum log level to warning:

RUST_LOG=warn cargo run

On Windows you need to write this:

set RUST_LOG=warn
cargo run

Set minimum level as a command line option

For some reason setting the minimum level with an environment variable feels strange. I think this is especially the case when the application starts to have a number of command line parameters. Then it feels more natural to provide the log level too as a command line parameter. So I add a little function that can help me do this.

The initialization code now looks like this:

#![allow(unused)]
fn main() {
simple_logger::init_with_level(get_log_level()).unwrap();
}

and the get_log_level function looks like this:

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

fn get_log_level() -> log::Level {
    log::Level::from_str(
        std::env::args()
            .collect::<Vec<String>>()
            .get(1)
            .unwrap_or(&String::from("trace"))
            .to_lowercase()
            .as_str(),
    )
    .unwrap_or(log::Level::Trace)
}
}

Now we can run the code using

cargo run

and get trace-level logging or we can run using

cargo run warn

and we get warnings and errors.

How to implement something similar with clap is left as an exercise for the reader.

The code with several cases

[package]
name = "simple-log-demo"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
log = "0.4"
simple_logger = { version = "4.3", features = ["stderr"] }

use log::error;
use log::{debug, info};

fn main() {
    // Default initialization, all the log levels.
    // simple_logger::SimpleLogger::new().init().unwrap();

    // Set the log level inside the code.
    // simple_logger::init_with_level(log::Level::Warn).unwrap();

    // Allow the user to set the log level as an environment variable:
    // RUST_LOG=warn
    // simple_logger::init_with_env().unwrap();

    // Allow the user to provide the log level on the command line:
    // crate run warn
    simple_logger::init_with_level(get_log_level()).unwrap();

    println!("Hello, world!");

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");

    debug!("Another debug.");
    info!("Another info.");
    error!("Another error.");
}

use std::str::FromStr;

fn get_log_level() -> log::Level {
    log::Level::from_str(
        std::env::args()
            .collect::<Vec<String>>()
            .get(1)
            .unwrap_or(&String::from("trace"))
            .to_lowercase()
            .as_str(),
    )
    .unwrap_or(log::Level::Trace)
}

Conclusion

There are tons of other things we need to know in order to take full advantage of logging, but this can already get you started.

A few things I'll need to address:

  • How to allow the user to save the log messages to a file - without the need for redirection?
  • How to focus the logging on a given crate? Many of the crates we use might have log messages, but when we focus on our code we probably only want to see the log messages from our crate. Or maybe we would want to have trace-level logging from our crate, and warn-level logging from other crates.
  • How to change the format of the log messages? For example to include the filename and the line number where the log was created.

Simple Logger new

Simple Logger new

In order to use the simple_logger crate we need to add that and log to Cargo.toml

[package]
name = "simple_logger_new"
version = "0.1.0"
edition = "2021"

[dependencies]
log = "0.4.22"
simple_logger = "5.0.0"

fn main() {
    simple_logger::SimpleLogger::new().init().unwrap();

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");
}

By default it print out all the log levels.

2024-08-04T12:13:57.055Z TRACE [simple_logger_new] This is a sample trace.
2024-08-04T12:13:57.055Z DEBUG [simple_logger_new] This is a sample debug.
2024-08-04T12:13:57.055Z INFO  [simple_logger_new] This is a sample info.
2024-08-04T12:13:57.055Z WARN  [simple_logger_new] This is a sample warn.
2024-08-04T12:13:57.055Z ERROR [simple_logger_new] This is a sample error.

Simple Logger init

We can write a bit less calling init directly.

[package]
name = "simple_logger_init"
version = "0.1.0"
edition = "2021"

[dependencies]
simple_logger = "4.2"
log = "0.4"

fn main() {
    simple_logger::init().unwrap();

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");
}
2024-08-04T12:09:32.085Z TRACE [simple_logger_init] This is a sample trace.
2024-08-04T12:09:32.085Z DEBUG [simple_logger_init] This is a sample debug.
2024-08-04T12:09:32.085Z INFO  [simple_logger_init] This is a sample info.
2024-08-04T12:09:32.085Z WARN  [simple_logger_init] This is a sample warn.
2024-08-04T12:09:32.085Z ERROR [simple_logger_init] This is a sample error.

Simple Logger set the level manually

Using the init_with_level function we can set the log level manually.

[package]
name = "simple_logger_init_with_level"
version = "0.1.0"
edition = "2021"

[dependencies]
log = "0.4.22"
simple_logger = "5.0.0"

fn main() {
    simple_logger::init_with_level(log::Level::Info).unwrap();

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");
}
2024-08-04T12:12:25.438Z INFO  [simple_logger_init_with_level] This is a sample info.
2024-08-04T12:12:25.438Z WARN  [simple_logger_init_with_level] This is a sample warn.
2024-08-04T12:12:25.438Z ERROR [simple_logger_init_with_level] This is a sample error.

Logging with log4rs

Dependencies

[package]
name = "try-log4rs"
version = "0.1.0"
edition = "2021"

[dependencies]
log = "0.4.22"
log4rs = "1.3.0"

The code:

fn main() {
    log4rs::init_file("log4rs.yaml", Default::default()).unwrap();

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");

    tools::do_something();
}

mod tools {
    pub fn do_something() {
        log::trace!("do_something trace.");
        log::debug!("do_something debug.");
        log::info!("do_something info.");
        log::warn!("do_something warn.");
        log::error!("do_something error.");
    }
}

The configuration

appenders:
  stdout:
    kind: console
  all:
    kind: file
    path: "all.log"
    encoder:
      pattern: "{d} - {l} {f}:{L} {m}{n}"

root:
  level: debug
  appenders:
    - stdout

loggers:
   try_log4rs::tools:
     level: trace
     appenders:
       - all

Standard output:

2024-08-11T12:13:17.484418418+03:00 DEBUG try_log4rs - This is a sample debug.
2024-08-11T12:13:17.484549182+03:00 INFO try_log4rs - This is a sample info.
2024-08-11T12:13:17.484559672+03:00 WARN try_log4rs - This is a sample warn.
2024-08-11T12:13:17.484566695+03:00 ERROR try_log4rs - This is a sample error.
2024-08-11T12:13:17.484595188+03:00 TRACE try_log4rs::tools - do_something trace.
2024-08-11T12:13:17.484609084+03:00 DEBUG try_log4rs::tools - do_something debug.
2024-08-11T12:13:17.484620947+03:00 INFO try_log4rs::tools - do_something info.
2024-08-11T12:13:17.484632638+03:00 WARN try_log4rs::tools - do_something warn.
2024-08-11T12:13:17.484644481+03:00 ERROR try_log4rs::tools - do_something error.

The all.log file:

2024-08-11T12:13:17.484581753+03:00 - TRACE src/main.rs:16 do_something trace.
2024-08-11T12:13:17.484603574+03:00 - DEBUG src/main.rs:17 do_something debug.
2024-08-11T12:13:17.484615887+03:00 - INFO src/main.rs:18 do_something info.
2024-08-11T12:13:17.484627539+03:00 - WARN src/main.rs:19 do_something warn.
2024-08-11T12:13:17.484639321+03:00 - ERROR src/main.rs:20 do_something error.

env_logger

env-logger

Simple use of env_logger

[package]
name = "env-logger-demo"
version = "0.1.0"
edition = "2024"

[dependencies]
env_logger = "0.11.8"
log = "0.4.27"


fn main() {
    env_logger::init();

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");
}

By default this sets the log-level to ERROR so if we run the code we get a single log:

$ cargo run

[2025-04-26T04:59:00Z ERROR env_logger_demo] This is a sample error.

The user can control the level of the logging by setting the RUST_LOG environment variable.

On Linux and macOS you can do it this way:

$ RUST_LOG=trace cargo run

[2025-04-26T04:59:57Z TRACE env_logger_demo] This is a sample trace.
[2025-04-26T04:59:57Z DEBUG env_logger_demo] This is a sample debug.
[2025-04-26T04:59:57Z INFO  env_logger_demo] This is a sample info.
[2025-04-26T04:59:57Z WARN  env_logger_demo] This is a sample warn.
[2025-04-26T04:59:57Z ERROR env_logger_demo] This is a sample error.

In Windows in CMD

> set RUST_LOG=trace

In PowerShell

> [Environment]::SetEnvironmentVariable("RUST_LOG", "trace", "Process")

env_logger with Builder

Using the env_logger::Builder we can define the formatting of each log-line.

We can also set the default log-level, if the user does not set one via the RUST_LOG environment variable.

[package]
name = "env-logger-builder"
version = "0.1.0"
edition = "2024"

[dependencies]
chrono = "0.4.40"
env_logger = "0.11.8"
log = "0.4.27"

use std::io::Write;
use std::env;

use env_logger::Builder;
use chrono::Local;

fn main() {
    init_logger();

    log::trace!("This is a sample trace.");
    log::debug!("This is a sample debug.");
    log::info!("This is a sample info.");
    log::warn!("This is a sample warn.");
    log::error!("This is a sample error.");
}

fn init_logger() {
    let mut builder = Builder::new();

    builder.format(|formatter, record| {
        writeln!(
            formatter,
            "{} [{}] ({}): {}",
            Local::now().format("%Y-%m-%d %H:%M:%S"),
            record.level(),
            record.target(),
            record.args()
        )
    });
    let log_level = env::var("RUST_LOG").unwrap_or(String::from("info"));
    builder.parse_filters(&log_level);

    builder.init();
}

Tracing

Tracing demo

  • trace
  • tracing
  • tracing-subscriber
[package]
name = "demo"
version = "0.1.0"
edition = "2024"

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3.0"

use tracing::{Level, debug, info};
use tracing_subscriber::FmtSubscriber;

fn main() {
    // Set up a tracing subscriber that logs to stdout.
    let subscriber = FmtSubscriber::builder()
        .with_max_level(Level::TRACE)
        .finish();
    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

    // Emit some log messages.
    info!("hello world");

    let number_of_yaks = 3;
    debug!(number_of_yaks, "preparing to shave yaks");
}

Tracing in a library

[package]
name = "demo-lib"
version = "0.1.0"
edition = "2024"

[dependencies]
tracing = "0.1"

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

pub fn add(left: u64, right: u64) -> u64 {
    debug!(left, right, "add");
    left + right
}

#[cfg(test)]
mod tests {
    use super::*;

    #[test]
    fn it_works() {
        let result = add(2, 2);
        assert_eq!(result, 4);
    }
}
}

Tracing in an application

[package]
name = "demo-application"
version = "0.1.0"
edition = "2024"

[dependencies]
demo-lib = { version = "0.1.0", path = "../demo-lib" }
tracing = "0.1"
tracing-subscriber = "0.3.0"

use demo_lib::add;
use tracing::{Level, info};
use tracing_subscriber::FmtSubscriber;

fn main() {
    // Set up a tracing subscriber that logs to stdout.
    let subscriber = FmtSubscriber::builder()
        .with_max_level(Level::TRACE)
        .finish();
    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

    info!("Before");

    add(2, 3);

    info!("after");
}

Simple tracing configuration with RUST_LOG environment variable

[package]
name = "demo-rust-log-env"
version = "0.1.0"
edition = "2024"

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3.0"

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

fn main() {
    // Set up a tracing subscriber that logs to stdout.
    // User RUST_LOG to control the logging level.
    // RUST_LOG=trace
    // RUST_LOG=error
    tracing_subscriber::fmt::init();

    // Emit some log messages.
    trace!("trace");
    debug!("debug");
    info!("info");
    warn!("warn");
    error!("error");
}