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) <noreply@anthropic.com>
This commit is contained in:
1 parent
bd0c311dbc
commit
79137598cf
5 files changed
+191
-13
No files matched your search
@@ -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
|
||||
|
||||
@@ -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())
|
||||
|
||||
@@ -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)
|
||||
@@ -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.
|
||||
|
||||
@@ -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()
|
||||
Reference in new issue
Block a user