Rust: Actix-web and Daily Logging

Currently, our actix-web learning application simply prints debug information to the console using the println! macro. In this post, we will implement proper non-blocking daily logging to files. Daily logging entails rotating to a new log file each day. Non-blocking refers to having a dedicated thread for file writing operations. We will utilise the tracing, tracing-appender, and tracing-subscriber crates for our logging implementation.

🦀 Index of the Complete Series.


Rust: Actix-web and Daily Logging

🚀 Please note, complete code for this post can be downloaded from GitHub with:

git clone -b v0.11.0 https://github.com/behai-nguyen/rust_web_01.git

The actix-web learning application mentioned above has been discussed in the following ten previous posts:

The code we’re developing in this post is a continuation of the code from the tenth post above. 🚀 To get the code of this tenth post, please use the following command:

git clone -b v0.10.0 https://github.com/behai-nguyen/rust_web_01.git

– Note the tag v0.10.0.

While this post continues from previous posts in this series, it can also be read independently. The logging module developed herein can be used in other projects without modification.

❶ For this post, we introduce a new module src/helper/app_logger.rs, and some other modules and files are updated. The project layout remains the same as in the last post. The layout chart below shows the affected files and modules:

– Please note that files marked with ★ are updated, and src/helper/app_logger.rs is marked with ☆, as it is the only new module.

.
├── .env ★
├── Cargo.toml ★
├── ...
├── README.md ★
├── src
│ ├── auth_middleware.rs ★
│ ├── database.rs ★
│ ├── helper
│ │ ├── app_logger.rs ☆
│ │ └── ...
│ ├── helper.rs ★
│ ├── main.rs ★
│ ├── middleware.rs ★
│ └── ...
└── tests
    ├── common.rs ★
    └── ...

❷ An update to the .env file: a new entry has been added:

RUST_LOG=debug

The value of RUST_LOG is translated into tracing::Level. Valid values include trace, debug, info, warn and error. Any other values are invalid and will default to Level::DEBUG.

❸ Updates to the Cargo.toml file: as expected, the new crates are added to the [dependencies] section.

...
[dependencies]
...
tracing = "0.1"
tracing-appender = "0.2"
tracing-subscriber = {version = "0.3", features = ["fmt", "std", "local-time", "time"]}

❹ 💥 Issue with calculating UTC time offset on Ubuntu 22.10.

In the new code added for this post, we need to calculate the UTC time offset to obtain local time. The following code works on Windows 10:

use time::UtcOffset;

let offset = UtcOffset::current_local_offset().unwrap();

However, on Ubuntu 22.10, it doesn’t always function as expected. Sometimes, it raises the error IndeterminateOffset. The inconsistency in its behavior makes it challenging to identify a clear pattern of when it works and when it doesn’t.

After extensive searching, I came across this GitHub issue, Document #293 in local-offset feature description #297. It appears that even after three years, this issue remains unresolved.

This complication adds an extra layer of difficulty in ensuring both the code and integration tests function properly. In the subsequent sections of this post, when discussing the code, we’ll refer back to this issue when relevant. Please keep this in mind.

❺ The src/helper/app_logger.rs module has been designed to be easily copied into other projects, provided that the Cargo.toml file includes the required crates discussed earlier.

This module contains only a single public function, pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard, which the application calls to set up the log. Please refer to the notes and documentation within this module while reading the code.

Originally, the utc_offset: time::UtcOffset parameter was not present. However, due to the issue mentioned in 💥 Issue with calculating UTC time offset on Ubuntu 22.10, the code was refactored to include this parameter, offering a bit more flexibility.

⓵ Setting up the daily log files.

    let log_appender = RollingFileAppender::builder()
        .rotation(Rotation::DAILY) // Daily log file.
        .filename_suffix("log") // log file names will be suffixed with `.log`
        .build("./log") // try to build an appender that stores log files in `/var/log`
        .expect("Initialising rolling file appender failed");

To set up the daily log files, we begin by calling the pub fn builder() -> Builder function.

We specify DAILY rotation to generate daily log files. However, it’s important to note that according to the documentation, the file names are appended with the current date in UTC. Since I’m in the Australian Eastern Standard Time (AEST) zone, which is 10-11 hours ahead of UTC, there were instances where my log file names were created with dates from the previous day.

To give log files the .log extension, we use the method pub fn filename_suffix(self, suffix: impl Into<String>) -> Self.

The format of the daily log file names follows the pattern YYYY-MM-DD.log, for example, 2024-03-10.log.

We then invoke the method pub fn build( &self, directory: impl AsRef<Path>) -> Result<RollingFileAppender, InitError> to specify the location of the log files within the log/ sub-directory relative to where the application is executed. For instance:

▶️<code>Windows 10:</code> F:\rust\actix_web>target\debug\learn_actix_web.exe
▶️<code>Ubuntu 22.10:</code> behai@hp-pavilion-15:~/rust/actix_web$ /home/behai/rust/actix_web/target/debug/learn_actix_web

This results in the log files being stored at F:\rust\actix_web\log\ and /home/behai/rust/actix_web/target/debug/learn_actix_web/log/ respectively.

⓶ We create a non-blocking writer thread using the following code:

    let (non_blocking_appender, log_guard) = tracing_appender::non_blocking(log_appender);

This is the documentation section for the function tracing_appender::non_blocking. For more detailed documentation, refer to the tracing_appender::non_blocking module. Please note the following:

This function returns a tuple of NonBlocking and WorkerGuard. NonBlocking implements MakeWriter which integrates with tracing_subscriber. WorkerGuard is a drop guard that is responsible for flushing any remaining logs when the program terminates.

Note that the WorkerGuard returned by non_blocking must be assigned to a binding that is not _, as _ will result in the WorkerGuard being dropped immediately. Unintentional drops of WorkerGuard remove the guarantee that logs will be flushed during a program’s termination, in a panic or otherwise.

What this means is that we must keep log_guard alive for the application to continue logging. log_guard is an instance of the WorkerGuard struct and is also the returned value of the public function pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard. We will revisit this returned value in a later section.

⓷ Next, we specify the date and time format for each log line. Each line begins with a local date and time. For instance, 2024-03-12-08:19:13:

    // Each log line starts with a local date and time token.
    // 
    // On Ubuntu 22.10, calling UtcOffset::current_local_offset().unwrap() after non_blocking()
    // causes IndeterminateOffset error!!
    // 
    // See also https://github.com/time-rs/time/pull/297.
    //
    let timer = OffsetTime::new(
        //UtcOffset::current_local_offset().unwrap(),
        utc_offset,
        format_description!("[year]-[month]-[day]-[hour]:[minute]:[second]"),
    );

We’ve discussed local dates in some detail in this post.

🚀 Please note that this is a local date and time. In my time zone, Australian Eastern Standard Time (AEST), which is 10-11 hours ahead of UTC, the log file name for a log line that starts with 2024-03-12-08:19:13 would actually be log/2024-03-11.log.

⓸ Next, we attempt to define the tracing::Level based on the environment variable RUST_LOG discussed previously:

    // Extracts tracing::Level from .env RUST_LOG, if there is any problem, 
    // defaults to Level::DEBUG.
    //
    let level: Level = match std::env::var_os("RUST_LOG") {
        None => Level::DEBUG,

        Some(text) => {
            match Level::from_str(text.to_str().unwrap()) {
                Ok(val) => val,
                Err(_) => Level::DEBUG
            }
        }
    };

💥 I initially assumed that having RUST_LOG defined in the environment file .env would suffice. However, it turns out that we need to explicitly set it in the code.

⓹ We then proceed to “create a subscriber”, I hope I’m using the correct terminology:

    let subscriber = tracing_subscriber::registry()
        .with(
            Layer::new()
                .with_timer(timer)
                .with_ansi(false)
                .with_writer(non_blocking_appender.with_max_level(level)
                    .and(std::io::stdout.with_max_level(level)))
        );

The function tracing_subscriber::registry() returns a tracing_subscriber::registry::Registry struct. This struct implements the trait tracing_subscriber::layer::SubscriberExt. The method fn with<L>(self, layer: L) -> Layered<L, Self> from this trait returns a tracing_subscriber::layer::Layered struct, which is a:

A Subscriber composed of a Subscriber wrapped by one or more Layers.

We create the new Layer using tracing_subscriber::fmt::Layer implementation.

Note that non_blocking_appender is an instance of tracing_appender::non_blocking::NonBlocking struct. This struct implements the trait tracing_subscriber::fmt::writer::MakeWriterExt, where the method fn with_max_level(self, level: Level) -> WithMaxLevel<Self> is defined.

🚀 .and(std::io::stdout.with_max_level(level)) means that anything logged to the log file will also be printed to the console.

⓺ Next, the new Subscriber is set as the global default for the duration of the entire program:

    // tracing::subscriber::set_global_default(subscriber) can only be called once. 
    // Subsequent calls raise SetGlobalDefaultError, ignore these errors.
    //
    // There are integeration test methods which call this init_app_logger(...) repeatedly!!
    //
    match tracing::subscriber::set_global_default(subscriber) {
        Err(err) => tracing::error!("Logger set_global_default, ignored: {}", err),
        _ => (),
    }

The documentation for the function tracing::subscriber::set_global_default states:

Can only be set once; subsequent attempts to set the global default will fail. Returns whether the initialization was successful.

Since some integration test methods call the pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard more than once, we catch potential errors and ignore them.

⓻ Finally, pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard returns log_guard, as discussed above.

❻ Updates to the src/main.rs module.

⓵ Coming back to pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard, specifically regarding the returned value discussed previously, I read and understood the quoted documentation, and I believe the code was correct. However, it did not write to log files as expected. I sought help. As per my help request post, I initially called init_app_logger in the src/lib.rs module’s pub async fn run(listener: TcpListener) -> Result<Server, std::io::Error>. Consequently, as soon as run went of scope, the returned WorkerGuard was dropped, and the writer thread terminated.

Simply moved it to src/main.rs’s async fn main() -> Result<(), std::io::Error>, fixed this problem:

    // Call this to load RUST_LOG.
    dotenv().ok(); 

    // Calling UtcOffset::current_local_offset().unwrap() here works in Ubuntu 22.10, i.e.,
    // it does not raise the IndeterminateOffset error.
    //
    // TO_DO. But this does not guarantee that it will always work! 
    //
    let _guards = init_app_logger(UtcOffset::current_local_offset().unwrap());

Please note the call UtcOffset::current_local_offset().unwrap(). This is due to the problem discussed in the section 💥 Issue with calculating UTC time offset on Ubuntu 22.10.

⓶ The function pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard requires the environment variable RUST_LOG as discussed previously. That’s why dotenv().ok() is called in async fn main() -> Result<(), std::io::Error>.

Recall that dotenv().ok() is also called in the src/lib.rs module’s pub async fn run(listener: TcpListener) -> Result<Server, std::io::Error> to load other environment variables. This setup might seem clunky, but I haven’t found a better solution yet!

❼ Updating integration tests. We want integration tests to be able to log as well. These updates are made solely in the tests/common.rs module.

The function pub async fn spawn_app() -> TestApp in tests/common.rs calls the src/lib.rs module’s function pub async fn run(listener: TcpListener) -> Result<Server, std::io::Error> to create application server instances.

This means that spawn_app() must be refactored to call pub fn init_app_logger(utc_offset: time::UtcOffset) -> WorkerGuard and somehow keep the writer thread alive after spawn_app() goes out of scope. We manage this by:

⓵ Update TestApp struct by adding pub guard: WorkerGuard.

⓶ Update the function pub async fn spawn_app() -> TestApp with additional calls:

    // To load RUST_LOG from .env file.
    dotenv().ok(); 

    /*
    On Ubuntu 22.10, calling UtcOffset's offset methods causes IndeterminateOffset error!!

    See also https://github.com/time-rs/time/pull/297

    ...
    */

    // TO_DO: 11 is the current number of hours the Australian Eastern Standard Time (AEST)
    // is ahead of UTC. This value need to be worked out dynamically -- if it is at all 
    // possible on Linux!!
    // 
    let guard = init_app_logger(UtcOffset::from_hms(11, 0, 0).unwrap());

Note the call UtcOffset::from_hms(11, 0, 0).unwrap(). This is due to the problem discussed in section 💥 Issue with calculating UTC time offset on Ubuntu 22.10:

– 👎 Unlike src/main.rs, where UtcOffset::current_local_offset().unwrap() works, calling it here consistently results in the IndeterminateOffset error! UtcOffset::from_hms(11, 0, 0).unwrap() works, but again, this is not a guarantee it will keep working.

👎 The value 11 is hardcoded. Presently, the Australian Eastern Standard Time (AEST) zone is 11 hours ahead of UTC. To get the AEST date and time, we need to offset UTC by 11 hours. However, 11 is not a constant value; due to daylight savings, in Southern Hemisphere winters, it changes to 10 hours (I think). This means that this code will no longer be correct.

❽ We’ve reached the conclusion of this post. I’d like to mention that the ecosystem surrounding tracing and logging is incredibly vast. While this post only scratches the surface, it provides a complete working example nonetheless. We can build upon this foundation as needed.

The UTC offset issue on Ubuntu 22.10, as described, must be addressed definitively. However, that task is for another day.

I’m not entirely satisfied with the numerous debug loggings from other crates. These can be filtered and removed, but that’s a topic for another post, perhaps.

I hope you find the information useful. Thank you for reading. And stay safe, as always.

✿✿✿

Feature image source: