fix(#1128): log every hidden-history check, run or skipped

The owner's first radio log showed the key-change lines but nothing for
the hidden-history check, so "ran and found nothing" could not be told
from "did not run". Every channel sync now logs either the check's
result (keys checked, channels on the radio, keys deleted) or why it was
skipped: erased slots, unconfirmed slots, a partial sync, no device info,
or a write in flight.

Also makes the key-change test helper wait for each set-channel frame in
real time: the history move can decode on another isolate, so a fixed
number of microtask turns raced it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lib/connector/meshcore_connector.dart

@@ -7131,8 +7131,8 @@ class MeshCoreConnector extends ChangeNotifier {
     );
     // A sync before device info, or one asked for fewer slots, has not seen
     // every channel, so it cannot say what the radio does not hold (#1128).
-    final sawEverySlot =
-        _slotCountKnown && _totalChannelsToRequest >= _maxChannels;
+    final askedSlots = _totalChannelsToRequest;
+    final sawEverySlot = _slotCountKnown && askedSlots >= _maxChannels;
 
     _cleanupChannelSync(completed: true);
 
@@ -7179,6 +7179,7 @@ class MeshCoreConnector extends ChangeNotifier {
         'channel(s) retained); use Restore to write them back to the radio.',
         tag: 'ChannelSync',
       );
+      _logHistoryCheckSkipped('the radio has erased slots (Restore case)');
     } else if (_unconfirmedChannelSlots.isEmpty) {
       // Full confirmation: the fresh list is the truth, replace the cache.
       _cachedChannels = List<Channel>.from(_channels);
@@ -7193,7 +7194,15 @@ class MeshCoreConnector extends ChangeNotifier {
       // Only here: an erased slot means the radio lost channels that Restore
       // can put back with their history, and a hole means the list is not
       // known. Neither is a list to judge history against (#1128).
-      if (sawEverySlot) unawaited(_purgeHistoryNotOnRadio());
+      if (sawEverySlot) {
+        unawaited(_purgeHistoryNotOnRadio());
+      } else {
+        _logHistoryCheckSkipped(
+          _slotCountKnown
+              ? 'this sync read $askedSlots of the radio\'s $_maxChannels slots'
+              : 'device info has not said how many slots the radio has',
+        );
+      }
     } else {
       // Holes: keep the last fully-confirmed persisted list for offline use
       // rather than overwriting it with a partial one. The holes are surfaced
@@ -7204,6 +7213,9 @@ class MeshCoreConnector extends ChangeNotifier {
         'Retry the sync to confirm them.',
         tag: 'ChannelSync',
       );
+      _logHistoryCheckSkipped(
+        'slots $_unconfirmedChannelSlots are unconfirmed',
+      );
     }
     _recalculateCachedChannelsUnreadTotal();
 
@@ -7724,6 +7736,14 @@ class MeshCoreConnector extends ChangeNotifier {
     return moved != null;
   }
 
+  /// Every sync says what became of the hidden-history check, so a log never
+  /// leaves "ran and found nothing" indistinguishable from "did not run".
+  void _logHistoryCheckSkipped(String why) => _appDebugLogService?.info(
+    'Hidden channel history check skipped for radio '
+    '${_channelMessageStore.publicKeyHex}: $why. Nothing deleted (#1128)',
+    tag: 'Storage',
+  );
+
   /// Deletes this radio's channel history that no channel on it shows, after
   /// a sync the radio fully confirmed with nothing erased (#1128). Not while a
   /// write is waiting on the radio: the list could be mid-change.
@@ -7733,7 +7753,10 @@ class MeshCoreConnector extends ChangeNotifier {
   /// for this connection, and a key leaves it once the radio holds it again,
   /// so a later delete of that channel is judged normally.
   Future<void> _purgeHistoryNotOnRadio() async {
-    if (_channelWritesInFlight > 0) return;
+    if (_channelWritesInFlight > 0) {
+      _logHistoryCheckSkipped('a channel write is waiting on the radio');
+      return;
+    }
     final onRadio = _channels.where((c) => !c.isUnusable).toList();
     _sparedFromPurge.removeAll(onRadio.map((c) => c.pskHex));
     try {

lib/storage/channel_message_store.dart

@@ -586,6 +586,12 @@ class ChannelMessageStore {
         tag: 'Storage',
       );
     }
+    appLogger.info(
+      'Hidden channel history check for radio $publicKeyHex: '
+      '${candidates.length} stored key(s) against ${radioPskHex.length} '
+      'channel(s) on the radio, ${deleted.length} deleted (#1128)',
+      tag: 'Storage',
+    );
     return deleted;
   }
 

test/connector/channel_write_history_identity_test.dart

@@ -18,11 +18,13 @@ import 'package:meshcore_open/connector/meshcore_protocol.dart';
 import 'package:meshcore_open/models/app_settings.dart';
 import 'package:meshcore_open/models/channel.dart';
 import 'package:meshcore_open/models/channel_message.dart';
+import 'package:meshcore_open/services/app_debug_log_service.dart';
 import 'package:meshcore_open/services/app_settings_service.dart';
 import 'package:meshcore_open/storage/channel_message_store.dart';
 import 'package:meshcore_open/storage/drift/blob_store.dart';
 import 'package:meshcore_open/storage/drift/offband_database.dart';
 import 'package:meshcore_open/storage/prefs_manager.dart';
+import 'package:meshcore_open/utils/app_logger.dart';
 import 'package:shared_preferences/shared_preferences.dart';
 
 Uint8List psk(int fill) => Uint8List.fromList(List<int>.filled(16, fill));
@@ -52,6 +54,13 @@ void main() {
   late MeshCoreConnector connector;
   late AppSettingsService settings;
   late List<Uint8List> sent;
+  late AppDebugLogService log;
+
+  /// What the exported log says about the hidden-history check, newest last.
+  List<String> historyChecks() => [
+    for (final e in log.entries)
+      if (e.message.startsWith('Hidden channel history check')) e.message,
+  ];
 
   final weather = Channel(index: 0, name: 'Weather', psk: psk(0x22));
   final empty = Uint8List(16);
@@ -101,6 +110,9 @@ void main() {
     settings = AppSettingsService();
     await settings.loadSettings();
     connector.setAppSettingsServiceForTest(settings);
+    log = AppDebugLogService()..setEnabled(true);
+    appLogger.initialize(log, enabled: true);
+    connector.setAppDebugLogServiceForTest(log);
 
     // Device info says the radio has [slots] channel slots.
     connector.handleFrameForTest([respCodeDeviceInfo, 14, 100, slots]);
@@ -125,15 +137,27 @@ void main() {
     KeyChangeHistory history, {
     List<int>? addReply,
   }) async {
+    int setFrames() =>
+        sent.where((f) => f.isNotEmpty && f[0] == cmdSetChannel).length;
+    final before = setFrames();
     final edit = connector.editChannel(
       weather,
       'Weather',
       newKey,
       history: history,
     );
-    await settle();
+    Future<void> untilSetFrames(int n) async {
+      // The history move can decode on another isolate, so wait in real time
+      // for the frame rather than a fixed number of microtask turns.
+      for (var i = 0; i < 500 && setFrames() < before + n; i++) {
+        await Future<void>.delayed(const Duration(milliseconds: 5));
+      }
+      expect(setFrames(), before + n, reason: 'set-channel frame $n sent');
+    }
+
+    await untilSetFrames(1);
     ok(); // the clear
-    await settle(50);
+    await untilSetFrames(2);
     connector.handleFrameForTest(addReply ?? [respCodeOk]);
     return edit;
   }
@@ -298,6 +322,10 @@ void main() {
       await radioHolds([('Other', psk(0x33)), null]);
 
       expect(await historyOf(weather.psk).loadChannelMessages(0), isEmpty);
+      expect(
+        historyChecks().last,
+        allOf(contains('against 1 channel(s)'), contains('1 deleted')),
+      );
     });
 
     test(
@@ -328,6 +356,8 @@ void main() {
 
       expect(connector.canRestoreChannelsToRadio, isTrue);
       expect(await historyOf(weather.psk).loadChannelMessages(0), hasLength(1));
+      expect(historyChecks().last, contains('skipped'));
+      expect(historyChecks().last, contains('erased slots'));
     });
 
     test('a sync asked for fewer slots than the radio has', () async {
@@ -336,6 +366,13 @@ void main() {
       await settle(50);
 
       expect(await historyOf(weather.psk).loadChannelMessages(0), hasLength(1));
+      expect(
+        historyChecks().last,
+        contains(
+          'skipped for radio 0001020304: this sync read 1 of the '
+          'radio\'s 2 slots',
+        ),
+      );
     });
 
     test('a radio that reports no channels at all', () async {