New feature: capture recent logs for testing

packages/test-helpers/src/configuration.rs

@@ -29,7 +29,12 @@ pub fn ephemeral() -> Configuration {
 
     let mut config = Configuration::default();
 
-    config.logging.threshold = Threshold::Off; // It should always be off here, the tests manage their own logging.
+    // This have to be Off otherwise the tracing global subscriber
+    // initialization will panic because you can't set a global subscriber more
+    // than once. You can use enable logging in tests with:
+    // `crate::common::logging::setup(LevelFilter::ERROR);`
+    // That will also allow you to capture logs and write assertions on them.
+    config.logging.threshold = Threshold::Off;
 
     // Ephemeral socket address for API
     let api_port = 0u16;

src/bootstrap/logging.rs

@@ -28,7 +28,7 @@ pub fn setup(cfg: &Configuration) {
     }
 
     INIT.call_once(|| {
-        tracing_stdout_init(tracing_level, &TraceStyle::Default);
+        tracing_init(tracing_level, &TraceStyle::Default);
     });
 }
 
@@ -43,8 +43,11 @@ fn map_to_tracing_level_filter(threshold: &Threshold) -> LevelFilter {
     }
 }
 
-fn tracing_stdout_init(filter: LevelFilter, style: &TraceStyle) {
-    let builder = tracing_subscriber::fmt().with_max_level(filter).with_ansi(true);
+fn tracing_init(filter: LevelFilter, style: &TraceStyle) {
+    let builder = tracing_subscriber::fmt()
+        .with_max_level(filter)
+        .with_ansi(true)
+        .with_test_writer();
 
     let () = match style {
         TraceStyle::Default => builder.init(),

tests/common/clock.rs

@@ -1,17 +1,11 @@
 use std::time::Duration;
 
 use torrust_tracker_clock::clock::Time;
-use tracing::level_filters::LevelFilter;
 
-use crate::common::logging::{tracing_stderr_init, INIT};
 use crate::CurrentClock;
 
 #[test]
 fn it_should_use_stopped_time_for_testing() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     assert_eq!(CurrentClock::dbg_clock_type(), "Stopped".to_owned());
 
     let time = CurrentClock::now();

tests/common/logging.rs

@@ -1,30 +1,154 @@
-#![allow(clippy::doc_markdown)]
-//! Logging for the Integration Tests
-//!
-//! Tests should start their own logging.
-//!
-//! To find tests that do not start their own logging:
-//!
-//! ´´´ sh
-//! awk 'BEGIN{RS=""; FS="\n"} /#\[tokio::test\]\s*async\s+fn\s+\w+\s*\(\s*\)\s*\{[^}]*\}/ && !/#\[tokio::test\]\s*async\s+fn\s+\w+\s*\(\s*\)\s*\{[^}]*INIT\.call_once/' $(find . -name "*.rs")
-//! ´´´
-//!
-
-use std::sync::Once;
+//! Setup for logging in tests.
+use std::collections::VecDeque;
+use std::io;
+use std::sync::{Mutex, MutexGuard, Once, OnceLock};
 
+use torrust_tracker::bootstrap::logging::TraceStyle;
 use tracing::level_filters::LevelFilter;
+use tracing_subscriber::fmt::MakeWriter;
 
-#[allow(dead_code)]
-pub static INIT: Once = Once::new();
+static INIT: Once = Once::new();
+
+/// A global buffer containing the latest lines captured from logs.
+#[doc(hidden)]
+pub fn captured_logs_buffer() -> &'static Mutex<CircularBuffer> {
+    static CAPTURED_LOGS_GLOBAL_BUFFER: OnceLock<Mutex<CircularBuffer>> = OnceLock::new();
+    CAPTURED_LOGS_GLOBAL_BUFFER.get_or_init(|| Mutex::new(CircularBuffer::new(1000, 200)))
+}
+
+pub fn setup(filter: LevelFilter) {
+    INIT.call_once(|| {
+        tracing_init(filter, &TraceStyle::Default);
+    });
+}
+
+fn tracing_init(level_filter: LevelFilter, style: &TraceStyle) {
+    let mock_writer = LogCapturer::new(captured_logs_buffer());
 
-#[allow(dead_code)]
-pub fn tracing_stderr_init(filter: LevelFilter) {
     let builder = tracing_subscriber::fmt()
-        .with_max_level(filter)
+        .with_max_level(level_filter)
         .with_ansi(true)
-        .with_writer(std::io::stderr);
+        .with_test_writer()
+        .with_writer(mock_writer);
 
-    builder.pretty().with_file(true).init();
+    let () = match style {
+        TraceStyle::Default => builder.init(),
+        TraceStyle::Pretty(display_filename) => builder.pretty().with_file(*display_filename).init(),
+        TraceStyle::Compact => builder.compact().init(),
+        TraceStyle::Json => builder.json().init(),
+    };
 
     tracing::info!("Logging initialized");
 }
+
+/// It returns true is there is a log line containing all the words passed.
+///
+/// # Panics
+///
+/// Will panic if it can't get the lock for the global buffer or convert it into
+/// a vec.
+#[must_use]
+pub fn logs_contains_a_line_with(words: &[&str]) -> bool {
+    // code-review: we can search directly in the buffer instead of converting
+    // the buffer into a string but that would slow down the tests because
+    // cloning should be faster that locking the buffer for searching.
+    // Because the buffer is not big.
+    let logs = String::from_utf8(captured_logs_buffer().lock().unwrap().as_vec()).unwrap();
+
+    for line in logs.split('\n') {
+        if contains_words_in_any_order(line, words) {
+            return true;
+        }
+    }
+
+    false
+}
+
+fn contains_words_in_any_order(text: &str, words: &[&str]) -> bool {
+    words.iter().all(|&word| text.contains(word))
+}
+
+/// A tracing writer which captures the latests logs lines into a buffer.
+/// It's used to capture the logs in the tests.
+#[derive(Debug)]
+pub struct LogCapturer<'a> {
+    logs: &'a Mutex<CircularBuffer>,
+}
+
+impl<'a> LogCapturer<'a> {
+    pub fn new(buf: &'a Mutex<CircularBuffer>) -> Self {
+        Self { logs: buf }
+    }
+
+    fn buf(&self) -> io::Result<MutexGuard<'a, CircularBuffer>> {
+        self.logs.lock().map_err(|_| io::Error::from(io::ErrorKind::Other))
+    }
+}
+
+impl io::Write for LogCapturer<'_> {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        print!("{}", String::from_utf8(buf.to_vec()).unwrap());
+
+        let mut target = self.buf()?;
+
+        target.write(buf)
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        self.buf()?.flush()
+    }
+}
+
+impl MakeWriter<'_> for LogCapturer<'_> {
+    type Writer = Self;
+
+    fn make_writer(&self) -> Self::Writer {
+        LogCapturer::new(self.logs)
+    }
+}
+
+#[derive(Debug)]
+pub struct CircularBuffer {
+    max_size: usize,
+    buffer: VecDeque<u8>,
+}
+
+impl CircularBuffer {
+    #[must_use]
+    pub fn new(max_lines: usize, average_line_size: usize) -> Self {
+        Self {
+            max_size: max_lines * average_line_size,
+            buffer: VecDeque::with_capacity(max_lines * average_line_size),
+        }
+    }
+
+    /// # Errors
+    ///
+    /// Won't return any error.
+    #[allow(clippy::unnecessary_wraps)]
+    pub fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        for &byte in buf {
+            if self.buffer.len() == self.max_size {
+                // Remove oldest byte to make space
+                self.buffer.pop_front();
+            }
+            self.buffer.push_back(byte);
+        }
+
+        Ok(buf.len())
+    }
+
+    /// # Errors
+    ///
+    /// Won't return any error.
+    #[allow(clippy::unnecessary_wraps)]
+    #[allow(clippy::unused_self)]
+    pub fn flush(&mut self) -> io::Result<()> {
+        Ok(())
+    }
+
+    #[must_use]
+    pub fn as_vec(&self) -> Vec<u8> {
+        self.buffer.iter().copied().collect()
+    }
+}

tests/servers/api/v1/contract/authentication.rs

@@ -1,18 +1,12 @@
 use torrust_tracker_test_helpers::configuration;
-use tracing::level_filters::LevelFilter;
 
 use crate::common::http::{Query, QueryParam};
-use crate::common::logging::{tracing_stderr_init, INIT};
 use crate::servers::api::v1::asserts::{assert_token_not_valid, assert_unauthorized};
 use crate::servers::api::v1::client::Client;
 use crate::servers::api::Started;
 
 #[tokio::test]
 async fn should_authenticate_requests_by_using_a_token_query_param() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     let env = Started::new(&configuration::ephemeral().into()).await;
 
     let token = env.get_connection_info().api_token.unwrap();
@@ -28,10 +22,6 @@ async fn should_authenticate_requests_by_using_a_token_query_param() {
 
 #[tokio::test]
 async fn should_not_authenticate_requests_when_the_token_is_missing() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     let env = Started::new(&configuration::ephemeral().into()).await;
 
     let response = Client::new(env.get_connection_info())
@@ -45,10 +35,6 @@ async fn should_not_authenticate_requests_when_the_token_is_missing() {
 
 #[tokio::test]
 async fn should_not_authenticate_requests_when_the_token_is_empty() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     let env = Started::new(&configuration::ephemeral().into()).await;
 
     let response = Client::new(env.get_connection_info())
@@ -62,10 +48,6 @@ async fn should_not_authenticate_requests_when_the_token_is_empty() {
 
 #[tokio::test]
 async fn should_not_authenticate_requests_when_the_token_is_invalid() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     let env = Started::new(&configuration::ephemeral().into()).await;
 
     let response = Client::new(env.get_connection_info())
@@ -79,10 +61,6 @@ async fn should_not_authenticate_requests_when_the_token_is_invalid() {
 
 #[tokio::test]
 async fn should_allow_the_token_query_param_to_be_at_any_position_in_the_url_query() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     let env = Started::new(&configuration::ephemeral().into()).await;
 
     let token = env.get_connection_info().api_token.unwrap();

tests/servers/api/v1/contract/configuration.rs

@@ -7,18 +7,10 @@
 // use crate::common::app::setup_with_configuration;
 // use crate::servers::api::environment::stopped_environment;
 
-use tracing::level_filters::LevelFilter;
-
-use crate::common::logging::{tracing_stderr_init, INIT};
-
 #[tokio::test]
 #[ignore]
 #[should_panic = "Could not receive bind_address."]
 async fn should_fail_with_ssl_enabled_and_bad_ssl_config() {
-    INIT.call_once(|| {
-        tracing_stderr_init(LevelFilter::ERROR);
-    });
-
     // let tracker = setup_with_configuration(&Arc::new(configuration::ephemeral()));
 
     // let config = tracker.config.http_api.clone();
@@ -36,6 +28,5 @@ async fn should_fail_with_ssl_enabled_and_bad_ssl_config() {
     //     };
 
     // let env = new_stopped(tracker, bind_to, tls);
-
     // env.start().await;
 }