diff --git a/CHANGELOG.md b/CHANGELOG.md index 3837fcc..7c672c8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,15 @@ semantic versioning. unchanged. - `cmd` no longer lists commands that are disabled in `config.ini`. Commands with no `[_Command]` section at all are still listed, as before. +- Stale-contact cleanup no longer retries forever (#176). When the device refuses to + remove a contact the contact stays in the list, so every sweep re-selected it and + logged the same failure again — hundreds of `Failed to remove stale contact` warnings + that only a restart cleared. A contact is now dropped from cleanup after + 3 consecutive refusals, with one summary warning explaining that the list may stay + near its limit. A successful removal clears the count. +- Contacts whose `last_seen` is unset (parsing as 1970) or in the future are no longer + treated as stale. They sorted to the top of the staleness list and consumed the whole + per-sweep removal budget, crowding out contacts that could actually be removed. ### Added diff --git a/modules/repeater_manager.py b/modules/repeater_manager.py index e0e9ac6..77fb7b4 100644 --- a/modules/repeater_manager.py +++ b/modules/repeater_manager.py @@ -107,6 +107,15 @@ def validate_repeater_tables(db_manager: Any, logger: Any) -> None: class RepeaterManager: """Manages repeater contacts database and purging operations""" + # A contact the device keeps refusing is dropped from future sweeps after this many + # consecutive failures, so one unremovable contact cannot generate warnings forever. + MAX_STALE_REMOVAL_ATTEMPTS = 3 + + # last_seen values at or before this are not real observations (a zero/unset + # timestamp parses as 1970). They would otherwise sort to the top of the + # staleness list and consume the whole removal budget every sweep. + MIN_PLAUSIBLE_LAST_SEEN = datetime(2020, 1, 1) + def __init__(self, bot): self.bot = bot self.logger = bot.logger @@ -118,6 +127,11 @@ class RepeaterManager: # Initialize repeater-specific tables self._init_repeater_tables() + # Public keys the device has refused to remove, and how many times. A refusal + # leaves the contact in place, so without this the next sweep re-selects the + # same contacts and retries forever (see issue #176). + self._stale_removal_failures: dict[str, int] = {} + # Initialize auto-purge monitoring self.contact_limit = 300 # MeshCore device limit (will be updated from device info) self.auto_purge_threshold = 280 # Start purging when 280+ contacts @@ -2711,12 +2725,32 @@ class RepeaterManager: # Assume it's already a datetime object last_seen_dt = last_seen + now = datetime.now() + + # A zero/unset timestamp parses as 1970 and would otherwise sort + # to the top of the list, spending the whole removal budget on + # contacts whose staleness is not actually known. Same for a + # timestamp in the future, which cannot be a past observation. + if last_seen_dt < self.MIN_PLAUSIBLE_LAST_SEEN or last_seen_dt > now: + self.logger.debug( + "Ignoring implausible last_seen %r for contact %s", + last_seen, + sanitize_name(contact_data.get('name', 'Unknown')), + ) + continue + if last_seen_dt < cutoff_date: + public_key = contact_data.get('public_key', '') + attempts = self._stale_removal_failures.get(public_key, 0) + if public_key and attempts >= self.MAX_STALE_REMOVAL_ATTEMPTS: + # Already given up on this one; excluded so it does not + # keep occupying the removal budget or the warning log. + continue stale_contacts.append({ 'name': contact_data.get('name', contact_data.get('adv_name', 'Unknown')), - 'public_key': contact_data.get('public_key', ''), + 'public_key': public_key, 'last_seen': last_seen, - 'days_stale': (datetime.now() - last_seen_dt).days + 'days_stale': (now - last_seen_dt).days }) except Exception as e: self.logger.debug(f"Error parsing timestamp for contact {sanitize_name(contact_data.get('name', 'Unknown'))}: {e}") @@ -2784,6 +2818,7 @@ class RepeaterManager: """Remove stale contacts to free up space""" try: removed_count = 0 + given_up = 0 for contact in stale_contacts[:max_remove]: try: @@ -2805,6 +2840,7 @@ class RepeaterManager: if result.type == EventType.OK: removed_count += 1 + self._stale_removal_failures.pop(public_key, None) self.logger.info(f"✅ Successfully removed stale contact: {contact_name}") # Log the removal @@ -2814,7 +2850,24 @@ class RepeaterManager: ) else: error_code = result.payload.get('error_code', 'unknown') if hasattr(result, 'payload') else 'unknown' - self.logger.warning(f"❌ Failed to remove stale contact: {contact_name} - Error: {result.type}, Code: {error_code}") + # A refusal leaves the contact on the device, so the next sweep + # would pick it up again. Count the attempt and stop after a few. + attempts = self._stale_removal_failures.get(public_key, 0) + 1 + self._stale_removal_failures[public_key] = attempts + + if attempts >= self.MAX_STALE_REMOVAL_ATTEMPTS: + given_up += 1 + self.logger.warning( + f"❌ Giving up on stale contact: {contact_name} - the device " + f"refused removal {attempts} times (last error: {result.type}, " + f"Code: {error_code}). It will be skipped from now on." + ) + else: + self.logger.warning( + f"❌ Failed to remove stale contact: {contact_name} - " + f"Error: {result.type}, Code: {error_code} " + f"(attempt {attempts}/{self.MAX_STALE_REMOVAL_ATTEMPTS})" + ) # Small delay between removals await asyncio.sleep(1) @@ -2823,6 +2876,14 @@ class RepeaterManager: self.logger.error(f"Error removing stale contact {sanitize_name(contact.get('name', 'Unknown'))}: {e}") continue + if given_up: + self.logger.warning( + "%d stale contact(s) could not be removed by the device and are now " + "excluded from cleanup. The contact list may stay near its limit; " + "remove them from the companion app if space is needed.", + given_up, + ) + return removed_count except Exception as e: diff --git a/tests/test_repeater_manager.py b/tests/test_repeater_manager.py index 2ac84ca..156c018 100644 --- a/tests/test_repeater_manager.py +++ b/tests/test_repeater_manager.py @@ -1668,3 +1668,139 @@ class TestUpdateContactLimitFromDevice: assert rm.contact_limit == 300 assert rm.auto_purge_threshold == 280 + + +class TestStaleContactRemovalStorm: + """Issue #176: a contact the device refuses stays in the list, so every sweep + re-selected it and logged the same failure forever.""" + + @staticmethod + def _manager(contacts): + mgr = object.__new__(RepeaterManager) + mgr.bot = SimpleNamespace( + meshcore=SimpleNamespace(contacts=contacts, commands=SimpleNamespace()), + ) + mgr.logger = Mock() + mgr._stale_removal_failures = {} + mgr._is_repeater_device = lambda contact_data: False + mgr.log_purging_action = Mock() + return mgr + + @staticmethod + def _contact(name, key, days_ago): + seen = (datetime.now() - timedelta(days=days_ago)).timestamp() + return {'name': name, 'public_key': key, 'last_seen': seen} + + @staticmethod + def _result(ok): + if ok: + return SimpleNamespace(type=EventType.OK, payload={}) + return SimpleNamespace(type=EventType.ERROR, payload={'error_code': 2}) + + def _refusing_device(self, mgr): + mgr.bot.meshcore.commands.remove_contact = AsyncMock(return_value=self._result(False)) + + @pytest.mark.asyncio + async def test_refused_contact_is_dropped_after_the_attempt_limit(self): + contacts = {'a': self._contact('variable', 'KEY_A', 30)} + mgr = self._manager(contacts) + self._refusing_device(mgr) + + with patch('asyncio.sleep', new=AsyncMock()): + for _ in range(RepeaterManager.MAX_STALE_REMOVAL_ATTEMPTS): + stale = await mgr._get_stale_contacts() + assert stale, "should still be attempted before the limit" + await mgr._remove_stale_contacts(stale) + + # The storm stops: the contact is no longer selected at all. + assert await mgr._get_stale_contacts() == [] + + @pytest.mark.asyncio + async def test_gives_up_message_is_logged_once(self): + contacts = {'a': self._contact('variable', 'KEY_A', 30)} + mgr = self._manager(contacts) + self._refusing_device(mgr) + + with patch('asyncio.sleep', new=AsyncMock()): + for _ in range(RepeaterManager.MAX_STALE_REMOVAL_ATTEMPTS): + stale = await mgr._get_stale_contacts() + if stale: + await mgr._remove_stale_contacts(stale) + + warnings = [str(c) for c in mgr.logger.warning.call_args_list] + assert sum('Giving up' in w for w in warnings) == 1 + + @pytest.mark.asyncio + async def test_successful_removal_clears_the_failure_count(self): + contacts = {'a': self._contact('flaky', 'KEY_A', 30)} + mgr = self._manager(contacts) + mgr.bot.meshcore.commands.remove_contact = AsyncMock( + side_effect=[self._result(False), self._result(True)] + ) + + with patch('asyncio.sleep', new=AsyncMock()): + await mgr._remove_stale_contacts(await mgr._get_stale_contacts()) + assert mgr._stale_removal_failures.get('KEY_A') == 1 + removed = await mgr._remove_stale_contacts(await mgr._get_stale_contacts()) + + assert removed == 1 + assert 'KEY_A' not in mgr._stale_removal_failures + + @pytest.mark.asyncio + async def test_other_contacts_are_unaffected_by_one_bad_apple(self): + contacts = { + 'a': self._contact('stubborn', 'KEY_A', 40), + 'b': self._contact('removable', 'KEY_B', 30), + } + mgr = self._manager(contacts) + + async def remove(public_key): + return self._result(public_key != 'KEY_A') + + mgr.bot.meshcore.commands.remove_contact = AsyncMock(side_effect=remove) + + with patch('asyncio.sleep', new=AsyncMock()): + removed = await mgr._remove_stale_contacts(await mgr._get_stale_contacts()) + + assert removed == 1 + assert mgr._stale_removal_failures == {'KEY_A': 1} + + +class TestStaleContactTimestampSanity: + """Unset timestamps parse as 1970 and sorted to the top, spending the whole + removal budget on contacts whose real staleness is unknown.""" + + @staticmethod + def _manager(contacts): + return TestStaleContactRemovalStorm._manager(contacts) + + @pytest.mark.asyncio + async def test_zero_timestamp_is_ignored(self): + mgr = self._manager({'a': {'name': 'never-heard', 'public_key': 'K', 'last_seen': 0}}) + assert await mgr._get_stale_contacts() == [] + + @pytest.mark.asyncio + async def test_future_timestamp_is_ignored(self): + future = (datetime.now() + timedelta(days=5)).timestamp() + mgr = self._manager({'a': {'name': 'clock-skew', 'public_key': 'K', 'last_seen': future}}) + assert await mgr._get_stale_contacts() == [] + + @pytest.mark.asyncio + async def test_genuinely_old_contact_is_still_selected(self): + """722 days ago is a real observation, not a bad timestamp.""" + mgr = self._manager({'a': TestStaleContactRemovalStorm._contact('old', 'K', 722)}) + stale = await mgr._get_stale_contacts() + assert len(stale) == 1 + assert stale[0]['days_stale'] == 722 + + @pytest.mark.asyncio + async def test_junk_timestamps_no_longer_crowd_out_real_candidates(self): + contacts = {f'junk{i}': {'name': f'j{i}', 'public_key': f'J{i}', 'last_seen': 0} + for i in range(12)} + contacts['real'] = TestStaleContactRemovalStorm._contact('real', 'REAL', 30) + mgr = self._manager(contacts) + + stale = await mgr._get_stale_contacts() + + # Without the guard the twelve 1970 entries sort first and fill max_remove=10. + assert [c['public_key'] for c in stale] == ['REAL']