Logging

This chapter wouldn't be complete if we did not talk about logging. Logging is an important part of any application. It allows you to track the behavior of your application and diagnose problems when they occur. The de facto logging library in Rust is log. The log crate provides a logging interface that allows you to write log messages using any logging implementation.

These are a few of the most popular logging implementations:

  • env_logger: A simple logger that reads the RUST_LOG environment variable.
  • pretty_env_logger: A prettier logger that reads the RUST_LOG environment variable.
  • slog: A structured logger that allows you to create custom loggers.
  • simple_logger: A simple logger that logs to stdout.
  • fern: A feature-rich logger that allows you to configure log levels and output.

In this chapter, we'll use env_logger as it is really easy to set up and use. To use env_logger, add it to your Cargo.toml file:

[dependencies]
log = "0.4"
env_logger = "0.11"

Let's create a simple logger in our application. First, we need to initialize the logger in our main function:

fn main() {
    env_logger::init();
    log::info!("Hello, world!");
}

Interestingly, there is no output if you run the above code. This is because the env_logger reads the RUST_LOG environment variable by default to determine the log level. To see the log messages, you need to set the RUST_LOG environment variable to info:

$ RUST_LOG=info cargo run

env_logger::init() must be called before any log messages are written. If you call env_logger::init() after writing log messages, the log messages will be ignored.

Log levels

The log crate provides several log levels:

  • trace
  • debug
  • info
  • warn
  • error

You can set the log level by setting the RUST_LOG environment variable to the desired log level. For example, to see info and higher log messages, set the RUST_LOG environment variable to info:

Useful logging

Logging is a powerful tool for debugging and diagnosing problems in your application. Here are a few tips to help you make the most of logging:

  • Use debug! for debug messages that are useful for tracking the behavior of your application during development.
  • Use info! for informational messages that are useful for tracking the behavior of your application.
  • Use warn! for warning messages that indicate potential, but recoverable, problems in your application.
  • Use error! for error messages that indicate problems that are not recoverable and need to be addressed.

One of the biggest mistakes developers make is designing log messages with low volume and single threading in mind. Once such an application is deployed in a production environment and the volume increases and multiple threads are writing logs simultaneously, the log messages become little more than noise. Log message must have context and be actionable.

Here's an example of a simple application that logs messages to the console:

use std::thread;

use log::{info, warn};

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

    thread::scope(|s| {
        for i in 0..10 {
            s.spawn(move || fake_database_operation(i));
        }
    });
}

fn fake_database_operation(_account_number: i32) {
    info!("Reading account record from database");

    // randomly sleep up to 0.5 seconds
    let sleep_duration = std::time::Duration::from_millis((rand::random::<f64>() * 500.0) as u64);
    thread::sleep(sleep_duration);

    if sleep_duration.as_millis() > 400 {
        warn!("Timeout reading account record from database");
        return;
    } else {
        info!("Successfully read account record from database");
    }

    info!("Updating account record in database");

    // fail 50% of the time
    if rand::random::<f64>() > 0.5 {
        warn!("Failed to update account record in database; record locked");
    } else {
        info!("Successfully updated account record in database");
    }
}

This code spawns 10 threads, each of which simulates reading and updating an account record in a database. The log messages indicate when the account record is read, when it is updated, and when there is a timeout or an update failure. The code will randomly fail with a timeout or a record-locked error.

While at first glance this code seems to have good logging, let's take a look at the output to see if it's actually useful.

Here's a potential output.

[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Reading account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Successfully read account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Updating account record in database
[2024-03-29T11:07:11Z INFO  logging_example] Successfully updated account record in database
[2024-03-29T11:07:11Z INFO  logging_example] Successfully read account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Updating account record in database
[2024-03-29T11:07:11Z INFO  logging_example] Successfully updated account record in database
[2024-03-29T11:07:11Z INFO  logging_example] Successfully read account record from database
[2024-03-29T11:07:11Z INFO  logging_example] Updating account record in database
[2024-03-29T11:07:11Z WARN  logging_example] Failed to update account record in database; record locked
[2024-03-29T11:07:12Z INFO  logging_example] Successfully read account record from database
[2024-03-29T11:07:12Z INFO  logging_example] Updating account record in database
[2024-03-29T11:07:12Z INFO  logging_example] Successfully updated account record in database
[2024-03-29T11:07:12Z INFO  logging_example] Successfully read account record from database
[2024-03-29T11:07:12Z INFO  logging_example] Updating account record in database
[2024-03-29T11:07:12Z WARN  logging_example] Failed to update account record in database; record locked
[2024-03-29T11:07:12Z WARN  logging_example] Timeout reading account record from database
[2024-03-29T11:07:12Z WARN  logging_example] Timeout reading account record from database
[2024-03-29T11:07:12Z WARN  logging_example] Timeout reading account record from database
[2024-03-29T11:07:12Z WARN  logging_example] Timeout reading account record from database
[2024-03-29T11:07:12Z WARN  logging_example] Timeout reading account record from database

So what's wrong with this output? The log messages are not very useful. They don't provide any context or actionable information. Based on the log, there is no way of telling what account record is being read or updated. Is one operation causing the other to fail? Is there a pattern to the failures? Are the failures related to the same account record? These are all questions that the log messages should answer.

Here's an improved version of the code that logs more useful information:

use std::thread;

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

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

    thread::scope(|s| {
        for i in 0..10 {
            s.spawn(move || fake_database_operation(i));
        }
    });
}

fn fake_database_operation(account_number: i32) {
    let start_time = std::time::Instant::now();
    info!("Reading account record from database for account number {account_number}");

    // randomly sleep up to 0.5 seconds
    let sleep_duration = std::time::Duration::from_millis((rand::random::<f64>() * 500.0) as u64);
    thread::sleep(sleep_duration);

    let elapsed_time = start_time.elapsed().as_millis();
    if sleep_duration.as_millis() > 400 {
        warn!("Timeout reading account record from database for account number {account_number}; operation took {elapsed_time} ms");
        return;
    } else {
        info!("Successfully read account record from database for account number {account_number}; operation took {elapsed_time} ms");
    }

    info!("Updating account record in database for account number {account_number}");

    // fail 50% of the time
    if rand::random::<f64>() > 0.5 {
        warn!("Failed to update account record in database for account number {account_number}; record locked");
    } else {
        info!("Successfully updated account record in database for account number {account_number}");
    }

    let elapsed_time = start_time.elapsed().as_millis();
    debug!("fake_database_operation completed successfully in {elapsed_time} ms")
}

In case of a failure, the log messages now provide the account number, the elapsed time, and the operation that failed. We can use a tool like grep to filter the log messages based on the account number and keep the context of the log messages. This makes it easier to diagnose problems and track the behavior of the application.

... but there is a lot of repetition in the code.

Tracing

The Tokio tracing crate takes logging to the next level by providing structured logging. Structured logging allows you to log key-value pairs that can be easily searched and filtered. This makes it easier to track the behavior of your application and diagnose problems when they occur, without the code repetition.

To use tracing, add it to your Cargo.toml file:

[dependencies]
log = "0.4"
rand = "0.8"
tracing = "0.1"
tracing-subscriber = "0.3"

Let's update the previous example to use tracing:

use std::thread;

use tracing::{debug, info, instrument, warn};

fn main() {
    tracing_subscriber::fmt::init();
    thread::scope(|s| {
        for i in 0..10 {
            s.spawn(move || fake_database_operation(i));
        }
    });
}

#[instrument]
fn fake_database_operation(account_number: i32) {
    let start_time = std::time::Instant::now();
    info!("Reading account record from database");

    // randomly sleep up to 0.5 seconds
    let sleep_duration = std::time::Duration::from_millis((rand::random::<f64>() * 500.0) as u64);
    thread::sleep(sleep_duration);

    let elapsed_time = start_time.elapsed().as_millis();
    if sleep_duration.as_millis() > 400 {
        warn!("Timeout reading account record from database; operation took {elapsed_time} ms");
        return;
    } else {
        info!("Successfully read account record from database; operation took {elapsed_time} ms");
    }

    info!("Updating account record in database");

    // fail 50% of the time
    if rand::random::<f64>() > 0.5 {
        warn!("Failed to update account record in database; record locked");
    } else {
        info!("Successfully updated account record in database");
    }

    let elapsed_time = start_time.elapsed().as_millis();
    debug!("fake_database_operation completed successfully in {elapsed_time} ms")
}

There is no need to log the account number in every log message. The tracing crate provides a way to add context to log messages using the #[instrument] attribute. The #[instrument] attribute automatically logs the function name, arguments, and return value. This makes it easier to track the behavior of your application and diagnose problems when they occur.

Let's look at the output of the tracing crate:

2024-03-29T11:16:47.819412Z  INFO fake_database_operation{account_number=6}: logging_example: Reading account record from database
2024-03-29T11:16:47.819422Z  INFO fake_database_operation{account_number=1}: logging_example: Reading account record from database
2024-03-29T11:16:47.819446Z  INFO fake_database_operation{account_number=3}: logging_example: Reading account record from database
2024-03-29T11:16:47.819453Z  INFO fake_database_operation{account_number=4}: logging_example: Reading account record from database
2024-03-29T11:16:47.819443Z  INFO fake_database_operation{account_number=7}: logging_example: Reading account record from database
2024-03-29T11:16:47.819489Z  INFO fake_database_operation{account_number=8}: logging_example: Reading account record from database
2024-03-29T11:16:47.819468Z  INFO fake_database_operation{account_number=5}: logging_example: Reading account record from database
2024-03-29T11:16:47.819410Z  INFO fake_database_operation{account_number=2}: logging_example: Reading account record from database
2024-03-29T11:16:47.819407Z  INFO fake_database_operation{account_number=0}: logging_example: Reading account record from database
2024-03-29T11:16:47.819518Z  INFO fake_database_operation{account_number=9}: logging_example: Reading account record from database
2024-03-29T11:16:47.896003Z  INFO fake_database_operation{account_number=9}: logging_example: Successfully read account record from database; operation took 76 ms
2024-03-29T11:16:47.896042Z  INFO fake_database_operation{account_number=9}: logging_example: Updating account record in database
2024-03-29T11:16:47.896052Z  INFO fake_database_operation{account_number=9}: logging_example: Successfully updated account record in database
2024-03-29T11:16:47.915817Z  INFO fake_database_operation{account_number=5}: logging_example: Successfully read account record from database; operation took 96 ms
2024-03-29T11:16:47.915848Z  INFO fake_database_operation{account_number=5}: logging_example: Updating account record in database
2024-03-29T11:16:47.915856Z  INFO fake_database_operation{account_number=5}: logging_example: Successfully updated account record in database
2024-03-29T11:16:47.925931Z  INFO fake_database_operation{account_number=0}: logging_example: Successfully read account record from database; operation took 106 ms
2024-03-29T11:16:47.925981Z  INFO fake_database_operation{account_number=0}: logging_example: Updating account record in database
2024-03-29T11:16:47.925992Z  INFO fake_database_operation{account_number=0}: logging_example: Successfully updated account record in database
2024-03-29T11:16:47.933133Z  INFO fake_database_operation{account_number=8}: logging_example: Successfully read account record from database; operation took 113 ms
2024-03-29T11:16:47.933157Z  INFO fake_database_operation{account_number=8}: logging_example: Updating account record in database
2024-03-29T11:16:47.933168Z  INFO fake_database_operation{account_number=8}: logging_example: Successfully updated account record in database
2024-03-29T11:16:48.004544Z  INFO fake_database_operation{account_number=7}: logging_example: Successfully read account record from database; operation took 185 ms
2024-03-29T11:16:48.004568Z  INFO fake_database_operation{account_number=7}: logging_example: Updating account record in database
2024-03-29T11:16:48.004579Z  INFO fake_database_operation{account_number=7}: logging_example: Successfully updated account record in database
2024-03-29T11:16:48.048530Z  INFO fake_database_operation{account_number=4}: logging_example: Successfully read account record from database; operation took 229 ms
2024-03-29T11:16:48.048558Z  INFO fake_database_operation{account_number=4}: logging_example: Updating account record in database
2024-03-29T11:16:48.048568Z  INFO fake_database_operation{account_number=4}: logging_example: Successfully updated account record in database
2024-03-29T11:16:48.239550Z  WARN fake_database_operation{account_number=3}: logging_example: Timeout reading account record from database; operation took 420 ms
2024-03-29T11:16:48.263141Z  WARN fake_database_operation{account_number=1}: logging_example: Timeout reading account record from database; operation took 443 ms
2024-03-29T11:16:48.263466Z  WARN fake_database_operation{account_number=6}: logging_example: Timeout reading account record from database; operation took 444 ms
2024-03-29T11:16:48.312712Z  WARN fake_database_operation{account_number=2}: logging_example: Timeout reading account record from database; operation took 493 ms

Note that the account_number is automatically added to the log messages. This makes it easier to filter the log messages based on the account number and keep the context of the log messages.

Conclusion

Logging is an important part of any application. It allows you to track the behavior of your application and diagnose problems as they occur. Make sure your log messages are contextual and actionable. Use structured logging to make it easier to construct contextualized log messages.