Fix a flaky test and work around issue 16003 in pkg/watcher.

There's an additional flaky test that this CL is not likely to fix. Additional
debugging is added to help track down the cause of that flake.

R=rnystrom@google.com
BUG=16079

Review URL: https://codereview.chromium.org//134963007

git-svn-id: https://dart.googlecode.com/svn/branches/bleeding_edge/dart/pkg/watcher@31815 260f80e4-7a28-3924-810f-c04153c831b5
diff --git a/lib/src/directory_watcher/mac_os.dart b/lib/src/directory_watcher/mac_os.dart
index 17c25ad..bb82a4c 100644
--- a/lib/src/directory_watcher/mac_os.dart
+++ b/lib/src/directory_watcher/mac_os.dart
@@ -24,7 +24,7 @@
 /// succession, it won't report them in the order they occurred. See issue
 /// 14373.
 ///
-/// This also works around issue 14849 in the implementation of
+/// This also works around issues 16003 and 14849 in the implementation of
 /// [Directory.watch].
 class MacOSDirectoryWatcher extends ResubscribableDirectoryWatcher {
   // TODO(nweiz): remove these when issue 15042 is fixed.
@@ -56,7 +56,7 @@
   /// This is used to determine if the [Directory.watch] stream was falsely
   /// closed due to issue 14849. A close caused by events in the past will only
   /// happen before or immediately after the first batch of events.
-  int batches = 0;
+  int _batches = 0;
 
   /// The set of files that are known to exist recursively within the watched
   /// directory.
@@ -129,12 +129,12 @@
       }
     }
 
-    batches++;
+    _batches++;
 
     _sortEvents(batch).forEach((path, events) {
       var relativePath = p.relative(path, from: directory);
       if (MacOSDirectoryWatcher.logDebugInfo) {
-        print("[$_id] events for $relativePath:\n");
+        print("[$_id] events for $relativePath:");
         for (var event in events) {
           print("[$_id]   ${_formatEvent(event)}");
         }
@@ -168,6 +168,8 @@
           _listen(Chain.track(new Directory(path).list(recursive: true)),
               (entity) {
             if (entity is Directory) return;
+            if (_files.contains(path)) return;
+
             _emitEvent(ChangeType.ADD, entity.path);
             _files.add(entity.path);
           }, onError: (e, stackTrace) {
@@ -293,9 +295,14 @@
 
     switch (type) {
       case FileSystemEvent.CREATE:
-        return new ConstructableFileSystemCreateEvent(batch.first.path, isDir);
-      case FileSystemEvent.DELETE:
+        // Issue 16003 means that a CREATE event for a directory can indicate
+        // that the directory was moved and then re-created.
+        // [_eventsBasedOnFileSystem] will handle this correctly by producing a
+        // DELETE event followed by a CREATE event if the directory exists.
+        if (isDir) return null;
         return new ConstructableFileSystemCreateEvent(batch.first.path, false);
+      case FileSystemEvent.DELETE:
+        return new ConstructableFileSystemDeleteEvent(batch.first.path, isDir);
       case FileSystemEvent.MODIFY:
         return new ConstructableFileSystemModifyEvent(
             batch.first.path, isDir, false);
@@ -317,10 +324,12 @@
     var dirExists = new Directory(path).existsSync();
 
     if (MacOSDirectoryWatcher.logDebugInfo) {
-      print("[$_id] file existed: $fileExisted");
-      print("[$_id] dir existed: $dirExisted");
-      print("[$_id] file exists: $fileExists");
-      print("[$_id] dir exists: $dirExists");
+      print("[$_id] checking file system for "
+          "${p.relative(path, from: directory)}");
+      print("[$_id]   file existed: $fileExisted");
+      print("[$_id]   dir existed: $dirExisted");
+      print("[$_id]   file exists: $fileExists");
+      print("[$_id]   dir exists: $dirExists");
     }
 
     var events = [];
@@ -353,19 +362,24 @@
 
   /// The callback that's run when the [Directory.watch] stream is closed.
   void _onDone() {
+    if (MacOSDirectoryWatcher.logDebugInfo) print("[$_id] stream closed");
+
     _watchSubscription = null;
 
     // If the directory still exists and we haven't seen more than one batch,
     // this is probably issue 14849 rather than a real close event. We should
     // just restart the watcher.
-    if (batches < 2 && new Directory(directory).existsSync()) {
+    if (_batches < 2 && new Directory(directory).existsSync()) {
+      if (MacOSDirectoryWatcher.logDebugInfo) {
+        print("[$_id] fake closure (issue 14849), re-opening stream");
+      }
       _startWatch();
       return;
     }
 
     // FSEvents can fail to report the contents of the directory being removed
-    // when the directory itself is removed, so we need to manually mark the as
-    // removed.
+    // when the directory itself is removed, so we need to manually mark the
+    // files as removed.
     for (var file in _files.toSet()) {
       _emitEvent(ChangeType.REMOVE, file);
     }
diff --git a/test/directory_watcher/mac_os_test.dart b/test/directory_watcher/mac_os_test.dart
index 43567f0..1e9bd7d 100644
--- a/test/directory_watcher/mac_os_test.dart
+++ b/test/directory_watcher/mac_os_test.dart
@@ -36,26 +36,25 @@
     expectAddEvent("dir/newer.txt");
   });
 
-  // TODO(nweiz): re-enable this when issue 16003 is fixed.
-  // test('emits events for many nested files moved out then immediately back in',
-  //     () {
-  //   withPermutations((i, j, k) =>
-  //       writeFile("dir/sub/sub-$i/sub-$j/file-$k.txt"));
+  test('emits events for many nested files moved out then immediately back in',
+      () {
+    withPermutations((i, j, k) =>
+        writeFile("dir/sub/sub-$i/sub-$j/file-$k.txt"));
 
-  //   startWatcher(dir: "dir");
+    startWatcher(dir: "dir");
 
-  //   renameDir("dir/sub", "sub");
-  //   renameDir("sub", "dir/sub");
+    renameDir("dir/sub", "sub");
+    renameDir("sub", "dir/sub");
 
-  //   allowEither(() {
-  //     inAnyOrder(withPermutations((i, j, k) =>
-  //         isRemoveEvent("dir/sub/sub-$i/sub-$j/file-$k.txt")));
+    allowEither(() {
+      inAnyOrder(withPermutations((i, j, k) =>
+          isRemoveEvent("dir/sub/sub-$i/sub-$j/file-$k.txt")));
 
-  //     inAnyOrder(withPermutations((i, j, k) =>
-  //         isAddEvent("dir/sub/sub-$i/sub-$j/file-$k.txt")));
-  //   }, () {
-  //     inAnyOrder(withPermutations((i, j, k) =>
-  //         isModifyEvent("dir/sub/sub-$i/sub-$j/file-$k.txt")));
-  //   });
-  // });
+      inAnyOrder(withPermutations((i, j, k) =>
+          isAddEvent("dir/sub/sub-$i/sub-$j/file-$k.txt")));
+    }, () {
+      inAnyOrder(withPermutations((i, j, k) =>
+          isModifyEvent("dir/sub/sub-$i/sub-$j/file-$k.txt")));
+    });
+  });
 }
diff --git a/test/utils.dart b/test/utils.dart
index f7e35f1..885018b 100644
--- a/test/utils.dart
+++ b/test/utils.dart
@@ -116,7 +116,7 @@
 void startWatcher({String dir}) {
   var testCase = currentTestCase.description;
   if (MacOSDirectoryWatcher.logDebugInfo) {
-    print("starting watcher for $testCase");
+    print("starting watcher for $testCase (${new DateTime.now()})");
   }
 
   // We want to wait until we're ready *after* we subscribe to the watcher's
@@ -129,7 +129,7 @@
   _watcherEvents = new ScheduledStream(futureStream(schedule(() {
     currentSchedule.onComplete.schedule(() {
       if (MacOSDirectoryWatcher.logDebugInfo) {
-        print("stopping watcher for $testCase");
+        print("stopping watcher for $testCase (${new DateTime.now()})");
       }
 
       _watcher = null;
@@ -298,6 +298,9 @@
       dir.createSync(recursive: true);
     }
 
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[test] writing file $path");
+    }
     new File(fullPath).writeAsStringSync(contents);
 
     // Manually update the mock modification time for the file.
@@ -314,6 +317,9 @@
 /// Schedules deleting a file in the sandbox at [path].
 void deleteFile(String path) {
   schedule(() {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[test] deleting file $path");
+    }
     new File(p.join(_sandboxDir, path)).deleteSync();
   }, "delete file $path");
 }
@@ -323,6 +329,10 @@
 /// If [contents] is omitted, creates an empty file.
 void renameFile(String from, String to) {
   schedule(() {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[test] renaming file $from to $to");
+    }
+
     new File(p.join(_sandboxDir, from)).renameSync(p.join(_sandboxDir, to));
 
     // Make sure we always use the same separator on Windows.
@@ -337,6 +347,9 @@
 /// Schedules creating a directory in the sandbox at [path].
 void createDir(String path) {
   schedule(() {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[test] creating directory $path");
+    }
     new Directory(p.join(_sandboxDir, path)).createSync();
   }, "create directory $path");
 }
@@ -344,6 +357,9 @@
 /// Schedules renaming a directory in the sandbox from [from] to [to].
 void renameDir(String from, String to) {
   schedule(() {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[test] renaming directory $from to $to");
+    }
     new Directory(p.join(_sandboxDir, from))
         .renameSync(p.join(_sandboxDir, to));
   }, "rename directory $from to $to");
@@ -352,6 +368,9 @@
 /// Schedules deleting a directory in the sandbox at [path].
 void deleteDir(String path) {
   schedule(() {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[test] deleting directory $path");
+    }
     new Directory(p.join(_sandboxDir, path)).deleteSync(recursive: true);
   }, "delete directory $path");
 }