test: refactor test-fs-watch

[Trott]

• Exchange 20 millisecond timers for setImmediate().
• Do not attempt to unlink path that will have been guaranteed to be
  removed by common.refreshTmpDir()
• Do not swallow errors thrown by failed creation of needed test
  subdirectory. If that happens, we want to know about it.
• Use common.isSunOS in one place where it is applicable

[Trott]

CI: https://ci.nodejs.org/job/node-test-pull-request/1312/

I started looking at the test because it timed out on FreeBSD in a CI run with an unrelated change. If nothing else, this change does eliminate some error-swallowing which might mean we get more info if it fails again.

[evanlucas]

This is a test I see fail pretty regularly locally. Pulled down the changes and haven't seen a fail yet.

Awesome job @Trott!!!

LGTM if CI is happy

[santigimeno]

This is great! Without this patch the test is failing in my FreeBSD VM quite easily, with the patch I can't make it fail.

One question: does this mean a timer (setTimeout) can fire before setImmediate? I thought they were fired afterwards.

Probably the same fix could be applied for #4629 and other fs-watch tests?

[cjihrig]

LGTM. Maybe run the CI again though.

[Trott]

@santigimeno A setTimeout() can fire before a setImmediate(). It does so for me reliably with this code:

const immediate = () => { console.log('immediate'); };
const timeout = () => { console.log('timeout'); };

setTimeout(timeout, 1);
setImmediate(immediate);

@cjihrig While all the CI failures are build failures unrelated to the test, I sure do like green, so let's try again:

https://ci.nodejs.org/job/node-test-pull-request/1319/

[Trott]

CI is green. \o/

[santigimeno]

@Trott I see, thanks for the info.
I'm still trying to understand why using setImmediate fixes the issue. Does it have anything to do with when in the event loop the setImmediate callbacks are fired that makes sure the fs event is registered? or is there still a race condition only that it's harder to make test fail? or something else? Thanks in advance

[Trott]

@santigimeno:

I'm still trying to understand why using setImmediate fixes the issue.

Can you confirm that it's the setImmediate() calls that fix the issue by running the current test with just the setTimeout() calls changed to setImmediate()? Maybe it's the removal of the unlinkSync() instead or something else. Maybe let's confirm what aspect of the refactor is really fixing things...

[santigimeno]

@Trott I can confirm that in a FreeBSD VM:

• Only removing the unlinkSync(): the test failed after ~ 300 executions.
• Only replacing SetTimeout with SetImmediate: the test didn't fail after ~ 10000 executions.

[Trott]

@santigimeno And the failure is that the test hangs/times out? Or is there an assertion error or something?

[Trott]

@santigimeno If it helps clarify things, setTimeout() timers that will fire on the next tick can (will?) execute before those created with setImmediate(). So if there's something async happening in fs.watch(), it's possible that setImmediate() gives fs.watch() a chance to do its thing first. With multiple 20ms timeouts being set, one or more are pretty much guaranteed to fire on the next tick. If that's the bug this change is fixing, then the issue I'd expect to see is the test hanging or timing out because the change occurs before the watcher is fully watching.

The problem with this theory is that I haven't located the asynchronous code in fs.watch() that would be involved in the race condition. But I also didn't look that hard (and I certainly didn't think about if it's possible that it's in libuv or the OS...)

[Trott]

@santigimeno Oh, wait, yeah, you identify the delay/asynchronous issue in #4629. Seems at least plausible to me.

[Trott]

Landed in d26b014

[santigimeno]

@Trott The failure was indeed a timeout.
Regarding the race condition, I think the problem may be similar to this issue in libuv: libuv/libuv#581.

[santigimeno]

I've got this error on OS X a couple of times running the test suite:

=== release test-fs-watch ===                                             
Path: sequential/test-fs-watch
assert.js:89
  throw new assert.AssertionError({
  ^
AssertionError: 'newfile.txt' == 'watch.txt'
    at FSWatcher.<anonymous> (/Users/sgimeno/node/node/test/sequential/test-fs-watch.js:89:18)
    at emitTwo (events.js:101:13)
    at FSWatcher.emit (events.js:186:7)
    at FSEvent.FSWatcher._handle.onchange (fs.js:1314:12)
Command: out/Release/node /Users/sgimeno/node/node/test/sequential/test-fs-watch.js

Something interesting is that when this test failed, in the same run also failed test-fe-watch-recursive as described in #4629

[Trott]

@santigimeno That's odd. Perhaps it might be a good idea to isolate the three tests in test-fs-watch by moving them to separate files.

[jasnell]

@Trott ... see any pressing need to backport this to LTS?

[Trott]

@jasnell Pressing need? No. But it if the commit merges cleanly, it's probably better to have it in LTS than not.

[jasnell]

+1... watch label added