Add debugging prints to the Mac OS directory watcher.

pkg/watcher/lib/src/directory_watcher/mac_os.dart

 // Copyright (c) 2013, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
 library watcher.directory_watcher.mac_os;
 
 import 'dart:async';
 import 'dart:io';
 
+import 'package:path/path.dart' as p;
 import 'package:stack_trace/stack_trace.dart';
 
 import '../constructable_file_system_event.dart';
 import '../path_set.dart';
 import '../utils.dart';
 import '../watch_event.dart';
 import 'resubscribable.dart';
 
 /// Uses the FSEvents subsystem to watch for filesystem events.
 ///
 /// FSEvents has two main idiosyncrasies that this class works around. First, it
 /// will occasionally report events that occurred before the filesystem watch
 /// was initiated. Second, if multiple events happen to the same file in close
 /// succession, it won't report them in the order they occurred. See issue
 /// 14373.
 ///
 /// This also works around issues 15458 and 14849 in the implementation of
 /// [Directory.watch].
 class MacOSDirectoryWatcher extends ResubscribableDirectoryWatcher {
+  // TODO(nweiz): remove these when issue 15042 is fixed.
+  static var logDebugInfo = false;
+  static var _count = 0;
+  final int _id;
+
   MacOSDirectoryWatcher(String directory)
-      : super(directory, () => new _MacOSDirectoryWatcher(directory));
+      : _id = _count++,
+        super(directory, () => new _MacOSDirectoryWatcher(directory, _count));

[Bob Nystrom, 2013/12/05 22:43:55]

How does ++ work in an initialization list? Should this be _count - 1?

[nweiz, 2013/12/05 22:48:47]

Come to think of it, there's really no reason the wrapper class should have an
_id at all. Fixed.

 }
 
 class _MacOSDirectoryWatcher implements ManuallyClosedDirectoryWatcher {
+  // TODO(nweiz): remove these when issue 15042 is fixed.
+  static var _count = 0;
+  final String _id;
+
   final String directory;
 
   Stream<WatchEvent> get events => _eventsController.stream;
   final _eventsController = new StreamController<WatchEvent>.broadcast();
 
   bool get isReady => _readyCompleter.isCompleted;
 
   Future get ready => _readyCompleter.future;
   final _readyCompleter = new Completer();
 
@@ skipping 19 matching lines @@
   /// This is separate from [_subscriptions] because this stream occasionally
   /// needs to be resubscribed in order to work around issue 14849.
   StreamSubscription<FileSystemEvent> _watchSubscription;
 
   /// A set of subscriptions that this watcher subscribes to.
   ///
   /// These are gathered together so that they may all be canceled when the
   /// watcher is closed. This does not include [_watchSubscription].
   final _subscriptions = new Set<StreamSubscription>();
 
-  _MacOSDirectoryWatcher(String directory)
+  _MacOSDirectoryWatcher(String directory, int parentId)
       : directory = directory,
-        _files = new PathSet(directory) {
+        _files = new PathSet(directory),
+        _id = "$parentId/${_count++}" {
     _startWatch();
 
     _listen(Chain.track(new Directory(directory).list(recursive: true)),
         (entity) {
       if (entity is! Directory) _files.add(entity.path);
     },
         onError: _emitError,
-        onDone: _readyCompleter.complete,
+        onDone: () {
+      if (MacOSDirectoryWatcher.logDebugInfo) {
+        print("[$_id] watcher is ready, known files:");
+        for (var file in _files.toSet()) {
+          print("[$_id]   ${p.relative(file, from: directory)}");
+        }
+      }
+      _readyCompleter.complete();
+    },
         cancelOnError: true);
   }
 
   void close() {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[$_id] watcher is closed");
+    }
     for (var subscription in _subscriptions) {
       subscription.cancel();
     }
     _subscriptions.clear();
     if (_watchSubscription != null) _watchSubscription.cancel();
     _watchSubscription = null;
     _eventsController.close();
   }
 
   /// The callback that's run when [Directory.watch] emits a batch of events.
   void _onBatch(List<FileSystemEvent> batch) {
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[$_id] ======== batch:");
+      for (var event in batch) {
+        print("[$_id]   ${_formatEvent(event)}");
+      }
+
+      print("[$_id] known files:");
+      for (var file in _files.toSet()) {
+        print("[$_id]   ${p.relative(file, from: directory)}");
+      }
+    }
+
     batches++;
 
     _sortEvents(batch).forEach((path, events) {
+      var relativePath = p.relative(path, from: directory);
+      if (MacOSDirectoryWatcher.logDebugInfo) {
+        print("[$_id] events for $relativePath:\n");
+        for (var event in events) {
+          print("[$_id]   ${_formatEvent(event)}");
+        }
+      }
+
       var canonicalEvent = _canonicalEvent(events);
       events = canonicalEvent == null ?
           _eventsBasedOnFileSystem(path) : [canonicalEvent];
+      if (MacOSDirectoryWatcher.logDebugInfo) {
+        print("[$_id] canonical event for $relativePath: "
+            "${_formatEvent(canonicalEvent)}");
+        print("[$_id] actionable events for $relativePath: "
+            "${events.map(_formatEvent)}");
+      }
 
       for (var event in events) {
         if (event is FileSystemCreateEvent) {
           if (!event.isDirectory) {
             // Don't emit ADD events for files or directories that we already
             // know about. Such an event comes from FSEvents reporting an add
             // that happened prior to the watch beginning.
             if (_files.contains(path)) continue;
 
             _emitEvent(ChangeType.ADD, path);
             _files.add(path);
             continue;
           }
 
           if (_files.containsDir(path)) continue;
 
           _listen(Chain.track(new Directory(path).list(recursive: true)),
               (entity) {
             if (entity is Directory) return;
             _emitEvent(ChangeType.ADD, entity.path);
             _files.add(entity.path);
-          }, onError: _emitError, cancelOnError: true);
+          }, onError: (e, stackTrace) {
+            if (MacOSDirectoryWatcher.logDebugInfo) {
+              print("[$_id] got error listing $relativePath: $e");
+            }
+            _emitError(e, stackTrace);
+          }, cancelOnError: true);
         } else if (event is FileSystemModifyEvent) {
           assert(!event.isDirectory);
           _emitEvent(ChangeType.MODIFY, path);
         } else {
           assert(event is FileSystemDeleteEvent);
           for (var removedPath in _files.remove(path)) {
             _emitEvent(ChangeType.REMOVE, removedPath);
           }
         }
       }
     });
+
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[$_id] ======== batch complete");
+    }
   }
 
   /// Sort all the events in a batch into sets based on their path.
   ///
   /// A single input event may result in multiple events in the returned map;
   /// for example, a MOVE event becomes a DELETE event for the source and a
   /// CREATE event for the destination.
   ///
   /// The returned events won't contain any [FileSystemMoveEvent]s, nor will it
   /// contain any events relating to [directory].
@@ skipping 108 matching lines @@
   /// This returns a list whose order should be reflected in the events emitted
   /// to the user, unlike the batched events from [Directory.watch]. The
   /// returned list may be empty, indicating that no changes occurred to [path]
   /// (probably indicating that it was created and then immediately deleted).
   List<FileSystemEvent> _eventsBasedOnFileSystem(String path) {
     var fileExisted = _files.contains(path);
     var dirExisted = _files.containsDir(path);
     var fileExists = new File(path).existsSync();
     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");
+    }
+
     var events = [];
     if (fileExisted) {
       if (fileExists) {
         events.add(new ConstructableFileSystemModifyEvent(path, false, false));
       } else {
         events.add(new ConstructableFileSystemDeleteEvent(path, false));
       }
     } else if (dirExisted) {
       if (dirExists) {
         // If we got contradictory events for a directory that used to exist and
@@ skipping 45 matching lines @@
         .transform(new BatchedStreamTransformer<FileSystemEvent>());
     _watchSubscription = innerStream.listen(_onBatch,
         onError: _eventsController.addError,
         onDone: _onDone);
   }
 
   /// Emit an event with the given [type] and [path].
   void _emitEvent(ChangeType type, String path) {
     if (!isReady) return;
 
+    if (MacOSDirectoryWatcher.logDebugInfo) {
+      print("[$_id] emitting $type ${p.relative(path, from: directory)}");
+    }
+
     _eventsController.add(new WatchEvent(type, path));
   }
 
   /// Emit an error, then close the watcher.
   void _emitError(error, StackTrace stackTrace) {
     _eventsController.addError(error, stackTrace);
     close();
   }
 
   /// Like [Stream.listen], but automatically adds the subscription to
   /// [_subscriptions] so that it can be canceled when [close] is called.
   void _listen(Stream stream, void onData(event), {Function onError,
       void onDone(), bool cancelOnError}) {
     var subscription;
     subscription = stream.listen(onData, onError: onError, onDone: () {
       _subscriptions.remove(subscription);
       if (onDone != null) onDone();
     }, cancelOnError: cancelOnError);
     _subscriptions.add(subscription);
   }
+
+  // TODO(nweiz): remove this when issue 15042 is fixed.
+  /// Return a human-friendly string representation of [event].
+  String _formatEvent(FileSystemEvent event) {
+    if (event == null) return 'null';
+
+    var path = p.relative(event.path, from: directory);
+    var type = event.isDirectory ? 'directory' : 'file';
+    if (event is FileSystemCreateEvent) {
+      return "create $type $path";
+    } else if (event is FileSystemDeleteEvent) {
+      return "delete $type $path";
+    } else if (event is FileSystemModifyEvent) {
+      return "modify $type $path";
+    } else if (event is FileSystemMoveEvent) {
+      return "move $type $path to "
+          "${p.relative(event.destination, from: directory)}";
+    }
+  }
 }