Generally improve logging, and exit automatically on build update

Author: jakemac53

e2e_example/tool/build.dart

@@ -1,8 +1,6 @@
 // Copyright (c) 2016, 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.
-import 'dart:io';
-
 import 'package:build/build.dart';
 
 import 'package:e2e_example/copy_builder.dart';
@@ -17,11 +15,5 @@ main() async {
   /// the transitive deps issue.
   CopyBuilder.addPhases(phases, graph);
 
-  var result = await build(phases);
-
-  if (result.status == BuildStatus.Success) {
-    stdout.writeln(result);
-  } else {
-    stderr.writeln(result);
-  }
+  await build(phases);
 }

e2e_example/tool/watch.dart

@@ -1,8 +1,6 @@
 // Copyright (c) 2016, 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.
-import 'dart:io';
-
 import 'package:build/build.dart';
 
 import 'package:e2e_example/copy_builder.dart';

lib/src/generate/build.dart

@@ -56,13 +56,12 @@ Future<BuildResult> build(PhaseGroup phaseGroup,
   var futureResult = buildImpl.runBuild();
 
   // Stop doing new builds when told to terminate.
-  var listener = _setupTerminateLogic(terminateEventStream, () {
+  _setupTerminateLogic(terminateEventStream, () {
     new Logger('Build').info('Waiting for build to finish...');
     return futureResult;
-  });
+  }, cancelWhen: futureResult);
 
   var result = await futureResult;
-  listener.cancel();
   options.logListener.cancel();
   return result;
 }
@@ -106,6 +105,9 @@ Stream<BuildResult> watch(PhaseGroup phaseGroup,
   // Stop doing new builds when told to terminate.
   _setupTerminateLogic(terminateEventStream, () async {
     await watchImpl.terminate();
+  }, cancelWhen: watchImpl.onTerminated);
+
+  watchImpl.onTerminated.then((_) {
     options.logListener.cancel();
   });
 
@@ -151,6 +153,9 @@ Stream<BuildResult> serve(PhaseGroup phaseGroup,
   // Stop doing new builds when told to terminate.
   _setupTerminateLogic(terminateEventStream, () async {
     await watchImpl.terminate();
+  }, cancelWhen: watchImpl.onTerminated);
+
+  watchImpl.onTerminated.then((_) async{
     await serverStarted;
     await stopServer();
     options.logListener.cancel();
@@ -162,7 +167,7 @@ Stream<BuildResult> serve(PhaseGroup phaseGroup,
 /// Given [terminateEventStream], call [onTerminate] the first time an event is
 /// seen. If a second event is recieved, simply exit.
 StreamSubscription _setupTerminateLogic(
-    Stream terminateEventStream, Future onTerminate()) {
+    Stream terminateEventStream, Future onTerminate(), {Future cancelWhen}) {
   terminateEventStream ??= ProcessSignal.SIGINT.watch();
   int numEventsSeen = 0;
   var terminateListener;
@@ -176,5 +181,9 @@ StreamSubscription _setupTerminateLogic(
       exit(2);
     }
   });
+
+  cancelWhen?.then((_) {
+    terminateListener.cancel();
+  });
   return terminateListener;
 }

lib/src/generate/build_impl.dart

@@ -22,6 +22,7 @@ import '../asset_graph/graph.dart';
 import '../asset_graph/node.dart';
 import '../builder/build_step_impl.dart';
 import '../builder/builder.dart';
+import '../logging/logging.dart';
 import '../package_graph/package_graph.dart';
 import 'build_result.dart';
 import 'exceptions.dart';
@@ -76,13 +77,14 @@ class BuildImpl {
 
       /// Initialize the [assetGraph] if its not yet set up.
       if (_assetGraph == null) {
-        _logger.info('Reading cached dependency graph');
-        _assetGraph = await _readAssetGraph();
-
-        /// Collect updates since the asset graph was last created. This only
-        /// handles updates and deletes, not adds. We list the file system for
-        /// all inputs later on (in [_initializeInputsByPackage]).
-        updates.addAll(await _getUpdates());
+        await logWithTime(_logger, 'Reading cached dependency graph', () async {
+          _assetGraph = await _readAssetGraph();
+
+          /// Collect updates since the asset graph was last created. This only
+          /// handles updates and deletes, not adds. We list the file system for
+          /// all inputs later on (in [_initializeInputsByPackage]).
+          updates.addAll(await _getUpdates());
+        });
       }
 
       /// If the build script gets updated, we need to either fully invalidate
@@ -95,48 +97,53 @@ class BuildImpl {
       ///
       /// TODO(jakemac): Come up with a better way of telling if the script
       /// has been updated since it started running.
-      _logger.info('Checking if the build script has been updated');
-      if (await _buildScriptUpdated()) {
-        buildType = BuildType.Full;
-        if (_isFirstBuild) {
-          _logger.info('Invalidating asset graph due to build script update');
-          _assetGraph.allNodes
-              .where((node) => node is GeneratedAssetNode)
-              .forEach(
-                  (node) => (node as GeneratedAssetNode).needsUpdate = true);
-        } else {
-          done.complete(new BuildResult(BuildStatus.Failure, buildType, [],
-              exception: 'Build abandoned due to change to the build script or '
-                  'one of its dependencies. This could be caused by a pub get '
-                  'or any other change. Please terminate the build script and '
-                  'restart it.'));
-          return;
+      await logWithTime(_logger, 'Checking build script for updates', () async {
+        if (await _buildScriptUpdated()) {
+          buildType = BuildType.Full;
+          if (_isFirstBuild) {
+            _logger
+                .warning('Invalidating asset graph due to build script update');
+            _assetGraph.allNodes
+                .where((node) => node is GeneratedAssetNode)
+                .forEach(
+                    (node) => (node as GeneratedAssetNode).needsUpdate = true);
+          } else {
+            done.complete(new BuildResult(BuildStatus.Failure, buildType, [],
+              exception: new BuildScriptUpdatedException()));
+          }
         }
-      }
-
-      /// Applies all [updates] to the [_assetGraph] as well as doing other
-      /// necessary cleanup.
-      _logger.info('Updating dependency graph with changes since last build.');
-      await _updateWithChanges(updates);
-
-      /// Wait while all inputs are collected.
-      _logger.info('Initializing inputs');
-      await _initializeInputsByPackage();
-
-      /// Delete all previous outputs!
-      _logger.info('Deleting previous outputs');
-      await _deletePreviousOutputs();
+      });
+      // Bail if the previous step completed the build.
+      if (done.isCompleted) return;
+
+      await logWithTime(_logger, 'Finalizing build setup', () async {
+        /// Applies all [updates] to the [_assetGraph] as well as doing other
+        /// necessary cleanup.
+        _logger
+            .info('Updating dependency graph with changes since last build.');
+        await _updateWithChanges(updates);
+
+        /// Wait while all inputs are collected.
+        _logger.info('Initializing inputs');
+        await _initializeInputsByPackage();
+
+        /// Delete all previous outputs!
+        _logger.info('Deleting previous outputs');
+        await _deletePreviousOutputs();
+      });
 
       /// Run a fresh build.
-      _logger.info('Running build phases');
-      var result = await _runPhases();
+      var result =
+          await logWithTime(_logger, 'Running build', _runPhases);
 
       /// Write out the dependency graph file.
-      _logger.info('Caching finalized dependency graph');
-      _assetGraph.validAsOf = validAsOf;
-      var assetGraphAsset =
-          new Asset(_assetGraphId, JSON.encode(_assetGraph.serialize()));
-      await _writer.writeAsString(assetGraphAsset);
+      await logWithTime(_logger, 'Caching finalized dependency graph',
+          () async {
+        _assetGraph.validAsOf = validAsOf;
+        var assetGraphAsset =
+            new Asset(_assetGraphId, JSON.encode(_assetGraph.serialize()));
+        await _writer.writeAsString(assetGraphAsset);
+      });
 
       done.complete(result);
     }, onError: (e, Chain chain) {
@@ -148,12 +155,14 @@ class BuildImpl {
     _isFirstBuild = false;
     if (result.status == BuildStatus.Success) {
       _logger.info('Succeeded after ${watch.elapsedMilliseconds}ms with '
-          '${result.outputs.length} outputs\n');
+          '${result.outputs.length} outputs\n\n');
     } else {
+      var exceptionString =
+          result.exception != null ? '\n${result.exception}' : '';
       var stackTraceString =
-          result.stackTrace != null ? '\n\n${result.stackTrace}' : '';
-      _logger.severe('Failed after ${watch.elapsedMilliseconds}ms:'
-          '${result.exception}$stackTraceString\n');
+          result.stackTrace != null ? '\n${result.stackTrace}' : '';
+      _logger.severe('Failed after ${watch.elapsedMilliseconds}ms'
+          '$exceptionString$stackTraceString\n');
     }
     return result;
   }

lib/src/generate/exceptions.dart

@@ -8,3 +8,12 @@ class ConcurrentBuildException implements Exception {
   String toString() =>
       'ConcurrentBuildException: Only one build may be running at a time.';
 }
+
+class BuildScriptUpdatedException implements Exception {
+  const BuildScriptUpdatedException();
+
+  @override
+  String toString() => 'Build abandoned due to change to the build script or '
+      'one of its dependencies. This could be caused by a pub get or any other '
+      'change. Please restart the build script.';
+}

lib/src/generate/watch_impl.dart

@@ -11,10 +11,12 @@ import '../asset/id.dart';
 import '../asset/writer.dart';
 import '../asset_graph/graph.dart';
 import '../asset_graph/node.dart';
+import '../logging/logging.dart';
 import '../package_graph/package_graph.dart';
 import 'build_impl.dart';
 import 'build_result.dart';
 import 'directory_watcher_factory.dart';
+import 'exceptions.dart';
 import 'options.dart';
 import 'phase.dart';
 
@@ -46,8 +48,8 @@ class WatchImpl {
   final AssetWriter _writer;
 
   /// A future that completes when the current build is done.
-  Future _currentBuild;
-  Future get currentBuild => _currentBuild;
+  Future<BuildResult> _currentBuild;
+  Future<BuildResult> get currentBuild => _currentBuild;
 
   /// Whether or not another build is scheduled.
   bool _nextBuildScheduled;
@@ -61,6 +63,9 @@ class WatchImpl {
   /// Whether we are in the process of terminating.
   bool _terminating = false;
 
+  Completer _onTerminatedCompleter = new Completer();
+  Future get onTerminated => _onTerminatedCompleter.future;
+
   WatchImpl(BuildOptions options, PhaseGroup phaseGroup)
       : _directoryWatcherFactory = options.directoryWatcherFactory,
         _debounceDelay = options.debounceDelay,
@@ -71,7 +76,10 @@ class WatchImpl {
   /// Completes after the current build is done, and stops further builds from
   /// happening.
   Future terminate() async {
-    if (_terminating) throw new StateError('Already terminating.');
+    if (_terminating) {
+      _logger.warning('Already terminating.');
+      return;
+    }
     if (_resultStreamController == null) {
       throw new StateError('`terminate` called before `runWatch`');
     }
@@ -93,6 +101,7 @@ class WatchImpl {
     }
     _terminating = false;
     _logger.info('Build watching terminated, safe to exit.\n');
+    _onTerminatedCompleter.complete();
   }
 
   /// Runs a build any time relevant files change.
@@ -140,11 +149,17 @@ class WatchImpl {
         return;
       }
 
-      _logger.info('Preparing for next build');
-      _logger.info('Starting build');
+      _logger.info('Starting next build');
       _currentBuild =
           _buildImpl.runBuild(validAsOf: validAsOf, updates: updatedInputsCopy);
       _currentBuild.then((result) {
+        // Terminate the watcher if the build script is updated, there is no
+        // need to continue listening.
+        if (result.status == BuildStatus.Failure &&
+            result.exception is BuildScriptUpdatedException) {
+          terminate();
+        }
+
         if (_resultStreamController.hasListener) {
           _resultStreamController.add(result);
         }
@@ -162,46 +177,48 @@ class WatchImpl {
       buildTimer = new Timer(_debounceDelay, doBuild);
     }
 
-    final watchers = <DirectoryWatcher>[];
-    _logger.info('Setting up file watchers');
+    logWithTime(_logger, 'Setting up file watchers', () {
+      final watchers = <DirectoryWatcher>[];
 
-    // Collect absolute file paths for all the packages. This needs to happen
-    // before setting up the watchers.
-    final absolutePackagePaths = <PackageNode, String>{};
-    for (var package in _packageGraph.allPackages.values) {
-      absolutePackagePaths[package] =
-          path.normalize(path.absolute(package.location.toFilePath()));
-    }
+      // Collect absolute file paths for all the packages. This needs to happen
+      // before setting up the watchers.
+      final absolutePackagePaths = <PackageNode, String>{};
+      for (var package in _packageGraph.allPackages.values) {
+        absolutePackagePaths[package] =
+            path.normalize(path.absolute(package.location.toFilePath()));
+      }
 
-    // Set up watchers for all the packages
-    for (var package in _packageGraph.allPackages.values) {
-      var absolutePackagePath = absolutePackagePaths[package];
-      _logger.fine('Setting up watcher at $absolutePackagePath');
-
-      // Ignore all subfolders which are other packages.
-      var pathsToIgnore = absolutePackagePaths.values.where((path) =>
-          path != absolutePackagePath && path.startsWith(absolutePackagePath));
-
-      var watcher = _directoryWatcherFactory(absolutePackagePath);
-      watchers.add(watcher);
-      _allListeners.add(watcher.events.listen((WatchEvent e) {
-        // Check for ignored paths and immediately bail.
-        if (pathsToIgnore.any((path) => e.path.startsWith(path))) return;
-
-        var relativePath = path.relative(e.path, from: absolutePackagePath);
-        _logger.finest(
-            'Got ${e.type} event for path $relativePath from ${watcher.path}');
-        var id = new AssetId(package.name, relativePath);
-        var node = _assetGraph.get(id);
-        // Short circuit for deletes of nodes that aren't in the graph.
-        if (e.type == ChangeType.REMOVE && node == null) return;
-
-        updatedInputs[id] = e.type;
-        scheduleBuild();
-      }));
-    }
+      // Set up watchers for all the packages
+      for (var package in _packageGraph.allPackages.values) {
+        var absolutePackagePath = absolutePackagePaths[package];
+        _logger.fine('Setting up watcher at $absolutePackagePath');
+
+        // Ignore all subfolders which are other packages.
+        var pathsToIgnore = absolutePackagePaths.values.where((path) =>
+            path != absolutePackagePath &&
+            path.startsWith(absolutePackagePath));
+
+        var watcher = _directoryWatcherFactory(absolutePackagePath);
+        watchers.add(watcher);
+        _allListeners.add(watcher.events.listen((WatchEvent e) {
+          // Check for ignored paths and immediately bail.
+          if (pathsToIgnore.any((path) => e.path.startsWith(path))) return;
+
+          var relativePath = path.relative(e.path, from: absolutePackagePath);
+          _logger.finest(
+              'Got ${e.type} event for path $relativePath from ${watcher.path}');
+          var id = new AssetId(package.name, relativePath);
+          var node = _assetGraph.get(id);
+          // Short circuit for deletes of nodes that aren't in the graph.
+          if (e.type == ChangeType.REMOVE && node == null) return;
+
+          updatedInputs[id] = e.type;
+          scheduleBuild();
+        }));
+      }
 
-    Future.wait(watchers.map((w) => w.ready)).then((_) {
+      return Future.wait(watchers.map((w) => w.ready));
+    }).then((_) {
       // Schedule the first build!
       doBuild(true);
     });