Test if a trace line was emitted

Question

I am writing integration tests for a library and I want to test if in a certain scenario a particular trace line was emitted. I see how tracing-test can capture a trace within a test step, I had a look at tracing-fluent-assertions and test-log, but all of these seem to do almost what I need, just not exactly that.

In my case I have one test step which causes some trace lines to be emitted, and I need to check in another test step that these trace lines were actually emitted. Do you know of a way to do this? I'd thought that tracing-subscriber or cucumber already have means to do this, but I don't see it in their documentation.

This is a the structure of a minimal example:

.
│   Cargo.toml
├───src
│   │   lib.rs
│   └───bin
│           test-of-trace.rs
└───tests
    │   minimal.rs
    └───features
            minimal.feature

The library defines one function which we will call in our integration test. We use the tracing crate for generating traces.

// lib.rs
use tracing::{info, trace};

pub fn add(left: usize, right: usize) -> usize {
    trace!("I'm adding");
    let result = left + right;
    info!("The result is {}", result);
    result
}

The integration test is done with cucumber-rs. This is our feature file defining our test:

# tests/features/minimal.feature
Feature: Test if trace was emitted

    Scenario: Emit and check trace
        When I call the add function
        Then a trace is emitted

We implement the test steps with cucumber-rs as follows:

// tests/minimal.rs
use cucumber::{then, when, World};
use test_of_trace;

#[derive(Debug, World)]
#[world(init = Self::new)]
pub struct TestWorld {}

impl TestWorld {
    fn new() -> Self {
        Self {}
    }
}

#[when("I call the add function")]
fn call_add(_world: &mut TestWorld) {
    test_of_trace::add(3, 4);
}

#[then("a trace is emitted")]
fn trace_is_emitted(_world: &mut TestWorld) {
    //TODO
    assert!(false); // how to look up if the trace was emitted?
}

#[tokio::main]
async fn main() {
    TestWorld::run("tests/features").await;
}

We tell cargo about our integration test in the table [[test]]

[package]
name = "test-of-trace"
version = "0.1.0"
edition = "2021"

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

[dependencies]
tracing = "0.1.37"
tracing-subscriber = {version = "0.3.16", features = ["env-filter", "registry"]}

[dev-dependencies]
cucumber = "0.19"
futures = "0.3"
tokio = { version = "1.25", features = ["macros", "rt-multi-thread", "time"] }

[[test]]
name = "minimal"
harness = false

Additionaly we can create a binary which will run and show that the traces are actually emitted when the add function runs

// bin/test-of-trace.rs
use test_of_trace;
use tracing::{instrument, trace};
use tracing_subscriber::{fmt, EnvFilter};

fn install_tracing() {
    fmt()
        .without_time()
        .with_line_number(true)
        .with_env_filter(
            EnvFilter::try_from_default_env()
                .or_else(|_| EnvFilter::try_new("trace"))
                .unwrap(),
        )
        .init();
}

#[instrument]
fn main() {
    install_tracing();
    trace!("Starting {}", env!("CARGO_PKG_NAME"));
    test_of_trace::add(5, 8);
    trace!("Finishing {}", env!("CARGO_PKG_NAME"));
}

This example is also available as a repository

Answer 1

I found a solution. First of all, the tracing apparatus has to be installed in the main function of the test runner. And the tracing-subscriber which we initiate there has to use our custom tracing target -- our writer test_of_trace::logger::Logger.

// tests/minimal.rs
// --snip--
fn install_tracing() {
    fmt()
        .without_time()
        .with_line_number(true)
        .with_max_level(Level::TRACE)
        .json()
        .with_writer(test_of_trace::logger::Logger::new)
        .init();
}

#[tokio::main]
#[instrument]
async fn main() {
    install_tracing();
    TestWorld::run("tests/features").await;
}

When writing our own logger (code below), we make it write the traces to a globally accessible String (GLOBAL_STRING) because the tracing-subscriber wants to write the logs into it, and also our test steps want to read logs from it. This is made possible by OnceCell's Lazy and Mutex.

// logger.rs
use once_cell::sync::Lazy;
use std::{
    io::{Error, ErrorKind, Write},
    sync::Mutex,
};
use tracing::Level;

pub static GLOBAL_STRING: Lazy<Mutex<String>> = Lazy::new(|| Mutex::new(String::new()));

#[derive(Debug)]
pub struct Logger;

impl Logger {
    pub fn new() -> Self {
        Self {}
    }
}

impl Write for Logger {
    fn write(&mut self, buf: &[u8]) -> Result<usize, Error> {
        match std::str::from_utf8(buf) {
            Ok(decoded) => {
                let mut s = GLOBAL_STRING.lock().unwrap();
                s.push_str(decoded);
                Ok(buf.len())
            }
            Err(_) => Err(Error::new(
                ErrorKind::InvalidData,
                "could not decode data as utf8",
            )),
        }
    }
    fn flush(&mut self) -> Result<(), Error> {
        Ok(())
    }
}


pub fn clear() {
    let mut s = GLOBAL_STRING.lock().unwrap();
    s.clear()
}

pub fn level_contains(level: &Level, pattern: &str) -> Result<bool, std::io::Error> {
    let s = GLOBAL_STRING.lock().unwrap();
    Ok(s.lines()
        .filter(|l| l.starts_with(&("{\"level\":\"".to_owned() + level.as_str())))
        .any(|l| l.contains(pattern)))
}

The logger module also has public functions clear and level_contains to clear the logger content and to check if certain logs are present, respectively.

Our TestWorld::new clears the content of the logger upon constructing itself:

#[derive(Debug, World)]
#[world(init = Self::new)]
pub struct TestWorld {}

impl TestWorld {
    fn new() -> Self {
        test_of_trace::logger::clear();
        Self {}
    }
}

Finally, we come to the TODO part of our test step which can now test if a certain trace has been emitted:

#[then("a trace is emitted")]
fn trace_is_emitted(_world: &mut TestWorld) {
    match test_of_trace::logger::level_contains(&Level::INFO, "result is") {
        Ok(val) => assert!(val),
        Err(_) => assert!(false),
    }
}

Of course our Cargo.toml needs a few updates:

tracing-subscriber = {version = "0.3.16", features = ["fmt", "json", "env-filter", "registry"]}
once_cell = "1.17.1"

The structure of this (still minimal) example is:

.
│   Cargo.toml
├───src
│   │   lib.rs
│   │   logger.rs
│   └───bin
│           test-of-trace.rs
└───tests
    │   minimal.rs
    └───features
            minimal.feature

I have merged this solution to the master branch of the repository. Here is a screenshot of the integration test run:

The tests and test implementation have been modified to have two scenario outlines run in parallel. I expected conflicts because each world clears the global logger when being constructed. Maybe the implementation of the Logger and TestWorld should be reworked. For instance each logger being constructed with a logger_id, and then have a global HashMap between logger_ids and their Strings.

However, I have tested the crude and potentially colliding implementation in parallel running scenarios and did not encounter any conflicts. Maybe I was just lucky?

If you have any suggestions how to improve this or make it less complicated, please comment or send a PR to the repo.