From 74176fb07d28d61cf05e195f6624cc6cc3cbfd62 Mon Sep 17 00:00:00 2001 From: diffwireauto <330573775+diffwireauto@users.noreply.github.com> Date: Mon, 9 Nov 2026 01:56:48 -0500 Subject: [PATCH] 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 --- lib/connector/meshcore_connector.dart | 31 ++++++++++++-- lib/storage/channel_message_store.dart | 6 +++ .../channel_write_history_identity_test.dart | 41 ++++++++++++++++++- 3 files changed, 72 insertions(+), 6 deletions(-) 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 {