Skip to content

Commit

Permalink
Fix a race condition in test_multi_threaded_dates
Browse files Browse the repository at this point in the history
If a worker thread takes less than 500 ms, this test fails due to
missing MUST_BE_PRINTED lines. This is because the main thread sleeps
500 ms before setting a new spec for trace!.

```
XXXXX [2024-09-02 09:55:33.010986 +00:00] T["test_multi_threaded_dates"] INFO [tests/test_multi_threaded_dates.rs:41] create many log lines with a considerable number of threads, verify the log
XXXXX [2024-09-02 09:55:33.514113 +00:00] T["test_multi_threaded_dates"] INFO [tests/test_utils.rs:81] Task executed in 503 ms.
test test_multi_threaded_dates ... FAILED

failures:

---- test_multi_threaded_dates stdout ----
thread 'test_multi_threaded_dates' panicked at tests/test_multi_threaded_dates.rs:139:5:
assertion `left == right` failed
  left: 100003
 right: 100008
```
  • Loading branch information
sepeth committed Sep 2, 2024
1 parent a13c0dc commit 33bf703
Showing 1 changed file with 24 additions and 10 deletions.
34 changes: 24 additions & 10 deletions tests/test_multi_threaded_dates.rs
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ use std::fs::File;
use std::io::{BufRead, BufReader};
use std::ops::Add;
use std::thread::JoinHandle;
use std::sync::{Arc, Mutex, Condvar};

const NO_OF_THREADS: usize = 5;
const NO_OF_LOGLINES_PER_THREAD: usize = 20_000;
Expand Down Expand Up @@ -38,11 +39,20 @@ fn test_multi_threaded_dates() {
.start()
.unwrap_or_else(|e| panic!("Logger initialization failed with {e}"));

let mtx_cvar_pair = Arc::new((Mutex::new(0), Condvar::new()));

info!("create many log lines with a considerable number of threads, verify the log");

let worker_handles = start_worker_threads(NO_OF_THREADS);
let worker_handles = start_worker_threads(NO_OF_THREADS, mtx_cvar_pair.clone());

{
let (mtx, cvar) = &*mtx_cvar_pair;
let mut started = mtx.lock().unwrap();
while *started != NO_OF_THREADS {
started = cvar.wait(started).unwrap();
}
}

std::thread::sleep(std::time::Duration::from_millis(500));
logger.set_new_spec(LogSpecification::parse("trace").unwrap());

wait_for_workers_to_close(worker_handles);
Expand All @@ -52,16 +62,17 @@ fn test_multi_threaded_dates() {
}

// Starts given number of worker threads and lets each execute `do_work`
fn start_worker_threads(no_of_workers: usize) -> Vec<JoinHandle<u8>> {
fn start_worker_threads(no_of_workers: usize, mtx_cvar_pair: Arc<(Mutex<usize>,Condvar)>) -> Vec<JoinHandle<u8>> {
let mut worker_handles: Vec<JoinHandle<u8>> = Vec::with_capacity(no_of_workers);
trace!("Starting {} worker threads", no_of_workers);
for thread_number in 0..no_of_workers {
trace!("Starting thread {}", thread_number);
let thread_mtx_cvar_pair = mtx_cvar_pair.clone();
worker_handles.push(
std::thread::Builder::new()
.name(thread_number.to_string())
.spawn(move || {
do_work(thread_number);
do_work(thread_number, thread_mtx_cvar_pair);
0
})
.unwrap(),
Expand All @@ -71,15 +82,18 @@ fn start_worker_threads(no_of_workers: usize) -> Vec<JoinHandle<u8>> {
worker_handles
}

fn do_work(thread_number: usize) {
fn do_work(thread_number: usize, mtx_cvar_pair: Arc<(Mutex<usize>,Condvar)>) {
trace!("({}) Thread started working", thread_number);
trace!("ERROR_IF_PRINTED");

{
let (mtx, cvar) = &*mtx_cvar_pair;
let mut started = mtx.lock().unwrap();
*started += 1;
cvar.notify_one();
}

for idx in 0..NO_OF_LOGLINES_PER_THREAD {
if idx == 500 {
// this sleep triggers a yield, hopefully allowing all threads to start before the main thread
// changes the log specification
std::thread::sleep(std::time::Duration::from_millis(200));
}
debug!("({}) writing out line number {}", thread_number, idx);
}
trace!("MUST_BE_PRINTED");
Expand Down

0 comments on commit 33bf703

Please sign in to comment.