From 0a08ef7b0662f561e7d61dab07b482db2ce221fa Mon Sep 17 00:00:00 2001 From: diffwireauto <330573775+diffwireauto@users.noreply.github.com> Date: Mon, 19 Oct 2026 03:55:12 -0400 Subject: [PATCH] test(#910): exit-record selection, formatting, pruning and rotation 43 tests. Selection covers the dedup contract: strictly-newer only, a record equal to the watermark treated as already logged, two records in one millisecond both kept, the watermark taking the highest rather than the first, and the backfill trace cap. Formatting covers the cases that would otherwise read wrong: zero pss and rss render as unknown rather than as a real measurement, a null description is omitted rather than printed, an absent trace records why, and a backfilled record says so. Every message the service can surface is asserted present for its own failure, and an ideal line is asserted to carry none of the failure markers. The channel layer runs behind a mock handler, which proves the watermark advances on success, does not move on a query failure so the next launch retries, and that collect never throws and runs once per launch. What these cannot prove, stated in the test file header: that Android actually produces a REASON_ANR record with a readable trace. That needs a real main-thread block on an API 30+ device and a relaunch, which is #911 part B. The rotation tests pin down what a 40 KB entry actually does, which is the Epic's rotation criterion: it rotates once and is written whole, the active file is then legitimately above maxBytes because that gate decides when to rotate rather than truncating, and maxFiles still holds so the log cannot grow without bound. Co-Authored-By: Claude Opus 5 --- test/services/app_exit_info_service_test.dart | 529 ++++++++++++++++++ test/utils/file_log_writer_test.dart | 79 +++ 2 files changed, 608 insertions(+) create mode 100644 test/services/app_exit_info_service_test.dart diff --git a/test/services/app_exit_info_service_test.dart b/test/services/app_exit_info_service_test.dart new file mode 100644 index 00000000..79af5137 --- /dev/null +++ b/test/services/app_exit_info_service_test.dart @@ -0,0 +1,529 @@ +// Exit-record capture (#906). Covers the selection, formatting, naming and +// pruning logic as pure functions, plus the channel layer behind a mock handler +// so the dedup contract and the never-throw contract are both checked. +// +// NOT covered here, and it cannot be: that Android actually produces a +// REASON_ANR record with a readable trace. No adb command induces an ANR +// (`am crash` is a crash; `kill -3` dumps traces without a REASON_ANR death), +// so that needs a real main-thread block on an API 30+ device and a relaunch. +// That is #911 part B, and it is the only way to prove the mechanism. + +import 'package:flutter/foundation.dart'; +import 'package:flutter/services.dart'; +import 'package:flutter_test/flutter_test.dart'; +import 'package:meshcore_open/services/app_exit_info_service.dart'; +import 'package:meshcore_open/storage/prefs_manager.dart'; +import 'package:shared_preferences/shared_preferences.dart'; + +ExitRecord _record({ + int reason = 6, + String reasonName = 'ANR', + required int timestampMs, + int pid = 1234, + String? description, + String? processName = 'app.offband.meshcore', + int importance = 100, + int pssKb = 0, + int rssKb = 0, + int status = 0, + Uint8List? traceBytes, + String? traceUnavailable, + bool traceTruncated = false, +}) => ExitRecord( + reason: reason, + reasonName: reasonName, + timestampMs: timestampMs, + pid: pid, + description: description, + processName: processName, + importance: importance, + pssKb: pssKb, + rssKb: rssKb, + status: status, + traceBytes: traceBytes, + traceUnavailable: traceUnavailable, + traceTruncated: traceTruncated, +); + +void main() { + group('selectExitRecords', () { + test('first run backfills everything and caps the trace budget', () { + final all = [ + _record(timestampMs: 500), + _record(timestampMs: 400), + _record(timestampMs: 300), + _record(timestampMs: 200), + _record(timestampMs: 100), + ]; + final s = selectExitRecords(all, null, backfillTraceCap: 3); + expect(s.backfill, isTrue); + expect(s.records.length, 5, reason: 'metadata for every record'); + expect(s.traceBudget, 3, reason: 'traces capped on a backfill'); + expect(s.newWatermarkMs, 500); + }); + + test('backfill budget never exceeds the number of records', () { + final s = selectExitRecords( + [_record(timestampMs: 10)], + null, + backfillTraceCap: 3, + ); + expect(s.traceBudget, 1); + }); + + test('with a watermark, only strictly newer records are selected', () { + final all = [ + _record(timestampMs: 300), + _record(timestampMs: 200), + _record(timestampMs: 100), + ]; + final s = selectExitRecords(all, 200); + expect(s.backfill, isFalse); + expect(s.records.map((r) => r.timestampMs), [300]); + expect(s.newWatermarkMs, 300); + expect(s.traceBudget, 1, reason: 'no cap outside a backfill'); + }); + + test('a record equal to the watermark is treated as already logged', () { + final s = selectExitRecords([_record(timestampMs: 200)], 200); + expect(s.records, isEmpty); + expect(s.newWatermarkMs, isNull, reason: 'watermark must not move'); + }); + + test('two records in the same millisecond are both kept', () { + final all = [ + _record(timestampMs: 400, pid: 2), + _record(timestampMs: 400, pid: 1), + _record(timestampMs: 100, pid: 0), + ]; + final s = selectExitRecords(all, 100); + expect(s.records.map((r) => r.pid), [2, 1]); + expect( + s.newWatermarkMs, + 400, + reason: 'both logged before the watermark advances past them', + ); + }); + + test('nothing new yields an empty, non-backfill selection', () { + final s = selectExitRecords([_record(timestampMs: 50)], 999); + expect(s.records, isEmpty); + expect(s.backfill, isFalse); + expect(s.traceBudget, 0); + expect(s.newWatermarkMs, isNull); + }); + + test('watermark takes the highest timestamp, not the first', () { + final all = [_record(timestampMs: 100), _record(timestampMs: 900)]; + expect(selectExitRecords(all, 50).newWatermarkMs, 900); + }); + }); + + group('formatExitLine', () { + final at = DateTime.utc(2026, 10, 19, 7, 30).millisecondsSinceEpoch; + final now = DateTime.utc(2026, 10, 19, 8); + + test('an ANR logs at WARN with reason, pid and the trace filename', () { + final line = formatExitLine( + _record(timestampMs: at, description: 'Input dispatching timed out'), + backfill: false, + writtenFileName: 'anr-20261019T073000Z-1234.txt', + now: now, + ); + expect(line, startsWith('2026-10-19T08:00:00.000Z [WARN/ExitInfo] ')); + expect(line, contains('reason=ANR(6)')); + expect(line, contains('desc="Input dispatching timed out"')); + expect(line, contains('pid=1234')); + expect(line, contains('proc=app.offband.meshcore')); + expect(line, contains('importance=FOREGROUND')); + expect(line, contains('trace=anr-20261019T073000Z-1234.txt')); + expect(line, isNot(contains('backfill=true'))); + }); + + test('a routine exit logs at INFO, not WARN', () { + final line = formatExitLine( + _record(timestampMs: at, reason: 1, reasonName: 'EXIT_SELF'), + backfill: false, + now: now, + ); + expect(line, contains('[INFO/ExitInfo]')); + expect(line, contains('reason=EXIT_SELF(1)')); + }); + + test('a resource kill logs at WARN', () { + for (final name in const [ + 'LOW_MEMORY', + 'FREEZER', + 'EXCESSIVE_RESOURCE_USAGE', + 'CRASH', + 'CRASH_NATIVE', + ]) { + final line = formatExitLine( + _record(timestampMs: at, reasonName: name), + backfill: false, + now: now, + ); + expect(line, contains('[WARN/ExitInfo]'), reason: name); + } + }); + + test('zero memory renders as unknown, never as a real measurement', () { + final line = formatExitLine( + _record(timestampMs: at, pssKb: 0, rssKb: 0), + backfill: false, + now: now, + ); + expect(line, contains('pss=unknown')); + expect(line, contains('rss=unknown')); + expect(line, isNot(contains('0kB'))); + }); + + test('real memory figures render in kB', () { + final line = formatExitLine( + _record(timestampMs: at, pssKb: 182340, rssKb: 241088), + backfill: false, + now: now, + ); + expect(line, contains('pss=182340kB')); + expect(line, contains('rss=241088kB')); + }); + + test('a null description is omitted rather than printed as null', () { + final line = formatExitLine( + _record(timestampMs: at), + backfill: false, + now: now, + ); + expect(line, isNot(contains('desc='))); + expect(line, isNot(contains('null'))); + }); + + test('an absent trace records why, which is a normal outcome', () { + final line = formatExitLine( + _record(timestampMs: at, traceUnavailable: 'evicted_or_absent'), + backfill: false, + now: now, + ); + expect(line, contains('trace=none(evicted_or_absent)')); + }); + + test('a truncated trace is marked as such', () { + final line = formatExitLine( + _record(timestampMs: at, traceTruncated: true), + backfill: false, + writtenFileName: 'anr-x.txt', + now: now, + ); + expect(line, contains('trace=anr-x.txt(truncated)')); + }); + + test('a backfilled record says so, so it is not read as fresh', () { + final line = formatExitLine( + _record(timestampMs: at), + backfill: true, + now: now, + ); + expect(line, contains('backfill=true')); + }); + + test('an ideal line carries none of the failure markers', () { + final line = formatExitLine( + _record( + timestampMs: at, + pssKb: 1000, + rssKb: 2000, + description: 'Input dispatching timed out', + ), + backfill: false, + writtenFileName: 'anr-ok.txt', + now: now, + ); + for (final marker in ExitInfoMessages.failureMarkers) { + expect(line, isNot(contains(marker)), reason: marker); + } + }); + }); + + group('importanceName', () { + test('names the values that matter for reading an ANR', () { + expect(importanceName(100), 'FOREGROUND'); + expect(importanceName(125), 'FOREGROUND_SERVICE'); + expect(importanceName(200), 'VISIBLE'); + expect(importanceName(230), 'PERCEPTIBLE'); + expect(importanceName(300), 'SERVICE'); + expect(importanceName(400), 'CACHED'); + expect(importanceName(1000), 'GONE'); + }); + + test('zero is unknown, and an unmapped value keeps its number', () { + expect(importanceName(0), 'unknown'); + expect(importanceName(275), 'IMPORTANCE_275'); + }); + }); + + group('traceFileName', () { + test('is UTC, zero-padded, and sorts chronologically by name', () { + final a = traceFileName( + DateTime.utc(2026, 9, 3, 4, 5, 6).millisecondsSinceEpoch, + 7, + ); + final b = traceFileName( + DateTime.utc(2026, 10, 19, 7, 30, 0).millisecondsSinceEpoch, + 1234, + ); + expect(a, 'anr-20260903T040506Z-7.txt'); + expect(b, 'anr-20261019T073000Z-1234.txt'); + expect(a.compareTo(b), lessThan(0), reason: 'name order is time order'); + }); + }); + + group('traceFilesToPrune', () { + test('keeps nothing to do when under both limits', () { + final doomed = traceFilesToPrune( + {'anr-1.txt': 10, 'anr-2.txt': 10}, + keep: 5, + ceilingBytes: 1000, + ); + expect(doomed, isEmpty); + }); + + test('drops the oldest beyond the keep count', () { + final doomed = traceFilesToPrune( + { + 'anr-20260101T000000Z-1.txt': 10, + 'anr-20260102T000000Z-1.txt': 10, + 'anr-20260103T000000Z-1.txt': 10, + }, + keep: 2, + ceilingBytes: 1000, + ); + expect(doomed, ['anr-20260101T000000Z-1.txt']); + }); + + test('drops oldest first until the byte ceiling is met', () { + final doomed = traceFilesToPrune( + { + 'anr-20260101T000000Z-1.txt': 600, + 'anr-20260102T000000Z-1.txt': 600, + 'anr-20260103T000000Z-1.txt': 600, + }, + keep: 5, + ceilingBytes: 1000, + ); + expect(doomed, [ + 'anr-20260101T000000Z-1.txt', + 'anr-20260102T000000Z-1.txt', + ]); + }); + + test( + 'never deletes the newest file, even if it alone busts the ceiling', + () { + final doomed = traceFilesToPrune( + {'anr-20260103T000000Z-1.txt': 5000}, + keep: 5, + ceilingBytes: 1000, + ); + expect( + doomed, + isEmpty, + reason: 'a trace too big to keep is still the only evidence we have', + ); + }, + ); + }); + + group('ExitInfoMessages', () { + test('each failure has a distinct, non-empty message', () { + final messages = [ + ExitInfoMessages.notAndroid, + ExitInfoMessages.nullResult, + ExitInfoMessages.unsupported('api_below_30', 29), + ExitInfoMessages.queryFailed('exit_info_query_failed', 'boom'), + ExitInfoMessages.captureFailed('boom'), + ExitInfoMessages.traceDirMissing(42), + ExitInfoMessages.traceWriteFailed('anr-x.txt', 'boom'), + ExitInfoMessages.pruneFailed('boom'), + ExitInfoMessages.listFailed('boom'), + ExitInfoMessages.watermarkReadFailed('boom'), + ExitInfoMessages.watermarkWriteFailed('boom'), + ExitInfoMessages.forceBlockFailed('boom'), + ]; + for (final m in messages) { + expect(m, isNotEmpty); + } + expect(messages.toSet().length, messages.length, reason: 'all distinct'); + }); + + test('the unsupported message names the API level and the reason', () { + final m = ExitInfoMessages.unsupported('api_below_30', 29); + expect(m, contains('api_below_30')); + expect(m, contains('sdkInt=29')); + expect(m, contains('API 30')); + }); + + test('a query failure names the code so it is traceable', () { + expect( + ExitInfoMessages.queryFailed('exit_info_query_failed', 'binder died'), + contains('exit_info_query_failed'), + ); + }); + + test('every failure message trips at least one failure marker', () { + final messages = [ + ExitInfoMessages.unsupported('api_below_30', 29), + ExitInfoMessages.queryFailed('c', 'm'), + ExitInfoMessages.captureFailed('e'), + ExitInfoMessages.traceDirMissing(1), + ExitInfoMessages.traceWriteFailed('n', 'e'), + ExitInfoMessages.pruneFailed('e'), + ExitInfoMessages.listFailed('e'), + ExitInfoMessages.watermarkReadFailed('e'), + ExitInfoMessages.watermarkWriteFailed('e'), + ExitInfoMessages.forceBlockFailed('e'), + ]; + for (final m in messages) { + expect( + ExitInfoMessages.failureMarkers.any(m.contains), + isTrue, + reason: 'not detectable as a failure: $m', + ); + } + }); + }); + + group('collect over the platform channel', () { + const channel = MethodChannel('meshcore_open/app_exit_info'); + late List calls; + + setUp(() { + TestWidgetsFlutterBinding.ensureInitialized(); + debugDefaultTargetPlatformOverride = TargetPlatform.android; + calls = []; + SharedPreferences.setMockInitialValues({}); + PrefsManager.reset(); + }); + + tearDown(() { + debugDefaultTargetPlatformOverride = null; + TestDefaultBinaryMessengerBinding.instance.defaultBinaryMessenger + .setMockMethodCallHandler(channel, null); + PrefsManager.reset(); + }); + + void handle(Future? Function(MethodCall) handler) { + TestDefaultBinaryMessengerBinding.instance.defaultBinaryMessenger + .setMockMethodCallHandler(channel, (call) { + calls.add(call); + return handler(call); + }); + } + + Map reply(List> records) => { + 'supported': true, + 'sdkInt': 34, + 'records': records, + }; + + Map rec(int ts, {int pid = 1}) => { + 'reason': 6, + 'reasonName': 'ANR', + 'timestampMs': ts, + 'pid': pid, + 'importance': 100, + 'pssKb': 0, + 'rssKb': 0, + 'status': 0, + 'traceUnavailable': 'evicted_or_absent', + }; + + test('advances the watermark so nothing is logged twice', () async { + await PrefsManager.initialize(); + handle((_) async => reply([rec(5000), rec(4000)])); + + AppExitInfoService.instance.resetForTest(); + await AppExitInfoService.instance.collect(); + + expect( + PrefsManager.instance.getInt(AppExitInfoService.watermarkKey), + 5000, + ); + + // Second launch, same records: nothing new, watermark unchanged. + AppExitInfoService.instance.resetForTest(); + await AppExitInfoService.instance.collect(); + expect( + PrefsManager.instance.getInt(AppExitInfoService.watermarkKey), + 5000, + ); + }); + + test('a query failure leaves the watermark alone so it retries', () async { + SharedPreferences.setMockInitialValues({ + AppExitInfoService.watermarkKey: 1234, + }); + await PrefsManager.initialize(); + handle( + (_) async => throw PlatformException(code: 'exit_info_query_failed'), + ); + + AppExitInfoService.instance.resetForTest(); + await AppExitInfoService.instance.collect(); + + expect( + PrefsManager.instance.getInt(AppExitInfoService.watermarkKey), + 1234, + reason: 'an untouched watermark is what makes the next launch retry', + ); + }); + + test( + 'an unsupported platform reply does not throw or move anything', + () async { + await PrefsManager.initialize(); + handle( + (_) async => { + 'supported': false, + 'unsupportedReason': 'api_below_30', + 'sdkInt': 29, + 'records': [], + }, + ); + + AppExitInfoService.instance.resetForTest(); + await AppExitInfoService.instance.collect(); + + expect( + PrefsManager.instance.getInt(AppExitInfoService.watermarkKey), + isNull, + ); + expect(calls.single.method, 'getExitRecords'); + }, + ); + + test('a null reply does not throw', () async { + await PrefsManager.initialize(); + handle((_) async => null); + AppExitInfoService.instance.resetForTest(); + await expectLater(AppExitInfoService.instance.collect(), completes); + }); + + test('collect runs once per launch', () async { + await PrefsManager.initialize(); + handle((_) async => reply([rec(10)])); + AppExitInfoService.instance.resetForTest(); + await AppExitInfoService.instance.collect(); + await AppExitInfoService.instance.collect(); + expect(calls.length, 1, reason: 'second call is a no-op'); + }); + + test('off Android the channel is never touched', () async { + debugDefaultTargetPlatformOverride = TargetPlatform.windows; + await PrefsManager.initialize(); + handle((_) async => reply([rec(10)])); + AppExitInfoService.instance.resetForTest(); + await AppExitInfoService.instance.collect(); + expect(calls, isEmpty); + }); + }); +} diff --git a/test/utils/file_log_writer_test.dart b/test/utils/file_log_writer_test.dart index 3e9c21cc..384101b4 100644 --- a/test/utils/file_log_writer_test.dart +++ b/test/utils/file_log_writer_test.dart @@ -75,5 +75,84 @@ void main() { expect(File('${dir.path}/t.log').existsSync(), isTrue); expect(File('${dir.path}/t.1.log').existsSync(), isTrue); }); + + // #906: exit-record capture puts a pointer line in offband.log and the + // trace itself in a sibling file, partly because a trace is tens of KB. + // These pin down what a large entry actually does to rotation, so the + // Epic's "rotation still behaves with a large trace present" criterion is + // measured rather than assumed. + group('with an oversized entry present (#906)', () { + test( + 'an entry larger than maxBytes rotates and is written whole', + () async { + final w = FileLogWriter( + dir: dir, + baseName: 't', + maxBytes: 2048, + maxFiles: 3, + ); + await w.writeLine('small line to make the active file non-empty'); + final big = 'T' * 40000; + await w.writeLine(big); + + // Rotation fired, and the oversized entry is intact rather than cut. + expect(File('${dir.path}/t.1.log').existsSync(), isTrue); + expect(await w.activeFile.readAsString(), '$big\n'); + }, + ); + + test('a single entry over maxBytes leaves the active file above the cap, ' + 'by design: it rotates once then appends regardless', () async { + final w = FileLogWriter( + dir: dir, + baseName: 't', + maxBytes: 2048, + maxFiles: 3, + ); + await w.writeLine('seed'); + await w.writeLine('T' * 40000); + expect( + await w.activeFile.length(), + greaterThan(2048), + reason: 'maxBytes gates when to rotate, it is not a hard truncation', + ); + }); + + test('normal rotation still works after an oversized entry', () async { + final w = FileLogWriter( + dir: dir, + baseName: 't', + maxBytes: 2048, + maxFiles: 3, + ); + await w.writeLine('T' * 40000); + for (var i = 0; i < 40; i++) { + await w.writeLine('line $i ${'z' * 100}'); + } + expect(File('${dir.path}/t.log').existsSync(), isTrue); + expect(File('${dir.path}/t.1.log').existsSync(), isTrue); + expect(File('${dir.path}/t.2.log').existsSync(), isTrue); + expect( + File('${dir.path}/t.3.log').existsSync(), + isFalse, + reason: 'maxFiles still holds, so the log cannot grow without bound', + ); + }); + + test('an oversized batch rotates once and is not dropped', () async { + final w = FileLogWriter( + dir: dir, + baseName: 't', + maxBytes: 2048, + maxFiles: 3, + ); + await w.writeLine('seed'); + final lines = List.generate(500, (i) => 'trace frame $i ${'f' * 60}'); + await w.writeLines(lines); + final active = await w.activeFile.readAsString(); + expect(active, contains('trace frame 0 ')); + expect(active, contains('trace frame 499 ')); + }); + }); }); }