diff --git a/README.md b/README.md index 9fce266..46f589b 100644 --- a/README.md +++ b/README.md @@ -616,6 +616,24 @@ and the second engine runs `start()` again. So the assertion is on everything that reached the receiver over the launch, and the start-up line's "recovered N" is required to say exactly one only when the activity was not relaunched. +A fresh install includes the OS having forgotten the last one. `adb uninstall` +returns when the package manager is done, not the activity manager: that drops +the uninstalled package's exit records when the removal broadcast reaches it, +and it drops them by package *name*, so the next install's record goes too if +that install has already crashed. The broadcast usually lands within two +seconds; on a loaded emulator it has taken about 16 and 17 seconds, after the +new install had crashed and the OS had filed it, and the launch that followed +read nothing (`received []`). So the harness dumps the exit history before it +uninstalls, and after the uninstall waits, every half second for at most two +minutes, until the dump lists no record and the OS has written its history +since. It prints `previous install left the exit history after ms`, and a +run that shows ten seconds or more there is one the harness used to be exposed +to. That wait is on the OS's own state, not a retry, and no assertion is relaxed +by it; `--upgrade-apk` needs none, because an update is a replacing install and +the same receiver ignores it. When a run still comes back without its record, +its failure says whether the OS still holds it (the app lost it) or no longer +does. + ```bash cd example && flutter pub get && flutter create --platforms=android . && cd .. dart run tool/android-crash-harness.dart --device emulator-5554 @@ -657,7 +675,9 @@ crash arrive twice) and how it stays fixed; the window is tens of milliseconds wide and moves with the machine, so sweep it rather than trust one value. The receiver (`tool/otlp-log-sink.dart`) decodes OTLP by hand and is -unit-tested against the SDK's own encoder. +unit-tested against the SDK's own encoder, and what the harness reads out of +the OS's exit history (`tool/exit-info.dart`) is unit-tested against dumps +captured from the CI emulators. **The ANR needs two things a bare block does not give.** An ANR is declared only when something is *waiting* on the blocked main thread, so the script sends diff --git a/test/exit-info_test.dart b/test/exit-info_test.dart new file mode 100644 index 0000000..e3ec28c --- /dev/null +++ b/test/exit-info_test.dart @@ -0,0 +1,232 @@ +// The Android crash harness reads the OS's exit history (`dumpsys activity +// exit-info`) to know when a record has been filed and when the previous +// install's history is gone. These are the pure readings of that dump, checked +// against dumps captured from the CI emulators. +import 'package:flutter_test/flutter_test.dart'; + +import '../tool/exit-info.dart'; + +/// The dump at the end of a passing native case (artifact `art51`, repeat run +/// 1, API 34): the crash is filed under pid 8036 as reason 5, then two force +/// stops, newest first, all for uid 10197. +const String _kept = ''' +ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info) +Last Timestamp of Persistence Into Persistent Storage: 2026-10-08 22:49:04.298 + package: com.example.otel_zone_example + Historical Process Exit for uid=10197 + ApplicationExitInfo #0: + timestamp=2026-10-08 22:49:31.375 pid=8297 realUid=10197 packageUid=10197 definingUid=10197 user=0 + process=com.example.otel_zone_example reason=10 (USER REQUESTED) subreason=21 (FORCE STOP) status=0 + importance=100 pss=0.00 rss=0.00 description=stop com.example.otel_zone_example due to from pid 8396 state=46 bytes trace=null + ApplicationExitInfo #1: + timestamp=2026-10-08 22:49:23.372 pid=8180 realUid=10197 packageUid=10197 definingUid=10197 user=0 + process=com.example.otel_zone_example reason=10 (USER REQUESTED) subreason=21 (FORCE STOP) status=0 + importance=100 pss=0.00 rss=0.00 description=stop com.example.otel_zone_example due to from pid 8283 state=46 bytes trace=null + ApplicationExitInfo #2: + timestamp=2026-10-08 22:49:14.248 pid=8036 realUid=10197 packageUid=10197 definingUid=10197 user=0 + process=com.example.otel_zone_example reason=5 (APP CRASH(NATIVE)) subreason=0 (UNKNOWN) status=11 + importance=100 pss=0.00 rss=0.00 description=crash state=46 bytes trace=null +'''; + +/// The dump at the end of the failing native case (artifact `art49`, job +/// 113560596835, API 34). The app crashed as pid 5059 and the OS filed it at +/// 22:04:09; this is what was left at 22:05:57. Only the force stops remain +/// under the new install's uid, and the persistence timestamp is the moment +/// the previous install's removal landed. +const String _lost = ''' +ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info) +Last Timestamp of Persistence Into Persistent Storage: 2026-10-08 22:04:11.860 + package: com.example.otel_zone_example + Historical Process Exit for uid=10193 + ApplicationExitInfo #0: + timestamp=2026-10-08 22:05:57.008 pid=7414 realUid=10193 packageUid=10193 definingUid=10193 user=0 + process=com.example.otel_zone_example reason=10 (USER REQUESTED) subreason=21 (FORCE STOP) status=0 + importance=100 pss=0.00 rss=0.00 description=stop com.example.otel_zone_example due to from pid 7506 state=46 bytes trace=null + ApplicationExitInfo #1: + timestamp=2026-10-08 22:05:49.166 pid=5246 realUid=10193 packageUid=10193 definingUid=10193 user=0 + process=com.example.otel_zone_example reason=10 (USER REQUESTED) subreason=21 (FORCE STOP) status=0 + importance=100 pss=221MB rss=304MB description=stop com.example.otel_zone_example due to from pid 7397 state=46 bytes trace=null +'''; + +/// The dump of the install that the failing run replaced (artifact `art49`, +/// the `jvm` case before it, uid 10192): a crash and two force stops, and a +/// timestamp of the epoch because nothing had been persisted since boot. +const String _previousInstall = ''' +ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info) +Last Timestamp of Persistence Into Persistent Storage: 1970-01-01 00:00:00.000 + package: com.example.otel_zone_example + Historical Process Exit for uid=10192 + ApplicationExitInfo #0: + timestamp=2026-10-08 22:03:54.743 pid=4719 realUid=10192 packageUid=10192 definingUid=10192 user=0 + process=com.example.otel_zone_example reason=10 (USER REQUESTED) subreason=21 (FORCE STOP) status=0 + importance=100 pss=0.00 rss=0.00 description=stop com.example.otel_zone_example due to from pid 4985 state=46 bytes trace=null + ApplicationExitInfo #1: + timestamp=2026-10-08 22:03:43.342 pid=4192 realUid=10192 packageUid=10192 definingUid=10192 user=0 + process=com.example.otel_zone_example reason=10 (USER REQUESTED) subreason=21 (FORCE STOP) status=0 + importance=100 pss=208MB rss=289MB description=stop com.example.otel_zone_example due to from pid 4697 state=46 bytes trace=null + ApplicationExitInfo #2: + timestamp=2026-10-08 22:03:27.665 pid=3212 realUid=10192 packageUid=10192 definingUid=10192 user=0 + process=com.example.otel_zone_example reason=4 (APP CRASH(EXCEPTION)) subreason=0 (UNKNOWN) status=0 + importance=100 pss=0.00 rss=0.00 description=crash state=46 bytes trace=null +'''; + +/// What `dumpsys activity exit-info ` prints once the OS has dropped +/// the package: the two header lines the dump always starts with, and nothing +/// else. The OS prints a package's section only while it holds one. No dump was +/// captured at that moment, so this is the captured header with the timestamp +/// that the failing run's removal wrote (the one in [_lost]). +const String _removed = ''' +ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info) +Last Timestamp of Persistence Into Persistent Storage: 2026-10-08 22:04:11.860 +'''; + +/// The same header, an older persistence: the app had no history when it was +/// uninstalled, and the OS has not yet processed the removal. +const String _emptyBefore = ''' +ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info) +Last Timestamp of Persistence Into Persistent Storage: 2026-10-08 22:03:30.120 +'''; + +void main() { + group('holdsExitRecords', () { + test('is true for a dump that lists records', () { + expect(holdsExitRecords(_kept), isTrue); + expect(holdsExitRecords(_previousInstall), isTrue); + }); + + test('is false for a dump of only the header', () { + expect(holdsExitRecords(_removed), isFalse); + expect(holdsExitRecords(''), isFalse); + }); + }); + + group('exitInfoPersistedAt', () { + test('reads the timestamp as the OS prints it', () { + expect(exitInfoPersistedAt(_kept), '2026-10-08 22:49:04.298'); + expect(exitInfoPersistedAt(_removed), '2026-10-08 22:04:11.860'); + }); + + test('reads the epoch of a boot that has persisted nothing', () { + expect(exitInfoPersistedAt(_previousInstall), '1970-01-01 00:00:00.000'); + }); + + test('throws when the line is missing, rather than guess', () { + expect( + () => exitInfoPersistedAt( + 'ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info)\n', + ), + throwsFormatException, + ); + expect(() => exitInfoPersistedAt(''), throwsFormatException); + }); + }); + + group('holdsExitRecord', () { + test('finds the native crash of pid 8036 as reason 5', () { + expect(holdsExitRecord(_kept, 8036, 5), isTrue); + }); + + test('does not find pid 8036 under another reason', () { + expect(holdsExitRecord(_kept, 8036, 10), isFalse); + expect(holdsExitRecord(_kept, 8036, 4), isFalse); + }); + + test('never reads across two records', () { + // pid 8180 is a force stop (reason 10); the reason-5 line that follows + // it in the dump belongs to pid 8036. + expect(holdsExitRecord(_kept, 8180, 5), isFalse); + expect(holdsExitRecord(_kept, 8297, 5), isFalse); + expect(holdsExitRecord(_kept, 8180, 10), isTrue); + }); + + test('matches the whole pid, not a prefix of it', () { + expect(holdsExitRecord(_kept, 803, 5), isFalse); + expect(holdsExitRecord(_kept, 80361, 5), isFalse); + }); + + test('does not mistake reason 5 for reason 15 or 50', () { + final String other = _kept.replaceFirst('reason=5 (', 'reason=15 ('); + expect(holdsExitRecord(other, 8036, 5), isFalse); + expect(holdsExitRecord(other, 8036, 15), isTrue); + }); + + test('has nothing to find in the dump that lost the record', () { + expect(holdsExitRecord(_lost, 5059, 5), isFalse); + expect(holdsExitRecord(_lost, 7414, 10), isTrue); + expect(holdsExitRecord(_removed, 5059, 5), isFalse); + }); + }); + + group('removalSettled', () { + test('is false while the previous install records are still listed', () { + expect( + removalSettled(before: _previousInstall, after: _previousInstall), + isFalse, + ); + }); + + test('is false when the records are gone but nothing was persisted', () { + // The records are not what proves the OS is done: the persistence that + // follows the removal is, and it has not happened. + final String gone = + 'ACTIVITY MANAGER PROCESS EXIT INFO (dumpsys activity exit-info)\n' + 'Last Timestamp of Persistence Into Persistent Storage: ' + '1970-01-01 00:00:00.000\n'; + expect(removalSettled(before: _previousInstall, after: gone), isFalse); + }); + + test( + 'is false while records are listed even if something was persisted', + () { + // A persistence of some other package's exit does not mean this + // package's removal has been processed. + final String persistedElsewhere = _previousInstall.replaceFirst( + '1970-01-01 00:00:00.000', + '2026-10-08 22:03:56.000', + ); + expect( + removalSettled(before: _previousInstall, after: persistedElsewhere), + isFalse, + ); + }, + ); + + test('is true once the records are gone and the history was persisted', () { + // The failing run's uninstall at 22:03:55.7, then the removal landing + // and being persisted at 22:04:11.860. + expect(removalSettled(before: _previousInstall, after: _removed), isTrue); + }); + + test('is true for a passing run, too', () { + final String removedLater = _removed.replaceFirst( + '2026-10-08 22:04:11.860', + '2026-10-08 22:49:32.574', + ); + expect(removalSettled(before: _kept, after: removedLater), isTrue); + }); + + test('waits on the persistence when the old install had no records', () { + // Nothing to see disappear, so only the timestamp can say the removal + // has been processed: unchanged is not settled, moved is. + expect( + removalSettled(before: _emptyBefore, after: _emptyBefore), + isFalse, + ); + expect(removalSettled(before: _emptyBefore, after: _removed), isTrue); + }); + + test('is not settled by the new install\'s own records', () { + // The shape of the failing run: the removal landed after the new + // install had crashed, so the history holds the new uid's records and a + // moved timestamp. Waiting is what keeps the install from being here. + expect(removalSettled(before: _previousInstall, after: _lost), isFalse); + }); + + test('throws on a dump with no persistence line, rather than guess', () { + expect( + () => removalSettled(before: _previousInstall, after: ''), + throwsFormatException, + ); + }); + }); +} diff --git a/tool/android-crash-harness.dart b/tool/android-crash-harness.dart index 9b0accd..a085a4c 100644 --- a/tool/android-crash-harness.dart +++ b/tool/android-crash-harness.dart @@ -20,6 +20,11 @@ // receiver; // 5. relaunch once more: nothing may have been recovered. // +// "Freshly installed" includes the OS having forgotten the previous install: +// uninstalling returns before the activity manager has dropped that install's +// exit records, and dropping them later would take the new install's with them. +// `_Device.reinstall` waits for it, on the OS's own state, before it installs. +// // A launch is judged once it has been quiet for `--settle` seconds, not when // the first start-up line appears. Android relaunches an activity in the same // process, by itself, whenever an asset path or the package's application info @@ -60,6 +65,7 @@ import 'dart:async'; import 'dart:convert'; import 'dart:io'; +import 'exit-info.dart'; import 'log-window.dart'; import 'otlp-log-sink.dart'; @@ -369,11 +375,52 @@ class _Device { } /// A fresh install, so no earlier run's exit records or watermark survive. + /// + /// `adb uninstall` returns when the package manager is done, not the + /// activity manager. The package manager then broadcasts the removal, and + /// when the activity manager's receiver gets it, which on a loaded emulator + /// can be seconds later, it destroys every exit record filed under the + /// package *name*: the new install's too, if it has already crashed. Installed + /// straight away, the next install can crash and have its record filed + /// before that happens, and the harness then reads nothing for a crash that + /// did happen (`received []`). So this dumps the exit history first, and + /// after the uninstall waits until the OS says it has dropped it + /// ([removalSettled]) before it installs, polling every half a second and + /// throwing a [StateError] after two minutes, as it does when `adb` fails. + /// The wait is on the OS's own state and is not a retry: the run itself is + /// untouched and nothing it asserts is relaxed. + /// + /// [upgrade] needs none of this. Replacing an install broadcasts a removal + /// marked as a replacement, which the activity manager ignores, so the + /// history is kept: that is the point of an update. Future reinstall(String apk) async { + const Duration pause = Duration(milliseconds: 500); + const Duration timeout = Duration(seconds: 120); + final String before = await exitInfo(); + var uninstalled = false; try { await adbCommand(['uninstall', _package]); + uninstalled = true; } on Object { - // Not installed yet. + // Not installed yet: no removal is coming, so nothing to wait for. + } + if (uninstalled) { + final Stopwatch clock = Stopwatch()..start(); + String after = await exitInfo(); + while (!removalSettled(before: before, after: after)) { + if (clock.elapsed >= timeout) { + throw StateError( + 'the OS still held the previous install\'s exit history ' + '${timeout.inSeconds}s after it was uninstalled\n$after', + ); + } + await Future.delayed(pause); + after = await exitInfo(); + } + stdout.writeln( + ' previous install left the exit history after ' + '${clock.elapsedMilliseconds} ms', + ); } await adbCommand(['install', '-r', '-t', apk]); } @@ -517,12 +564,9 @@ class _Device { int reason, { Duration timeout = const Duration(seconds: 60), }) async { - final RegExp record = RegExp( - 'pid=$pid\\b(?:(?!ApplicationExitInfo)[\\s\\S])*?reason=$reason \\(', - ); final Stopwatch clock = Stopwatch()..start(); while (clock.elapsed < timeout) { - if (record.hasMatch(await exitInfo())) return true; + if (holdsExitRecord(await exitInfo(), pid, reason)) return true; await Future.delayed(const Duration(milliseconds: 500)); } return false; @@ -733,6 +777,11 @@ class _KindRun { 'launch 2: expected exactly one "$kind" record, ' 'received ${second.kinds}', ); + if (crashing != null && !second.kinds.contains(kind)) { + // Not an assertion of its own: the one above has already failed. It + // says which of the two ways a record goes missing this was. + _problems.add(await _whereTheRecordWent(crashing)); + } final Iterable crashes = second.records.where( (SinkRecord r) => r.crashKind != null, ); @@ -814,6 +863,21 @@ class _KindRun { return false; } + /// Where the OS's record of [pid]'s death is now that launch 2 reported none: + /// still in its history, so the app lost it, or gone from it, so the OS did. + Future _whereTheRecordWent(int pid) async { + try { + final String dump = await device.exitInfo(); + return holdsExitRecord(dump, pid, _exitReason) + ? "launch 2: the OS still holds pid $pid's record (the app lost it)" + : "launch 2: the OS removed pid $pid's record " + '(last persisted ${exitInfoPersistedAt(dump)})'; + } on Object catch (error) { + return "launch 2: could not read the OS's exit history to say where " + "pid $pid's record went: $error"; + } + } + /// The start-up lines of [launch], with the process each came from. String _lines(_Launch launch) => launch.summaries.isEmpty ? 'no start-up line' diff --git a/tool/exit-info.dart b/tool/exit-info.dart new file mode 100644 index 0000000..fe14e05 --- /dev/null +++ b/tool/exit-info.dart @@ -0,0 +1,75 @@ +// What the crash harness reads out of the OS's exit history, kept apart from +// the `adb` plumbing so it can be tested without a device. The history is what +// `dumpsys activity exit-info ` prints; see `_Device.reinstall` and +// `_Device.waitForExitRecord` in `android-crash-harness.dart` for how it is +// used, and `holdsExitRecord` for the one reading that decides a verdict. + +final RegExp _anyRecord = RegExp(r'reason=\d+ \('); + +final RegExp _persistedAt = RegExp( + r'Last Timestamp of Persistence Into Persistent Storage: (.+)', +); + +/// Whether [dump] lists at least one exit record, of any process and reason. +/// +/// A dump lists a record as `reason= ()`; a package the OS holds +/// nothing for is the two header lines alone. +bool holdsExitRecords(String dump) => _anyRecord.hasMatch(dump); + +/// When the OS last wrote its exit history to storage, as the dump prints it: +/// `2026-10-08 22:04:11.860`, or `1970-01-01 00:00:00.000` on a boot that has +/// not written it yet. +/// +/// The OS writes the history out at once when a package is removed, and +/// otherwise only every half hour, so a removal moves this. The string is +/// compared, never parsed: it is only ever asked whether it changed. Throws a +/// [FormatException] when the line is missing, because a dump in a format this +/// does not know cannot say that anything settled, and a harness that guessed +/// would stop waiting. +String exitInfoPersistedAt(String dump) { + final RegExpMatch? match = _persistedAt.firstMatch(dump); + if (match == null) { + throw FormatException( + 'no "Last Timestamp of Persistence Into Persistent Storage" line in the ' + 'exit-info dump', + dump, + ); + } + return match.group(1)!.trim(); +} + +/// Whether [dump] holds the record of [pid] having died for [reason], one of +/// `ApplicationExitInfo`'s `REASON_*` constants (4 a Java crash, 5 a native +/// crash, 6 an ANR, 10 a user request such as a force stop). +/// +/// The match stays inside one record: it starts at `pid=` and may run on +/// to a `reason= (` of the same record, never past the next +/// `ApplicationExitInfo`. So a pid that died for another reason is not found +/// because the next process in the dump died for this one, and `803` is not +/// found in `pid=8036`. +bool holdsExitRecord(String dump, int pid, int reason) => RegExp( + 'pid=$pid\\b(?:(?!ApplicationExitInfo)[\\s\\S])*?reason=$reason \\(', +).hasMatch(dump); + +/// Whether the OS has finished taking the app's previous install out of its +/// exit history, given the dump [before] the app was uninstalled and the dump +/// [after], taken since. +/// +/// The OS does it after the uninstall has returned, not during it: the package +/// manager broadcasts the removal and the activity manager's receiver then +/// destroys every exit record filed under the package name, whatever uid it +/// was filed for, and writes the history out. A crash of the *next* install +/// that is filed before that broadcast is handled is destroyed with the old +/// one's records, and the harness then reads no record for a crash that +/// happened. +/// +/// It is settled when no record is listed and the history was written since +/// [before]. Both are needed. The records going away alone can be read before +/// the write, and the write alone can be the half-hourly one, or another +/// package's, with this package's records still listed. The write also covers +/// an old install that had no records at all, which leaves nothing to watch +/// disappear but still moves the timestamp. Throws a [FormatException] when +/// [after] has no timestamp (see [exitInfoPersistedAt]). +bool removalSettled({required String before, required String after}) => + !holdsExitRecords(after) && + exitInfoPersistedAt(after) != exitInfoPersistedAt(before);