From 436e5ee97a40834df16ffa5a5982aff4efd4f9c0 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 9 Oct 2026 01:43:35 +0000 Subject: [PATCH] ci: wait out the uninstall before the crash harness reinstalls The Android crash harness sometimes failed a native case with "expected exactly one native record, received []" although the OS had filed the crash. The fault is in the harness, not in the library. _Device.reinstall uninstalled the app and installed the next build at once, but adb uninstall returns when the package manager is done, not the activity manager. The activity manager drops the uninstalled package's exit records later, when the removal broadcast reaches it, and it drops them by package name, which takes the new install's records with them. In the two failures that left a log, the broadcast landed 16 and 17 seconds after the uninstall, after the new install had crashed and the OS had filed its record. In 27 passing runs it landed 0.2 to 1.8 seconds after the uninstall, long before the crash. reinstall now dumps the exit history, uninstalls, and polls until the dump lists no record and the history has been written since, every 500 ms for at most 120 s and then a StateError, before it installs. It prints how long that took. The wait is on the OS's own state: no assertion is relaxed, no run is retried and the library is unchanged. The readings of the dump move to tool/exit-info.dart, tested against dumps captured from the CI emulators, and a launch 2 that received no record now says whether the OS still holds it or removed it. Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_01XLy7TiPAxtVjPKEwQ9iwBa --- README.md | 22 ++- test/exit-info_test.dart | 232 ++++++++++++++++++++++++++++++++ tool/android-crash-harness.dart | 74 +++++++++- tool/exit-info.dart | 75 +++++++++++ 4 files changed, 397 insertions(+), 6 deletions(-) create mode 100644 test/exit-info_test.dart create mode 100644 tool/exit-info.dart 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);