Two of the tests appear to be susceptible to race conditions #28
Description
Two of the tests appear to be susceptible to race conditions.
With the current head of master – the tree at 8b1698e – on macOS Catalina with Rust 1.41.0, after initial cloning of the fsevent-rust repository and first run of cargo test, two of the tests failed.
The tests that failed were observe_folder_async and observe_folder_sync. The test output from that initial invocation of cargo test was:
Compiling libc v0.2.68
Compiling getrandom v0.1.14
Compiling cfg-if v0.1.10
Compiling ppv-lite86 v0.2.6
Compiling bitflags v1.2.1
Compiling remove_dir_all v0.5.2
Compiling fsevent-sys v3.0.0
Compiling time v0.1.42
Compiling fsevent v2.0.1 (/Users/erikn/src/github.com/octplane/fsevent-rust)
Compiling rand_core v0.5.1
Compiling rand_chacha v0.2.2
Compiling rand v0.7.3
Compiling tempfile v3.1.0
Finished test [unoptimized + debuginfo] target(s) in 10.76s
Running target/debug/deps/fsevent-ce679260b5d6056f
running 0 tests
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
Running target/debug/deps/fsevent-a3719c7d2dc1d40b
running 4 tests
test observe_folder_sync ... FAILED
test observe_folder_async ... FAILED
test validate_watch_single_file_sync ... ok
test validate_watch_single_file_async ... ok
failures:
---- observe_folder_sync stdout ----
thread 'observe_folder_sync' panicked at 'Some expected events did not occur before the test timedout:
[("/private/var/folders/97/2k44164n2s9c3_c9zydgdz_80000gn/T/durj2526W/dest1", ITEM_CREATED | IS_DIR), ("/private/var/folders/97/2k44164n2s9c3_c9zydgdz_80000gn/T/durj2526W/dest2", ITEM_CREATED | IS_DIR)]', tests/fsevent.rs:45:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
---- observe_folder_async stdout ----
thread 'observe_folder_async' panicked at 'Some expected events did not occur before the test timedout:
[("/private/var/folders/97/2k44164n2s9c3_c9zydgdz_80000gn/T/duru38162/dest1", ITEM_CREATED | IS_DIR)]', tests/fsevent.rs:45:5
failures:
observe_folder_async
observe_folder_sync
test result: FAILED. 2 passed; 2 failed; 0 ignored; 0 measured; 0 filtered out
error: test failed, to rerun pass '--test fsevent'
Notice that the failure output of one of the tests mentions "dest1" and "dest2", and the failure output of the other test mentions "dest1".
Looking at the tests, we have:
#[test]
fn observe_folder_sync() {
internal_observe_folder(false);
}and
#[test]
fn observe_folder_async() {
internal_observe_folder(true);
}Looking then at internal_observe_folder, we have:
fn internal_observe_folder(run_async: bool) {Inside of which, first a bunch of directories are created
let dir = tempfile::Builder::new().prefix("dur").tempdir().unwrap();
// Resolve path so we don't have to worry about affect of symlinks on the test.
let dst = resolve_path(dir.path().to_str().unwrap());
let mut dst1 = dst.clone();
dst1.push("dest1");
let ddst1 = dst1.clone();
fs::create_dir(dst1.as_path().to_str().unwrap()).unwrap();
let mut dst2 = dst.clone();
dst2.push("dest2");
let ddst2 = dst2.clone();
fs::create_dir(dst2.as_path().to_str().unwrap()).unwrap();
let mut dst3 = dst.clone();
dst3.push("dest3");
let ddst3 = dst3.clone();
fs::create_dir(dst3.as_path().to_str().unwrap()).unwrap();Then a channel is created, and the directories are observed
let (sender, receiver) = channel();
let mut async_fsevent = fsevent::FsEvent::new(vec![]);
let fsevent_ref_wrapper = if run_async {
async_fsevent
.append_path(dst1.as_path().to_str().unwrap())
.unwrap();
async_fsevent
.append_path(dst2.as_path().to_str().unwrap())
.unwrap();
async_fsevent
.append_path(dst3.as_path().to_str().unwrap())
.unwrap();
Some(async_fsevent.observe_async(sender).unwrap())
} else {
let _t = thread::spawn(move || {
let mut fsevent = fsevent::FsEvent::new(vec![]);
fsevent
.append_path(dst1.as_path().to_str().unwrap())
.unwrap();
fsevent
.append_path(dst2.as_path().to_str().unwrap())
.unwrap();
fsevent
.append_path(dst3.as_path().to_str().unwrap())
.unwrap();
fsevent.observe(sender);
});
None
};
Then, it proceeds to attempt to validate that it received the ITEM_CREATED events for the directories it was watching (and then after that there is the shutdown stuff for the async observer).
validate_recv(
receiver,
vec![
(
ddst1.to_str().unwrap().to_string(),
StreamFlags::ITEM_CREATED | StreamFlags::IS_DIR,
),
(
ddst2.to_str().unwrap().to_string(),
StreamFlags::ITEM_CREATED | StreamFlags::IS_DIR,
),
(
ddst3.to_str().unwrap().to_string(),
StreamFlags::ITEM_CREATED | StreamFlags::IS_DIR,
),
],
);
match fsevent_ref_wrapper {
Some(r) => async_fsevent.shutdown_observe(r),
None => {}
}
}
But keep in mind that the directory creation was initiated prior to watching those paths.
Upon subsequently running the tests again a few times, both with and without doing a rebuild of the tests themselves in-between, all four tests passed.
But from the initial failure that I saw, and from the code I quoted above, this looks like a case of susceptibility to race conditions to me.
Also, the test case seems a little odd to me. Is there a particular reason for subscribing to events on all three of those the paths "dest1", "dest2" and "dest3" rather than subscribing to none of those and instead subscribing to the initial temporary directory that is created (dst) before creating dst1, dst2 and dst3 and then verifying that the creation of dst1, dst2 and dst3 is seen from the observer of dst? I am thinking that I might be missing something here.