diff --git a/app/radio_sync.py b/app/radio_sync.py index c9912f0..e0116bd 100644 --- a/app/radio_sync.py +++ b/app/radio_sync.py @@ -855,7 +855,7 @@ async def _attempt_clock_wraparound(mc: MeshCore, *, now: int, observed_radio_ti return False -async def sync_radio_time(mc: MeshCore) -> bool: +async def sync_radio_time(mc: MeshCore, *, warn_on_failure: bool = True) -> bool: """Sync the radio's clock with the system time. The firmware only accepts forward time adjustments (new >= current). @@ -870,9 +870,15 @@ async def sync_radio_time(mc: MeshCore) -> bool: only once; if it doesn't help (hardware RTC persists the wrong time), the skew is logged as a warning on subsequent syncs. + ``warn_on_failure`` controls log severity for rejected/failed sync attempts. + Startup and reconnect setup should leave this enabled so operators see the + initial skew problem. Periodic maintenance syncs pass ``False`` to avoid + repeating the same warning every few minutes after startup. + Returns True if the radio accepted the new time, False otherwise. """ global _clock_reboot_attempted # noqa: PLW0603 + log_failure = logger.warning if warn_on_failure else logger.debug try: now = int(time.time()) preflight_radio_time: int | None = None @@ -901,7 +907,7 @@ async def sync_radio_time(mc: MeshCore) -> bool: if radio_time is not None: delta = radio_time - now - logger.warning( + log_failure( "Radio rejected time sync: radio clock is %+d seconds " "(%+.1f hours) from system time (radio=%d, system=%d).", delta, @@ -911,7 +917,7 @@ async def sync_radio_time(mc: MeshCore) -> bool: ) else: delta = None - logger.warning( + log_failure( "Radio rejected time sync (set_time returned %s) " "and get_time query failed; cannot determine clock skew.", result.type, @@ -936,14 +942,14 @@ async def sync_radio_time(mc: MeshCore) -> bool: # 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( + log_failure( "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) + log_failure("Reboot command failed", exc_info=True) elif _clock_reboot_attempted: logger.debug( "Clock skew persists after reboot (hardware RTC); ignoring until next session." @@ -951,7 +957,7 @@ async def sync_radio_time(mc: MeshCore) -> bool: return False except Exception as e: - logger.warning("Failed to sync radio time: %s", e, exc_info=True) + log_failure("Failed to sync radio time: %s", e, exc_info=True) return False @@ -971,7 +977,7 @@ async def _periodic_sync_loop(): ) as mc: if await should_run_full_periodic_sync(mc): await sync_and_offload_all(mc) - await sync_radio_time(mc) + await sync_radio_time(mc, warn_on_failure=False) except RadioOperationBusyError: logger.debug("Skipping periodic sync: radio busy") except asyncio.CancelledError: diff --git a/tests/test_radio_sync.py b/tests/test_radio_sync.py index 8471307..a0da173 100644 --- a/tests/test_radio_sync.py +++ b/tests/test_radio_sync.py @@ -353,6 +353,32 @@ class TestSyncRadioTime: assert result is False mock_mc.commands.reboot.assert_not_called() + @pytest.mark.asyncio + async def test_background_failures_log_debug_instead_of_warning(self, caplog): + """Periodic syncs should not keep emitting warning-level clock skew logs.""" + import time as _time + + 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() + + with caplog.at_level("DEBUG"): + result = await sync_radio_time(mock_mc, warn_on_failure=False) + + assert result is False + assert "Radio rejected time sync:" in caplog.text + assert not [ + rec + for rec in caplog.records + if rec.levelname == "WARNING" and "Radio rejected time sync:" in rec.message + ] + class TestSyncRecentContactsToRadio: """Test the sync_recent_contacts_to_radio function.""" @@ -1686,7 +1712,7 @@ class TestPeriodicSyncLoopRaces: mock_cleanup.assert_called_once() mock_sync.assert_called_once_with(mock_mc) - mock_time.assert_called_once_with(mock_mc) + mock_time.assert_called_once_with(mock_mc, warn_on_failure=False) @pytest.mark.asyncio async def test_skips_full_sync_below_threshold_but_still_syncs_time(self): @@ -1710,7 +1736,7 @@ class TestPeriodicSyncLoopRaces: mock_cleanup.assert_called_once() mock_sync.assert_not_called() - mock_time.assert_called_once_with(mock_mc) + mock_time.assert_called_once_with(mock_mc, warn_on_failure=False) # ---------------------------------------------------------------------------