improve verbose output

packages/flutter_tools/lib/src/base/logger.dart

@@ -4,8 +4,10 @@
 
 import 'dart:io';
 
+final _terminal = new _AnsiTerminal();
+
 abstract class Logger {
-  bool verbose = false;
+  bool get isVerbose => false;
 
   /// Display an error level message to the user. Commands should use this if they
   /// fail in some way.
@@ -18,43 +20,34 @@ abstract class Logger {
   /// Use this for verbose tracing output. Users can turn this output on in order
   /// to help diagnose issues with the toolchain or with their setup.
   void printTrace(String message);
+
+  /// Flush any buffered output.
+  void flush() { }
 }
 
 class StdoutLogger implements Logger {
-  DateTime _startTime = new DateTime.now();
-
-  bool verbose = false;
+  bool get isVerbose => false;
 
   void printError(String message, [StackTrace stackTrace]) {
-    stderr.writeln(_prefix + message);
+    stderr.writeln(message);
     if (stackTrace != null)
       stderr.writeln(stackTrace);
   }
 
-  void printStatus(String message) {
-    print(_prefix + message);
-  }
+  void printStatus(String message) => print(message);
 
-  void printTrace(String message) {
-    if (verbose)
-      print('$_prefix- $message');
-  }
+  void printTrace(String message) { }
 
-  String get _prefix {
-    if (!verbose)
-      return '';
-    Duration elapsed = new DateTime.now().difference(_startTime);
-    return '[${elapsed.inMilliseconds.toString().padLeft(4)} ms] ';
-  }
+  void flush() { }
 }
 
 class BufferLogger implements Logger {
+  bool get isVerbose => false;
+
   StringBuffer _error = new StringBuffer();
   StringBuffer _status = new StringBuffer();
   StringBuffer _trace = new StringBuffer();
 
-  bool verbose = false;
-
   String get errorText => _error.toString();
   String get statusText => _status.toString();
   String get traceText => _trace.toString();
@@ -62,4 +55,88 @@ class BufferLogger implements Logger {
   void printError(String message, [StackTrace stackTrace]) => _error.writeln(message);
   void printStatus(String message) => _status.writeln(message);
   void printTrace(String message) => _trace.writeln(message);
+
+  void flush() { }
+}
+
+class VerboseLogger implements Logger {
+  _LogMessage lastMessage;
+
+  bool get isVerbose => true;
+
+  void printError(String message, [StackTrace stackTrace]) {
+    _emit();
+    lastMessage = new _LogMessage(_LogType.error, message, stackTrace);
+  }
+
+  void printStatus(String message) {
+    _emit();
+    lastMessage = new _LogMessage(_LogType.status, message);
+  }
+
+  void printTrace(String message) {
+    _emit();
+    lastMessage = new _LogMessage(_LogType.trace, message);
+  }
+
+  void flush() => _emit();
+
+  void _emit() {
+    lastMessage?.emit();
+    lastMessage = null;
+  }
+}
+
+enum _LogType {
+  error,
+  status,
+  trace
+}
+
+class _LogMessage {
+  _LogMessage(this.type, this.message, [this.stackTrace]) {
+    stopwatch.start();
+  }
+
+  final _LogType type;
+  final String message;
+  final StackTrace stackTrace;
+
+  Stopwatch stopwatch = new Stopwatch();
+
+  void emit() {
+    stopwatch.stop();
+
+    int millis = stopwatch.elapsedMilliseconds;
+    String prefix = '${millis.toString().padLeft(4)} ms • ';
+    String indent = ''.padLeft(prefix.length);
+    if (millis >= 100)
+      prefix = _terminal.writeBold(prefix.substring(0, prefix.length - 3)) + ' • ';
+    String indentMessage = message.replaceAll('\n', '\n$indent');
+
+    if (type == _LogType.error) {
+      stderr.writeln(prefix + _terminal.writeBold(indentMessage));
+      if (stackTrace != null)
+        stderr.writeln(indent + stackTrace.toString().replaceAll('\n', '\n$indent'));
+    } else if (type == _LogType.status) {
+      print(prefix + _terminal.writeBold(indentMessage));
+    } else {
+      print(prefix + indentMessage);
+    }
+  }
+}
+
+class _AnsiTerminal {
+  _AnsiTerminal() {
+    String term = Platform.environment['TERM'];
+    _supportsColor = term != null && term != 'dumb';
+  }
+
+  static const String _bold = '\u001B[1m';
+  static const String _reset = '\u001B[0m';
+
+  bool _supportsColor;
+  bool get supportsColor => _supportsColor;
+
+  String writeBold(String str) => supportsColor ? '$_bold$str$_reset' : str;
 }

packages/flutter_tools/lib/src/base/process.dart

@@ -85,6 +85,8 @@ String sdkBinaryName(String name) {
 }
 
 bool exitsHappy(List<String> cli) {
+  printTrace(cli.join(' '));
+
   try {
     return Process.runSync(cli.first, cli.sublist(1)).exitCode == 0;
   } catch (error) {

packages/flutter_tools/lib/src/commands/run.dart

@@ -128,7 +128,6 @@ class RunCommand extends RunCommandBase {
       debugPort: debugPort
     );
 
-    printTrace('Finished $name command.');
     return result;
   }
 }
@@ -272,10 +271,8 @@ Future delayUntilObservatoryAvailable(String host, int port, {
   while (stopwatch.elapsed <= timeout) {
     try {
       WebSocket ws = await WebSocket.connect(url);
-
-      printTrace('Connected to the observatory port (${stopwatch.elapsedMilliseconds}ms).');
+      printTrace('Connected to the observatory port.');
       ws.close().catchError((error) => null);
-
       return;
     } catch (error) {
       await new Future.delayed(new Duration(milliseconds: 250));

packages/flutter_tools/lib/src/commands/run_mojo.dart

@@ -120,7 +120,7 @@ class RunMojoCommand extends FlutterCommand {
     if (useDevtools) {
       final String buildFlag = argResults['mojo-debug'] ? '--debug' : '--release';
       args.add(buildFlag);
-      if (logger.verbose)
+      if (logger.isVerbose)
         args.add('--verbose');
     }
 

packages/flutter_tools/lib/src/doctor.dart

@@ -232,7 +232,9 @@ class _AtomValidator extends DoctorValidator {
     ValidationType flutterPluginExists() {
       try {
         // apm list -b -p -i
-        ProcessResult result = Process.runSync('apm', <String>['list', '-b', '-p', '-i']);
+        List<String> args = <String>['list', '-b', '-p', '-i'];
+        printTrace('apm ${args.join(' ')}');
+        ProcessResult result = Process.runSync('apm', args);
         if (result.exitCode != 0)
           return ValidationType.missing;
         bool available = (result.stdout as String).split('\n').any((String line) {

packages/flutter_tools/lib/src/runner/flutter_command.dart

@@ -47,7 +47,17 @@ abstract class FlutterCommand extends Command {
     devices ??= new DeviceStore.forConfigs(buildConfigurations);
   }
 
-  Future<int> run() async {
+  Future<int> run() {
+    Stopwatch stopwatch = new Stopwatch()..start();
+
+    return _run().then((int exitCode) {
+      printTrace("'flutter $name' exiting with code $exitCode; "
+        "elasped time ${stopwatch.elapsedMilliseconds}ms.");
+      return exitCode;
+    });
+  }
+
+  Future<int> _run() async {
     if (requiresProjectRoot && !projectRootValidator())
       return 1;
 

packages/flutter_tools/lib/src/runner/flutter_command_runner.dart

@@ -12,6 +12,7 @@ import 'package:path/path.dart' as path;
 import '../android/android_sdk.dart';
 import '../artifacts.dart';
 import '../base/context.dart';
+import '../base/logger.dart';
 import '../base/process.dart';
 import '../build_configuration.dart';
 import '../globals.dart';
@@ -160,12 +161,19 @@ class FlutterCommandRunner extends CommandRunner {
     return '.';
   }
 
+  Future<dynamic> run(Iterable<String> args) {
+    return super.run(args).then((dynamic result) {
+      logger.flush();
+      return result;
+    });
+  }
+
   Future<int> runCommand(ArgResults globalResults) {
     _globalResults = globalResults;
 
     // Check for verbose.
     if (globalResults['verbose'])
-      logger.verbose = true;
+      context[Logger] = new VerboseLogger();
 
     // we must set ArtifactStore.flutterRoot early because other features use it
     // (e.g. enginePath's initialiser uses it)