From aef883cc752e32ad8bdd63ab043a2a3174042d74 Mon Sep 17 00:00:00 2001 From: Patrick Skillen Date: Thu, 4 Jun 2026 10:16:47 +0100 Subject: [PATCH] feat(meshcore): log DESIRED vs READBACK after channel apply After apply_mc_channel_config, read the device without scope_hints and warn on name/type mismatches so operators do not treat scope_hints merge as firmware truth. Closes #129. --- src/meshcore/channel_sync.py | 11 +-- src/meshcore/channels.py | 99 ++++++++++++++++++- test/meshcore/test_channel_sync.py | 22 +++-- test/meshcore/test_channels.py | 151 +++++++++++++++++++++++++++-- 4 files changed, 256 insertions(+), 27 deletions(-) diff --git a/src/meshcore/channel_sync.py b/src/meshcore/channel_sync.py index 93813e2..d8bc226 100644 --- a/src/meshcore/channel_sync.py +++ b/src/meshcore/channel_sync.py @@ -8,11 +8,8 @@ CHANNEL_READ_DELAY_S = 2.0 -from src.meshcore.channels import ( - log_device_channels, - read_device_channels, - snapshot_sync_body, -) +from src.meshcore.channels import (log_device_channels, read_device_channels, + snapshot_sync_body) if TYPE_CHECKING: from src.api.StorageAPI import StorageAPIWrapper @@ -116,13 +113,15 @@ def sync_channels_to_api( def apply_channels_on_device(radio: "MeshCoreRadio", channels: list[dict]) -> bool: """Apply WS command payload to device, then caller should re-sync API.""" - from src.meshcore.channels import apply_device_channels + from src.meshcore.channels import (apply_device_channels, + verify_apply_channels) async def _apply(): mc = radio._meshcore # noqa: SLF001 if mc is None: raise RuntimeError("MeshCore not connected") await apply_device_channels(mc, channels) + await verify_apply_channels(mc, channels) try: radio.run_coroutine(_apply()) diff --git a/src/meshcore/channels.py b/src/meshcore/channels.py index 058cccf..b6c5ccb 100644 --- a/src/meshcore/channels.py +++ b/src/meshcore/channels.py @@ -2,6 +2,7 @@ from __future__ import annotations +import asyncio import logging from datetime import datetime, timezone from typing import Any, Optional @@ -12,6 +13,7 @@ logger = logging.getLogger(__name__) DEFAULT_MAX_CHANNEL_SCAN = 16 +APPLY_READBACK_DELAY_S = 2.0 def _normalize_region_scope(value: Any) -> str | None: @@ -174,6 +176,99 @@ async def apply_device_channels(meshcore: MeshCore, channels: list[dict]) -> Non ) +def _format_region_scope(scope: str | None) -> str: + return scope if scope else "(none)" + + +def _channels_by_idx(channels: list[dict]) -> dict[int, dict]: + by_idx: dict[int, dict] = {} + for row in channels: + if row.get("mc_channel_idx") is None: + continue + by_idx[int(row["mc_channel_idx"])] = row + return by_idx + + +def _normalize_compare_name(entry: dict) -> str: + name = str(entry.get("name") or "").strip() + if str(entry.get("mc_channel_type", "PUBLIC")).upper() == "HASHTAG": + name = name.lstrip("#") + return name + + +def log_labeled_channel_config(label: str, channels: list[dict]) -> None: + """Log apply DESIRED or READBACK channel rows (operator-visible in feeder logs).""" + tag = label.upper() + if not channels: + logger.info("MeshCore apply %s: (no channels)", tag) + return + logger.info("MeshCore apply %s (%s channel(s)):", tag, len(channels)) + for ch in sorted(channels, key=lambda c: int(c["mc_channel_idx"])): + idx = ch["mc_channel_idx"] + typ = ch.get("mc_channel_type", "?") + name = ch.get("name", "") + logger.info( + " [%s] %s name=%r region_scope=%s", + idx, + typ, + name, + _format_region_scope(ch.get("region_scope")), + ) + + +def warn_apply_readback_mismatches(desired: list[dict], readback: list[dict]) -> None: + """ + Compare apply payload to device readback (no scope_hints). + + region_scope mismatches are warned only when readback includes scope from + CHANNEL_INFO; firmware often omits scope until per-slot scope is exposed. + """ + read_by_idx = _channels_by_idx(readback) + for want in sorted(desired, key=lambda c: int(c["mc_channel_idx"])): + idx = int(want["mc_channel_idx"]) + got = read_by_idx.get(idx) + if got is None: + logger.warning( + "MeshCore apply READBACK mismatch slot [%s]: desired present, no readback row", + idx, + ) + continue + if _normalize_compare_name(want) != _normalize_compare_name(got): + logger.warning( + "MeshCore apply READBACK mismatch slot [%s]: desired name=%r readback name=%r", + idx, + want.get("name"), + got.get("name"), + ) + want_type = str(want.get("mc_channel_type", "PUBLIC")).upper() + got_type = str(got.get("mc_channel_type", "PUBLIC")).upper() + if want_type != got_type: + logger.warning( + "MeshCore apply READBACK mismatch slot [%s]: desired type=%s readback type=%s", + idx, + want_type, + got_type, + ) + want_scope = _normalize_region_scope(want.get("region_scope")) + got_scope = got.get("region_scope") + if got_scope is not None and want_scope != got_scope: + logger.warning( + "MeshCore apply READBACK mismatch slot [%s]: desired region_scope=%s readback region_scope=%s", + idx, + _format_region_scope(want_scope), + _format_region_scope(got_scope), + ) + + +async def verify_apply_channels(meshcore: MeshCore, desired: list[dict]) -> None: + """Log desired apply payload, read device without scope_hints, warn on mismatch.""" + log_labeled_channel_config("DESIRED", desired) + await asyncio.sleep(APPLY_READBACK_DELAY_S) + readback = await read_device_channels(meshcore, scope_hints=None) + log_labeled_channel_config("READBACK", readback) + warn_apply_readback_mismatches(desired, readback) + + def log_device_channels(channels: list[dict]) -> None: """Log the device channel table at INFO (visible in docker logs on connect).""" if not channels: @@ -184,14 +279,12 @@ def log_device_channels(channels: list[dict]) -> None: idx = ch["mc_channel_idx"] typ = ch.get("mc_channel_type", "?") name = ch.get("name", "") - scope = ch.get("region_scope") - scope_label = scope if scope else "(none)" logger.info( " [%s] %s name=%r region_scope=%s", idx, typ, name, - scope_label, + _format_region_scope(ch.get("region_scope")), ) diff --git a/test/meshcore/test_channel_sync.py b/test/meshcore/test_channel_sync.py index 0192170..3f87d6c 100644 --- a/test/meshcore/test_channel_sync.py +++ b/test/meshcore/test_channel_sync.py @@ -5,12 +5,10 @@ import asyncio from unittest.mock import AsyncMock, MagicMock, patch -from src.meshcore.channel_sync import ( - apply_channels_on_device, - sync_channels_to_api, - sync_channels_to_api_async, - sync_channels_to_storage_apis_async, -) +from src.meshcore.channel_sync import (apply_channels_on_device, + sync_channels_to_api, + sync_channels_to_api_async, + sync_channels_to_storage_apis_async) class _MeshCoreRadioStub: @@ -147,11 +145,17 @@ def test_apply_channels_success() -> None: "mc_hashtag": "galloway", } ] - with patch( - "src.meshcore.channels.apply_device_channels", new_callable=AsyncMock - ) as apply_mock: + with ( + patch( + "src.meshcore.channels.apply_device_channels", new_callable=AsyncMock + ) as apply_mock, + patch( + "src.meshcore.channels.verify_apply_channels", new_callable=AsyncMock + ) as verify_mock, + ): assert apply_channels_on_device(radio, channels) is True apply_mock.assert_awaited_once() + verify_mock.assert_awaited_once() def test_apply_channels_fails_when_not_connected() -> None: diff --git a/test/meshcore/test_channels.py b/test/meshcore/test_channels.py index 16f0119..e2198a4 100644 --- a/test/meshcore/test_channels.py +++ b/test/meshcore/test_channels.py @@ -3,17 +3,16 @@ from __future__ import annotations import asyncio -from unittest.mock import AsyncMock, MagicMock +from unittest.mock import AsyncMock, MagicMock, patch from meshcore.events import Event, EventType -from src.meshcore.channels import ( - _channel_entry_from_info, - apply_device_channels, - log_device_channels, - merge_channel_region_scopes, - read_device_channels, - snapshot_sync_body, -) +from src.meshcore.channels import (_channel_entry_from_info, + apply_device_channels, log_device_channels, + log_labeled_channel_config, + merge_channel_region_scopes, + read_device_channels, snapshot_sync_body, + verify_apply_channels, + warn_apply_readback_mismatches) def test_channel_entry_public(): @@ -182,3 +181,137 @@ def test_apply_device_channels_sets_flood_scope() -> None: ) ) mc.commands.set_flood_scope.assert_awaited_once_with("sample-west") + + +def test_log_labeled_channel_config_desired(caplog) -> None: + import logging + + caplog.set_level(logging.INFO) + log_labeled_channel_config( + "DESIRED", + [ + { + "mc_channel_idx": 0, + "name": "Public", + "mc_channel_type": "PUBLIC", + "region_scope": "sco", + }, + ], + ) + assert "MeshCore apply DESIRED" in caplog.text + assert "region_scope=sco" in caplog.text + + +def test_warn_apply_readback_mismatch_name(caplog) -> None: + import logging + + caplog.set_level(logging.WARNING) + desired = [ + { + "mc_channel_idx": 1, + "name": "glasgow", + "mc_channel_type": "HASHTAG", + "region_scope": "gla", + }, + ] + readback = [ + { + "mc_channel_idx": 1, + "name": "wrong", + "mc_channel_type": "HASHTAG", + "region_scope": None, + }, + ] + warn_apply_readback_mismatches(desired, readback) + assert "READBACK mismatch slot [1]" in caplog.text + assert "desired name='glasgow'" in caplog.text + + +def test_warn_apply_readback_no_scope_warning_when_readback_omits_scope( + caplog, +) -> None: + import logging + + caplog.set_level(logging.WARNING) + desired = [ + { + "mc_channel_idx": 0, + "name": "Public", + "mc_channel_type": "PUBLIC", + "region_scope": "sco", + }, + ] + readback = [ + { + "mc_channel_idx": 0, + "name": "Public", + "mc_channel_type": "PUBLIC", + "region_scope": None, + }, + ] + warn_apply_readback_mismatches(desired, readback) + assert "READBACK mismatch" not in caplog.text + + +def test_warn_apply_readback_scope_when_readback_has_scope(caplog) -> None: + import logging + + caplog.set_level(logging.WARNING) + desired = [ + { + "mc_channel_idx": 0, + "name": "test", + "mc_channel_type": "HASHTAG", + "region_scope": "gla", + }, + ] + readback = [ + { + "mc_channel_idx": 0, + "name": "test", + "mc_channel_type": "HASHTAG", + "region_scope": "sco", + }, + ] + warn_apply_readback_mismatches(desired, readback) + assert "region_scope=gla" in caplog.text + assert "region_scope=sco" in caplog.text + + +def test_verify_apply_channels_logs_desired_and_readback(caplog) -> None: + import logging + + caplog.set_level(logging.INFO) + mc = MagicMock() + desired = [ + { + "mc_channel_idx": 0, + "name": "Public", + "mc_channel_type": "PUBLIC", + "region_scope": "sco", + }, + ] + readback = [ + { + "mc_channel_idx": 0, + "name": "Public", + "mc_channel_type": "PUBLIC", + "region_scope": None, + }, + ] + + async def _run(): + with ( + patch("src.meshcore.channels.asyncio.sleep", new_callable=AsyncMock), + patch( + "src.meshcore.channels.read_device_channels", + new_callable=AsyncMock, + return_value=readback, + ) as read_mock, + ): + await verify_apply_channels(mc, desired) + read_mock.assert_awaited_once_with(mc, scope_hints=None) + + asyncio.run(_run()) + assert "MeshCore apply DESIRED" in caplog.text + assert "MeshCore apply READBACK" in caplog.text