Logger mock for Rust unit tests

Context

I’m writing a CLI app in Rust with clap. Some commands result in one or multiple messages being written to stdout and/or stderr. These messages are an actual part of the commands’ result, not just “some logs”. So I need to verify their integrity.

I wrote integration tests with assert_cmd and predicates, but I wanted unit tests for each of my commands. Some commands interact with external tools that need to be mocked for testing. Even printing messages is an external interaction with stdout and stderr.

Directly capturing stdout and stderr seems not to be an easy approach. I found the capture_stdio crate, but it needs the nightly toolchain.

There might be other better approaches, but the learning process is a good enough reason for me to go on the path of implementing a solution.

Inject everything

For a simple CLI app, I consider println!/eprintln! enough. And I wanted to stick to them. I went searching for another approach just to have the possibility to fully unit test my code.

One of the first ideas was obvious: dependency injection. Inject a logger into the task (a struct with a function) that is attached to the command. Which is usually the way to go. But why go easy when going hard will push me into learning more? It seemed a bit of overkill to go from println to injecting dependencies.

And I reached out to loggers. The log facade lets you change between multiple logger implementations. And I wanted to write a simple custom logger (again, mostly for learning). Although it implies a shared global instance of the logger and, further down in my implementation, a singleton, I let the inconvenience aside and followed my goal of unit testing the tasks my CLI app runs.

What I need

I knew I needed a production logger that writes messages on stdout/stderr. I chose to write on stdout the info-level messages and on stderr all of the other ones.

use log::{Level, Metadata, Record};

struct Logger;

impl log::Log for Logger {
    fn enabled(&self, metadata: &Metadata<'_>) -> bool {
        metadata.level() <= Level::Info
    }

    fn log(&self, record: &Record<'_>) {
        if self.enabled(record.metadata()) {
            match record.level() {
                Level::Info => println!("{}", record.args()),
                _ => eprintln!("{}", record.args()),
            }
        }
    }

    fn flush(&self) {}
}

 

And a test logger that writes the messages somewhere I can get them and verify they are correct.

use log::{Level, Metadata, Record};

struct TestLogger;

impl log::Log for TestLogger {
    fn enabled(&self, metadata: &Metadata<'_>) -> bool {
        metadata.level() <= Level::Info
    }

    fn log(&self, record: &Record<'_>) {
        if self.enabled(record.metadata()) {
            // save log record somewhere
        }
    }

    fn flush(&self) {}
}

Challenges

Rust runs unit tests on multiple threads. Thus, I needed to share the logger. But I have no control, as far as I know at the moment. Some threads run my tests, they all write messages in my test logger, and I need to know the exact log messages I got for each test case.

Since I don’t know how I could control the test runner, one approach is thread-local variables. With a thread-local variable, I could separately store the messages from each test, then write asserts for them.

Another aspect is that a logger can be initialized only once in a process.

Implementation

To sum it up, I need a logger

• • that is initialized only once in a process
  • and writes the messages from each test separately.

Initialize the logger once

use log::LevelFilter;
use std::sync::Once;

static START: Once = Once::new();
static LOGGER: TestLogger = TestLogger;

pub fn init_logger() {
    START.call_once(|| {
        log::set_logger(&LOGGER).map(|()| log::set_max_level(LevelFilter::Info)).unwrap()
    });
}

Write messages

As mentioned, I used a thread-local variable to store the messages coming from each test. The challenge is that the variable must be static. And variables are immutable by default. I want to write into that variable, and it’s unsafe to have a static mutable variable shared between threads.

RefCell comes to help. I can have a static immutable variable of type RefCell, which contains a vector of log records. RefCell allows interior mutability by doing the unsafe part for you.

use log::Level;
use std::cell::RefCell;

pub struct LogRecord {
    pub level: Level,
    pub args: String,
}

thread_local! {
    static LOG_RECORDS: RefCell<Vec<LogRecord>> = const {RefCell::new(Vec::new())};   
}

Now the test logger needs to write each log to LogRecord vector (Vec<LogRecord>). I need to mutably borrow the RefCell’s inner data, which is the vector, and push the log message into it.

impl log::Log for TestLogger {
    fn log(&self, record: &Record<'_>) {
        if self.enabled(record.metadata()) {
            LOG_RECORDS.with(|rec| {
                let mut records = rec.borrow_mut();
                records.push(LogRecord { level: record.level(), args: record.args().to_string() });
            });
        }
    }
}

How to use

Put a breakpoint and start debugging. See the code in a sample project on GitHub.

use log::{error, info};

pub fn function_that_writes_logs() {
    info!("Some info message");
    error!("Some error message");
}

#[cfg(test)]
mod tests {
   use log::Level;

    use super::*;
    use crate::test_logger::{get_logs, init_logger};

    #[test]
    fn test_function_that_writes_logs() {
        init_logger();

        function_that_writes_logs();

        let logs = get_logs();
        assert_eq!(logs.len(), 2);

        assert_eq!(logs[0].level, Level::Info);
        assert_eq!(logs[0].args, "Some info message");

        assert_eq!(logs[1].level, Level::Error);
        assert_eq!(logs[1].args, "Some error message");
    }
}