Test if a trace was emitted in one of the preceding steps

[fleetingbytes]

I've been trying to find a way how to implement the following test. For a minimal example, let's have a library with an add function which emits some traces:

use tracing::{info, trace};

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

Now let's specify an integration test to see if it emits the expected traces:

Feature: Test if trace was emitted

    Scenario Outline: Emit and check addition trace
        When I call the add function with <left> and <right>
        Then a trace about adding <left> and <right> is emitted
        And the result <result> is written in the <level> trace

        Examples:
            | left | right | result | level |
            | 1    | 2     | 3      | info  |
            | 3    | 5     | 8      | info  |

I've been struggling to implement this in cucumber for the past two weeks or so. I have found different kinds difficulties:

Concurrency

Worlds are constructed on a per-scenario basis and Scenarios run in parallel. Each world would have to have its own tracing subscriber registering only traces coming from the threads spawned in this world. tracing::dispatcher seems to be able to do something like that with with_default or set_default. But maybe a better way would be to use a custom generic tracing subscriber and each world would use its own version of it, marking this World's trace spans and events, and adding it dynamically to a tracing_subscriber::registry as a reloadable Layer for the duration of its existence. Or have each world set up and tear down its own tracing instrumentation (how to make them not interfere?). But anyway, parallel execution of these trace test scenarios is a secondary goal for me at this moment.

Save the trace in the World

Even when running each trace test Scenario alone, the biggest problem I currently have is how to make a tracing subscriber write the trace into the world. This way I could look up from a Step whether something like world.log contains the line I'm looking for.

I have tried several different approaches, but always failed, often because of ownership and moving, global tracing subscriber. It is probably because I'm quite new to all of cucumber, tracing, and rust, but I've been hacking at this problem for dozens of hours now and still see no good way.

Save the trace in a shared memory location

I have tried to write the traces into heap-allocated memory behind a Mutex (in a OnceCell), reading this from the steps, and running the test with max_concurrent_scenarios(1), but to my surprise, this has also failed when running more than a few Scenarios in a row. It's not failing in a minimal example, but in my actual library under test. (Here is my minimal example repo with this dangerously useless implementation)

Write trace to a file and read it

Serial scenario execution, writing and reading and reading a trace file, that's what my implementation of this will probably look like.

I'd be happy to hear your Ideas how to approach this problem.

[fleetingbytes]

I've been thinking about this issue a lot lately. My case is likely an example of the XY problem. I think I have to solve Y (the test of the emission of a trace), because I am ignoring a root problem X which got me in this situation in the first place. As Ian Cooper preached in his talk on TDD: Don't test implementation details, test your API. The root problem X in this case is me trying to test an implementation detail. Emitting a certain trace in a certain scenario is a feature I want my library to do, but I shall not test it because that is an implementation detail. It is not part of my public API. The library I'm writing does not communicate with its callers via traces. Rather it provides results (or Results in Rust's terms, wrapped in Ok or Err). So I should probably build my integration tests around that.

[ilslv]

@Nagidal I pretty much agree that testing emitted logs is not what you usually want to do, as it's an implementation details.

[mateuszkj]

@Nagidal Sometimes testings emitted logs is a feature but rather for error logs. E.g. when log are stored somewhere and user want to look up why some processes failed.

example:

Feature: As I a user I want to login to system

    Scenario:  User successfully established login session with system
        Given User 'xxx' has active account
        When User 'xxx' tries to login to system with valid credentials
        Then User successfully logged to system
        And No error log has been emitted
        
    Scenario:  User failed  to established login session with system
        Given User 'xxx' has active account
        When User 'xxx' tries to login to system with invalid credentials
        Then User failed to login to system
        And Error 'invalid credentials' has been emitted with username and real IP address
        And No password has been emitted in logs

There is not implementation details in above scenarios, it don't specify how and where logs are stored. Logging with tracing crate and store logs in some kind of database is one of many solutions.

I started my own logs recorder for tracing https://gitlab.com/mateuszkj/ldap-test-server/-/blob/modify/src/logs_recorder.rs but today I found that there is already crate for that https://crates.io/crates/tracing-capture

[fleetingbytes]

@mateuszkj thanks, I saw the tracing capture crate early in the process of trying to implement it, but I did not know much of the tracing crate and tracing-subscriber, so I did not understand, that this could be a potential way. Now I see it much more clearly. It could indeed work in a serial testing setup.

[mateuszkj]

@Nagidal I've created crate that capturing logging can work concurrently.

Example how to use it with cucumber: https://gitlab.com/mateuszkj/tracing-span-capture/-/blob/main/tests/cucumber.rs

it's requires feature tracing from cucumber, which is not yet published to crates.io