Skip to content

Commit

Permalink
test: capture logs in tests
Browse files Browse the repository at this point in the history
This feature will be used in the future to write assertions about logs.

It also changes when we show logs running tests. If you run tests with:

```console
cargo test
```

logs win't be showed. If you want to see logs you have to execute tests
with:

```console
cargo test -- --nocapture
```
  • Loading branch information
josecelano committed Dec 23, 2024
1 parent 4a9dcef commit d11ab32
Show file tree
Hide file tree
Showing 15 changed files with 302 additions and 438 deletions.
7 changes: 6 additions & 1 deletion packages/test-helpers/src/configuration.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
9 changes: 6 additions & 3 deletions src/bootstrap/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
}

Expand All @@ -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(),
Expand Down
6 changes: 0 additions & 6 deletions tests/common/clock.rs
Original file line number Diff line number Diff line change
@@ -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();
Expand Down
166 changes: 146 additions & 20 deletions tests/common/logging.rs
Original file line number Diff line number Diff line change
@@ -1,30 +1,156 @@
#![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(10000, 200)))
}

pub fn setup() {
INIT.call_once(|| {
tracing_init(LevelFilter::ERROR, &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 texts passed.
///
/// # Panics
///
/// Will panic if it can't get the lock for the global buffer or convert it into
/// a vec.
#[must_use]
#[allow(dead_code)]
pub fn logs_contains_a_line_with(texts: &[&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(line, texts) {
return true;
}
}

false
}

#[allow(dead_code)]
fn contains(text: &str, texts: &[&str]) -> bool {
texts.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()
}
}
23 changes: 6 additions & 17 deletions tests/servers/api/v1/contract/authentication.rs
Original file line number Diff line number Diff line change
@@ -1,17 +1,14 @@
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::common::logging::{self};
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);
});
logging::setup();

let env = Started::new(&configuration::ephemeral().into()).await;

Expand All @@ -28,9 +25,7 @@ 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);
});
logging::setup();

let env = Started::new(&configuration::ephemeral().into()).await;

Expand All @@ -45,9 +40,7 @@ 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);
});
logging::setup();

let env = Started::new(&configuration::ephemeral().into()).await;

Expand All @@ -62,9 +55,7 @@ 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);
});
logging::setup();

let env = Started::new(&configuration::ephemeral().into()).await;

Expand All @@ -79,9 +70,7 @@ 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);
});
logging::setup();

let env = Started::new(&configuration::ephemeral().into()).await;

Expand Down
9 changes: 0 additions & 9 deletions tests/servers/api/v1/contract/configuration.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -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;
}
Loading

0 comments on commit d11ab32

Please sign in to comment.