diff --git a/lib/connector/meshcore_connector.dart b/lib/connector/meshcore_connector.dart index 98feeb04..52006501 100644 --- a/lib/connector/meshcore_connector.dart +++ b/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.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 _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 { diff --git a/lib/storage/channel_message_store.dart b/lib/storage/channel_message_store.dart index 32485573..04e92f76 100644 --- a/lib/storage/channel_message_store.dart +++ b/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; } diff --git a/test/connector/channel_write_history_identity_test.dart b/test/connector/channel_write_history_identity_test.dart index dcab6705..7c078f47 100644 --- a/test/connector/channel_write_history_identity_test.dart +++ b/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.filled(16, fill)); @@ -52,6 +54,13 @@ void main() { late MeshCoreConnector connector; late AppSettingsService settings; late List sent; + late AppDebugLogService log; + + /// What the exported log says about the hidden-history check, newest last. + List 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? 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 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.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 {