Skip to content

Commit 90f6a01

Browse files
committed
Merge #1149: New feature: capture recent logs for testing (rework)
d11ab32 test: capture logs in tests (Jose Celano) Pull request description: Relates to: - #1069 - #1148 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 won't be shown. If you want to see the logs you have to execute tests with: ```console cargo test -- --nocapture ``` ACKs for top commit: josecelano: ACK d11ab32 Tree-SHA512: d4a11d899b7c0bd005c5e3b518eec89487ec12eac9535fcb5dca8684f1ea4075e706d51178df9e67d01b359c0221d0926e77159797d9d9c53083f4b56a9ee904
2 parents 4a9dcef + d11ab32 commit 90f6a01

File tree

15 files changed

+302
-438
lines changed

15 files changed

+302
-438
lines changed

packages/test-helpers/src/configuration.rs

+6-1
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,12 @@ pub fn ephemeral() -> Configuration {
2929

3030
let mut config = Configuration::default();
3131

32-
config.logging.threshold = Threshold::Off; // It should always be off here, the tests manage their own logging.
32+
// This have to be Off otherwise the tracing global subscriber
33+
// initialization will panic because you can't set a global subscriber more
34+
// than once. You can use enable logging in tests with:
35+
// `crate::common::logging::setup(LevelFilter::ERROR);`
36+
// That will also allow you to capture logs and write assertions on them.
37+
config.logging.threshold = Threshold::Off;
3338

3439
// Ephemeral socket address for API
3540
let api_port = 0u16;

src/bootstrap/logging.rs

+6-3
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ pub fn setup(cfg: &Configuration) {
2828
}
2929

3030
INIT.call_once(|| {
31-
tracing_stdout_init(tracing_level, &TraceStyle::Default);
31+
tracing_init(tracing_level, &TraceStyle::Default);
3232
});
3333
}
3434

@@ -43,8 +43,11 @@ fn map_to_tracing_level_filter(threshold: &Threshold) -> LevelFilter {
4343
}
4444
}
4545

46-
fn tracing_stdout_init(filter: LevelFilter, style: &TraceStyle) {
47-
let builder = tracing_subscriber::fmt().with_max_level(filter).with_ansi(true);
46+
fn tracing_init(filter: LevelFilter, style: &TraceStyle) {
47+
let builder = tracing_subscriber::fmt()
48+
.with_max_level(filter)
49+
.with_ansi(true)
50+
.with_test_writer();
4851

4952
let () = match style {
5053
TraceStyle::Default => builder.init(),

tests/common/clock.rs

-6
Original file line numberDiff line numberDiff line change
@@ -1,17 +1,11 @@
11
use std::time::Duration;
22

33
use torrust_tracker_clock::clock::Time;
4-
use tracing::level_filters::LevelFilter;
54

6-
use crate::common::logging::{tracing_stderr_init, INIT};
75
use crate::CurrentClock;
86

97
#[test]
108
fn it_should_use_stopped_time_for_testing() {
11-
INIT.call_once(|| {
12-
tracing_stderr_init(LevelFilter::ERROR);
13-
});
14-
159
assert_eq!(CurrentClock::dbg_clock_type(), "Stopped".to_owned());
1610

1711
let time = CurrentClock::now();

tests/common/logging.rs

+146-20
Original file line numberDiff line numberDiff line change
@@ -1,30 +1,156 @@
1-
#![allow(clippy::doc_markdown)]
2-
//! Logging for the Integration Tests
3-
//!
4-
//! Tests should start their own logging.
5-
//!
6-
//! To find tests that do not start their own logging:
7-
//!
8-
//! ´´´ sh
9-
//! 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")
10-
//! ´´´
11-
//!
12-
13-
use std::sync::Once;
1+
//! Setup for logging in tests.
2+
use std::collections::VecDeque;
3+
use std::io;
4+
use std::sync::{Mutex, MutexGuard, Once, OnceLock};
145

6+
use torrust_tracker::bootstrap::logging::TraceStyle;
157
use tracing::level_filters::LevelFilter;
8+
use tracing_subscriber::fmt::MakeWriter;
169

17-
#[allow(dead_code)]
18-
pub static INIT: Once = Once::new();
10+
static INIT: Once = Once::new();
11+
12+
/// A global buffer containing the latest lines captured from logs.
13+
#[doc(hidden)]
14+
pub fn captured_logs_buffer() -> &'static Mutex<CircularBuffer> {
15+
static CAPTURED_LOGS_GLOBAL_BUFFER: OnceLock<Mutex<CircularBuffer>> = OnceLock::new();
16+
CAPTURED_LOGS_GLOBAL_BUFFER.get_or_init(|| Mutex::new(CircularBuffer::new(10000, 200)))
17+
}
18+
19+
pub fn setup() {
20+
INIT.call_once(|| {
21+
tracing_init(LevelFilter::ERROR, &TraceStyle::Default);
22+
});
23+
}
24+
25+
fn tracing_init(level_filter: LevelFilter, style: &TraceStyle) {
26+
let mock_writer = LogCapturer::new(captured_logs_buffer());
1927

20-
#[allow(dead_code)]
21-
pub fn tracing_stderr_init(filter: LevelFilter) {
2228
let builder = tracing_subscriber::fmt()
23-
.with_max_level(filter)
29+
.with_max_level(level_filter)
2430
.with_ansi(true)
25-
.with_writer(std::io::stderr);
31+
.with_test_writer()
32+
.with_writer(mock_writer);
2633

27-
builder.pretty().with_file(true).init();
34+
let () = match style {
35+
TraceStyle::Default => builder.init(),
36+
TraceStyle::Pretty(display_filename) => builder.pretty().with_file(*display_filename).init(),
37+
TraceStyle::Compact => builder.compact().init(),
38+
TraceStyle::Json => builder.json().init(),
39+
};
2840

2941
tracing::info!("Logging initialized");
3042
}
43+
44+
/// It returns true is there is a log line containing all the texts passed.
45+
///
46+
/// # Panics
47+
///
48+
/// Will panic if it can't get the lock for the global buffer or convert it into
49+
/// a vec.
50+
#[must_use]
51+
#[allow(dead_code)]
52+
pub fn logs_contains_a_line_with(texts: &[&str]) -> bool {
53+
// code-review: we can search directly in the buffer instead of converting
54+
// the buffer into a string but that would slow down the tests because
55+
// cloning should be faster that locking the buffer for searching.
56+
// Because the buffer is not big.
57+
let logs = String::from_utf8(captured_logs_buffer().lock().unwrap().as_vec()).unwrap();
58+
59+
for line in logs.split('\n') {
60+
if contains(line, texts) {
61+
return true;
62+
}
63+
}
64+
65+
false
66+
}
67+
68+
#[allow(dead_code)]
69+
fn contains(text: &str, texts: &[&str]) -> bool {
70+
texts.iter().all(|&word| text.contains(word))
71+
}
72+
73+
/// A tracing writer which captures the latests logs lines into a buffer.
74+
/// It's used to capture the logs in the tests.
75+
#[derive(Debug)]
76+
pub struct LogCapturer<'a> {
77+
logs: &'a Mutex<CircularBuffer>,
78+
}
79+
80+
impl<'a> LogCapturer<'a> {
81+
pub fn new(buf: &'a Mutex<CircularBuffer>) -> Self {
82+
Self { logs: buf }
83+
}
84+
85+
fn buf(&self) -> io::Result<MutexGuard<'a, CircularBuffer>> {
86+
self.logs.lock().map_err(|_| io::Error::from(io::ErrorKind::Other))
87+
}
88+
}
89+
90+
impl io::Write for LogCapturer<'_> {
91+
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
92+
print!("{}", String::from_utf8(buf.to_vec()).unwrap());
93+
94+
let mut target = self.buf()?;
95+
96+
target.write(buf)
97+
}
98+
99+
fn flush(&mut self) -> io::Result<()> {
100+
self.buf()?.flush()
101+
}
102+
}
103+
104+
impl MakeWriter<'_> for LogCapturer<'_> {
105+
type Writer = Self;
106+
107+
fn make_writer(&self) -> Self::Writer {
108+
LogCapturer::new(self.logs)
109+
}
110+
}
111+
112+
#[derive(Debug)]
113+
pub struct CircularBuffer {
114+
max_size: usize,
115+
buffer: VecDeque<u8>,
116+
}
117+
118+
impl CircularBuffer {
119+
#[must_use]
120+
pub fn new(max_lines: usize, average_line_size: usize) -> Self {
121+
Self {
122+
max_size: max_lines * average_line_size,
123+
buffer: VecDeque::with_capacity(max_lines * average_line_size),
124+
}
125+
}
126+
127+
/// # Errors
128+
///
129+
/// Won't return any error.
130+
#[allow(clippy::unnecessary_wraps)]
131+
pub fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
132+
for &byte in buf {
133+
if self.buffer.len() == self.max_size {
134+
// Remove oldest byte to make space
135+
self.buffer.pop_front();
136+
}
137+
self.buffer.push_back(byte);
138+
}
139+
140+
Ok(buf.len())
141+
}
142+
143+
/// # Errors
144+
///
145+
/// Won't return any error.
146+
#[allow(clippy::unnecessary_wraps)]
147+
#[allow(clippy::unused_self)]
148+
pub fn flush(&mut self) -> io::Result<()> {
149+
Ok(())
150+
}
151+
152+
#[must_use]
153+
pub fn as_vec(&self) -> Vec<u8> {
154+
self.buffer.iter().copied().collect()
155+
}
156+
}

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

+6-17
Original file line numberDiff line numberDiff line change
@@ -1,17 +1,14 @@
11
use torrust_tracker_test_helpers::configuration;
2-
use tracing::level_filters::LevelFilter;
32

43
use crate::common::http::{Query, QueryParam};
5-
use crate::common::logging::{tracing_stderr_init, INIT};
4+
use crate::common::logging::{self};
65
use crate::servers::api::v1::asserts::{assert_token_not_valid, assert_unauthorized};
76
use crate::servers::api::v1::client::Client;
87
use crate::servers::api::Started;
98

109
#[tokio::test]
1110
async fn should_authenticate_requests_by_using_a_token_query_param() {
12-
INIT.call_once(|| {
13-
tracing_stderr_init(LevelFilter::ERROR);
14-
});
11+
logging::setup();
1512

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

@@ -28,9 +25,7 @@ async fn should_authenticate_requests_by_using_a_token_query_param() {
2825

2926
#[tokio::test]
3027
async fn should_not_authenticate_requests_when_the_token_is_missing() {
31-
INIT.call_once(|| {
32-
tracing_stderr_init(LevelFilter::ERROR);
33-
});
28+
logging::setup();
3429

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

@@ -45,9 +40,7 @@ async fn should_not_authenticate_requests_when_the_token_is_missing() {
4540

4641
#[tokio::test]
4742
async fn should_not_authenticate_requests_when_the_token_is_empty() {
48-
INIT.call_once(|| {
49-
tracing_stderr_init(LevelFilter::ERROR);
50-
});
43+
logging::setup();
5144

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

@@ -62,9 +55,7 @@ async fn should_not_authenticate_requests_when_the_token_is_empty() {
6255

6356
#[tokio::test]
6457
async fn should_not_authenticate_requests_when_the_token_is_invalid() {
65-
INIT.call_once(|| {
66-
tracing_stderr_init(LevelFilter::ERROR);
67-
});
58+
logging::setup();
6859

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

@@ -79,9 +70,7 @@ async fn should_not_authenticate_requests_when_the_token_is_invalid() {
7970

8071
#[tokio::test]
8172
async fn should_allow_the_token_query_param_to_be_at_any_position_in_the_url_query() {
82-
INIT.call_once(|| {
83-
tracing_stderr_init(LevelFilter::ERROR);
84-
});
73+
logging::setup();
8574

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

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

-9
Original file line numberDiff line numberDiff line change
@@ -7,18 +7,10 @@
77
// use crate::common::app::setup_with_configuration;
88
// use crate::servers::api::environment::stopped_environment;
99

10-
use tracing::level_filters::LevelFilter;
11-
12-
use crate::common::logging::{tracing_stderr_init, INIT};
13-
1410
#[tokio::test]
1511
#[ignore]
1612
#[should_panic = "Could not receive bind_address."]
1713
async fn should_fail_with_ssl_enabled_and_bad_ssl_config() {
18-
INIT.call_once(|| {
19-
tracing_stderr_init(LevelFilter::ERROR);
20-
});
21-
2214
// let tracker = setup_with_configuration(&Arc::new(configuration::ephemeral()));
2315

2416
// let config = tracker.config.http_api.clone();
@@ -36,6 +28,5 @@ async fn should_fail_with_ssl_enabled_and_bad_ssl_config() {
3628
// };
3729

3830
// let env = new_stopped(tracker, bind_to, tls);
39-
4031
// env.start().await;
4132
}

0 commit comments

Comments
 (0)