diff --git a/dev/devicelab/README.md b/dev/devicelab/README.md index 2830ed0ca09..6bc1d7a52a6 100644 --- a/dev/devicelab/README.md +++ b/dev/devicelab/README.md @@ -119,7 +119,7 @@ Notably, it will start and stop gradle, for instance. To run all tests defined in `manifest.yaml`, use option `-a` (`--all`): ```sh -dart bin/run.dart -a +../../bin/cache/dart-sdk/bin/dart bin/run.dart -a ``` ## Running specific tests @@ -128,7 +128,7 @@ To run a test, use option `-t` (`--task`): ```sh # from the .../flutter/dev/devicelab directory -dart bin/run.dart -t {NAME_OR_PATH_OF_TEST} +../../bin/cache/dart-sdk/bin/dart bin/run.dart -t {NAME_OR_PATH_OF_TEST} ``` Where `NAME_OR_PATH_OF_TEST` can be either of: @@ -142,7 +142,7 @@ Where `NAME_OR_PATH_OF_TEST` can be either of: To run multiple tests, repeat option `-t` (`--task`) multiple times: ```sh -dart bin/run.dart -t test1 -t test2 -t test3 +../../bin/cache/dart-sdk/bin/dart bin/run.dart -t test1 -t test2 -t test3 ``` To run tests from a specific stage, use option `-s` (`--stage`). @@ -151,7 +151,7 @@ Currently there are only three stages defined, `devicelab`, ```sh -dart bin/run.dart -s {NAME_OF_STAGE} +../../bin/cache/dart-sdk/bin/dart bin/run.dart -s {NAME_OF_STAGE} ``` # Reproducing broken builds locally @@ -162,7 +162,7 @@ failing test is `flutter_gallery__transition_perf`. This name can be passed to the `run.dart` command. For example: ```sh -dart bin/run.dart -t flutter_gallery__transition_perf +../../bin/cache/dart-sdk/bin/dart bin/run.dart -t flutter_gallery__transition_perf ``` # Writing tests diff --git a/dev/devicelab/bin/tasks/commands_test.dart b/dev/devicelab/bin/tasks/commands_test.dart index 903cd39b0a7..1611fd3a0d5 100644 --- a/dev/devicelab/bin/tasks/commands_test.dart +++ b/dev/devicelab/bin/tasks/commands_test.dart @@ -74,18 +74,18 @@ void main() { run.stdin.write('P'); await driver.drive('none'); final Future reloadStartingText = - stdout.stream.firstWhere((String line) => line.endsWith('hot reload...')); + stdout.stream.firstWhere((String line) => line.endsWith('] Initializing hot reload...')); final Future reloadEndingText = - stdout.stream.firstWhere((String line) => line.contains('Hot reload performed in ')); + stdout.stream.firstWhere((String line) => line.contains('] Reloaded ') && line.endsWith('ms.')); print('test: pressing "r" to perform a hot reload...'); run.stdin.write('r'); await reloadStartingText; await reloadEndingText; await driver.drive('none'); final Future restartStartingText = - stdout.stream.firstWhere((String line) => line.endsWith('hot restart...')); + stdout.stream.firstWhere((String line) => line.endsWith('Performing hot restart...')); final Future restartEndingText = - stdout.stream.firstWhere((String line) => line.contains('Hot restart performed in ')); + stdout.stream.firstWhere((String line) => line.contains('] Restarted application in ')); print('test: pressing "R" to perform a full reload...'); run.stdin.write('R'); await restartStartingText; diff --git a/dev/integration_tests/external_ui/test_driver/main_test.dart b/dev/integration_tests/external_ui/test_driver/main_test.dart index 40cff6705ff..115056471b7 100644 --- a/dev/integration_tests/external_ui/test_driver/main_test.dart +++ b/dev/integration_tests/external_ui/test_driver/main_test.dart @@ -29,7 +29,7 @@ Future main() async { final SerializableFinder summary = find.byValueKey('summary'); // Wait for calibration to complete and fab to appear. - await driver.waitFor(fab, timeout: const Duration(seconds: 40)); + await driver.waitFor(fab); final String calibrationResult = await driver.getText(summary); final Match matchCalibration = calibrationRegExp.matchAsPrefix(calibrationResult); @@ -59,7 +59,7 @@ Future main() async { expect(double.parse(matchFast.group(1)), closeTo(flutterFrameRate * 2.0, 5.0)); expect(double.parse(matchFast.group(2)), closeTo(flutterFrameRate, 10.0)); expect(int.parse(matchFast.group(3)), 1); - }, timeout: const Timeout(Duration(minutes: 1))); + }); tearDownAll(() async { driver?.close(); diff --git a/packages/flutter/lib/src/widgets/binding.dart b/packages/flutter/lib/src/widgets/binding.dart index 34ff8f92d3a..81fbdebdef8 100644 --- a/packages/flutter/lib/src/widgets/binding.dart +++ b/packages/flutter/lib/src/widgets/binding.dart @@ -268,8 +268,7 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB void initServiceExtensions() { super.initServiceExtensions(); - const bool isReleaseMode = bool.fromEnvironment('dart.vm.product'); - if (!isReleaseMode) { + profile(() { registerSignalServiceExtension( name: 'debugDumpApp', callback: () { @@ -294,11 +293,14 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB name: 'didSendFirstFrameEvent', callback: (_) async { return { + // This is defined to return a STRING, not a boolean. + // Devtools, the Intellij plugin, and the flutter tool all depend + // on it returning a string and not a boolean. 'enabled': _needToReportFirstFrame ? 'false' : 'true' }; }, ); - } + }); assert(() { registerBoolServiceExtension( @@ -540,22 +542,25 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB /// Whether the first frame has finished rendering. /// - /// Only valid in profile and debug builds, it can't be used in release - /// builds. - /// It can be deferred using [deferFirstFrameReport] and - /// [allowFirstFrameReport]. - /// The value is set at the end of the call to [drawFrame]. + /// Only useful in profile and debug builds; in release builds, this always + /// return false. This can be deferred using [deferFirstFrameReport] and + /// [allowFirstFrameReport]. The value is set at the end of the call to + /// [drawFrame]. + /// + /// This value can also be obtained over the VM service protocol as + /// `ext.flutter.didSendFirstFrameEvent`. bool get debugDidSendFirstFrameEvent => !_needToReportFirstFrame; /// Tell the framework not to report the frame it is building as a "useful" /// first frame until there is a corresponding call to [allowFirstFrameReport]. /// - /// This is used by [WidgetsApp] to report the first frame. - // - // TODO(ianh): This method should only be available in debug and profile modes. + /// This is used by [WidgetsApp] to avoid reporting frames that aren't useful + /// during startup as the "first frame". void deferFirstFrameReport() { - assert(_deferFirstFrameReportCount >= 0); - _deferFirstFrameReportCount += 1; + profile(() { + assert(_deferFirstFrameReportCount >= 0); + _deferFirstFrameReportCount += 1; + }); } /// When called after [deferFirstFrameReport]: tell the framework to report @@ -564,12 +569,13 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB /// This method may only be called once for each corresponding call /// to [deferFirstFrameReport]. /// - /// This is used by [WidgetsApp] to report the first frame. - // - // TODO(ianh): This method should only be available in debug and profile modes. + /// This is used by [WidgetsApp] to report when the first useful frame is + /// painted. void allowFirstFrameReport() { - assert(_deferFirstFrameReportCount >= 1); - _deferFirstFrameReportCount -= 1; + profile(() { + assert(_deferFirstFrameReportCount >= 1); + _deferFirstFrameReportCount -= 1; + }); } void _handleBuildScheduled() { @@ -691,13 +697,13 @@ mixin WidgetsBinding on BindingBase, SchedulerBinding, GestureBinding, RendererB return true; }()); } - // TODO(ianh): Following code should not be included in release mode, only profile and debug modes. - // See https://github.com/dart-lang/sdk/issues/27192 - if (_needToReportFirstFrame && _reportFirstFrame) { - developer.Timeline.instantSync('Widgets completed first useful frame'); - developer.postEvent('Flutter.FirstFrame', {}); - _needToReportFirstFrame = false; - } + profile(() { + if (_needToReportFirstFrame && _reportFirstFrame) { + developer.Timeline.instantSync('Widgets completed first useful frame'); + developer.postEvent('Flutter.FirstFrame', {}); + _needToReportFirstFrame = false; + } + }); } /// The [Element] that is at the root of the hierarchy (and which wraps the diff --git a/packages/flutter_driver/lib/src/common/message.dart b/packages/flutter_driver/lib/src/common/message.dart index 36aab524c5c..f66d14804e1 100644 --- a/packages/flutter_driver/lib/src/common/message.dart +++ b/packages/flutter_driver/lib/src/common/message.dart @@ -9,16 +9,24 @@ import 'package:meta/meta.dart'; abstract class Command { /// Abstract const constructor. This constructor enables subclasses to provide /// const constructors so that they can be used in const expressions. - const Command({ Duration timeout }) - : timeout = timeout ?? const Duration(seconds: 5); + const Command({ this.timeout }); /// Deserializes this command from the value generated by [serialize]. Command.deserialize(Map json) - : timeout = Duration(milliseconds: int.parse(json['timeout'])); + : timeout = _parseTimeout(json); + + static Duration _parseTimeout(Map json) { + final String timeout = json['timeout']; + if (timeout == null) + return null; + return Duration(milliseconds: int.parse(timeout)); + } /// The maximum amount of time to wait for the command to complete. /// - /// Defaults to 5 seconds. + /// Defaults to no timeout, because it is common for operations to take oddly + /// long in test environments (e.g. because the test host is overloaded), and + /// having timeouts essentially means having race conditions. final Duration timeout; /// Identifies the type of the command object and of the handler. @@ -26,10 +34,14 @@ abstract class Command { /// Serializes this command to parameter name/value pairs. @mustCallSuper - Map serialize() => { - 'command': kind, - 'timeout': '${timeout.inMilliseconds}', - }; + Map serialize() { + final Map result = { + 'command': kind, + }; + if (timeout != null) + result['timeout'] = '${timeout.inMilliseconds}'; + return result; + } } /// An object sent from a Flutter application back to the Flutter Driver in diff --git a/packages/flutter_driver/lib/src/driver/driver.dart b/packages/flutter_driver/lib/src/driver/driver.dart index 34c3cf4262c..96edc272116 100644 --- a/packages/flutter_driver/lib/src/driver/driver.dart +++ b/packages/flutter_driver/lib/src/driver/driver.dart @@ -61,38 +61,13 @@ enum TimelineStream { const List _defaultStreams = [TimelineStream.all]; -/// Multiplies the timeout values used when establishing a connection to the -/// Flutter app under test and obtain an instance of [FlutterDriver]. -/// -/// This multiplier applies automatically when using the default implementation -/// of the [vmServiceConnectFunction]. -/// -/// See also: -/// -/// * [FlutterDriver.timeoutMultiplier], which multiplies all command timeouts by this number. -double connectionTimeoutMultiplier = _kDefaultTimeoutMultiplier; - -const double _kDefaultTimeoutMultiplier = 1.0; - -/// Default timeout for short-running RPCs. -Duration _shortTimeout(double multiplier) => const Duration(seconds: 5) * multiplier; - -/// Default timeout for awaiting an Isolate to become runnable. -Duration _isolateLoadRunnableTimeout(double multiplier) => const Duration(minutes: 1) * multiplier; - -/// Time to delay before driving a Fuchsia module. -Duration _fuchsiaDriveDelay(double multiplier) => const Duration(milliseconds: 500) * multiplier; - -/// Default timeout for long-running RPCs. -Duration _longTimeout(double multiplier) => _shortTimeout(multiplier) * 6; - -/// Additional amount of time we give the command to finish or timeout remotely -/// before timing out locally. -Duration _rpcGraceTime(double multiplier) => _shortTimeout(multiplier) ~/ 2; +/// How long to wait before showing a message saying that +/// things seem to be taking a long time. +const Duration _kUnusuallyLongTimeout = Duration(seconds: 5); /// The amount of time we wait prior to making the next attempt to connect to /// the VM service. -Duration _pauseBetweenReconnectAttempts(double multiplier) => _shortTimeout(multiplier) ~/ 5; +const Duration _kPauseBetweenReconnectAttempts = Duration(seconds: 1); // See https://github.com/dart-lang/sdk/blob/master/runtime/vm/timeline.cc#L32 String _timelineStreamsToString(List streams) { @@ -116,6 +91,27 @@ String _timelineStreamsToString(List streams) { final Logger _log = Logger('FlutterDriver'); +Future _warnIfSlow({ + @required Future future, + @required Duration timeout, + @required String message, +}) { + assert(future != null); + assert(timeout != null); + assert(message != null); + return future..timeout(timeout, onTimeout: () { _log.warning(message); }); +} + +Duration _maxDuration(Duration a, Duration b) { + if (a == null) + return b; + if (b == null) + return a; + if (a > b) + return a; + return b; +} + /// A convenient accessor to frequently used finders. /// /// Examples: @@ -142,7 +138,6 @@ class FlutterDriver { this._appIsolate, { bool printCommunication = false, bool logCommunicationToFile = true, - this.timeoutMultiplier = _kDefaultTimeoutMultiplier, }) : _printCommunication = printCommunication, _logCommunicationToFile = logCommunicationToFile, _driverId = _nextDriverId++; @@ -159,41 +154,38 @@ class FlutterDriver { /// /// Resumes the application if it is currently paused (e.g. at a breakpoint). /// - /// [dartVmServiceUrl] is the URL to Dart observatory (a.k.a. VM service). If + /// `dartVmServiceUrl` is the URL to Dart observatory (a.k.a. VM service). If /// not specified, the URL specified by the `VM_SERVICE_URL` environment /// variable is used. One or the other must be specified. /// - /// [printCommunication] determines whether the command communication between + /// `printCommunication` determines whether the command communication between /// the test and the app should be printed to stdout. /// - /// [logCommunicationToFile] determines whether the command communication + /// `logCommunicationToFile` determines whether the command communication /// between the test and the app should be logged to `flutter_driver_commands.log`. /// - /// [FlutterDriver] multiplies all command timeouts by [timeoutMultiplier]. - /// - /// [isolateNumber] (optional) determines the specific isolate to connect to. + /// `isolateNumber` determines the specific isolate to connect to. /// If this is left as `null`, will connect to the first isolate found - /// running on [dartVmServiceUrl]. + /// running on `dartVmServiceUrl`. /// - /// [isolateReadyTimeout] determines how long after we connect to the VM - /// service we will wait for the first isolate to become runnable. Explicitly - /// specified non-null values are not affected by [timeoutMultiplier]. + /// `fuchsiaModuleTarget` specifies the pattern for determining which mod to + /// control. When running on a Fuchsia device, either this or the environment + /// variable `FUCHSIA_MODULE_TARGET` must be set (the environment variable is + /// treated as a substring pattern). This field will be ignored if + /// `isolateNumber` is set, as this is already enough information to connect + /// to an isolate. /// - /// [fuchsiaModuleTarget] (optional) If running on a Fuchsia Device, either - /// this or the environment variable `FUCHSIA_MODULE_TARGET` must be set. This - /// field will be ignored if [isolateNumber] is set, as this is already - /// enough information to connect to an Isolate. + /// The return value is a future. This method never times out, though it may + /// fail (completing with an error). A timeout can be applied by the caller + /// using [Future.timeout] if necessary. static Future connect({ String dartVmServiceUrl, bool printCommunication = false, bool logCommunicationToFile = true, - double timeoutMultiplier = _kDefaultTimeoutMultiplier, int isolateNumber, - Duration isolateReadyTimeout, Pattern fuchsiaModuleTarget, }) async { - isolateReadyTimeout ??= _isolateLoadRunnableTimeout(timeoutMultiplier); - // If running on a Fuchsia device, connect to the first Isolate whose name + // If running on a Fuchsia device, connect to the first isolate whose name // matches FUCHSIA_MODULE_TARGET. // // If the user has already supplied an isolate number/URL to the Dart VM @@ -204,16 +196,17 @@ class FlutterDriver { flutterDriverLog.listen(print); fuchsiaModuleTarget ??= Platform.environment['FUCHSIA_MODULE_TARGET']; if (fuchsiaModuleTarget == null) { - throw DriverError('No Fuchsia module target has been specified.\n' - 'Please make sure to specify the FUCHSIA_MODULE_TARGET\n' - 'environment variable.'); + throw DriverError( + 'No Fuchsia module target has been specified.\n' + 'Please make sure to specify the FUCHSIA_MODULE_TARGET ' + 'environment variable.' + ); } final fuchsia.FuchsiaRemoteConnection fuchsiaConnection = await FuchsiaCompat.connect(); final List refs = await fuchsiaConnection.getMainIsolatesByPattern(fuchsiaModuleTarget); final fuchsia.IsolateRef ref = refs.first; - await Future.delayed(_fuchsiaDriveDelay(timeoutMultiplier)); isolateNumber = ref.number; dartVmServiceUrl = ref.dartVm.uri.toString(); await fuchsiaConnection.stop(); @@ -224,14 +217,14 @@ class FlutterDriver { if (dartVmServiceUrl == null) { throw DriverError( - 'Could not determine URL to connect to application.\n' - 'Either the VM_SERVICE_URL environment variable should be set, or an explicit\n' - 'URL should be provided to the FlutterDriver.connect() method.'); + 'Could not determine URL to connect to application.\n' + 'Either the VM_SERVICE_URL environment variable should be set, or an explicit ' + 'URL should be provided to the FlutterDriver.connect() method.' + ); } // Connect to Dart VM services _log.info('Connecting to Flutter application at $dartVmServiceUrl'); - connectionTimeoutMultiplier = timeoutMultiplier; final VMServiceClientConnection connection = await vmServiceConnectFunction(dartVmServiceUrl); final VMServiceClient client = connection.client; @@ -242,12 +235,7 @@ class FlutterDriver { (VMIsolateRef isolate) => isolate.number == isolateNumber); _log.trace('Isolate found with number: ${isolateRef.number}'); - VMIsolate isolate = await isolateRef - .loadRunnable() - .timeout(isolateReadyTimeout, onTimeout: () { - throw TimeoutException( - 'Timeout while waiting for the isolate to become runnable'); - }); + VMIsolate isolate = await isolateRef.loadRunnable(); // TODO(yjbanov): vm_service_client does not support "None" pause event yet. // It is currently reported as null, but we cannot rely on it because @@ -262,7 +250,6 @@ class FlutterDriver { isolate.pauseEvent is! VMPauseExceptionEvent && isolate.pauseEvent is! VMPauseInterruptedEvent && isolate.pauseEvent is! VMResumeEvent) { - await Future.delayed(_shortTimeout(timeoutMultiplier) ~/ 10); isolate = await isolateRef.loadRunnable(); } @@ -270,7 +257,6 @@ class FlutterDriver { client, connection.peer, isolate, printCommunication: printCommunication, logCommunicationToFile: logCommunicationToFile, - timeoutMultiplier: timeoutMultiplier, ); // Attempts to resume the isolate, but does not crash if it fails because @@ -323,23 +309,21 @@ class FlutterDriver { // option, then the VM service extension is not registered yet. Wait for // it to be registered. await enableIsolateStreams(); - final Future whenServiceExtensionReady = waitForServiceExtension(); + final Future whenServiceExtensionReady = waitForServiceExtension(); final Future whenResumed = resumeLeniently(); await whenResumed; - try { - _log.trace('Waiting for service extension'); - // We will never receive the extension event if the user does not - // register it. If that happens time out. - await whenServiceExtensionReady.timeout(_longTimeout(timeoutMultiplier) * 2); - } on TimeoutException catch (_) { - throw DriverError( - 'Timed out waiting for Flutter Driver extension to become available. ' - 'Ensure your test app (often: lib/main.dart) imports ' - '"package:flutter_driver/driver_extension.dart" and ' - 'calls enableFlutterDriverExtension() as the first call in main().' - ); - } + _log.trace('Waiting for service extension'); + // We will never receive the extension event if the user does not + // register it. If that happens, show a message but continue waiting. + await _warnIfSlow( + future: whenServiceExtensionReady, + timeout: _kUnusuallyLongTimeout, + message: 'Flutter Driver extension is taking a long time to become available. ' + 'Ensure your test app (often "lib/main.dart") imports ' + '"package:flutter_driver/driver_extension.dart" and ' + 'calls enableFlutterDriverExtension() as the first call in main().' + ); } else if (isolate.pauseEvent is VMPauseExitEvent || isolate.pauseEvent is VMPauseBreakpointEvent || isolate.pauseEvent is VMPauseExceptionEvent || @@ -372,7 +356,7 @@ class FlutterDriver { 'registered.' ); await enableIsolateStreams(); - await waitForServiceExtension().timeout(_longTimeout(timeoutMultiplier) * 2); + await waitForServiceExtension(); return driver.checkHealth(); } } @@ -405,29 +389,21 @@ class FlutterDriver { /// Whether to log communication between host and app to `flutter_driver_commands.log`. final bool _logCommunicationToFile; - /// [FlutterDriver] multiplies all command timeouts by this number. - /// - /// The right amount of time a driver command should be given to complete - /// depends on various environmental factors, such as the speed of the - /// device or the emulator, connection speed and latency, and others. Use - /// this multiplier to tailor the timeouts to your environment. - final double timeoutMultiplier; - Future> _sendCommand(Command command) async { Map response; try { final Map serialized = command.serialize(); _logCommunication('>>> $serialized'); - response = await _appIsolate - .invokeExtension(_flutterExtensionMethodName, serialized) - .timeout(command.timeout + _rpcGraceTime(timeoutMultiplier)); - _logCommunication('<<< $response'); - } on TimeoutException catch (error, stackTrace) { - throw DriverError( - 'Failed to fulfill ${command.runtimeType}: Flutter application not responding', - error, - stackTrace, + final Future> future = _appIsolate.invokeExtension( + _flutterExtensionMethodName, + serialized, + ).then>((Object value) => value); + response = await _warnIfSlow>( + future: future, + timeout: _maxDuration(command.timeout, _kUnusuallyLongTimeout), + message: '${command.kind} message is taking a long time to complete...', ); + _logCommunication('<<< $response'); } catch (error, stackTrace) { throw DriverError( 'Failed to fulfill ${command.runtimeType} due to remote error', @@ -452,31 +428,26 @@ class FlutterDriver { /// Checks the status of the Flutter Driver extension. Future checkHealth({Duration timeout}) async { - timeout ??= _shortTimeout(timeoutMultiplier); return Health.fromJson(await _sendCommand(GetHealth(timeout: timeout))); } /// Returns a dump of the render tree. Future getRenderTree({Duration timeout}) async { - timeout ??= _shortTimeout(timeoutMultiplier); return RenderTree.fromJson(await _sendCommand(GetRenderTree(timeout: timeout))); } /// Taps at the center of the widget located by [finder]. Future tap(SerializableFinder finder, {Duration timeout}) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(Tap(finder, timeout: timeout)); } /// Waits until [finder] locates the target. Future waitFor(SerializableFinder finder, {Duration timeout}) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(WaitFor(finder, timeout: timeout)); } /// Waits until [finder] can no longer locate the target. Future waitForAbsent(SerializableFinder finder, {Duration timeout}) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(WaitForAbsent(finder, timeout: timeout)); } @@ -485,7 +456,6 @@ class FlutterDriver { /// Use this method when you need to wait for the moment when the application /// becomes "stable", for example, prior to taking a [screenshot]. Future waitUntilNoTransientCallbacks({Duration timeout}) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(WaitUntilNoTransientCallbacks(timeout: timeout)); } @@ -503,7 +473,6 @@ class FlutterDriver { /// The move events are generated at a given [frequency] in Hz (or events per /// second). It defaults to 60Hz. Future scroll(SerializableFinder finder, double dx, double dy, Duration duration, { int frequency = 60, Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(Scroll(finder, dx, dy, duration, frequency, timeout: timeout)); } @@ -515,7 +484,6 @@ class FlutterDriver { /// then this method may fail because [finder] doesn't actually exist. /// The [scrollUntilVisible] method can be used in this case. Future scrollIntoView(SerializableFinder finder, { double alignment = 0.0, Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(ScrollIntoView(finder, alignment: alignment, timeout: timeout)); } @@ -540,12 +508,12 @@ class FlutterDriver { /// for [dyScroll]. /// /// The [timeout] value should be long enough to accommodate as many scrolls - /// as needed to bring an item into view. The default is 10 seconds. + /// as needed to bring an item into view. The default is to not time out. Future scrollUntilVisible(SerializableFinder scrollable, SerializableFinder item, { double alignment = 0.0, double dxScroll = 0.0, double dyScroll = 0.0, - Duration timeout = const Duration(seconds: 10), + Duration timeout, }) async { assert(scrollable != null); assert(item != null); @@ -553,7 +521,6 @@ class FlutterDriver { assert(dxScroll != null); assert(dyScroll != null); assert(dxScroll != 0.0 || dyScroll != 0.0); - assert(timeout != null); // Kick off an (unawaited) waitFor that will complete when the item we're // looking for finally scrolls onscreen. We add an initial pause to give it @@ -572,7 +539,6 @@ class FlutterDriver { /// Returns the text in the `Text` widget located by [finder]. Future getText(SerializableFinder finder, { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); return GetTextResult.fromJson(await _sendCommand(GetText(finder, timeout: timeout))).text; } @@ -609,7 +575,6 @@ class FlutterDriver { /// }); /// ``` Future enterText(String text, { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(EnterText(text, timeout: timeout)); } @@ -628,7 +593,6 @@ class FlutterDriver { /// channel will be mocked out. Future setTextEntryEmulation({ @required bool enabled, Duration timeout }) async { assert(enabled != null); - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(SetTextEntryEmulation(enabled, timeout: timeout)); } @@ -639,7 +603,6 @@ class FlutterDriver { /// callback in [enableFlutterDriverExtension] that can successfully handle /// these requests. Future requestData(String message, { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); return RequestDataResult.fromJson(await _sendCommand(RequestData(message, timeout: timeout))).message; } @@ -648,7 +611,6 @@ class FlutterDriver { /// Returns true when the call actually changed the state from on to off or /// vice versa. Future setSemantics(bool enabled, { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); final SetSemanticsResult result = SetSemanticsResult.fromJson(await _sendCommand(SetSemantics(enabled, timeout: timeout))); return result.changedState; } @@ -662,16 +624,15 @@ class FlutterDriver { /// Semantics must be enabled to use this method, either using a platform /// specific shell command or [setSemantics]. Future getSemanticsId(SerializableFinder finder, { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); final Map jsonResponse = await _sendCommand(GetSemanticsId(finder, timeout: timeout)); final GetSemanticsIdResult result = GetSemanticsIdResult.fromJson(jsonResponse); return result.id; } - /// Take a screenshot. The image will be returned as a PNG. - Future> screenshot({ Duration timeout }) async { - timeout ??= _longTimeout(timeoutMultiplier); - + /// Take a screenshot. + /// + /// The image will be returned as a PNG. + Future> screenshot() async { // HACK: this artificial delay here is to deal with a race between the // driver script and the GPU thread. The issue is that driver API // synchronizes with the framework based on transient callbacks, which @@ -679,7 +640,7 @@ class FlutterDriver { // in ASCII art: // // ------------------------------------------------------------------- - // Before this change: + // Without this delay: // ------------------------------------------------------------------- // UI : <-- build --> // GPU : <-- rasterize --> @@ -690,12 +651,13 @@ class FlutterDriver { // action taken, such as a `tap()`, and the subsequent call to // `screenshot()`. The gap is random because it is determined by the // unpredictable network communication between the driver process and - // the application. If this gap is too short, the screenshot is taken - // before the GPU thread is done rasterizing the frame, so the - // screenshot of the previous frame is taken, which is wrong. + // the application. If this gap is too short, which it typically will + // be, the screenshot is taken before the GPU thread is done + // rasterizing the frame, so the screenshot of the previous frame is + // taken, which is wrong. // // ------------------------------------------------------------------- - // After this change: + // With this delay, if we're lucky: // ------------------------------------------------------------------- // UI : <-- build --> // GPU : <-- rasterize --> @@ -705,16 +667,28 @@ class FlutterDriver { // The two-second gap should be long enough for the GPU thread to // finish rasterizing the frame, but not longer than necessary to keep // driver tests as fast a possible. + // + // ------------------------------------------------------------------- + // With this delay, if we're not lucky: + // ------------------------------------------------------------------- + // UI : <-- build --> + // GPU : <-- rasterize randomly slow today --> + // Gap : | 2 seconds or more | + // Driver: <-- screenshot --> + // + // In practice, sometimes the device gets really busy for a while and + // even two seconds isn't enough, which means that this is still racy + // and a source of flakes. await Future.delayed(const Duration(seconds: 2)); - final Map result = await _peer.sendRequest('_flutter.screenshot').timeout(timeout); + final Map result = await _peer.sendRequest('_flutter.screenshot'); return base64.decode(result['screenshot']); } /// Returns the Flags set in the Dart VM as JSON. /// - /// See the complete documentation for `getFlagList` Dart VM service method - /// [here][getFlagList]. + /// See the complete documentation for [the `getFlagList` Dart VM service + /// method][getFlagList]. /// /// Example return value: /// @@ -730,23 +704,30 @@ class FlutterDriver { /// ] /// /// [getFlagList]: https://github.com/dart-lang/sdk/blob/master/runtime/vm/service/service.md#getflaglist - Future>> getVmFlags({ Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); - final Map result = await _peer.sendRequest('getFlagList').timeout(timeout); + Future>> getVmFlags() async { + final Map result = await _peer.sendRequest('getFlagList'); return result['flags']; } /// Starts recording performance traces. + /// + /// The `timeout` argument causes a warning to be displayed to the user if the + /// operation exceeds the specified timeout; it does not actually cancel the + /// operation. Future startTracing({ List streams = _defaultStreams, - Duration timeout, + Duration timeout = _kUnusuallyLongTimeout, }) async { - timeout ??= _shortTimeout(timeoutMultiplier); assert(streams != null && streams.isNotEmpty); + assert(timeout != null); try { - await _peer.sendRequest(_setVMTimelineFlagsMethodName, { - 'recordedStreams': _timelineStreamsToString(streams) - }).timeout(timeout); + await _warnIfSlow( + future: _peer.sendRequest(_setVMTimelineFlagsMethodName, { + 'recordedStreams': _timelineStreamsToString(streams) + }), + timeout: timeout, + message: 'VM is taking an unusually long time to respond to being told to start tracing...', + ); } catch (error, stackTrace) { throw DriverError( 'Failed to start tracing due to remote error', @@ -757,12 +738,20 @@ class FlutterDriver { } /// Stops recording performance traces and downloads the timeline. - Future stopTracingAndDownloadTimeline({ Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); + /// + /// The `timeout` argument causes a warning to be displayed to the user if the + /// operation exceeds the specified timeout; it does not actually cancel the + /// operation. + Future stopTracingAndDownloadTimeline({ + Duration timeout = _kUnusuallyLongTimeout, + }) async { + assert(timeout != null); try { - await _peer - .sendRequest(_setVMTimelineFlagsMethodName, {'recordedStreams': '[]'}) - .timeout(timeout); + await _warnIfSlow( + future: _peer.sendRequest(_setVMTimelineFlagsMethodName, {'recordedStreams': '[]'}), + timeout: timeout, + message: 'VM is taking an unusually long time to respond to being told to stop tracing...', + ); return Timeline.fromJson(await _peer.sendRequest(_getVMTimelineMethodName)); } catch (error, stackTrace) { throw DriverError( @@ -801,12 +790,20 @@ class FlutterDriver { } /// Clears all timeline events recorded up until now. - Future clearTimeline({ Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); + /// + /// The `timeout` argument causes a warning to be displayed to the user if the + /// operation exceeds the specified timeout; it does not actually cancel the + /// operation. + Future clearTimeline({ + Duration timeout = _kUnusuallyLongTimeout + }) async { + assert(timeout != null); try { - await _peer - .sendRequest(_clearVMTimelineMethodName, {}) - .timeout(timeout); + await _warnIfSlow( + future: _peer.sendRequest(_clearVMTimelineMethodName, {}), + timeout: timeout, + message: 'VM is taking an unusually long time to respond to being told to clear its timeline buffer...', + ); } catch (error, stackTrace) { throw DriverError( 'Failed to clear event timeline due to remote error', @@ -833,7 +830,6 @@ class FlutterDriver { /// ensure that no action is performed while the app is undergoing a /// transition to avoid flakiness. Future runUnsynchronized(Future action(), { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(SetFrameSync(false, timeout: timeout)); T result; try { @@ -893,11 +889,6 @@ typedef VMServiceConnectFunction = Future Function(St /// /// Overwrite this function if you require a custom method for connecting to /// the VM service. -/// -/// See also: -/// -/// * [connectionTimeoutMultiplier], which controls the timeouts while -/// establishing a connection using the default connection function. VMServiceConnectFunction vmServiceConnectFunction = _waitAndConnect; /// Restores [vmServiceConnectFunction] to its default value. @@ -907,44 +898,30 @@ void restoreVmServiceConnectFunction() { /// Waits for a real Dart VM service to become available, then connects using /// the [VMServiceClient]. -/// -/// Times out after 30 seconds. Future _waitAndConnect(String url) async { - final Stopwatch timer = Stopwatch()..start(); - - Future attemptConnection() async { - Uri uri = Uri.parse(url); - if (uri.scheme == 'http') - uri = uri.replace(scheme: 'ws', path: '/ws'); - + Uri uri = Uri.parse(url); + if (uri.scheme == 'http') + uri = uri.replace(scheme: 'ws', path: '/ws'); + int attempts = 0; + while (true) { WebSocket ws1; WebSocket ws2; try { - ws1 = await WebSocket.connect(uri.toString()).timeout(_shortTimeout(connectionTimeoutMultiplier)); - ws2 = await WebSocket.connect(uri.toString()).timeout(_shortTimeout(connectionTimeoutMultiplier)); + ws1 = await WebSocket.connect(uri.toString()); + ws2 = await WebSocket.connect(uri.toString()); return VMServiceClientConnection( VMServiceClient(IOWebSocketChannel(ws1).cast()), - rpc.Peer(IOWebSocketChannel(ws2).cast())..listen() + rpc.Peer(IOWebSocketChannel(ws2).cast())..listen(), ); } catch (e) { await ws1?.close(); await ws2?.close(); - - if (timer.elapsed < _longTimeout(connectionTimeoutMultiplier) * 2) { - _log.info('Waiting for application to start'); - await Future.delayed(_pauseBetweenReconnectAttempts(connectionTimeoutMultiplier)); - return attemptConnection(); - } else { - _log.critical( - 'Application has not started in 30 seconds. ' - 'Giving up.' - ); - rethrow; - } + if (attempts > 5) + _log.warning('It is taking an unusually long time to connect to the VM...'); + attempts += 1; + await Future.delayed(_kPauseBetweenReconnectAttempts); } } - - return attemptConnection(); } /// Provides convenient accessors to frequently used finders. diff --git a/packages/flutter_driver/lib/src/extension/extension.dart b/packages/flutter_driver/lib/src/extension/extension.dart index 98afd4ededc..01857be8953 100644 --- a/packages/flutter_driver/lib/src/extension/extension.dart +++ b/packages/flutter_driver/lib/src/extension/extension.dart @@ -177,7 +177,10 @@ class FlutterDriverExtension { if (commandHandler == null || commandDeserializer == null) throw 'Extension $_extensionMethod does not support command $commandKind'; final Command command = commandDeserializer(params); - final Result response = await commandHandler(command).timeout(command.timeout); + Future responseFuture = commandHandler(command); + if (command.timeout != null) + responseFuture = responseFuture.timeout(command.timeout); + final Result response = await responseFuture; return _makeResponse(response?.toJson()); } on TimeoutException catch (error, stackTrace) { final String msg = 'Timeout while executing $commandKind: $error\n$stackTrace'; diff --git a/packages/flutter_driver/test/flutter_driver_test.dart b/packages/flutter_driver/test/flutter_driver_test.dart index 4a72a16a15a..6bf130236d7 100644 --- a/packages/flutter_driver/test/flutter_driver_test.dart +++ b/packages/flutter_driver/test/flutter_driver_test.dart @@ -11,13 +11,13 @@ import 'package:flutter_driver/src/driver/timeline.dart'; import 'package:json_rpc_2/json_rpc_2.dart' as rpc; import 'package:mockito/mockito.dart'; import 'package:vm_service_client/vm_service_client.dart'; +import 'package:quiver/testing/async.dart'; import 'common.dart'; /// Magical timeout value that's different from the default. const Duration _kTestTimeout = Duration(milliseconds: 1234); const String _kSerializedTestTimeout = '1234'; -const Duration _kDefaultCommandTimeout = Duration(seconds: 5); void main() { group('FlutterDriver.connect', () { @@ -358,17 +358,19 @@ void main() { group('sendCommand error conditions', () { test('local timeout', () async { + final List log = []; + final StreamSubscription logSub = flutterDriverLog.listen((LogRecord s) => log.add(s.toString())); when(mockIsolate.invokeExtension(any, any)).thenAnswer((Invocation i) { - // completer never competed to trigger timeout + // completer never completed to trigger timeout return Completer>().future; }); - try { - await driver.waitFor(find.byTooltip('foo'), timeout: const Duration(milliseconds: 100)); - fail('expected an exception'); - } catch (error) { - expect(error is DriverError, isTrue); - expect(error.message, 'Failed to fulfill WaitFor: Flutter application not responding'); - } + FakeAsync().run((FakeAsync time) { + driver.waitFor(find.byTooltip('foo')); + expect(log, []); + time.elapse(const Duration(hours: 1)); + }); + expect(log, ['[warning] FlutterDriver: waitFor message is taking a long time to complete...']); + await logSub.cancel(); }); test('remote error', () async { @@ -389,7 +391,6 @@ void main() { }); group('FlutterDriver with custom timeout', () { - const double kTestMultiplier = 3.0; MockVMServiceClient mockClient; MockPeer mockPeer; MockIsolate mockIsolate; @@ -399,21 +400,20 @@ void main() { mockClient = MockVMServiceClient(); mockPeer = MockPeer(); mockIsolate = MockIsolate(); - driver = FlutterDriver.connectedTo(mockClient, mockPeer, mockIsolate, timeoutMultiplier: kTestMultiplier); + driver = FlutterDriver.connectedTo(mockClient, mockPeer, mockIsolate); }); - test('multiplies the timeout', () async { + test('GetHealth has no default timeout', () async { when(mockIsolate.invokeExtension(any, any)).thenAnswer((Invocation i) { expect(i.positionalArguments[1], { 'command': 'get_health', - 'timeout': '${(_kDefaultCommandTimeout * kTestMultiplier).inMilliseconds}', }); return makeMockResponse({'status': 'ok'}); }); await driver.checkHealth(); }); - test('does not multiply explicit timeouts', () async { + test('does not interfere with explicit timeouts', () async { when(mockIsolate.invokeExtension(any, any)).thenAnswer((Invocation i) { expect(i.positionalArguments[1], { 'command': 'get_health', diff --git a/packages/flutter_tools/lib/src/android/android_device.dart b/packages/flutter_tools/lib/src/android/android_device.dart index fdb9ebfe7ea..bca4b00475f 100644 --- a/packages/flutter_tools/lib/src/android/android_device.dart +++ b/packages/flutter_tools/lib/src/android/android_device.dart @@ -88,15 +88,13 @@ class AndroidDevice extends Device { propCommand, stdoutEncoding: latin1, stderrEncoding: latin1, - ).timeout(const Duration(seconds: 5)); + ); if (result.exitCode == 0) { _properties = parseAdbDeviceProperties(result.stdout); } else { printError('Error retrieving device properties for $name:'); printError(result.stderr); } - } on TimeoutException catch (_) { - throwToolExit('adb not responding'); } on ProcessException catch (error) { printError('Error retrieving device properties for $name: $error'); } @@ -279,7 +277,7 @@ class AndroidDevice extends Device { if (!await _checkForSupportedAdbVersion() || !await _checkForSupportedAndroidVersion()) return false; - final Status status = logger.startProgress('Installing ${fs.path.relative(apk.file.path)}...', expectSlowOperation: true); + final Status status = logger.startProgress('Installing ${fs.path.relative(apk.file.path)}...', timeout: kSlowOperation); final RunResult installResult = await runAsync(adbCommandForDevice(['install', '-t', '-r', apk.file.path])); status.stop(); // Some versions of adb exit with exit code 0 even on failure :( diff --git a/packages/flutter_tools/lib/src/android/android_emulator.dart b/packages/flutter_tools/lib/src/android/android_emulator.dart index 6a0e24de693..bce406251ae 100644 --- a/packages/flutter_tools/lib/src/android/android_emulator.dart +++ b/packages/flutter_tools/lib/src/android/android_emulator.dart @@ -51,9 +51,10 @@ class AndroidEmulator extends Emulator { throw '${runResult.stdout}\n${runResult.stderr}'.trimRight(); } }); - // emulator continues running on a successful launch so if we - // haven't quit within 3 seconds we assume that's a success and just - // return. + // The emulator continues running on a successful launch, so if it hasn't + // quit within 3 seconds we assume that's a success and just return. This + // means that on a slow machine, a failure that takes more than three + // seconds won't be recognized as such... :-/ return Future.any(>[ launchResult, Future.delayed(const Duration(seconds: 3)) diff --git a/packages/flutter_tools/lib/src/android/android_workflow.dart b/packages/flutter_tools/lib/src/android/android_workflow.dart index 6fccde73989..d1978a225fc 100644 --- a/packages/flutter_tools/lib/src/android/android_workflow.dart +++ b/packages/flutter_tools/lib/src/android/android_workflow.dart @@ -50,32 +50,41 @@ class AndroidWorkflow implements Workflow { class AndroidValidator extends DoctorValidator { AndroidValidator(): super('Android toolchain - develop for Android devices',); + @override + String get slowWarning => '${_task ?? 'This'} is taking a long time...'; + String _task; + /// Returns false if we cannot determine the Java version or if the version /// is not compatible. Future _checkJavaVersion(String javaBinary, List messages) async { - if (!processManager.canRun(javaBinary)) { - messages.add(ValidationMessage.error(userMessages.androidCantRunJavaBinary(javaBinary))); - return false; - } - String javaVersion; + _task = 'Checking Java status'; try { - printTrace('java -version'); - final ProcessResult result = await processManager.run([javaBinary, '-version']); - if (result.exitCode == 0) { - final List versionLines = result.stderr.split('\n'); - javaVersion = versionLines.length >= 2 ? versionLines[1] : versionLines[0]; + if (!processManager.canRun(javaBinary)) { + messages.add(ValidationMessage.error(userMessages.androidCantRunJavaBinary(javaBinary))); + return false; } - } catch (error) { - printTrace(error.toString()); + String javaVersion; + try { + printTrace('java -version'); + final ProcessResult result = await processManager.run([javaBinary, '-version']); + if (result.exitCode == 0) { + final List versionLines = result.stderr.split('\n'); + javaVersion = versionLines.length >= 2 ? versionLines[1] : versionLines[0]; + } + } catch (error) { + printTrace(error.toString()); + } + if (javaVersion == null) { + // Could not determine the java version. + messages.add(ValidationMessage.error(userMessages.androidUnknownJavaVersion)); + return false; + } + messages.add(ValidationMessage(userMessages.androidJavaVersion(javaVersion))); + // TODO(johnmccutchan): Validate version. + return true; + } finally { + _task = null; } - if (javaVersion == null) { - // Could not determine the java version. - messages.add(ValidationMessage.error(userMessages.androidUnknownJavaVersion)); - return false; - } - messages.add(ValidationMessage(userMessages.androidJavaVersion(javaVersion))); - // TODO(johnmccutchan): Validate version. - return true; } @override @@ -149,6 +158,9 @@ class AndroidValidator extends DoctorValidator { class AndroidLicenseValidator extends DoctorValidator { AndroidLicenseValidator(): super('Android license subvalidator',); + @override + String get slowWarning => 'Checking Android licenses is taking an unexpectedly long time...'; + @override Future validate() async { final List messages = []; @@ -208,10 +220,8 @@ class AndroidLicenseValidator extends DoctorValidator { Future get licensesAccepted async { LicensesAccepted status; - void _onLine(String line) { - if (status == null && licenseAccepted.hasMatch(line)) { - status = LicensesAccepted.all; - } else if (licenseCounts.hasMatch(line)) { + void _handleLine(String line) { + if (licenseCounts.hasMatch(line)) { final Match match = licenseCounts.firstMatch(line); if (match.group(1) != match.group(2)) { status = LicensesAccepted.some; @@ -219,9 +229,12 @@ class AndroidLicenseValidator extends DoctorValidator { status = LicensesAccepted.none; } } else if (licenseNotAccepted.hasMatch(line)) { - // In case the format changes, a more general match will keep doctor - // mostly working. + // The licenseNotAccepted pattern is trying to match the same line as + // licenseCounts, but is more general. In case the format changes, a + // more general match may keep doctor mostly working. status = LicensesAccepted.none; + } else if (licenseAccepted.hasMatch(line)) { + status ??= LicensesAccepted.all; } } @@ -235,19 +248,14 @@ class AndroidLicenseValidator extends DoctorValidator { final Future output = process.stdout .transform(const Utf8Decoder(allowMalformed: true)) .transform(const LineSplitter()) - .listen(_onLine) + .listen(_handleLine) .asFuture(null); final Future errors = process.stderr .transform(const Utf8Decoder(allowMalformed: true)) .transform(const LineSplitter()) - .listen(_onLine) + .listen(_handleLine) .asFuture(null); - try { - await Future.wait(>[output, errors]).timeout(const Duration(seconds: 30)); - } catch (TimeoutException) { - printTrace(userMessages.androidLicensesTimeout(androidSdk.sdkManagerPath)); - processManager.killPid(process.pid); - } + await Future.wait(>[output, errors]); return status ?? LicensesAccepted.unknown; } @@ -261,9 +269,10 @@ class AndroidLicenseValidator extends DoctorValidator { _ensureCanRunSdkManager(); final Version sdkManagerVersion = Version.parse(androidSdk.sdkManagerVersion); - if (sdkManagerVersion == null || sdkManagerVersion.major < 26) + if (sdkManagerVersion == null || sdkManagerVersion.major < 26) { // SDK manager is found, but needs to be updated. throwToolExit(userMessages.androidSdkOutdated(androidSdk.sdkManagerPath)); + } final Process process = await runCommand( [androidSdk.sdkManagerPath, '--licenses'], diff --git a/packages/flutter_tools/lib/src/android/gradle.dart b/packages/flutter_tools/lib/src/android/gradle.dart index 781f7197029..60ddf91191f 100644 --- a/packages/flutter_tools/lib/src/android/gradle.dart +++ b/packages/flutter_tools/lib/src/android/gradle.dart @@ -97,7 +97,7 @@ Future _readGradleProject() async { final FlutterProject flutterProject = await FlutterProject.current(); final String gradle = await _ensureGradle(flutterProject); updateLocalProperties(project: flutterProject); - final Status status = logger.startProgress('Resolving dependencies...', expectSlowOperation: true); + final Status status = logger.startProgress('Resolving dependencies...', timeout: kSlowOperation); GradleProject project; try { final RunResult propertiesRunResult = await runCheckedAsync( @@ -175,7 +175,7 @@ Future _ensureGradle(FlutterProject project) async { // of validating the Gradle executable. This may take several seconds. Future _initializeGradle(FlutterProject project) async { final Directory android = project.android.hostAppGradleRoot; - final Status status = logger.startProgress('Initializing gradle...', expectSlowOperation: true); + final Status status = logger.startProgress('Initializing gradle...', timeout: kSlowOperation); String gradle = _locateGradlewExecutable(android); if (gradle == null) { injectGradleWrapper(android); @@ -314,8 +314,8 @@ Future buildGradleProject({ Future _buildGradleProjectV1(FlutterProject project, String gradle) async { // Run 'gradlew build'. final Status status = logger.startProgress( - "Running 'gradlew build'...", - expectSlowOperation: true, + 'Running \'gradlew build\'...', + timeout: kSlowOperation, multilineOutput: true, ); final int exitCode = await runCommandAndStreamOutput( @@ -365,8 +365,8 @@ Future _buildGradleProjectV2( } } final Status status = logger.startProgress( - "Gradle task '$assembleTask'...", - expectSlowOperation: true, + 'Running Gradle task \'$assembleTask\'...', + timeout: kSlowOperation, multilineOutput: true, ); final String gradlePath = fs.file(gradle).absolute.path; diff --git a/packages/flutter_tools/lib/src/base/context.dart b/packages/flutter_tools/lib/src/base/context.dart index df3de183ae0..5bc60d5b424 100644 --- a/packages/flutter_tools/lib/src/base/context.dart +++ b/packages/flutter_tools/lib/src/base/context.dart @@ -107,7 +107,7 @@ class AppContext { /// Gets the value associated with the specified [type], or `null` if no /// such value has been associated. - dynamic operator [](Type type) { + Object operator [](Type type) { dynamic value = _generateIfNecessary(type, _overrides); if (value == null && _parent != null) value = _parent[type]; diff --git a/packages/flutter_tools/lib/src/base/file_system.dart b/packages/flutter_tools/lib/src/base/file_system.dart index 0aeebed305f..3123e3502ef 100644 --- a/packages/flutter_tools/lib/src/base/file_system.dart +++ b/packages/flutter_tools/lib/src/base/file_system.dart @@ -36,9 +36,7 @@ RecordingFileSystem getRecordingFileSystem(String location) { final RecordingFileSystem fileSystem = RecordingFileSystem( delegate: _kLocalFs, destination: dir); addShutdownHook(() async { - await fileSystem.recording.flush( - pendingResultTimeout: const Duration(seconds: 5), - ); + await fileSystem.recording.flush(); }, ShutdownStage.SERIALIZE_RECORDING); return fileSystem; } diff --git a/packages/flutter_tools/lib/src/base/io.dart b/packages/flutter_tools/lib/src/base/io.dart index 70ca4fe9665..a3de8836290 100644 --- a/packages/flutter_tools/lib/src/base/io.dart +++ b/packages/flutter_tools/lib/src/base/io.dart @@ -162,10 +162,7 @@ class Stdio { bool get supportsAnsiEscapes => hasTerminal ? io.stdout.supportsAnsiEscapes : false; } -io.IOSink get stderr => context[Stdio].stderr; - -Stream> get stdin => context[Stdio].stdin; - -io.IOSink get stdout => context[Stdio].stdout; - Stdio get stdio => context[Stdio]; +io.IOSink get stdout => stdio.stdout; +Stream> get stdin => stdio.stdin; +io.IOSink get stderr => stdio.stderr; diff --git a/packages/flutter_tools/lib/src/base/logger.dart b/packages/flutter_tools/lib/src/base/logger.dart index eb8d92f5b5f..06b78075b6c 100644 --- a/packages/flutter_tools/lib/src/base/logger.dart +++ b/packages/flutter_tools/lib/src/base/logger.dart @@ -12,6 +12,8 @@ import 'terminal.dart'; import 'utils.dart'; const int kDefaultStatusPadding = 59; +const Duration kFastOperation = Duration(seconds: 2); +const Duration kSlowOperation = Duration(minutes: 2); typedef VoidCallback = void Function(); @@ -24,24 +26,30 @@ abstract class Logger { bool get hasTerminal => stdio.hasTerminal; - /// Display an error [message] to the user. Commands should use this if they + /// Display an error `message` to the user. Commands should use this if they /// fail in some way. /// - /// The [message] argument is printed to the stderr in red by default. - /// The [stackTrace] argument is the stack trace that will be printed if + /// The `message` argument is printed to the stderr in red by default. + /// + /// The `stackTrace` argument is the stack trace that will be printed if /// supplied. - /// The [emphasis] argument will cause the output message be printed in bold text. - /// The [color] argument will print the message in the supplied color instead + /// + /// The `emphasis` argument will cause the output message be printed in bold text. + /// + /// The `color` argument will print the message in the supplied color instead /// of the default of red. Colors will not be printed if the output terminal /// doesn't support them. - /// The [indent] argument specifies the number of spaces to indent the overall + /// + /// The `indent` argument specifies the number of spaces to indent the overall /// message. If wrapping is enabled in [outputPreferences], then the wrapped /// lines will be indented as well. - /// If [hangingIndent] is specified, then any wrapped lines will be indented + /// + /// If `hangingIndent` is specified, then any wrapped lines will be indented /// by this much more than the first line, if wrapping is enabled in /// [outputPreferences]. - /// If [wrap] is specified, then it overrides the - /// [outputPreferences.wrapText] setting. + /// + /// If `wrap` is specified, then it overrides the + /// `outputPreferences.wrapText` setting. void printError( String message, { StackTrace stackTrace, @@ -55,24 +63,31 @@ abstract class Logger { /// Display normal output of the command. This should be used for things like /// progress messages, success messages, or just normal command output. /// - /// The [message] argument is printed to the stderr in red by default. - /// The [stackTrace] argument is the stack trace that will be printed if + /// The `message` argument is printed to the stderr in red by default. + /// + /// The `stackTrace` argument is the stack trace that will be printed if /// supplied. - /// If the [emphasis] argument is true, it will cause the output message be + /// + /// If the `emphasis` argument is true, it will cause the output message be /// printed in bold text. Defaults to false. - /// The [color] argument will print the message in the supplied color instead + /// + /// The `color` argument will print the message in the supplied color instead /// of the default of red. Colors will not be printed if the output terminal /// doesn't support them. - /// If [newline] is true, then a newline will be added after printing the + /// + /// If `newline` is true, then a newline will be added after printing the /// status. Defaults to true. - /// The [indent] argument specifies the number of spaces to indent the overall + /// + /// The `indent` argument specifies the number of spaces to indent the overall /// message. If wrapping is enabled in [outputPreferences], then the wrapped /// lines will be indented as well. - /// If [hangingIndent] is specified, then any wrapped lines will be indented + /// + /// If `hangingIndent` is specified, then any wrapped lines will be indented /// by this much more than the first line, if wrapping is enabled in /// [outputPreferences]. - /// If [wrap] is specified, then it overrides the - /// [outputPreferences.wrapText] setting. + /// + /// If `wrap` is specified, then it overrides the + /// `outputPreferences.wrapText` setting. void printStatus( String message, { bool emphasis, @@ -89,17 +104,25 @@ abstract class Logger { /// Start an indeterminate progress display. /// - /// [message] is the message to display to the user; [progressId] provides an ID which can be - /// used to identify this type of progress (`hot.reload`, `hot.restart`, ...). + /// The `message` argument is the message to display to the user. /// - /// [progressIndicatorPadding] can optionally be used to specify spacing - /// between the [message] and the progress indicator. + /// The `timeout` argument sets a duration after which an additional message + /// may be shown saying that the operation is taking a long time. (Not all + /// [Status] subclasses show such a message.) Set this to null if the + /// operation can legitimately take an abritrary amount of time (e.g. waiting + /// for the user). + /// + /// The `progressId` argument provides an ID that can be used to identify + /// this type of progress (e.g. `hot.reload`, `hot.restart`). + /// + /// The `progressIndicatorPadding` can optionally be used to specify spacing + /// between the `message` and the progress indicator, if any. Status startProgress( String message, { + @required Duration timeout, String progressId, - bool expectSlowOperation, - bool multilineOutput, - int progressIndicatorPadding, + bool multilineOutput = false, + int progressIndicatorPadding = kDefaultStatusPadding, }); } @@ -119,17 +142,16 @@ class StdoutLogger extends Logger { int hangingIndent, bool wrap, }) { + _status?.pause(); message ??= ''; message = wrapText(message, indent: indent, hangingIndent: hangingIndent, shouldWrap: wrap); - _status?.cancel(); - _status = null; if (emphasis == true) message = terminal.bolden(message); message = terminal.color(message, color ?? TerminalColor.red); stderr.writeln(message); - if (stackTrace != null) { + if (stackTrace != null) stderr.writeln(stackTrace.toString()); - } + _status?.resume(); } @override @@ -142,10 +164,9 @@ class StdoutLogger extends Logger { int hangingIndent, bool wrap, }) { + _status?.pause(); message ??= ''; message = wrapText(message, indent: indent, hangingIndent: hangingIndent, shouldWrap: wrap); - _status?.cancel(); - _status = null; if (emphasis == true) message = terminal.bolden(message); if (color != null) @@ -153,6 +174,7 @@ class StdoutLogger extends Logger { if (newline != false) message = '$message\n'; writeToStdOut(message); + _status?.resume(); } @protected @@ -166,21 +188,23 @@ class StdoutLogger extends Logger { @override Status startProgress( String message, { + @required Duration timeout, String progressId, - bool expectSlowOperation, - bool multilineOutput, - int progressIndicatorPadding, + bool multilineOutput = false, + int progressIndicatorPadding = kDefaultStatusPadding, }) { - expectSlowOperation ??= false; - progressIndicatorPadding ??= kDefaultStatusPadding; + assert(progressIndicatorPadding != null); if (_status != null) { // Ignore nested progresses; return a no-op status object. - return Status(onFinish: _clearStatus)..start(); + return SilentStatus( + timeout: timeout, + onFinish: _clearStatus, + )..start(); } if (terminal.supportsColor) { _status = AnsiStatus( message: message, - expectSlowOperation: expectSlowOperation, + timeout: timeout, multilineOutput: multilineOutput, padding: progressIndicatorPadding, onFinish: _clearStatus, @@ -188,7 +212,7 @@ class StdoutLogger extends Logger { } else { _status = SummaryStatus( message: message, - expectSlowOperation: expectSlowOperation, + timeout: timeout, padding: progressIndicatorPadding, onFinish: _clearStatus, )..start(); @@ -270,13 +294,14 @@ class BufferLogger extends Logger { @override Status startProgress( String message, { + @required Duration timeout, String progressId, - bool expectSlowOperation, - bool multilineOutput, - int progressIndicatorPadding, + bool multilineOutput = false, + int progressIndicatorPadding = kDefaultStatusPadding, }) { + assert(progressIndicatorPadding != null); printStatus(message); - return Status()..start(); + return SilentStatus(timeout: timeout)..start(); } /// Clears all buffers. @@ -337,15 +362,30 @@ class VerboseLogger extends Logger { @override Status startProgress( String message, { + @required Duration timeout, String progressId, - bool expectSlowOperation, - bool multilineOutput, - int progressIndicatorPadding, + bool multilineOutput = false, + int progressIndicatorPadding = kDefaultStatusPadding, }) { + assert(progressIndicatorPadding != null); printStatus(message); - return Status(onFinish: () { - printTrace('$message (completed)'); - })..start(); + final Stopwatch timer = Stopwatch()..start(); + return SilentStatus( + timeout: timeout, + onFinish: () { + String time; + if (timeout == null || timeout > kFastOperation) { + time = getElapsedAsSeconds(timer.elapsed); + } else { + time = getElapsedAsMilliseconds(timer.elapsed); + } + if (timeout != null && timer.elapsed > timeout) { + printTrace('$message (completed in $time, longer than expected)'); + } else { + printTrace('$message (completed in $time)'); + } + }, + )..start(); } void _emit(_LogType type, String message, [StackTrace stackTrace]) { @@ -383,10 +423,15 @@ class VerboseLogger extends Logger { enum _LogType { error, status, trace } +typedef SlowWarningCallback = String Function(); + /// A [Status] class begins when start is called, and may produce progress /// information asynchronously. /// -/// The [Status] class itself never has any output. +/// Some subclasses change output once [timeout] has expired, to indicate that +/// something is taking longer than expected. +/// +/// The [SilentStatus] class never has any output. /// /// The [AnsiSpinner] subclass shows a spinner, and replaces it with a single /// space character when stopped or canceled. @@ -395,51 +440,159 @@ enum _LogType { error, status, trace } /// information when stopped. When canceled, the information isn't shown. In /// either case, a newline is printed. /// +/// The [SummaryStatus] subclass shows only a static message (without an +/// indicator), then updates it when the operation ends. +/// /// Generally, consider `logger.startProgress` instead of directly creating /// a [Status] or one of its subclasses. -class Status { - Status({this.onFinish}); +abstract class Status { + Status({ @required this.timeout, this.onFinish }); - /// A straight [Status] or an [AnsiSpinner] (depending on whether the + /// A [SilentStatus] or an [AnsiSpinner] (depending on whether the /// terminal is fancy enough), already started. - factory Status.withSpinner({ VoidCallback onFinish }) { + factory Status.withSpinner({ + @required Duration timeout, + VoidCallback onFinish, + SlowWarningCallback slowWarningCallback, + }) { if (terminal.supportsColor) - return AnsiSpinner(onFinish: onFinish)..start(); - return Status(onFinish: onFinish)..start(); + return AnsiSpinner(timeout: timeout, onFinish: onFinish, slowWarningCallback: slowWarningCallback)..start(); + return SilentStatus(timeout: timeout, onFinish: onFinish)..start(); } + final Duration timeout; final VoidCallback onFinish; - bool _isStarted = false; + @protected + final Stopwatch _stopwatch = Stopwatch(); + + @protected + bool get seemsSlow => timeout != null && _stopwatch.elapsed > timeout; + + @protected + String get elapsedTime { + if (timeout == null || timeout > kFastOperation) + return getElapsedAsSeconds(_stopwatch.elapsed); + return getElapsedAsMilliseconds(_stopwatch.elapsed); + } /// Call to start spinning. void start() { - assert(!_isStarted); - _isStarted = true; + assert(!_stopwatch.isRunning); + _stopwatch.start(); } /// Call to stop spinning after success. void stop() { - assert(_isStarted); - _isStarted = false; - if (onFinish != null) - onFinish(); + finish(); } /// Call to cancel the spinner after failure or cancellation. void cancel() { - assert(_isStarted); - _isStarted = false; + finish(); + } + + /// Call to clear the current line but not end the progress. + void pause() { } + + /// Call to resume after a pause. + void resume() { } + + @protected + void finish() { + assert(_stopwatch.isRunning); + _stopwatch.stop(); if (onFinish != null) onFinish(); } } +/// A [SilentStatus] shows nothing. +class SilentStatus extends Status { + SilentStatus({ + @required Duration timeout, + VoidCallback onFinish, + }) : super(timeout: timeout, onFinish: onFinish); +} + +/// Constructor writes [message] to [stdout]. On [cancel] or [stop], will call +/// [onFinish]. On [stop], will additionally print out summary information. +class SummaryStatus extends Status { + SummaryStatus({ + this.message = '', + @required Duration timeout, + this.padding = kDefaultStatusPadding, + VoidCallback onFinish, + }) : assert(message != null), + assert(padding != null), + super(timeout: timeout, onFinish: onFinish); + + final String message; + final int padding; + + bool _messageShowingOnCurrentLine = false; + + @override + void start() { + _printMessage(); + super.start(); + } + + void _printMessage() { + assert(!_messageShowingOnCurrentLine); + stdout.write('${message.padRight(padding)} '); + _messageShowingOnCurrentLine = true; + } + + @override + void stop() { + if (!_messageShowingOnCurrentLine) + _printMessage(); + super.stop(); + writeSummaryInformation(); + stdout.write('\n'); + } + + @override + void cancel() { + super.cancel(); + if (_messageShowingOnCurrentLine) + stdout.write('\n'); + } + + /// Prints a (minimum) 8 character padded time. + /// + /// If [timeout] is less than or equal to [kFastOperation], the time is in + /// seconds; otherwise, milliseconds. If the time is longer than [timeout], + /// appends "(!)" to the time. + /// + /// Examples: ` 0.5s`, ` 150ms`, ` 1,600ms`, ` 3.1s (!)` + void writeSummaryInformation() { + assert(_messageShowingOnCurrentLine); + stdout.write(elapsedTime.padLeft(_kTimePadding)); + if (seemsSlow) + stdout.write(' (!)'); + } + + @override + void pause() { + super.pause(); + stdout.write('\n'); + _messageShowingOnCurrentLine = false; + } +} + /// An [AnsiSpinner] is a simple animation that does nothing but implement a -/// ASCII/Unicode spinner. When stopped or canceled, the animation erases -/// itself. +/// terminal spinner. When stopped or canceled, the animation erases itself. +/// +/// If the timeout expires, a customizable warning is shown (but the spinner +/// continues otherwise unabated). class AnsiSpinner extends Status { - AnsiSpinner({VoidCallback onFinish}) : super(onFinish: onFinish); + AnsiSpinner({ + @required Duration timeout, + VoidCallback onFinish, + this.slowWarningCallback, + }) : super(timeout: timeout, onFinish: onFinish); int ticks = 0; Timer timer; @@ -449,73 +602,123 @@ class AnsiSpinner extends Status { ? [r'-', r'\', r'|', r'/'] : ['⣾', '⣽', '⣻', '⢿', '⡿', '⣟', '⣯', '⣷']; - String get _backspace => '\b' * _animation[0].length; - String get _clear => ' ' * _animation[0].length; + static const String _defaultSlowWarning = '(This is taking an unexpectedly long time.)'; + final SlowWarningCallback slowWarningCallback; - void _callback(Timer timer) { - stdout.write('$_backspace${_animation[ticks++ % _animation.length]}'); - } + String _slowWarning = ''; + + String get _currentAnimationFrame => _animation[ticks % _animation.length]; + int get _currentLength => _currentAnimationFrame.length + _slowWarning.length; + String get _backspace => '\b' * _currentLength; + String get _clear => ' ' * _currentLength; + + @protected + int get spinnerIndent => 0; @override void start() { super.start(); assert(timer == null); - stdout.write(' '); + _startSpinner(); + } + + void _startSpinner() { + stdout.write(_clear * (spinnerIndent + 1)); // for _callback to backspace over timer = Timer.periodic(const Duration(milliseconds: 100), _callback); _callback(timer); } - @override - void stop() { + void _callback(Timer timer) { + assert(this.timer == timer); + assert(timer != null); assert(timer.isActive); - timer.cancel(); - stdout.write('$_backspace$_clear$_backspace'); - super.stop(); + stdout.write('${_backspace * (spinnerIndent + 1)}'); + ticks += 1; + stdout.write('${_clear * spinnerIndent}$_currentAnimationFrame'); + if (seemsSlow) { + if (slowWarningCallback != null) { + _slowWarning = ' ' + slowWarningCallback(); + } else { + _slowWarning = ' ' + _defaultSlowWarning; + } + stdout.write(_slowWarning); + } } @override - void cancel() { + void finish() { + assert(timer != null); assert(timer.isActive); timer.cancel(); - stdout.write('$_backspace$_clear$_backspace'); - super.cancel(); + timer = null; + _clearSpinner(); + super.finish(); + } + + void _clearSpinner() { + final int width = spinnerIndent + 1; + stdout.write('${_backspace * width}${_clear * width}${_backspace * width}'); + } + + @override + void pause() { + assert(timer != null); + assert(timer.isActive); + _clearSpinner(); + timer.cancel(); + } + + @override + void resume() { + assert(timer != null); + assert(!timer.isActive); + _startSpinner(); } } -/// Constructor writes [message] to [stdout] with padding, then starts as an -/// [AnsiSpinner]. On [cancel] or [stop], will call [onFinish]. -/// On [stop], will additionally print out summary information in -/// milliseconds if [expectSlowOperation] is false, as seconds otherwise. +const int _kTimePadding = 8; // should fit "99,999ms" + +/// Constructor writes [message] to [stdout] with padding, then starts an +/// indeterminate progress indicator animation (it's a subclass of +/// [AnsiSpinner]). +/// +/// On [cancel] or [stop], will call [onFinish]. On [stop], will +/// additionally print out summary information. class AnsiStatus extends AnsiSpinner { AnsiStatus({ - String message, - bool expectSlowOperation, - bool multilineOutput, - int padding, + this.message = '', + @required Duration timeout, + this.multilineOutput = false, + this.padding = kDefaultStatusPadding, VoidCallback onFinish, - }) : message = message ?? '', - padding = padding ?? 0, - expectSlowOperation = expectSlowOperation ?? false, - multilineOutput = multilineOutput ?? false, - super(onFinish: onFinish); + }) : assert(message != null), + assert(multilineOutput != null), + assert(padding != null), + super(timeout: timeout, onFinish: onFinish); final String message; - final bool expectSlowOperation; final bool multilineOutput; final int padding; - Stopwatch stopwatch; - static const String _margin = ' '; + @override + int get spinnerIndent => _kTimePadding - 1; + + int _totalMessageLength; + @override void start() { - assert(stopwatch == null || !stopwatch.isRunning); - stopwatch = Stopwatch()..start(); - stdout.write('${message.padRight(padding)}$_margin'); + _startStatus(); super.start(); } + void _startStatus() { + final String line = '${message.padRight(padding)}$_margin'; + _totalMessageLength = line.length; + stdout.write(line); + } + @override void stop() { super.stop(); @@ -531,74 +734,31 @@ class AnsiStatus extends AnsiSpinner { /// Print summary information when a task is done. /// - /// If [multilineOutput] is false, backs up 4 characters and prints a - /// (minimum) 5 character padded time. If [expectSlowOperation] is true, the - /// time is in seconds; otherwise, milliseconds. Only backs up 4 characters - /// because [super.cancel] backs up one. + /// If [multilineOutput] is false, replaces the spinner with the summary message. /// /// If [multilineOutput] is true, then it prints the message again on a new - /// line before writing the elapsed time, and doesn't back up at all. + /// line before writing the elapsed time. void writeSummaryInformation() { - final String prefix = multilineOutput - ? '\n${'$message Done'.padRight(padding - 4)}$_margin' - : '\b\b\b\b'; - if (expectSlowOperation) { - stdout.write('$prefix${getElapsedAsSeconds(stopwatch.elapsed).padLeft(5)}'); - } else { - stdout.write('$prefix${getElapsedAsMilliseconds(stopwatch.elapsed).padLeft(5)}'); - } - } -} - -/// Constructor writes [message] to [stdout]. On [cancel] or [stop], will call -/// [onFinish]. On [stop], will additionally print out summary information in -/// milliseconds if [expectSlowOperation] is false, as seconds otherwise. -class SummaryStatus extends Status { - SummaryStatus({ - String message, - bool expectSlowOperation, - int padding, - VoidCallback onFinish, - }) : message = message ?? '', - padding = padding ?? 0, - expectSlowOperation = expectSlowOperation ?? false, - super(onFinish: onFinish); - - final String message; - final bool expectSlowOperation; - final int padding; - - Stopwatch stopwatch; - - @override - void start() { - stopwatch = Stopwatch()..start(); - stdout.write('${message.padRight(padding)} '); - super.start(); - } - - @override - void stop() { - super.stop(); - writeSummaryInformation(); - stdout.write('\n'); - } - - @override - void cancel() { - super.cancel(); - stdout.write('\n'); - } - - /// Prints a (minimum) 5 character padded time. If [expectSlowOperation] is - /// true, the time is in seconds; otherwise, milliseconds. - /// - /// Example: ' 0.5s', '150ms', '1600ms' - void writeSummaryInformation() { - if (expectSlowOperation) { - stdout.write(getElapsedAsSeconds(stopwatch.elapsed).padLeft(5)); - } else { - stdout.write(getElapsedAsMilliseconds(stopwatch.elapsed).padLeft(5)); - } + if (multilineOutput) + stdout.write('\n${'$message Done'.padRight(padding)}$_margin'); + stdout.write(elapsedTime.padLeft(_kTimePadding)); + if (seemsSlow) + stdout.write(' (!)'); + } + + void _clearStatus() { + stdout.write('${_backspace * _totalMessageLength}${_clear * _totalMessageLength}${_backspace * _totalMessageLength}'); + } + + @override + void pause() { + super.pause(); + _clearStatus(); + } + + @override + void resume() { + _startStatus(); + super.resume(); } } diff --git a/packages/flutter_tools/lib/src/base/net.dart b/packages/flutter_tools/lib/src/base/net.dart index 57ec0650aeb..5196fc796a9 100644 --- a/packages/flutter_tools/lib/src/base/net.dart +++ b/packages/flutter_tools/lib/src/base/net.dart @@ -37,7 +37,7 @@ Future> _attempt(Uri url, {bool onlyHeaders = false}) async { printTrace('Downloading: $url'); HttpClient httpClient; if (context[HttpClientFactory] != null) { - httpClient = context[HttpClientFactory](); + httpClient = (context[HttpClientFactory] as HttpClientFactory)(); // ignore: avoid_as } else { httpClient = HttpClient(); } diff --git a/packages/flutter_tools/lib/src/base/process.dart b/packages/flutter_tools/lib/src/base/process.dart index 37ef5bfef97..e61b4c1040a 100644 --- a/packages/flutter_tools/lib/src/base/process.dart +++ b/packages/flutter_tools/lib/src/base/process.dart @@ -203,14 +203,6 @@ Future runInteractively(List command, { return await process.exitCode; } -Future runAndKill(List cmd, Duration timeout) { - final Future proc = runDetached(cmd); - return Future.delayed(timeout, () async { - printTrace('Intentionally killing ${cmd[0]}'); - processManager.killPid((await proc).pid); - }); -} - Future runDetached(List cmd) { _traceCommand(cmd); final Future proc = processManager.start( diff --git a/packages/flutter_tools/lib/src/base/terminal.dart b/packages/flutter_tools/lib/src/base/terminal.dart index 8ad874c924e..6f9d54268e0 100644 --- a/packages/flutter_tools/lib/src/base/terminal.dart +++ b/packages/flutter_tools/lib/src/base/terminal.dart @@ -5,8 +5,6 @@ import 'dart:async'; import 'dart:convert' show AsciiDecoder; -import 'package:quiver/strings.dart'; - import '../globals.dart'; import 'context.dart'; import 'io.dart' as io; @@ -172,31 +170,32 @@ class AnsiTerminal { /// Return keystrokes from the console. /// /// Useful when the console is in [singleCharMode]. - Stream get onCharInput { + Stream get keystrokes { _broadcastStdInString ??= io.stdin.transform(const AsciiDecoder(allowInvalid: true)).asBroadcastStream(); return _broadcastStdInString; } - /// Prompts the user to input a character within the accepted list. Re-prompts - /// if entered character is not in the list. + /// Prompts the user to input a character within a given list. Re-prompts if + /// entered character is not in the list. /// - /// The [prompt] is the text displayed prior to waiting for user input. The - /// [defaultChoiceIndex], if given, will be the character appearing in - /// [acceptedCharacters] in the index given if the user presses enter without - /// any key input. Setting [displayAcceptedCharacters] also prints the - /// accepted keys next to the [prompt]. + /// The `prompt`, if non-null, is the text displayed prior to waiting for user + /// input each time. If `prompt` is non-null and `displayAcceptedCharacters` + /// is true, the accepted keys are printed next to the `prompt`. /// - /// Throws a [TimeoutException] if a `timeout` is provided and its duration - /// expired without user input. Duration resets per key press. + /// The returned value is the user's input; if `defaultChoiceIndex` is not + /// null, and the user presses enter without any other input, the return value + /// will be the character in `acceptedCharacters` at the index given by + /// `defaultChoiceIndex`. Future promptForCharInput( List acceptedCharacters, { String prompt, int defaultChoiceIndex, bool displayAcceptedCharacters = true, - Duration timeout, }) async { assert(acceptedCharacters != null); assert(acceptedCharacters.isNotEmpty); + assert(prompt == null || prompt.isNotEmpty); + assert(displayAcceptedCharacters != null); List charactersToDisplay = acceptedCharacters; if (defaultChoiceIndex != null) { assert(defaultChoiceIndex >= 0 && defaultChoiceIndex < acceptedCharacters.length); @@ -206,17 +205,14 @@ class AnsiTerminal { } String choice; singleCharMode = true; - while (isEmpty(choice) || choice.length != 1 || !acceptedCharacters.contains(choice)) { - if (isNotEmpty(prompt)) { + while (choice == null || choice.length > 1 || !acceptedCharacters.contains(choice)) { + if (prompt != null) { printStatus(prompt, emphasis: true, newline: false); if (displayAcceptedCharacters) printStatus(' [${charactersToDisplay.join("|")}]', newline: false); printStatus(': ', emphasis: true, newline: false); } - Future inputFuture = onCharInput.first; - if (timeout != null) - inputFuture = inputFuture.timeout(timeout); - choice = await inputFuture; + choice = await keystrokes.first; printStatus(choice); } singleCharMode = false; diff --git a/packages/flutter_tools/lib/src/cache.dart b/packages/flutter_tools/lib/src/cache.dart index a8b0cb43f0c..dd1db595d12 100644 --- a/packages/flutter_tools/lib/src/cache.dart +++ b/packages/flutter_tools/lib/src/cache.dart @@ -299,7 +299,7 @@ abstract class CachedArtifact { Future _downloadArchive(String message, Uri url, Directory location, bool verifier(File f), void extractor(File f, Directory d)) { return _withDownloadFile('${flattenNameSubdirs(url)}', (File tempFile) async { if (!verifier(tempFile)) { - final Status status = logger.startProgress(message, expectSlowOperation: true); + final Status status = logger.startProgress(message, timeout: kSlowOperation); try { await _downloadFile(url, tempFile); status.stop(); @@ -648,7 +648,7 @@ Future _downloadFile(Uri url, File location) async { } Future _doesRemoteExist(String message, Uri url) async { - final Status status = logger.startProgress(message, expectSlowOperation: true); + final Status status = logger.startProgress(message, timeout: kSlowOperation); final bool exists = await doesRemoteFileExist(url); status.stop(); return exists; diff --git a/packages/flutter_tools/lib/src/commands/analyze_continuously.dart b/packages/flutter_tools/lib/src/commands/analyze_continuously.dart index dda2ab86167..1be67c68341 100644 --- a/packages/flutter_tools/lib/src/commands/analyze_continuously.dart +++ b/packages/flutter_tools/lib/src/commands/analyze_continuously.dart @@ -74,11 +74,12 @@ class AnalyzeContinuously extends AnalyzeBase { analysisStatus?.cancel(); if (!firstAnalysis) printStatus('\n'); - analysisStatus = logger.startProgress('Analyzing $analysisTarget...'); + analysisStatus = logger.startProgress('Analyzing $analysisTarget...', timeout: kSlowOperation); analyzedPaths.clear(); analysisTimer = Stopwatch()..start(); } else { analysisStatus?.stop(); + analysisStatus = null; analysisTimer.stop(); logger.printStatus(terminal.clearScreen(), newline: false); diff --git a/packages/flutter_tools/lib/src/commands/analyze_once.dart b/packages/flutter_tools/lib/src/commands/analyze_once.dart index 3a536e5eadf..e75d3790ef2 100644 --- a/packages/flutter_tools/lib/src/commands/analyze_once.dart +++ b/packages/flutter_tools/lib/src/commands/analyze_once.dart @@ -107,7 +107,7 @@ class AnalyzeOnce extends AnalyzeBase { ? '${directories.length} ${directories.length == 1 ? 'directory' : 'directories'}' : fs.path.basename(directories.first); final Status progress = argResults['preamble'] - ? logger.startProgress('Analyzing $message...') + ? logger.startProgress('Analyzing $message...', timeout: kSlowOperation) : null; await analysisCompleter.future; diff --git a/packages/flutter_tools/lib/src/commands/attach.dart b/packages/flutter_tools/lib/src/commands/attach.dart index 0cba1583819..732c0cd0f52 100644 --- a/packages/flutter_tools/lib/src/commands/attach.dart +++ b/packages/flutter_tools/lib/src/commands/attach.dart @@ -135,15 +135,14 @@ class AttachCommand extends FlutterCommand { if (device is FuchsiaDevice) { attachLogger = true; final String module = argResults['module']; - if (module == null) { - throwToolExit('\'--module\' is requried for attaching to a Fuchsia device'); - } + if (module == null) + throwToolExit('\'--module\' is required for attaching to a Fuchsia device'); usesIpv6 = device.ipv6; FuchsiaIsolateDiscoveryProtocol isolateDiscoveryProtocol; try { isolateDiscoveryProtocol = device.getIsolateDiscoveryProtocol(module); observatoryUri = await isolateDiscoveryProtocol.uri; - printStatus('Done.'); + printStatus('Done.'); // FYI, this message is used as a sentinel in tests. } catch (_) { isolateDiscoveryProtocol?.dispose(); final List ports = device.portForwarder.forwardedPorts.toList(); @@ -163,7 +162,7 @@ class AttachCommand extends FlutterCommand { observatoryUri = await observatoryDiscovery.uri; // Determine ipv6 status from the scanned logs. usesIpv6 = observatoryDiscovery.ipv6; - printStatus('Done.'); + printStatus('Done.'); // FYI, this message is used as a sentinel in tests. } finally { await observatoryDiscovery?.cancel(); } @@ -210,20 +209,30 @@ class AttachCommand extends FlutterCommand { if (attachLogger) { flutterDevice.startEchoingDeviceLog(); } + + int result; if (daemon != null) { AppInstance app; try { - app = await daemon.appDomain.launch(runner, runner.attach, - device, null, true, fs.currentDirectory); + app = await daemon.appDomain.launch( + runner, + runner.attach, + device, + null, + true, + fs.currentDirectory, + ); } catch (error) { throwToolExit(error.toString()); } - final int result = await app.runner.waitForAppToFinish(); - if (result != 0) - throwToolExit(null, exitCode: result); + result = await app.runner.waitForAppToFinish(); + assert(result != null); } else { - await runner.attach(); + result = await runner.attach(); + assert(result != null); } + if (result != 0) + throwToolExit(null, exitCode: result); } finally { final List ports = device.portForwarder.forwardedPorts.toList(); for (ForwardedPort port in ports) { diff --git a/packages/flutter_tools/lib/src/commands/build.dart b/packages/flutter_tools/lib/src/commands/build.dart index 11c21f33a35..c31f741718c 100644 --- a/packages/flutter_tools/lib/src/commands/build.dart +++ b/packages/flutter_tools/lib/src/commands/build.dart @@ -4,11 +4,6 @@ import 'dart:async'; -import 'package:meta/meta.dart'; - -import '../base/file_system.dart'; -import '../base/utils.dart'; -import '../globals.dart'; import '../runner/flutter_command.dart'; import 'build_aot.dart'; import 'build_apk.dart'; @@ -41,25 +36,4 @@ abstract class BuildSubCommand extends FlutterCommand { BuildSubCommand() { requiresPubspecYaml(); } - - @override - @mustCallSuper - Future runCommand() async { - if (isRunningOnBot) { - final File dotPackages = fs.file('.packages'); - printStatus('Contents of .packages:'); - if (dotPackages.existsSync()) - printStatus(dotPackages.readAsStringSync()); - else - printError('File not found: ${dotPackages.absolute.path}'); - - final File pubspecLock = fs.file('pubspec.lock'); - printStatus('Contents of pubspec.lock:'); - if (pubspecLock.existsSync()) - printStatus(pubspecLock.readAsStringSync()); - else - printError('File not found: ${pubspecLock.absolute.path}'); - } - return null; - } } diff --git a/packages/flutter_tools/lib/src/commands/build_aot.dart b/packages/flutter_tools/lib/src/commands/build_aot.dart index e7d40f7a53a..f541aae6908 100644 --- a/packages/flutter_tools/lib/src/commands/build_aot.dart +++ b/packages/flutter_tools/lib/src/commands/build_aot.dart @@ -57,8 +57,6 @@ class BuildAotCommand extends BuildSubCommand { @override Future runCommand() async { - await super.runCommand(); - final String targetPlatform = argResults['target-platform']; final TargetPlatform platform = getTargetPlatformForName(targetPlatform); if (platform == null) @@ -71,7 +69,7 @@ class BuildAotCommand extends BuildSubCommand { final String typeName = artifacts.getEngineType(platform, buildMode); status = logger.startProgress( 'Building AOT snapshot in ${getFriendlyModeName(getBuildMode())} mode ($typeName)...', - expectSlowOperation: true, + timeout: kSlowOperation, ); } final String outputPath = argResults['output-dir'] ?? getAotBuildDirectory(); diff --git a/packages/flutter_tools/lib/src/commands/build_apk.dart b/packages/flutter_tools/lib/src/commands/build_apk.dart index d76a421b552..2660932b2db 100644 --- a/packages/flutter_tools/lib/src/commands/build_apk.dart +++ b/packages/flutter_tools/lib/src/commands/build_apk.dart @@ -42,7 +42,6 @@ class BuildApkCommand extends BuildSubCommand { @override Future runCommand() async { - await super.runCommand(); await buildApk( project: await FlutterProject.current(), target: targetFile, diff --git a/packages/flutter_tools/lib/src/commands/build_appbundle.dart b/packages/flutter_tools/lib/src/commands/build_appbundle.dart index d9f22ca0086..bf8979a7c16 100644 --- a/packages/flutter_tools/lib/src/commands/build_appbundle.dart +++ b/packages/flutter_tools/lib/src/commands/build_appbundle.dart @@ -40,7 +40,6 @@ class BuildAppBundleCommand extends BuildSubCommand { @override Future runCommand() async { - await super.runCommand(); await buildAppBundle( project: await FlutterProject.current(), target: targetFile, diff --git a/packages/flutter_tools/lib/src/commands/build_bundle.dart b/packages/flutter_tools/lib/src/commands/build_bundle.dart index 4093787efc8..2fff12f07ff 100644 --- a/packages/flutter_tools/lib/src/commands/build_bundle.dart +++ b/packages/flutter_tools/lib/src/commands/build_bundle.dart @@ -65,8 +65,6 @@ class BuildBundleCommand extends BuildSubCommand { @override Future runCommand() async { - await super.runCommand(); - final String targetPlatform = argResults['target-platform']; final TargetPlatform platform = getTargetPlatformForName(targetPlatform); if (platform == null) diff --git a/packages/flutter_tools/lib/src/commands/build_flx.dart b/packages/flutter_tools/lib/src/commands/build_flx.dart index 33e6946753b..d6a22748533 100644 --- a/packages/flutter_tools/lib/src/commands/build_flx.dart +++ b/packages/flutter_tools/lib/src/commands/build_flx.dart @@ -20,12 +20,9 @@ class BuildFlxCommand extends BuildSubCommand { @override Future runCommand() async { - await super.runCommand(); - printError("'build flx' is no longer supported. Instead, use 'build " "bundle' to build and assemble the application code and resources " 'for your app.'); - return null; } } diff --git a/packages/flutter_tools/lib/src/commands/build_ios.dart b/packages/flutter_tools/lib/src/commands/build_ios.dart index 539eb76a32b..b90e3329758 100644 --- a/packages/flutter_tools/lib/src/commands/build_ios.dart +++ b/packages/flutter_tools/lib/src/commands/build_ios.dart @@ -53,7 +53,6 @@ class BuildIOSCommand extends BuildSubCommand { final bool forSimulator = argResults['simulator']; defaultBuildMode = forSimulator ? BuildMode.debug : BuildMode.release; - await super.runCommand(); if (getCurrentHostPlatform() != HostPlatform.darwin_x64) throwToolExit('Building for iOS is only supported on the Mac.'); diff --git a/packages/flutter_tools/lib/src/commands/daemon.dart b/packages/flutter_tools/lib/src/commands/daemon.dart index 55f331f16d4..2a2d9d56fc9 100644 --- a/packages/flutter_tools/lib/src/commands/daemon.dart +++ b/packages/flutter_tools/lib/src/commands/daemon.dart @@ -383,16 +383,22 @@ class AppDomain extends Domain { } return launch( - runner, - ({ Completer connectionInfoCompleter, - Completer appStartedCompleter }) => runner.run( - connectionInfoCompleter: connectionInfoCompleter, - appStartedCompleter: appStartedCompleter, - route: route), - device, - projectDirectory, - enableHotReload, - cwd); + runner, + ({ + Completer connectionInfoCompleter, + Completer appStartedCompleter, + }) { + return runner.run( + connectionInfoCompleter: connectionInfoCompleter, + appStartedCompleter: appStartedCompleter, + route: route, + ); + }, + device, + projectDirectory, + enableHotReload, + cwd, + ); } Future launch( @@ -428,17 +434,19 @@ class AppDomain extends Domain { }); } final Completer appStartedCompleter = Completer(); - // We don't want to wait for this future to complete and callbacks won't fail. - // As it just writes to stdout. - appStartedCompleter.future.then((_) { // ignore: unawaited_futures - _sendAppEvent(app, 'started'); - }); + // We don't want to wait for this future to complete, and callbacks won't fail, + // as it just writes to stdout. + appStartedCompleter.future // ignore: unawaited_futures + .then((void value) { + _sendAppEvent(app, 'started'); + }); await app._runInZone(this, () async { try { await runOrAttach( - connectionInfoCompleter: connectionInfoCompleter, - appStartedCompleter: appStartedCompleter); + connectionInfoCompleter: connectionInfoCompleter, + appStartedCompleter: appStartedCompleter, + ); _sendAppEvent(app, 'stop'); } catch (error, trace) { _sendAppEvent(app, 'stop', { @@ -515,14 +523,15 @@ class AppDomain extends Domain { if (app == null) throw "app '$appId' not found"; - return app.stop().timeout(const Duration(seconds: 5)).then((_) { - return true; - }).catchError((dynamic error) { - _sendAppEvent(app, 'log', { 'log': '$error', 'error': true }); - app.closeLogger(); - _apps.remove(app); - return false; - }); + return app.stop().then( + (void value) => true, + onError: (dynamic error, StackTrace stack) { + _sendAppEvent(app, 'log', { 'log': '$error', 'error': true }); + app.closeLogger(); + _apps.remove(app); + return false; + }, + ); } Future detach(Map args) async { @@ -532,14 +541,15 @@ class AppDomain extends Domain { if (app == null) throw "app '$appId' not found"; - return app.detach().timeout(const Duration(seconds: 5)).then((_) { - return true; - }).catchError((dynamic error) { - _sendAppEvent(app, 'log', { 'log': '$error', 'error': true }); - app.closeLogger(); - _apps.remove(app); - return false; - }); + return app.detach().then( + (void value) => true, + onError: (dynamic error, StackTrace stack) { + _sendAppEvent(app, 'log', { 'log': '$error', 'error': true }); + app.closeLogger(); + _apps.remove(app); + return false; + }, + ); } AppInstance _getApp(String id) { @@ -772,13 +782,14 @@ class NotifyingLogger extends Logger { @override Status startProgress( String message, { + @required Duration timeout, String progressId, - bool expectSlowOperation = false, bool multilineOutput, int progressIndicatorPadding = kDefaultStatusPadding, }) { + assert(timeout != null); printStatus(message); - return Status(); + return SilentStatus(timeout: timeout); } void dispose() { @@ -948,11 +959,12 @@ class _AppRunLogger extends Logger { @override Status startProgress( String message, { + @required Duration timeout, String progressId, - bool expectSlowOperation = false, bool multilineOutput, int progressIndicatorPadding = 52, }) { + assert(timeout != null); final int id = _nextProgressId++; _sendProgressEvent({ @@ -961,13 +973,16 @@ class _AppRunLogger extends Logger { 'message': message, }); - _status = Status(onFinish: () { - _status = null; - _sendProgressEvent({ - 'id': id.toString(), - 'progressId': progressId, - 'finished': true - }); + _status = SilentStatus( + timeout: timeout, + onFinish: () { + _status = null; + _sendProgressEvent({ + 'id': id.toString(), + 'progressId': progressId, + 'finished': true, + }, + ); })..start(); return _status; } diff --git a/packages/flutter_tools/lib/src/commands/logs.dart b/packages/flutter_tools/lib/src/commands/logs.dart index 77759f696b0..e3d3c2bbb01 100644 --- a/packages/flutter_tools/lib/src/commands/logs.dart +++ b/packages/flutter_tools/lib/src/commands/logs.dart @@ -29,11 +29,11 @@ class LogsCommand extends FlutterCommand { Device device; @override - Future verifyThenRunCommand() async { + Future verifyThenRunCommand(String commandPath) async { device = await findTargetDevice(); if (device == null) throwToolExit(null); - return super.verifyThenRunCommand(); + return super.verifyThenRunCommand(commandPath); } @override diff --git a/packages/flutter_tools/lib/src/commands/run.dart b/packages/flutter_tools/lib/src/commands/run.dart index 3ae3b2d6301..16b764e4151 100644 --- a/packages/flutter_tools/lib/src/commands/run.dart +++ b/packages/flutter_tools/lib/src/commands/run.dart @@ -17,9 +17,9 @@ import '../resident_runner.dart'; import '../run_cold.dart'; import '../run_hot.dart'; import '../runner/flutter_command.dart'; +import '../tracing.dart'; import 'daemon.dart'; -// TODO(mklim): Test this, flutter/flutter#23031. abstract class RunCommandBase extends FlutterCommand { // Used by run and drive commands. RunCommandBase({ bool verboseHelp = false }) { @@ -30,7 +30,7 @@ abstract class RunCommandBase extends FlutterCommand { argParser ..addFlag('trace-startup', negatable: false, - help: 'Start tracing during startup.', + help: 'Trace application startup, then exit, saving the trace to a file.', ) ..addOption('route', help: 'Which route to load when running the app.', @@ -90,6 +90,14 @@ class RunCommand extends RunCommandBase { help: 'Enable tracing of Skia code. This is useful when debugging ' 'the GPU thread. By default, Flutter will not log skia code.', ) + ..addFlag('await-first-frame-when-tracing', + defaultsTo: true, + help: 'Whether to wait for the first frame when tracing startup ("--trace-startup"), ' + 'or just dump the trace as soon as the application is running. The first frame ' + 'is detected by looking for a Timeline event with the name ' + '"${Tracing.firstUsefulFrameEventName}". ' + 'By default, the widgets library\'s binding takes care of sending this event. ', + ) ..addFlag('use-test-fonts', negatable: true, help: 'Enable (and default to) the "Ahem" font. This is a special font ' @@ -108,7 +116,7 @@ class RunCommand extends RunCommandBase { ) ..addFlag('track-widget-creation', hide: !verboseHelp, - help: 'Track widget creation locations. Requires Dart 2.0 functionality.', + help: 'Track widget creation locations.', ) ..addOption('project-root', hide: !verboseHelp, @@ -123,18 +131,18 @@ class RunCommand extends RunCommandBase { ..addFlag('hot', negatable: true, defaultsTo: kHotReloadDefault, - help: 'Run with support for hot reloading.', - ) - ..addOption('pid-file', - help: 'Specify a file to write the process id to. ' - 'You can send SIGUSR1 to trigger a hot reload ' - 'and SIGUSR2 to trigger a hot restart.', + help: 'Run with support for hot reloading. Only available for debug mode. Not available with "--trace-startup".', ) ..addFlag('resident', negatable: true, defaultsTo: true, hide: !verboseHelp, - help: 'Stay resident after launching the application.', + help: 'Stay resident after launching the application. Not available with "--trace-startup".', + ) + ..addOption('pid-file', + help: 'Specify a file to write the process id to. ' + 'You can send SIGUSR1 to trigger a hot reload ' + 'and SIGUSR2 to trigger a hot restart.', ) ..addFlag('benchmark', negatable: false, @@ -206,7 +214,7 @@ class RunCommand extends RunCommandBase { bool shouldUseHotMode() { final bool hotArg = argResults['hot'] ?? false; - final bool shouldUseHotMode = hotArg; + final bool shouldUseHotMode = hotArg && !traceStartup; return getBuildInfo().isDebug && shouldUseHotMode; } @@ -214,6 +222,7 @@ class RunCommand extends RunCommandBase { argResults['use-application-binary'] != null; bool get stayResident => argResults['resident']; + bool get awaitFirstFrameWhenTracing => argResults['await-first-frame-when-tracing']; @override Future validateCommand() async { @@ -359,6 +368,7 @@ class RunCommand extends RunCommandBase { target: targetFile, debuggingOptions: _createDebuggingOptions(), traceStartup: traceStartup, + awaitFirstFrameWhenTracing: awaitFirstFrameWhenTracing, applicationBinary: applicationBinaryPath == null ? null : fs.file(applicationBinaryPath), diff --git a/packages/flutter_tools/lib/src/commands/screenshot.dart b/packages/flutter_tools/lib/src/commands/screenshot.dart index c2dc3d1e9ea..20a2d1f2a33 100644 --- a/packages/flutter_tools/lib/src/commands/screenshot.dart +++ b/packages/flutter_tools/lib/src/commands/screenshot.dart @@ -64,7 +64,7 @@ class ScreenshotCommand extends FlutterCommand { Device device; @override - Future verifyThenRunCommand() async { + Future verifyThenRunCommand(String commandPath) async { device = await findTargetDevice(); if (device == null) throwToolExit('Must have a connected device'); @@ -72,7 +72,7 @@ class ScreenshotCommand extends FlutterCommand { throwToolExit('Screenshot not supported for ${device.name}.'); if (argResults[_kType] != _kDeviceType && argResults[_kObservatoryPort] == null) throwToolExit('Observatory port must be specified for screenshot type ${argResults[_kType]}'); - return super.verifyThenRunCommand(); + return super.verifyThenRunCommand(commandPath); } @override diff --git a/packages/flutter_tools/lib/src/commands/update_packages.dart b/packages/flutter_tools/lib/src/commands/update_packages.dart index 73b62de99d3..b084fb43aad 100644 --- a/packages/flutter_tools/lib/src/commands/update_packages.dart +++ b/packages/flutter_tools/lib/src/commands/update_packages.dart @@ -87,7 +87,7 @@ class UpdatePackagesCommand extends FlutterCommand { Future _downloadCoverageData() async { final Status status = logger.startProgress( 'Downloading lcov data for package:flutter...', - expectSlowOperation: true, + timeout: kSlowOperation, ); final String urlBase = platform.environment['FLUTTER_STORAGE_BASE_URL'] ?? 'https://storage.googleapis.com'; final List data = await fetchUrl(Uri.parse('$urlBase/flutter_infra/flutter/coverage/lcov.info')); diff --git a/packages/flutter_tools/lib/src/dart/pub.dart b/packages/flutter_tools/lib/src/dart/pub.dart index 062bc122d9d..ce61edace4f 100644 --- a/packages/flutter_tools/lib/src/dart/pub.dart +++ b/packages/flutter_tools/lib/src/dart/pub.dart @@ -92,7 +92,7 @@ Future pubGet({ final String command = upgrade ? 'upgrade' : 'get'; final Status status = logger.startProgress( 'Running "flutter packages $command" in ${fs.path.basename(directory)}...', - expectSlowOperation: true, + timeout: kSlowOperation, ); final List args = ['--verbosity=warning']; if (FlutterCommand.current != null && FlutterCommand.current.globalResults['verbose']) diff --git a/packages/flutter_tools/lib/src/device.dart b/packages/flutter_tools/lib/src/device.dart index f6418b2c265..94030fe410f 100644 --- a/packages/flutter_tools/lib/src/device.dart +++ b/packages/flutter_tools/lib/src/device.dart @@ -156,7 +156,7 @@ abstract class PollingDeviceDiscovery extends DeviceDiscovery { final List devices = await pollingGetDevices().timeout(_pollingTimeout); _items.updateWithNewList(devices); } on TimeoutException { - printTrace('Device poll timed out.'); + printTrace('Device poll timed out. Will retry.'); } }, _pollingInterval); } diff --git a/packages/flutter_tools/lib/src/doctor.dart b/packages/flutter_tools/lib/src/doctor.dart index 090e9e66cea..a790c832be0 100644 --- a/packages/flutter_tools/lib/src/doctor.dart +++ b/packages/flutter_tools/lib/src/doctor.dart @@ -188,7 +188,10 @@ class Doctor { for (ValidatorTask validatorTask in startValidatorTasks()) { final DoctorValidator validator = validatorTask.validator; - final Status status = Status.withSpinner(); + final Status status = Status.withSpinner( + timeout: kFastOperation, + slowWarningCallback: () => validator.slowWarning, + ); ValidationResult result; try { result = await validatorTask.result; @@ -290,6 +293,8 @@ abstract class DoctorValidator { final String title; + String get slowWarning => 'This is taking an unexpectedly long time...'; + Future validate(); } @@ -302,6 +307,10 @@ class GroupedValidator extends DoctorValidator { final List subValidators; + @override + String get slowWarning => _currentSlowWarning; + String _currentSlowWarning = 'Initializing...'; + @override Future validate() async { final List tasks = []; @@ -311,8 +320,10 @@ class GroupedValidator extends DoctorValidator { final List results = []; for (ValidatorTask subValidator in tasks) { + _currentSlowWarning = subValidator.validator.slowWarning; results.add(await subValidator.result); } + _currentSlowWarning = 'Merging results...'; return _mergeValidationResults(results); } @@ -675,6 +686,9 @@ class IntelliJValidatorOnMac extends IntelliJValidator { class DeviceValidator extends DoctorValidator { DeviceValidator() : super('Connected device'); + @override + String get slowWarning => 'Scanning for devices is taking a long time...'; + @override Future validate() async { final List devices = await deviceManager.getAllConnectedDevices().toList(); diff --git a/packages/flutter_tools/lib/src/fuchsia/fuchsia_device.dart b/packages/flutter_tools/lib/src/fuchsia/fuchsia_device.dart index eb508e036bc..84bc1bab3ff 100644 --- a/packages/flutter_tools/lib/src/fuchsia/fuchsia_device.dart +++ b/packages/flutter_tools/lib/src/fuchsia/fuchsia_device.dart @@ -325,7 +325,7 @@ class FuchsiaIsolateDiscoveryProtocol { } _status ??= logger.startProgress( 'Waiting for a connection from $_isolateName on ${_device.name}...', - expectSlowOperation: true, + timeout: null, // could take an arbitrary amount of time ); _pollingTimer ??= Timer(_pollDuration, _findIsolate); return _foundUri.future.then((Uri uri) { diff --git a/packages/flutter_tools/lib/src/ios/cocoapods.dart b/packages/flutter_tools/lib/src/ios/cocoapods.dart index ce1cbbe0b21..92b7a3e4bd9 100644 --- a/packages/flutter_tools/lib/src/ios/cocoapods.dart +++ b/packages/flutter_tools/lib/src/ios/cocoapods.dart @@ -237,7 +237,7 @@ class CocoaPods { } Future _runPodInstall(IosProject iosProject, String engineDirectory) async { - final Status status = logger.startProgress('Running pod install...', expectSlowOperation: true); + final Status status = logger.startProgress('Running pod install...', timeout: kSlowOperation); final ProcessResult result = await processManager.run( ['pod', 'install', '--verbose'], workingDirectory: iosProject.hostAppRoot.path, diff --git a/packages/flutter_tools/lib/src/ios/devices.dart b/packages/flutter_tools/lib/src/ios/devices.dart index c55cb85337a..aa8317e9358 100644 --- a/packages/flutter_tools/lib/src/ios/devices.dart +++ b/packages/flutter_tools/lib/src/ios/devices.dart @@ -26,8 +26,6 @@ const String _kIdeviceinstallerInstructions = 'To work with iOS devices, please install ideviceinstaller. To install, run:\n' 'brew install ideviceinstaller.'; -const Duration kPortForwardTimeout = Duration(seconds: 10); - class IOSDeploy { const IOSDeploy(); @@ -297,7 +295,7 @@ class IOSDevice extends Device { int installationResult = -1; Uri localObservatoryUri; - final Status installStatus = logger.startProgress('Installing and launching...', expectSlowOperation: true); + final Status installStatus = logger.startProgress('Installing and launching...', timeout: kSlowOperation); if (!debuggingOptions.debuggingEnabled) { // If debugging is not enabled, just launch the application and continue. diff --git a/packages/flutter_tools/lib/src/ios/mac.dart b/packages/flutter_tools/lib/src/ios/mac.dart index 845a6961fcf..f7d32676b3c 100644 --- a/packages/flutter_tools/lib/src/ios/mac.dart +++ b/packages/flutter_tools/lib/src/ios/mac.dart @@ -470,7 +470,7 @@ Future buildXcodeProject({ initialBuildStatus.cancel(); buildSubStatus = logger.startProgress( line, - expectSlowOperation: true, + timeout: kSlowOperation, progressIndicatorPadding: kDefaultStatusPadding - 7, ); } @@ -485,7 +485,7 @@ Future buildXcodeProject({ } final Stopwatch buildStopwatch = Stopwatch()..start(); - initialBuildStatus = logger.startProgress('Starting Xcode build...'); + initialBuildStatus = logger.startProgress('Starting Xcode build...', timeout: kFastOperation); final RunResult buildResult = await runAsync( buildCommands, workingDirectory: app.project.hostAppRoot.path, diff --git a/packages/flutter_tools/lib/src/resident_runner.dart b/packages/flutter_tools/lib/src/resident_runner.dart index 6cc1db335c4..eecb0571737 100644 --- a/packages/flutter_tools/lib/src/resident_runner.dart +++ b/packages/flutter_tools/lib/src/resident_runner.dart @@ -9,7 +9,6 @@ import 'package:meta/meta.dart'; import 'application_package.dart'; import 'artifacts.dart'; import 'asset.dart'; -import 'base/common.dart'; import 'base/file_system.dart'; import 'base/io.dart'; import 'base/logger.dart'; @@ -76,12 +75,14 @@ class FlutterDevice { if (vmServices != null) return; final List localVmServices = List(observatoryUris.length); - for (int i = 0; i < observatoryUris.length; i++) { + for (int i = 0; i < observatoryUris.length; i += 1) { printTrace('Connecting to service protocol: ${observatoryUris[i]}'); - localVmServices[i] = await VMService.connect(observatoryUris[i], - reloadSources: reloadSources, - restart: restart, - compileExpression: compileExpression); + localVmServices[i] = await VMService.connect( + observatoryUris[i], + reloadSources: reloadSources, + restart: restart, + compileExpression: compileExpression, + ); printTrace('Successfully connected to service protocol: ${observatoryUris[i]}'); } vmServices = localVmServices; @@ -102,9 +103,13 @@ class FlutterDevice { return vmServices .where((VMService service) => !service.isClosed) - .expand((VMService service) => viewFilter != null - ? service.vm.allViewsWithName(viewFilter) - : service.vm.views) + .expand( + (VMService service) { + return viewFilter != null + ? service.vm.allViewsWithName(viewFilter) + : service.vm.views; + }, + ) .toList(); } @@ -120,13 +125,16 @@ class FlutterDevice { final List flutterViews = views; if (flutterViews == null || flutterViews.isEmpty) return; + final List> futures = >[]; for (FlutterView view in flutterViews) { if (view != null && view.uiIsolate != null) { - // Manage waits specifically below. - view.uiIsolate.flutterExit(); // ignore: unawaited_futures + futures.add(view.uiIsolate.flutterExit()); } } - await Future.delayed(const Duration(milliseconds: 100)); + // The flutterExit message only returns if it fails, so just wait a few + // seconds then assume it worked. + // TODO(ianh): We should make this return once the VM service disconnects. + await Future.wait(futures).timeout(const Duration(seconds: 2), onTimeout: () { }); } Future setupDevFS(String fsName, @@ -390,7 +398,7 @@ class FlutterDevice { }) async { final Status devFSStatus = logger.startProgress( 'Syncing files to device ${device.name}...', - expectSlowOperation: true, + timeout: kFastOperation, ); UpdateFSReport report; try { @@ -482,11 +490,14 @@ abstract class ResidentRunner { } /// Start the app and keep the process running during its lifetime. + /// + /// Returns the exit code that we should use for the flutter tool process; 0 + /// for success, 1 for user error (e.g. bad arguments), 2 for other failures. Future run({ Completer connectionInfoCompleter, Completer appStartedCompleter, String route, - bool shouldBuild = true + bool shouldBuild = true, }); Future attach({ @@ -506,7 +517,7 @@ abstract class ResidentRunner { await _debugSaveCompilationTrace(); await stopEchoingDeviceLog(); await preStop(); - return stopApp(); + await stopApp(); } Future detach() async { @@ -571,7 +582,7 @@ abstract class ResidentRunner { } Future _screenshot(FlutterDevice device) async { - final Status status = logger.startProgress('Taking screenshot for ${device.device.name}...'); + final Status status = logger.startProgress('Taking screenshot for ${device.device.name}...', timeout: kFastOperation); final File outputFile = getUniqueFile(fs.currentDirectory, 'flutter', 'png'); try { if (supportsServiceProtocol && isRunningDebug) { @@ -686,14 +697,18 @@ abstract class ResidentRunner { } /// If the [reloadSources] parameter is not null the 'reloadSources' service - /// will be registered + /// will be registered. + // + // Failures should be indicated by completing the future with an error, using + // a string as the error object, which will be used by the caller (attach()) + // to display an error message. Future connectToServiceProtocol({ ReloadSources reloadSources, Restart restart, CompileExpression compileExpression, }) async { if (!debuggingOptions.debuggingEnabled) - return Future.error('Error the service protocol is not enabled.'); + throw 'The service protocol is not enabled.'; bool viewFound = false; for (FlutterDevice device in flutterDevices) { @@ -704,13 +719,15 @@ abstract class ResidentRunner { ); await device.getVMs(); await device.refreshViews(); - if (device.views.isEmpty) - printStatus('No Flutter views available on ${device.device.name}'); - else + if (device.views.isNotEmpty) viewFound = true; } - if (!viewFound) - throwToolExit('No Flutter view is available'); + if (!viewFound) { + if (flutterDevices.length == 1) + throw 'No Flutter view is available on ${flutterDevices.first.device.name}.'; + throw 'No Flutter view is available on any device ' + '(${flutterDevices.map((FlutterDevice device) => device.device.name).join(', ')}).'; + } // Listen for service protocol connection to close. for (FlutterDevice device in flutterDevices) { @@ -861,12 +878,13 @@ abstract class ResidentRunner { printHelp(details: false); } terminal.singleCharMode = true; - terminal.onCharInput.listen(processTerminalInput); + terminal.keystrokes.listen(processTerminalInput); } } Future waitForAppToFinish() async { final int exitCode = await _finished.future; + assert(exitCode != null); await cleanupAtFinish(); return exitCode; } @@ -887,8 +905,10 @@ abstract class ResidentRunner { Future preStop() async { } Future stopApp() async { + final List> futures = >[]; for (FlutterDevice device in flutterDevices) - await device.stopApps(); + futures.add(device.stopApps()); + await Future.wait(futures); appFinished(); } diff --git a/packages/flutter_tools/lib/src/run_cold.dart b/packages/flutter_tools/lib/src/run_cold.dart index 7fc18dba4c0..87b6213266c 100644 --- a/packages/flutter_tools/lib/src/run_cold.dart +++ b/packages/flutter_tools/lib/src/run_cold.dart @@ -21,6 +21,7 @@ class ColdRunner extends ResidentRunner { DebuggingOptions debuggingOptions, bool usesTerminalUI = true, this.traceStartup = false, + this.awaitFirstFrameWhenTracing = true, this.applicationBinary, bool saveCompilationTrace = false, bool stayResident = true, @@ -34,6 +35,7 @@ class ColdRunner extends ResidentRunner { ipv6: ipv6); final bool traceStartup; + final bool awaitFirstFrameWhenTracing; final File applicationBinary; bool _didAttach = false; @@ -66,8 +68,14 @@ class ColdRunner extends ResidentRunner { } // Connect to observatory. - if (debuggingOptions.debuggingEnabled) - await connectToServiceProtocol(); + if (debuggingOptions.debuggingEnabled) { + try { + await connectToServiceProtocol(); + } on String catch (message) { + printError(message); + return 2; + } + } if (flutterDevices.first.observatoryUris != null) { // For now, only support one debugger connection. @@ -91,13 +99,11 @@ class ColdRunner extends ResidentRunner { // Only trace startup for the first device. final FlutterDevice device = flutterDevices.first; if (device.vmServices != null && device.vmServices.isNotEmpty) { - printStatus('Downloading startup trace info for ${device.device.name}'); - try { - await downloadStartupTrace(device.vmServices.first); - } catch (error) { - printError('Error downloading startup trace: $error'); - return 2; - } + printStatus('Tracing startup on ${device.device.name}.'); + await downloadStartupTrace( + device.vmServices.first, + awaitFirstFrame: awaitFirstFrameWhenTracing, + ); } appFinished(); } else if (stayResident) { @@ -107,7 +113,7 @@ class ColdRunner extends ResidentRunner { appStartedCompleter?.complete(); - if (stayResident) + if (stayResident && !traceStartup) return waitForAppToFinish(); await cleanupAtFinish(); return 0; diff --git a/packages/flutter_tools/lib/src/run_hot.dart b/packages/flutter_tools/lib/src/run_hot.dart index 103790de61d..c5f10395977 100644 --- a/packages/flutter_tools/lib/src/run_hot.dart +++ b/packages/flutter_tools/lib/src/run_hot.dart @@ -176,6 +176,7 @@ class HotRunner extends ResidentRunner { throw 'Failed to compile $expression'; } + // Returns the exit code of the flutter tool process, like [run]. @override Future attach({ Completer connectionInfoCompleter, @@ -260,10 +261,11 @@ class HotRunner extends ResidentRunner { return 0; } + int result = 0; if (stayResident) - return waitForAppToFinish(); + result = await waitForAppToFinish(); await cleanupAtFinish(); - return 0; + return result; } @override @@ -409,22 +411,21 @@ class HotRunner extends ResidentRunner { device.devFS.assetPathsToEvict.clear(); } - Future _cleanupDevFS() { + Future _cleanupDevFS() async { final List> futures = >[]; for (FlutterDevice device in flutterDevices) { if (device.devFS != null) { - // Cleanup the devFS; don't wait indefinitely, and ignore any errors. + // Cleanup the devFS, but don't wait indefinitely. + // We ignore any errors, because it's not clear what we would do anyway. futures.add(device.devFS.destroy() .timeout(const Duration(milliseconds: 250)) .catchError((dynamic error) { - printTrace('$error'); + printTrace('Ignored error while cleaning up DevFS: $error'); })); } device.devFS = null; } - final Completer completer = Completer(); - Future.wait(futures).whenComplete(() { completer.complete(null); } ); // ignore: unawaited_futures - return completer.future; + await Future.wait(futures); } Future _launchInView(FlutterDevice device, @@ -575,6 +576,7 @@ class HotRunner extends ResidentRunner { } final Status status = logger.startProgress( 'Performing hot restart...', + timeout: kFastOperation, progressId: 'hot.restart', ); try { @@ -591,26 +593,45 @@ class HotRunner extends ResidentRunner { } else { final bool reloadOnTopOfSnapshot = _runningFromSnapshot; final String progressPrefix = reloadOnTopOfSnapshot ? 'Initializing' : 'Performing'; - final Status status = logger.startProgress( + Status status = logger.startProgress( '$progressPrefix hot reload...', - progressId: 'hot.reload' + timeout: kFastOperation, + progressId: 'hot.reload', ); OperationResult result; + bool showTime = true; try { - result = await _reloadSources(pause: pauseAfterRestart, reason: reason); + result = await _reloadSources( + pause: pauseAfterRestart, + reason: reason, + onSlow: (String message) { + status?.cancel(); + status = logger.startProgress( + message, + timeout: kSlowOperation, + progressId: 'hot.reload', + ); + showTime = false; + }, + ); } finally { status.cancel(); } - if (result.isOk) - printStatus('${result.message} in ${getElapsedAsMilliseconds(timer.elapsed)}.'); + if (result.isOk) { + if (showTime) { + printStatus('${result.message} in ${getElapsedAsMilliseconds(timer.elapsed)}.'); + } else { + printStatus('${result.message}.'); + } + } if (result.hintMessage != null) printStatus('\n${result.hintMessage}'); return result; } } - Future _reloadSources({ bool pause = false, String reason }) async { - final Map analyticsParameters = {}; + Future _reloadSources({ bool pause = false, String reason, void Function(String message) onSlow }) async { + final Map analyticsParameters = {}; if (reason != null) { analyticsParameters[kEventReloadReasonParameterName] = reason; } @@ -621,25 +642,24 @@ class HotRunner extends ResidentRunner { } } - if (!_isPaused()) { - printTrace('Refreshing active FlutterViews before reloading.'); - await refreshViews(); - } - // The initial launch is from a script snapshot. When we reload from source // on top of a script snapshot, the first reload will be a worst case reload // because all of the sources will end up being dirty (library paths will // change from host path to a device path). Subsequent reloads will // not be affected, so we resume reporting reload times on the second // reload. - final bool shouldReportReloadTime = !_runningFromSnapshot; + bool shouldReportReloadTime = !_runningFromSnapshot; final Stopwatch reloadTimer = Stopwatch()..start(); + if (!_isPaused()) { + printTrace('Refreshing active FlutterViews before reloading.'); + await refreshViews(); + } + final Stopwatch devFSTimer = Stopwatch()..start(); final UpdateFSReport updatedDevFS = await _updateDevFS(); // Record time it took to synchronize to DevFS. - _addBenchmarkData('hotReloadDevFSSyncMilliseconds', - devFSTimer.elapsed.inMilliseconds); + _addBenchmarkData('hotReloadDevFSSyncMilliseconds', devFSTimer.elapsed.inMilliseconds); if (!updatedDevFS.success) return OperationResult(1, 'DevFS synchronization failed'); String reloadMessage; @@ -656,7 +676,6 @@ class HotRunner extends ResidentRunner { // running from snapshot to running from uploaded files. await device.resetAssetDirectory(); } - final Completer completer = Completer(); allReportsFutures.add(completer.future); final List>> reportFutures = device.reloadSources( @@ -672,7 +691,6 @@ class HotRunner extends ResidentRunner { completer.complete(DeviceReloadReport(device, reports)); }); } - final List reports = await Future.wait(allReportsFutures); for (DeviceReloadReport report in reports) { final Map reloadReport = report.reports[0]; @@ -700,29 +718,26 @@ class HotRunner extends ResidentRunner { reloadMessage = 'Reloaded $loadedLibraryCount of $finalLibraryCount libraries'; } } - } on Map catch (error, st) { - printError('Hot reload failed: $error\n$st'); + } on Map catch (error, stackTrace) { + printTrace('Hot reload failed: $error\n$stackTrace'); final int errorCode = error['code']; - final String errorMessage = error['message']; + String errorMessage = error['message']; if (errorCode == Isolate.kIsolateReloadBarred) { - printError( - 'Unable to hot reload application due to an unrecoverable error in ' - 'the source code. Please address the error and then use "R" to ' - 'restart the app.' - ); + errorMessage = 'Unable to hot reload application due to an unrecoverable error in ' + 'the source code. Please address the error and then use "R" to ' + 'restart the app.\n' + '$errorMessage (error code: $errorCode)'; flutterUsage.sendEvent('hot', 'reload-barred'); return OperationResult(errorCode, errorMessage); } - - printError('Hot reload failed:\ncode = $errorCode\nmessage = $errorMessage\n$st'); - return OperationResult(errorCode, errorMessage); - } catch (error, st) { - printError('Hot reload failed: $error\n$st'); + return OperationResult(errorCode, '$errorMessage (error code: $errorCode)'); + } catch (error, stackTrace) { + printTrace('Hot reload failed: $error\n$stackTrace'); return OperationResult(1, '$error'); } // Record time it took for the VM to reload the sources. - _addBenchmarkData('hotReloadVMReloadMilliseconds', - vmReloadTimer.elapsed.inMilliseconds); + _addBenchmarkData('hotReloadVMReloadMilliseconds', vmReloadTimer.elapsed.inMilliseconds); + final Stopwatch reassembleTimer = Stopwatch()..start(); // Reload the isolate. final List> allDevices = >[]; @@ -739,53 +754,97 @@ class HotRunner extends ResidentRunner { }); allDevices.add(deviceCompleter.future); } - await Future.wait(allDevices); // We are now running from source. _runningFromSnapshot = false; - // Check if the isolate is paused. - + // Check if any isolates are paused. final List reassembleViews = []; + String serviceEventKind; + int pausedIsolatesFound = 0; for (FlutterDevice device in flutterDevices) { for (FlutterView view in device.views) { // Check if the isolate is paused, and if so, don't reassemble. Ignore the // PostPauseEvent event - the client requesting the pause will resume the app. final ServiceEvent pauseEvent = view.uiIsolate.pauseEvent; if (pauseEvent != null && pauseEvent.isPauseEvent && pauseEvent.kind != ServiceEvent.kPausePostRequest) { - continue; + pausedIsolatesFound += 1; + if (serviceEventKind == null) { + serviceEventKind = pauseEvent.kind; + } else if (serviceEventKind != pauseEvent.kind) { + serviceEventKind = ''; // many kinds + } + } else { + reassembleViews.add(view); } - reassembleViews.add(view); } } - if (reassembleViews.isEmpty) { - printTrace('Skipping reassemble because all isolates are paused.'); - return OperationResult(OperationResult.ok.code, reloadMessage); + if (pausedIsolatesFound > 0) { + if (onSlow != null) + onSlow('${_describePausedIsolates(pausedIsolatesFound, serviceEventKind)}; interface might not update.'); + if (reassembleViews.isEmpty) { + printTrace('Skipping reassemble because all isolates are paused.'); + return OperationResult(OperationResult.ok.code, reloadMessage); + } } + assert(reassembleViews.isNotEmpty); printTrace('Evicting dirty assets'); await _evictDirtyAssets(); printTrace('Reassembling application'); - bool reassembleAndScheduleErrors = false; - bool reassembleTimedOut = false; + bool failedReassemble = false; final List> futures = >[]; for (FlutterView view in reassembleViews) { - futures.add(view.uiIsolate.flutterReassemble().then((_) { - return view.uiIsolate.uiWindowScheduleFrame(); - }).catchError((dynamic error) { - if (error is TimeoutException) { - reassembleTimedOut = true; - printTrace('Reassembling ${view.uiIsolate.name} took too long.'); - printStatus('Hot reloading ${view.uiIsolate.name} took too long; the reload may have failed.'); - } else { - reassembleAndScheduleErrors = true; + futures.add(() async { + try { + await view.uiIsolate.flutterReassemble(); + } catch (error) { + failedReassemble = true; printError('Reassembling ${view.uiIsolate.name} failed: $error'); + return; } - })); + try { + await view.uiIsolate.uiWindowScheduleFrame(); + } catch (error) { + failedReassemble = true; + printError('Scheduling a frame for ${view.uiIsolate.name} failed: $error'); + } + }()); } - await Future.wait(futures); - + final Future reassembleFuture = Future.wait(futures).then((List values) { }); + await reassembleFuture.timeout( + const Duration(seconds: 2), + onTimeout: () async { + if (pausedIsolatesFound > 0) { + shouldReportReloadTime = false; + return; // probably no point waiting, they're probably deadlocked and we've already warned. + } + // Check if any isolate is newly paused. + printTrace('This is taking a long time; will now check for paused isolates.'); + int postReloadPausedIsolatesFound = 0; + String serviceEventKind; + for (FlutterView view in reassembleViews) { + await view.uiIsolate.reload(); + final ServiceEvent pauseEvent = view.uiIsolate.pauseEvent; + if (pauseEvent != null && pauseEvent.isPauseEvent) { + postReloadPausedIsolatesFound += 1; + if (serviceEventKind == null) { + serviceEventKind = pauseEvent.kind; + } else if (serviceEventKind != pauseEvent.kind) { + serviceEventKind = ''; // many kinds + } + } + } + printTrace('Found $postReloadPausedIsolatesFound newly paused isolate(s).'); + if (postReloadPausedIsolatesFound == 0) { + await reassembleFuture; // must just be taking a long time... keep waiting! + return; + } + shouldReportReloadTime = false; + if (onSlow != null) + onSlow('${_describePausedIsolates(postReloadPausedIsolatesFound, serviceEventKind)}.'); + }, + ); // Record time it took for Flutter to reassemble the application. - _addBenchmarkData('hotReloadFlutterReassembleMilliseconds', - reassembleTimer.elapsed.inMilliseconds); + _addBenchmarkData('hotReloadFlutterReassembleMilliseconds', reassembleTimer.elapsed.inMilliseconds); reloadTimer.stop(); final Duration reloadDuration = reloadTimer.elapsed; @@ -794,23 +853,51 @@ class HotRunner extends ResidentRunner { analyticsParameters[kEventReloadOverallTimeInMs] = '$reloadInMs'; flutterUsage.sendEvent('hot', 'reload', parameters: analyticsParameters); - printTrace('Hot reload performed in $reloadInMs.'); - // Record complete time it took for the reload. - _addBenchmarkData('hotReloadMillisecondsToFrame', reloadInMs); - // Only report timings if we reloaded a single view without any - // errors or timeouts. - if ((reassembleViews.length == 1) && - !reassembleAndScheduleErrors && - !reassembleTimedOut && - shouldReportReloadTime) + if (shouldReportReloadTime) { + printTrace('Hot reload performed in ${getElapsedAsMilliseconds(reloadDuration)}.'); + // Record complete time it took for the reload. + _addBenchmarkData('hotReloadMillisecondsToFrame', reloadInMs); + } + // Only report timings if we reloaded a single view without any errors. + if ((reassembleViews.length == 1) && !failedReassemble && shouldReportReloadTime) flutterUsage.sendTiming('hot', 'reload', reloadDuration); return OperationResult( - reassembleAndScheduleErrors ? 1 : OperationResult.ok.code, + failedReassemble ? 1 : OperationResult.ok.code, reloadMessage, ); } + String _describePausedIsolates(int pausedIsolatesFound, String serviceEventKind) { + assert(pausedIsolatesFound > 0); + final StringBuffer message = StringBuffer(); + bool plural; + if (pausedIsolatesFound == 1) { + if (flutterDevices.length == 1 && flutterDevices.single.views.length == 1) { + message.write('The application is '); + } else { + message.write('An isolate is '); + } + plural = false; + } else { + message.write('$pausedIsolatesFound isolates are '); + plural = true; + } + assert(serviceEventKind != null); + switch (serviceEventKind) { + case ServiceEvent.kPauseStart: message.write('paused (probably due to --start-paused)'); break; + case ServiceEvent.kPauseExit: message.write('paused because ${ plural ? 'they have' : 'it has' } terminated'); break; + case ServiceEvent.kPauseBreakpoint: message.write('paused in the debugger on a breakpoint'); break; + case ServiceEvent.kPauseInterrupted: message.write('paused due in the debugger'); break; + case ServiceEvent.kPauseException: message.write('paused in the debugger after an exception was thrown'); break; + case ServiceEvent.kPausePostRequest: message.write('paused'); break; + case '': message.write('paused for various reasons'); break; + default: + message.write('paused'); + } + return message.toString(); + } + bool _isPaused() { for (FlutterDevice device in flutterDevices) { for (FlutterView view in device.views) { @@ -822,7 +909,6 @@ class HotRunner extends ResidentRunner { } } } - return false; } diff --git a/packages/flutter_tools/lib/src/runner/flutter_command.dart b/packages/flutter_tools/lib/src/runner/flutter_command.dart index f2faebb42e3..591d557bf27 100644 --- a/packages/flutter_tools/lib/src/runner/flutter_command.dart +++ b/packages/flutter_tools/lib/src/runner/flutter_command.dart @@ -482,19 +482,18 @@ abstract class FlutterCommand extends Command { body: () async { if (flutterUsage.isFirstRun) flutterUsage.printWelcome(); - + final String commandPath = await usagePath; FlutterCommandResult commandResult; try { - commandResult = await verifyThenRunCommand(); + commandResult = await verifyThenRunCommand(commandPath); } on ToolExit { commandResult = const FlutterCommandResult(ExitStatus.fail); rethrow; } finally { final DateTime endTime = systemClock.now(); printTrace(userMessages.flutterElapsedTime(name, getElapsedAsMilliseconds(endTime.difference(startTime)))); - // This is checking the result of the call to 'usagePath' - // (a Future), and not the result of evaluating the Future. - if (usagePath != null) { + printTrace('"flutter $name" took ${getElapsedAsMilliseconds(endTime.difference(startTime))}.'); + if (commandPath != null) { final List labels = []; if (commandResult?.exitStatus != null) labels.add(getEnumName(commandResult.exitStatus)); @@ -528,7 +527,7 @@ abstract class FlutterCommand extends Command { /// then call this method to execute the command /// rather than calling [runCommand] directly. @mustCallSuper - Future verifyThenRunCommand() async { + Future verifyThenRunCommand(String commandPath) async { await validateCommand(); // Populate the cache. We call this before pub get below so that the sky_engine @@ -544,8 +543,6 @@ abstract class FlutterCommand extends Command { setupApplicationPackages(); - final String commandPath = await usagePath; - if (commandPath != null) { final Map additionalUsageValues = await usageValues; flutterUsage.sendCommand(commandPath, parameters: additionalUsageValues); diff --git a/packages/flutter_tools/lib/src/test/coverage_collector.dart b/packages/flutter_tools/lib/src/test/coverage_collector.dart index fda1785f612..ff8ca0c6256 100644 --- a/packages/flutter_tools/lib/src/test/coverage_collector.dart +++ b/packages/flutter_tools/lib/src/test/coverage_collector.dart @@ -57,13 +57,7 @@ class CoverageCollector extends TestWatcher { if (result == null) throw Exception('Failed to collect coverage.'); data = result; - }) - .timeout( - const Duration(minutes: 10), - onTimeout: () { - throw Exception('Timed out while collecting coverage.'); - }, - ); + }); await Future.any(>[ processComplete, collectionComplete ]); assert(data != null); @@ -77,12 +71,8 @@ class CoverageCollector extends TestWatcher { /// /// This will not start any collection tasks. It us up to the caller of to /// call [collectCoverage] for each process first. - /// - /// If [timeout] is specified, the future will timeout (with a - /// [TimeoutException]) after the specified duration. Future finalizeCoverage({ coverage.Formatter formatter, - Duration timeout, Directory coverageDirectory, }) async { printTrace('formating coverage data'); @@ -102,9 +92,8 @@ class CoverageCollector extends TestWatcher { } Future collectCoverageData(String coveragePath, { bool mergeCoverageData = false, Directory coverageDirectory }) async { - final Status status = logger.startProgress('Collecting coverage information...'); + final Status status = logger.startProgress('Collecting coverage information...', timeout: kFastOperation); final String coverageData = await finalizeCoverage( - timeout: const Duration(seconds: 30), coverageDirectory: coverageDirectory, ); status.stop(); diff --git a/packages/flutter_tools/lib/src/test/flutter_platform.dart b/packages/flutter_tools/lib/src/test/flutter_platform.dart index e01414e47ab..5886f03e3a2 100644 --- a/packages/flutter_tools/lib/src/test/flutter_platform.dart +++ b/packages/flutter_tools/lib/src/test/flutter_platform.dart @@ -33,11 +33,17 @@ import 'watcher.dart'; /// The timeout we give the test process to connect to the test harness /// once the process has entered its main method. -const Duration _kTestStartupTimeout = Duration(minutes: 1); +/// +/// We time out test execution because we expect some tests to hang and we want +/// to know which test hung, rather than have the entire test harness just do +/// nothing for a few hours until the user (or CI environment) gets bored. +const Duration _kTestStartupTimeout = Duration(minutes: 5); /// The timeout we give the test process to start executing Dart code. When the /// CPU is under severe load, this can take a while, but it's not indicative of /// any problem with Flutter, so we give it a large timeout. +/// +/// See comment under [_kTestStartupTimeout] regarding timeouts. const Duration _kTestProcessTimeout = Duration(minutes: 5); /// Message logged by the test process to signal that its main method has begun @@ -288,13 +294,11 @@ class _Compiler { firstCompile = true; } suppressOutput = false; - final CompilerOutput compilerOutput = await handleTimeout( - compiler.recompile( - request.path, - [request.path], - outputPath: outputDill.path), - request.path, - ); + final CompilerOutput compilerOutput = await compiler.recompile( + request.path, + [request.path], + outputPath: outputDill.path, + ); final String outputPath = compilerOutput?.outputFilename; // In case compiler didn't produce output or reported compilation @@ -337,7 +341,7 @@ class _Compiler { Future compile(String mainDart) { final Completer completer = Completer(); compilerController.add(_CompilationRequest(mainDart, completer)); - return handleTimeout(completer.future, mainDart); + return completer.future; } Future _shutdown() async { @@ -353,13 +357,6 @@ class _Compiler { await _shutdown(); await compilerController.close(); } - - static Future handleTimeout(Future value, String path) { - return value.timeout(const Duration(minutes: 5), onTimeout: () { - printError('Compilation of $path timed out after 5 minutes.'); - return null; - }); - } } class _FlutterPlatform extends PlatformPlugin { diff --git a/packages/flutter_tools/lib/src/tracing.dart b/packages/flutter_tools/lib/src/tracing.dart index 3fe3953ac3b..485fb30e9a8 100644 --- a/packages/flutter_tools/lib/src/tracing.dart +++ b/packages/flutter_tools/lib/src/tracing.dart @@ -5,6 +5,7 @@ import 'dart:async'; import 'base/file_system.dart'; +import 'base/logger.dart'; import 'base/utils.dart'; import 'build_info.dart'; import 'globals.dart'; @@ -18,6 +19,8 @@ const String _kFirstUsefulFrameEventName = 'Widgets completed first useful frame class Tracing { Tracing(this.vmService); + static const String firstUsefulFrameEventName = _kFirstUsefulFrameEventName; + static Future connect(Uri uri) async { final VMService observatory = await VMService.connect(uri); return Tracing(observatory); @@ -32,49 +35,46 @@ class Tracing { /// Stops tracing; optionally wait for first frame. Future> stopTracingAndDownloadTimeline({ - bool waitForFirstFrame = false + bool awaitFirstFrame = false }) async { - Map timeline; - - if (!waitForFirstFrame) { - // Stop tracing immediately and get the timeline - await vmService.vm.setVMTimelineFlags([]); - timeline = await vmService.vm.getVMTimeline(); - } else { - final Completer whenFirstFrameRendered = Completer(); - - (await vmService.onTimelineEvent).listen((ServiceEvent timelineEvent) { - final List> events = timelineEvent.timelineEvents; - for (Map event in events) { - if (event['name'] == _kFirstUsefulFrameEventName) - whenFirstFrameRendered.complete(); - } - }); - - await whenFirstFrameRendered.future.timeout( - const Duration(seconds: 10), - onTimeout: () { - printError( - 'Timed out waiting for the first frame event. Either the ' - 'application failed to start, or the event was missed because ' - '"flutter run" took too long to subscribe to timeline events.' - ); - return null; - } + if (awaitFirstFrame) { + final Status status = logger.startProgress( + 'Waiting for application to render first frame...', + timeout: kFastOperation, ); - - timeline = await vmService.vm.getVMTimeline(); - - await vmService.vm.setVMTimelineFlags([]); + try { + final Completer whenFirstFrameRendered = Completer(); + (await vmService.onTimelineEvent).listen((ServiceEvent timelineEvent) { + final List> events = timelineEvent.timelineEvents; + for (Map event in events) { + if (event['name'] == _kFirstUsefulFrameEventName) + whenFirstFrameRendered.complete(); + } + }); + bool done = false; + for (FlutterView view in vmService.vm.views) { + if (await view.uiIsolate.flutterAlreadyPaintedFirstUsefulFrame()) { + done = true; + break; + } + } + if (!done) + await whenFirstFrameRendered.future; + } catch (exception) { + status.cancel(); + rethrow; + } + status.stop(); } - + final Map timeline = await vmService.vm.getVMTimeline(); + await vmService.vm.setVMTimelineFlags([]); return timeline; } } /// Download the startup trace information from the given observatory client and /// store it to build/start_up_info.json. -Future downloadStartupTrace(VMService observatory) async { +Future downloadStartupTrace(VMService observatory, { bool awaitFirstFrame = true }) async { final String traceInfoFilePath = fs.path.join(getBuildDirectory(), 'start_up_info.json'); final File traceInfoFile = fs.file(traceInfoFilePath); @@ -89,45 +89,53 @@ Future downloadStartupTrace(VMService observatory) async { final Tracing tracing = Tracing(observatory); final Map timeline = await tracing.stopTracingAndDownloadTimeline( - waitForFirstFrame: true + awaitFirstFrame: awaitFirstFrame, ); int extractInstantEventTimestamp(String eventName) { final List> events = List>.from(timeline['traceEvents']); final Map event = events.firstWhere( - (Map event) => event['name'] == eventName, orElse: () => null + (Map event) => event['name'] == eventName, orElse: () => null ); return event == null ? null : event['ts']; } + String message = 'No useful metrics were gathered.'; + final int engineEnterTimestampMicros = extractInstantEventTimestamp(_kFlutterEngineMainEnterEventName); final int frameworkInitTimestampMicros = extractInstantEventTimestamp(_kFrameworkInitEventName); - final int firstFrameTimestampMicros = extractInstantEventTimestamp(_kFirstUsefulFrameEventName); if (engineEnterTimestampMicros == null) { printTrace('Engine start event is missing in the timeline: $timeline'); throw 'Engine start event is missing in the timeline. Cannot compute startup time.'; } - if (firstFrameTimestampMicros == null) { - printTrace('First frame event is missing in the timeline: $timeline'); - throw 'First frame event is missing in the timeline. Cannot compute startup time.'; - } - - final int timeToFirstFrameMicros = firstFrameTimestampMicros - engineEnterTimestampMicros; final Map traceInfo = { 'engineEnterTimestampMicros': engineEnterTimestampMicros, - 'timeToFirstFrameMicros': timeToFirstFrameMicros, }; if (frameworkInitTimestampMicros != null) { - traceInfo['timeToFrameworkInitMicros'] = frameworkInitTimestampMicros - engineEnterTimestampMicros; - traceInfo['timeAfterFrameworkInitMicros'] = firstFrameTimestampMicros - frameworkInitTimestampMicros; + final int timeToFrameworkInitMicros = frameworkInitTimestampMicros - engineEnterTimestampMicros; + traceInfo['timeToFrameworkInitMicros'] = timeToFrameworkInitMicros; + message = 'Time to framework init: ${timeToFrameworkInitMicros ~/ 1000}ms.'; + } + + if (awaitFirstFrame) { + final int firstFrameTimestampMicros = extractInstantEventTimestamp(_kFirstUsefulFrameEventName); + if (firstFrameTimestampMicros == null) { + printTrace('First frame event is missing in the timeline: $timeline'); + throw 'First frame event is missing in the timeline. Cannot compute startup time.'; + } + final int timeToFirstFrameMicros = firstFrameTimestampMicros - engineEnterTimestampMicros; + traceInfo['timeToFirstFrameMicros'] = timeToFirstFrameMicros; + message = 'Time to first frame: ${timeToFirstFrameMicros ~/ 1000}ms.'; + if (frameworkInitTimestampMicros != null) + traceInfo['timeAfterFrameworkInitMicros'] = firstFrameTimestampMicros - frameworkInitTimestampMicros; } traceInfoFile.writeAsStringSync(toPrettyJson(traceInfo)); - printStatus('Time to first frame: ${timeToFirstFrameMicros ~/ 1000}ms.'); + printStatus(message); printStatus('Saved startup trace info in ${traceInfoFile.path}.'); } diff --git a/packages/flutter_tools/lib/src/vmservice.dart b/packages/flutter_tools/lib/src/vmservice.dart index 48a8c8a059e..f9b53b98fe2 100644 --- a/packages/flutter_tools/lib/src/vmservice.dart +++ b/packages/flutter_tools/lib/src/vmservice.dart @@ -15,12 +15,17 @@ import 'package:web_socket_channel/io.dart'; import 'package:web_socket_channel/web_socket_channel.dart'; import 'base/common.dart'; +import 'base/context.dart'; import 'base/file_system.dart'; import 'base/io.dart' as io; import 'base/utils.dart'; import 'globals.dart'; import 'vmservice_record_replay.dart'; +/// Override `WebSocketConnector` in [context] to use a different constructor +/// for [WebSocket]s (used by tests). +typedef WebSocketConnector = Future Function(String url); + /// A function that opens a two-way communication channel to the specified [uri]. typedef _OpenChannel = Future> Function(Uri uri); @@ -58,60 +63,46 @@ typedef CompileExpression = Future Function( const String _kRecordingType = 'vmservice'; Future> _defaultOpenChannel(Uri uri) async { - const int _kMaxAttempts = 5; Duration delay = const Duration(milliseconds: 100); int attempts = 0; io.WebSocket socket; - Future onError(dynamic e) async { - printTrace('Exception attempting to connect to observatory: $e'); + Future handleError(dynamic e) async { + printTrace('Exception attempting to connect to Observatory: $e'); printTrace('This was attempt #$attempts. Will retry in $delay.'); + if (attempts == 10) + printStatus('This is taking longer than expected...'); + // Delay next attempt. await Future.delayed(delay); - // Back off exponentially. - delay *= 2; + // Back off exponentially, up to 1600ms per attempt. + if (delay < const Duration(seconds: 1)) + delay *= 2; } - while (attempts < _kMaxAttempts && socket == null) { + final WebSocketConnector constructor = context[WebSocketConnector] ?? io.WebSocket.connect; + while (socket == null) { attempts += 1; try { - socket = await io.WebSocket.connect(uri.toString()); + socket = await constructor(uri.toString()); } on io.WebSocketException catch (e) { - await onError(e); + await handleError(e); } on io.SocketException catch (e) { - await onError(e); + await handleError(e); } } - - if (socket == null) { - throw ToolExit( - 'Attempted to connect to Dart observatory $_kMaxAttempts times, and ' - 'all attempts failed. Giving up. The URL was $uri' - ); - } - return IOWebSocketChannel(socket).cast(); } -/// The default VM service request timeout. -const Duration kDefaultRequestTimeout = Duration(seconds: 30); - -/// Used for RPC requests that may take a long time. -const Duration kLongRequestTimeout = Duration(minutes: 1); - -/// Used for RPC requests that should never take a long time. -const Duration kShortRequestTimeout = Duration(seconds: 5); - -// TODO(mklim): Test this, flutter/flutter#23031. /// A connection to the Dart VM Service. +// TODO(mklim): Test this, https://github.com/flutter/flutter/issues/23031 class VMService { VMService( this._peer, this.httpAddress, this.wsAddress, - this._requestTimeout, ReloadSources reloadSources, Restart restart, CompileExpression compileExpression, @@ -247,9 +238,6 @@ class VMService { /// Connect to a Dart VM Service at [httpUri]. /// - /// Requests made via the returned [VMService] time out after [requestTimeout] - /// amount of time, which is [kDefaultRequestTimeout] by default. - /// /// If the [reloadSources] parameter is not null, the 'reloadSources' service /// will be registered. The VM Service Protocol allows clients to register /// custom services that can be invoked by other clients through the service @@ -258,7 +246,6 @@ class VMService { /// See: https://github.com/dart-lang/sdk/commit/df8bf384eb815cf38450cb50a0f4b62230fba217 static Future connect( Uri httpUri, { - Duration requestTimeout = kDefaultRequestTimeout, ReloadSources reloadSources, Restart restart, CompileExpression compileExpression, @@ -266,7 +253,7 @@ class VMService { final Uri wsUri = httpUri.replace(scheme: 'ws', path: fs.path.join(httpUri.path, 'ws')); final StreamChannel channel = await _openChannel(wsUri); final rpc.Peer peer = rpc.Peer.withoutJson(jsonDocument.bind(channel)); - final VMService service = VMService(peer, httpUri, wsUri, requestTimeout, reloadSources, restart, compileExpression); + final VMService service = VMService(peer, httpUri, wsUri, reloadSources, restart, compileExpression); // This call is to ensure we are able to establish a connection instead of // keeping on trucking and failing farther down the process. await service._sendRequest('getVersion', const {}); @@ -276,7 +263,6 @@ class VMService { final Uri httpAddress; final Uri wsAddress; final rpc.Peer _peer; - final Duration _requestTimeout; final Completer> _connectionError = Completer>(); VM _vm; @@ -841,28 +827,15 @@ class VM extends ServiceObjectOwner { } /// Invoke the RPC and return the raw response. - /// - /// If `timeoutFatal` is false, then a timeout will result in a null return - /// value. Otherwise, it results in an exception. Future> invokeRpcRaw(String method, { Map params = const {}, - Duration timeout, - bool timeoutFatal = true, }) async { printTrace('Sending to VM service: $method($params)'); assert(params != null); - timeout ??= _vmService._requestTimeout; try { - final Map result = await _vmService - ._sendRequest(method, params) - .timeout(timeout); + final Map result = await _vmService._sendRequest(method, params); printTrace('Result: ${_truncate(result.toString(), 250, '...')}'); return result; - } on TimeoutException { - printTrace('Request to Dart VM Service timed out: $method($params)'); - if (timeoutFatal) - throw TimeoutException('Request to Dart VM Service timed out: $method($params)'); - return null; } on WebSocketChannelException catch (error) { throwToolExit('Error connecting to observatory: $error'); return null; @@ -876,12 +849,10 @@ class VM extends ServiceObjectOwner { /// Invoke the RPC and return a [ServiceObject] response. Future invokeRpc(String method, { Map params = const {}, - Duration timeout, }) async { final Map response = await invokeRpcRaw( method, params: params, - timeout: timeout, ); final ServiceObject serviceObject = ServiceObject._fromMap(this, response); if ((serviceObject != null) && (serviceObject._canCache)) { @@ -968,7 +939,7 @@ class VM extends ServiceObjectOwner { } Future> getVMTimeline() { - return invokeRpcRaw('_getVMTimeline', timeout: kLongRequestTimeout); + return invokeRpcRaw('_getVMTimeline'); } Future refreshViews({ bool waitForViews = false }) async { @@ -982,10 +953,7 @@ class VM extends ServiceObjectOwner { // When the future returned by invokeRpc() below returns, // the _viewCache will have been updated. // This message updates all the views of every isolate. - await vmService.vm.invokeRpc( - '_flutter.listViews', - timeout: kLongRequestTimeout, - ); + await vmService.vm.invokeRpc('_flutter.listViews'); if (_viewCache.values.isNotEmpty || !waitForViews) return; failCount += 1; @@ -1124,8 +1092,6 @@ class Isolate extends ServiceObjectOwner { /// Invoke the RPC and return the raw response. Future> invokeRpcRaw(String method, { Map params, - Duration timeout, - bool timeoutFatal = true, }) { // Inject the 'isolateId' parameter. if (params == null) { @@ -1135,7 +1101,7 @@ class Isolate extends ServiceObjectOwner { } else { params['isolateId'] = id; } - return vm.invokeRpcRaw(method, params: params, timeout: timeout, timeoutFatal: timeoutFatal); + return vm.invokeRpcRaw(method, params: params); } /// Invoke the RPC and return a ServiceObject response. @@ -1257,40 +1223,36 @@ class Isolate extends ServiceObjectOwner { Future> invokeFlutterExtensionRpcRaw( String method, { Map params, - Duration timeout, - bool timeoutFatal = true, } - ) { - return invokeRpcRaw(method, params: params, timeout: timeout, - timeoutFatal: timeoutFatal).catchError((dynamic error) { - if (error is rpc.RpcException) { - // If an application is not using the framework - if (error.code == rpc_error_code.METHOD_NOT_FOUND) - return null; - throw error; - }}); + ) async { + try { + return await invokeRpcRaw(method, params: params); + } on rpc.RpcException catch (e) { + // If an application is not using the framework + if (e.code == rpc_error_code.METHOD_NOT_FOUND) + return null; + rethrow; + } } - // Debug dump extension methods. - Future> flutterDebugDumpApp() { - return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpApp', timeout: kLongRequestTimeout); + return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpApp'); } Future> flutterDebugDumpRenderTree() { - return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpRenderTree', timeout: kLongRequestTimeout); + return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpRenderTree'); } Future> flutterDebugDumpLayerTree() { - return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpLayerTree', timeout: kLongRequestTimeout); + return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpLayerTree'); } Future> flutterDebugDumpSemanticsTreeInTraversalOrder() { - return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpSemanticsTreeInTraversalOrder', timeout: kLongRequestTimeout); + return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpSemanticsTreeInTraversalOrder'); } Future> flutterDebugDumpSemanticsTreeInInverseHitTestOrder() { - return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpSemanticsTreeInInverseHitTestOrder', timeout: kLongRequestTimeout); + return invokeFlutterExtensionRpcRaw('ext.flutter.debugDumpSemanticsTreeInInverseHitTestOrder'); } Future> _flutterToggle(String name) async { @@ -1299,8 +1261,6 @@ class Isolate extends ServiceObjectOwner { state = await invokeFlutterExtensionRpcRaw( 'ext.flutter.$name', params: { 'enabled': state['enabled'] == 'true' ? 'false' : 'true' }, - timeout: const Duration(milliseconds: 150), - timeoutFatal: false, ); } return state; @@ -1312,22 +1272,20 @@ class Isolate extends ServiceObjectOwner { Future> flutterToggleWidgetInspector() => _flutterToggle('inspector.show'); - Future flutterDebugAllowBanner(bool show) async { - await invokeFlutterExtensionRpcRaw( + Future> flutterDebugAllowBanner(bool show) { + return invokeFlutterExtensionRpcRaw( 'ext.flutter.debugAllowBanner', params: { 'enabled': show ? 'true' : 'false' }, - timeout: const Duration(milliseconds: 150), - timeoutFatal: false, ); } - // Reload related extension methods. Future> flutterReassemble() { - return invokeFlutterExtensionRpcRaw( - 'ext.flutter.reassemble', - timeout: kShortRequestTimeout, - timeoutFatal: true, - ); + return invokeFlutterExtensionRpcRaw('ext.flutter.reassemble'); + } + + Future flutterAlreadyPaintedFirstUsefulFrame() async { + final Map result = await invokeFlutterExtensionRpcRaw('ext.flutter.didSendFirstFrameEvent'); + return result['enabled'] == 'true'; } Future> uiWindowScheduleFrame() { @@ -1335,7 +1293,8 @@ class Isolate extends ServiceObjectOwner { } Future> flutterEvictAsset(String assetPath) { - return invokeFlutterExtensionRpcRaw('ext.flutter.evict', + return invokeFlutterExtensionRpcRaw( + 'ext.flutter.evict', params: { 'value': assetPath, } @@ -1352,19 +1311,13 @@ class Isolate extends ServiceObjectOwner { // Application control extension methods. Future> flutterExit() { - return invokeFlutterExtensionRpcRaw( - 'ext.flutter.exit', - timeout: const Duration(seconds: 2), - timeoutFatal: false, - ); + return invokeFlutterExtensionRpcRaw('ext.flutter.exit'); } Future flutterPlatformOverride([String platform]) async { final Map result = await invokeFlutterExtensionRpcRaw( 'ext.flutter.platformOverride', params: platform != null ? { 'value': platform } : {}, - timeout: const Duration(seconds: 5), - timeoutFatal: false, ); if (result != null && result['value'] is String) return result['value']; diff --git a/packages/flutter_tools/lib/src/vscode/vscode_validator.dart b/packages/flutter_tools/lib/src/vscode/vscode_validator.dart index f955c5f4e8f..8fc643492ab 100644 --- a/packages/flutter_tools/lib/src/vscode/vscode_validator.dart +++ b/packages/flutter_tools/lib/src/vscode/vscode_validator.dart @@ -14,7 +14,6 @@ class VsCodeValidator extends DoctorValidator { final VsCode _vsCode; - static Iterable get installedValidators { return VsCode .allInstalled() diff --git a/packages/flutter_tools/test/base/context_test.dart b/packages/flutter_tools/test/base/context_test.dart index 94ec5675a79..9b05cbc0f4f 100644 --- a/packages/flutter_tools/test/base/context_test.dart +++ b/packages/flutter_tools/test/base/context_test.dart @@ -158,7 +158,7 @@ void main() { fallbacks: { int: () => int.parse(context[String]), String: () => '${context[double]}', - double: () => context[int] * 1.0, + double: () => (context[int] as int) * 1.0, // ignore: avoid_as }, ); try { diff --git a/packages/flutter_tools/test/base/logger_test.dart b/packages/flutter_tools/test/base/logger_test.dart index 923b5c7fe60..ec61cffb5e5 100644 --- a/packages/flutter_tools/test/base/logger_test.dart +++ b/packages/flutter_tools/test/base/logger_test.dart @@ -2,13 +2,12 @@ // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. -import 'dart:async'; - import 'package:flutter_tools/src/base/context.dart'; import 'package:flutter_tools/src/base/io.dart'; import 'package:flutter_tools/src/base/logger.dart'; import 'package:flutter_tools/src/base/platform.dart'; import 'package:flutter_tools/src/base/terminal.dart'; +import 'package:quiver/testing/async.dart'; import '../src/common.dart'; import '../src/context.dart'; @@ -64,73 +63,117 @@ void main() { group('Spinners', () { MockStdio mockStdio; - AnsiSpinner ansiSpinner; AnsiStatus ansiStatus; int called; const List testPlatforms = ['linux', 'macos', 'windows', 'fuchsia']; - final RegExp secondDigits = RegExp(r'[^\b]\b\b\b\b\b[0-9]+[.][0-9]+(?:s|ms)'); + final RegExp secondDigits = RegExp(r'[0-9,.]*[0-9]m?s'); setUp(() { mockStdio = MockStdio(); - ansiSpinner = AnsiSpinner(); called = 0; ansiStatus = AnsiStatus( message: 'Hello world', - expectSlowOperation: true, + timeout: const Duration(milliseconds: 10), padding: 20, - onFinish: () => called++, + onFinish: () => called += 1, ); }); List outputStdout() => mockStdio.writtenToStdout.join('').split('\n'); List outputStderr() => mockStdio.writtenToStderr.join('').split('\n'); - Future doWhileAsync(bool doThis()) async { - return Future.doWhile(() { - // We want to let other tasks run at the same time, so we schedule these - // using a timer rather than a microtask. - return Future.delayed(Duration.zero, doThis); - }); + void doWhileAsync(FakeAsync time, bool doThis()) { + do { + time.elapse(const Duration(milliseconds: 1)); + } while (doThis()); } for (String testOs in testPlatforms) { testUsingContext('AnsiSpinner works for $testOs', () async { - ansiSpinner.start(); - await doWhileAsync(() => ansiSpinner.ticks < 10); - List lines = outputStdout(); - expect(lines[0], startsWith(platform.isWindows - ? ' \b-\b\\\b|\b/\b-\b\\\b|\b/' - : ' \b⣾\b⣽\b⣻\b⢿\b⡿\b⣟\b⣯\b⣷\b⣾\b⣽')); - expect(lines[0].endsWith('\n'), isFalse); - expect(lines.length, equals(1)); - ansiSpinner.stop(); - lines = outputStdout(); - expect(lines[0], endsWith('\b \b')); - expect(lines.length, equals(1)); - - // Verify that stopping or canceling multiple times throws. - expect(() { + bool done = false; + FakeAsync().run((FakeAsync time) { + final AnsiSpinner ansiSpinner = AnsiSpinner( + timeout: const Duration(hours: 10), + )..start(); + doWhileAsync(time, () => ansiSpinner.ticks < 10); + List lines = outputStdout(); + expect(lines[0], startsWith( + platform.isWindows + ? ' \b\\\b|\b/\b-\b\\\b|\b/\b-' + : ' \b⣽\b⣻\b⢿\b⡿\b⣟\b⣯\b⣷\b⣾\b⣽\b⣻' + ), + ); + expect(lines[0].endsWith('\n'), isFalse); + expect(lines.length, equals(1)); ansiSpinner.stop(); - }, throwsA(isInstanceOf())); - expect(() { - ansiSpinner.cancel(); - }, throwsA(isInstanceOf())); + lines = outputStdout(); + expect(lines[0], endsWith('\b \b')); + expect(lines.length, equals(1)); + + // Verify that stopping or canceling multiple times throws. + expect(() { + ansiSpinner.stop(); + }, throwsA(isInstanceOf())); + expect(() { + ansiSpinner.cancel(); + }, throwsA(isInstanceOf())); + done = true; + }); + expect(done, isTrue); }, overrides: { Platform: () => FakePlatform(operatingSystem: testOs), Stdio: () => mockStdio, }); - testUsingContext('Stdout startProgress handle null inputs on colored terminal for $testOs', () async { - context[Logger].startProgress( - null, - progressId: null, - expectSlowOperation: null, - progressIndicatorPadding: null, - ); - final List lines = outputStdout(); - expect(outputStderr().length, equals(1)); - expect(outputStderr().first, isEmpty); - expect(lines[0], matches(platform.isWindows ? r'[ ]{64} [\b]-' : r'[ ]{64} [\b]⣾')); + testUsingContext('AnsiSpinner works for $testOs', () async { + bool done = false; + // We pad the time here so that we have a little slack in terms of the first part of this test + // taking longer to run than we'd like, since we are forced to start the timer before the actual + // stopwatch that we're trying to test. This is an unfortunate possible race condition. If this + // turns out to be flaky, we will need to find another solution. + final Future tenMillisecondsLater = Future.delayed(const Duration(milliseconds: 15)); + await FakeAsync().run((FakeAsync time) async { + final AnsiSpinner ansiSpinner = AnsiSpinner( + timeout: const Duration(milliseconds: 10), + )..start(); + doWhileAsync(time, () => ansiSpinner.ticks < 10); // one second + expect(ansiSpinner.seemsSlow, isFalse); // ignore: invalid_use_of_protected_member + expect(outputStdout().join('\n'), isNot(contains('This is taking an unexpectedly long time.'))); + await tenMillisecondsLater; + doWhileAsync(time, () => ansiSpinner.ticks < 30); // three seconds + expect(ansiSpinner.seemsSlow, isTrue); // ignore: invalid_use_of_protected_member + expect(outputStdout().join('\n'), contains('This is taking an unexpectedly long time.')); + ansiSpinner.stop(); + expect(outputStdout().join('\n'), isNot(contains('(!)'))); + done = true; + }); + expect(done, isTrue); + }, overrides: { + Platform: () => FakePlatform(operatingSystem: testOs), + Stdio: () => mockStdio, + }); + + testUsingContext('Stdout startProgress on colored terminal for $testOs', () async { + bool done = false; + FakeAsync().run((FakeAsync time) { + final Logger logger = context[Logger]; + final Status status = logger.startProgress( + 'Hello', + progressId: null, + timeout: kSlowOperation, + progressIndicatorPadding: 20, // this minus the "Hello" equals the 15 below. + ); + expect(outputStderr().length, equals(1)); + expect(outputStderr().first, isEmpty); + // the 5 below is the margin that is always included between the message and the time. + expect(outputStdout().join('\n'), matches(platform.isWindows ? r'^Hello {15} {5} {8}[\b]{8} {7}\\$' : + r'^Hello {15} {5} {8}[\b]{8} {7}⣽$')); + status.stop(); + expect(outputStdout().join('\n'), matches(platform.isWindows ? r'^Hello {15} {5} {8}[\b]{8} {7}\\[\b]{8} {8}[\b]{8}[\d, ]{4}[\d]\.[\d]s[\n]$' : + r'^Hello {15} {5} {8}[\b]{8} {7}⣽[\b]{8} {8}[\b]{8}[\d, ]{4}[\d]\.[\d]s[\n]$')); + done = true; + }); + expect(done, isTrue); }, overrides: { Logger: () => StdoutLogger(), OutputPreferences: () => OutputPreferences(showColor: true), @@ -138,58 +181,145 @@ void main() { Stdio: () => mockStdio, }); + testUsingContext('Stdout startProgress on colored terminal pauses on $testOs', () async { + bool done = false; + FakeAsync().run((FakeAsync time) { + final Logger logger = context[Logger]; + final Status status = logger.startProgress( + 'Knock Knock, Who\'s There', + timeout: const Duration(days: 10), + progressIndicatorPadding: 10, + ); + logger.printStatus('Rude Interrupting Cow'); + status.stop(); + final String a = platform.isWindows ? '\\' : '⣽'; + final String b = platform.isWindows ? '|' : '⣻'; + expect( + outputStdout().join('\n'), + 'Knock Knock, Who\'s There ' // initial message + ' ' // placeholder so that spinner can backspace on its first tick + '\b\b\b\b\b\b\b\b $a' // first tick + '\b\b\b\b\b\b\b\b ' // clearing the spinner + '\b\b\b\b\b\b\b\b' // clearing the clearing of the spinner + '\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b ' // clearing the message + '\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b' // clearing the clearing of the message + 'Rude Interrupting Cow\n' // message + 'Knock Knock, Who\'s There ' // message restoration + ' ' // placeholder so that spinner can backspace on its second tick + '\b\b\b\b\b\b\b\b $b' // second tick + '\b\b\b\b\b\b\b\b ' // clearing the spinner to put the time + '\b\b\b\b\b\b\b\b' // clearing the clearing of the spinner + ' 0.0s\n', // replacing it with the time + ); + done = true; + }); + expect(done, isTrue); + }, overrides: { + Logger: () => StdoutLogger(), + OutputPreferences: () => OutputPreferences(showColor: true), + Platform: () => FakePlatform(operatingSystem: testOs)..stdoutSupportsAnsi = true, + Stdio: () => mockStdio, + }); + + testUsingContext('AnsiStatus works for $testOs', () async { + bool done = false; + // We pad the time here so that we have a little slack in terms of the first part of this test + // taking longer to run than we'd like, since we are forced to start the timer before the actual + // stopwatch that we're trying to test. This is an unfortunate possible race condition. If this + // turns out to be flaky, we will need to find another solution. + final Future tenMillisecondsLater = Future.delayed(const Duration(milliseconds: 15)); + await FakeAsync().run((FakeAsync time) async { + ansiStatus.start(); + doWhileAsync(time, () => ansiStatus.ticks < 10); // one second + expect(ansiStatus.seemsSlow, isFalse); // ignore: invalid_use_of_protected_member + expect(outputStdout().join('\n'), isNot(contains('This is taking an unexpectedly long time.'))); + expect(outputStdout().join('\n'), isNot(contains('(!)'))); + await tenMillisecondsLater; + doWhileAsync(time, () => ansiStatus.ticks < 30); // three seconds + expect(ansiStatus.seemsSlow, isTrue); // ignore: invalid_use_of_protected_member + expect(outputStdout().join('\n'), contains('This is taking an unexpectedly long time.')); + ansiStatus.stop(); + expect(outputStdout().join('\n'), contains('(!)')); + done = true; + }); + expect(done, isTrue); + }, overrides: { + Platform: () => FakePlatform(operatingSystem: testOs), + Stdio: () => mockStdio, + }); + testUsingContext('AnsiStatus works when cancelled for $testOs', () async { - ansiStatus.start(); - await doWhileAsync(() => ansiStatus.ticks < 10); - List lines = outputStdout(); - expect(lines[0], startsWith(platform.isWindows - ? 'Hello world \b-\b\\\b|\b/\b-\b\\\b|\b/' - : 'Hello world \b⣾\b⣽\b⣻\b⢿\b⡿\b⣟\b⣯\b⣷\b⣾\b⣽')); - expect(lines.length, equals(1)); - expect(lines[0].endsWith('\n'), isFalse); + bool done = false; + FakeAsync().run((FakeAsync time) { + ansiStatus.start(); + doWhileAsync(time, () => ansiStatus.ticks < 10); + List lines = outputStdout(); + expect(lines[0], startsWith(platform.isWindows + ? 'Hello world \b\b\b\b\b\b\b\b \\\b\b\b\b\b\b\b\b |\b\b\b\b\b\b\b\b /\b\b\b\b\b\b\b\b -\b\b\b\b\b\b\b\b \\\b\b\b\b\b\b\b\b |\b\b\b\b\b\b\b\b /\b\b\b\b\b\b\b\b -\b\b\b\b\b\b\b\b \\\b\b\b\b\b\b\b\b |' + : 'Hello world \b\b\b\b\b\b\b\b ⣽\b\b\b\b\b\b\b\b ⣻\b\b\b\b\b\b\b\b ⢿\b\b\b\b\b\b\b\b ⡿\b\b\b\b\b\b\b\b ⣟\b\b\b\b\b\b\b\b ⣯\b\b\b\b\b\b\b\b ⣷\b\b\b\b\b\b\b\b ⣾\b\b\b\b\b\b\b\b ⣽\b\b\b\b\b\b\b\b ⣻')); + expect(lines.length, equals(1)); + expect(lines[0].endsWith('\n'), isFalse); - // Verify a cancel does _not_ print the time and prints a newline. - ansiStatus.cancel(); - lines = outputStdout(); - final List matches = secondDigits.allMatches(lines[0]).toList(); - expect(matches, isEmpty); - expect(lines[0], endsWith('\b \b')); - expect(called, equals(1)); - expect(lines.length, equals(2)); - expect(lines[1], equals('')); + // Verify a cancel does _not_ print the time and prints a newline. + ansiStatus.cancel(); + lines = outputStdout(); + final List matches = secondDigits.allMatches(lines[0]).toList(); + expect(matches, isEmpty); + final String x = platform.isWindows ? '|' : '⣻'; + expect(lines[0], endsWith('$x\b\b\b\b\b\b\b\b \b\b\b\b\b\b\b\b')); + expect(called, equals(1)); + expect(lines.length, equals(2)); + expect(lines[1], equals('')); - // Verify that stopping or canceling multiple times throws. - expect(() { ansiStatus.cancel(); }, throwsA(isInstanceOf())); - expect(() { ansiStatus.stop(); }, throwsA(isInstanceOf())); + // Verify that stopping or canceling multiple times throws. + expect(() { ansiStatus.cancel(); }, throwsA(isInstanceOf())); + expect(() { ansiStatus.stop(); }, throwsA(isInstanceOf())); + done = true; + }); + expect(done, isTrue); }, overrides: { Platform: () => FakePlatform(operatingSystem: testOs), Stdio: () => mockStdio, }); testUsingContext('AnsiStatus works when stopped for $testOs', () async { - ansiStatus.start(); - await doWhileAsync(() => ansiStatus.ticks < 10); - List lines = outputStdout(); - expect(lines[0], startsWith(platform.isWindows - ? 'Hello world \b-\b\\\b|\b/\b-\b\\\b|\b/' - : 'Hello world \b⣾\b⣽\b⣻\b⢿\b⡿\b⣟\b⣯\b⣷\b⣾\b⣽')); - expect(lines.length, equals(1)); + bool done = false; + FakeAsync().run((FakeAsync time) { + ansiStatus.start(); + doWhileAsync(time, () => ansiStatus.ticks < 10); + List lines = outputStdout(); + expect(lines, hasLength(1)); + expect(lines[0], + platform.isWindows + ? 'Hello world \b\b\b\b\b\b\b\b \\\b\b\b\b\b\b\b\b |\b\b\b\b\b\b\b\b /\b\b\b\b\b\b\b\b -\b\b\b\b\b\b\b\b \\\b\b\b\b\b\b\b\b |\b\b\b\b\b\b\b\b /\b\b\b\b\b\b\b\b -\b\b\b\b\b\b\b\b \\\b\b\b\b\b\b\b\b |' + : 'Hello world \b\b\b\b\b\b\b\b ⣽\b\b\b\b\b\b\b\b ⣻\b\b\b\b\b\b\b\b ⢿\b\b\b\b\b\b\b\b ⡿\b\b\b\b\b\b\b\b ⣟\b\b\b\b\b\b\b\b ⣯\b\b\b\b\b\b\b\b ⣷\b\b\b\b\b\b\b\b ⣾\b\b\b\b\b\b\b\b ⣽\b\b\b\b\b\b\b\b ⣻', + ); - // Verify a stop prints the time. - ansiStatus.stop(); - lines = outputStdout(); - final List matches = secondDigits.allMatches(lines[0]).toList(); - expect(matches, isNotNull); - expect(matches, hasLength(1)); - final Match match = matches.first; - expect(lines[0], endsWith(match.group(0))); - expect(called, equals(1)); - expect(lines.length, equals(2)); - expect(lines[1], equals('')); + // Verify a stop prints the time. + ansiStatus.stop(); + lines = outputStdout(); + expect(lines, hasLength(2)); + expect(lines[0], matches( + platform.isWindows + ? r'Hello world {8}[\b]{8} {7}\\[\b]{8} {7}|[\b]{8} {7}/[\b]{8} {7}-[\b]{8} {7}\\[\b]{8} {7}|[\b]{8} {7}/[\b]{8} {7}-[\b]{8} {7}\\[\b]{8} {7}|[\b]{8} {7} [\b]{8}[\d., ]{6}[\d]ms$' + : r'Hello world {8}[\b]{8} {7}⣽[\b]{8} {7}⣻[\b]{8} {7}⢿[\b]{8} {7}⡿[\b]{8} {7}⣟[\b]{8} {7}⣯[\b]{8} {7}⣷[\b]{8} {7}⣾[\b]{8} {7}⣽[\b]{8} {7}⣻[\b]{8} {7} [\b]{8}[\d., ]{5}[\d]ms$' + )); + expect(lines[1], isEmpty); + final List times = secondDigits.allMatches(lines[0]).toList(); + expect(times, isNotNull); + expect(times, hasLength(1)); + final Match match = times.single; + expect(lines[0], endsWith(match.group(0))); + expect(called, equals(1)); + expect(lines.length, equals(2)); + expect(lines[1], equals('')); - // Verify that stopping or canceling multiple times throws. - expect(() { ansiStatus.stop(); }, throwsA(isInstanceOf())); - expect(() { ansiStatus.cancel(); }, throwsA(isInstanceOf())); + // Verify that stopping or canceling multiple times throws. + expect(() { ansiStatus.stop(); }, throwsA(isInstanceOf())); + expect(() { ansiStatus.cancel(); }, throwsA(isInstanceOf())); + done = true; + }); + expect(done, isTrue); }, overrides: { Platform: () => FakePlatform(operatingSystem: testOs), Stdio: () => mockStdio, @@ -207,7 +337,7 @@ void main() { called = 0; summaryStatus = SummaryStatus( message: 'Hello world', - expectSlowOperation: true, + timeout: kSlowOperation, padding: 20, onFinish: () => called++, ); @@ -217,7 +347,8 @@ void main() { List outputStderr() => mockStdio.writtenToStderr.join('').split('\n'); testUsingContext('Error logs are wrapped', () async { - context[Logger].printError('0123456789' * 15); + final Logger logger = context[Logger]; + logger.printError('0123456789' * 15); final List lines = outputStderr(); expect(outputStdout().length, equals(1)); expect(outputStdout().first, isEmpty); @@ -233,7 +364,8 @@ void main() { }); testUsingContext('Error logs are wrapped and can be indented.', () async { - context[Logger].printError('0123456789' * 15, indent: 5); + final Logger logger = context[Logger]; + logger.printError('0123456789' * 15, indent: 5); final List lines = outputStderr(); expect(outputStdout().length, equals(1)); expect(outputStdout().first, isEmpty); @@ -252,7 +384,8 @@ void main() { }); testUsingContext('Error logs are wrapped and can have hanging indent.', () async { - context[Logger].printError('0123456789' * 15, hangingIndent: 5); + final Logger logger = context[Logger]; + logger.printError('0123456789' * 15, hangingIndent: 5); final List lines = outputStderr(); expect(outputStdout().length, equals(1)); expect(outputStdout().first, isEmpty); @@ -271,7 +404,8 @@ void main() { }); testUsingContext('Error logs are wrapped, indented, and can have hanging indent.', () async { - context[Logger].printError('0123456789' * 15, indent: 4, hangingIndent: 5); + final Logger logger = context[Logger]; + logger.printError('0123456789' * 15, indent: 4, hangingIndent: 5); final List lines = outputStderr(); expect(outputStdout().length, equals(1)); expect(outputStdout().first, isEmpty); @@ -290,7 +424,8 @@ void main() { }); testUsingContext('Stdout logs are wrapped', () async { - context[Logger].printStatus('0123456789' * 15); + final Logger logger = context[Logger]; + logger.printStatus('0123456789' * 15); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -306,7 +441,8 @@ void main() { }); testUsingContext('Stdout logs are wrapped and can be indented.', () async { - context[Logger].printStatus('0123456789' * 15, indent: 5); + final Logger logger = context[Logger]; + logger.printStatus('0123456789' * 15, indent: 5); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -325,7 +461,8 @@ void main() { }); testUsingContext('Stdout logs are wrapped and can have hanging indent.', () async { - context[Logger].printStatus('0123456789' * 15, hangingIndent: 5); + final Logger logger = context[Logger]; + logger.printStatus('0123456789' * 15, hangingIndent: 5); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -344,7 +481,8 @@ void main() { }); testUsingContext('Stdout logs are wrapped, indented, and can have hanging indent.', () async { - context[Logger].printStatus('0123456789' * 15, indent: 4, hangingIndent: 5); + final Logger logger = context[Logger]; + logger.printStatus('0123456789' * 15, indent: 4, hangingIndent: 5); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -363,7 +501,8 @@ void main() { }); testUsingContext('Error logs are red', () async { - context[Logger].printError('Pants on fire!'); + final Logger logger = context[Logger]; + logger.printError('Pants on fire!'); final List lines = outputStderr(); expect(outputStdout().length, equals(1)); expect(outputStdout().first, isEmpty); @@ -376,7 +515,8 @@ void main() { }); testUsingContext('Stdout logs are not colored', () async { - context[Logger].printStatus('All good.'); + final Logger logger = context[Logger]; + logger.printStatus('All good.'); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -388,7 +528,14 @@ void main() { }); testUsingContext('Stdout printStatus handle null inputs on colored terminal', () async { - context[Logger].printStatus(null, emphasis: null, color: null, newline: null, indent: null); + final Logger logger = context[Logger]; + logger.printStatus( + null, + emphasis: null, + color: null, + newline: null, + indent: null, + ); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -399,8 +546,15 @@ void main() { Stdio: () => mockStdio, }); - testUsingContext('Stdout printStatus handle null inputs on regular terminal', () async { - context[Logger].printStatus(null, emphasis: null, color: null, newline: null, indent: null); + testUsingContext('Stdout printStatus handle null inputs on non-color terminal', () async { + final Logger logger = context[Logger]; + logger.printStatus( + null, + emphasis: null, + color: null, + newline: null, + indent: null, + ); final List lines = outputStdout(); expect(outputStderr().length, equals(1)); expect(outputStderr().first, isEmpty); @@ -412,17 +566,27 @@ void main() { Platform: _kNoAnsiPlatform, }); - testUsingContext('Stdout startProgress handle null inputs on regular terminal', () async { - context[Logger].startProgress( - null, - progressId: null, - expectSlowOperation: null, - progressIndicatorPadding: null, - ); - final List lines = outputStdout(); - expect(outputStderr().length, equals(1)); - expect(outputStderr().first, isEmpty); - expect(lines[0], matches('[ ]{64}')); + testUsingContext('Stdout startProgress on non-color terminal', () async { + bool done = false; + FakeAsync().run((FakeAsync time) { + final Logger logger = context[Logger]; + final Status status = logger.startProgress( + 'Hello', + progressId: null, + timeout: kSlowOperation, + progressIndicatorPadding: 20, // this minus the "Hello" equals the 15 below. + ); + expect(outputStderr().length, equals(1)); + expect(outputStderr().first, isEmpty); + // the 5 below is the margin that is always included between the message and the time. + expect(outputStdout().join('\n'), matches(platform.isWindows ? r'^Hello {15} {5}$' : + r'^Hello {15} {5}$')); + status.stop(); + expect(outputStdout().join('\n'), matches(platform.isWindows ? r'^Hello {15} {5}[\d, ]{4}[\d]\.[\d]s[\n]$' : + r'^Hello {15} {5}[\d, ]{4}[\d]\.[\d]s[\n]$')); + done = true; + }); + expect(done, isTrue); }, overrides: { Logger: () => StdoutLogger(), OutputPreferences: () => OutputPreferences(showColor: false), @@ -476,11 +640,16 @@ void main() { }, overrides: {Stdio: () => mockStdio, Platform: _kNoAnsiPlatform}); testUsingContext('sequential startProgress calls with StdoutLogger', () async { - context[Logger].startProgress('AAA')..stop(); - context[Logger].startProgress('BBB')..stop(); - expect(outputStdout().length, equals(3)); - expect(outputStdout()[0], matches(RegExp(r'AAA[ ]{60}[\d ]{3}[\d]ms'))); - expect(outputStdout()[1], matches(RegExp(r'BBB[ ]{60}[\d ]{3}[\d]ms'))); + final Logger logger = context[Logger]; + logger.startProgress('AAA', timeout: kFastOperation)..stop(); + logger.startProgress('BBB', timeout: kFastOperation)..stop(); + final List output = outputStdout(); + expect(output.length, equals(3)); + // There's 61 spaces at the start: 59 (padding default) - 3 (length of AAA) + 5 (margin). + // Then there's a left-padded "0ms" 8 characters wide, so 5 spaces then "0ms" + // (except sometimes it's randomly slow so we handle up to "99,999ms"). + expect(output[0], matches(RegExp(r'AAA[ ]{61}[\d, ]{5}[\d]ms'))); + expect(output[1], matches(RegExp(r'BBB[ ]{61}[\d, ]{5}[\d]ms'))); }, overrides: { Logger: () => StdoutLogger(), OutputPreferences: () => OutputPreferences(showColor: false), @@ -489,13 +658,14 @@ void main() { }); testUsingContext('sequential startProgress calls with VerboseLogger and StdoutLogger', () async { - context[Logger].startProgress('AAA')..stop(); - context[Logger].startProgress('BBB')..stop(); + final Logger logger = context[Logger]; + logger.startProgress('AAA', timeout: kFastOperation)..stop(); + logger.startProgress('BBB', timeout: kFastOperation)..stop(); expect(outputStdout(), [ matches(r'^\[ (?: {0,2}\+[0-9]{1,3} ms| )\] AAA$'), - matches(r'^\[ (?: {0,2}\+[0-9]{1,3} ms| )\] AAA \(completed\)$'), + matches(r'^\[ (?: {0,2}\+[0-9]{1,3} ms| )\] AAA \(completed.*\)$'), matches(r'^\[ (?: {0,2}\+[0-9]{1,3} ms| )\] BBB$'), - matches(r'^\[ (?: {0,2}\+[0-9]{1,3} ms| )\] BBB \(completed\)$'), + matches(r'^\[ (?: {0,2}\+[0-9]{1,3} ms| )\] BBB \(completed.*\)$'), matches(r'^$'), ]); }, overrides: { @@ -505,9 +675,9 @@ void main() { }); testUsingContext('sequential startProgress calls with BufferLogger', () async { - context[Logger].startProgress('AAA')..stop(); - context[Logger].startProgress('BBB')..stop(); final BufferLogger logger = context[Logger]; + logger.startProgress('AAA', timeout: kFastOperation)..stop(); + logger.startProgress('BBB', timeout: kFastOperation)..stop(); expect(logger.statusText, 'AAA\nBBB\n'); }, overrides: { Logger: () => BufferLogger(), diff --git a/packages/flutter_tools/test/base/terminal_test.dart b/packages/flutter_tools/test/base/terminal_test.dart index 5b72f09b52d..d5b4ef7c506 100644 --- a/packages/flutter_tools/test/base/terminal_test.dart +++ b/packages/flutter_tools/test/base/terminal_test.dart @@ -165,7 +165,7 @@ Stream mockStdInStream; class TestTerminal extends AnsiTerminal { @override - Stream get onCharInput { + Stream get keystrokes { return mockStdInStream; } } diff --git a/packages/flutter_tools/test/commands/attach_test.dart b/packages/flutter_tools/test/commands/attach_test.dart index 064a7e6276c..68de5038cb6 100644 --- a/packages/flutter_tools/test/commands/attach_test.dart +++ b/packages/flutter_tools/test/commands/attach_test.dart @@ -7,12 +7,15 @@ import 'dart:async'; import 'package:file/memory.dart'; import 'package:flutter_tools/src/base/common.dart'; import 'package:flutter_tools/src/base/file_system.dart'; +import 'package:flutter_tools/src/base/logger.dart'; import 'package:flutter_tools/src/base/platform.dart'; +import 'package:flutter_tools/src/base/terminal.dart'; import 'package:flutter_tools/src/cache.dart'; import 'package:flutter_tools/src/commands/attach.dart'; import 'package:flutter_tools/src/device.dart'; import 'package:flutter_tools/src/resident_runner.dart'; import 'package:flutter_tools/src/run_hot.dart'; +import 'package:meta/meta.dart'; import 'package:mockito/mockito.dart'; import '../src/common.dart'; @@ -20,6 +23,7 @@ import '../src/context.dart'; import '../src/mocks.dart'; void main() { + final StreamLogger logger = StreamLogger(); group('attach', () { final FileSystem testFileSystem = MemoryFileSystem( style: platform.isWindows ? FileSystemStyle.windows : FileSystemStyle @@ -48,18 +52,19 @@ void main() { // Now that the reader is used, start writing messages to it. Timer.run(() { mockLogReader.addLine('Foo'); - mockLogReader.addLine( - 'Observatory listening on http://127.0.0.1:$devicePort'); + mockLogReader.addLine('Observatory listening on http://127.0.0.1:$devicePort'); }); return mockLogReader; }); - when(device.portForwarder).thenReturn(portForwarder); + when(device.portForwarder) + .thenReturn(portForwarder); when(portForwarder.forward(devicePort, hostPort: anyNamed('hostPort'))) - .thenAnswer((_) async => hostPort); - when(portForwarder.forwardedPorts).thenReturn( - [ForwardedPort(hostPort, devicePort)]); - when(portForwarder.unforward(any)).thenAnswer((_) async => null); + .thenAnswer((_) async => hostPort); + when(portForwarder.forwardedPorts) + .thenReturn([ForwardedPort(hostPort, devicePort)]); + when(portForwarder.unforward(any)) + .thenAnswer((_) async => null); // We cannot add the device to a device manager because that is // only enabled by the context of each testUsingContext call. @@ -74,16 +79,23 @@ void main() { testUsingContext('finds observatory port and forwards', () async { testDeviceManager.addDevice(device); - - final AttachCommand command = AttachCommand(); - - await createTestCommandRunner(command).run(['attach']); - + final Completer completer = Completer(); + final StreamSubscription loggerSubscription = logger.stream.listen((String message) { + if (message == '[stdout] Done.') { + // The "Done." message is output by the AttachCommand when it's done. + completer.complete(); + } + }); + final Future task = createTestCommandRunner(AttachCommand()).run(['attach']); + await completer.future; verify( portForwarder.forward(devicePort, hostPort: anyNamed('hostPort')), ).called(1); + await expectLoggerInterruptEndsTask(task, logger); + await loggerSubscription.cancel(); }, overrides: { FileSystem: () => testFileSystem, + Logger: () => logger, }); testUsingContext('accepts filesystem parameters', () async { @@ -94,6 +106,9 @@ void main() { const String projectRoot = '/build-output/project-root'; const String outputDill = '/tmp/output.dill'; + final MockHotRunner mockHotRunner = MockHotRunner(); + when(mockHotRunner.attach()).thenAnswer((_) async => 0); + final MockHotRunnerFactory mockHotRunnerFactory = MockHotRunnerFactory(); when( mockHotRunnerFactory.build( @@ -106,7 +121,7 @@ void main() { usesTerminalUI: anyNamed('usesTerminalUI'), ipv6: false, ), - )..thenReturn(MockHotRunner()); + ).thenReturn(mockHotRunner); final AttachCommand command = AttachCommand( hotRunnerFactory: mockHotRunnerFactory, @@ -121,7 +136,7 @@ void main() { projectRoot, '--output-dill', outputDill, - '-v', + '-v', // enables verbose logging ]); // Validate the attach call built a mock runner with the right @@ -191,30 +206,36 @@ void main() { final MockDeviceLogReader mockLogReader = MockDeviceLogReader(); final MockPortForwarder portForwarder = MockPortForwarder(); final MockAndroidDevice device = MockAndroidDevice(); + final MockHotRunner mockHotRunner = MockHotRunner(); final MockHotRunnerFactory mockHotRunnerFactory = MockHotRunnerFactory(); - when(device.portForwarder).thenReturn(portForwarder); + when(device.portForwarder) + .thenReturn(portForwarder); when(portForwarder.forward(devicePort, hostPort: anyNamed('hostPort'))) - .thenAnswer((_) async => hostPort); - when(portForwarder.forwardedPorts).thenReturn( - [ForwardedPort(hostPort, devicePort)]); - when(portForwarder.unforward(any)).thenAnswer((_) async => null); - when(mockHotRunnerFactory.build(any, - target: anyNamed('target'), - debuggingOptions: anyNamed('debuggingOptions'), - packagesFilePath: anyNamed('packagesFilePath'), - usesTerminalUI: anyNamed('usesTerminalUI'), - ipv6: false)).thenReturn( - MockHotRunner()); + .thenAnswer((_) async => hostPort); + when(portForwarder.forwardedPorts) + .thenReturn([ForwardedPort(hostPort, devicePort)]); + when(portForwarder.unforward(any)) + .thenAnswer((_) async => null); + when(mockHotRunner.attach()) + .thenAnswer((_) async => 0); + when(mockHotRunnerFactory.build( + any, + target: anyNamed('target'), + debuggingOptions: anyNamed('debuggingOptions'), + packagesFilePath: anyNamed('packagesFilePath'), + usesTerminalUI: anyNamed('usesTerminalUI'), + ipv6: false, + )).thenReturn(mockHotRunner); testDeviceManager.addDevice(device); - when(device.getLogReader()).thenAnswer((_) { - // Now that the reader is used, start writing messages to it. - Timer.run(() { - mockLogReader.addLine('Foo'); - mockLogReader.addLine( - 'Observatory listening on http://127.0.0.1:$devicePort'); - }); - + when(device.getLogReader()) + .thenAnswer((_) { + // Now that the reader is used, start writing messages to it. + Timer.run(() { + mockLogReader.addLine('Foo'); + mockLogReader.addLine( + 'Observatory listening on http://127.0.0.1:$devicePort'); + }); return mockLogReader; }); final File foo = fs.file('lib/foo.dart') @@ -223,20 +244,20 @@ void main() { // Delete the main.dart file to be sure that attach works without it. fs.file('lib/main.dart').deleteSync(); - final AttachCommand command = AttachCommand( - hotRunnerFactory: mockHotRunnerFactory); - await createTestCommandRunner(command).run( - ['attach', '-t', foo.path, '-v']); + final AttachCommand command = AttachCommand(hotRunnerFactory: mockHotRunnerFactory); + await createTestCommandRunner(command).run(['attach', '-t', foo.path, '-v']); - verify(mockHotRunnerFactory.build(any, - target: foo.path, - debuggingOptions: anyNamed('debuggingOptions'), - packagesFilePath: anyNamed('packagesFilePath'), - usesTerminalUI: anyNamed('usesTerminalUI'), - ipv6: false)).called(1); + verify(mockHotRunnerFactory.build( + any, + target: foo.path, + debuggingOptions: anyNamed('debuggingOptions'), + packagesFilePath: anyNamed('packagesFilePath'), + usesTerminalUI: anyNamed('usesTerminalUI'), + ipv6: false, + )).called(1); }, overrides: { FileSystem: () => testFileSystem, - },); + }); group('forwarding to given port', () { const int devicePort = 499; @@ -248,74 +269,121 @@ void main() { portForwarder = MockPortForwarder(); device = MockAndroidDevice(); - when(device.portForwarder).thenReturn(portForwarder); - when(portForwarder.forward(devicePort)).thenAnswer((_) async => hostPort); - when(portForwarder.forwardedPorts).thenReturn( - [ForwardedPort(hostPort, devicePort)]); - when(portForwarder.unforward(any)).thenAnswer((_) async => null); + when(device.portForwarder) + .thenReturn(portForwarder); + when(portForwarder.forward(devicePort)) + .thenAnswer((_) async => hostPort); + when(portForwarder.forwardedPorts) + .thenReturn([ForwardedPort(hostPort, devicePort)]); + when(portForwarder.unforward(any)) + .thenAnswer((_) async => null); }); testUsingContext('succeeds in ipv4 mode', () async { testDeviceManager.addDevice(device); - final AttachCommand command = AttachCommand(); - - await createTestCommandRunner(command).run( - ['attach', '--debug-port', '$devicePort']); + final Completer completer = Completer(); + final StreamSubscription loggerSubscription = logger.stream.listen((String message) { + if (message == '[verbose] Connecting to service protocol: http://127.0.0.1:42/') { + // Wait until resident_runner.dart tries to connect. + // There's nothing to connect _to_, so that's as far as we care to go. + completer.complete(); + } + }); + final Future task = createTestCommandRunner(AttachCommand()) + .run(['attach', '--debug-port', '$devicePort']); + await completer.future; verify(portForwarder.forward(devicePort)).called(1); + + await expectLoggerInterruptEndsTask(task, logger); + await loggerSubscription.cancel(); }, overrides: { FileSystem: () => testFileSystem, + Logger: () => logger, }); testUsingContext('succeeds in ipv6 mode', () async { testDeviceManager.addDevice(device); - final AttachCommand command = AttachCommand(); - - await createTestCommandRunner(command).run( - ['attach', '--debug-port', '$devicePort', '--ipv6']); + final Completer completer = Completer(); + final StreamSubscription loggerSubscription = logger.stream.listen((String message) { + if (message == '[verbose] Connecting to service protocol: http://[::1]:42/') { + // Wait until resident_runner.dart tries to connect. + // There's nothing to connect _to_, so that's as far as we care to go. + completer.complete(); + } + }); + final Future task = createTestCommandRunner(AttachCommand()) + .run(['attach', '--debug-port', '$devicePort', '--ipv6']); + await completer.future; verify(portForwarder.forward(devicePort)).called(1); + + await expectLoggerInterruptEndsTask(task, logger); + await loggerSubscription.cancel(); }, overrides: { FileSystem: () => testFileSystem, + Logger: () => logger, }); testUsingContext('skips in ipv4 mode with a provided observatory port', () async { testDeviceManager.addDevice(device); - final AttachCommand command = AttachCommand(); - await createTestCommandRunner(command).run( - [ - 'attach', - '--debug-port', - '$devicePort', - '--observatory-port', - '$hostPort', - ], + final Completer completer = Completer(); + final StreamSubscription loggerSubscription = logger.stream.listen((String message) { + if (message == '[verbose] Connecting to service protocol: http://127.0.0.1:42/') { + // Wait until resident_runner.dart tries to connect. + // There's nothing to connect _to_, so that's as far as we care to go. + completer.complete(); + } + }); + final Future task = createTestCommandRunner(AttachCommand()).run( + [ + 'attach', + '--debug-port', + '$devicePort', + '--observatory-port', + '$hostPort', + ], ); - + await completer.future; verifyNever(portForwarder.forward(devicePort)); + + await expectLoggerInterruptEndsTask(task, logger); + await loggerSubscription.cancel(); }, overrides: { FileSystem: () => testFileSystem, + Logger: () => logger, }); testUsingContext('skips in ipv6 mode with a provided observatory port', () async { testDeviceManager.addDevice(device); - final AttachCommand command = AttachCommand(); - await createTestCommandRunner(command).run( - [ - 'attach', - '--debug-port', - '$devicePort', - '--observatory-port', - '$hostPort', - '--ipv6', - ], + final Completer completer = Completer(); + final StreamSubscription loggerSubscription = logger.stream.listen((String message) { + if (message == '[verbose] Connecting to service protocol: http://[::1]:42/') { + // Wait until resident_runner.dart tries to connect. + // There's nothing to connect _to_, so that's as far as we care to go. + completer.complete(); + } + }); + final Future task = createTestCommandRunner(AttachCommand()).run( + [ + 'attach', + '--debug-port', + '$devicePort', + '--observatory-port', + '$hostPort', + '--ipv6', + ], ); - + await completer.future; verifyNever(portForwarder.forward(devicePort)); + + await expectLoggerInterruptEndsTask(task, logger); + await loggerSubscription.cancel(); }, overrides: { FileSystem: () => testFileSystem, + Logger: () => logger, }); }); @@ -328,7 +396,7 @@ void main() { expect(testLogger.statusText, contains('No connected devices')); }, overrides: { FileSystem: () => testFileSystem, - },); + }); testUsingContext('exits when multiple devices connected', () async { Device aDeviceWithId(String id) { @@ -352,7 +420,7 @@ void main() { expect(testLogger.statusText, contains('yy2')); }, overrides: { FileSystem: () => testFileSystem, - },); + }); }); } @@ -361,3 +429,83 @@ class MockPortForwarder extends Mock implements DevicePortForwarder {} class MockHotRunner extends Mock implements HotRunner {} class MockHotRunnerFactory extends Mock implements HotRunnerFactory {} + +class StreamLogger extends Logger { + @override + bool get isVerbose => true; + + @override + void printError( + String message, { + StackTrace stackTrace, + bool emphasis, + TerminalColor color, + int indent, + int hangingIndent, + bool wrap, + }) { + _log('[stderr] $message'); + } + + @override + void printStatus( + String message, { + bool emphasis, + TerminalColor color, + bool newline, + int indent, + int hangingIndent, + bool wrap, + }) { + _log('[stdout] $message'); + } + + @override + void printTrace(String message) { + _log('[verbose] $message'); + } + + @override + Status startProgress( + String message, { + @required Duration timeout, + String progressId, + bool multilineOutput = false, + int progressIndicatorPadding = kDefaultStatusPadding, + }) { + _log('[progress] $message'); + return SilentStatus(timeout: timeout)..start(); + } + + bool _interrupt = false; + + void interrupt() { + _interrupt = true; + } + + final StreamController _controller = StreamController.broadcast(); + + void _log(String message) { + _controller.add(message); + if (_interrupt) { + _interrupt = false; + throw const LoggerInterrupted(); + } + } + + Stream get stream => _controller.stream; +} + +class LoggerInterrupted implements Exception { + const LoggerInterrupted(); +} + +Future expectLoggerInterruptEndsTask(Future task, StreamLogger logger) async { + logger.interrupt(); // an exception during the task should cause it to fail... + try { + await task; + expect(false, isTrue); // (shouldn't reach here) + } on ToolExit catch (error) { + expect(error.exitCode, 2); // ...with exit code 2. + } +} diff --git a/packages/flutter_tools/test/integration/daemon_mode_test.dart b/packages/flutter_tools/test/integration/daemon_mode_test.dart index f28e5e894bd..8771b602fb0 100644 --- a/packages/flutter_tools/test/integration/daemon_mode_test.dart +++ b/packages/flutter_tools/test/integration/daemon_mode_test.dart @@ -90,5 +90,5 @@ void main() { expect(result, isList); expect(result, isNotEmpty); }); - }, timeout: const Timeout.factor(2)); + }, timeout: const Timeout.factor(10)); // This test uses the `flutter` tool, which could be blocked behind the startup lock for a long time. } diff --git a/packages/flutter_tools/test/integration/debugger_stepping_test.dart b/packages/flutter_tools/test/integration/debugger_stepping_test.dart index acfded340e6..4173d1077a9 100644 --- a/packages/flutter_tools/test/integration/debugger_stepping_test.dart +++ b/packages/flutter_tools/test/integration/debugger_stepping_test.dart @@ -28,13 +28,15 @@ void main() { }); test('can step over statements', () async { - await _flutter.run(withDebugger: true); + await _flutter.run(withDebugger: true, startPaused: true); + await _flutter.addBreakpoint(_project.breakpointUri, _project.breakpointLine); + await _flutter.resume(); + await _flutter.waitForPause(); // Now we should be on the breakpoint. - // Stop at the initial breakpoint that the expected steps are based on. - await _flutter.breakAt(_project.breakpointUri, _project.breakpointLine, restart: true); + expect((await _flutter.getSourceLocation()).line, equals(_project.breakpointLine)); // Issue 5 steps, ensuring that we end up on the annotated lines each time. - for (int i = 1; i <= _project.numberOfSteps; i++) { + for (int i = 1; i <= _project.numberOfSteps; i += 1) { await _flutter.stepOverOrOverAsyncSuspension(); final SourcePosition location = await _flutter.getSourceLocation(); final int actualLine = location.line; @@ -47,5 +49,5 @@ void main() { reason: 'After $i steps, debugger should stop at $expectedLine but stopped at $actualLine'); } }); - }, timeout: const Timeout.factor(3)); + }, timeout: const Timeout.factor(10)); // The DevFS sync takes a really long time, so these tests can be slow. } diff --git a/packages/flutter_tools/test/integration/expression_evaluation_test.dart b/packages/flutter_tools/test/integration/expression_evaluation_test.dart index 53eaa95ccc3..b736a00f5f6 100644 --- a/packages/flutter_tools/test/integration/expression_evaluation_test.dart +++ b/packages/flutter_tools/test/integration/expression_evaluation_test.dart @@ -32,16 +32,18 @@ void main() { tryToDelete(tempDir); }); - Future breakInBuildMethod(FlutterTestDriver flutter) async { - return _flutter.breakAt( - _project.buildMethodBreakpointUri, - _project.buildMethodBreakpointLine); + Future breakInBuildMethod(FlutterTestDriver flutter) async { + await _flutter.breakAt( + _project.buildMethodBreakpointUri, + _project.buildMethodBreakpointLine, + ); } - Future breakInTopLevelFunction(FlutterTestDriver flutter) async { - return _flutter.breakAt( - _project.topLevelFunctionBreakpointUri, - _project.topLevelFunctionBreakpointLine); + Future breakInTopLevelFunction(FlutterTestDriver flutter) async { + await _flutter.breakAt( + _project.topLevelFunctionBreakpointUri, + _project.topLevelFunctionBreakpointLine, + ); } test('can evaluate trivial expressions in top level function', () async { @@ -79,7 +81,7 @@ void main() { await breakInBuildMethod(_flutter); await evaluateComplexReturningExpressions(_flutter); }); - }, timeout: const Timeout.factor(6)); + }, timeout: const Timeout.factor(10)); // The DevFS sync takes a really long time, so these tests can be slow. group('flutter test expression evaluation', () { Directory tempDir; @@ -124,7 +126,7 @@ void main() { await evaluateComplexReturningExpressions(_flutter); }); // Skipped due to https://github.com/flutter/flutter/issues/26518 - }, timeout: const Timeout.factor(6)); + }, timeout: const Timeout.factor(10), skip: true); // The DevFS sync takes a really long time, so these tests can be slow. } Future evaluateTrivialExpressions(FlutterTestDriver flutter) async { diff --git a/packages/flutter_tools/test/integration/flutter_attach_test.dart b/packages/flutter_tools/test/integration/flutter_attach_test.dart index 0a184c3a8bf..1b5ac6a5b93 100644 --- a/packages/flutter_tools/test/integration/flutter_attach_test.dart +++ b/packages/flutter_tools/test/integration/flutter_attach_test.dart @@ -18,8 +18,8 @@ void main() { setUp(() async { tempDir = createResolvedTempDirectorySync('attach_test.'); await _project.setUpIn(tempDir); - _flutterRun = FlutterRunTestDriver(tempDir, logPrefix: 'RUN'); - _flutterAttach = FlutterRunTestDriver(tempDir, logPrefix: 'ATTACH'); + _flutterRun = FlutterRunTestDriver(tempDir, logPrefix: ' RUN '); + _flutterAttach = FlutterRunTestDriver(tempDir, logPrefix: 'ATTACH '); }); tearDown(() async { @@ -58,5 +58,5 @@ void main() { await _flutterAttach.attach(_flutterRun.vmServicePort); await _flutterAttach.hotReload(); }); - }, timeout: const Timeout.factor(6)); + }, timeout: const Timeout.factor(10)); // The DevFS sync takes a really long time, so these tests can be slow. } diff --git a/packages/flutter_tools/test/integration/flutter_run_test.dart b/packages/flutter_tools/test/integration/flutter_run_test.dart index 72b8e19f44a..f225533f15e 100644 --- a/packages/flutter_tools/test/integration/flutter_run_test.dart +++ b/packages/flutter_tools/test/integration/flutter_run_test.dart @@ -55,5 +55,5 @@ void main() { await _flutter.run(pidFile: pidFile); expect(pidFile.existsSync(), isTrue); }); - }, timeout: const Timeout.factor(6)); + }, timeout: const Timeout.factor(10)); // The DevFS sync takes a really long time, so these tests can be slow. } diff --git a/packages/flutter_tools/test/integration/hot_reload_test.dart b/packages/flutter_tools/test/integration/hot_reload_test.dart index d4edd4f3e39..ee0e66b0563 100644 --- a/packages/flutter_tools/test/integration/hot_reload_test.dart +++ b/packages/flutter_tools/test/integration/hot_reload_test.dart @@ -14,7 +14,7 @@ import 'test_driver.dart'; import 'test_utils.dart'; void main() { - group('hot', () { + group('hot reload tests', () { Directory tempDir; final HotReloadProject _project = HotReloadProject(); FlutterRunTestDriver _flutter; @@ -26,39 +26,127 @@ void main() { }); tearDown(() async { - await _flutter.stop(); + await _flutter?.stop(); tryToDelete(tempDir); }); - test('reload works without error', () async { + test('hot reload works without error', () async { await _flutter.run(); await _flutter.hotReload(); }); - test('newly added code executes during reload', () async { + test('newly added code executes during hot reload', () async { await _flutter.run(); _project.uncommentHotReloadPrint(); final StringBuffer stdout = StringBuffer(); - final StreamSubscription sub = _flutter.stdout.listen(stdout.writeln); + final StreamSubscription subscription = _flutter.stdout.listen(stdout.writeln); try { await _flutter.hotReload(); expect(stdout.toString(), contains('(((((RELOAD WORKED)))))')); } finally { - await sub.cancel(); + await subscription.cancel(); } }); - test('restart works without error', () async { + test('hot restart works without error', () async { await _flutter.run(); await _flutter.hotRestart(); }); - test('reload hits breakpoints after reload', () async { - await _flutter.run(withDebugger: true); - final Isolate isolate = await _flutter.breakAt( - _project.breakpointUri, - _project.breakpointLine); + test('breakpoints are hit after hot reload', () async { + Isolate isolate; + await _flutter.run(withDebugger: true, startPaused: true); + final Completer sawTick1 = Completer(); + final Completer sawTick3 = Completer(); + final Completer sawDebuggerPausedMessage = Completer(); + final StreamSubscription subscription = _flutter.stdout.listen( + (String line) { + if (line.contains('((((TICK 1))))')) { + expect(sawTick1.isCompleted, isFalse); + sawTick1.complete(); + } + if (line.contains('((((TICK 3))))')) { + expect(sawTick3.isCompleted, isFalse); + sawTick3.complete(); + } + if (line.contains('The application is paused in the debugger on a breakpoint.')) { + expect(sawDebuggerPausedMessage.isCompleted, isFalse); + sawDebuggerPausedMessage.complete(); + } + }, + ); + await _flutter.resume(); // we start paused so we can set up our TICK 1 listener before the app starts + sawTick1.future.timeout( // ignore: unawaited_futures + const Duration(seconds: 5), + onTimeout: () { print('The test app is taking longer than expected to print its synchronization line...'); }, + ); + await sawTick1.future; // after this, app is in steady state + await _flutter.addBreakpoint( + _project.scheduledBreakpointUri, + _project.scheduledBreakpointLine, + ); + await _flutter.hotReload(); // reload triggers code which eventually hits the breakpoint + isolate = await _flutter.waitForPause(); expect(isolate.pauseEvent.kind, equals(EventKind.kPauseBreakpoint)); + await _flutter.resume(); + await _flutter.addBreakpoint( + _project.buildBreakpointUri, + _project.buildBreakpointLine, + ); + bool reloaded = false; + final Future reloadFuture = _flutter.hotReload().then((void value) { reloaded = true; }); + await sawTick3.future; // this should happen before it pauses + isolate = await _flutter.waitForPause(); + expect(isolate.pauseEvent.kind, equals(EventKind.kPauseBreakpoint)); + await sawDebuggerPausedMessage.future; + expect(reloaded, isFalse); + await _flutter.resume(); + await reloadFuture; + expect(reloaded, isTrue); + reloaded = false; + await subscription.cancel(); }); - }, timeout: const Timeout.factor(6)); + + test('hot reload doesn\'t reassemble if paused', () async { + await _flutter.run(withDebugger: true); + final Completer sawTick2 = Completer(); + final Completer sawTick3 = Completer(); + final Completer sawDebuggerPausedMessage1 = Completer(); + final Completer sawDebuggerPausedMessage2 = Completer(); + final StreamSubscription subscription = _flutter.stdout.listen( + (String line) { + if (line.contains('((((TICK 2))))')) { + expect(sawTick2.isCompleted, isFalse); + sawTick2.complete(); + } + if (line.contains('The application is paused in the debugger on a breakpoint.')) { + expect(sawDebuggerPausedMessage1.isCompleted, isFalse); + sawDebuggerPausedMessage1.complete(); + } + if (line.contains('The application is paused in the debugger on a breakpoint; interface might not update.')) { + expect(sawDebuggerPausedMessage2.isCompleted, isFalse); + sawDebuggerPausedMessage2.complete(); + } + }, + ); + await _flutter.addBreakpoint( + _project.buildBreakpointUri, + _project.buildBreakpointLine, + ); + bool reloaded = false; + final Future reloadFuture = _flutter.hotReload().then((void value) { reloaded = true; }); + await sawTick2.future; // this should happen before it pauses + final Isolate isolate = await _flutter.waitForPause(); + expect(isolate.pauseEvent.kind, equals(EventKind.kPauseBreakpoint)); + expect(reloaded, isFalse); + await sawDebuggerPausedMessage1.future; // this is the one where it say "uh, you broke into the debugger while reloading" + await reloadFuture; // this is the one where it times out because you're in the debugger + expect(reloaded, isTrue); + await _flutter.hotReload(); // now we're already paused + expect(sawTick3.isCompleted, isFalse); + await sawDebuggerPausedMessage2.future; // so we just get told that nothing is going to happen + await _flutter.resume(); + await subscription.cancel(); + }); + }, timeout: const Timeout.factor(10)); // The DevFS sync takes a really long time, so these tests can be slow. } diff --git a/packages/flutter_tools/test/integration/lifetime_test.dart b/packages/flutter_tools/test/integration/lifetime_test.dart index 62a0000309b..c3c1b27d4a8 100644 --- a/packages/flutter_tools/test/integration/lifetime_test.dart +++ b/packages/flutter_tools/test/integration/lifetime_test.dart @@ -45,5 +45,5 @@ void main() { await Future.delayed(requiredLifespan); expect(_flutter.hasExited, equals(false)); }); - }, timeout: const Timeout.factor(6)); + }, timeout: const Timeout.factor(10)); // The DevFS sync takes a really long time, so these tests can be slow. } diff --git a/packages/flutter_tools/test/integration/test_data/basic_project.dart b/packages/flutter_tools/test/integration/test_data/basic_project.dart index b315f059a0d..791feed7773 100644 --- a/packages/flutter_tools/test/integration/test_data/basic_project.dart +++ b/packages/flutter_tools/test/integration/test_data/basic_project.dart @@ -19,15 +19,22 @@ class BasicProject extends Project { @override final String main = r''' + import 'dart:async'; + import 'package:flutter/material.dart'; - void main() => runApp(new MyApp()); + Future main() async { + while (true) { + runApp(new MyApp()); + await Future.delayed(const Duration(milliseconds: 50)); + } + } class MyApp extends StatelessWidget { @override Widget build(BuildContext context) { topLevelFunction(); - return new MaterialApp( // BREAKPOINT + return new MaterialApp( // BUILD BREAKPOINT title: 'Flutter Demo', home: new Container(), ); @@ -39,9 +46,9 @@ class BasicProject extends Project { } '''; - Uri get buildMethodBreakpointUri => breakpointUri; - int get buildMethodBreakpointLine => breakpointLine; + Uri get buildMethodBreakpointUri => mainDart; + int get buildMethodBreakpointLine => lineContaining(main, '// BUILD BREAKPOINT'); - Uri get topLevelFunctionBreakpointUri => breakpointUri; + Uri get topLevelFunctionBreakpointUri => mainDart; int get topLevelFunctionBreakpointLine => lineContaining(main, '// TOP LEVEL BREAKPOINT'); } diff --git a/packages/flutter_tools/test/integration/test_data/hot_reload_project.dart b/packages/flutter_tools/test/integration/test_data/hot_reload_project.dart index f4174edcbd6..ef85ac8298f 100644 --- a/packages/flutter_tools/test/integration/test_data/hot_reload_project.dart +++ b/packages/flutter_tools/test/integration/test_data/hot_reload_project.dart @@ -22,33 +22,63 @@ class HotReloadProject extends Project { @override final String main = r''' import 'package:flutter/material.dart'; + import 'package:flutter/scheduler.dart'; void main() => runApp(new MyApp()); + int count = 1; + class MyApp extends StatelessWidget { @override Widget build(BuildContext context) { - // Do not remove this line, it's uncommented by a test to verify that hot - // reloading worked. + // This method gets called each time we hot reload, during reassemble. + + // Do not remove the next line, it's uncommented by a test to verify that + // hot reloading worked: // printHotReloadWorked(); - return new MaterialApp( // BREAKPOINT + print('((((TICK $count))))'); + // tick 1 = startup warmup frame + // tick 2 = hot reload warmup reassemble frame + // after that there's a post-hot-reload frame scheduled by the tool that + // doesn't trigger this to rebuild, but does trigger the first callback + // below, then that callback schedules another frame on which we do the + // breakpoint. + // tick 3 = second hot reload warmup reassemble frame (pre breakpoint) + if (count == 2) { + SchedulerBinding.instance.scheduleFrameCallback((Duration timestamp) { + SchedulerBinding.instance.scheduleFrameCallback((Duration timestamp) { + print('breakpoint line'); // SCHEDULED BREAKPOINT + }); + }); + } + count += 1; + + return MaterialApp( // BUILD BREAKPOINT title: 'Flutter Demo', - home: new Container(), + home: Container(), ); } } - printHotReloadWorked() { + void printHotReloadWorked() { // The call to this function is uncommented by a test to verify that hot // reloading worked. print('(((((RELOAD WORKED)))))'); } '''; + Uri get scheduledBreakpointUri => mainDart; + int get scheduledBreakpointLine => lineContaining(main, '// SCHEDULED BREAKPOINT'); + + Uri get buildBreakpointUri => mainDart; + int get buildBreakpointLine => lineContaining(main, '// BUILD BREAKPOINT'); + void uncommentHotReloadPrint() { final String newMainContents = main.replaceAll( - '// printHotReloadWorked();', 'printHotReloadWorked();'); + '// printHotReloadWorked();', + 'printHotReloadWorked();' + ); writeFile(fs.path.join(dir.path, 'lib', 'main.dart'), newMainContents); } } diff --git a/packages/flutter_tools/test/integration/test_data/project.dart b/packages/flutter_tools/test/integration/test_data/project.dart index e723affd85d..69a2b3cc081 100644 --- a/packages/flutter_tools/test/integration/test_data/project.dart +++ b/packages/flutter_tools/test/integration/test_data/project.dart @@ -15,9 +15,7 @@ abstract class Project { String get pubspec; String get main; - // Valid locations for a breakpoint for tests that just need to break somewhere. - Uri get breakpointUri => Uri.parse('package:test/main.dart'); - int get breakpointLine => lineContaining(main, '// BREAKPOINT'); + Uri get mainDart => Uri.parse('package:test/main.dart'); Future setUpIn(Directory dir) async { this.dir = dir; @@ -32,6 +30,6 @@ abstract class Project { final int index = contents.split('\n').indexWhere((String l) => l.contains(search)); if (index == -1) throw Exception("Did not find '$search' inside the file"); - return index; + return index + 1; // first line is line 1, not line 0 } } diff --git a/packages/flutter_tools/test/integration/test_data/stepping_project.dart b/packages/flutter_tools/test/integration/test_data/stepping_project.dart index ac9c6024ff9..c7ddc1c2940 100644 --- a/packages/flutter_tools/test/integration/test_data/stepping_project.dart +++ b/packages/flutter_tools/test/integration/test_data/stepping_project.dart @@ -35,11 +35,11 @@ class SteppingProject extends Project { Future doAsyncStuff() async { print("test"); // BREAKPOINT - await new Future.value(true); // STEP 1 - await new Future.microtask(() => true); // STEP 2 // STEP 3 - await new Future.delayed(const Duration(milliseconds: 1)); // STEP 4 // STEP 5 - print("done!"); // STEP 6 - } + await new Future.value(true); // STEP 1 // STEP 2 + await new Future.microtask(() => true); // STEP 3 // STEP 4 + await new Future.delayed(const Duration(milliseconds: 1)); // STEP 5 // STEP 6 + print("done!"); // STEP 7 + } // STEP 8 @override Widget build(BuildContext context) { @@ -51,7 +51,9 @@ class SteppingProject extends Project { } '''; + Uri get breakpointUri => mainDart; + int get breakpointLine => lineContaining(main, '// BREAKPOINT'); int lineForStep(int i) => lineContaining(main, '// STEP $i'); - final int numberOfSteps = 6; + final int numberOfSteps = 8; } diff --git a/packages/flutter_tools/test/integration/test_data/tests_project.dart b/packages/flutter_tools/test/integration/test_data/tests_project.dart index c98d28036a8..785d6563dce 100644 --- a/packages/flutter_tools/test/integration/test_data/tests_project.dart +++ b/packages/flutter_tools/test/integration/test_data/tests_project.dart @@ -47,9 +47,7 @@ class TestsProject extends Project { String get testFilePath => fs.path.join(dir.path, 'test', 'test.dart'); - @override Uri get breakpointUri => Uri.file(testFilePath); - @override int get breakpointLine => lineContaining(testContent, '// BREAKPOINT'); } diff --git a/packages/flutter_tools/test/integration/test_driver.dart b/packages/flutter_tools/test/integration/test_driver.dart index 74b6cab1002..e8166f2e993 100644 --- a/packages/flutter_tools/test/integration/test_driver.dart +++ b/packages/flutter_tools/test/integration/test_driver.dart @@ -8,26 +8,41 @@ import 'dart:convert'; import 'package:file/file.dart'; import 'package:flutter_tools/src/base/file_system.dart'; import 'package:flutter_tools/src/base/io.dart'; +import 'package:meta/meta.dart'; import 'package:process/process.dart'; import 'package:vm_service_lib/vm_service_lib.dart'; import 'package:vm_service_lib/vm_service_lib_io.dart'; import '../src/common.dart'; -// Set this to true for debugging to get JSON written to stdout. +// Set this to true for debugging to get verbose logs written to stdout. +// The logs include the following: +// <=stdout= data that the flutter tool running in --verbose mode wrote to stdout. +// <=stderr= data that the flutter tool running in --verbose mode wrote to stderr. +// =stdin=> data that the test sent to the flutter tool over stdin. +// =vm=> data that was sent over the VM service channel to the app running on the test device. +// <=vm= data that was sent from the app on the test device over the VM service channel. +// Messages regarding what the test is doing. +// If this is false, then only critical errors and logs when things appear to be +// taking a long time are printed to the console. const bool _printDebugOutputToStdOut = false; -const Duration defaultTimeout = Duration(seconds: 40); + +final DateTime startTime = DateTime.now(); + +const Duration defaultTimeout = Duration(seconds: 5); const Duration appStartTimeout = Duration(seconds: 120); const Duration quitTimeout = Duration(seconds: 10); abstract class FlutterTestDriver { - FlutterTestDriver(this._projectFolder, {String logPrefix}): - _logPrefix = logPrefix != null ? '$logPrefix: ' : ''; + FlutterTestDriver( + this._projectFolder, { + String logPrefix, + }) : _logPrefix = logPrefix != null ? '$logPrefix: ' : ''; final Directory _projectFolder; final String _logPrefix; - Process _proc; - int _procPid; + Process _process; + int _processPid; final StreamController _stdout = StreamController.broadcast(); final StreamController _stderr = StreamController.broadcast(); final StreamController _allMessages = StreamController.broadcast(); @@ -42,101 +57,108 @@ abstract class FlutterTestDriver { int get vmServicePort => _vmServiceWsUri.port; bool get hasExited => _hasExited; - String _debugPrint(String msg) { - const int maxLength = 500; - final String truncatedMsg = - msg.length > maxLength ? msg.substring(0, maxLength) + '...' : msg; - _allMessages.add(truncatedMsg); - if (_printDebugOutputToStdOut) { - print('$_logPrefix$truncatedMsg'); + String lastTime = ''; + void _debugPrint(String message, { String topic = '' }) { + const int maxLength = 2500; + final String truncatedMessage = message.length > maxLength ? message.substring(0, maxLength) + '...' : message; + final String line = '${topic.padRight(10)} $truncatedMessage'; + _allMessages.add(line); + final int timeInSeconds = DateTime.now().difference(startTime).inSeconds; + String time = timeInSeconds.toString().padLeft(5) + 's '; + if (time == lastTime) { + time = ' ' * time.length; + } else { + lastTime = time; } - return msg; + if (_printDebugOutputToStdOut) + print('$time$_logPrefix$line'); } Future _setupProcess( - List args, { + List arguments, { String script, bool withDebugger = false, - bool pauseOnExceptions = false, File pidFile, }) async { final String flutterBin = fs.path.join(getFlutterRoot(), 'bin', 'flutter'); - if (withDebugger) { - args.add('--start-paused'); - } + if (withDebugger) + arguments.add('--start-paused'); + if (_printDebugOutputToStdOut) + arguments.add('--verbose'); if (pidFile != null) { - args.addAll(['--pid-file', pidFile.path]); + arguments.addAll(['--pid-file', pidFile.path]); } if (script != null) { - args.add(script); + arguments.add(script); } - _debugPrint('Spawning flutter $args in ${_projectFolder.path}'); + _debugPrint('Spawning flutter $arguments in ${_projectFolder.path}'); const ProcessManager _processManager = LocalProcessManager(); - _proc = await _processManager.start( - [flutterBin] - .followedBy(args) - .toList(), - workingDirectory: _projectFolder.path, - environment: {'FLUTTER_TEST': 'true'}); + _process = await _processManager.start( + [flutterBin] + .followedBy(arguments) + .toList(), + workingDirectory: _projectFolder.path, + environment: {'FLUTTER_TEST': 'true'}, + ); // This class doesn't use the result of the future. It's made available // via a getter for external uses. - _proc.exitCode.then((int code) { // ignore: unawaited_futures + _process.exitCode.then((int code) { // ignore: unawaited_futures _debugPrint('Process exited ($code)'); _hasExited = true; }); - transformToLines(_proc.stdout).listen((String line) => _stdout.add(line)); - transformToLines(_proc.stderr).listen((String line) => _stderr.add(line)); + transformToLines(_process.stdout).listen((String line) => _stdout.add(line)); + transformToLines(_process.stderr).listen((String line) => _stderr.add(line)); // Capture stderr to a buffer so we can show it all if any requests fail. _stderr.stream.listen(_errorBuffer.writeln); // This is just debug printing to aid running/debugging tests locally. - _stdout.stream.listen(_debugPrint); - _stderr.stream.listen(_debugPrint); + _stdout.stream.listen((String message) => _debugPrint(message, topic: '<=stdout=')); + _stderr.stream.listen((String message) => _debugPrint(message, topic: '<=stderr=')); } Future connectToVmService({bool pauseOnExceptions = false}) async { - _vmService = await vmServiceConnectUri(_vmServiceWsUri.toString()); - _vmService.onSend.listen((String s) => _debugPrint('==> $s')); - _vmService.onReceive.listen((String s) => _debugPrint('<== $s')); - await Future.wait(>[ - _vmService.streamListen('Isolate'), - _vmService.streamListen('Debug'), - ]); - - // On hot restarts, the isolate ID we have for the Flutter thread will - // exit so we need to invalidate our cached ID. - _vmService.onIsolateEvent.listen((Event event) { - if (event.kind == EventKind.kIsolateExit && event.isolate.id == _flutterIsolateId) { - _flutterIsolateId = null; - } - }); - - // Because we start paused, resume so the app is in a "running" state as - // expected by tests. Tests will reload/restart as required if they need - // to hit breakpoints, etc. - await waitForPause(); - if (pauseOnExceptions) { - await _vmService.setExceptionPauseMode(await _getFlutterIsolateId(), ExceptionPauseMode.kUnhandled); + _vmService = await vmServiceConnectUri('$_vmServiceWsUri'); + _vmService.onSend.listen((String s) => _debugPrint(s, topic: '=vm=>')); + _vmService.onReceive.listen((String s) => _debugPrint(s, topic: '<=vm=')); + _vmService.onIsolateEvent.listen((Event event) { + if (event.kind == EventKind.kIsolateExit && event.isolate.id == _flutterIsolateId) { + // Hot restarts cause all the isolates to exit, so we need to refresh + // our idea of what the Flutter isolate ID is. + _flutterIsolateId = null; } + }); + + await Future.wait(>[ + _vmService.streamListen('Isolate'), + _vmService.streamListen('Debug'), + ]); + + await waitForPause(); + if (pauseOnExceptions) { + await _vmService.setExceptionPauseMode( + await _getFlutterIsolateId(), + ExceptionPauseMode.kUnhandled, + ); + } } Future quit() => _killGracefully(); Future _killGracefully() async { - if (_procPid == null) + if (_processPid == null) return -1; - _debugPrint('Sending SIGTERM to $_procPid..'); - Process.killPid(_procPid); - return _proc.exitCode.timeout(quitTimeout, onTimeout: _killForcefully); + _debugPrint('Sending SIGTERM to $_processPid..'); + Process.killPid(_processPid); + return _process.exitCode.timeout(quitTimeout, onTimeout: _killForcefully); } Future _killForcefully() { - _debugPrint('Sending SIGKILL to $_procPid..'); - Process.killPid(_procPid, ProcessSignal.SIGKILL); - return _proc.exitCode; + _debugPrint('Sending SIGKILL to $_processPid..'); + Process.killPid(_processPid, ProcessSignal.SIGKILL); + return _process.exitCode; } String _flutterIsolateId; @@ -155,75 +177,106 @@ abstract class FlutterTestDriver { return isolate; } + /// Add a breakpoint and wait for it to trip the program execution. + /// + /// Only call this when you are absolutely sure that the program under test + /// will hit the breakpoint _in the future_. + /// + /// In particular, do not call this if the program is currently racing to pass + /// the line of code you are breaking on. Pretend that calling this will take + /// an hour before setting the breakpoint. Would the code still eventually hit + /// the breakpoint and stop? + Future breakAt(Uri uri, int line) async { + await addBreakpoint(uri, line); + await waitForPause(); + } + Future addBreakpoint(Uri uri, int line) async { - _debugPrint('Sending breakpoint for $uri:$line'); + _debugPrint('Sending breakpoint for: $uri:$line'); await _vmService.addBreakpointWithScriptUri( - await _getFlutterIsolateId(), uri.toString(), line); + await _getFlutterIsolateId(), + uri.toString(), + line, + ); } + // This method isn't racy. If the isolate is already paused, + // it will immediately return. Future waitForPause() async { - _debugPrint('Waiting for isolate to pause'); - final String flutterIsolate = await _getFlutterIsolateId(); + return _timeoutWithMessages( + () async { + final String flutterIsolate = await _getFlutterIsolateId(); + final Completer pauseEvent = Completer(); - Future waitForPause() async { - final Completer pauseEvent = Completer(); + // Start listening for pause events. + final StreamSubscription pauseSubscription = _vmService.onDebugEvent + .where((Event event) { + return event.isolate.id == flutterIsolate + && event.kind.startsWith('Pause'); + }) + .listen((Event event) { + if (!pauseEvent.isCompleted) + pauseEvent.complete(event); + }); - // Start listening for pause events. - final StreamSubscription pauseSub = _vmService.onDebugEvent - .where((Event event) => - event.isolate.id == flutterIsolate && - event.kind.startsWith('Pause')) - .listen(pauseEvent.complete); + // But also check if the isolate was already paused (only after we've set + // up the subscription) to avoid races. If it was paused, we don't need to wait + // for the event. + final Isolate isolate = await _vmService.getIsolate(flutterIsolate); + if (isolate.pauseEvent.kind.startsWith('Pause')) { + _debugPrint('Isolate was already paused (${isolate.pauseEvent.kind}).'); + } else { + _debugPrint('Isolate is not already paused, waiting for event to arrive...'); + await pauseEvent.future; + } - // But also check if the isolate was already paused (only after we've set - // up the sub) to avoid races. If it was paused, we don't need to wait - // for the event. - final Isolate isolate = await _vmService.getIsolate(flutterIsolate); - if (!isolate.pauseEvent.kind.startsWith('Pause')) { - await pauseEvent.future; - } + // Cancel the subscription on either of the above. + await pauseSubscription.cancel(); - // Cancel the sub on either of the above. - await pauseSub.cancel(); - - return _getFlutterIsolate(); - } - - return _timeoutWithMessages(waitForPause, - message: 'Isolate did not pause'); + return _getFlutterIsolate(); + }, + task: 'Waiting for isolate to pause', + ); } + Future resume({bool waitForNextPause = false}) => _resume(null, waitForNextPause); + Future stepOver({bool waitForNextPause = true}) => _resume(StepOption.kOver, waitForNextPause); + Future stepOverAsync({ bool waitForNextPause = true }) => _resume(StepOption.kOverAsyncSuspension, waitForNextPause); + Future stepInto({bool waitForNextPause = true}) => _resume(StepOption.kInto, waitForNextPause); + Future stepOut({bool waitForNextPause = true}) => _resume(StepOption.kOut, waitForNextPause); + Future isAtAsyncSuspension() async { final Isolate isolate = await _getFlutterIsolate(); return isolate.pauseEvent.atAsyncSuspension == true; } - Future resume({bool wait = true}) => _resume(wait: wait); - Future stepOver({bool wait = true}) => _resume(step: StepOption.kOver, wait: wait); - Future stepOverAsync({ bool wait = true }) => _resume(step: StepOption.kOverAsyncSuspension, wait: wait); - Future stepOverOrOverAsyncSuspension({ bool wait = true }) async { - return (await isAtAsyncSuspension()) ? stepOverAsync(wait: wait) : stepOver(wait: wait); + Future stepOverOrOverAsyncSuspension({ bool waitForNextPause = true }) async { + if (await isAtAsyncSuspension()) + return await stepOverAsync(waitForNextPause: waitForNextPause); + return await stepOver(waitForNextPause: waitForNextPause); } - Future stepInto({bool wait = true}) => _resume(step: StepOption.kInto, wait: wait); - Future stepOut({bool wait = true}) => _resume(step: StepOption.kOut, wait: wait); - Future _resume({String step, bool wait = true}) async { - _debugPrint('Sending resume ($step)'); - await _timeoutWithMessages(() async => _vmService.resume(await _getFlutterIsolateId(), step: step), - message: 'Isolate did not respond to resume ($step)'); - return wait ? waitForPause() : null; + Future _resume(String step, bool waitForNextPause) async { + assert(waitForNextPause != null); + await _timeoutWithMessages( + () async => _vmService.resume(await _getFlutterIsolateId(), step: step), + task: 'Resuming isolate (step=$step)', + ); + return waitForNextPause ? waitForPause() : null; } Future evaluateInFrame(String expression) async { return _timeoutWithMessages( - () async => await _vmService.evaluateInFrame(await _getFlutterIsolateId(), 0, expression), - message: 'Timed out evaluating expression ($expression)'); + () async => await _vmService.evaluateInFrame(await _getFlutterIsolateId(), 0, expression), + task: 'Evaluating expression ($expression)', + ); } Future evaluate(String targetId, String expression) async { return _timeoutWithMessages( - () async => await _vmService.evaluate(await _getFlutterIsolateId(), targetId, expression), - message: 'Timed out evaluating expression ($expression for $targetId)'); + () async => await _vmService.evaluate(await _getFlutterIsolateId(), targetId, expression), + task: 'Evaluating expression ($expression for $targetId)', + ); } Future getTopStackFrame() async { @@ -260,26 +313,29 @@ abstract class FlutterTestDriver { Future> _waitFor({ String event, int id, - Duration timeout, + Duration timeout = defaultTimeout, bool ignoreAppStopEvent = false, }) async { + assert(timeout != null); + assert(event != null || id != null); + assert(event == null || id == null); + final String interestingOccurrence = event != null ? '$event event' : 'response to request $id'; final Completer> response = Completer>(); - StreamSubscription sub; - sub = _stdout.stream.listen((String line) async { + StreamSubscription subscription; + subscription = _stdout.stream.listen((String line) async { final dynamic json = parseFlutterResponse(line); _lastResponse = line; - if (json == null) { + if (json == null) return; - } else if ( - (event != null && json['event'] == event) - || (id != null && json['id'] == id)) { - await sub.cancel(); + if ((event != null && json['event'] == event) || + (id != null && json['id'] == id)) { + await subscription.cancel(); + _debugPrint('OK ($interestingOccurrence)'); response.complete(json); } else if (!ignoreAppStopEvent && json['event'] == 'app.stop') { - await sub.cancel(); + await subscription.cancel(); final StringBuffer error = StringBuffer(); - error.write('Received app.stop event while waiting for '); - error.write('${event != null ? '$event event' : 'response to request $id.'}.\n\n'); + error.write('Received app.stop event while waiting for $interestingOccurrence\n\n'); if (json['params'] != null && json['params']['error'] != null) { error.write('${json['params']['error']}\n\n'); } @@ -290,67 +346,107 @@ abstract class FlutterTestDriver { } }); - return _timeoutWithMessages>(() => response.future, - timeout: timeout, - message: event != null - ? 'Did not receive expected $event event.' - : 'Did not receive response to request "$id".') - .whenComplete(() => sub.cancel()); + return _timeoutWithMessages( + () => response.future, + timeout: timeout, + task: 'Expecting $interestingOccurrence', + ).whenComplete(subscription.cancel); } - Future _timeoutWithMessages(Future Function() f, {Duration timeout, String message}) { - // Capture output to a buffer so if we don't get the response we want we can show - // the output that did arrive in the timeout error. - final StringBuffer messages = StringBuffer(); - final DateTime start = DateTime.now(); - void logMessage(String m) { - final int ms = DateTime.now().difference(start).inMilliseconds; - messages.writeln('[+ ${ms.toString().padLeft(5)}] $m'); - } - final StreamSubscription sub = _allMessages.stream.listen(logMessage); + Future _timeoutWithMessages(Future Function() callback, { + @required String task, + Duration timeout = defaultTimeout, + }) { + assert(task != null); + assert(timeout != null); - return f().timeout(timeout ?? defaultTimeout, onTimeout: () { - logMessage(''); - throw '$message'; - }).catchError((dynamic error) { - throw '$error\nReceived:\n${messages.toString()}'; - }).whenComplete(() => sub.cancel()); + if (_printDebugOutputToStdOut) { + _debugPrint('$task...'); + return callback()..timeout(timeout, onTimeout: () { + _debugPrint('$task is taking longer than usual...'); + }); + } + + // We're not showing all output to the screen, so let's capture the output + // that we would have printed if we were, and output it if we take longer + // than the timeout or if we get an error. + final StringBuffer messages = StringBuffer('$task\n'); + final DateTime start = DateTime.now(); + bool timeoutExpired = false; + void logMessage(String logLine) { + final int ms = DateTime.now().difference(start).inMilliseconds; + final String formattedLine = '[+ ${ms.toString().padLeft(5)}] $logLine'; + messages.writeln(formattedLine); + } + final StreamSubscription subscription = _allMessages.stream.listen(logMessage); + + final Future future = callback(); + + future.timeout(timeout ?? defaultTimeout, onTimeout: () { + print(messages.toString()); + timeoutExpired = true; + print('$task is taking longer than usual...'); + }); + + return future.catchError((dynamic error) { + if (!timeoutExpired) { + timeoutExpired = true; + print(messages.toString()); + } + throw error; + }).whenComplete(() => subscription.cancel()); } } class FlutterRunTestDriver extends FlutterTestDriver { - FlutterRunTestDriver(Directory _projectFolder, {String logPrefix}): - super(_projectFolder, logPrefix: logPrefix); + FlutterRunTestDriver( + Directory projectFolder, { + String logPrefix, + }) : super(projectFolder, logPrefix: logPrefix); String _currentRunningAppId; - Future run({ + Future run({ bool withDebugger = false, + bool startPaused = false, bool pauseOnExceptions = false, File pidFile, }) async { - await _setupProcess([ + await _setupProcess( + [ 'run', '--machine', '-d', 'flutter-tester', - ], withDebugger: withDebugger, pauseOnExceptions: pauseOnExceptions, pidFile: pidFile); + ], + withDebugger: withDebugger, + startPaused: startPaused, + pauseOnExceptions: pauseOnExceptions, + pidFile: pidFile, + ); } Future attach( int port, { bool withDebugger = false, + bool startPaused = false, bool pauseOnExceptions = false, File pidFile, }) async { - await _setupProcess([ + await _setupProcess( + [ 'attach', '--machine', '-d', 'flutter-tester', '--debug-port', '$port', - ], withDebugger: withDebugger, pauseOnExceptions: pauseOnExceptions, pidFile: pidFile); + ], + withDebugger: withDebugger, + startPaused: startPaused, + pauseOnExceptions: pauseOnExceptions, + pidFile: pidFile, + ); } @override @@ -358,35 +454,35 @@ class FlutterRunTestDriver extends FlutterTestDriver { List args, { String script, bool withDebugger = false, + bool startPaused = false, bool pauseOnExceptions = false, File pidFile, }) async { + assert(!startPaused || withDebugger); await super._setupProcess( args, script: script, withDebugger: withDebugger, - pauseOnExceptions: pauseOnExceptions, pidFile: pidFile, ); // Stash the PID so that we can terminate the VM more reliably than using - // _proc.kill() (because _proc is a shell, because `flutter` is a shell - // script). + // _process.kill() (`flutter` is a shell script so _process itself is a + // shell, not the flutter tool's Dart process). final Map connected = await _waitFor(event: 'daemon.connected'); - _procPid = connected['params']['pid']; + _processPid = connected['params']['pid']; // Set this up now, but we don't wait it yet. We want to make sure we don't // miss it while waiting for debugPort below. - final Future> started = _waitFor(event: 'app.started', - timeout: appStartTimeout); + final Future> started = _waitFor(event: 'app.started', timeout: appStartTimeout); if (withDebugger) { - final Map debugPort = await _waitFor(event: 'app.debugPort', - timeout: appStartTimeout); + final Map debugPort = await _waitFor(event: 'app.debugPort', timeout: appStartTimeout); final String wsUriString = debugPort['params']['wsUri']; _vmServiceWsUri = Uri.parse(wsUriString); await connectToVmService(pauseOnExceptions: pauseOnExceptions); - await resume(wait: false); + if (!startPaused) + await resume(waitForNextPause: false); } // Now await the started event; if it had already happened the future will @@ -401,24 +497,26 @@ class FlutterRunTestDriver extends FlutterTestDriver { if (_currentRunningAppId == null) throw Exception('App has not started yet'); - final dynamic hotReloadResp = await _sendRequest( - 'app.restart', - {'appId': _currentRunningAppId, 'fullRestart': fullRestart, 'pause': pause}, + _debugPrint('Performing ${ pause ? "paused " : "" }${ fullRestart ? "hot restart" : "hot reload" }...'); + final dynamic hotReloadResponse = await _sendRequest( + 'app.restart', + {'appId': _currentRunningAppId, 'fullRestart': fullRestart, 'pause': pause} ); + _debugPrint('${ fullRestart ? "Hot restart" : "Hot reload" } complete.'); - if (hotReloadResp == null || hotReloadResp['code'] != 0) + if (hotReloadResponse == null || hotReloadResponse['code'] != 0) _throwErrorResponse('Hot ${fullRestart ? 'restart' : 'reload'} request failed'); } Future detach() async { if (_vmService != null) { - _debugPrint('Closing VM service'); + _debugPrint('Closing VM service...'); _vmService.dispose(); } if (_currentRunningAppId != null) { - _debugPrint('Detaching from app'); + _debugPrint('Detaching from app...'); await Future.any(>[ - _proc.exitCode, + _process.exitCode, _sendRequest( 'app.detach', {'appId': _currentRunningAppId}, @@ -429,19 +527,19 @@ class FlutterRunTestDriver extends FlutterTestDriver { ); _currentRunningAppId = null; } - _debugPrint('Waiting for process to end'); - return _proc.exitCode.timeout(quitTimeout, onTimeout: _killGracefully); + _debugPrint('Waiting for process to end...'); + return _process.exitCode.timeout(quitTimeout, onTimeout: _killGracefully); } Future stop() async { if (_vmService != null) { - _debugPrint('Closing VM service'); + _debugPrint('Closing VM service...'); _vmService.dispose(); } if (_currentRunningAppId != null) { - _debugPrint('Stopping app'); + _debugPrint('Stopping application...'); await Future.any(>[ - _proc.exitCode, + _process.exitCode, _sendRequest( 'app.stop', {'appId': _currentRunningAppId}, @@ -452,27 +550,13 @@ class FlutterRunTestDriver extends FlutterTestDriver { ); _currentRunningAppId = null; } - if (_proc != null) { - _debugPrint('Waiting for process to end'); - return _proc.exitCode.timeout(quitTimeout, onTimeout: _killGracefully); + if (_process != null) { + _debugPrint('Waiting for process to end...'); + return _process.exitCode.timeout(quitTimeout, onTimeout: _killGracefully); } return 0; } - Future breakAt(Uri uri, int line, { bool restart = false }) async { - if (restart) { - // For a hot restart, we need to send the breakpoints after the restart - // so we need to pause during the restart to avoid races. - await hotRestart(pause: true); - await addBreakpoint(uri, line); - return resume(); - } else { - await addBreakpoint(uri, line); - await hotReload(); - return waitForPause(); - } - } - int id = 1; Future _sendRequest(String method, dynamic params) async { final int requestId = id++; @@ -482,16 +566,16 @@ class FlutterRunTestDriver extends FlutterTestDriver { 'params': params }; final String jsonEncoded = json.encode(>[request]); - _debugPrint(jsonEncoded); + _debugPrint(jsonEncoded, topic: '=stdin=>'); // Set up the response future before we send the request to avoid any - // races. If the method we're calling is app.stop then we tell waitFor not + // races. If the method we're calling is app.stop then we tell _waitFor not // to throw if it sees an app.stop event before the response to this request. final Future> responseFuture = _waitFor( id: requestId, ignoreAppStopEvent: method == 'app.stop', ); - _proc.stdin.writeln(jsonEncoded); + _process.stdin.writeln(jsonEncoded); final Map response = await responseFuture; if (response['error'] != null || response['result'] == null) @@ -500,8 +584,8 @@ class FlutterRunTestDriver extends FlutterTestDriver { return response['result']; } - void _throwErrorResponse(String msg) { - throw '$msg\n\n$_lastResponse\n\n${_errorBuffer.toString()}'.trim(); + void _throwErrorResponse(String message) { + throw '$message\n\n$_lastResponse\n\n${_errorBuffer.toString()}'.trim(); } } @@ -537,7 +621,6 @@ class FlutterTestTestDriver extends FlutterTestDriver { args, script: script, withDebugger: withDebugger, - pauseOnExceptions: pauseOnExceptions, pidFile: pidFile, ); @@ -545,7 +628,7 @@ class FlutterTestTestDriver extends FlutterTestDriver { // _proc.kill() (because _proc is a shell, because `flutter` is a shell // script). final Map version = await _waitForJson(); - _procPid = version['pid']; + _processPid = version['pid']; if (withDebugger) { final Map startedProcess = await _waitFor(event: 'test.startedProcess', timeout: appStartTimeout); @@ -556,7 +639,7 @@ class FlutterTestTestDriver extends FlutterTestDriver { if (beforeStart != null) { await beforeStart(); } - await resume(wait: false); + await resume(waitForNextPause: false); } } @@ -566,7 +649,7 @@ class FlutterTestTestDriver extends FlutterTestDriver { return _timeoutWithMessages>( () => _stdout.stream.map>(_parseJsonResponse).first, timeout: timeout, - message: 'Did not receive any JSON.', + task: 'Waiting for JSON', ); } @@ -587,8 +670,8 @@ Stream transformToLines(Stream> byteStream) { Map parseFlutterResponse(String line) { if (line.startsWith('[') && line.endsWith(']')) { try { - final Map resp = json.decode(line)[0]; - return resp; + final Map response = json.decode(line)[0]; + return response; } catch (e) { // Not valid JSON, so likely some other output that was surrounded by [brackets] return null; diff --git a/packages/flutter_tools/test/ios/code_signing_test.dart b/packages/flutter_tools/test/ios/code_signing_test.dart index 859d82b3f55..8c1fc5d86fc 100644 --- a/packages/flutter_tools/test/ios/code_signing_test.dart +++ b/packages/flutter_tools/test/ios/code_signing_test.dart @@ -470,7 +470,7 @@ class TestTerminal extends AnsiTerminal { String bolden(String message) => '$message'; @override - Stream get onCharInput { + Stream get keystrokes { return mockTerminalStdInStream; } } diff --git a/packages/flutter_tools/test/vmservice_test.dart b/packages/flutter_tools/test/vmservice_test.dart index 04217643fdf..15c64c4132c 100644 --- a/packages/flutter_tools/test/vmservice_test.dart +++ b/packages/flutter_tools/test/vmservice_test.dart @@ -153,13 +153,32 @@ class MockPeer implements rpc.Peer { } void main() { - final MockStdio mockStdio = MockStdio(); + MockStdio mockStdio; group('VMService', () { + setUp(() { + mockStdio = MockStdio(); + }); + testUsingContext('fails connection eagerly in the connect() method', () async { - expect( - VMService.connect(Uri.parse('http://host.invalid:9999/')), - throwsToolExit(), - ); + FakeAsync().run((FakeAsync time) { + bool failed = false; + final Future future = VMService.connect(Uri.parse('http://host.invalid:9999/')); + future.whenComplete(() { + failed = true; + }); + time.elapse(const Duration(seconds: 5)); + expect(failed, isFalse); + expect(mockStdio.writtenToStdout.join(''), ''); + expect(mockStdio.writtenToStderr.join(''), ''); + time.elapse(const Duration(seconds: 5)); + expect(failed, isFalse); + expect(mockStdio.writtenToStdout.join(''), 'This is taking longer than expected...\n'); + expect(mockStdio.writtenToStderr.join(''), ''); + }); + }, overrides: { + Logger: () => StdoutLogger(), + Stdio: () => mockStdio, + WebSocketConnector: () => (String url) async => throw const SocketException('test'), }); testUsingContext('refreshViews', () { @@ -167,7 +186,7 @@ void main() { bool done = false; final MockPeer mockPeer = MockPeer(); expect(mockPeer.returnedFromSendRequest, 0); - final VMService vmService = VMService(mockPeer, null, null, const Duration(seconds: 1), null, null, null); + final VMService vmService = VMService(mockPeer, null, null, null, null, null); vmService.getVM().then((void value) { done = true; }); expect(done, isFalse); expect(mockPeer.returnedFromSendRequest, 0);