test-fs-watch-latency.js

var fs = require('fs');
var path = require('path');

/*
This test is designed for Windows, and tests whether changed folder events
are emitted on time or after several seconds delay (up to 40 seconds or more).

This requires renaming a file at least two subfolders deep relative to the
watched folder. Renaming a file only one subfolder deep will not reproduce
the slow behavior.

After renaming [watched]/a/b/source to [watched]/target we expect these path
events to be emitted fairly close in time to each other, at least a few 100ms:

null - this is for the removed source path (null for fs.watch on Windows)
target - this is for the created target path (there may be several of these)
a\b - this is for the changed subfolder path from which the source was removed

What happens instead when the bug is triggered:
"null" and "target" are emitted shortly after renaming.
"a\b" is emitted several seconds later, even tens of seconds after renaming.

Reproducible at least on Windows 10 in a Parallels VM.

On Windows 7 in a Parallels VM, only two "target" events are received.
"null" and "a\b" are never emitted.
*/

var watched = path.join(process.cwd(), 'test-fs-watch-latency-directory');
var a = path.join(watched, 'a');
var b = path.join(watched, 'a', 'b');
var source = path.join(b, 'source');
var target = path.join(watched, 'target');

function log(string) {
  console.log(new Date().toISOString() + ' ' + string);
}

function relative(to) {
  if (to === watched) {
    var base = process.cwd();
  } else {
    var base = process.cwd();
  }
  return '.' + path.sep + path.relative(base, to);
}

function prepare(end) {
  log('preparing directory structure...');
  log('fs.mkdir ' + relative(watched));
  fs.mkdir(watched,
    function(error) {
      if (error && error.code === 'EEXIST') error = null;
      if (error) return end(error);
      log('fs.mkdir ' + relative(a));
      fs.mkdir(a,
        function(error) {
          if (error && error.code === 'EEXIST') error = null;
          if (error) return end(error);
          log('fs.mkdir ' + relative(b));
          fs.mkdir(b,
            function(error) {
              if (error && error.code === 'EEXIST') error = null;
              if (error) return end(error);
              unlink(
                function(error) {
                  if (error) return end(error);
                  // File size appears to be irrelevant to the test.
                  log('fs.writeFile ' + relative(source) + ' (0 bytes)');
                  fs.writeFile(source, '',
                    function(error) {
                      if (error) return end(error);
                      var message = '';
                      message += 'waiting 10 seconds before creating ';
                      message += 'fs.watch to prevent spurious events...';
                      log(message);
                      setTimeout(end, 10000);
                    }
                  );
                }
              );
            }
          );
        }
      );
    }
  );
}

function unlink(end) {
  log('fs.unlink ' + relative(source));
  fs.unlink(source,
    function(error) {
      if (error && error.code === 'ENOENT') error = null;
      if (error) return end(error);
      log('fs.unlink ' + relative(target));
      fs.unlink(target,
        function(error) {
          if (error && error.code === 'ENOENT') error = null;
          if (error) return end(error);
          end();
        }
      );
    }
  );
}

function cleanup() {
  function end(error) {
    if (error) throw error;
    process.exit();
  }
  log('cleaning up...');
  setTimeout(
    function() {
      if (watch) watch.close();
      unlink(
        function(error) {
          if (error) return end(error);
          log('fs.rmdir ' + relative(b));
          fs.rmdir(b,
            function(error) {
              if (error && error.code === 'ENOENT') error = null;
              if (error) return end(error);
              log('fs.rmdir ' + relative(a));
              fs.rmdir(a,
                function(error) {
                  if (error && error.code === 'ENOENT') error = null;
                  if (error) return end(error);
                  log('fs.rmdir ' + relative(watched));
                  fs.rmdir(watched,
                    function(error) {
                      if (error && error.code === 'ENOENT') error = null;
                      if (error) return end(error);
                      end();
                    }
                  );
                }
              );
            }
          );
        }
      );
    },
    3000 // Try not to cause an alert on Windows if user has a/b open in Explorer.
  );
}

function onChange(binaryPath) {
  log('change event: ' + binaryPath);
  if (received === undefined) {
    if (binaryPath === path.join('a', 'b') || binaryPath === path.join('a', 'b', 'source')) {
      received = Date.now();
      log('received "' + binaryPath + '" changed event after ' + (received - issued) + 'ms.');
      cleanup();
    }
  }
}

var watch;
var issued;
var received;

prepare(
  function(error) {
    if (error) throw error;
    log('creating recursive fs.watch on ' + relative(watched));
    watch = fs.watch(watched, { recursive: true });
    watch.on('change',
      function(change, binaryPath) {
        onChange(binaryPath);
      }
    );
    watch.on('error',
      function(error) {
        throw error;
      }
    );
    log('waiting 10 seconds for fs.watch to open handle...');
    setTimeout(
      function() {
        log('renaming source > target...');
        log('fs.rename ' + relative(source) + ' > ' + relative(target));
        setTimeout(
          function() {
            if (received === undefined) {
              log('still waiting for source directory/file changed event after 3 seconds...');
              log('try navigating to "' + relative(b) + '" in Windows Explorer to trigger the delayed event...');
              log('going to wait for at most 5 minutes...');
            }
          },
          3 * 1000
        );
        setTimeout(
          function() {
            if (received === undefined) {
              log('still waiting for source directory/file changed event after 5 minutes...');
              cleanup();
            }
          },
          5 * 60 * 1000 // It can really take this long on Windows 10 (although Windows 7 never gets it).
        );
        issued = Date.now();
        fs.rename(source, target,
          function(error) {
            if (error) throw error;
          }
        );
      },
      10000
    );
  }
);