Make tests more realistic (#5762)

Previously, pumpWidget() would do a partial pump (it didn't trigger
Ticker callbacks or post-frame callbacks), and pump() would do a full
pump. This patch brings them closer together. It also makes runApp run a
full actual frame, rather than skipping the transient callback part of
the frame logic. Having "half-frames" in the system was confusing and
could lead to bugs where code expecting to run before the next layout
pass didn't because a "half-frame" ran first.

Also, make Tickers start ticking in the frame that they were started in,
if they were started during a frame. This means we no longer spin a
frame for t=0, we jump straight to the first actual frame.

Other changes in this patch:

* rename WidgetsBinding._runApp to WidgetsBinding.attachRootWidget, so
  that tests can use it to more accurately mock out runApp.

* allow loadStructuredData to return synchronously.

* make handleBeginFrame handle not being given a time stamp.

* make DataPipeImageProvider.loadAsync protected (rather than private),
  and document it. There wasn't really a reason for it to be private.

* fix ImageConfiguration.toString.

* introduce debugPrintBuildScope and debugPrintScheduleBuildForStacks,
  which can help debug problems with widgets getting marked as dirty but
  not cleaned.

* make debugPrintRebuildDirtyWidgets say "Building" the first time and
  "Rebuilding" the second, to make it clearer when a widget is first
  created. This makes debugging widget lifecycle issues much easier.

* make debugDumpApp more resilient.

* debugPrintStack now takes a label that is printed before the stack.

* improve the banner shown for debugPrintBeginFrameBanner.

* various and sundry documentation fixes

packages/flutter/lib/src/foundation/assertions.dart

@@ -334,7 +334,11 @@ class FlutterError extends AssertionError {
 ///
 /// The `maxFrames` argument can be given to limit the stack to the given number
 /// of lines. By default, all non-filtered stack lines are shown.
-void debugPrintStack({ int maxFrames }) {
+///
+/// The `label` argument, if present, will be printed before the stack.
+void debugPrintStack({ String label, int maxFrames }) {
+  if (label != null)
+    debugPrint(label);
   List<String> lines = StackTrace.current.toString().trimRight().split('\n');
   if (maxFrames != null)
     lines = lines.take(maxFrames);

packages/flutter/lib/src/foundation/print.dart

@@ -16,7 +16,7 @@ typedef void DebugPrintCallback(String message, { int wrapWidth });
 ///
 /// By default, this function very crudely attempts to throttle the rate at
 /// which messages are sent to avoid data loss on Android. This means that
-/// interleaving calls to this function (directly or indirectly via
+/// interleaving calls to this function (directly or indirectly via, e.g.,
 /// [debugDumpRenderTree] or [debugDumpApp]) and to the Dart [print] method can
 /// result in out-of-order messages in the logs.
 ///

packages/flutter/lib/src/rendering/object.dart

@@ -1337,7 +1337,7 @@ abstract class RenderObject extends AbstractNode implements HitTestTarget {
       if (owner != null) {
         assert(() {
           if (debugPrintMarkNeedsLayoutStacks)
-            debugPrintStack();
+            debugPrintStack(label: 'markNeedsLayout() called for $this');
           return true;
         });
         owner._nodesNeedingLayout.add(this);
@@ -1790,7 +1790,7 @@ abstract class RenderObject extends AbstractNode implements HitTestTarget {
     if (isRepaintBoundary) {
       assert(() {
         if (debugPrintMarkNeedsPaintStacks)
-          debugPrintStack();
+          debugPrintStack(label: 'markNeedsPaint() called for $this');
         return true;
       });
       // If we always have our own layer, then we can just repaint

packages/flutter/lib/src/scheduler/binding.dart

@@ -469,46 +469,97 @@ abstract class SchedulerBinding extends BindingBase {
     return new Duration(microseconds: (rawDurationSinceEpoch.inMicroseconds / timeDilation).round() + _epochStart.inMicroseconds);
   }
 
+  /// The time stamp for the frame currently being processed.
+  ///
+  /// This is only valid while [handleBeginFrame] is running, i.e. while a frame
+  /// is being produced.
+  // TODO(ianh): Replace this when fixing https://github.com/flutter/flutter/issues/5469
+  Duration get currentFrameTimeStamp {
+    assert(_currentFrameTimeStamp != null);
+    return _currentFrameTimeStamp;
+  }
+  Duration _currentFrameTimeStamp;
+
+  int _debugFrameNumber = 0;
+
   /// Called by the engine to produce a new frame.
   ///
   /// This function first calls all the callbacks registered by
-  /// [scheduleFrameCallback]/[addFrameCallback], then calls all the
-  /// callbacks registered by [addPersistentFrameCallback], which
-  /// typically drive the rendering pipeline, and finally calls the
-  /// callbacks registered by [addPostFrameCallback].
+  /// [scheduleFrameCallback]/[addFrameCallback], then calls all the callbacks
+  /// registered by [addPersistentFrameCallback], which typically drive the
+  /// rendering pipeline, and finally calls the callbacks registered by
+  /// [addPostFrameCallback].
+  ///
+  /// If the given time stamp is null, the time stamp from the last frame is
+  /// reused.
+  ///
+  /// To have a banner shown at the start of every frame in debug mode, set
+  /// [debugPrintBeginFrameBanner] to true. The banner will be printed to the
+  /// console using [debugPrint] and will contain the frame number (which
+  /// increments by one for each frame), and the time stamp of the frame. If the
+  /// given time stamp was null, then the string "warm-up frame" is shown
+  /// instead of the time stamp. This allows you to distinguish frames eagerly
+  /// pushed by the framework from those requested by the engine in response to
+  /// the vsync signal from the operating system.
+  ///
+  /// You can also show a banner at the end of every frame by setting
+  /// [debugPrintEndFrameBanner] to true. This allows you to distinguish log
+  /// statements printed during a frame from those printed between frames (e.g.
+  /// in response to events or timers).
   void handleBeginFrame(Duration rawTimeStamp) {
     Timeline.startSync('Frame');
     _firstRawTimeStampInEpoch ??= rawTimeStamp;
-    Duration timeStamp = _adjustForEpoch(rawTimeStamp);
+    _currentFrameTimeStamp = _adjustForEpoch(rawTimeStamp ?? _lastRawTimeStamp);
+    if (rawTimeStamp != null)
+      _lastRawTimeStamp = rawTimeStamp;
+
+    String debugBanner;
     assert(() {
-      if (debugPrintBeginFrameBanner)
-        debugPrint('━━━━━━━┫ Begin Frame ($timeStamp) ┣━━━━━━━');
+      _debugFrameNumber += 1;
+      if (debugPrintBeginFrameBanner || debugPrintEndFrameBanner) {
+        StringBuffer frameTimeStampDescription = new StringBuffer();
+        if (rawTimeStamp != null) {
+          _debugDescribeTimeStamp(_currentFrameTimeStamp, frameTimeStampDescription);
+        } else {
+          frameTimeStampDescription.write('(warm-up frame)');
+        }
+        debugBanner = '▄▄▄▄▄▄▄▄ Frame ${_debugFrameNumber.toString().padRight(7)}   ${frameTimeStampDescription.toString().padLeft(18)} ▄▄▄▄▄▄▄▄';
+        if (debugPrintBeginFrameBanner)
+          debugPrint(debugBanner);
+      }
       return true;
     });
-    _lastRawTimeStamp = rawTimeStamp;
+
     assert(!_isProducingFrame);
     _isProducingFrame = true;
     _hasScheduledFrame = false;
-    _invokeTransientFrameCallbacks(timeStamp);
-
-    for (FrameCallback callback in _persistentCallbacks)
-      _invokeFrameCallback(callback, timeStamp);
-
-    _isProducingFrame = false;
-
-    List<FrameCallback> localPostFrameCallbacks =
-        new List<FrameCallback>.from(_postFrameCallbacks);
-    _postFrameCallbacks.clear();
-    for (FrameCallback callback in localPostFrameCallbacks)
-      _invokeFrameCallback(callback, timeStamp);
-
-    Timeline.finishSync();
+    try {
 
-    assert(() {
-      if (debugPrintEndFrameBanner)
-        debugPrint('━━━━━━━┫ End of Frame ┣━━━━━━━');
-      return true;
-    });
+      // TRANSIENT FRAME CALLBACKS
+      _invokeTransientFrameCallbacks(_currentFrameTimeStamp);
+
+      // PERSISTENT FRAME CALLBACKS
+      for (FrameCallback callback in _persistentCallbacks)
+        _invokeFrameCallback(callback, _currentFrameTimeStamp);
+      _isProducingFrame = false;
+
+      // POST-FRAME CALLBACKS
+      List<FrameCallback> localPostFrameCallbacks =
+          new List<FrameCallback>.from(_postFrameCallbacks);
+      _postFrameCallbacks.clear();
+      for (FrameCallback callback in localPostFrameCallbacks)
+        _invokeFrameCallback(callback, _currentFrameTimeStamp);
+
+    } finally {
+      _isProducingFrame = false; // just in case we throw before setting it above
+      _currentFrameTimeStamp = null;
+      Timeline.finishSync();
+      assert(() {
+        if (debugPrintEndFrameBanner)
+          debugPrint('▀' * debugBanner.length);
+        return true;
+      });
+    }
 
     // All frame-related callbacks have been executed. Run lower-priority tasks.
     _runTasks();
@@ -527,6 +578,22 @@ abstract class SchedulerBinding extends BindingBase {
     Timeline.finishSync();
   }
 
+  static void _debugDescribeTimeStamp(Duration timeStamp, StringBuffer buffer) {
+    if (timeStamp.inDays > 0)
+      buffer.write('${timeStamp.inDays}d ');
+    if (timeStamp.inHours > 0)
+      buffer.write('${timeStamp.inHours - timeStamp.inDays * Duration.HOURS_PER_DAY}h ');
+    if (timeStamp.inMinutes > 0)
+      buffer.write('${timeStamp.inMinutes - timeStamp.inHours * Duration.MINUTES_PER_HOUR}m ');
+    if (timeStamp.inSeconds > 0)
+      buffer.write('${timeStamp.inSeconds - timeStamp.inMinutes * Duration.SECONDS_PER_MINUTE}s ');
+    buffer.write('${timeStamp.inMilliseconds - timeStamp.inSeconds * Duration.MILLISECONDS_PER_SECOND}');
+    int microseconds = timeStamp.inMicroseconds - timeStamp.inMilliseconds * Duration.MICROSECONDS_PER_MILLISECOND;
+    if (microseconds > 0)
+      buffer.write('.${microseconds.toString().padLeft(3, "0")}');
+    buffer.write('ms');
+  }
+
   // Calls the given [callback] with [timestamp] as argument.
   //
   // Wraps the callback in a try/catch and forwards any error to

packages/flutter/lib/src/scheduler/debug.dart

@@ -5,10 +5,12 @@
 /// Print a banner at the beginning of each frame.
 ///
 /// Frames triggered by the engine and handler by the scheduler binding will
-/// have a banner saying "Begin Frame" and giving the time stamp of the frame.
+/// have a banner giving the frame number and the time stamp of the frame.
 ///
 /// Frames triggered eagerly by the widget framework (e.g. when calling
-/// [runApp]) will have a label saying "Begin Warm-Up Frame".
+/// [runApp]) will have a label saying "warm-up frame" instead of the time stamp
+/// (the time stamp sent to frame callbacks in that case is the time of the last
+/// frame, or 0:00 if it is the first frame).
 ///
 /// To include a banner at the end of each frame as well, to distinguish
 /// intra-frame output from inter-frame output, set [debugPrintEndFrameBanner]

packages/flutter/lib/src/scheduler/ticker.dart

@@ -40,6 +40,8 @@ class Ticker {
     assert(_startTime == null);
     _completer = new Completer<Null>();
     _scheduleTick();
+    if (SchedulerBinding.instance.isProducingFrame)
+      _startTime = SchedulerBinding.instance.currentFrameTimeStamp;
     return _completer.future;
   }
 

packages/flutter/lib/src/services/asset_bundle.dart

@@ -155,12 +155,27 @@ abstract class CachingAssetBundle extends AssetBundle {
     assert(parser != null);
     if (_structuredDataCache.containsKey(key))
       return _structuredDataCache[key];
-    final Completer<dynamic> completer = new Completer<dynamic>();
-    _structuredDataCache[key] = completer.future;
-    completer.complete(loadString(key, cache: false).then/*<dynamic>*/(parser));
-    completer.future.then((dynamic value) {
-      _structuredDataCache[key] = new SynchronousFuture<dynamic>(value);
+    Completer<dynamic> completer;
+    Future<dynamic> result;
+    loadString(key, cache: false).then(parser).then((dynamic value) {
+      result = new SynchronousFuture<dynamic>(value);
+      _structuredDataCache[key] = result;
+      if (completer != null) {
+        // We already returned from the loadStructuredData function, which means
+        // we are in the asynchronous mode. Pass the value to the completer. The
+        // completer's future is what we returned.
+        completer.complete(value);
+      }
     });
+    if (result != null) {
+      // The code above ran synchronously, and came up with an answer.
+      // Return the SynchronousFuture that we created above.
+      return result;
+    }
+    // The code above hasn't yet run its "then" handler yet. Let's prepare a
+    // completer for it to use when it does run.
+    completer = new Completer<dynamic>();
+    _structuredDataCache[key] = completer.future;
     return completer.future;
   }
 

packages/flutter/lib/src/services/image_provider.dart

@@ -99,26 +99,31 @@ class ImageConfiguration {
       if (hasArguments)
         result.write(', ');
       result.write('bundle: $bundle');
+      hasArguments = true;
     }
     if (devicePixelRatio != null) {
       if (hasArguments)
         result.write(', ');
       result.write('devicePixelRatio: $devicePixelRatio');
+      hasArguments = true;
     }
     if (locale != null) {
       if (hasArguments)
         result.write(', ');
       result.write('locale: $locale');
+      hasArguments = true;
     }
     if (size != null) {
       if (hasArguments)
         result.write(', ');
       result.write('size: $size');
+      hasArguments = true;
     }
     if (platform != null) {
       if (hasArguments)
         result.write(', ');
       result.write('platform: $platform');
+      hasArguments = true;
     }
     result.write(')');
     return result.toString();
@@ -219,10 +224,12 @@ abstract class DataPipeImageProvider<T> extends ImageProvider<T> {
   /// const constructors so that they can be used in const expressions.
   const DataPipeImageProvider();
 
+  /// Converts a key into an [ImageStreamCompleter], and begins fetching the
+  /// image using [loadAsync].
   @override
   ImageStreamCompleter load(T key) {
     return new OneFrameImageStreamCompleter(
-      _loadAsync(key),
+      loadAsync(key),
       informationCollector: (StringBuffer information) {
         information.writeln('Image provider: $this');
         information.write('Image key: $key');
@@ -230,7 +237,12 @@ abstract class DataPipeImageProvider<T> extends ImageProvider<T> {
     );
   }
 
-  Future<ImageInfo> _loadAsync(T key) async {
+  /// Fetches the image from the data pipe, decodes it, and returns a
+  /// corresponding [ImageInfo] object.
+  ///
+  /// This function is used by [load].
+  @protected
+  Future<ImageInfo> loadAsync(T key) async {
     final mojo.MojoDataPipeConsumer dataPipe = await loadDataPipe(key);
     if (dataPipe == null)
       throw 'Unable to read data';
@@ -367,7 +379,7 @@ abstract class AssetBundleImageProvider extends DataPipeImageProvider<AssetBundl
   Future<AssetBundleImageKey> obtainKey(ImageConfiguration configuration);
 
   @override
-  Future<mojo.MojoDataPipeConsumer> loadDataPipe(AssetBundleImageKey key) async {
+  Future<mojo.MojoDataPipeConsumer> loadDataPipe(AssetBundleImageKey key) {
     return key.bundle.load(key.name);
   }
 

packages/flutter/lib/src/services/image_resolution.dart

@@ -110,7 +110,7 @@ class AssetImage extends AssetBundleImageProvider {
         if (completer != null) {
           // We already returned from this function, which means we are in the
           // asynchronous mode. Pass the value to the completer. The completer's
-          // function is what we returned.
+          // future is what we returned.
           completer.complete(key);
         } else {
           // We haven't yet returned, so we must have been called synchronously

packages/flutter/lib/src/widgets/binding.dart

@@ -321,23 +321,19 @@ abstract class WidgetsBinding extends BindingBase implements GestureBinding, Ren
   /// This is initialized the first time [runApp] is called.
   Element get renderViewElement => _renderViewElement;
   Element _renderViewElement;
-  void _runApp(Widget app) {
+
+  /// Takes a widget and attaches it to the [renderViewElement], creating it if
+  /// necessary.
+  ///
+  /// This is called by [runApp] to configure the widget tree.
+  ///
+  /// See also [RenderObjectToWidgetAdapter.attachToRenderTree].
+  void attachRootWidget(Widget rootWidget) {
     _renderViewElement = new RenderObjectToWidgetAdapter<RenderBox>(
       container: renderView,
       debugShortDescription: '[root]',
-      child: app
+      child: rootWidget
     ).attachToRenderTree(buildOwner, renderViewElement);
-    assert(() {
-      if (debugPrintBeginFrameBanner)
-        debugPrint('━━━━━━━┫ Begin Warm-Up Frame ┣━━━━━━━');
-      return true;
-    });
-    beginFrame();
-    assert(() {
-      if (debugPrintEndFrameBanner)
-        debugPrint('━━━━━━━┫ End of Warm-Up Frame ┣━━━━━━━');
-      return true;
-    });
   }
 
   @override
@@ -352,18 +348,32 @@ abstract class WidgetsBinding extends BindingBase implements GestureBinding, Ren
 /// Inflate the given widget and attach it to the screen.
 ///
 /// Initializes the binding using [WidgetsFlutterBinding] if necessary.
+///
+/// See also:
+///
+/// * [WidgetsBinding.attachRootWidget], which creates the root widget for the
+///   widget hierarchy.
+/// * [RenderObjectToWidgetAdapter.attachToRenderTree], which creates the root
+///   element for the element hierarchy.
+/// * [WidgetsBinding.handleBeginFrame], which pumps the widget pipeline to
+///   ensure the widget, element, and render trees are all built.
 void runApp(Widget app) {
-  WidgetsFlutterBinding.ensureInitialized()._runApp(app);
+  WidgetsFlutterBinding.ensureInitialized()
+    ..attachRootWidget(app)
+    ..handleBeginFrame(null);
 }
 
 /// Print a string representation of the currently running app.
 void debugDumpApp() {
   assert(WidgetsBinding.instance != null);
-  assert(WidgetsBinding.instance.renderViewElement != null);
   String mode = 'RELEASE MODE';
   assert(() { mode = 'CHECKED MODE'; return true; });
   debugPrint('${WidgetsBinding.instance.runtimeType} - $mode');
-  debugPrint(WidgetsBinding.instance.renderViewElement.toStringDeep());
+  if (WidgetsBinding.instance.renderViewElement != null) {
+    debugPrint(WidgetsBinding.instance.renderViewElement.toStringDeep());
+  } else {
+    debugPrint('<no tree currently mounted>');
+  }
 }
 
 /// A bridge from a [RenderObject] to an [Element] tree.
@@ -406,7 +416,7 @@ class RenderObjectToWidgetAdapter<T extends RenderObject> extends RenderObjectWi
   /// child of [container].
   ///
   /// If `element` is null, this function will create a new element. Otherwise,
-  /// the given element will be updated with this widget.
+  /// the given element will have an update scheduled to switch to this widget.
   ///
   /// Used by [runApp] to bootstrap applications.
   RenderObjectToWidgetElement<T> attachToRenderTree(BuildOwner owner, [RenderObjectToWidgetElement<T> element]) {
@@ -420,9 +430,8 @@ class RenderObjectToWidgetAdapter<T extends RenderObject> extends RenderObjectWi
         element.mount(null, null);
       });
     } else {
-      owner.buildScope(element, () {
-        element.update(this);
-      });
+      element._newWidget = this;
+      element.markNeedsBuild();
     }
     return element;
   }
@@ -476,6 +485,20 @@ class RenderObjectToWidgetElement<T extends RenderObject> extends RootRenderObje
     _rebuild();
   }
 
+  // When we are assigned a new widget, we store it here
+  // until we are ready to update to it.
+  Widget _newWidget;
+
+  @override
+  void performRebuild() {
+    assert(_newWidget != null);
+    final Widget newWidget = _newWidget;
+    _newWidget = null;
+    super.performRebuild();
+    update(newWidget);
+    assert(_newWidget == null);
+  }
+
   void _rebuild() {
     try {
       _child = updateChild(_child, widget.child, _rootChildSlot);

packages/flutter/lib/src/widgets/debug.dart

@@ -9,8 +9,39 @@ import 'framework.dart';
 import 'table.dart';
 
 /// Log the dirty widgets that are built each frame.
+///
+/// Combined with [debugPrintBuildScope] or [debugPrintBeginFrameBanner], this
+/// allows you to distinguish builds triggered by the initial mounting of a
+/// widget tree (e.g. in a call to [runApp]) from the regular builds triggered
+/// by the pipeline (see [WidgetsBinding.beginFrame].
+///
+/// Combined with [debugPrintScheduleBuildForStacks], this lets you watch a
+/// widget's dirty/clean lifecycle.
 bool debugPrintRebuildDirtyWidgets = false;
 
+/// Log all calls to [BuildOwner.buildScope].
+///
+/// Combined with [debugPrintScheduleBuildForStacks], this allows you to track
+/// when a [State.setState] call gets serviced.
+///
+/// Combined with [debugPrintRebuildDirtyWidgets] or
+/// [debugPrintBeginFrameBanner], this allows you to distinguish builds
+/// triggered by the initial mounting of a widget tree (e.g. in a call to
+/// [runApp]) from the regular builds triggered by the pipeline (see
+/// [WidgetsBinding.beginFrame].
+bool debugPrintBuildScope = false;
+
+/// Log the call stacks that mark widgets as needing to be rebuilt.
+///
+/// This is called whenever [BuildOwner.scheduleBuildFor] adds an element to the
+/// dirty list. Typically this is as a result of [Element.markNeedsBuild] being
+/// called, which itself is usually a result of [State.setState] being called.
+///
+/// To see when a widget is rebuilt, see [debugPrintRebuildDirtyWidgets].
+///
+/// To see when the dirty list is flushed, see [debugPrintBuildDirtyElements].
+bool debugPrintScheduleBuildForStacks = false;
+
 /// Log when widgets with global keys are deactivated and log when they are
 /// reactivated (retaken).
 ///

packages/flutter/lib/src/widgets/framework.dart

@@ -1419,6 +1419,8 @@ class BuildOwner {
     assert(element.owner == this);
     assert(element._inDirtyList == _dirtyElements.contains(element));
     assert(() {
+      if (debugPrintScheduleBuildForStacks)
+        debugPrintStack(label: 'scheduleBuildFor() called for $element${_dirtyElements.contains(element) ? " (ALREADY IN LIST)" : ""}');
       if (element._inDirtyList) {
         throw new FlutterError(
           'scheduleBuildFor() called for a widget for which a build was already scheduled.\n'
@@ -1426,8 +1428,13 @@ class BuildOwner {
           '  $element\n'
           'The current dirty list consists of:\n'
           '  $_dirtyElements\n'
-          'This should not be possible and probably indicates a bug in the widgets framework. '
-          'Please report it: https://github.com/flutter/flutter/issues/new'
+          'This usually indicates that a widget was rebuilt outside the build phase (thus '
+          'marking the element as clean even though it is still in the dirty list). '
+          'This should not be possible and is probably caused by a bug in the widgets framework. '
+          'Please report it: https://github.com/flutter/flutter/issues/new\n'
+          'To debug this issue, consider setting the debugPrintScheduleBuildForStacks and '
+          'debugPrintBuildDirtyElements flags to true and looking for a call to scheduleBuildFor '
+          'for a widget that is labeled "ALREADY IN LIST".'
         );
       }
       if (!element.dirty) {
@@ -1450,6 +1457,11 @@ class BuildOwner {
     }
     _dirtyElements.add(element);
     element._inDirtyList = true;
+    assert(() {
+      if (debugPrintScheduleBuildForStacks)
+        debugPrint('...dirty list is now: $_dirtyElements');
+      return true;
+    });
   }
 
   int _debugStateLockLevel = 0;
@@ -1507,6 +1519,8 @@ class BuildOwner {
     assert(_debugStateLockLevel >= 0);
     assert(!_debugBuilding);
     assert(() {
+      if (debugPrintBuildScope)
+        debugPrint('buildScope called with context $context; dirty list is: $_dirtyElements');
       _debugStateLockLevel += 1;
       _debugBuilding = true;
       return true;
@@ -1543,6 +1557,8 @@ class BuildOwner {
       assert(() {
         _debugBuilding = false;
         _debugStateLockLevel -= 1;
+        if (debugPrintBuildScope)
+          debugPrint('buildScope finished');
         return true;
       });
     }
@@ -2138,6 +2154,9 @@ abstract class BuildableElement extends Element {
   // should be adding the element back into the list when it's reactivated.
   bool _inDirtyList = false;
 
+  // Whether we've already built or not. Set in [rebuild].
+  bool _debugBuiltOnce = false;
+
   // We let widget authors call setState from initState, didUpdateConfig, and
   // build even when state is locked because its convenient and a no-op anyway.
   // This flag ensures that this convenience is only allowed on the element
@@ -2194,16 +2213,22 @@ abstract class BuildableElement extends Element {
     owner.scheduleBuildFor(this);
   }
 
-  /// Called by the binding when scheduleBuild() has been called to mark this
-  /// element dirty, and, in components, by update() when the widget has
-  /// changed.
+  /// Called by the binding when [BuildOwner.scheduleBuildFor] has been called
+  /// to mark this element dirty, and, in components, by [mount] when the
+  /// element is first built and by [update] when the widget has changed.
   void rebuild() {
     assert(_debugLifecycleState != _ElementLifecycle.initial);
     if (!_active || !_dirty)
       return;
     assert(() {
-      if (debugPrintRebuildDirtyWidgets)
-        debugPrint('Rebuilding $this');
+      if (debugPrintRebuildDirtyWidgets) {
+        if (!_debugBuiltOnce) {
+          debugPrint('Building $this');
+          _debugBuiltOnce = true;
+        } else {
+          debugPrint('Rebuilding $this');
+        }
+      }
       return true;
     });
     assert(_debugLifecycleState == _ElementLifecycle.active);
@@ -2304,12 +2329,12 @@ abstract class ComponentElement extends BuildableElement {
     rebuild();
   }
 
-  /// Calls the build() method of the [StatelessWidget] object (for
+  /// Calls the `build` method of the [StatelessWidget] object (for
   /// stateless widgets) or the [State] object (for stateful widgets) and
   /// then updates the widget tree.
   ///
-  /// Called automatically during mount() to generate the first build, and by
-  /// rebuild() when the element needs updating.
+  /// Called automatically during [mount] to generate the first build, and by
+  /// [rebuild] when the element needs updating.
   @override
   void performRebuild() {
     assert(_debugSetAllowIgnoredCallsToMarkNeedsBuild(true));

packages/flutter/test/material/expansion_panels_test.dart

@@ -40,6 +40,7 @@ void main() {
     box = tester.renderObject(find.byType(ExpansionPanelList));
     expect(box.size.height, equals(oldHeight));
 
+    // now expand the child panel
     await tester.pumpWidget(
       new ScrollableViewport(
         child: new ExpansionPanelList(
@@ -53,14 +54,16 @@ void main() {
                 return new Text(isExpanded ? 'B' : 'A');
               },
               body: new SizedBox(height: 100.0),
-              isExpanded: true
+              isExpanded: true // this is the addition
             )
           ]
         )
       )
     );
+
     await tester.pump(const Duration(milliseconds: 200));
 
+
     expect(find.text('A'), findsNothing);
     expect(find.text('B'), findsOneWidget);
     box = tester.renderObject(find.byType(ExpansionPanelList));

packages/flutter/test/material/mergeable_material_test.dart

@@ -597,7 +597,6 @@ void main() {
       )
     );
 
-    await tester.pump();
     expect(box.size.height, equals(300));
 
     matches(getBorderRadius(tester, 0), RadiusType.Round, RadiusType.Round);

packages/flutter/test/widget/image_resolution_test.dart

@@ -62,7 +62,7 @@ class TestAssetBundle extends CachingAssetBundle {
         pipe = new TestMojoDataPipeConsumer(4.0);
         break;
     }
-    return (new Completer<mojo.MojoDataPipeConsumer>()..complete(pipe)).future;
+    return new SynchronousFuture<mojo.MojoDataPipeConsumer>(pipe);
   }
 
   @override
@@ -79,9 +79,21 @@ class TestAssetBundle extends CachingAssetBundle {
 class TestAssetImage extends AssetImage {
   TestAssetImage(String name) : super(name);
 
+  @override
+  Future<ImageInfo> loadAsync(AssetBundleImageKey key) {
+    ImageInfo result;
+    key.bundle.load(key.name).then((mojo.MojoDataPipeConsumer dataPipe) {
+      decodeImage(dataPipe).then((ui.Image image) {
+        result = new ImageInfo(image: image, scale: getScale(key));
+      });
+    });
+    assert(result != null);
+    return new SynchronousFuture<ImageInfo>(result);
+  }
+
   @override
   Future<ui.Image> decodeImage(TestMojoDataPipeConsumer pipe) {
-    return new Future<ui.Image>.value(new TestImage(pipe.scale));
+    return new SynchronousFuture<ui.Image>(new TestImage(pipe.scale));
   }
 }
 

packages/flutter_test/lib/src/widget_tester.dart

@@ -164,7 +164,8 @@ class WidgetTester extends WidgetController implements HitTestDispatcher {
     EnginePhase phase = EnginePhase.sendSemanticsTree
   ]) {
     return TestAsyncUtils.guard(() {
-      runApp(widget);
+      binding.attachRootWidget(widget);
+      binding.scheduleFrame();
       return binding.pump(duration, phase);
     });
   }