From 79137598cf1365ffce4c8f5f96e26f1d9eaa8727 Mon Sep 17 00:00:00 2001 From: Jean-Pierre Martineau Date: Fri, 25 Sep 2026 17:10:09 -0400 Subject: [PATCH] Clock sync explains a radio whose clock is ahead instead of calling it malformed MeshCore firmware sets its clock only forward: CMD_SET_DEVICE_TIME with an earlier time is answered ERR_CODE_ILLEGAL_ARG, which read as 'the device rejected the request as malformed'. Since 2026-09-24 the companion's clock has been ahead of this computer's (itself within 0.7 s of NTP), so every connect's sync was refused. set_clock now reads the radio's clock first: within a minute ahead is in sync and nothing is written; further ahead raises ClockAheadError, which says by how much and that a reboot resets it. The device layer also maps the firmware's refusal to that error, and the simulator's clock now only moves forward, like the firmware's. Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 6 +++ meshterm/core/connection.py | 63 +++++++++++++++++++++++++- meshterm/services/clock_sync.py | 44 ++++++++++++++++-- meshterm/tools/config.py | 12 +++-- tests/test_clock_sync.py | 79 ++++++++++++++++++++++++++++++--- 5 files changed, 191 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e137950..dc80e6d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -50,6 +50,12 @@ one caveat SemVer makes for a leading zero: while the major version is still `0` ### Fixed +- **Clock sync explains a radio whose clock is ahead, instead of calling it malformed.** + MeshCore firmware never sets its clock back, so once a radio's clock ran ahead of the + computer's — a GPS fix, another app, drift — every sync was refused and logged as "the + device rejected the request as malformed". MeshTerm now reads the radio's clock first: a + few seconds ahead is in sync and left alone, and further ahead says by how much and that + rebooting the radio resets it. - **The default flood scope is stored the way the firmware and the MeshCore app store it.** MeshTerm saved it as `#name` where they save `name`, refused a 30-character name the firmware accepts, and mis-framed a name with an accent. Device config also now refuses diff --git a/meshterm/core/connection.py b/meshterm/core/connection.py index d38f8c3..f05c211 100644 --- a/meshterm/core/connection.py +++ b/meshterm/core/connection.py @@ -218,6 +218,47 @@ class ContactNotOnDeviceError(DeviceCommandError): self.contact = contact +class ClockAheadError(DeviceCommandError): + """The radio's clock is ahead of the time being written, and firmware won't go back. + + MeshCore's companion firmware sets its clock only *forward*: ``CMD_SET_DEVICE_TIME`` + with a time earlier than the one it holds is answered ``ERR_CODE_ILLEGAL_ARG`` + (``examples/companion_radio/MyMesh.cpp``), which the error table reads as "malformed" — + true of the argument, and no help to anyone. A clock a GPS fix, another app, or plain + drift carried past this computer's stays there until the radio reboots, so a set that + meets one is not a failure to retry but a fact to state. + + Attributes: + ahead_s: How far ahead the radio's clock was, in seconds, or ``None`` where it was + not read (the firmware's refusal says only *that* it is ahead). + """ + + def __init__(self, ahead_s: int | None) -> None: + """Say how far ahead the clock is, and what does and does not move it. + + Args: + ahead_s: Seconds ahead of the time written, or ``None`` when unknown. + """ + by = f" {_span(ahead_s)}" if ahead_s is not None else "" + super().__init__( + f"the radio's clock is{by} ahead of this computer's, and MeshCore firmware never " + "sets its clock back — rebooting the radio resets it" + ) + self.ahead_s = ahead_s + + +def _span(seconds: int) -> str: + """A duration as a person says it: ``3 s``, ``12 min``, ``5 h``, ``2 days``.""" + seconds = abs(int(seconds)) + if seconds < 120: + return f"{seconds} s" + if seconds < 2 * 3600: + return f"{seconds // 60} min" + if seconds < 2 * 86400: + return f"{seconds // 3600} h" + return f"{seconds // 86400} days" + + class DeviceAuthenticationError(DeviceCommandError): """A Bluetooth companion refused the connection because it needs a pairing PIN/bond. @@ -334,6 +375,10 @@ def _scope_refusal(scope: str, exc: BaseException) -> str: #: ``ERR_CODE_NOT_FOUND`` — the companion has no entry matching what a command addressed. _ERR_NOT_FOUND = 2 +#: ``ERR_CODE_ILLEGAL_ARG`` — an argument the firmware refuses; for ``CMD_SET_DEVICE_TIME`` +#: specifically, a time earlier than the clock it already holds (see :class:`ClockAheadError`). +_ERR_ILLEGAL_ARG = 6 + #: ``CMD_SET_AUTOADD_CONFIG`` — the auto-add bitmask, and (as an optional second byte, which #: the ``meshcore`` library never sends) the hop limit. _CMD_SET_AUTOADD_CONFIG = 58 @@ -1498,7 +1543,12 @@ class Device(ABC): @abstractmethod async def set_time(self, epoch: int) -> None: - """Set the device clock to a UNIX epoch timestamp.""" + """Set the device clock to a UNIX epoch timestamp. + + Raises: + ClockAheadError: If the device's clock is already later than ``epoch`` — + MeshCore firmware only moves its clock forward. + """ @abstractmethod async def send_advert(self, flood: bool = False) -> None: @@ -3722,7 +3772,12 @@ class MeshCoreDevice(Device): self._ok(await self._require().commands.set_channel(index, name, secret)) async def set_time(self, epoch: int) -> None: # noqa: D102 - inherited docstring - self._ok(await self._require().commands.set_time(epoch)) + event = await self._require().commands.set_time(epoch) + if getattr(event, "is_error", lambda: False)() and error_code(event) == _ERR_ILLEGAL_ARG: + # The one argument the set-time handler refuses: a time behind the radio's own + # clock, which firmware never winds back (see ClockAheadError). + raise ClockAheadError(None) + self._ok(event) async def send_advert(self, flood: bool = False) -> None: # noqa: D102 transmit_gate.mark(flood_advert=flood) @@ -4337,6 +4392,10 @@ class MockDevice(Device): async def set_time(self, epoch: int) -> None: # noqa: D102 - inherited docstring import time as _time + # Like the firmware, the simulated clock only ever moves forward. + current = await self.get_time() + if current is not None and epoch < current: + raise ClockAheadError(None) self._info["clock"] = epoch # The simulated clock now runs from the set point (drift corrected). self._clock_offset = epoch - int(_time.time()) diff --git a/meshterm/services/clock_sync.py b/meshterm/services/clock_sync.py index ca1e1c7..85584b5 100644 --- a/meshterm/services/clock_sync.py +++ b/meshterm/services/clock_sync.py @@ -11,6 +11,13 @@ and acknowledges on screen; :class:`ClockSync` calls the same function on its ow per connection, when the ``set_clock_on_connect`` preference asks for it (off by default — writing to a radio that nobody asked to be written to is a choice the owner makes). +**Forward only.** MeshCore firmware never sets its clock back: a time earlier than the one +it holds is refused (:class:`~meshterm.core.connection.ClockAheadError`). So a radio whose +clock has run ahead of this computer's — a GPS fix, another app, drift — is read first and +not written at all: a few seconds ahead is simply in sync, and more is stated plainly with +what resets it, rather than retried every connect into a refusal the firmware's error code +calls "malformed". + The automatic set is a background step, not a startup step: the connect path hands the device over and carries on, and the write happens in a task of its own so a slow or silent firmware never holds the menu. It reports in the **log**, never on screen. @@ -30,23 +37,35 @@ from dataclasses import dataclass from datetime import datetime from typing import TYPE_CHECKING +from ..core.connection import ClockAheadError + if TYPE_CHECKING: from ..context import AppContext from ..core.connection import Device +#: How far ahead a radio's clock may run and still count as in sync. Two clocks a few +#: seconds apart — a GPS-disciplined radio beside a PC that is itself a second or so off +#: true time — are not a problem to report, and the firmware couldn't close the gap anyway. +IN_SYNC_AHEAD_S = 60 + @dataclass(frozen=True, slots=True) class ClockSet: """What one clock set did. Attributes: - epoch: The UNIX time written to the device. + epoch: The UNIX time written to the device — or, where nothing was written, the + time the device already held. drift_s: How far the device's clock was from ours *before* the set (device minus host, seconds), or ``None`` where the firmware would not report its clock. + written: Whether the clock was written. ``False`` when it was already a few + seconds ahead (within :data:`IN_SYNC_AHEAD_S`), which firmware would refuse to + set back and which needs no setting. """ epoch: int drift_s: int | None + written: bool = True @property def set_at(self) -> datetime: @@ -72,13 +91,23 @@ async def set_clock(device: Device) -> ClockSet: The instant written and the drift it corrected. Raises: - Whatever the device raises when the write itself fails. + ClockAheadError: If the device's clock is ahead of this computer's by more than + :data:`IN_SYNC_AHEAD_S` (read first) or the firmware refused the write as one + that would set it back. Within the margin nothing is written, and the result + says so (``written`` false). + Whatever the device raises when the write itself fails otherwise. """ try: before = await device.get_time() except Exception: # noqa: BLE001 - optional read; the drift is a nicety before = None epoch = int(time.time()) + if before is not None and before > epoch: + # Firmware only moves its clock forward, so a write here could only be refused. + # Close enough is in sync; further ahead is a fact to state, not a write to retry. + if before - epoch > IN_SYNC_AHEAD_S: + raise ClockAheadError(before - epoch) + return ClockSet(epoch=before, drift_s=before - epoch, written=False) await device.set_time(epoch) return ClockSet(epoch=epoch, drift_s=None if before is None else before - epoch) @@ -161,10 +190,19 @@ class ClockSync: done = await set_clock(device) except asyncio.CancelledError: raise + except ClockAheadError as exc: + log.warning("clock sync: left the device clock alone: %s", exc) + return except Exception as exc: # noqa: BLE001 - best-effort; the link is not ours to break log.warning("clock sync: could not set the device clock: %s", exc) return - if done.drift_s is None: + if not done.written: + log.info( + "clock sync: device clock already in sync (%+d s, ahead of ours; firmware " + "never sets it back)", + done.drift_s, + ) + elif done.drift_s is None: log.info("clock sync: device clock set to %s (drift unknown)", done.stamp) else: log.info("clock sync: device clock set to %s (was %+d s off)", done.stamp, done.drift_s) diff --git a/meshterm/tools/config.py b/meshterm/tools/config.py index 987a1d2..33aedec 100644 --- a/meshterm/tools/config.py +++ b/meshterm/tools/config.py @@ -280,12 +280,18 @@ async def apply_ops( # The same step the on-connect service runs in the background # (:mod:`meshterm.services.clock_sync`); here it is acknowledged and reported. done = await set_clock(device) - ctx.ui.ack(f"[ok]✓[/ok] device clock set to [brand]{done.stamp}[/brand]") - changes += 1 + if done.written: + ctx.ui.ack(f"[ok]✓[/ok] device clock set to [brand]{done.stamp}[/brand]") + else: + ctx.ui.ack( + f"[ok]✓[/ok] device clock already in sync " + f"([muted]{done.drift_s:+d} s, ahead of this computer's[/muted])" + ) + changes += int(done.written) report.append( _acted( "clock", - changes=1, + changes=int(done.written), set_at=done.set_at, # What the clock was off by *before* the set: the fact worth logging, # and the one this command destroys by succeeding. diff --git a/tests/test_clock_sync.py b/tests/test_clock_sync.py index b40fff9..0e22353 100644 --- a/tests/test_clock_sync.py +++ b/tests/test_clock_sync.py @@ -20,6 +20,7 @@ from rich.console import Console from meshterm.context import AppContext from meshterm.core.admin_store import AdminStore from meshterm.core.config import Settings +from meshterm.core.connection import ClockAheadError from meshterm.core.device_store import DeviceStore from meshterm.core.preferences import get_spec from meshterm.persistence.repository import Repository @@ -78,7 +79,7 @@ def test_the_preference_exists_and_is_off_by_default() -> None: async def test_set_clock_writes_the_host_time_and_reports_the_drift(ctx: AppContext) -> None: """The shared step corrects a clock an hour slow and says by how much.""" device = await ctx.device() - await device.set_time(int(time.time()) - 3600) + device._clock_offset = -3600 # noqa: SLF001 - an hour slow; a write could only go forward done = await set_clock(device) @@ -92,7 +93,7 @@ async def test_the_service_does_nothing_while_the_preference_is_off( ) -> None: """Off by default: a connection is noted and the clock is left alone.""" device = await ctx.device() - await device.set_time(int(time.time()) - 3600) + device._clock_offset = -3600 # noqa: SLF001 - an hour slow; a write could only go forward service = ClockSync(ctx) await service.start() @@ -109,7 +110,7 @@ async def test_the_service_sets_the_clock_once_per_connection_and_logs_it( """On: the first settled connection is set in the background; the same one is not set twice.""" ctx.preferences.set("set_clock_on_connect", True) device = await ctx.device() - await device.set_time(int(time.time()) - 3600) + device._clock_offset = -3600 # noqa: SLF001 - an hour slow; a write could only go forward service = ClockSync(ctx) await service.start() # a device is already connected: that counts as the first one @@ -119,7 +120,7 @@ async def test_the_service_sets_the_clock_once_per_connection_and_logs_it( assert len(said) == 1 assert "-36" in said[0] # "(was -3600 s off)", give or take the seconds the test took - await device.set_time(int(time.time()) - 3600) + device._clock_offset = -3600 # noqa: SLF001 - an hour slow; a write could only go forward service.on_connected(device) await _settle() assert abs(await device.get_time() - (int(time.time()) - 3600)) <= 2 # untouched @@ -133,7 +134,7 @@ async def test_a_service_never_started_ignores_connections( """A scripted run never starts the service, so its connections never write the clock.""" ctx.preferences.set("set_clock_on_connect", True) device = await ctx.device() - await device.set_time(int(time.time()) - 3600) + device._clock_offset = -3600 # noqa: SLF001 - an hour slow; a write could only go forward ctx.clock_sync.on_connected(device) # what the connect path does await _settle() @@ -158,3 +159,71 @@ async def test_a_write_that_fails_is_logged_not_raised( await _settle() assert any("could not set the device clock: no clock here" in line for line in log_lines) + + +async def test_a_clock_a_few_seconds_ahead_is_in_sync_and_left_alone(ctx: AppContext) -> None: + """Firmware never sets its clock back; a few seconds ahead needs no setting anyway.""" + device = await ctx.device() + device._clock_offset = 5 # noqa: SLF001 - e.g. a GPS-disciplined radio beside a slow PC + + done = await set_clock(device) + + assert not done.written + assert done.drift_s is not None and 3 <= done.drift_s <= 6 + + +async def test_a_clock_far_ahead_is_stated_not_retried(ctx: AppContext) -> None: + """Minutes ahead: nothing is written, and the error says why and what resets it.""" + device = await ctx.device() + device._clock_offset = 1800 # noqa: SLF001 + + with pytest.raises(ClockAheadError) as caught: + await set_clock(device) + assert caught.value.ahead_s is not None and 1795 <= caught.value.ahead_s <= 1801 + assert "30 min ahead" in str(caught.value) and "rebooting the radio" in str(caught.value) + + +async def test_the_simulator_refuses_to_set_its_clock_back_like_the_firmware() -> None: + """``CMD_SET_DEVICE_TIME`` with an earlier time is refused, never applied.""" + from meshterm.core.connection import MockDevice + + device = MockDevice() + await device.connect() + now = int(time.time()) + await device.set_time(now + 100) + with pytest.raises(ClockAheadError): + await device.set_time(now) + assert await device.get_time() >= now + 99 + + +async def test_the_firmwares_refusal_reads_as_a_clock_ahead_not_malformed() -> None: + """The real device turns ERR_CODE_ILLEGAL_ARG on a set-time into ClockAheadError.""" + from types import SimpleNamespace + + from meshterm.core.connection import MeshCoreDevice + + class _Commands: + async def set_time(self, epoch): # noqa: ANN001, ANN201 + return SimpleNamespace(is_error=lambda: True, payload={"error_code": 6}) + + device = object.__new__(MeshCoreDevice) + device._mc = SimpleNamespace(commands=_Commands()) # noqa: SLF001 + with pytest.raises(ClockAheadError) as caught: + await device.set_time(int(time.time())) + assert "malformed" not in str(caught.value) + + +async def test_the_service_logs_a_clock_ahead_plainly( + ctx: AppContext, log_lines: list[str] +) -> None: + """On connect, a clock far ahead is one clear warning, not a 'malformed' request.""" + ctx.preferences.set("set_clock_on_connect", True) + device = await ctx.device() + device._clock_offset = 7200 # noqa: SLF001 + service = ClockSync(ctx) + await service.start() + service.on_connected(device) + await _settle() + assert any("left the device clock alone" in line and "2 h ahead" in line for line in log_lines) + assert not any("malformed" in line for line in log_lines) + await service.aclose()