Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Two of the tests appear to be susceptible to race conditions #28

Open
ctsrc opened this issue Mar 21, 2020 · 2 comments
Open

Two of the tests appear to be susceptible to race conditions #28

ctsrc opened this issue Mar 21, 2020 · 2 comments

Comments

@ctsrc
Copy link

ctsrc commented Mar 21, 2020

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.

@ctsrc
Copy link
Author

ctsrc commented Mar 21, 2020

I have a couple of suggestions for making some changes to the tests, and can submit a PR for that, but wanted to get your feedback on my initial impression and questions about these two tests first.

@octplane
Copy link
Owner

Hey @ctsrc , thanks for the feedback. From my analysis, the fact:

  • That they observe folders which have been created before the start of the test seems curious
  • And that they seem to test 3 times the same IS_DIR ITEM_CREATED feels a bit redundant

So if you have something in mind, I'll gladly have look and integrate your changes!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants