From 3c4633199cb89d783fa9e8b6ea51ca614a782a3b Mon Sep 17 00:00:00 2001 From: Simon Clark Date: Tue, 25 Aug 2026 23:41:04 +0100 Subject: [PATCH] fix: honour the contract that justifies a silent swallow, and log state removal on change (#308, #312) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit **#308 — the silence was fine; the contract behind it was not implemented.** I filed #308 saying `SurveyLog._persist`'s silent swallow was the wrong shape. Reading the code properly says otherwise: the silence is deliberate and its comment gives the reason — "the caller supplies the save hook and logs there if it wants to", and a failed save costs one repeated INFO rather than an exception escaping `create_devices`. `NodeDeviceTombstones._persist` warns instead because ITS failure resurrects a deliberately-deleted device, which is not cosmetic. The asymmetry is reasoned and stands. The actual defect: `DiagnosticsMenuMixin._save_survey_log` — the hook that comment points at — had no try/except and no logging, so a raising `savePluginPrefs()` reached `_persist`, was swallowed, and nobody logged anything. The comment described a contract nothing honoured. The hook now catches and warns, naming the failure and its consequence. `_persist` stays silent and its comment now states a fact. **#312 — log on change, not on evaluation.** `getDeviceStateList`'s state-removal INFO reprinted on every rebuild with the same answer: ~3 lines per plugin start, every start, measured across a week of jarvis logs. The filtering is correct — Indigo calls it on each rebuild, so re-applying it every time is right. Only the cadence was wrong. The comment justifying INFO ("a state disappearing silently breaks any trigger bound to it") holds the first time a device loses a set of states, not the fortieth reprint of an unchanged answer. `device_settings.RemovedStateLog` records device id → fingerprint of the removed set, so a device that later loses a DIFFERENT state still logs. It persists, because an in-memory latch would have suppressed almost nothing: the jarvis data shows the repeats are per-restart, not within-session. `deviceDeleted` forgets the entry for every device type, so a deleted device cannot leak one forever. `getDeviceStateList` fails open to logging every time if the store is somehow unwired. 3882 passing on 3.11 and 3.13 (3873 + 9 new). pylint 9.48, unchanged. No existing test was changed or deleted — the two touched test files are additions only. Closes #308 Closes #312 Co-Authored-By: Claude Opus 5 (1M context) --- .../Contents/Info.plist | 2 +- .../Contents/Server Plugin/device_settings.py | 102 +++++++++++++++- .../Server Plugin/diagnostics_menu_mixin.py | 16 ++- .../Contents/Server Plugin/plugin.py | 95 +++++++++++---- .../Server Plugin/plugin_constants.py | 7 ++ .../Contents/Server Plugin/settings_report.py | 7 +- tests/test_diagnostics_menu.py | 28 +++++ tests/test_plugin_module.py | 109 ++++++++++++++++++ 8 files changed, 339 insertions(+), 27 deletions(-) diff --git a/indigo-matter.indigoPlugin/Contents/Info.plist b/indigo-matter.indigoPlugin/Contents/Info.plist index 26abdc9..863f12f 100644 --- a/indigo-matter.indigoPlugin/Contents/Info.plist +++ b/indigo-matter.indigoPlugin/Contents/Info.plist @@ -20,7 +20,7 @@ IwsApiVersion 1.0.0 PluginVersion - 2026.28.8 + 2026.28.9 ServerApiVersion 3.6 diff --git a/indigo-matter.indigoPlugin/Contents/Server Plugin/device_settings.py b/indigo-matter.indigoPlugin/Contents/Server Plugin/device_settings.py index 2308086..e50d33e 100644 --- a/indigo-matter.indigoPlugin/Contents/Server Plugin/device_settings.py +++ b/indigo-matter.indigoPlugin/Contents/Server Plugin/device_settings.py @@ -25,8 +25,10 @@ from __future__ import annotations import asyncio +import json +import threading from dataclasses import dataclass -from typing import Any, Callable, Optional +from typing import Any, Callable, Iterable, Optional from matter_client import ATTRIBUTE_TIMEOUT from matter_handlers.settings import ( @@ -45,6 +47,7 @@ "OfferedSetting", "PlannedWrite", "MARKER_YES", "MARKER_NO", "offered_settings", "unimplemented_states", "config_ui_values", "validate_settings", "planned_writes", "apply_setting", + "RemovedStateLog", ] #: Marker values for the ``hasX`` hidden ConfigUI fields that drive @@ -405,3 +408,100 @@ async def apply_setting(client: Any, node_id: int, endpoint: int, # really happened, that is self-defeating. reason = f"{reason} (read-back failed: {read_error})" return False, reason + + +class RemovedStateLog: + """Which device's state-removal ANSWER was last reported (issue #312). + + ``getDeviceStateList`` (``plugin.py``) filters a device's declared states + down to what its AttributeList says it implements, and it is right to do + that on EVERY rebuild — Indigo calls it as a filter each time, and the + cache the answer is drawn from can have changed. Only the LOGGING should + happen once per distinct answer, not once per evaluation: the first time a + device's removed-set is seen, and again only if that set later changes. + + Same pluginPrefs-blob shape as ``settings_report.SurveyLog`` and + ``device_sync.NodeDeviceTombstones`` (deliberately not unified with them — + assessed and rejected in the 2026-08-25 refactor; see those two classes' + docstrings). Keyed on the Indigo device id rather than a node/endpoint + pair: ``getDeviceStateList`` is handed the Indigo device, and a device + whose backing node/endpoint is reassigned is a new question anyway. + + **Keyed on the ANSWER, not just the device.** The stored value is a + fingerprint of the removed-set (:meth:`fingerprint`), not a boolean + "already logged" flag — so a device that later loses a DIFFERENT state + still logs, exactly as a device losing its first state does. + + A blob that will not parse starts empty rather than raising — the cost of + being wrong is one duplicate INFO line on the next rebuild, not a device + that fails to build its state list. + """ + + def __init__(self, save: Optional[Callable[[str], None]] = None) -> None: + self._last: dict[str, str] = {} + self._save = save + self._lock = threading.RLock() + + def load(self, blob: Any) -> None: + """Replace the log from a stored JSON string (or anything unusable).""" + parsed: dict[str, str] = {} + if isinstance(blob, str) and blob.strip(): + try: + raw = json.loads(blob) + if isinstance(raw, dict): + parsed = {str(k): str(v) for k, v in raw.items()} + except (TypeError, ValueError): + parsed = {} + with self._lock: + self._last = parsed + + def to_json(self) -> str: + with self._lock: + return json.dumps(self._last, separators=(",", ":"), sort_keys=True) + + @staticmethod + def fingerprint(removed: Iterable[str]) -> str: + """A stable, order-independent answer for a removed-key set.""" + return ",".join(sorted(set(removed))) + + def should_log(self, dev_id: Any, fingerprint: str) -> bool: + """Has this device's removed-set changed since it was last logged? + + True the first time a device is asked about (nothing recorded yet), + matching the issue #312 requirement that the first occurrence always + logs. + """ + with self._lock: + return self._last.get(str(int(dev_id))) != fingerprint + + def record(self, dev_id: Any, fingerprint: str) -> None: + """Remember that this answer has been logged, and persist.""" + with self._lock: + self._last[str(int(dev_id))] = fingerprint + self._persist() + + def forget(self, dev_id: Any) -> None: + """Drop a deleted device, so it cannot leak an entry forever. + + Indigo device ids are not reused the way Matter node ids are, but + without this every deleted device's entry would sit in ``pluginPrefs`` + forever — unbounded growth for bookkeeping about a device that no + longer exists. Wired to ``plugin.deviceDeleted``. + """ + with self._lock: + existed = self._last.pop(str(int(dev_id)), None) is not None + if existed: + self._persist() + + def _persist(self) -> None: + if self._save is None: + return + try: + self._save(self.to_json()) + except Exception: # noqa: BLE001 - bookkeeping must never sink a device rebuild + # Deliberately silent here, same reasoning as SurveyLog._persist + # (issue #308): the caller supplies the save hook and logs there. + # A failed save costs one repeated INFO line on the next rebuild, + # which is a strictly better outcome than an exception escaping + # into getDeviceStateList. + pass diff --git a/indigo-matter.indigoPlugin/Contents/Server Plugin/diagnostics_menu_mixin.py b/indigo-matter.indigoPlugin/Contents/Server Plugin/diagnostics_menu_mixin.py index d3187a0..f2180fc 100644 --- a/indigo-matter.indigoPlugin/Contents/Server Plugin/diagnostics_menu_mixin.py +++ b/indigo-matter.indigoPlugin/Contents/Server Plugin/diagnostics_menu_mixin.py @@ -67,9 +67,21 @@ def _save_survey_log(self, blob: str) -> None: mapping: Indigo rebinds it when the PluginConfig dialog is saved, and a held reference would write into an orphan. ``savePluginPrefs`` is the commit — without it the value survives only until the plugin stops. + + Caught and logged rather than left to escape into + ``SurveyLog._persist`` (issue #308): that method is deliberately + silent on the assumption that "the caller supplies the save hook and + logs there if it wants to" — this is that logging. A failure here is + cosmetic (the affected device(s) are simply re-reported on the next + start), which is why WARNING rather than anything louder. """ - self.pluginPrefs[SURVEY_LOG_PREF] = blob - indigo.server.savePluginPrefs() + try: + self.pluginPrefs[SURVEY_LOG_PREF] = blob + indigo.server.savePluginPrefs() + except Exception as exc: # noqa: BLE001 - bookkeeping must never sink a reconcile + self.logger.warning( + "Matter: could not save the settable-attribute survey log (%s) — " + "the affected device(s) will be re-reported on the next start.", exc) # ------------------------------------------------------------------ # Pickers diff --git a/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin.py b/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin.py index b62c367..a232997 100644 --- a/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin.py +++ b/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin.py @@ -64,8 +64,8 @@ from plugin_constants import ( COMMAND_TIMEOUT, MAX_RESUBSCRIBE_ATTEMPTS, NODE_TOMBSTONES_PREF, ON_TIME_RETIRED_PREF, - PLUGIN_NAME, PORT_CONFLICT_CHECK_INTERVAL, RESUBSCRIBE_TICKS, SURVEY_LOG_PREF, - sanitize_host, server_location, + PLUGIN_NAME, PORT_CONFLICT_CHECK_INTERVAL, REMOVED_STATE_LOG_PREF, RESUBSCRIBE_TICKS, + SURVEY_LOG_PREF, sanitize_host, server_location, ) import settings_report @@ -241,6 +241,11 @@ def startup(self) -> None: self.node_tombstones.load(self.pluginPrefs.get(NODE_TOMBSTONES_PREF, "")) self.device_sync.node_tombstones = self.node_tombstones + # getDeviceStateList's "last reported removed-set" per device (issue + # #312) — same prefs discipline as survey_log above. + self.removed_state_log = device_settings.RemovedStateLog(save=self._save_removed_state_log) + self.removed_state_log.load(self.pluginPrefs.get(REMOVED_STATE_LOG_PREF, "")) + self._announce_retired_on_time_state() self.runtime = AsyncRuntime(self.logger) @@ -547,6 +552,15 @@ def deviceDeleted(self, dev): # noqa: N802 self.device_sync.note_node_device_deleted(int(node_id), dev.id) except Exception as exc: # noqa: BLE001 - a deletion must always complete self.logger.exception(exc) + # Every device type can carry a removed_state_log entry (issue #312), + # not just matterNode — unlike the tombstone above this is unconditional + # and unrelated to exports, so it runs before the early return below. + try: + log = getattr(self, "removed_state_log", None) + if log is not None: + log.forget(dev.id) + except Exception as exc: # noqa: BLE001 - a deletion must always complete + self.logger.exception(exc) if dev.id not in self._exported_ids or self.exports is None: return try: @@ -1157,6 +1171,30 @@ def lookup(cluster): return lookup + def _save_removed_state_log(self, blob: str) -> None: + """Persist ``removed_state_log`` (issue #312). + + Same discipline as ``DiagnosticsMenuMixin._save_survey_log``: written + through ``self.pluginPrefs`` at call time rather than a captured + mapping, because Indigo rebinds it when the PluginConfig dialog is + saved, and committed via ``savePluginPrefs`` without which it survives + only until the plugin stops. + + Caught and logged rather than left to escape into + ``RemovedStateLog._persist``, which is deliberately silent for the same + reason ``SurveyLog._persist`` is (issue #308: the caller supplies the + save hook and logs there). A failure here is cosmetic — the affected + device(s) simply reprint their removed-state INFO once more on the + next rebuild — which is why WARNING rather than anything louder. + """ + try: + self.pluginPrefs[REMOVED_STATE_LOG_PREF] = blob + indigo.server.savePluginPrefs() + except Exception as exc: # noqa: BLE001 - bookkeeping must never sink a device rebuild + self.logger.warning( + "Matter: could not save the removed-state log (%s) — the affected " + "device(s) will reprint their state-removal notice on the next rebuild.", exc) + def getDeviceStateList(self, dev): # noqa: N802 """Build this device's states from what the DEVICE says it implements. @@ -1225,24 +1263,41 @@ def getDeviceStateList(self, dev): # noqa: N802 'device "%s": %d of %d state entries could not be read, so the Matter ' "capability filter was not applied to them", dev.name, unreadable, total) if removed: - # INFO, and worth it: a state disappearing silently breaks any - # trigger or control page bound to it, with nothing in the log to - # connect the two. One line per device rather than per state. - # - # Frequency: NOT at device start — deviceStartComm forces a rebuild - # before the first reconcile has run, so the cache is cold, every - # answer is unknown and nothing is removed. The line comes from the - # first _refresh_state_lists after that reconcile, and thereafter - # when a node's AttributeLists change OR the pass created a device - # (the refresh covers the whole node, so a new sibling reprints this - # for the devices already filtered). Indigo also rebuilds when an - # Edit Device dialog is dismissed, so editing one reprints it. - self.logger.info( - 'device "%s": removed the state(s) %s — this unit\'s AttributeList says it ' - "does not implement %s, so the values shown were Indigo's defaults rather " - "than anything the device reported", - dev.name, ", ".join(f'"{key}"' for key in removed), - ", ".join(f"0x{drop[key].attribute:04X}" for key in removed)) + # Logged once per distinct ANSWER, not once per evaluation (issue + # #312). The filtering above is correct to re-run on every rebuild + # — Indigo calls this as a filter each time, and the cache the + # answer is drawn from can have changed — but reprinting the same + # removed-set on every rebuild was pure noise: ~3 lines/device on + # every plugin start, forever, for an answer that essentially never + # changes within a session. removed_state_log persists a + # fingerprint per device so a genuinely NEW or CHANGED answer still + # logs (including the very first time) while an unchanged repeat + # does not. `None` (not wired — only possible if getDeviceStateList + # runs before startup finishes) fails open to the old behaviour + # rather than silently going quiet. + log = getattr(self, "removed_state_log", None) + fingerprint = device_settings.RemovedStateLog.fingerprint(removed) + if log is None or log.should_log(dev.id, fingerprint): + # INFO, and worth it: a state disappearing silently breaks any + # trigger or control page bound to it, with nothing in the log to + # connect the two. One line per device rather than per state. + # + # Frequency: NOT at device start — deviceStartComm forces a rebuild + # before the first reconcile has run, so the cache is cold, every + # answer is unknown and nothing is removed. The line comes from the + # first _refresh_state_lists after that reconcile, and thereafter + # when a node's AttributeLists change OR the pass created a device + # (the refresh covers the whole node, so a new sibling reprints this + # for the devices already filtered). Indigo also rebuilds when an + # Edit Device dialog is dismissed, so editing one reprints it. + self.logger.info( + 'device "%s": removed the state(s) %s — this unit\'s AttributeList says it ' + "does not implement %s, so the values shown were Indigo's defaults rather " + "than anything the device reported", + dev.name, ", ".join(f'"{key}"' for key in removed), + ", ".join(f"0x{drop[key].attribute:04X}" for key in removed)) + if log is not None: + log.record(dev.id, fingerprint) return kept def getDeviceConfigUiValues(self, pluginProps, typeId, devId): # noqa: N802 diff --git a/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin_constants.py b/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin_constants.py index 21eccf1..60e7db0 100644 --- a/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin_constants.py +++ b/indigo-matter.indigoPlugin/Contents/Server Plugin/plugin_constants.py @@ -102,6 +102,13 @@ #: startup loads it, MatterServerMenuMixin saves it (the "Recreate Matter node #: devices…" menu item is where a tombstone is cleared). NODE_TOMBSTONES_PREF = "matterNodeDeviceTombstones" +#: pluginPrefs key holding ``getDeviceStateList``'s "last reported removed-set" +#: log (issue #312) — one JSON object keyed by Indigo device id, valued by a +#: fingerprint of the removed state keys, so the state-removal INFO logs once +#: per distinct answer rather than on every rebuild. Same prefs discipline as +#: SURVEY_LOG_PREF: plugin.startup loads it, plugin.py saves it, and +#: plugin.deviceDeleted forgets a deleted device's entry. +REMOVED_STATE_LOG_PREF = "matterRemovedStateLog" #: How long the "Recreate Matter node devices…" menu action may block the #: Indigo UI thread on a full reconcile (get_nodes + get_node per node, not #: just one round trip like SURVEY_READ_TIMEOUT) — generous for the same diff --git a/indigo-matter.indigoPlugin/Contents/Server Plugin/settings_report.py b/indigo-matter.indigoPlugin/Contents/Server Plugin/settings_report.py index d2c0b89..c4b2354 100644 --- a/indigo-matter.indigoPlugin/Contents/Server Plugin/settings_report.py +++ b/indigo-matter.indigoPlugin/Contents/Server Plugin/settings_report.py @@ -703,9 +703,10 @@ def _persist(self) -> None: try: self._save(self.to_json()) except Exception: # noqa: BLE001 - bookkeeping must never sink a reconcile - # Deliberately silent: the caller supplies the save hook and logs - # there if it wants to. A failed save costs one repeated INFO on the - # next start, which is a strictly better outcome than an exception + # Deliberately silent here: the caller supplies the save hook and + # logs there (DiagnosticsMenuMixin._save_survey_log does, per + # issue #308). A failed save costs one repeated INFO on the next + # start, which is a strictly better outcome than an exception # escaping into create_devices. pass diff --git a/tests/test_diagnostics_menu.py b/tests/test_diagnostics_menu.py index 73de7a1..5f7a447 100644 --- a/tests/test_diagnostics_menu.py +++ b/tests/test_diagnostics_menu.py @@ -299,6 +299,34 @@ def test_saving_the_log_commits_through_indigo(mixin): assert sys.modules["indigo"].server.savePluginPrefs.called +def test_a_failed_save_is_logged_not_swallowed(mixin): + """Issue #308: ``SurveyLog._persist`` is deliberately silent on the + assumption that its caller logs — this pins that the caller actually + does, so the documented contract is not just a comment nobody honours. + """ + _module, obj = mixin + sys.modules["indigo"].server.savePluginPrefs.side_effect = OSError("prefs are gone") + + obj._save_survey_log('{"52": "fp"}') # must not raise + + assert obj.logger.warning.called + warning_args = obj.logger.warning.call_args[0] + assert "survey log" in warning_args[0] + + +def test_a_failed_save_logs_exactly_once(mixin): + """To assert the swallow in ``SurveyLog._persist`` is never what does the + logging, make the *caller's* own logging the only thing capable of firing: + if this fired twice, something upstream (``_persist`` itself) would have + to have logged too — which the #308 fix explicitly says it must not.""" + _module, obj = mixin + sys.modules["indigo"].server.savePluginPrefs.side_effect = OSError("prefs are gone") + + obj._save_survey_log('{"52": "fp"}') + + assert obj.logger.warning.call_count == 1 + + # --------------------------------------------------------------------------- # The invariant # --------------------------------------------------------------------------- diff --git a/tests/test_plugin_module.py b/tests/test_plugin_module.py index 1ed7b75..125ace0 100644 --- a/tests/test_plugin_module.py +++ b/tests/test_plugin_module.py @@ -12,6 +12,8 @@ import pytest +import device_settings + BUNDLE = ( Path(__file__).parent.parent / "indigo-matter.indigoPlugin" @@ -2086,6 +2088,7 @@ def lookup(node, ep, cluster): plugin.device_sync = device_sync plugin.base_state_lists = {"matterRelay": _relay_states(), "matterMotionSensor": _motion_states()} + plugin.removed_state_log = device_settings.RemovedStateLog() return plugin @@ -2252,3 +2255,109 @@ def test_a_device_type_with_no_settings_is_passed_straight_through( dev = SimpleNamespace(id=9, name="Hall Temp", deviceTypeId="matterTemperatureSensor", pluginProps={"nodeId": "52", "endpointId": "1"}) assert [s["Key"] for s in plugin.getDeviceStateList(dev)] == ["sensorValue"] + + +# =========================================================================== +# issue #312 — the removed-state INFO logs once per distinct answer, not once +# per evaluation. The filtering itself does not change (proven above); only +# how often it is announced. +# =========================================================================== + +def test_the_first_evaluation_logs(plugin_cls, mock_indigo_base, mock_logger): + """No prior fingerprint recorded — the answer is new, so it must log.""" + plugin = _state_list_plugin(plugin_cls, mock_indigo_base, mock_logger, _PLAIN_PLUG_LISTS) + plugin.getDeviceStateList(_relay_dev()) + assert mock_logger.info.call_count == 1 + + +def test_an_identical_re_evaluation_does_not_log_again( + plugin_cls, mock_indigo_base, mock_logger): + """The bug in #312: Indigo rebuilds a device's state list on every dialog + dismiss and every plugin start, and the filter is right to re-run every + time — but re-announcing the SAME answer is the noise being fixed.""" + plugin = _state_list_plugin(plugin_cls, mock_indigo_base, mock_logger, _PLAIN_PLUG_LISTS) + plugin.getDeviceStateList(_relay_dev()) + plugin.getDeviceStateList(_relay_dev()) + plugin.getDeviceStateList(_relay_dev()) + assert mock_logger.info.call_count == 1 + + +def test_a_changed_removed_set_logs_again(plugin_cls, mock_indigo_base, mock_logger): + """Keyed on the ANSWER, not just the device: a device that first drops one + state and later drops a DIFFERENT one must log the second time too — a + boolean "already logged this device" latch would wrongly suppress it.""" + plugin = _state_list_plugin(plugin_cls, mock_indigo_base, mock_logger, { + 0x0406: [0, 65528, 65529, 65531, 65532, 65533], # no HoldTime + 0x0080: [0, 65528, 65529, 65531, 65532, 65533], # HAS sensitivityLevel + }) + plugin.getDeviceStateList(_motion_dev()) # drops holdTime only + plugin.device_sync.attribute_list.side_effect = lambda node, ep, cluster: { + 0x0406: [0, 65528, 65529, 65531, 65532, 65533], # still no HoldTime + 0x0080: [65528, 65529, 65531, 65532, 65533], # NOW also loses sensitivityLevel + }.get(cluster) + plugin.getDeviceStateList(_motion_dev()) # drops holdTime AND sensitivityLevel + assert mock_logger.info.call_count == 2 + second = str(mock_logger.info.call_args_list[1]) + assert "sensitivityLevel" in second + + +def test_the_same_answer_on_two_different_devices_logs_for_each( + plugin_cls, mock_indigo_base, mock_logger): + """The fingerprint is keyed per device id — two devices dropping the exact + same state must not be treated as the same "already logged" answer.""" + plugin = _state_list_plugin(plugin_cls, mock_indigo_base, mock_logger, _PLAIN_PLUG_LISTS) + plugin.getDeviceStateList(_relay_dev(dev_id=7, node="52")) + plugin.getDeviceStateList(_relay_dev(dev_id=8, name="Second plug", node="53")) + assert mock_logger.info.call_count == 2 + + +def test_a_save_failure_does_not_raise_into_getDeviceStateList( + plugin_cls, mock_indigo_base, mock_logger): + """To assert the swallow lives in RemovedStateLog._persist and not in + getDeviceStateList's own exception handling, make the save hook fatal and + confirm the state list still builds — if this needed the OUTER handler to + catch it, `.exception` would fire, which the assertion below rules out.""" + plugin = _state_list_plugin(plugin_cls, mock_indigo_base, mock_logger, _PLAIN_PLUG_LISTS) + + def boom(_blob): + raise OSError("prefs are gone") + + plugin.removed_state_log = device_settings.RemovedStateLog(save=boom) + keys = [state["Key"] for state in plugin.getDeviceStateList(_relay_dev())] + assert keys == ["onOffState"] + assert not mock_logger.exception.called + + +def test_a_device_with_no_removed_state_log_wired_fails_open_to_logging_every_time( + plugin_cls, mock_indigo_base, mock_logger): + """Defensive fallback for the (only theoretical) case getDeviceStateList + runs before startup wires removed_state_log: better to over-log than to + raise or silently drop the #190 warning altogether.""" + plugin = _state_list_plugin(plugin_cls, mock_indigo_base, mock_logger, _PLAIN_PLUG_LISTS) + del plugin.removed_state_log + plugin.getDeviceStateList(_relay_dev()) + plugin.getDeviceStateList(_relay_dev()) + assert mock_logger.info.call_count == 2 + + +def test_a_deleted_device_is_forgotten_by_the_removed_state_log( + plugin_cls, mock_indigo_base, mock_logger): + """Wired to plugin.deviceDeleted (issue #312): otherwise a deleted device's + fingerprint entry sits in pluginPrefs forever, unbounded, for a device that + no longer exists — and if the id were ever reused, a new device could + silently inherit a stale "already logged" answer.""" + import plugin as plugin_module + plugin = plugin_module.Plugin.__new__(plugin_module.Plugin) + plugin.logger = mock_logger + plugin.removed_state_log = device_settings.RemovedStateLog() + plugin.removed_state_log.record(7, "startUpOnOff") + assert not plugin.removed_state_log.should_log(7, "startUpOnOff") + + dev = _relay_dev(dev_id=7) + dev.pluginProps = {} # not a matterNode, no export bookkeeping to touch + plugin._exported_ids = set() + plugin.exports = None + plugin.device_sync = None + plugin.deviceDeleted(dev) + + assert plugin.removed_state_log.should_log(7, "startUpOnOff")