diff --git a/dev/devicelab/bin/tasks/run_machine_concurrent_hot_reload.dart b/dev/devicelab/bin/tasks/run_machine_concurrent_hot_reload.dart index 34d32aeed5d..ee8c86c3aeb 100644 --- a/dev/devicelab/bin/tasks/run_machine_concurrent_hot_reload.dart +++ b/dev/devicelab/bin/tasks/run_machine_concurrent_hot_reload.dart @@ -50,20 +50,22 @@ void main() { '--verbose', '-d', device.deviceId, - 'lib/commands.dart' + 'lib/commands.dart', ], ); - final StreamController stdout = - StreamController.broadcast(); + final StreamController stdout = StreamController.broadcast(); transformToLines(run.stdout).listen((String line) { print('run:stdout: $line'); stdout.add(line); final dynamic json = parseFlutterResponse(line); - if (json != null && json['event'] == 'app.debugPort') { - vmServicePort = Uri.parse(json['params']['wsUri']).port; - print('service protocol connection available at port $vmServicePort'); - } else if (json != null && json['event'] == 'app.started') { - appId = json['params']['appId']; + if (json != null) { + if (json['event'] == 'app.debugPort') { + vmServicePort = Uri.parse(json['params']['wsUri']).port; + print('service protocol connection available at port $vmServicePort'); + } else if (json['event'] == 'app.started') { + appId = json['params']['appId']; + print('application identifier is $appId'); + } } if (vmServicePort != null && appId != null && !ready.isCompleted) { print('run: ready!'); @@ -73,6 +75,7 @@ void main() { }); transformToLines(run.stderr).listen((String line) { stderr.writeln('run:stderr: $line'); + ok = false; }); run.exitCode.then((int exitCode) { ok = false; @@ -81,17 +84,15 @@ void main() { if (!ok) throw 'Failed to run test app.'; - final VMServiceClient client = - VMServiceClient.connect('ws://localhost:$vmServicePort/ws'); + final VMServiceClient client = VMServiceClient.connect( + 'ws://localhost:$vmServicePort/ws' + ); int id = 1; - Future> sendRequest( - String method, dynamic params) async { + Future> sendRequest(String method, dynamic params) async { final int requestId = id++; - final Completer> response = - Completer>(); - final StreamSubscription responseSubscription = - stdout.stream.listen((String line) { + final Completer> response = Completer>(); + final StreamSubscription responseSubscription = stdout.stream.listen((String line) { final Map json = parseFlutterResponse(line); if (json != null && json['id'] == requestId) response.complete(json); @@ -110,27 +111,35 @@ void main() { } print('test: sending two hot reloads...'); - final Future hotReload1 = sendRequest('app.restart', - {'appId': appId, 'fullRestart': false}); - final Future hotReload2 = sendRequest('app.restart', - {'appId': appId, 'fullRestart': false}); - final Future> reloadRequests = - Future.wait(>[hotReload1, hotReload2]); - final dynamic results = await Future - .any(>[run.exitCode, reloadRequests]); + final Future hotReload1 = sendRequest( + 'app.restart', + {'appId': appId, 'fullRestart': false}, + ); + final Future hotReload2 = sendRequest( + 'app.restart', + {'appId': appId, 'fullRestart': false}, + ); + final Future> reloadRequests = Future.wait(>[ + hotReload1, + hotReload2, + ]); + final dynamic results = await Future.any(>[ + run.exitCode, + reloadRequests, + ]); if (!ok) - throw 'App crashed during hot reloads.'; + throw 'App failed or crashed during hot reloads.'; final List responses = results; - final List errorResponses = - responses.where((dynamic r) => r['error'] != null).toList(); - final List successResponses = responses - .where((dynamic r) => - r['error'] == null && - r['result'] != null && - r['result']['code'] == 0) - .toList(); + final List errorResponses = responses.where( + (dynamic r) => r['error'] != null + ).toList(); + final List successResponses = responses.where( + (dynamic r) => r['error'] == null && + r['result'] != null && + r['result']['code'] == 0 + ).toList(); if (errorResponses.length != 1) throw 'Did not receive the expected (exactly one) hot reload error response.'; @@ -140,8 +149,10 @@ void main() { if (successResponses.length != 1) throw 'Did not receive the expected (exactly one) successful hot reload response.'; - final dynamic hotReload3 = await sendRequest('app.restart', - {'appId': appId, 'fullRestart': false}); + final dynamic hotReload3 = await sendRequest( + 'app.restart', + {'appId': appId, 'fullRestart': false}, + ); if (hotReload3['error'] != null) throw 'Received an error response from a hot reload after all other hot reloads had completed.'; @@ -150,7 +161,7 @@ void main() { if (result != 0) throw 'Received unexpected exit code $result from run process.'; print('test: validating that the app has in fact closed...'); - await client.done.timeout(const Duration(seconds: 5)); + await client.done; }); return TaskResult.success(null); }); 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_driver/lib/src/common/message.dart b/packages/flutter_driver/lib/src/common/message.dart index 36aab524c5c..edf6a69a74d 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. @@ -28,7 +36,7 @@ abstract class Command { @mustCallSuper Map serialize() => { 'command': kind, - 'timeout': '${timeout.inMilliseconds}', + 'timeout': timeout == null ? null : '${timeout.inMilliseconds}', }; } diff --git a/packages/flutter_driver/lib/src/driver/driver.dart b/packages/flutter_driver/lib/src/driver/driver.dart index a70bb24ff7d..6d83446ebf8 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 @@ -201,16 +193,17 @@ class FlutterDriver { if (Platform.isFuchsia && isolateNumber == null) { 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(); @@ -225,14 +218,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; @@ -243,12 +236,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 @@ -263,7 +251,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(); } @@ -271,7 +258,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 @@ -324,23 +310,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 || @@ -373,7 +357,7 @@ class FlutterDriver { 'registered.' ); await enableIsolateStreams(); - await waitForServiceExtension().timeout(_longTimeout(timeoutMultiplier) * 2); + await waitForServiceExtension(); return driver.checkHealth(); } } @@ -406,29 +390,17 @@ 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, + response = await _warnIfSlow>( + future: _appIsolate.invokeExtension(_flutterExtensionMethodName, serialized), + 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', @@ -453,31 +425,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)); } @@ -486,7 +453,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)); } @@ -504,7 +470,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)); } @@ -516,7 +481,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)); } @@ -541,12 +505,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); @@ -554,7 +518,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 @@ -573,7 +536,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; } @@ -610,7 +572,6 @@ class FlutterDriver { /// }); /// ``` Future enterText(String text, { Duration timeout }) async { - timeout ??= _shortTimeout(timeoutMultiplier); await _sendCommand(EnterText(text, timeout: timeout)); } @@ -629,7 +590,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)); } @@ -640,7 +600,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; } @@ -649,7 +608,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; } @@ -663,16 +621,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 @@ -680,7 +637,7 @@ class FlutterDriver { // in ASCII art: // // ------------------------------------------------------------------- - // Before this change: + // Without this timeout: // ------------------------------------------------------------------- // UI : <-- build --> // GPU : <-- rasterize --> @@ -691,12 +648,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 timeout, if we're lucky: // ------------------------------------------------------------------- // UI : <-- build --> // GPU : <-- rasterize --> @@ -706,16 +664,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 timeout, 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: /// @@ -731,23 +701,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', @@ -758,12 +735,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( @@ -802,12 +787,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', @@ -834,7 +827,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 { @@ -894,11 +886,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. @@ -908,44 +895,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..73681b8fc40 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,21 @@ 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}', + 'timeout': null, }); 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 680b82ff9d7..65bada16c83 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 8d218c21d12..b246223942a 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( @@ -174,7 +174,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); @@ -312,8 +312,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( @@ -354,8 +354,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..87bf6c108a2 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,23 @@ 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.) + /// + /// 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, }); } @@ -166,21 +187,24 @@ 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(timeout != null); + 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,15 @@ 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(timeout != null); + assert(progressIndicatorPadding != null); printStatus(message); - return Status()..start(); + return SilentStatus(timeout: timeout)..start(); } /// Clears all buffers. @@ -337,15 +363,31 @@ 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(timeout != null); + 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 > kFastOperation) { + time = getElapsedAsSeconds(timer.elapsed); + } else { + time = getElapsedAsMilliseconds(timer.elapsed); + } + if (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 +425,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 +442,87 @@ 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 }) : assert(timeout != null); - /// 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, + }) { + assert(timeout != null); 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 => _stopwatch.elapsed > timeout; + + @protected + String get elapsedTime { + if (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(); + } + + @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); +} + /// 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,69 +532,74 @@ 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; @override void start() { super.start(); assert(timer == null); - stdout.write(' '); + stdout.write(_clear); // for _callback to backspace over timer = Timer.periodic(const Duration(milliseconds: 100), _callback); _callback(timer); } @override - void stop() { + void finish() { assert(timer.isActive); timer.cancel(); stdout.write('$_backspace$_clear$_backspace'); - super.stop(); + super.finish(); } - @override - void cancel() { - assert(timer.isActive); - timer.cancel(); - stdout.write('$_backspace$_clear$_backspace'); - super.cancel(); + void _callback(Timer timer) { + stdout.write('$_backspace'); + ticks += 1; + stdout.write('$_currentAnimationFrame'); + if (seemsSlow) { + if (slowWarningCallback != null) { + _slowWarning = ' ' + slowWarningCallback(); + } else { + _slowWarning = ' ' + _defaultSlowWarning; + } + stdout.write(_slowWarning); + } } } -/// 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. +/// 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 void start() { - assert(stopwatch == null || !stopwatch.isRunning); - stopwatch = Stopwatch()..start(); stdout.write('${message.padRight(padding)}$_margin'); super.start(); } @@ -531,48 +619,36 @@ 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)}'); - } + if (multilineOutput) + stdout.write('\n${'$message Done'.padRight(padding - 4)}$_margin'); + stdout.write(elapsedTime.padLeft(8)); // should fit "99,999ms" + if (seemsSlow) + stdout.write(' (!)'); } } /// 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. +/// [onFinish]. On [stop], will additionally print out summary information. class SummaryStatus extends Status { SummaryStatus({ - String message, - bool expectSlowOperation, - int padding, + this.message = '', + @required Duration timeout, + this.padding = kDefaultStatusPadding, VoidCallback onFinish, - }) : message = message ?? '', - padding = padding ?? 0, - expectSlowOperation = expectSlowOperation ?? false, - super(onFinish: onFinish); + }) : assert(message != null), + assert(padding != null), + super(timeout: timeout, 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(); } @@ -590,15 +666,16 @@ class SummaryStatus extends Status { stdout.write('\n'); } - /// Prints a (minimum) 5 character padded time. If [expectSlowOperation] is - /// true, the time is in seconds; otherwise, milliseconds. + /// Prints a (minimum) 8 character padded time. /// - /// Example: ' 0.5s', '150ms', '1600ms' + /// 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() { - if (expectSlowOperation) { - stdout.write(getElapsedAsSeconds(stopwatch.elapsed).padLeft(5)); - } else { - stdout.write(getElapsedAsMilliseconds(stopwatch.elapsed).padLeft(5)); - } + stdout.write(elapsedTime.padLeft(8)); + if (seemsSlow) + stdout.write(' (!)'); } } 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 dfa33772555..67459102641 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(); @@ -620,7 +620,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 63316afdfa4..95f54102094 100644 --- a/packages/flutter_tools/lib/src/commands/attach.dart +++ b/packages/flutter_tools/lib/src/commands/attach.dart @@ -149,7 +149,7 @@ class AttachCommand extends FlutterCommand { } final Status status = logger.startProgress( 'Waiting for a connection from Flutter on ${device.name}...', - expectSlowOperation: true, + timeout: kSlowOperation, ); try { final int localPort = await device.findIsolatePort(module, localPorts); @@ -179,7 +179,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(); } @@ -217,20 +217,29 @@ class AttachCommand extends FlutterCommand { flutterDevice.startEchoingDeviceLog(); } + int result; if (daemon != null) { AppInstance app; try { - app = await daemon.appDomain.launch(hotRunner, hotRunner.attach, - device, null, true, fs.currentDirectory); + app = await daemon.appDomain.launch( + hotRunner, + hotRunner.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 hotRunner.attach(); + result = await hotRunner.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_aot.dart b/packages/flutter_tools/lib/src/commands/build_aot.dart index d7ad96e1639..52be625ec10 100644 --- a/packages/flutter_tools/lib/src/commands/build_aot.dart +++ b/packages/flutter_tools/lib/src/commands/build_aot.dart @@ -71,7 +71,7 @@ class BuildAotCommand extends BuildSubCommand { final String typeName = artifacts.getEngineType(platform, buildMode); status = logger.startProgress( 'Building AOT snapshot in ${getModeName(getBuildMode())} mode ($typeName)...', - expectSlowOperation: true, + timeout: kSlowOperation, ); } final String outputPath = argResults['output-dir'] ?? getAotBuildDirectory(); diff --git a/packages/flutter_tools/lib/src/commands/daemon.dart b/packages/flutter_tools/lib/src/commands/daemon.dart index 30b5d702106..e7d3bb0a6d3 100644 --- a/packages/flutter_tools/lib/src/commands/daemon.dart +++ b/packages/flutter_tools/lib/src/commands/daemon.dart @@ -428,11 +428,12 @@ 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 { @@ -515,14 +516,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 +534,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 +775,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 +952,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 +966,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/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 b0e6cadee83..aef2311183d 100644 --- a/packages/flutter_tools/lib/src/commands/update_packages.dart +++ b/packages/flutter_tools/lib/src/commands/update_packages.dart @@ -95,7 +95,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 3c6d378e67c..0d7677ca096 100644 --- a/packages/flutter_tools/lib/src/device.dart +++ b/packages/flutter_tools/lib/src/device.dart @@ -150,7 +150,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 e9a34a06686..392a7d4df9b 100644 --- a/packages/flutter_tools/lib/src/doctor.dart +++ b/packages/flutter_tools/lib/src/doctor.dart @@ -184,7 +184,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; @@ -286,6 +289,8 @@ abstract class DoctorValidator { final String title; + String get slowWarning => 'This is taking an unexpectedly long time...'; + Future validate(); } @@ -298,6 +303,10 @@ class GroupedValidator extends DoctorValidator { final List subValidators; + @override + String get slowWarning => _currentSlowWarning; + String _currentSlowWarning = 'Initializing...'; + @override Future validate() async { final List tasks = []; @@ -307,8 +316,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); } @@ -671,6 +682,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/ios/cocoapods.dart b/packages/flutter_tools/lib/src/ios/cocoapods.dart index 26a903d2829..9302ba37b75 100644 --- a/packages/flutter_tools/lib/src/ios/cocoapods.dart +++ b/packages/flutter_tools/lib/src/ios/cocoapods.dart @@ -220,7 +220,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 f18f1450d2f..e0c802a623b 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'; @@ -72,11 +71,13 @@ 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, - compileExpression: compileExpression); + localVmServices[i] = await VMService.connect( + observatoryUris[i], + reloadSources: reloadSources, + compileExpression: compileExpression, + ); printTrace('Successfully connected to service protocol: ${observatoryUris[i]}'); } vmServices = localVmServices; @@ -112,13 +113,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, @@ -382,7 +386,7 @@ class FlutterDevice { }) async { final Status devFSStatus = logger.startProgress( 'Syncing files to device ${device.name}...', - expectSlowOperation: true, + timeout: kFastOperation, ); int bytes = 0; try { @@ -474,11 +478,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, }); bool get supportsRestart => false; @@ -493,7 +500,7 @@ abstract class ResidentRunner { await _debugSaveCompilationTrace(); await stopEchoingDeviceLog(); await preStop(); - return stopApp(); + await stopApp(); } Future detach() async { @@ -558,7 +565,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) { @@ -673,24 +680,32 @@ 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, 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) { - await device._connect(reloadSources: reloadSources, - compileExpression: compileExpression); + await device._connect( + reloadSources: reloadSources, + compileExpression: compileExpression, + ); 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) { @@ -841,12 +856,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; } @@ -867,8 +883,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 f85a53f996e..80b066b0ccc 100644 --- a/packages/flutter_tools/lib/src/run_cold.dart +++ b/packages/flutter_tools/lib/src/run_cold.dart @@ -64,8 +64,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. diff --git a/packages/flutter_tools/lib/src/run_hot.dart b/packages/flutter_tools/lib/src/run_hot.dart index d03e02fa3cc..f95ca497828 100644 --- a/packages/flutter_tools/lib/src/run_hot.dart +++ b/packages/flutter_tools/lib/src/run_hot.dart @@ -159,6 +159,7 @@ class HotRunner extends ResidentRunner { throw 'Failed to compile $expression'; } + // Returns the exit code of the flutter tool process, like [run]. Future attach({ Completer connectionInfoCompleter, Completer appStartedCompleter, @@ -241,10 +242,11 @@ class HotRunner extends ResidentRunner { return 0; } + int result = 0; if (stayResident) - return waitForAppToFinish(); + result = await waitForAppToFinish(); await cleanupAtFinish(); - return 0; + return result; } @override @@ -391,22 +393,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, @@ -557,6 +558,7 @@ class HotRunner extends ResidentRunner { } final Status status = logger.startProgress( 'Performing hot restart...', + timeout: kFastOperation, progressId: 'hot.restart', ); try { @@ -573,25 +575,44 @@ 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 { + Future _reloadSources({ bool pause = false, String reason, void Function(String message) onSlow }) async { final Map analyticsParameters = reason == null ? null @@ -603,25 +624,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 bool updatedDevFS = await _updateDevFS(); // Record time it took to synchronize to DevFS. - _addBenchmarkData('hotReloadDevFSSyncMilliseconds', - devFSTimer.elapsed.inMilliseconds); + _addBenchmarkData('hotReloadDevFSSyncMilliseconds', devFSTimer.elapsed.inMilliseconds); if (!updatedDevFS) return OperationResult(1, 'DevFS synchronization failed'); String reloadMessage; @@ -638,7 +658,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( @@ -654,7 +673,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]; @@ -670,29 +688,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 = >[]; @@ -709,73 +724,144 @@ 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(); - printTrace('Hot reload performed in ${getElapsedAsMilliseconds(reloadTimer.elapsed)}.'); - // Record complete time it took for the reload. - _addBenchmarkData('hotReloadMillisecondsToFrame', - reloadTimer.elapsed.inMilliseconds); - // 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(reloadTimer.elapsed)}.'); + // Record complete time it took for the reload. + _addBenchmarkData('hotReloadMillisecondsToFrame', reloadTimer.elapsed.inMilliseconds); + } + // Only report timings if we reloaded a single view without any errors. + if ((reassembleViews.length == 1) && !failedReassemble && shouldReportReloadTime) flutterUsage.sendTiming('hot', 'reload', reloadTimer.elapsed); 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) { @@ -787,7 +873,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 9f05b0019d9..32f68f8adbf 100644 --- a/packages/flutter_tools/lib/src/runner/flutter_command.dart +++ b/packages/flutter_tools/lib/src/runner/flutter_command.dart @@ -454,19 +454,17 @@ 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('"flutter $name" took ${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) { + if (commandPath != null) { final List labels = []; if (commandResult?.exitStatus != null) labels.add(getEnumName(commandResult.exitStatus)); @@ -500,7 +498,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 @@ -516,8 +514,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..3f0cec056ea 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. +/// +/// 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: 1); /// 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..a5c5bccb31a 100644 --- a/packages/flutter_tools/lib/src/tracing.dart +++ b/packages/flutter_tools/lib/src/tracing.dart @@ -35,14 +35,12 @@ class Tracing { bool waitForFirstFrame = 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) { @@ -50,24 +48,10 @@ class Tracing { 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; - } - ); - + await whenFirstFrameRendered.future; timeline = await vmService.vm.getVMTimeline(); - await vmService.vm.setVMTimelineFlags([]); } - return timeline; } } diff --git a/packages/flutter_tools/lib/src/vmservice.dart b/packages/flutter_tools/lib/src/vmservice.dart index 83f837a6824..8afc2bec3b8 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); @@ -56,60 +61,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, CompileExpression compileExpression, ) { @@ -218,9 +209,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 @@ -229,14 +217,13 @@ class VMService { /// See: https://github.com/dart-lang/sdk/commit/df8bf384eb815cf38450cb50a0f4b62230fba217 static Future connect( Uri httpUri, { - Duration requestTimeout = kDefaultRequestTimeout, ReloadSources reloadSources, CompileExpression compileExpression, }) async { 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, compileExpression); + final VMService service = VMService(peer, httpUri, wsUri, reloadSources, 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 {}); @@ -246,7 +233,6 @@ class VMService { final Uri httpAddress; final Uri wsAddress; final rpc.Peer _peer; - final Duration _requestTimeout; final Completer> _connectionError = Completer>(); VM _vm; @@ -811,28 +797,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; @@ -846,12 +819,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)) { @@ -938,7 +909,7 @@ class VM extends ServiceObjectOwner { } Future> getVMTimeline() { - return invokeRpcRaw('_getVMTimeline', timeout: kLongRequestTimeout); + return invokeRpcRaw('_getVMTimeline'); } Future refreshViews({ bool waitForViews = false }) async { @@ -952,10 +923,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; @@ -1094,8 +1062,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) { @@ -1105,7 +1071,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. @@ -1227,40 +1193,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 { @@ -1269,8 +1231,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; @@ -1282,22 +1242,19 @@ 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 flutterFrameworkPresent() async { + return await invokeFlutterExtensionRpcRaw('ext.flutter.frameworkPresent') != null; } Future> uiWindowScheduleFrame() { @@ -1305,7 +1262,8 @@ class Isolate extends ServiceObjectOwner { } Future> flutterEvictAsset(String assetPath) { - return invokeFlutterExtensionRpcRaw('ext.flutter.evict', + return invokeFlutterExtensionRpcRaw( + 'ext.flutter.evict', params: { 'value': assetPath, } @@ -1322,19 +1280,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..0cf31953c5d 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} [\b]\\$' : + r'^Hello {15} {5} [\b]⣽$')); + status.stop(); + expect(outputStdout().join('\n'), matches(platform.isWindows ? r'^Hello {15} {5} [\b]\\[\b] [\b][\d, ]{4}[\d]\.[\d]s[\n]$' : + r'^Hello {15} {5} [\b]⣽[\b] [\b][\d, ]{4}[\d]\.[\d]s[\n]$')); + done = true; + }); + expect(done, isTrue); }, overrides: { Logger: () => StdoutLogger(), OutputPreferences: () => OutputPreferences(showColor: true), @@ -138,58 +181,105 @@ void main() { 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-' + : 'Hello world \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); + expect(lines[0], endsWith('\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], matches( + platform.isWindows + ? r'^Hello world [\b]\\[\b]|[\b]/[\b]-[\b]\\[\b]|[\b]/[\b]-$' + : r'^Hello world [\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 [\b]\\[\b]|[\b]/[\b]-[\b]\\[\b]|[\b]/[\b]-[\b] [\b][\d., ]{5}[\d]ms$' + : r'^Hello world [\b]⣽[\b]⣻[\b]⢿[\b]⡿[\b]⣟[\b]⣯[\b]⣷[\b]⣾[\b]⣽[\b]⣻[\b] [\b][\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 +297,7 @@ void main() { called = 0; summaryStatus = SummaryStatus( message: 'Hello world', - expectSlowOperation: true, + timeout: kSlowOperation, padding: 20, onFinish: () => called++, ); @@ -217,7 +307,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 +324,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 +344,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 +364,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 +384,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 +401,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 +421,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 +441,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 +461,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 +475,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 +488,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 +506,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 +526,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 +600,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 +618,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 +635,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 fbe80a3797f..ad22047ecb6 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 d8b33a34cf5..3156bc3e16f 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 6610ee60471..415e826fc6d 100644 --- a/packages/flutter_tools/test/integration/expression_evaluation_test.dart +++ b/packages/flutter_tools/test/integration/expression_evaluation_test.dart @@ -31,16 +31,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 { @@ -78,7 +80,8 @@ 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. } 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 dff11325714..34e4366a1a8 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(); 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 e597370265f..e4eeb15700e 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 b7e9602cde0..aa1f8c99ea6 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 f8faa038bed..6bb49eefd10 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_driver.dart b/packages/flutter_tools/test/integration/test_driver.dart index 18a9e84b4c2..e4a3ae50127 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,71 +57,79 @@ 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, { 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]); } - _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 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; @@ -125,75 +148,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 { @@ -230,26 +284,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'); } @@ -260,76 +317,118 @@ 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 Future _setupProcess( List args, { bool withDebugger = false, + bool startPaused = false, bool pauseOnExceptions = false, File pidFile, }) async { + assert(!startPaused || withDebugger); await super._setupProcess( args, withDebugger: withDebugger, @@ -338,46 +437,44 @@ class FlutterRunTestDriver extends FlutterTestDriver { ); // 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); - _vmService = - await vmServiceConnectUri(_vmServiceWsUri.toString()); - _vmService.onSend.listen((String s) => _debugPrint('==> $s')); - _vmService.onReceive.listen((String s) => _debugPrint('<== $s')); + _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'), ]); - // 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); + await _vmService.setExceptionPauseMode( + await _getFlutterIsolateId(), + ExceptionPauseMode.kUnhandled, + ); } - await resume(wait: false); + if (!startPaused) + await resume(); } // Now await the started event; if it had already happened the future will @@ -392,24 +489,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}, @@ -420,19 +519,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}, @@ -443,27 +542,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++; @@ -473,16 +558,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) @@ -491,8 +576,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(); } } @@ -503,8 +588,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 6f056ce59be..b0665913d45 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); + final VMService vmService = VMService(mockPeer, null, null, null, null); vmService.getVM().then((void value) { done = true; }); expect(done, isFalse); expect(mockPeer.returnedFromSendRequest, 0);