Add location information to watchers to make them more debuggable.

lib/watcher.dart

Index: lib/watcher.dart
diff --git a/lib/watcher.dart b/lib/watcher.dart
index febdcb18661c788060e771117d9867d8bb3d1a02..70c7f8ac7298d3089fc4966e226bb22111423c91 100644
--- a/lib/watcher.dart
+++ b/lib/watcher.dart
@@ -50,6 +50,7 @@ import 'dart:async';
 import 'dart:collection' hide LinkedList, LinkedListEntry;
 import 'observe.dart';
 import 'src/linked_list.dart';
+import 'package:logging/logging.dart';
 
 /**
  * True to use the [observe] library instead of watchers.
@@ -65,6 +66,20 @@ import 'src/linked_list.dart';
 bool useObservers = false;
 
 /**
+ * True to enable more verbose debugging messages. This is useful for tracing
+ * down errors that produce loops in the watcher evaluation order, for example
+ * when you see an error message of the form "_Possible loop in watchers
+ * propagation, stopped dispatch_".
+ */
+bool verboseDebugMessages = false;
+
+/**
+ * Log for messages produced at runtime by this library. Logging can be
+ * configured by accessing Logger.root from the logging library.
+ */
+final Logger _logger = new Logger('watcher');
+
+/**
  * Watch for changes in [target].  The [callback] function will be called when
  * [dispatch] is called and the value represented by [target] had changed.  The
  * returned function can be used to unregister this watcher.
@@ -92,11 +107,13 @@ bool useObservers = false;
  *   This is syntactic sugar for using the getter portion of a [Handle].
  *         watch(handle, ...)  // equivalent to `watch(handle._getter, ...)`
  */
-ChangeUnobserver watch(target, ChangeObserver callback, [String debugName]) {
+ChangeUnobserver watch(target, ChangeObserver callback,
+    [String debugName, String location]) {
   if (useObservers) return observe(target, callback);
 
   if (callback == null) return () {}; // no use in passing null as a callback.
   if (_watchers == null) _watchers = new LinkedList<_Watcher>();
+  debugName = debugName == null ? '<unnamed>' : debugName;
   Function exp;
   _WatcherType watcherType = _WatcherType.OTHER;
   if (target is Handle) {
@@ -116,10 +133,7 @@ ChangeUnobserver watch(target, ChangeObserver callback, [String debugName]) {
         watcherType = _WatcherType.HASH_MAP;
       }
     } catch (e, trace) { // in case target() throws some error
-      // TODO(sigmund): use logging instead of print when logger is in the SDK
-      // and available via pub (see dartbug.com/4363)
-      print('error: evaluating ${debugName != null ? debugName : "<unnamed>"} '
-            'watcher threw error ($e, $trace)');
+      _logger.warning('evaluating $debugName watcher threw error ($e, $trace)');
     }
   } else if (target is List) {
     exp = () => target;
@@ -135,7 +149,14 @@ ChangeUnobserver watch(target, ChangeObserver callback, [String debugName]) {
     watcherType = _WatcherType.HASH_MAP;
   }
 
-  var watcher = _createWatcher(watcherType, exp, callback, debugName);
+  if (verboseDebugMessages && location == null) {
+    // Record the current stack trace to help diagnoze loops.
+    try { throw ""; } catch (e, trace) {

[Jennifer Messerly, 2013/07/11 21:27:23]

use _readCurrentStackTrace?

[Siggi Cherem (dart-lang), 2013/07/11 22:07:01]

Done.

+      location = trace.toString();
+    }
+  }
+
+  var watcher = _createWatcher(watcherType, exp, callback, debugName, location);
   var node = _watchers.add(watcher);
   return node.remove;
 }
@@ -145,16 +166,16 @@ ChangeUnobserver watch(target, ChangeObserver callback, [String debugName]) {
  * [debugName].
  */
 _Watcher _createWatcher(_WatcherType type, Function exp,
-                        ChangeObserver callback, String debugName) {
+    ChangeObserver callback, String debugName, String location) {
   switch(type) {
     case _WatcherType.LIST:
-      return new _ListWatcher(exp, callback, debugName);
+      return new _ListWatcher(exp, callback, debugName, location);
     case _WatcherType.ORDERED_MAP:
-      return new _OrderDependantMapWatcher(exp, callback, debugName);
+      return new _OrderDependantMapWatcher(exp, callback, debugName, location);
     case _WatcherType.HASH_MAP:
-      return new _HashMapWatcher(exp, callback, debugName);
+      return new _HashMapWatcher(exp, callback, debugName, location);
     default:
-      return new _Watcher(exp, callback, debugName);
+      return new _Watcher(exp, callback, debugName, location);
   }
 }
 
@@ -163,8 +184,9 @@ _Watcher _createWatcher(_WatcherType type, Function exp,
  * passed to [callback] will have `null` as the old value, and the current
  * evaluation of [exp] as the new value.
  */
-ChangeUnobserver watchAndInvoke(exp, callback, [debugName]) {
-  var res = watch(exp, callback, debugName);
+ChangeUnobserver watchAndInvoke(exp, ChangeObserver callback,
+    [String debugName, String location]) {
+  var res = watch(exp, callback, debugName, location);
   // TODO(jmesserly): this should be "is Getter" once dart2js bug is fixed.
 
   var value = exp;
@@ -192,6 +214,13 @@ class _Watcher {
   /** Name used to debug. */
   final String debugName;
 
+  /** Location where the watcher was first installed (for debugging). */
+  String location;
+
+  /** Unique id used for debugging purposes. */
+  final int _uniqueId;
+  static int _nextId = 0;
+
   /** Function that retrieves the value being watched. */
   final Getter _getter;
 
@@ -201,11 +230,12 @@ class _Watcher {
   /** Last value observed on the matched expression. */
   var _lastValue;
 
-  _Watcher(this._getter, this._callback, this.debugName) {
+  _Watcher(this._getter, this._callback, this.debugName, this.location)
+    : _uniqueId = _nextId++ {
     _lastValue = _getter();
   }
 
-  String toString() => debugName == null ? '<unnamed>' : debugName;
+  String toString() => '$debugName (id: #$_uniqueId)';
 
   /** Detect if any changes occurred and if so invoke [_callback]. */
   bool compareAndNotify() {
@@ -222,6 +252,14 @@ class _Watcher {
   bool _compare(currentValue) => _lastValue != currentValue;
 
   void _update(currentValue) {
+    if (verboseDebugMessages) {
+      if (location != null) {
+        _logger.info('watcher updated: $this, defined at:\n$location');
+        location = null;
+      } else {
+        _logger.info('watcher updated: $this');
+      }
+    }
     _lastValue = currentValue;
   }
 
@@ -230,14 +268,14 @@ class _Watcher {
     try {
       return _getter();
     } catch (e, trace) {
-      print('error: evaluating $this watcher threw an exception ($e, $trace)');
+      _logger.warning('$this watcher threw an exception: $e, $trace');
     }
     return _lastValue;
   }
 }
 
 /** Bound for the [dispatch] algorithm. */
-final int _maxIter = 10;
+final int maxNumIterations = 10;
 
 /**
  * Scan all registered watchers and invoke their callbacks if the watched value
@@ -257,9 +295,9 @@ void dispatch() {
         dirty = true;
       }
     }
-  } while (dirty && ++total < _maxIter);
-  if (total == _maxIter) {
-    print('Possible loop in watchers propagation, stopped dispatch.');
+  } while (dirty && ++total < maxNumIterations);
+  if (total == maxNumIterations) {
+    _logger.warning('Possible loop in watchers propagation, stopped dispatch.');
   }
 }
 
@@ -321,8 +359,9 @@ class Handle<T> {
  */
 class _ListWatcher<T> extends _Watcher {
 
-  _ListWatcher(getter, ChangeObserver callback, String debugName)
-      : super(getter, callback, debugName) {
+  _ListWatcher(getter, ChangeObserver callback, String debugName,
+      String location)
+      : super(getter, callback, debugName, location) {
     _update(_safeRead());
   }
 
@@ -342,8 +381,9 @@ class _ListWatcher<T> extends _Watcher {
  */
 class _HashMapWatcher<K, V> extends _Watcher {
 
-  _HashMapWatcher(getter, ChangeObserver callback, String debugName)
-      : super(getter, callback, debugName) {
+  _HashMapWatcher(getter, ChangeObserver callback, String debugName,
+      String location)
+      : super(getter, callback, debugName, location) {
     _update(_safeRead());
   }
 
@@ -371,8 +411,9 @@ class _HashMapWatcher<K, V> extends _Watcher {
  */
 class _OrderDependantMapWatcher<K, V> extends _Watcher {
 
-  _OrderDependantMapWatcher(getter, ChangeObserver callback, String debugName)
-      : super(getter, callback, debugName) {
+  _OrderDependantMapWatcher(getter, ChangeObserver callback, String debugName,
+      String location)
+      : super(getter, callback, debugName, location) {
     _update(_safeRead());
   }