Stream logging from attached debugger on iOS 13+ (#66399)

dev/automated_tests/flutter_run_test/flutter_run_test.dart

@@ -2,11 +2,15 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+import 'dart:io';
+
 import 'package:flutter_test/flutter_test.dart';
 
 void main() {
   group('example', () {
     test('passed', () {
+      print('This is print');
+      stderr.writeln('This is writeln');
       expect(true, true);
     });
     test('failed', () {

dev/devicelab/bin/tasks/flutter_run_test.dart

@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 import 'dart:async';
+import 'dart:convert';
 import 'dart:io';
 
 import 'package:path/path.dart' as path;
@@ -19,9 +20,10 @@ const Pattern passedMessageMatch = '+0: example passed';
 const Pattern failedMessageMatch = '+1: example failed [E]';
 const Pattern skippedMessageMatch = '+1 -1: example skipped';
 const Pattern finishedMessageMatch = '+1 ~1 -1: Some tests failed.';
+const Pattern printMessageMatch = 'This is print';
+const Pattern writelnMessageMatch = 'This is writeln';
 
 Future<void> main() async {
-  deviceOperatingSystem = DeviceOperatingSystem.android;
   await task(createFlutterRunTask);
 }
 
@@ -31,19 +33,26 @@ Future<TaskResult> createFlutterRunTask() async {
   bool failedTest = false;
   bool skippedTest = false;
   bool finishedMessage = false;
+  bool printMessage = false;
+  bool writelnMessage = false;
   final Device device = await devices.workingDevice;
   await device.unlock();
   final List<String> options = <String>[
-    '-t', runTestSource.absolute.path, '-d', device.deviceId,
+    '-t', runTestSource.absolute.path, '-d', device.deviceId, '-v',
   ];
   await inDirectory<void>(flutterGalleryDir, () async {
-    startProcess(
+    final Process run = await startProcess(
       path.join(flutterDirectory.path, 'bin', 'flutter'),
       flutterCommandArgs('run', options),
       environment: null,
     );
+
     final Completer<void> finished = Completer<void>();
-    final StreamSubscription<void> subscription = device.logcat.listen((String line) {
+    final StreamSubscription<void> subscription = run.stdout
+        .transform<String>(utf8.decoder)
+        .transform<String>(const LineSplitter())
+        .listen((String line) {
+      print('stdout: $line');
       // tests execute in order.
       if (line.contains(passedMessageMatch)) {
         passedTest = true;
@@ -51,6 +60,10 @@ Future<TaskResult> createFlutterRunTask() async {
         failedTest = true;
       } else if (line.contains(skippedMessageMatch)) {
         skippedTest = true;
+      } else if (line.contains(printMessageMatch)) {
+        printMessage = true;
+      } else if (line.contains(writelnMessageMatch)) {
+        writelnMessage = true;
       } else if (line.contains(finishedMessageMatch)) {
         finishedMessage = true;
         finished.complete();
@@ -58,8 +71,9 @@ Future<TaskResult> createFlutterRunTask() async {
     });
     await finished.future.timeout(const Duration(minutes: 1));
     subscription.cancel();
+    run.kill();
   });
-  return passedTest && failedTest && skippedTest && finishedMessage
+  return passedTest && failedTest && skippedTest && finishedMessage && printMessage && writelnMessage
     ? TaskResult.success(<String, dynamic>{})
     : TaskResult.failure('Test did not execute as expected.');
 }

packages/flutter_tools/lib/src/ios/devices.dart

@@ -213,6 +213,9 @@ class IOSDevice extends Device {
 
   DevicePortForwarder _portForwarder;
 
+  @visibleForTesting
+  IOSDeployDebugger iosDeployDebugger;
+
   @override
   Future<bool> get isLocalEmulator async => false;
 
@@ -396,23 +399,45 @@ class IOSDevice extends Device {
         timeout: timeoutConfiguration.slowOperation);
     try {
       ProtocolDiscovery observatoryDiscovery;
+      int installationResult = 1;
       if (debuggingOptions.debuggingEnabled) {
         _logger.printTrace('Debugging is enabled, connecting to observatory');
+        final DeviceLogReader deviceLogReader = getLogReader(app: package);
+
+        // If the device supports syslog reading, prefer launching the app without
+        // attaching the debugger to avoid the overhead of the unnecessary extra running process.
+        if (majorSdkVersion >= IOSDeviceLogReader.minimumUniversalLoggingSdkVersion) {
+          iosDeployDebugger = _iosDeploy.prepareDebuggerForLaunch(
+            deviceId: id,
+            bundlePath: bundle.path,
+            launchArguments: launchArguments,
+            interfaceType: interfaceType,
+          );
+
+          if (deviceLogReader is IOSDeviceLogReader) {
+            deviceLogReader.debuggerStream = iosDeployDebugger;
+          }
+        }
         observatoryDiscovery = ProtocolDiscovery.observatory(
-          getLogReader(app: package),
+          deviceLogReader,
           portForwarder: portForwarder,
+          throttleDuration: fallbackPollingDelay,
+          throttleTimeout: fallbackThrottleTimeout ?? const Duration(seconds: 5),
           hostPort: debuggingOptions.hostVmServicePort,
           devicePort: debuggingOptions.deviceVmServicePort,
           ipv6: ipv6,
-          throttleTimeout: fallbackThrottleTimeout ?? const Duration(seconds: 1),
         );
       }
-      final int installationResult = await _iosDeploy.runApp(
-        deviceId: id,
-        bundlePath: bundle.path,
-        launchArguments: launchArguments,
-        interfaceType: interfaceType,
-      );
+      if (iosDeployDebugger == null) {
+        installationResult = await _iosDeploy.launchApp(
+          deviceId: id,
+          bundlePath: bundle.path,
+          launchArguments: launchArguments,
+          interfaceType: interfaceType,
+        );
+      } else {
+        installationResult = await iosDeployDebugger.launchAndAttach() ? 0 : 1;
+      }
       if (installationResult != 0) {
         _logger.printError('Could not run ${bundle.path} on $id.');
         _logger.printError('Try launching Xcode and selecting "Product > Run" to fix the problem:');
@@ -466,7 +491,11 @@ class IOSDevice extends Device {
     IOSApp app, {
     String userIdentifier,
   }) async {
-    // Currently we don't have a way to stop an app running on iOS.
+    // If the debugger is not attached, killing the ios-deploy process won't stop the app.
+    if (iosDeployDebugger!= null && iosDeployDebugger.debuggerAttached) {
+      // Avoid null.
+      return iosDeployDebugger?.exit() == true;
+    }
     return false;
   }
 
@@ -656,6 +685,13 @@ class IOSDeviceLogReader extends DeviceLogReader {
   // Matches a syslog line from any app.
   RegExp _anyLineRegex;
 
+  // Logging from native code/Flutter engine is prefixed by timestamp and process metadata:
+  // 2020-09-15 19:15:10.931434-0700 Runner[541:226276] Did finish launching.
+  // 2020-09-15 19:15:10.931434-0700 Runner[541:226276] [Category] Did finish launching.
+  //
+  // Logging from the dart code has no prefixing metadata.
+  final RegExp _debuggerLoggingRegex = RegExp(r'^\S* \S* \S*\[[0-9:]*] (.*)');
+
   StreamController<String> _linesController;
   List<StreamSubscription<void>> _loggingSubscriptions;
 
@@ -672,10 +708,10 @@ class IOSDeviceLogReader extends DeviceLogReader {
     _connectedVMService = connectedVmService;
   }
 
-  static const int _minimumUniversalLoggingSdkVersion = 13;
+  static const int minimumUniversalLoggingSdkVersion = 13;
 
   Future<void> _listenToUnifiedLoggingEvents(vm_service.VmService connectedVmService) async {
-    if (_majorSdkVersion < _minimumUniversalLoggingSdkVersion) {
+    if (_majorSdkVersion < minimumUniversalLoggingSdkVersion) {
       return;
     }
     try {
@@ -692,6 +728,10 @@ class IOSDeviceLogReader extends DeviceLogReader {
     }
 
     void logMessage(vm_service.Event event) {
+      if (_iosDeployDebugger != null && _iosDeployDebugger.debuggerAttached) {
+        // Prefer the more complete logs from the  attached debugger.
+        return;
+      }
       final String message = processVmServiceMessage(event);
       if (message.isNotEmpty) {
         _linesController.add(message);
@@ -704,9 +744,29 @@ class IOSDeviceLogReader extends DeviceLogReader {
     ]);
   }
 
+  /// Log reader will listen to [debugger.logLines] and will detach debugger on dispose.
+  set debuggerStream(IOSDeployDebugger debugger) {
+    // Logging is gathered from syslog on iOS 13 and earlier.
+    if (_majorSdkVersion < minimumUniversalLoggingSdkVersion) {
+      return;
+    }
+    _iosDeployDebugger = debugger;
+    // Add the debugger logs to the controller created on initialization.
+    _loggingSubscriptions.add(debugger.logLines.listen(
+      (String line) => _linesController.add(_debuggerLineHandler(line)),
+      onError: _linesController.addError,
+      onDone: _linesController.close,
+      cancelOnError: true,
+    ));
+  }
+  IOSDeployDebugger _iosDeployDebugger;
+
+  // Strip off the logging metadata (leave the category), or just echo the line.
+  String _debuggerLineHandler(String line) => _debuggerLoggingRegex?.firstMatch(line)?.group(1) ?? line;
+
   void _listenToSysLog() {
     // syslog is not written on iOS 13+.
-    if (_majorSdkVersion >= _minimumUniversalLoggingSdkVersion) {
+    if (_majorSdkVersion >= minimumUniversalLoggingSdkVersion) {
       return;
     }
     _iMobileDevice.startLogger(_deviceId).then<void>((Process process) {
@@ -763,6 +823,7 @@ class IOSDeviceLogReader extends DeviceLogReader {
       loggingSubscription.cancel();
     }
     _idevicesyslogProcess?.kill();
+    _iosDeployDebugger?.detach();
   }
 }
 

packages/flutter_tools/lib/src/ios/fallback_discovery.dart

@@ -82,50 +82,50 @@ class FallbackDiscovery {
     }
 
     try {
-      final Uri result = await _mDnsObservatoryDiscovery.getObservatoryUri(
-        packageId,
-        device,
-        usesIpv6: usesIpv6,
-        hostVmservicePort: hostVmservicePort,
-      );
+      final Uri result = await _protocolDiscovery.uri;
       if (result != null) {
         UsageEvent(
           _kEventName,
-          'mdns-success',
+          'log-success',
           flutterUsage: _flutterUsage,
         ).send();
         return result;
       }
+    } on ArgumentError {
+      // In the event of an invalid InternetAddress, this code attempts to catch
+      // an ArgumentError from protocol_discovery.dart
     } on Exception catch (err) {
       _logger.printTrace(err.toString());
     }
-    _logger.printTrace('Failed to connect with mDNS, falling back to log scanning');
+    _logger.printTrace('Failed to connect with log scanning, falling back to mDNS');
     UsageEvent(
       _kEventName,
-      'mdns-failure',
+      'log-failure',
       flutterUsage: _flutterUsage,
     ).send();
 
     try {
-      final Uri result = await _protocolDiscovery.uri;
+      final Uri result = await _mDnsObservatoryDiscovery.getObservatoryUri(
+        packageId,
+        device,
+        usesIpv6: usesIpv6,
+        hostVmservicePort: hostVmservicePort,
+      );
       if (result != null) {
         UsageEvent(
           _kEventName,
-          'fallback-success',
+          'mdns-success',
           flutterUsage: _flutterUsage,
         ).send();
         return result;
       }
-    } on ArgumentError {
-    // In the event of an invalid InternetAddress, this code attempts to catch
-    // an ArgumentError from protocol_discovery.dart
     } on Exception catch (err) {
       _logger.printTrace(err.toString());
     }
-    _logger.printTrace('Failed to connect with log scanning');
+    _logger.printTrace('Failed to connect with mDNS');
     UsageEvent(
       _kEventName,
-      'fallback-failure',
+      'mdns-failure',
       flutterUsage: _flutterUsage,
     ).send();
     return null;
@@ -148,7 +148,7 @@ class FallbackDiscovery {
       assumedWsUri = Uri.parse('ws://localhost:$hostPort/ws');
     } on Exception catch (err) {
       _logger.printTrace(err.toString());
-      _logger.printTrace('Failed to connect directly, falling back to mDNS');
+      _logger.printTrace('Failed to connect directly, falling back to log scanning');
       _sendFailureEvent(err, assumedDevicePort);
       return null;
     }

packages/flutter_tools/lib/src/protocol_discovery.dart

@@ -34,7 +34,7 @@ class ProtocolDiscovery {
   factory ProtocolDiscovery.observatory(
     DeviceLogReader logReader, {
     DevicePortForwarder portForwarder,
-    Duration throttleDuration = const Duration(milliseconds: 200),
+    Duration throttleDuration,
     Duration throttleTimeout,
     @required int hostPort,
     @required int devicePort,
@@ -45,7 +45,7 @@ class ProtocolDiscovery {
       logReader,
       kObservatoryService,
       portForwarder: portForwarder,
-      throttleDuration: throttleDuration,
+      throttleDuration: throttleDuration ?? const Duration(milliseconds: 200),
       throttleTimeout: throttleTimeout,
       hostPort: hostPort,
       devicePort: devicePort,
@@ -225,7 +225,7 @@ class _BufferedStreamController<T> {
 ///
 /// For example, consider a `waitDuration` of `10ms`, and list of event names
 /// and arrival times: `a (0ms), b (5ms), c (11ms), d (21ms)`.
-/// The events `c` and `d` will be produced as a result.
+/// The events `a`, `c`, and `d` will be produced as a result.
 StreamTransformer<S, S> _throttle<S>({
   @required Duration waitDuration,
 }) {
@@ -240,10 +240,13 @@ StreamTransformer<S, S> _throttle<S>({
       handleData: (S value, EventSink<S> sink) {
         latestLine = value;
 
+        final bool isFirstMessage = lastExecution == null;
         final int currentTime = DateTime.now().millisecondsSinceEpoch;
         lastExecution ??= currentTime;
         final int remainingTime = currentTime - lastExecution;
-        final int nextExecutionTime = remainingTime > waitDuration.inMilliseconds
+
+        // Always send the first event immediately.
+        final int nextExecutionTime = isFirstMessage || remainingTime > waitDuration.inMilliseconds
           ? 0
           : waitDuration.inMilliseconds - remainingTime;