New feature: capture recent logs for testing

[josecelano]

Relates to: #1069

Context

I'm trying to capture logs in memory to write assertions in tests. I tried to use the tracing-test crate in this PR, but it's not working due to this bug.

So, I decided to copy some code from that crate because the crate forces you to disable your tracing initialization, and I wanted to keep our initialization to have better control.

The idea is the same; a log capturer captures the logs in addition to printing to stdout.

I initiate the capturer in the production code instead of doing it in the testing code with a macro.

Problems

• I had to enable the LogCapturer in production. That's the reason I'm using a limited circular buffer. I don't know how to enable the capturer only for testing, since we can't control the first call to the tracing_init function. I tried using two tracing_init functions with attributes #[cfg(test)] and #[cfg(not(test))], only enabling the capturer for testing, but it's not working.
• The function that checks if logs contain a line with some words clones the whole buffer. However, I think searching in the "live" buffer would slow down the tests because it uses a lock, and other tests can't write to logs while one test is searching.
• You cannot capture logs for tests that don't run the test env. In those tests, you should initialize the subscriber manually.

Future work

Right now, you can write asserts like this:

assert!(logs_contains_a_line_with(&["ERROR", "tower_http", "response failed"]));

For example, for these tests. But there is no way to match assertings with log lines. We must introduce something like "scopes", or "labels". We need to add a UUID to the log lines when we write to logs with error!, info!, etc. So we can search for lines containing that ID. The tracing-test uses scopes. It inserts the name of the test in the logs so it can filter later. I think we can add a UUID to the test environment, for example, to make it more explicit. Each test runs its own test env, and the test env adds the UUID to the logs. This way, we can identify logs for a test environment but not for a concrete test. Maybe we can use both approaches.

Enable tracing output for tests only with --nocapture

I have introduced another change in one of the first commits. All test environments were created with an ephemeral configuration with the tracing level set to OFF. The reason was to hide logs when you run the tests, to avoid mixing both outputs. I have changed the ephemeral configuration to error:

pub fn ephemeral() -> Configuration {
    let mut config = Configuration::default();

    config.logging.threshold = Threshold::Error;

    // ...
}

After that change,cargo test printed all the errors.

I think the right way to disable the tracing output for testing is using the with_test_writer function in the builder:

let builder = tracing_subscriber::fmt()
    .with_max_level(filter)
    .with_ansi(true)
    .with_test_writer()
    .with_writer(mock_writer);

That configures the subscriber to show tracing output only when the option --nocapture is passed.

cargo test                  -> Will not show logs
cargo test -- --nocapture   -> Will not show logs at the level defined in the configuration used the first time `tracing_init` is called.

If we discard this PR, we should pick at least that configuration.

Important

• tracing_init is called only once, but we don't control which one is the first call. I mean, if we have two tests running test environments, the first test that calls the tracing_init will define the tracing level. Therefore, we have to ensure there are no tests that disable logs. If there is one and it's executed the first, all logs assert won't work.
• The capturer buffer is limited. It could happen that logs written by a test are removed before the test assertion if other tests write many lines (race condition).
• I have not benchmarked the solution. Maybe it's too slow to write logs to both memory and stdout. Notice that the default benchmarking configuration disabled tracing.

Alternatives

If we want to capture all logs, we could separate the tests for logs into a new group. Those tests only would have logs assertions. They would require the capturer to be enabled (like E2E tests in the Indes that require a running tracker). You could run the tests with:

TORRUST_TRACKER_CAPTURE_LOGS cargo test

Internally, that would enable the log capturer, which would otherwise be disabled.

TODO

• Benchmarking with Info logging level.

[codecov]

Codecov Report

Attention: Patch coverage is 50.00000% with 6 lines in your changes missing coverage. Please review.

Project coverage is 76.12%. Comparing base (4a9dcef) to head (b024575).

Files with missing lines	Patch %	Lines
src/bootstrap/logging.rs	0.00%	6 Missing ⚠️

Additional details and impacted files

@@             Coverage Diff             @@
##           develop    #1148      +/-   ##
===========================================
- Coverage    76.24%   76.12%   -0.13%     
===========================================
  Files          173      173              
  Lines        11543    11551       +8     
  Branches     11543    11551       +8     
===========================================
- Hits          8801     8793       -8     
- Misses        2579     2590      +11     
- Partials       163      168       +5     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[josecelano]

I finally moved the code to capture logs from production to testing code in a new PR.

Superseded by #1149

@da2ce7, the new PR is what we have right now, but capturing logs in tests.

I was planning to use tracing span names (like tracing-test crate does) to identify logs for a given test, but I ran into the same problem I described on:

• https://github.com/josecelano/tracing-test-bug
• No capture from std::thread::spawn or tokio::task::spawn_blocking dbrgn/tracing-test#23

The assertions can be written like this:

#[tokio::test]
async fn should_blab_bla() {
    logging::setup();

    let span = tracing::info_span!("unique scope");
    let _guard = span.enter();
    
    // test ...
    
    assert!(logs_contains_a_line_with(
        &["unique scope", "ERROR", "tower_http", "response failed"]
    ));    
}

However, the span is not moved into the spawned threads when we run the test environments. Therefore, the "unique scope" identifier is not present in the logs, and we can not write assertions.

It seems you can clone the span (see here at minute 40) or using [#instrument]. I was able to make it work in a test project (https://github.com/josecelano/tracing-test-bug/tree/main-async-and-using-tokio-for-spawns, notify it's not the main branch), but I could not make it work in the tracker. Our setup is much more complex. So I decided to introduce unique identifiers manually in the logs. For example, for this issue, we can use the request id to identify the log line triggered by the test.