diff --git a/CHANGELOG.md b/CHANGELOG.md index 7c672c8..7ec4426 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -26,9 +26,15 @@ semantic versioning. 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. +- Contacts whose device clock was never set are no longer treated as stale. MeshCore + seeds an unset clock with a hardcoded time — `1715770351` (15 May 2024) or + `1772323200` (1 Mar 2026) — so a never-synced node advertises that seed rather than + a real observation. The bot read it as extreme staleness, which put unsynced but + perfectly active contacts at the top of the removal list, consuming the whole + per-sweep budget and repeatedly trying to evict live nodes. This is what the + `722 days ago` entries in #176 were: the 15 May 2024 seed, not contacts last heard + in 2024. A raw `0` (decoding to 1970) is covered too, and genuine adverts near a + seed are unaffected. ### Added diff --git a/modules/repeater_manager.py b/modules/repeater_manager.py index 77fb7b4..9017b22 100644 --- a/modules/repeater_manager.py +++ b/modules/repeater_manager.py @@ -111,10 +111,19 @@ class RepeaterManager: # 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) + # MeshCore firmware seeds an unset clock with a hardcoded time, so a device that + # has never been synced advertises one of these rather than a real observation: + # 1715770351 — 15 May 2024, VolatileRTCClock's base_time (helpers/ArduinoHelpers.h) + # 1772323200 — 1 Mar 2026, RTC_TIME_MIN used by the NRF52 and ESP32 RTC paths + # These are not staleness. Treating them as such made unsynced-but-active contacts + # look like the oldest entries in the list: they sorted to the top, consumed the + # whole per-sweep removal budget, and the bot kept trying to evict live nodes + # (see issue #176, where every affected contact reported exactly 722 days). + FIRMWARE_CLOCK_SEEDS = (1715770351, 1772323200) + + # Nothing below the earliest seed can be a real observation either; a raw 0 for a + # contact that was never heard decodes to 1970. + FIRMWARE_CLOCK_FLOOR = 1715770351 def __init__(self, bot): self.bot = bot @@ -2696,6 +2705,21 @@ class RepeaterManager: self.logger.error(f"Error getting contact list status: {e}") return {} + @classmethod + def _is_unset_device_clock(cls, last_seen_dt: datetime) -> bool: + """True when a last_seen came from a device whose clock was never set. + + Matches the firmware's hardcoded seeds exactly, plus anything at or below the + earliest of them (which also covers a raw 0 decoding to 1970). A device that + has been running unsynced for a while reports seed + uptime and is not + detectable this way; those still look stale, but they are at least removable. + """ + if last_seen_dt <= datetime.fromtimestamp(cls.FIRMWARE_CLOCK_FLOOR): + return True + return any( + last_seen_dt == datetime.fromtimestamp(seed) for seed in cls.FIRMWARE_CLOCK_SEEDS + ) + async def _get_stale_contacts(self, days_without_advert: int = 7) -> list[dict]: """Get contacts that haven't sent adverts in specified days""" try: @@ -2727,13 +2751,13 @@ class RepeaterManager: 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: + # An unset device clock reports a firmware seed, which says + # nothing about when the contact was last heard. A future + # timestamp cannot be a past observation either. + if self._is_unset_device_clock(last_seen_dt) or last_seen_dt > now: self.logger.debug( - "Ignoring implausible last_seen %r for contact %s", + "Ignoring unset/implausible last_seen %r for contact %s " + "(device clock not set)", last_seen, sanitize_name(contact_data.get('name', 'Unknown')), ) diff --git a/tests/test_repeater_manager.py b/tests/test_repeater_manager.py index 156c018..1c1ee20 100644 --- a/tests/test_repeater_manager.py +++ b/tests/test_repeater_manager.py @@ -1767,8 +1767,9 @@ class TestStaleContactRemovalStorm: class TestStaleContactTimestampSanity: - """Unset timestamps parse as 1970 and sorted to the top, spending the whole - removal budget on contacts whose real staleness is unknown.""" + """MeshCore seeds an unset clock with a hardcoded time, so a never-synced device + advertises that seed rather than a real observation. Treating it as staleness put + unsynced-but-active contacts at the top of the removal list.""" @staticmethod def _manager(contacts): @@ -1785,13 +1786,36 @@ class TestStaleContactTimestampSanity: mgr = self._manager({'a': {'name': 'clock-skew', 'public_key': 'K', 'last_seen': future}}) assert await mgr._get_stale_contacts() == [] + @pytest.mark.parametrize("seed", RepeaterManager.FIRMWARE_CLOCK_SEEDS) @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)}) + async def test_firmware_clock_seed_is_ignored(self, seed): + """1715770351 (15 May 2024) and 1772323200 (1 Mar 2026) are unset-clock seeds.""" + mgr = self._manager({'a': {'name': 'never-synced', 'public_key': 'K', 'last_seen': seed}}) + assert await mgr._get_stale_contacts() == [] + + @pytest.mark.asyncio + async def test_the_reported_722_day_contacts_are_ignored(self): + """Issue #176: every affected contact reported exactly 722 days, which is the + 15 May 2024 firmware seed measured from the date in the report. They were + unsynced clocks, not contacts genuinely last heard in 2024.""" + mgr = self._manager( + {'a': {'name': 'variable', 'public_key': 'K', 'last_seen': 1715770351}} + ) + assert await mgr._get_stale_contacts() == [] + + @pytest.mark.asyncio + async def test_a_real_observation_near_a_seed_is_still_selected(self): + """Only the seed itself is a sentinel; a real advert a day later is not.""" + just_after = 1715770351 + 86400 + mgr = self._manager({'a': {'name': 'early', 'public_key': 'K', 'last_seen': just_after}}) stale = await mgr._get_stale_contacts() assert len(stale) == 1 - assert stale[0]['days_stale'] == 722 + + @pytest.mark.asyncio + async def test_recent_contact_is_not_stale(self): + """Control: the filter is not simply rejecting everything.""" + mgr = self._manager({'a': TestStaleContactRemovalStorm._contact('recent', 'K', 30)}) + assert len(await mgr._get_stale_contacts()) == 1 @pytest.mark.asyncio async def test_junk_timestamps_no_longer_crowd_out_real_candidates(self):