fix(contacts): detect unset device clocks by firmware seed (#176)

Corrects the timestamp guard shipped in 5b07ee2, which assumed the
reporter's "722 days ago" contacts were genuine mid-2024 observations.
They were not.

MeshCore seeds an unset clock with a hardcoded time rather than zero:
1715770351 (15 May 2024) in VolatileRTCClock, and RTC_TIME_MIN
1772323200 (1 Mar 2026) on the NRF52 and ESP32 RTC paths. Measured from
the date in the issue, 1715770351 is exactly 722 days — every affected
contact reported the same figure because they were all sitting on the
same seed.

So those contacts were never stale. Their clocks were unset, and the bot
was reading that as extreme age: they sorted to the top of the staleness
list, consumed the whole per-sweep removal budget, and the bot kept
trying to evict nodes that may well have been active. The previous
2020-then-2024-01-01 floor sat below both seeds and never fired.

Now matched against the seeds themselves, plus anything at or below the
earliest (which still covers a raw 0 decoding to 1970). A device running
unsynced for a while reports seed + uptime and remains undetectable;
noted in the docstring rather than guessed at.
This commit is contained in:
agessaman
2026-08-21 22:20:08 -07:00
parent 5b07ee2f71
commit c1cbdf9878
3 changed files with 73 additions and 19 deletions
+9 -3
View File
@@ -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
+34 -10
View File
@@ -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')),
)
+30 -6
View File
@@ -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):