diff --git a/.github/release-notes/2.0.0b16.md b/.github/release-notes/2.0.0b16.md index a871f4e9..e01a2308 100644 --- a/.github/release-notes/2.0.0b16.md +++ b/.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). diff --git a/custom_components/myhome/gateway_events.py b/custom_components/myhome/gateway_events.py index 10916c05..91aee848 100644 --- a/custom_components/myhome/gateway_events.py +++ b/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) diff --git a/tests/test_unparsed_frame_logging.py b/tests/test_unparsed_frame_logging.py new file mode 100644 index 00000000..832eeaae --- /dev/null +++ b/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