From d07ce92b15b89e525d72e6bb01db1fe99afa824f Mon Sep 17 00:00:00 2001 From: Christopher Fujino Date: Tue, 12 Apr 2022 13:24:04 -0700 Subject: [PATCH] [flutter_tools] Re-land Dump backtrace on ios app startup timeout (#101763) --- .../flutter_tools/lib/src/ios/devices.dart | 1 + .../flutter_tools/lib/src/ios/ios_deploy.dart | 50 +++++++++++++- .../general.shard/ios/ios_deploy_test.dart | 65 ++++++++++++++++++ .../ios/ios_device_start_prebuilt_test.dart | 66 +++++++++++-------- 4 files changed, 152 insertions(+), 30 deletions(-) diff --git a/packages/flutter_tools/lib/src/ios/devices.dart b/packages/flutter_tools/lib/src/ios/devices.dart index 7646aeb7c6..d47a270a82 100644 --- a/packages/flutter_tools/lib/src/ios/devices.dart +++ b/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(); diff --git a/packages/flutter_tools/lib/src/ios/ios_deploy.dart b/packages/flutter_tools/lib/src/ios/ios_deploy.dart index a5ca1f4061..e872363680 100644 --- a/packages/flutter_tools/lib/src/ios/ios_deploy.dart +++ b/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? _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(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,6 +360,13 @@ 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? processResumeCompleter = _processResumeCompleter; + if (processResumeCompleter != null) { + _processResumeCompleter = null; + processResumeCompleter.complete(); + } return; } @@ -357,9 +374,12 @@ class IOSDeployDebugger { // 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; } + /// Pause app, dump backtrace for debugging, and resume. + Future pauseDumpBacktraceResume() async { + if (!debuggerAttached) { + return; + } + final Completer completer = Completer(); + _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 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); diff --git a/packages/flutter_tools/test/general.shard/ios/ios_deploy_test.dart b/packages/flutter_tools/test/general.shard/ios/ios_deploy_test.dart index 3da7d21b95..b313e690f7 100644 --- a/packages/flutter_tools/test/general.shard/ios/ios_deploy_test.dart +++ b/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> stdin = StreamController>(); + final Stream stdinStream = stdin.stream.transform(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( + command: const [ + '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(), [ + 'thread backtrace all', + '\n', + 'process detach', + ]); + }); }); group('IOSDeploy.uninstallApp', () { diff --git a/packages/flutter_tools/test/general.shard/ios/ios_device_start_prebuilt_test.dart b/packages/flutter_tools/test/general.shard/ios/ios_device_start_prebuilt_test.dart index 270e26c598..0bac487f5a 100644 --- a/packages/flutter_tools/test/general.shard/ios/ios_device_start_prebuilt_test.dart +++ b/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: [ }); // The command used to actually launch the app and attach the debugger with args in debug. -const FakeCommand kAttachDebuggerCommand = FakeCommand(command: [ - '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: { - 'PATH': '/usr/bin:null', - 'DYLD_LIBRARY_PATH': '/path/to/libraries', -}, -stdout: '(lldb) run\nsuccess', -); +FakeCommand attachDebuggerCommand({ + IOSink stdin, + Completer/*?*/ completer, +}) { + return FakeCommand( + command: const [ + '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 { + '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([ - 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 completer = Completer(); final FakeProcessManager processManager = FakeProcessManager.list([ - 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.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 {