fix(gateway_events): warn once per frame shape for unparsed frames (#139)

.github/release-notes/2.0.0b16.md

@@ -27,6 +27,7 @@ See the cover docs for the details and the known limits.
 
 - **Diagnostics**: the gateway profile block reports the OWNd profile's real `model_name`, `display_name`, `event_keepalive_interval` and `keepalive_summary` instead of `Generic` / 90 s for every gateway.
 - **Setup**: when `myhome.yaml` has gateway sections but none under this gateway's MAC, a warning names the entry MAC and the section keys that match no configured gateway (#106).
+- **Logging**: `Data received is not a message` is logged once per frame shape (up to 64 shapes per gateway) at WARNING and at DEBUG afterwards, so an unparsed frame a thermostat repeats every few seconds no longer floods the log (#139).
 - **Expose Home Assistant to the bus**: a declarative `expose` engine projects HA entities and the clock onto free SCS addresses: virtual WHO 1 / WHO 2 actuators that a wall control can drive (mirroring HA state back to its LEDs), WHO 4 virtual temperature probes, WHO 18 virtual energy meters and the WHO 13 bus clock. Custom actions run as Home Assistant scripts (#750).
 - **Covers**: Venetian blind slat tilt as timed slat pulses (`slat_tilt`, `slat_time`) (#508); impulse garage and gate covers on WHO 1 relays with optional safety approval, door-entry strike locks and doorbell events (#667); native broadcast for general covers behind an interface (#679); a cover stop overtakes other queued frames (#694); cover kinematics split into pluggable strategies (#739).
 - **Lighting**: 2-digit Area 0 point addresses `01`–`09` (#713); ON dimmers on a fresh install are probed for brightness support (#742); timed turn-on uses the OWNd builders (#659); lights the startup sweep already reported are not polled again (#701); area and group re-syncs only skip once every member has echoed, counting only the members' own echoes in the commanded state (#740, #749).

custom_components/myhome/gateway_events.py

@@ -5,6 +5,7 @@
 """
 from __future__ import annotations
 
+import re
 from typing import TYPE_CHECKING, Any, cast
 
 from homeassistant.core import HomeAssistant
@@ -49,6 +50,14 @@
 
 # WHO 8 call kinds of the entrance panels PE1..PE4 (6: handset to handset, 14: pager).
 ENTRANCE_PANEL_KINDS = frozenset({1, 2, 3, 4})
+# Frames OWNd cannot parse warn once per shape (digits collapsed), then log at DEBUG (#139).
+_DIGITS = re.compile(r"\d+")
+UNPARSED_SHAPES_MAX = 64
+
+
+def frame_shape(raw: object) -> str:
+    """``*#4*#1*14*#0230*1##`` -> ``*#N*#N*N*#N*N##``: frames that differ only in values."""
+    return _DIGITS.sub("N", str(raw))
 
 
 class GatewayEventDispatcher:
@@ -64,6 +73,7 @@ def __init__(
         self._cen_devices: set[tuple[int, Any]] = (
             cen_devices if cen_devices is not None else set()
         )
+        self._unparsed_shapes: set[str] = set()
 
     @property
     def _logger(self) -> Any:
@@ -272,10 +282,15 @@ async def process_message(self, message: Any) -> None:
                 self._observe_health(message, who_int)
 
         if not isinstance(message, OWNMessage):
-            self._logger.warning(
-                "%s Data received is not a message: `%s`",
+            shape = frame_shape(message)
+            first = shape not in self._unparsed_shapes and len(self._unparsed_shapes) < UNPARSED_SHAPES_MAX
+            if first:
+                self._unparsed_shapes.add(shape)
+            (self._logger.warning if first else self._logger.debug)(
+                "%s Data received is not a message: `%s`%s",
                 self.handler.log_id,
                 message,
+                " (further frames of this shape are logged at DEBUG)" if first else "",
             )
         elif (
             isinstance(message, OWNLightingEvent)

tests/test_unparsed_frame_logging.py

@@ -0,0 +1,75 @@
+"""Frames OWNd cannot parse are logged once per shape at WARNING, then at DEBUG (#139)."""
+import logging
+from unittest.mock import MagicMock
+
+import pytest
+
+from custom_components.myhome.gateway import MyHOMEGatewayHandler
+
+
+@pytest.fixture
+def gateway_handler():
+    entry = MagicMock()
+    entry.entry_id = "entry_unparsed"
+    entry.data = {
+        "host": "192.0.2.5",
+        "port": 20000,
+        "password": "12345",
+        "mac": "00:03:50:00:00:01",
+        "name": "F461",
+        "manufacturer": "BTicino",
+        "firmware": "2.0.11",
+    }
+    entry.options = {}
+    entry.title = "F461 Gateway"
+    hass = MagicMock()
+    hass.data = {}
+    return MyHOMEGatewayHandler(hass, entry)
+
+
+def _not_a_message(caplog, level):
+    return [
+        r.getMessage()
+        for r in caplog.records
+        if r.levelno == level and "Data received is not a message" in r.getMessage()
+    ]
+
+
+async def test_unparsed_frame_warns_once_per_shape(gateway_handler, caplog):
+    """A zone thermostat pushing `*#4*#1*14*#0230*1##` every few seconds yields one WARNING, not a flood."""
+    with caplog.at_level(logging.DEBUG, logger="custom_components.myhome"):
+        for frame in ("*#4*#1*14*#0230*1##", "*#4*#1*14*#0231*1##", "*#4*#2*14*#0205*1##"):
+            await gateway_handler._process_message(frame)
+        # The live F461 2.0.11 answer to `*#13**27##` (model name as ASCII codes), a str in OWNd 2.0.0b11
+        await gateway_handler._process_message("*#13**27*70#52#54#49##")
+
+    warnings = _not_a_message(caplog, logging.WARNING)
+    assert len(warnings) == 2, warnings
+    assert "*#4*#1*14*#0230*1##" in warnings[0]
+    assert "*#13**27*70#52#54#49##" in warnings[1]
+    # The repeats are still visible at DEBUG for troubleshooting
+    assert len(_not_a_message(caplog, logging.DEBUG)) == 2
+
+
+def test_frame_shape_keeps_the_whole_frame():
+    """The dedup key is the full shape, not a prefix: two long frames differing past 120 characters stay apart."""
+    from custom_components.myhome.gateway_events import frame_shape
+
+    head = "*#13**27*" + "#".join(["70"] * 60)
+    assert frame_shape(head + "*1##") != frame_shape(head + "*#1##")
+    assert frame_shape("*#4*#1*14*#0230*1##") == "*#N*#N*N*#N*N##"
+
+
+async def test_unparsed_shapes_are_capped(gateway_handler, caplog, monkeypatch):
+    """Beyond UNPARSED_SHAPES_MAX distinct shapes everything is DEBUG: the set cannot grow without bound."""
+    from custom_components.myhome import gateway_events
+
+    monkeypatch.setattr(gateway_events, "UNPARSED_SHAPES_MAX", 2)
+    with caplog.at_level(logging.DEBUG, logger="custom_components.myhome"):
+        for frame in ("*#4*#1*14*#0230*1##", "*#13**27*70#52#54#49##", "*#4*#1*14*#0230*1*2##"):
+            await gateway_handler._process_message(frame)
+
+    warnings = _not_a_message(caplog, logging.WARNING)
+    assert len(warnings) == 2, warnings
+    assert "*#4*#1*14*#0230*1*2##" in _not_a_message(caplog, logging.DEBUG)[0]
+    assert len(gateway_handler._event_dispatcher._unparsed_shapes) == 2