Report timing on failed executions too (#9661)

* handle errors

* review notes

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

@@ -31,16 +31,14 @@ enum ExitStatus {
 }
 
 /// [FlutterCommand]s' subclasses' [FlutterCommand.runCommand] can optionally
-/// provide a [FlutterCommandResult] to furnish additional information for 
+/// provide a [FlutterCommandResult] to furnish additional information for
 /// analytics.
 class FlutterCommandResult {
-  FlutterCommandResult(
+  const FlutterCommandResult(
     this.exitStatus, {
     this.analyticsParameters,
     this.endTimeOverride,
-  }) { 
-    assert(exitStatus != null); 
-  }
+  });
 
   final ExitStatus exitStatus;
 
@@ -49,10 +47,10 @@ class FlutterCommandResult {
   /// Do not add PII.
   final List<String> analyticsParameters;
 
-  /// Optional epoch time when the command's non-interactive wait time is 
+  /// Optional epoch time when the command's non-interactive wait time is
   /// complete during the command's execution. Use to measure user perceivable
-  /// latency without measuring user interaction time. 
-  /// 
+  /// latency without measuring user interaction time.
+  ///
   /// [FlutterCommand] will automatically measure and report the command's
   /// complete time if not overriden.
   final DateTime endTimeOverride;
@@ -153,31 +151,38 @@ abstract class FlutterCommand extends Command<Null> {
     if (flutterUsage.isFirstRun)
       flutterUsage.printWelcome();
 
-    final FlutterCommandResult commandResult = await verifyThenRunCommand();
-
-    final DateTime endTime = clock.now();
-    printTrace("'flutter $name' took ${getElapsedAsMilliseconds(endTime.difference(startTime))}.");
-    if (usagePath != null) {
-      final List<String> labels = <String>[];
-      if (commandResult?.exitStatus != null)
-        labels.add(getEnumName(commandResult.exitStatus));
-      if (commandResult?.analyticsParameters?.isNotEmpty ?? false)
-        labels.addAll(commandResult.analyticsParameters);
-
-      final String label = labels
-          .where((String label) => !isBlank(label))
-          .join('-');
-      flutterUsage.sendTiming(
-        'flutter', 
-        name, 
-        // If the command provides its own end time, use it. Otherwise report
-        // the duration of the entire execution.
-        (commandResult?.endTimeOverride ?? endTime).difference(startTime), 
-        // Report in the form of `success-[parameter1-parameter2]`, all of which
-        // can be null if the command doesn't provide a FlutterCommandResult.
-        label: label == '' ? null : label,
-      );
+    FlutterCommandResult commandResult;
+    try {
+      commandResult = await verifyThenRunCommand();
+    } on ToolExit {
+      commandResult = const FlutterCommandResult(ExitStatus.fail);
+      rethrow;
+    } finally {
+      final DateTime endTime = clock.now();
+      printTrace('"flutter $name" took ${getElapsedAsMilliseconds(endTime.difference(startTime))}.');
+      if (usagePath != null) {
+        final List<String> labels = <String>[];
+        if (commandResult?.exitStatus != null)
+          labels.add(getEnumName(commandResult.exitStatus));
+        if (commandResult?.analyticsParameters?.isNotEmpty ?? false)
+          labels.addAll(commandResult.analyticsParameters);
+
+        final String label = labels
+            .where((String label) => !isBlank(label))
+            .join('-');
+        flutterUsage.sendTiming(
+          'flutter',
+          name,
+          // If the command provides its own end time, use it. Otherwise report
+          // the duration of the entire execution.
+          (commandResult?.endTimeOverride ?? endTime).difference(startTime),
+          // Report in the form of `success-[parameter1-parameter2]`, all of which
+          // can be null if the command doesn't provide a FlutterCommandResult.
+          label: label == '' ? null : label,
+        );
+      }
     }
+
   }
 
   /// Perform validation then call [runCommand] to execute the command.
@@ -202,11 +207,11 @@ abstract class FlutterCommand extends Command<Null> {
     final String commandPath = await usagePath;
     if (commandPath != null)
       flutterUsage.sendCommand(commandPath);
-    return runCommand();
+    return await runCommand();
   }
 
   /// Subclasses must implement this to execute the command.
-  /// Optionally provide a [FlutterCommandResult] to send more details about the 
+  /// Optionally provide a [FlutterCommandResult] to send more details about the
   /// execution for analytics.
   Future<FlutterCommandResult> runCommand();
 

packages/flutter_tools/test/src/runner/flutter_command_test.dart

@@ -6,6 +6,7 @@ import 'dart:async';
 
 import 'package:flutter_tools/src/cache.dart';
 import 'package:flutter_tools/src/usage.dart';
+import 'package:flutter_tools/src/base/common.dart';
 import 'package:flutter_tools/src/runner/flutter_command.dart';
 import 'package:mockito/mockito.dart';
 import 'package:quiver/time.dart';
@@ -59,7 +60,7 @@ void main() {
       verify(clock.now()).called(2);
 
       expect(
-        verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured, 
+        verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured,
         <dynamic>['flutter', 'dummy', const Duration(milliseconds: 1000), null]
       );
     },
@@ -72,7 +73,7 @@ void main() {
       // Crash if called a third time which is unexpected.
       mockTimes = <int>[1000, 2000];
 
-      final DummyFlutterCommand flutterCommand = 
+      final DummyFlutterCommand flutterCommand =
           new DummyFlutterCommand(noUsagePath: true);
       await flutterCommand.run();
       verify(clock.now()).called(2);
@@ -82,31 +83,57 @@ void main() {
       Clock: () => clock,
       Usage: () => usage,
     });
-    
+
     testUsingContext('report additional FlutterCommandResult data', () async {
       // Crash if called a third time which is unexpected.
       mockTimes = <int>[1000, 2000];
 
       final FlutterCommandResult commandResult = new FlutterCommandResult(
-        ExitStatus.fail,
+        ExitStatus.success,
         // nulls should be cleaned up.
         analyticsParameters: <String> ['blah1', 'blah2', null, 'blah3'],
         endTimeOverride: new DateTime.fromMillisecondsSinceEpoch(1500)
       );
 
-      final DummyFlutterCommand flutterCommand = 
-          new DummyFlutterCommand(flutterCommandResult: commandResult);
+      final DummyFlutterCommand flutterCommand = new DummyFlutterCommand(
+        commandFunction: () async => commandResult
+      );
       await flutterCommand.run();
       verify(clock.now()).called(2);
       expect(
-        verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured, 
+        verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured,
         <dynamic>[
-          'flutter', 
-          'dummy', 
+          'flutter',
+          'dummy',
           const Duration(milliseconds: 500), // FlutterCommandResult's end time used instead.
-          'fail-blah1-blah2-blah3',
+          'success-blah1-blah2-blah3',
         ],
-      );    
+      );
+    },
+    overrides: <Type, Generator>{
+      Clock: () => clock,
+      Usage: () => usage,
+    });
+
+    testUsingContext('report failed execution timing too', () async {
+      // Crash if called a third time which is unexpected.
+      mockTimes = <int>[1000, 2000];
+
+      final DummyFlutterCommand flutterCommand =
+          new DummyFlutterCommand(commandFunction: () async { throwToolExit('fail'); });
+
+      try {
+        await flutterCommand.run();
+        fail('Mock should make this fail');
+      } on ToolExit {
+        // Should have still checked time twice.
+        verify(clock.now()).called(2);
+
+        expect(
+          verify(usage.sendTiming(captureAny, captureAny, captureAny, label: captureAny)).captured,
+          <dynamic>['flutter', 'dummy', const Duration(milliseconds: 1000), 'fail']
+        );
+      }
     },
     overrides: <Type, Generator>{
       Clock: () => clock,
@@ -117,16 +144,18 @@ void main() {
 
 }
 
+typedef Future<FlutterCommandResult> CommandFunction();
+
 class DummyFlutterCommand extends FlutterCommand {
 
   DummyFlutterCommand({
-    this.shouldUpdateCache : false, 
-    this.noUsagePath : false, 
-    this.flutterCommandResult
+    this.shouldUpdateCache : false,
+    this.noUsagePath : false,
+    this.commandFunction,
   });
 
   final bool noUsagePath;
-  final FlutterCommandResult flutterCommandResult;
+  final CommandFunction commandFunction;
 
   @override
   final bool shouldUpdateCache;
@@ -142,10 +171,10 @@ class DummyFlutterCommand extends FlutterCommand {
 
   @override
   Future<FlutterCommandResult> runCommand() async {
-    return flutterCommandResult;
+    return commandFunction == null ? null : commandFunction();
   }
 }
 
 class MockCache extends Mock implements Cache {}
 
-class MockUsage extends Mock implements Usage {}
+class MockUsage extends Mock implements Usage {}
\ No newline at end of file