Skip to content

Commit f87b6c9

Browse files
Beennnnedenhaus
andauthored
fix(message): rate-limit "Could not parse" warnings per NAME (#1566)
* fix(message): rate-limit "Could not parse" warnings per NAME When a firmware version pushes messages whose on-wire format the lib does not yet support, every push triggers a `Could not parse <NAME>` WARNING via `_handle_error_or_analyse`. In one observed case a mower's spontaneous `getMapTrace` pushes produced 217 520 identical entries in 3 days (~70k/day, ~50/min during mowing), bloating the parent process' log file and any downstream sink (HA recorder DB, Loki, etc.). The first few warnings are useful — they let an operator notice that something is wrong. Beyond that, identical repeats add no information and only make the rest of the log harder to read. This adds a per-NAME counter and a threshold (default 3): the first 3 parse failures for a given message NAME are still logged at WARNING, followed by a single notice that further entries will be downgraded to DEBUG. After that, all subsequent parse failures for that NAME log at DEBUG. Counters are isolated per NAME, so a NEW message class hitting a parse error still surfaces normally. The 3 existing emission sites (`_handle_error_or_analyse` exception path, `_handle_error_or_analyse` ERROR-state path, `MessageBodyData` exception path) all route through the new helper. Behaviour for non-throttled flows (success, ANALYSE) is unchanged. Tests: - `test_warn_once_throttles_repeated_parse_failures` — calls `Message.handle()` `THRESHOLD + 2` times on a class whose `_handle` always raises, asserts THRESHOLD + 1 WARNINGs (incl. the "switching to DEBUG" notice) followed by 2 DEBUGs. - `test_warn_once_isolated_per_message_name` — burns through the threshold for one NAME, verifies a sibling NAME still WARNs on its first parse failure. - Full suite: 699/699 pass. Refs: #1376 * review: drop verbose comments, full counter reset via fixture, exact log assertions Address review feedback on #1566: - Remove the file-level explanatory comment block above the threshold - Drop the "Restart Home Assistant" line — the lib does not know its host - Replace per-NAME counter cleanup with a pytest fixture that wipes the whole dict before and after each test - Compare ``caplog.records`` against the full expected level/message list in order (the previous count-only assertion would have passed with WARNING/DEBUG entries interleaved out of order) * Refactor tests --------- Co-authored-by: Robert Resch <robert@resch.dev>
1 parent e91edcc commit f87b6c9

2 files changed

Lines changed: 145 additions & 3 deletions

File tree

deebot_client/message.py

Lines changed: 20 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,23 @@
2525

2626
MessagePayloadType = str | bytes | bytearray | dict[str, Any]
2727

28+
_PARSE_FAILURE_THRESHOLD = 3
29+
_parse_failure_counts: dict[str, int] = {}
30+
31+
32+
def _log_parse_failure(name: str, data: object, *, exc_info: bool = False) -> None:
33+
count = _parse_failure_counts.get(name, 0) + 1
34+
_parse_failure_counts[name] = count
35+
if count <= _PARSE_FAILURE_THRESHOLD:
36+
_LOGGER.warning("Could not parse %s: %s", name, data, exc_info=exc_info)
37+
if count == _PARSE_FAILURE_THRESHOLD:
38+
_LOGGER.warning(
39+
"Further 'Could not parse %s' entries will be logged at DEBUG level",
40+
name,
41+
)
42+
else:
43+
_LOGGER.debug("Could not parse %s: %s", name, data, exc_info=exc_info)
44+
2845

2946
class HandlingState(IntEnum):
3047
"""Handling state enum."""
@@ -65,7 +82,7 @@ def wrapper(cls: type[M], event_bus: EventBus, data: T) -> HandlingResult:
6582
try:
6683
response = func(cls, event_bus, data)
6784
except Exception:
68-
_LOGGER.warning("Could not parse %s: %s", cls.NAME, data, exc_info=True)
85+
_log_parse_failure(cls.NAME, data, exc_info=True)
6986
return HandlingResult(HandlingState.ERROR)
7087
else:
7188
# This happens if for some reason someone calls super() of an ABC where handle is not implemented
@@ -81,7 +98,7 @@ def wrapper(cls: type[M], event_bus: EventBus, data: T) -> HandlingResult:
8198
_LOGGER.debug("Could not handle %s message: %s", cls.NAME, data)
8299
return HandlingResult(HandlingState.ANALYSE_LOGGED, response.args)
83100
if response.state == HandlingState.ERROR:
84-
_LOGGER.warning("Could not parse %s: %s", cls.NAME, data)
101+
_log_parse_failure(cls.NAME, data)
85102
return response
86103

87104
return wrapper
@@ -256,7 +273,7 @@ def __handle_body_data(
256273
try:
257274
response = cls._handle_body_data(event_bus, data)
258275
except Exception:
259-
_LOGGER.warning("Could not parse %s: %s", cls.NAME, data, exc_info=True)
276+
_log_parse_failure(cls.NAME, data, exc_info=True)
260277
return HandlingResult(HandlingState.ERROR)
261278
else:
262279
if response.state == HandlingState.ANALYSE:

tests/test_message.py

Lines changed: 125 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,14 @@
11
from __future__ import annotations
22

3+
import logging
34
from unittest.mock import Mock
45

56
import pytest
67

8+
from deebot_client import message as message_module
79
from deebot_client.event_bus import EventBus
810
from deebot_client.message import (
11+
_PARSE_FAILURE_THRESHOLD,
912
HandlingResult,
1013
HandlingState,
1114
Message,
@@ -67,3 +70,125 @@ def test_WronglyImplementedMessage() -> None:
6770
result = WronglyImplementedMessage.handle(event_bus, {})
6871

6972
assert result.state == HandlingState.ERROR
73+
74+
75+
@pytest.fixture
76+
def _reset_parse_failure_counts() -> None:
77+
message_module._parse_failure_counts.clear()
78+
79+
80+
class _AlwaysRaisingMessage(Message):
81+
NAME = "AlwaysRaisingMessage_warnonce_test"
82+
83+
@classmethod
84+
def _handle(
85+
cls, _event_bus: EventBus, _message: MessagePayloadType
86+
) -> HandlingResult:
87+
raise ValueError("simulated parse failure")
88+
89+
90+
class _OtherFailingMessage(Message):
91+
NAME = "OtherFailingMessage_warnonce_test"
92+
93+
@classmethod
94+
def _handle(
95+
cls, _event_bus: EventBus, _message: MessagePayloadType
96+
) -> HandlingResult:
97+
raise ValueError("simulated parse failure")
98+
99+
100+
@pytest.mark.usefixtures("_reset_parse_failure_counts")
101+
def test_warn_once_throttles_repeated_parse_failures(
102+
caplog: pytest.LogCaptureFixture,
103+
) -> None:
104+
name = _AlwaysRaisingMessage.NAME
105+
event_bus = Mock(spec_set=EventBus)
106+
logger_name = "deebot_client.message"
107+
108+
with caplog.at_level(logging.DEBUG, logger=logger_name):
109+
for i in range(_PARSE_FAILURE_THRESHOLD + 2):
110+
assert (
111+
_AlwaysRaisingMessage.handle(event_bus, {"i": i}).state
112+
== HandlingState.ERROR
113+
)
114+
115+
assert [
116+
(
117+
logger_name,
118+
logging.WARNING,
119+
f"Could not parse {name}: {{'i': 0}}",
120+
),
121+
(
122+
logger_name,
123+
logging.WARNING,
124+
f"Could not parse {name}: {{'i': 1}}",
125+
),
126+
(
127+
logger_name,
128+
logging.WARNING,
129+
f"Could not parse {name}: {{'i': 2}}",
130+
),
131+
(
132+
logger_name,
133+
logging.WARNING,
134+
f"Further 'Could not parse {name}' entries will be logged at DEBUG level",
135+
),
136+
(
137+
logger_name,
138+
logging.DEBUG,
139+
f"Could not parse {name}: {{'i': 3}}",
140+
),
141+
(
142+
logger_name,
143+
logging.DEBUG,
144+
f"Could not parse {name}: {{'i': 4}}",
145+
),
146+
] == caplog.record_tuples
147+
148+
149+
@pytest.mark.usefixtures("_reset_parse_failure_counts")
150+
def test_warn_once_isolated_per_message_name(
151+
caplog: pytest.LogCaptureFixture,
152+
) -> None:
153+
name_a = _AlwaysRaisingMessage.NAME
154+
name_b = _OtherFailingMessage.NAME
155+
event_bus = Mock(spec_set=EventBus)
156+
logger_name = "deebot_client.message"
157+
158+
with caplog.at_level(logging.DEBUG, logger=logger_name):
159+
for i in range(_PARSE_FAILURE_THRESHOLD + 1):
160+
_AlwaysRaisingMessage.handle(event_bus, {"a": i})
161+
_OtherFailingMessage.handle(event_bus, {"b": "first"})
162+
163+
assert [
164+
(
165+
logger_name,
166+
logging.WARNING,
167+
f"Could not parse {name_a}: {{'a': 0}}",
168+
),
169+
(
170+
logger_name,
171+
logging.WARNING,
172+
f"Could not parse {name_a}: {{'a': 1}}",
173+
),
174+
(
175+
logger_name,
176+
logging.WARNING,
177+
f"Could not parse {name_a}: {{'a': 2}}",
178+
),
179+
(
180+
logger_name,
181+
logging.WARNING,
182+
f"Further 'Could not parse {name_a}' entries will be logged at DEBUG level",
183+
),
184+
(
185+
logger_name,
186+
logging.DEBUG,
187+
f"Could not parse {name_a}: {{'a': 3}}",
188+
),
189+
(
190+
logger_name,
191+
logging.WARNING,
192+
f"Could not parse {name_b}: {{'b': 'first'}}",
193+
),
194+
] == caplog.record_tuples

0 commit comments

Comments
 (0)