[flutter_tools] Re-land Dump backtrace on ios app startup timeout (#101763)

Author: christopherfujino

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

@@ -434,6 +434,7 @@ class IOSDevice extends Device {
       _logger.printTrace('Application launched on the device. Waiting for observatory url.');
       final Timer timer = Timer(discoveryTimeout ?? const Duration(seconds: 30), () {
         _logger.printError('iOS Observatory not discovered after 30 seconds. This is taking much longer than expected...');
+        iosDeployDebugger?.pauseDumpBacktraceResume();
       });
       final Uri? localUri = await observatoryDiscovery?.uri;
       timer.cancel();

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

@@ -296,12 +296,23 @@ class IOSDeployDebugger {
   // (lldb) Process 6152 detached
   static final RegExp _lldbProcessDetached = RegExp(r'Process \d* detached');
 
+  // (lldb) Process 6152 resuming
+  static final RegExp _lldbProcessResuming = RegExp(r'Process \d+ resuming');
+
   // Send signal to stop (pause) the app. Used before a backtrace dump.
   static const String _signalStop = 'process signal SIGSTOP';
 
+  static const String _processResume = 'process continue';
+  static const String _processInterrupt = 'process interrupt';
+
   // Print backtrace for all threads while app is stopped.
   static const String _backTraceAll = 'thread backtrace all';
 
+  /// If this is non-null, then the app process is paused and awaiting backtrace logging.
+  ///
+  /// The future should be completed once the backtraces are logged.
+  Completer<void>? _processResumeCompleter;
+
   /// Launch the app on the device, and attach the debugger.
   ///
   /// Returns whether or not the debugger successfully attached.
@@ -319,7 +330,6 @@ class IOSDeployDebugger {
           .transform<String>(const LineSplitter())
           .listen((String line) {
         _monitorIOSDeployFailure(line, _logger);
-
         // (lldb)     run
         // success
         // 2020-09-15 13:42:25.185474-0700 Runner[477:181141] flutter: The Dart VM service is listening on http://127.0.0.1:57782/
@@ -350,16 +360,26 @@ class IOSDeployDebugger {
           // Even though we're not "detached", just stopped, mark as detached so the backtrace
           // is only show in verbose.
           _debuggerState = _IOSDeployDebuggerState.detached;
+
+          // If we paused the app and are waiting to resume it, complete the completer
+          final Completer<void>? processResumeCompleter = _processResumeCompleter;
+          if (processResumeCompleter != null) {
+            _processResumeCompleter = null;
+            processResumeCompleter.complete();
+          }
           return;
         }
 
         if (line.contains('PROCESS_STOPPED') || _lldbProcessStopped.hasMatch(line)) {
           // The app has been stopped. Dump the backtrace, and detach.
           _logger.printTrace(line);
           _iosDeployProcess?.stdin.writeln(_backTraceAll);
-          detach();
+          if (_processResumeCompleter == null) {
+            detach();
+          }
           return;
         }
+
         if (line.contains('PROCESS_EXITED') || _lldbProcessExit.hasMatch(line)) {
           // The app exited or crashed, so exit. Continue passing debugging
           // messages to the log reader until it exits to capture crash dumps.
@@ -374,6 +394,13 @@ class IOSDeployDebugger {
           return;
         }
 
+        if (_lldbProcessResuming.hasMatch(line)) {
+          _logger.printTrace(line);
+          // we marked this detached when we received [_backTraceAll]
+          _debuggerState = _IOSDeployDebuggerState.attached;
+          return;
+        }
+
         if (_debuggerState != _IOSDeployDebuggerState.attached) {
           _logger.printTrace(line);
           return;
@@ -433,11 +460,28 @@ class IOSDeployDebugger {
     return success;
   }
 
-  Future<void> stopAndDumpBacktrace() async {
+  /// Pause app, dump backtrace for debugging, and resume.
+  Future<void> pauseDumpBacktraceResume() async {
     if (!debuggerAttached) {
       return;
     }
+    final Completer<void> completer = Completer<void>();
+    _processResumeCompleter = completer;
+    try {
+      // Stop the app, which will prompt the backtrace to be printed for all threads in the stdoutSubscription handler.
+      _iosDeployProcess?.stdin.writeln(_processInterrupt);
+    } on SocketException catch (error) {
+      _logger.printTrace('Could not stop app from debugger: $error');
+    }
+    // wait for backtrace to be dumped
+    await completer.future;
+    _iosDeployProcess?.stdin.writeln(_processResume);
+  }
 
+  Future<void> stopAndDumpBacktrace() async {
+    if (!debuggerAttached) {
+      return;
+    }
     try {
       // Stop the app, which will prompt the backtrace to be printed for all threads in the stdoutSubscription handler.
       _iosDeployProcess?.stdin.writeln(_signalStop);

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

@@ -330,6 +330,71 @@ void main () {
         'process detach',
       ]);
     });
+
+    testWithoutContext('pause with backtrace', () async {
+      final StreamController<List<int>> stdin = StreamController<List<int>>();
+      final Stream<String> stdinStream = stdin.stream.transform<String>(const Utf8Decoder());
+      const String stdout = '''
+(lldb)     run
+success
+Log on attach
+(lldb) Process 6156 stopped
+* thread #1, stop reason = Assertion failed:
+thread backtrace all
+process continue
+* thread #1, stop reason = signal SIGSTOP
+  * frame #0: 0x0000000102eaee80 dyld`dyld3::MachOFile::read_uleb128(Diagnostics&, unsigned char const*&, unsigned char const*) + 36
+    frame #1: 0x0000000102eabbd4 dyld`dyld3::MachOLoaded::trieWalk(Diagnostics&, unsigned char const*, unsigned char const*, char const*) + 332
+    frame #2: 0x0000000102eaa078 dyld`DyldSharedCache::hasImagePath(char const*, unsigned int&) const + 144
+    frame #3: 0x0000000102eaa13c dyld`DyldSharedCache::hasNonOverridablePath(char const*) const + 44
+    frame #4: 0x0000000102ebc404 dyld`dyld3::closure::ClosureBuilder::findImage(char const*, dyld3::closure::ClosureBuilder::LoadedImageChain const&, dyld3::closure::ClosureBuilder::BuilderLoadedImage*&, dyld3::closure::ClosureBuilder::LinkageType, unsigned int, bool) +
+
+    frame #5: 0x0000000102ebd974 dyld`invocation function for block in dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 136
+    frame #6: 0x0000000102eae1b0 dyld`invocation function for block in dyld3::MachOFile::forEachDependentDylib(void (char const*, bool, bool, bool, unsigned int, unsigned int, bool&) block_pointer) const + 136
+    frame #7: 0x0000000102eadc38 dyld`dyld3::MachOFile::forEachLoadCommand(Diagnostics&, void (load_command const*, bool&) block_pointer) const + 168
+    frame #8: 0x0000000102eae108 dyld`dyld3::MachOFile::forEachDependentDylib(void (char const*, bool, bool, bool, unsigned int, unsigned int, bool&) block_pointer) const + 116
+    frame #9: 0x0000000102ebd80c dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 164
+    frame #10: 0x0000000102ebd8a8 dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 320
+    frame #11: 0x0000000102ebd8a8 dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 320
+    frame #12: 0x0000000102ebd8a8 dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 320
+    frame #13: 0x0000000102ebd8a8 dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 320
+    frame #14: 0x0000000102ebd8a8 dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 320
+    frame #15: 0x0000000102ebd8a8 dyld`dyld3::closure::ClosureBuilder::recursiveLoadDependents(dyld3::closure::ClosureBuilder::LoadedImageChain&, bool) + 320
+    frame #16: 0x0000000102ec7638 dyld`dyld3::closure::ClosureBuilder::makeLaunchClosure(dyld3::closure::LoadedFileInfo const&, bool) + 752
+    frame #17: 0x0000000102e8fcf0 dyld`dyld::buildLaunchClosure(unsigned char const*, dyld3::closure::LoadedFileInfo const&, char const**) + 344
+    frame #18: 0x0000000102e8e938 dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**, unsigned long*) + 2876
+    frame #19: 0x0000000102e8922c dyld`dyldbootstrap::start(dyld3::MachOLoaded const*, int, char const**, dyld3::MachOLoaded const*, unsigned long*) + 432
+    frame #20: 0x0000000102e89038 dyld`_dyld_start + 56
+''';
+      final BufferLogger logger = BufferLogger.test();
+      final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
+        FakeCommand(
+          command: const <String>[
+            'ios-deploy',
+          ],
+          stdout: stdout,
+          stdin: IOSink(stdin.sink),
+        ),
+      ]);
+      final IOSDeployDebugger iosDeployDebugger = IOSDeployDebugger.test(
+        processManager: processManager,
+        logger: logger,
+      );
+      await iosDeployDebugger.launchAndAttach();
+      await iosDeployDebugger.pauseDumpBacktraceResume();
+      // verify stacktrace was logged to trace
+      expect(
+        logger.traceText,
+        contains(
+          'frame #0: 0x0000000102eaee80 dyld`dyld3::MachOFile::read_uleb128(Diagnostics&, unsigned char const*&, unsigned char const*) + 36',
+        ),
+      );
+      expect(await stdinStream.take(3).toList(), <String>[
+        'thread backtrace all',
+        '\n',
+        'process detach',
+      ]);
+    });
   });
 
   group('IOSDeploy.uninstallApp', () {

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

@@ -5,6 +5,7 @@
 // @dart = 2.8
 
 import 'dart:async';
+import 'dart:convert';
 
 import 'package:file/memory.dart';
 import 'package:flutter_tools/src/artifacts.dart';
@@ -64,26 +65,35 @@ const FakeCommand kLaunchDebugCommand = FakeCommand(command: <String>[
 });
 
 // The command used to actually launch the app and attach the debugger with args in debug.
-const FakeCommand kAttachDebuggerCommand = FakeCommand(command: <String>[
-  'script',
-  '-t',
-  '0',
-  '/dev/null',
-  'HostArtifact.iosDeploy',
-  '--id',
-  '123',
-  '--bundle',
-  '/',
-  '--debug',
-  '--no-wifi',
-  '--args',
-  '--enable-dart-profiling --disable-service-auth-codes --enable-checked-mode --verify-entry-points'
-], environment: <String, String>{
-  'PATH': '/usr/bin:null',
-  'DYLD_LIBRARY_PATH': '/path/to/libraries',
-},
-stdout: '(lldb)     run\nsuccess',
-);
+FakeCommand attachDebuggerCommand({
+  IOSink stdin,
+  Completer<void>/*?*/ completer,
+}) {
+  return FakeCommand(
+    command: const <String>[
+      'script',
+      '-t',
+      '0',
+      '/dev/null',
+      'HostArtifact.iosDeploy',
+      '--id',
+      '123',
+      '--bundle',
+      '/',
+      '--debug',
+      '--no-wifi',
+      '--args',
+      '--enable-dart-profiling --disable-service-auth-codes --enable-checked-mode --verify-entry-points',
+    ],
+    completer: completer,
+    environment: const <String, String>{
+      'PATH': '/usr/bin:null',
+      'DYLD_LIBRARY_PATH': '/path/to/libraries',
+    },
+    stdout: '(lldb)     run\nsuccess',
+    stdin: stdin,
+  );
+}
 
 void main() {
   testWithoutContext('disposing device disposes the portForwarder and logReader', () async {
@@ -108,7 +118,7 @@ void main() {
   testWithoutContext('IOSDevice.startApp attaches in debug mode via log reading on iOS 13+', () async {
     final FileSystem fileSystem = MemoryFileSystem.test();
     final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
-      kAttachDebuggerCommand,
+      attachDebuggerCommand(),
     ]);
     final IOSDevice device = setUpIOSDevice(
       processManager: processManager,
@@ -183,8 +193,10 @@ void main() {
   testWithoutContext('IOSDevice.startApp prints warning message if discovery takes longer than configured timeout', () async {
     final FileSystem fileSystem = MemoryFileSystem.test();
     final BufferLogger logger = BufferLogger.test();
+    final CompleterIOSink stdin = CompleterIOSink();
+    final Completer<void> completer = Completer<void>();
     final FakeProcessManager processManager = FakeProcessManager.list(<FakeCommand>[
-      kAttachDebuggerCommand,
+      attachDebuggerCommand(stdin: stdin, completer: completer),
     ]);
     final IOSDevice device = setUpIOSDevice(
       processManager: processManager,
@@ -203,11 +215,8 @@ void main() {
     device.setLogReader(iosApp, deviceLogReader);
 
     // Start writing messages to the log reader.
-    Timer.run(() async {
-      await Future<void>.delayed(const Duration(milliseconds: 1));
-      deviceLogReader.addLine('Foo');
-      deviceLogReader.addLine('The Dart VM service is listening on http://127.0.0.1:456');
-    });
+    deviceLogReader.addLine('Foo');
+    deviceLogReader.addLine('The Dart VM service is listening on http://127.0.0.1:456');
 
     final LaunchResult launchResult = await device.startApp(iosApp,
       prebuiltApplication: true,
@@ -220,6 +229,9 @@ void main() {
     expect(launchResult.hasObservatory, true);
     expect(await device.stopApp(iosApp), false);
     expect(logger.errorText, contains('iOS Observatory not discovered after 30 seconds. This is taking much longer than expected...'));
+    expect(utf8.decoder.convert(stdin.writes.first), contains('process interrupt'));
+    completer.complete();
+    expect(processManager, hasNoRemainingExpectations);
   });
 
   testWithoutContext('IOSDevice.startApp succeeds in release mode', () async {