test: fs_event_watch_dir fails on OSX about libuv HOT 19 CLOSED

What OSX version are you using? Can you consistently reproduce it in different runs?

from libuv.

yes i runned that a couple of times and got the same error.

OSX 10.9.5

from libuv.

( LOL: for your "bio" on your website. I got caught in an event loop and never got out )

from libuv.

I tried it on my 10.9.5 machine and it passes :/ This test has been known to fail under certain conditions, this probably means there is a race somewhere, but nobody has had the time / energy to hunt it down, I'm afraid.

from libuv.

🔍

from libuv.

I get the same failure on OS X 10.10.

from libuv.

I get the same failure on OS X 10.9.5.

[%  87|+ 221|-   0|T   0|S   0]: fs_event_watch_dir
`fs_event_watch_dir` failed: timeout
Output from process `fs_event_watch_dir`: (no output)

from libuv.

I just started looking into this and I was able to reproduce the flaky test failure on OS X but the failure is slightly different, but similar enough to report here. I am on OS X 10.10.4 and I ran the test suite a handful of times without a test failure. Then ran it a sixth time and fs_event_watch_dir_recursive failed. As I look into this, I will update you with anything I find.

from libuv.

@whitlockjc Good luck! Some people think it's a race condition.

from libuv.

Can someone apply the osx label? Also, what are the chances of getting a flaky-test label like in joyent/nodejs?

from libuv.

@whitlockjc Thanks for looking into this! I applied to "osx" label. We don't use "flaky-test" in libuv,it either passes, or it's a bug, like in this case :-)

from libuv.

Works for me.

from libuv.

Well, I've got some good news, I've figured out the cause of the race condition. fs_event_watch_dir uses fs_event_create_files to create some files, which drives the tests, and then schedules a timer to cleanup after itself. What can happen is you can end up with the cleanup callback (fs_event_unlink_files) running prior to all of the fs_event handler callbacks (as a result of the files being created) being processed. This is not the only race condition. The cleanup callback itself removes files, creating more fs_event, and then schedules another timer whose callback (fs_event_create_files) can run prior to all of the removal events being processed.

This will leave some fs_event handlers not having completed which keeps the event loop open, hence the timeout. fs_event_watch_dir_recursive is also flaky and happens to use the same testing logic so I think we should be able to fix both flaky tests in one pass using the same approach.

My plan is to refactor the tests to not use timers so this can be avoided. Once I've got this working, I will submit a PR. The way I validated this was keeping track of each of these callbacks, their order and such. I noticed that when things failed, not all fs_event handlers were processed. I bumped up the timers involved to use a timeout of 200ms instead of 50ms and the failures went away. I can run both flaky tests 1000 times without failure, where I use to run somewhere around 10 before I got the first failure. Below is the diff of my current changes which show this is clearly a timing issue:

diff --git a/test/test-fs-event.c b/test/test-fs-event.c
index f6c2214..245e550 100644
--- a/test/test-fs-event.c
+++ b/test/test-fs-event.c
@@ -195,7 +195,7 @@ static void fs_event_create_files(uv_timer_t* handle) {
     create_file(handle->loop, fs_event_get_filename(i));

   /* And unlink them */
-  ASSERT(0 == uv_timer_start(&timer, fs_event_unlink_files, 50, 0));
+  ASSERT(0 == uv_timer_start(&timer, fs_event_unlink_files, 200, 0));
 }

 static void fs_event_create_files_in_subdir(uv_timer_t* handle) {
@@ -212,7 +212,7 @@ static void fs_event_create_files_in_subdir(uv_timer_t* handle) {
     create_file(handle->loop, fs_event_get_filename_in_subdir(i));

   /* And unlink them */
-  ASSERT(0 == uv_timer_start(&timer, fs_event_unlink_files_in_subdir, 50, 0));
+  ASSERT(0 == uv_timer_start(&timer, fs_event_unlink_files_in_subdir, 200, 0));
 }

 void fs_event_unlink_files_in_subdir(uv_timer_t* handle) {
@@ -230,7 +230,7 @@ void fs_event_unlink_files_in_subdir(uv_timer_t* handle) {

   /* And create them again */
   if (handle != NULL)
-    ASSERT(0 == uv_timer_start(&timer, fs_event_create_files_in_subdir, 50, 0));
+    ASSERT(0 == uv_timer_start(&timer, fs_event_create_files_in_subdir, 200, 0));
 }

 void fs_event_unlink_files(uv_timer_t* handle) {
@@ -248,7 +248,7 @@ void fs_event_unlink_files(uv_timer_t* handle) {

   /* And create them again */
   if (handle != NULL)
-    ASSERT(0 == uv_timer_start(&timer, fs_event_create_files, 50, 0));
+    ASSERT(0 == uv_timer_start(&timer, fs_event_create_files, 200, 0));
 }

 static void fs_event_cb_file(uv_fs_event_t* handle, const char* filename,

/cc @indutny (The author of 0f5c28b)

from libuv.

What can happen is you can end up with the cleanup callback (fs_event_unlink_files) running prior to all of the fs_event handler callbacks (as a result of the files being created) being processed

How is this possible, if removing the files always happens 50ms after they where all created? I guess it's possible that if you create a file and remove it in less than 50ms you lose the event?

For this particular test, maybe we shouldn't have fs_event_unlink_files create more files after they have been removed.

My plan is to refactor the tests to not use timers so this can be avoided. Once I've got this working, I will submit a PR. The way I validated this was keeping track of each of these callbacks, their order and such.

Sounds like a plan! Thanks a lot for your help tracking this down!

from libuv.

No problem. As for your first question, you're right. What would happen is we'd create a file and remove it within 50ms and then we'd recreate it so the original handle was still open. It took a lot of debugging to find this but that's definitely the situation I was able to reproduce.

As for your suggestion, that's the first plan of attack...figure out a way to make new file creation happen in the proper place so these conditions can be avoided.

from libuv.

Good to know! Please add a note about this to the documentation when you
make the patch. Thanks!

On Fri, Aug 14, 2015 at 5:39 PM, Jeremy Whitlock [email protected]
wrote:

No problem. As for your first question, you're right. What would happen is
we'd create a file and remove it within 50ms and then we'd recreate it so
the original handle was still open. It took a lot of debugging to find this
but that's definitely the situation I was able to reproduce.

—
Reply to this email directly or view it on GitHub
#30 (comment).

/Saúl
bettercallsaghul.com

from libuv.

I've got a PR ready. What should the subsystem be? I'd figure tests since I'm only changing the tests but since this is related to fs events, it could be fs as well. Also, what documentation are you referring to?

from libuv.

"test,fs" will do.
On Aug 14, 2015 21:09, "Jeremy Whitlock" [email protected] wrote:

I've got a PR ready. What should the subsystem be? I'd figure tests since
I'm only changing the tests but since this is related to fs events, it
could be fs as well. Also, what documentation are you referring to?

—
Reply to this email directly or view it on GitHub
#30 (comment).

from libuv.

Fixed by #480.

from libuv.