feat(meshcore): log DESIRED vs READBACK after channel apply

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())

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")),
         )
 
 

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:

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