Stream logging from attached debugger on iOS (#66092) (#66390)

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

@@ -212,6 +212,9 @@ class IOSDevice extends Device {
 
   DevicePortForwarder _portForwarder;
 
+  @visibleForTesting
+  IOSDeployDebugger iosDeployDebugger;
+
   @override
   Future<bool> get isLocalEmulator async => false;
 
@@ -395,23 +398,38 @@ class IOSDevice extends Device {
         timeout: timeoutConfiguration.slowOperation);
     try {
       ProtocolDiscovery observatoryDiscovery;
+      int installationResult = 1;
       if (debuggingOptions.debuggingEnabled) {
         _logger.printTrace('Debugging is enabled, connecting to observatory');
+        iosDeployDebugger = _iosDeploy.prepareDebuggerForLaunch(
+          deviceId: id,
+          bundlePath: bundle.path,
+          launchArguments: launchArguments,
+          interfaceType: interfaceType,
+        );
+
+        final DeviceLogReader deviceLogReader = getLogReader(app: package);
+        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),
+        );
+        installationResult = await iosDeployDebugger.launchAndAttach() ? 0 : 1;
+      } else {
+        installationResult = await _iosDeploy.launchApp(
+          deviceId: id,
+          bundlePath: bundle.path,
+          launchArguments: launchArguments,
+          interfaceType: interfaceType,
         );
       }
-      final int installationResult = await _iosDeploy.runApp(
-        deviceId: id,
-        bundlePath: bundle.path,
-        launchArguments: launchArguments,
-        interfaceType: interfaceType,
-      );
       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:');
@@ -465,7 +483,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;
   }
 
@@ -655,6 +677,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;
 
@@ -687,6 +716,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);
@@ -699,6 +732,26 @@ 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) {
@@ -758,6 +811,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;
 

packages/flutter_tools/test/general.shard/ios/ios_device_start_prebuilt_test.dart

@@ -67,19 +67,25 @@ const FakeCommand kLaunchReleaseCommand = FakeCommand(
 
 // The command used to actually launch the app with args in debug.
 const FakeCommand kLaunchDebugCommand = FakeCommand(command: <String>[
+  'script',
+  '-t',
+  '0',
+  '/dev/null',
   'ios-deploy',
   '--id',
   '123',
   '--bundle',
   '/',
+  '--debug',
   '--no-wifi',
-  '--justlaunch',
   '--args',
   '--enable-dart-profiling --enable-service-port-fallback --disable-service-auth-codes --observatory-port=60700 --enable-checked-mode --verify-entry-points'
 ], environment: <String, String>{
   'PATH': '/usr/bin:null',
   'DYLD_LIBRARY_PATH': '/path/to/libraries',
-});
+},
+stdout: '(lldb)     run\nsuccess',
+);
 
 void main() {
   // TODO(jonahwilliams): This test doesn't really belong here but
@@ -102,7 +108,7 @@ void main() {
   });
 
   // Still uses context for analytics and mDNS.
-  testUsingContext('IOSDevice.startApp succeeds in debug mode via mDNS discovery', () async {
+  testUsingContext('IOSDevice.startApp succeeds in debug mode via mDNS discovery when log reading fails', () async {
     final FileSystem fileSystem = MemoryFileSystem.test();
     final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
       kDeployCommand,
@@ -145,6 +151,7 @@ void main() {
       debuggingOptions: DebuggingOptions.enabled(BuildInfo.debug),
       platformArgs: <String, dynamic>{},
       fallbackPollingDelay: Duration.zero,
+      fallbackThrottleTimeout: const Duration(milliseconds: 10),
     );
 
     verify(globals.flutterUsage.sendEvent('ios-handshake', 'mdns-success')).called(1);
@@ -157,7 +164,7 @@ void main() {
   });
 
   // Still uses context for analytics and mDNS.
-  testUsingContext('IOSDevice.startApp succeeds in debug mode when mDNS fails', () async {
+  testUsingContext('IOSDevice.startApp succeeds in debug mode via log reading', () async {
     final FileSystem fileSystem = MemoryFileSystem.test();
     final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
       kDeployCommand,
@@ -183,34 +190,32 @@ void main() {
     device.portForwarder = const NoOpDevicePortForwarder();
     device.setLogReader(iosApp, deviceLogReader);
 
-    // Now that the reader is used, start writing messages to it.
+    // Start writing messages to the log reader.
     Timer.run(() {
       deviceLogReader.addLine('Foo');
       deviceLogReader.addLine('Observatory listening on http://127.0.0.1:456');
     });
-    when(MDnsObservatoryDiscovery.instance.getObservatoryUri(any, any, usesIpv6: anyNamed('usesIpv6')))
-      .thenAnswer((Invocation invocation) async => null);
 
     final LaunchResult launchResult = await device.startApp(iosApp,
       prebuiltApplication: true,
       debuggingOptions: DebuggingOptions.enabled(BuildInfo.debug),
       platformArgs: <String, dynamic>{},
       fallbackPollingDelay: Duration.zero,
+      fallbackThrottleTimeout: const Duration(milliseconds: 10),
     );
 
     expect(launchResult.started, true);
     expect(launchResult.hasObservatory, true);
-    verify(globals.flutterUsage.sendEvent('ios-handshake', 'mdns-failure')).called(1);
-    verify(globals.flutterUsage.sendEvent('ios-handshake', 'fallback-success')).called(1);
+    verify(globals.flutterUsage.sendEvent('ios-handshake', 'log-success')).called(1);
+    verifyNever(globals.flutterUsage.sendEvent('ios-handshake', 'mdns-failure'));
     expect(await device.stopApp(iosApp), false);
   }, overrides: <Type, Generator>{
-    Usage: () => MockUsage(),
     MDnsObservatoryDiscovery: () => MockMDnsObservatoryDiscovery(),
+    Usage: () => MockUsage(),
   });
 
   // Still uses context for analytics and mDNS.
-  testUsingContext('IOSDevice.startApp fails in debug mode when mDNS fails and '
-    'when Observatory URI is malformed', () async {
+  testUsingContext('IOSDevice.startApp fails in debug mode when Observatory URI is malformed', () async {
     final FileSystem fileSystem = MemoryFileSystem.test();
     final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
       kDeployCommand,
@@ -239,16 +244,15 @@ void main() {
     // Now that the reader is used, start writing messages to it.
     Timer.run(() {
       deviceLogReader.addLine('Foo');
-      deviceLogReader.addLine('Observatory listening on http:/:/127.0.0.1:456');
+      deviceLogReader.addLine('Observatory listening on http://127.0.0.1:456abc');
     });
-    when(MDnsObservatoryDiscovery.instance.getObservatoryUri(any, any, usesIpv6: anyNamed('usesIpv6')))
-      .thenAnswer((Invocation invocation) async => null);
 
     final LaunchResult launchResult = await device.startApp(iosApp,
       prebuiltApplication: true,
       debuggingOptions: DebuggingOptions.enabled(BuildInfo.debug),
       platformArgs: <String, dynamic>{},
       fallbackPollingDelay: Duration.zero,
+      // fallbackThrottleTimeout: const Duration(milliseconds: 10),
     );
 
     expect(launchResult.started, false);
@@ -259,8 +263,8 @@ void main() {
       label: anyNamed('label'),
       value: anyNamed('value'),
     )).called(1);
+    verify(globals.flutterUsage.sendEvent('ios-handshake', 'log-failure')).called(1);
     verify(globals.flutterUsage.sendEvent('ios-handshake', 'mdns-failure')).called(1);
-    verify(globals.flutterUsage.sendEvent('ios-handshake', 'fallback-failure')).called(1);
     }, overrides: <Type, Generator>{
       MDnsObservatoryDiscovery: () => MockMDnsObservatoryDiscovery(),
       Usage: () => MockUsage(),
@@ -388,6 +392,7 @@ void main() {
       debuggingOptions: DebuggingOptions.disabled(BuildInfo.release),
       platformArgs: <String, dynamic>{},
       fallbackPollingDelay: Duration.zero,
+      fallbackThrottleTimeout: const Duration(milliseconds: 10),
     );
 
     expect(launchResult.started, true);
@@ -405,13 +410,17 @@ void main() {
       kDeployCommand,
       FakeCommand(
         command: <String>[
+          'script',
+          '-t',
+          '0',
+          '/dev/null',
           'ios-deploy',
           '--id',
           '123',
           '--bundle',
           '/',
+          '--debug',
           '--no-wifi',
-          '--justlaunch',
           // The arguments below are determined by what is passed into
           // the debugging options argument to startApp.
           '--args',
@@ -436,7 +445,8 @@ void main() {
         ], environment: const <String, String>{
           'PATH': '/usr/bin:null',
           'DYLD_LIBRARY_PATH': '/path/to/libraries',
-        }
+        },
+        stdout: '(lldb)     run\nsuccess',
       )
     ]);
     final IOSDevice device = setUpIOSDevice(
@@ -455,22 +465,15 @@ void main() {
       bundleName: 'Runner',
       bundleDir: fileSystem.currentDirectory,
     );
-    final Uri uri = Uri(
-      scheme: 'http',
-      host: '127.0.0.1',
-      port: 1234,
-      path: 'observatory',
-    );
+    final FakeDeviceLogReader deviceLogReader = FakeDeviceLogReader();
 
-    device.setLogReader(iosApp, FakeDeviceLogReader());
     device.portForwarder = const NoOpDevicePortForwarder();
+    device.setLogReader(iosApp, deviceLogReader);
 
-    when(MDnsObservatoryDiscovery.instance.getObservatoryUri(
-      any,
-      any,
-      usesIpv6: anyNamed('usesIpv6'),
-      hostVmservicePort: anyNamed('hostVmservicePort')
-    )).thenAnswer((Invocation invocation) async => uri);
+    // Start writing messages to the log reader.
+    Timer.run(() {
+      deviceLogReader.addLine('Observatory listening on http://127.0.0.1:1234');
+    });
 
     final LaunchResult launchResult = await device.startApp(iosApp,
       prebuiltApplication: true,
@@ -492,6 +495,7 @@ void main() {
       ),
       platformArgs: <String, dynamic>{},
       fallbackPollingDelay: Duration.zero,
+      fallbackThrottleTimeout: const Duration(milliseconds: 10),
     );
 
     expect(launchResult.started, true);