From 35b592d2a7aa5d2b13e5cffbf446586bc97c0037 Mon Sep 17 00:00:00 2001 From: Jack Kingsman Date: Mon, 16 Mar 2026 21:13:10 -0700 Subject: [PATCH] Auto-reset node if clock is too far ahead to change --- app/radio_sync.py | 77 +++++++++++++++++++++++++++++++-- tests/test_radio_sync.py | 92 +++++++++++++++++++++++++++++++++++++++- 2 files changed, 164 insertions(+), 5 deletions(-) diff --git a/app/radio_sync.py b/app/radio_sync.py index 30cede6..0dcce0e 100644 --- a/app/radio_sync.py +++ b/app/radio_sync.py @@ -796,16 +796,85 @@ async def stop_periodic_advert(): logger.info("Stopped periodic advertisement") +# Prevents reboot-loop: once we've rebooted to fix clock skew this session, +# don't do it again (the hardware RTC case can't be fixed by reboot). +_clock_reboot_attempted: bool = False + + async def sync_radio_time(mc: MeshCore) -> bool: """Sync the radio's clock with the system time. - Returns True if successful, False otherwise. + The firmware only accepts forward time adjustments (new >= current). + If the radio's clock is already ahead, set_time is silently rejected + with an ERROR response. We detect this by checking the response and, + on failure, querying the radio's actual time so we can log the skew. + + When significant forward skew is detected for the first time in a + session, the radio is rebooted so that boards with a volatile clock + (most companion radios) reset to their default epoch and accept the + correct time on the next connection setup. The reboot is attempted + only once; if it doesn't help (hardware RTC persists the wrong time), + the skew is logged as a warning on subsequent syncs. + + Returns True if the radio accepted the new time, False otherwise. """ + global _clock_reboot_attempted # noqa: PLW0603 try: now = int(time.time()) - await mc.commands.set_time(now) - logger.debug("Synced radio time to %d", now) - return True + result = await mc.commands.set_time(now) + + if result.type == EventType.OK: + logger.debug("Synced radio time to %d", now) + return True + + # Firmware rejected the time (most likely radio clock is ahead). + # Query actual radio time so we can report the delta. + try: + time_result = await mc.commands.get_time() + radio_time = time_result.payload.get("time") if time_result.payload else None + except Exception: + radio_time = None + + if radio_time is not None: + delta = radio_time - now + logger.warning( + "Radio rejected time sync: radio clock is %+d seconds " + "(%+.1f hours) from system time (radio=%d, system=%d).", + delta, + delta / 3600.0, + radio_time, + now, + ) + else: + delta = None + logger.warning( + "Radio rejected time sync (set_time returned %s) " + "and get_time query failed; cannot determine clock skew.", + result.type, + ) + + # If the clock is significantly ahead and we haven't already tried + # a corrective reboot this session, reboot the radio. Boards with + # a volatile RTC (most companion radios) will reset their clock on + # reboot, allowing the next post-connect sync to succeed. + if not _clock_reboot_attempted and (delta is None or delta > 30): + _clock_reboot_attempted = True + logger.warning( + "Rebooting radio to reset clock skew. Boards with a " + "volatile RTC will accept the correct time after restart." + ) + try: + await mc.commands.reboot() + except Exception: + logger.warning("Reboot command failed", exc_info=True) + elif _clock_reboot_attempted: + logger.warning( + "Clock skew persists after reboot — the radio likely has a " + "hardware RTC that preserved the wrong time. A manual " + "'clkreboot' CLI command is needed to reset it." + ) + + return False except Exception as e: logger.warning("Failed to sync radio time: %s", e, exc_info=True) return False diff --git a/tests/test_radio_sync.py b/tests/test_radio_sync.py index 5966754..bc2ab60 100644 --- a/tests/test_radio_sync.py +++ b/tests/test_radio_sync.py @@ -9,6 +9,7 @@ from unittest.mock import AsyncMock, MagicMock, patch import pytest from meshcore import EventType +from meshcore.events import Event from app.models import Favorite from app.radio import RadioManager, radio_manager @@ -162,11 +163,20 @@ class TestPollingPause: class TestSyncRadioTime: """Test the radio time sync function.""" + @pytest.fixture(autouse=True) + def _reset_reboot_flag(self): + """Reset the module-level reboot guard between tests.""" + import app.radio_sync as _mod + + _mod._clock_reboot_attempted = False + yield + _mod._clock_reboot_attempted = False + @pytest.mark.asyncio async def test_returns_true_on_success(self): """sync_radio_time returns True when time is set successfully.""" mock_mc = MagicMock() - mock_mc.commands.set_time = AsyncMock() + mock_mc.commands.set_time = AsyncMock(return_value=Event(EventType.OK, {})) result = await sync_radio_time(mock_mc) @@ -188,6 +198,86 @@ class TestSyncRadioTime: assert result is False + @pytest.mark.asyncio + async def test_returns_false_when_firmware_rejects_and_reboots(self): + """sync_radio_time reboots radio on first rejection with significant skew.""" + import time as _time + + radio_time = int(_time.time()) + 86400 # radio is 1 day ahead + mock_mc = MagicMock() + mock_mc.commands.set_time = AsyncMock( + return_value=Event(EventType.ERROR, {"reason": "illegal_arg"}) + ) + mock_mc.commands.get_time = AsyncMock( + return_value=Event(EventType.CURRENT_TIME, {"time": radio_time}) + ) + mock_mc.commands.reboot = AsyncMock() + + result = await sync_radio_time(mock_mc) + + assert result is False + mock_mc.commands.get_time.assert_called_once() + mock_mc.commands.reboot.assert_called_once() + + @pytest.mark.asyncio + async def test_does_not_reboot_twice(self): + """Second rejection logs hardware RTC warning instead of rebooting.""" + import time as _time + + import app.radio_sync as _mod + + _mod._clock_reboot_attempted = True # simulate prior reboot + + radio_time = int(_time.time()) + 86400 + mock_mc = MagicMock() + mock_mc.commands.set_time = AsyncMock( + return_value=Event(EventType.ERROR, {"reason": "illegal_arg"}) + ) + mock_mc.commands.get_time = AsyncMock( + return_value=Event(EventType.CURRENT_TIME, {"time": radio_time}) + ) + mock_mc.commands.reboot = AsyncMock() + + result = await sync_radio_time(mock_mc) + + assert result is False + mock_mc.commands.reboot.assert_not_called() + + @pytest.mark.asyncio + async def test_returns_false_when_rejected_and_get_time_fails(self): + """sync_radio_time reboots even when get_time fails (unknown skew).""" + mock_mc = MagicMock() + mock_mc.commands.set_time = AsyncMock( + return_value=Event(EventType.ERROR, {"reason": "illegal_arg"}) + ) + mock_mc.commands.get_time = AsyncMock(side_effect=Exception("timeout")) + mock_mc.commands.reboot = AsyncMock() + + result = await sync_radio_time(mock_mc) + + assert result is False + mock_mc.commands.reboot.assert_called_once() + + @pytest.mark.asyncio + async def test_no_reboot_for_small_skew(self): + """No reboot when radio is only slightly ahead (within tolerance).""" + import time as _time + + radio_time = int(_time.time()) + 5 # only 5 seconds ahead + mock_mc = MagicMock() + mock_mc.commands.set_time = AsyncMock( + return_value=Event(EventType.ERROR, {"reason": "illegal_arg"}) + ) + mock_mc.commands.get_time = AsyncMock( + return_value=Event(EventType.CURRENT_TIME, {"time": radio_time}) + ) + mock_mc.commands.reboot = AsyncMock() + + result = await sync_radio_time(mock_mc) + + assert result is False + mock_mc.commands.reboot.assert_not_called() + class TestSyncRecentContactsToRadio: """Test the sync_recent_contacts_to_radio function."""