From e68f170f89bf9acad66da93f71dd53c2ebc0fdaa Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 13:05:00 -0700 Subject: [PATCH 1/7] Controller: pace per-device subscriptions and heal stuck devices (#97) A tree-rooted Controller subscribed to every child of a tree at once. The broker queues every matching retained message for that one client and, past its per-client limit (mosquitto max_queued_messages 1000), drops the rest; retained messages are sent only at subscribe time, so the dropped children's $state and $description never arrived. Prevent: per-device subscriptions (tree-rooted descendants and wildcard discovery) go through a queue of at most subscription_batch_size (default 8) in-flight devices. The next pending device is subscribed when an in-flight one has both $state and $description, is removed, or is declared stuck. Descendants are subscribed in the order their parent's $description lists them. None or 0 restores the unpaced fan-out. Heal: check_stuck_children(timeout=None) unsubscribes and resubscribes the filters of any watched device still lacking $state or $description after the timeout (default stuck_device_timeout, 10 s), up to max_resubscribe_attempts (default 3), logging each attempt and the final give-up. Message handling runs it at most once a second. No threads or timers; bookkeeping is under a lock and transport calls are made outside it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- CHANGELOG.md | 2 + README.md | 15 ++ src/ebus_sdk/homie.py | 316 ++++++++++++++++++++++++++++++--------- tests/test_controller.py | 310 +++++++++++++++++++++++++++++++++++++- 4 files changed, 566 insertions(+), 77 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f7a04e7..52b7850 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,10 +34,12 @@ Homie 5 compliance, phase 1: producer wire correctness ([#95](https://github.com - Encoders for `datetime` (`datetime`/`date` as ISO 8601, :132), `duration` (`timedelta` as `PTxHxMxS`, :137-144) and `color` (a component tuple in the first `format` color type, :118-123). These fell through to `str()`, which produced `2026-10-08 12:00:00+00:00`, `0:05:00` and `(255, 0, 0)`. - `Device.publish_alert(alert_id, message)`, `Device.clear_alert(alert_id)` and `Device.alerts()`. Alerts publish retained to `$alert/[alert ID]` (:517), are republished on reconnect, and are cleared by `delete()` (:289). - `Device.invalidate_description_cache()`, the `$description` counterpart of `Property.invalidate_publish_cache()`. `clear_retained_topic()` aimed at the device's own `$description` and `delete_all_from_mqtt()` call it, so a later `publish_description()` is no longer suppressed after the topic was cleared. +- `Controller(subscription_batch_size=8, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device whose filters have been subscribed for `timeout` seconds without its `$state` or `$description` arriving is unsubscribed and resubscribed, so the broker resends its retained messages, up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end. Message handling runs the check at most once a second; a consumer on a quiet connection, or driving its own event loop, can call it from a timer. `stuck_device_timeout=None` turns off the automatic check ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ### Fixed - `delete()` followed by `stop()` re-created the deleted device as a bare `$state=disconnected` with no `$description` (:272, :288). After `delete()` the root's `stop()` announces nothing, flushes `delete()`'s retained clears and disconnects cleanly in either mode, and a reconnect's `refresh_tree()` republishes nothing. +- A tree-rooted `Controller` could miss the retained `$state` and `$description` of some children of a large tree for good. It subscribed to every child at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes at most `subscription_batch_size` devices (default 8) at a time and starts the next as each one's `$state` and `$description` arrive or it is declared stuck, in tree-rooted descendants and in wildcard discovery alike; all 30 are described. `subscription_batch_size=None` restores the unpaced fan-out. Descendants are subscribed in the order their parent's `$description` lists them ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ## [0.24.0] — 2026-10-03 diff --git a/README.md b/README.md index 542cb28..f93c01e 100644 --- a/README.md +++ b/README.md @@ -301,6 +301,21 @@ see the root and none of its children. As the publisher mutates the tree (`Device(parent=...)` to add, `child.delete()` to remove), descendants are subscribed or dropped on the parent's next init→ready transition. +#### Paced subscriptions and stuck devices + +A broker queues every retained message matching a new subscription for that one client and drops what exceeds its per-client limit (mosquitto: `max_queued_messages` 1000). Retained messages are sent only at subscribe time, so a device whose `$state` or `$description` was dropped is never discovered. The Controller therefore subscribes to at most `subscription_batch_size` devices at a time (default 8; tree-rooted descendants and wildcard-discovered devices) and subscribes the next as each one's `$state` and `$description` arrive. + +A device still lacking either after `stuck_device_timeout` seconds (default 10) gives up its slot and is unsubscribed and resubscribed, so the broker resends its retained messages, up to `max_resubscribe_attempts` times (default 3). Message handling runs this check at most once a second, so a controller that receives traffic heals without help. On a quiet connection, or under a caller-driven event loop, call it yourself: + +```python +controller = Controller(mqtt_cfg=cfg, root_device_id='panel-1', + subscription_batch_size=8, stuck_device_timeout=10.0) +... +resubscribed = controller.check_stuck_children() # or check_stuck_children(timeout=30) +``` + +`subscription_batch_size=None` subscribes every device at once; `stuck_device_timeout=None` turns off the automatic check. + ## Module Structure ``` diff --git a/src/ebus_sdk/homie.py b/src/ebus_sdk/homie.py index b8f54a1..20a3a5b 100644 --- a/src/ebus_sdk/homie.py +++ b/src/ebus_sdk/homie.py @@ -3544,6 +3544,32 @@ def get_node_properties(self, node_id: str) -> dict: return {} +# Controller subscription pacing and stuck-device healing (GH #97). Subscribing to many +# devices at once makes the broker queue every matching retained message for this one +# client; past its per-client limits (mosquitto: max_queued_messages 1000) it drops the +# excess, and retained messages are sent only at subscribe time, so a dropped $state or +# $description never arrives. +CONTROLLER_SUBSCRIPTION_BATCH_SIZE = 8 +CONTROLLER_STUCK_DEVICE_TIMEOUT = 10.0 +CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS = 3 +# Upper bound on how often message handling runs the opportunistic stuck check. +_STUCK_CHECK_INTERVAL = 1.0 +# Per-device topic filter suffixes. Wildcard discovery hears $state through its +# broker-wide {domain}/5/+/$state filter, so a device found that way needs only the rest. +_DEVICE_FILTERS = ("$state", "$description", "+/+", "+/+/$target") +_WILDCARD_DEVICE_FILTERS = ("$description", "+/+", "+/+/$target") + + +@dataclass +class _SubscriptionWatch: + """A device whose filters are subscribed but whose $state or $description has not arrived.""" + + filters: tuple + subscribed_at: float + holds_slot: bool + attempts: int = 0 + + class Controller: """ Homie MQTT Controller - discovers and interacts with Homie devices @@ -3575,6 +3601,9 @@ def __init__( root_device_id: Optional[str] = None, qos: int = EBUS_HOMIE_MQTT_QOS, mqttc: Optional[MqttControllerTransport] = None, + subscription_batch_size: Optional[int] = CONTROLLER_SUBSCRIPTION_BATCH_SIZE, + stuck_device_timeout: Optional[float] = CONTROLLER_STUCK_DEVICE_TIMEOUT, + max_resubscribe_attempts: int = CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS, ): """ Initialize a Homie Controller @@ -3604,6 +3633,21 @@ def __init__( Assistant consumer driving MQTT on its own loop). Drive discovery with start_discovery() once the client is connected. Default None: the SDK constructs, starts, and owns a client from mqtt_cfg. + subscription_batch_size: Most devices whose per-device subscriptions + may await their retained $state and $description at once (GH #97). + Further devices (tree descendants, or devices found by wildcard + discovery) wait in order and are subscribed as earlier ones finish + or are declared stuck, so the broker's per-client queue does not + overflow and drop retained messages. None or 0 subscribes every + device immediately. + stuck_device_timeout: Seconds a subscribed device may lack $state or + $description before it is declared stuck: it gives up its batch + slot and its filters are unsubscribed and resubscribed so the + broker resends its retained messages. Message handling runs this + check at most once a second; see check_stuck_children(). None + disables the automatic check. + max_resubscribe_attempts: Resubscribes per stuck device before it is + logged as unrecoverable and no longer checked. 0 only logs. """ if device_id is not None and root_device_id is not None: raise ValueError( @@ -3635,6 +3679,24 @@ def __init__( # doesn't look "missing" and get re-subscribed every reconcile. self._subscribed_children: dict = {} + # Subscription pacing and stuck-device healing (GH #97). Event-driven: state + # changes only on message arrival, device removal, resync, or a call to + # check_stuck_children(). The lock guards the bookkeeping only; transport + # calls are made after releasing it. + if subscription_batch_size is not None and subscription_batch_size < 0: + raise ValueError("subscription_batch_size must be None or >= 0") + if max_resubscribe_attempts < 0: + raise ValueError("max_resubscribe_attempts must be >= 0") + self._subscription_batch_size = subscription_batch_size or None + self._stuck_device_timeout = stuck_device_timeout + self._max_resubscribe_attempts = max_resubscribe_attempts + self._pacing_lock = threading.RLock() + # {device_id: _SubscriptionWatch}: subscribed, awaiting $state and $description. + self._watches: dict = {} + # {device_id: filters}, insertion-ordered: requested but not yet subscribed. + self._pending_subscriptions: dict = {} + self._last_stuck_check = time.monotonic() + # Callbacks self._on_device_discovered = None self._on_device_state_changed = None @@ -3730,6 +3792,14 @@ def resync(self) -> None: (via ``MqttClient.from_config``), which an injected client bypasses. """ if self.is_tree_rooted: + # The re-walk re-requests every descendant, paced, so pending work from the + # previous connection is dropped. The root's filters were resubscribed by the + # transport; watch it so a root whose retained messages are lost also heals. + with self._pacing_lock: + self._pending_subscriptions.clear() + self._watches = { + self.root_device_id: _SubscriptionWatch(_DEVICE_FILTERS, time.monotonic(), holds_slot=True) + } # Cold restart of tree-rooted bookkeeping. paho-mqtt's MqttClient # has already re-subscribed our root's four filters; retained # state/description will arrive momentarily and the state-edge @@ -3766,7 +3836,7 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: # discovered via the parent's $description.children device = DiscoveredDevice(self.root_device_id, domain) self.devices[self.root_device_id] = device - self._subscribe_device_topics(self.root_device_id) + self._request_subscription(self.root_device_id, _DEVICE_FILTERS) elif self.device_id: # Single-device mode: subscribe to exact topics, no wildcard # in the device-id position @@ -3774,41 +3844,169 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: # Pre-create the DiscoveredDevice entry device = DiscoveredDevice(self.device_id, domain) self.devices[self.device_id] = device - self._subscribe_device_topics(self.device_id) + self._request_subscription(self.device_id, _DEVICE_FILTERS) else: # Wildcard discovery mode (original behavior) discovery_topic = f"{domain}/{EBUS_HOMIE_VERSION_MAJOR}/+/$state" logger.info(f"reason=startDiscovery,topic={discovery_topic}") self.mqttc.subscribe(discovery_topic, param=self._on_state_message, qos=self._qos) - def _subscribe_device_topics(self, device_id: str) -> None: - """Subscribe to the four exact-device topic patterns for device_id. + def _subscribe_filters(self, device_id: str, filters: tuple) -> None: + """Subscribe the given per-device filter suffixes for device_id, in order. - Used by single-device mode, tree-rooted mode (for the root and each - discovered descendant). The wildcard $state subscription path uses a - different shape and bypasses this. + Single-device and tree-rooted modes subscribe all four (_DEVICE_FILTERS). + Wildcard discovery already hears $state through {domain}/5/+/$state and + subscribes the other three (_WILDCARD_DEVICE_FILTERS). """ + if not self.mqttc: + return base = f"{self.homie_domain}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}" - self.mqttc.subscribe( - f"{base}/$state", - param=self._on_state_message, - qos=self._qos, - ) - self.mqttc.subscribe( - f"{base}/$description", - param=partial(self._on_description_message, device_id), - qos=self._qos, - ) - self.mqttc.subscribe( - f"{base}/+/+", - param=partial(self._on_property_message, device_id), - qos=self._qos, - ) - self.mqttc.subscribe( - f"{base}/+/+/$target", - param=partial(self._on_target_message, device_id), - qos=self._qos, - ) + callbacks = { + "$state": self._on_state_message, + "$description": partial(self._on_description_message, device_id), + "+/+": partial(self._on_property_message, device_id), + "+/+/$target": partial(self._on_target_message, device_id), + } + for suffix in filters: + self.mqttc.subscribe(f"{base}/{suffix}", param=callbacks[suffix], qos=self._qos) + + def _unsubscribe_filters(self, device_id: str, filters: tuple) -> None: + if not self.mqttc: + return + base = f"{self.homie_domain}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}" + for suffix in filters: + self.mqttc.unsubscribe(f"{base}/{suffix}") + + # ── Subscription pacing and stuck-device healing (GH #97) ────────────── + + def _slot_free_locked(self) -> bool: + if self._subscription_batch_size is None: + return True + in_use = sum(1 for w in self._watches.values() if w.holds_slot) + return in_use < self._subscription_batch_size + + def _take_pending_locked(self) -> list: + """Move pending devices into free batch slots; the caller subscribes them unlocked.""" + started = [] + while self._pending_subscriptions and self._slot_free_locked(): + device_id = next(iter(self._pending_subscriptions)) + filters = self._pending_subscriptions.pop(device_id) + self._watches[device_id] = _SubscriptionWatch(filters, time.monotonic(), holds_slot=True) + started.append((device_id, filters)) + return started + + def _start_subscriptions(self, started: list) -> None: + for device_id, filters in started: + logger.info(f"reason=pacedSubscribe,deviceID={device_id},pending={len(self._pending_subscriptions)}") + self._subscribe_filters(device_id, filters) + + def _request_subscription(self, device_id: str, filters: tuple) -> None: + """Subscribe a device's filters now if a batch slot is free, else queue it in order.""" + with self._pacing_lock: + if device_id in self._watches or device_id in self._pending_subscriptions: + return + self._pending_subscriptions[device_id] = filters + started = self._take_pending_locked() + if device_id in self._pending_subscriptions: + logger.debug( + f"reason=subscriptionDeferred,deviceID={device_id},pending={len(self._pending_subscriptions)}" + ) + self._start_subscriptions(started) + + def _note_device_progress(self, device_id: str) -> None: + """Stop watching a device once it has both $state and $description; free its slot.""" + device = self.devices.get(device_id) + with self._pacing_lock: + if device_id not in self._watches: + return + if device is not None and (device.state is None or device.description is None): + return + del self._watches[device_id] + started = self._take_pending_locked() + self._start_subscriptions(started) + + def _forget_subscription(self, device_id: str) -> bool: + """Drop a device from pacing; True when it was still pending (never subscribed).""" + with self._pacing_lock: + was_pending = self._pending_subscriptions.pop(device_id, None) is not None + self._watches.pop(device_id, None) + started = self._take_pending_locked() + self._start_subscriptions(started) + return was_pending + + def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: + """Heal subscribed devices whose retained $state or $description never arrived (GH #97). + + A device counts as stuck when its filters have been subscribed for at + least ``timeout`` seconds (default: the constructor's + ``stuck_device_timeout``) and it still lacks ``$state`` or + ``$description``. A stuck device gives up its batch slot, so the next + pending device is subscribed, and its filters are unsubscribed and + resubscribed so the broker resends its retained messages. After + ``max_resubscribe_attempts`` resubscribes it is logged as unrecoverable + and no longer checked; its subscriptions stay in place, so a device + that appears later is still discovered. + + Message handling calls this at most once a second when + ``stuck_device_timeout`` is set, so a controller receiving traffic heals + without help. On a quiet connection nothing arrives to trigger it: call + it from your own timer or event loop. It uses no threads and is safe to + call from any thread. + + Returns the ids of the devices resubscribed by this call. + """ + if timeout is None: + timeout = self._stuck_device_timeout + if timeout is None: + return [] + now = time.monotonic() + resubscribe = [] + with self._pacing_lock: + self._last_stuck_check = now + for device_id, watch in list(self._watches.items()): + if now - watch.subscribed_at < timeout: + continue + device = self.devices.get(device_id) + if device is None: + del self._watches[device_id] + continue + missing = [ + name for name, v in (("$state", device.state), ("$description", device.description)) if v is None + ] + if not missing: + del self._watches[device_id] + continue + watch.holds_slot = False + if watch.attempts >= self._max_resubscribe_attempts: + del self._watches[device_id] + logger.error( + f"reason=stuckDeviceGaveUp,deviceID={device_id},missing={'+'.join(missing)}," + f"attempts={watch.attempts}" + ) + continue + watch.attempts += 1 + watch.subscribed_at = now + resubscribe.append((device_id, watch.filters, watch.attempts, missing)) + started = self._take_pending_locked() + + for device_id, filters, attempt, missing in resubscribe: + logger.warning( + f"reason=stuckDeviceResubscribe,deviceID={device_id},missing={'+'.join(missing)}," + f"attempt={attempt}/{self._max_resubscribe_attempts}" + ) + self._unsubscribe_filters(device_id, filters) + self._subscribe_filters(device_id, filters) + self._start_subscriptions(started) + return [device_id for device_id, *_ in resubscribe] + + def _maybe_check_stuck(self) -> None: + """Opportunistic, rate-limited stuck check run from message handling.""" + timeout = self._stuck_device_timeout + if timeout is None or not self._watches: + return + if time.monotonic() - self._last_stuck_check < min(_STUCK_CHECK_INTERVAL, timeout): + return + self.check_stuck_children() def _on_state_message(self, topic: str, payload: bytes) -> None: """ @@ -3817,6 +4015,7 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: Topic format: {domain}/5/{device_id}/$state Payload: init, ready, disconnected, sleeping, lost, or empty (device removal) """ + self._maybe_check_stuck() parts = topic.split("/") if len(parts) != 4 or parts[3] != "$state": logger.warning(f"reason=invalidStateTopic,topic={topic}") @@ -3831,6 +4030,7 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: # Empty payload indicates device removal if not payload_str or len(payload_str) == 0: logger.info(f"reason=deviceRemoved,deviceID={device_id}") + self._forget_subscription(device_id) if device_id in self.devices: removed_device = self.devices[device_id] del self.devices[device_id] @@ -3850,8 +4050,8 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: device.update_state(payload_str) self.devices[device_id] = device - # Subscribe to device's $description and all properties - self._subscribe_to_device(device_id) + # Subscribe to device's $description and all properties, paced + self._request_subscription(device_id, _WILDCARD_DEVICE_FILTERS) if self._on_device_discovered: self._on_device_discovered(device) @@ -3890,43 +4090,7 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: if self.is_tree_rooted and payload_str == DeviceState.READY.value and old_state != DeviceState.READY.value: self._reconcile_descendants(device_id) - def _subscribe_to_device(self, device_id: str) -> None: - """Subscribe to all topics for a discovered device (wildcard-mode helper). - - Wildcard discovery hears a device's $state via the {domain}/5/+/$state - subscription; once it knows the device exists, it needs three more - filters (description, properties, targets) to track everything else. - Tree-rooted and single-device modes don't go through here — they call - _subscribe_device_topics directly to get all four filters at once. - """ - if not self.mqttc: - return - - base_topic = f"{self.homie_domain}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}" - - # Subscribe to $description - description_topic = f"{base_topic}/$description" - self.mqttc.subscribe( - description_topic, - param=partial(self._on_description_message, device_id), - qos=self._qos, - ) - - # Subscribe to all properties and targets - property_topic = f"{base_topic}/+/+" - self.mqttc.subscribe( - property_topic, - param=partial(self._on_property_message, device_id), - qos=self._qos, - ) - - # Subscribe to all property targets - target_topic = f"{base_topic}/+/+/$target" - self.mqttc.subscribe( - target_topic, - param=partial(self._on_target_message, device_id), - qos=self._qos, - ) + self._note_device_progress(device_id) def _reconcile_descendants(self, device_id: str) -> None: """Diff a device's announced children against what's subscribed (SDK-o1h). @@ -3952,14 +4116,15 @@ def _reconcile_descendants(self, device_id: str) -> None: added = declared - current removed = current - declared - for child_id in added: + # Declared order, so paced subscriptions follow the description's order. + for child_id in [c for c in dict.fromkeys(device.children_ids) if c in added]: logger.info(f"reason=treeRootedAddDescendant,parentID={device_id},childID={child_id}") # Pre-create child entry; its own retained $state/$description # arrive via the new subscriptions and drive update + cascade. if child_id not in self.devices: self.devices[child_id] = DiscoveredDevice(child_id, self.homie_domain) self._subscribed_children.setdefault(device_id, set()).add(child_id) - self._subscribe_device_topics(child_id) + self._request_subscription(child_id, _DEVICE_FILTERS) for child_id in removed: logger.info(f"reason=treeRootedRemoveDescendant,parentID={device_id},childID={child_id}") @@ -3993,10 +4158,9 @@ def _unsubscribe_and_drop(self, device_id: str) -> None: if device is None: return - if self.mqttc: - base = f"{self.homie_domain}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}" - for suffix in ("$state", "$description", "+/+", "+/+/$target"): - self.mqttc.unsubscribe(f"{base}/{suffix}") + # A device still waiting for a batch slot was never subscribed. + if not self._forget_subscription(device_id): + self._unsubscribe_filters(device_id, _DEVICE_FILTERS) if self._on_device_removed: try: @@ -4011,6 +4175,7 @@ def _unsubscribe_and_drop(self, device_id: str) -> None: def _on_description_message(self, device_id: str, topic: str, payload: bytes) -> None: """Handle device $description messages""" + self._maybe_check_stuck() if device_id not in self.devices: return @@ -4039,6 +4204,8 @@ def _on_description_message(self, device_id: str, topic: str, payload: bytes) -> # this description just introduced is already registered. self._reevaluate_tree_completeness() + self._note_device_progress(device_id) + def _on_property_message(self, device_id: str, topic: str, payload: bytes) -> None: """ Handle property value messages @@ -4046,6 +4213,7 @@ def _on_property_message(self, device_id: str, topic: str, payload: bytes) -> No Topic format: {domain}/5/{device_id}/{node_id}/{property_id} Skip $target topics (handled separately) """ + self._maybe_check_stuck() # Skip $target topics if topic.endswith("/$target"): return @@ -4084,6 +4252,7 @@ def _on_target_message(self, device_id: str, topic: str, payload: bytes) -> None Topic format: {domain}/5/{device_id}/{node_id}/{property_id}/$target """ + self._maybe_check_stuck() parts = topic.split("/") if len(parts) != 6 or parts[5] != "$target": return @@ -4394,6 +4563,9 @@ def stop(self) -> None: self.devices.clear() self._subscribed_children.clear() self._tree_complete.clear() + with self._pacing_lock: + self._watches.clear() + self._pending_subscriptions.clear() # Clear callback references to break reference cycles self._on_device_discovered = None self._on_device_state_changed = None diff --git a/tests/test_controller.py b/tests/test_controller.py index e880888..30115ce 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -838,14 +838,14 @@ def test_broadcast_allows_qos_override(self, mock_paho): _, kwargs = mock_client.publish.call_args assert kwargs["qos"] == 0 - def test_subscribe_to_device_uses_custom_qos(self, mock_paho): - """Verify _subscribe_to_device (wildcard re-subscribe on new device) uses controller QoS.""" + def test_wildcard_per_device_subscribe_uses_custom_qos(self, mock_paho): + """The per-device filters wildcard discovery adds for a new device use controller QoS.""" ctrl, mock_client = _make_controller_with_qos(mock_paho, qos=1) ctrl.start_discovery() mock_client.subscribe.reset_mock() - # Simulate discovering a new device in wildcard mode - ctrl._subscribe_to_device("panel-2") + # Discover a new device in wildcard mode + ctrl._on_state_message(f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-2/$state", b"ready") assert mock_client.subscribe.call_count == 3 for c in mock_client.subscribe.call_args_list: @@ -1159,7 +1159,7 @@ class TestTreeRootedDescriptionRace: """SDK-gsn: retained $state=ready may arrive before retained $description. paho delivers retained messages in subscription order, and we subscribe - to $state before $description in _subscribe_device_topics. So on initial + to $state before $description in _subscribe_filters. So on initial connect to a broker holding both retained, the state-edge reconcile in _on_state_message can fire while the device's description is still None, seeing zero children and subscribing to nothing. The fix re-runs reconcile @@ -1541,3 +1541,303 @@ def test_on_tree_ready_survives_a_raising_callback(self, mock_paho): _push_description(ctrl, "bess-1", {"homie": "5.0", "root": "panel-1", "parent": "panel-1"}) assert ctrl.is_tree_complete("panel-1") is True + + +# ── Subscription pacing and stuck-device healing (GH #97) ──────────────── + + +def _make_paced_controller(root_device_id="panel-1", **kwargs): + """A Controller on a mock transport that records calls and delivers nothing by itself.""" + client = MagicMock() + ctrl = Controller(mqttc=client, root_device_id=root_device_id, **kwargs) + return ctrl, client + + +def _subscribed_devices(client): + """Device ids in first-subscribe order, from every subscribe call so far.""" + seen = [] + for c in client.subscribe.call_args_list: + device_id = c[0][0].split("/")[2] + if device_id not in seen: + seen.append(device_id) + return seen + + +def _child_desc(child_id, parent="panel-1"): + return {"homie": "5.0", "root": "panel-1", "parent": parent} + + +def _announce_root(ctrl, children): + ctrl.start_discovery() + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": children}) + _push_state(ctrl, "panel-1", "ready") + + +def _deliver(ctrl, child_id): + _push_state(ctrl, child_id, "ready") + _push_description(ctrl, child_id, _child_desc(child_id)) + + +class TestSubscriptionPacing: + def test_default_batch_bounds_the_fan_out(self): + ctrl, client = _make_paced_controller() + children = [f"c-{i:02d}" for i in range(20)] + _announce_root(ctrl, children) + + # The root's slot frees once it has both $state and $description, so + # exactly eight children are subscribed, in declared order. + assert _subscribed_devices(client) == ["panel-1"] + children[:8] + for child in children: + assert child in ctrl.devices # every declared child is registered, subscribed or not + + def test_next_pending_child_starts_when_one_has_state_and_description(self): + ctrl, client = _make_paced_controller(subscription_batch_size=2) + _announce_root(ctrl, ["a", "b", "c", "d"]) + assert _subscribed_devices(client) == ["panel-1", "a", "b"] + + _push_state(ctrl, "a", "ready") + assert _subscribed_devices(client) == ["panel-1", "a", "b"] # $state alone is not enough + + _push_description(ctrl, "a", _child_desc("a")) + assert _subscribed_devices(client) == ["panel-1", "a", "b", "c"] + + # Description first, then state, also completes a device. + _push_description(ctrl, "b", _child_desc("b")) + _push_state(ctrl, "b", "ready") + assert _subscribed_devices(client) == ["panel-1", "a", "b", "c", "d"] + + def test_each_child_gets_all_four_filters(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b"]) + _deliver(ctrl, "a") + topics = {c[0][0] for c in client.subscribe.call_args_list} + assert _filters_for("a") <= topics + assert _filters_for("b") <= topics + + def test_unbounded_subscribes_every_child_at_once(self): + ctrl, client = _make_paced_controller(subscription_batch_size=None) + children = [f"c-{i:02d}" for i in range(20)] + _announce_root(ctrl, children) + assert _subscribed_devices(client) == ["panel-1"] + children + + def test_zero_batch_means_unbounded(self): + ctrl, client = _make_paced_controller(subscription_batch_size=0) + _announce_root(ctrl, ["a", "b", "c"]) + assert _subscribed_devices(client) == ["panel-1", "a", "b", "c"] + + def test_negative_batch_rejected(self): + with pytest.raises(ValueError): + Controller(mqttc=MagicMock(), subscription_batch_size=-1) + + def test_removed_pending_child_is_never_subscribed_or_unsubscribed(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b"]) + assert _subscribed_devices(client) == ["panel-1", "a"] + + # The root drops "b" (still pending) through an init -> ready reconfiguration. + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["a"]}) + _push_state(ctrl, "panel-1", "ready") + _deliver(ctrl, "a") + + assert "b" not in ctrl.devices + assert "b" not in _subscribed_devices(client) + assert not [c for c in client.unsubscribe.call_args_list if "/b/" in c[0][0]] + + def test_removed_inflight_child_frees_its_slot(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b"]) + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["b"]}) + _push_state(ctrl, "panel-1", "ready") + + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("a") + assert _subscribed_devices(client) == ["panel-1", "a", "b"] + + def test_resync_drops_pending_and_rewalk_is_paced(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b", "c"]) + ctrl.resync() + client.subscribe.reset_mock() + + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["a", "b", "c"]}) + _push_state(ctrl, "panel-1", "ready") + assert _subscribed_devices(client) == ["a"] + + def test_stop_clears_pacing_state(self): + ctrl, _ = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b", "c"]) + ctrl.stop() + assert ctrl._watches == {} + assert ctrl._pending_subscriptions == {} + + def test_wildcard_discovery_is_paced(self): + client = MagicMock() + ctrl = Controller(mqttc=client, subscription_batch_size=2) + ctrl.start_discovery() + client.subscribe.reset_mock() + for d in ("d0", "d1", "d2", "d3"): + _push_state(ctrl, d, "ready") + + assert _subscribed_devices(client) == ["d0", "d1"] + assert len(client.subscribe.call_args_list) == 6 # $description, +/+, +/+/$target each + + _push_description(ctrl, "d0", {"homie": "5.0"}) + assert _subscribed_devices(client) == ["d0", "d1", "d2"] + + def test_wildcard_device_removed_while_pending_is_dropped(self): + client = MagicMock() + ctrl = Controller(mqttc=client, subscription_batch_size=1) + ctrl.start_discovery() + client.subscribe.reset_mock() + _push_state(ctrl, "d0", "ready") + _push_state(ctrl, "d1", "ready") + _push_state(ctrl, "d1", "") # retracted while pending + _push_description(ctrl, "d0", {"homie": "5.0"}) + assert _subscribed_devices(client) == ["d0"] + + +class TestStuckDeviceHealing: + def test_withheld_child_is_resubscribed(self, caplog): + ctrl, client = _make_paced_controller(subscription_batch_size=2) + _announce_root(ctrl, ["a", "b", "c"]) + _deliver(ctrl, "a") + _deliver(ctrl, "c") + # "b" never receives its retained $state/$description. + client.reset_mock() + + with caplog.at_level("WARNING", logger="homie"): + assert ctrl.check_stuck_children(timeout=0) == ["b"] + + names = [c[0] for c in client.method_calls] + assert names == ["unsubscribe"] * 4 + ["subscribe"] * 4 # unsubscribe first, then resubscribe + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("b") + assert {c[0][0] for c in client.subscribe.call_args_list} == _filters_for("b") + assert "reason=stuckDeviceResubscribe,deviceID=b,missing=$state+$description,attempt=1/3" in caplog.text + + def test_resubscribe_reuses_the_device_callbacks(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a"]) + client.reset_mock() + ctrl.check_stuck_children(timeout=0) + + callbacks = {c[0][0]: c[1]["param"] for c in client.subscribe.call_args_list} + base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/a" + callbacks[f"{base}/$state"](f"{base}/$state", b"ready") + callbacks[f"{base}/$description"](f"{base}/$description", json.dumps(_child_desc("a")).encode()) + assert ctrl.devices["a"].state == "ready" + assert ctrl.devices["a"].description is not None + assert ctrl.check_stuck_children(timeout=0) == [] + + def test_only_the_missing_attribute_is_reported(self, caplog): + ctrl, _ = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a"]) + _push_state(ctrl, "a", "ready") + with caplog.at_level("WARNING", logger="homie"): + ctrl.check_stuck_children(timeout=0) + assert "deviceID=a,missing=$description,attempt=1/3" in caplog.text + + def test_not_stuck_before_the_timeout(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a"]) + client.reset_mock() + assert ctrl.check_stuck_children(timeout=60) == [] + client.unsubscribe.assert_not_called() + + def test_stuck_child_releases_its_slot(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b"]) + assert _subscribed_devices(client) == ["panel-1", "a"] + + assert ctrl.check_stuck_children(timeout=0) == ["a"] + assert _subscribed_devices(client) == ["panel-1", "a", "b"] + + def test_retry_bound(self, caplog): + ctrl, client = _make_paced_controller(subscription_batch_size=1, max_resubscribe_attempts=2) + _announce_root(ctrl, ["a"]) + + with caplog.at_level("WARNING", logger="homie"): + assert ctrl.check_stuck_children(timeout=0) == ["a"] + assert ctrl.check_stuck_children(timeout=0) == ["a"] + assert ctrl.check_stuck_children(timeout=0) == [] + assert ctrl.check_stuck_children(timeout=0) == [] + + assert "reason=stuckDeviceGaveUp,deviceID=a,missing=$state+$description,attempts=2" in caplog.text + assert caplog.text.count("reason=stuckDeviceGaveUp") == 1 + assert len(client.unsubscribe.call_args_list) == 8 + # Given up, not unsubscribed: a device that appears later is still discovered. + _deliver(ctrl, "a") + assert ctrl.devices["a"].description is not None + + def test_zero_attempts_only_logs(self, caplog): + ctrl, client = _make_paced_controller(subscription_batch_size=1, max_resubscribe_attempts=0) + _announce_root(ctrl, ["a"]) + with caplog.at_level("WARNING", logger="homie"): + assert ctrl.check_stuck_children(timeout=0) == [] + client.unsubscribe.assert_not_called() + assert "reason=stuckDeviceGaveUp,deviceID=a" in caplog.text + + def test_default_timeout_comes_from_the_constructor(self): + ctrl, _ = _make_paced_controller(subscription_batch_size=1, stuck_device_timeout=0) + _announce_root(ctrl, ["a"]) + assert ctrl.check_stuck_children() == ["a"] + + def test_no_default_timeout_needs_an_explicit_one(self): + ctrl, _ = _make_paced_controller(subscription_batch_size=1, stuck_device_timeout=None) + _announce_root(ctrl, ["a"]) + assert ctrl.check_stuck_children() == [] + assert ctrl.check_stuck_children(timeout=0) == ["a"] + + def test_message_handling_runs_the_check(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1, stuck_device_timeout=0) + _announce_root(ctrl, ["a"]) + client.reset_mock() + + # Any inbound message (here a root property value) drives the heal. + ctrl._on_property_message("panel-1", f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-1/n/p", b"1") + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("a") + + def test_message_handling_check_is_rate_limited(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) # default timeout + _announce_root(ctrl, ["a"]) + with patch.object(ctrl, "check_stuck_children") as check: + for _ in range(100): + ctrl._on_property_message( + "panel-1", f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-1/n/p", b"1" + ) + check.assert_not_called() # under a second since construction + + def test_disabled_timeout_skips_the_message_check(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1, stuck_device_timeout=None) + _announce_root(ctrl, ["a"]) + with patch.object(ctrl, "check_stuck_children") as check: + ctrl._on_property_message("panel-1", f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-1/n/p", b"1") + check.assert_not_called() + + def test_wildcard_resubscribe_leaves_the_state_wildcard_alone(self): + client = MagicMock() + ctrl = Controller(mqttc=client) + ctrl.start_discovery() + _push_state(ctrl, "d0", "ready") + client.reset_mock() + + assert ctrl.check_stuck_children(timeout=0) == ["d0"] + base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/d0" + assert {c[0][0] for c in client.unsubscribe.call_args_list} == { + f"{base}/$description", + f"{base}/+/+", + f"{base}/+/+/$target", + } + + def test_stuck_root_is_healed(self): + ctrl, client = _make_paced_controller() + ctrl.start_discovery() + client.reset_mock() + assert ctrl.check_stuck_children(timeout=0) == ["panel-1"] + assert {c[0][0] for c in client.subscribe.call_args_list} == _filters_for("panel-1") + + def test_root_is_watched_after_resync(self): + ctrl, _ = _make_paced_controller() + ctrl.start_discovery() + ctrl.resync() + assert ctrl.check_stuck_children(timeout=0) == ["panel-1"] From 0ce750e1b50908bbe6403fd98a37a1b4bb4a5233 Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 13:05:00 -0700 Subject: [PATCH 2/7] test: real-broker regression for busy-tree discovery; mosquitto in CI (#97) Starts mosquitto with default limits on a free 127.0.0.1 port, seeds a retained tree (root plus 30 children, each with 60 property values, $state and $description) with a raw paho publisher, and asserts a tree-rooted Controller describes every child. Against main's src 17 of 30 children are described; with paced subscriptions all 30 are, in under a second. Skipped when no mosquitto binary is found. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- .github/workflows/test.yml | 3 + tests/test_controller_real_broker.py | 156 +++++++++++++++++++++++++++ 2 files changed, 159 insertions(+) create mode 100644 tests/test_controller_real_broker.py diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 2df79bd..bf5d380 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -29,5 +29,8 @@ jobs: - uses: actions/setup-python@a309ff8b426b58ec0e2a45f0f869d46889d02405 # v6.2.0 with: python-version: ${{ matrix.python-version }} + # mosquitto for tests/test_controller_real_broker.py (GH #97), which starts its + # own broker on a free port and is skipped when the binary is absent. + - run: sudo apt-get update && sudo apt-get install -y mosquitto - run: pip install -e '.[dev]' - run: python -m pytest -q diff --git a/tests/test_controller_real_broker.py b/tests/test_controller_real_broker.py new file mode 100644 index 0000000..f81fdf4 --- /dev/null +++ b/tests/test_controller_real_broker.py @@ -0,0 +1,156 @@ +"""Real-broker regression test for tree-rooted discovery on a busy tree (GH #97). + +Subscribing to every child of a large tree at once makes the broker queue every +matching retained message for one client. Past mosquitto's default per-client +limits (``max_inflight_messages`` 20, ``max_queued_messages`` 1000) it drops the +rest, and retained messages are sent only at subscribe time, so the children +subscribed last never deliver ``$state`` or ``$description``. + +Skipped when no ``mosquitto`` binary is available. +""" + +import json +import os +import shutil +import socket +import subprocess +import time +import uuid + +import pytest + +paho = pytest.importorskip("paho.mqtt.client") + +from ebus_sdk.homie import EBUS_HOMIE_DOMAIN, EBUS_HOMIE_VERSION_MAJOR, Controller + + +def _find_mosquitto(): + for candidate in ("/opt/homebrew/sbin/mosquitto", "/usr/sbin/mosquitto", "/usr/local/sbin/mosquitto"): + if os.access(candidate, os.X_OK): + return candidate + return shutil.which("mosquitto") + + +MOSQUITTO = _find_mosquitto() + +pytestmark = pytest.mark.skipif(MOSQUITTO is None, reason="mosquitto binary not found") + +CHILDREN = 30 +PROPERTIES_PER_CHILD = 60 +NODES_PER_CHILD = 3 +ROOT_ID = "busy-root" + + +def _free_port(): + with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s: + s.bind(("127.0.0.1", 0)) + return s.getsockname()[1] + + +def _wait_for_port(port, proc, timeout=10.0): + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + if proc.poll() is not None: + raise RuntimeError(f"mosquitto exited early with code {proc.returncode}") + try: + with socket.create_connection(("127.0.0.1", port), timeout=0.2): + return + except OSError: + time.sleep(0.05) + raise RuntimeError("mosquitto did not start listening") + + +@pytest.fixture +def broker(tmp_path): + """A throwaway mosquitto with default limits on a free 127.0.0.1 port.""" + port = _free_port() + conf = tmp_path / "mosquitto.conf" + conf.write_text(f"listener {port} 127.0.0.1\nallow_anonymous true\npersistence false\n") + proc = subprocess.Popen( + [MOSQUITTO, "-c", str(conf)], + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + ) + try: + _wait_for_port(port, proc) + yield port + finally: + proc.terminate() + try: + proc.wait(timeout=5) + except subprocess.TimeoutExpired: + proc.kill() + proc.wait(timeout=5) + + +def _child_id(i): + return f"busy-child-{i:02d}" + + +def _description(device_id, children=None): + props_per_node = PROPERTIES_PER_CHILD // NODES_PER_CHILD + nodes = { + f"node-{n}": { + "name": f"Node {n}", + "properties": {f"p{p:02d}": {"name": f"P{p}", "datatype": "integer"} for p in range(props_per_node)}, + } + for n in range(NODES_PER_CHILD) + } + description = {"homie": "5.0", "version": 1, "name": device_id, "nodes": nodes} + if children is not None: + description["children"] = children + else: + description["root"] = ROOT_ID + description["parent"] = ROOT_ID + return description + + +def _seed_tree(port): + """Publish a retained tree with a raw paho client and wait until the broker has it.""" + client = paho.Client(paho.CallbackAPIVersion.VERSION2, client_id=f"seeder-{uuid.uuid4()}") + client.max_inflight_messages_set(1000) + client.connect("127.0.0.1", port) + client.loop_start() + infos = [] + base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}" + + def pub(topic, payload): + infos.append(client.publish(topic, payload, qos=1, retain=True)) + + try: + children = [_child_id(i) for i in range(CHILDREN)] + for child in children: + pub(f"{base}/{child}/$description", json.dumps(_description(child))) + for n in range(NODES_PER_CHILD): + for p in range(PROPERTIES_PER_CHILD // NODES_PER_CHILD): + pub(f"{base}/{child}/node-{n}/p{p:02d}", str(n * 100 + p)) + pub(f"{base}/{child}/$state", "ready") + pub(f"{base}/{ROOT_ID}/$description", json.dumps(_description(ROOT_ID, children=children))) + pub(f"{base}/{ROOT_ID}/$state", "ready") + for info in infos: + info.wait_for_publish(timeout=10) + finally: + client.loop_stop() + client.disconnect() + return children + + +def test_tree_rooted_controller_discovers_every_child_of_a_busy_tree(broker): + children = _seed_tree(broker) + + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}, root_device_id=ROOT_ID) + try: + ctrl.start_discovery() + deadline = time.monotonic() + 30.0 + described = set() + while time.monotonic() < deadline: + described = {c for c in children if (d := ctrl.get_device(c)) is not None and d.description is not None} + if len(described) == len(children): + break + time.sleep(0.1) + missing = sorted(set(children) - described) + assert not missing, f"{len(described)}/{len(children)} children described; missing {missing}" + for child in children: + assert ctrl.get_device(child).state == "ready" + finally: + ctrl.stop() From 7e9cea4375f54874837a4bcafab7937c5d4be005 Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 13:35:20 -0700 Subject: [PATCH 3/7] Controller: stage subscriptions so silent devices block no one; pace by values (#97) Review fixes for the paced-subscription work: - Subscribe each device's $state and $description at once and its property filters only after both arrive. A declared child that never publishes, or a leftover $state with no $description, now holds no batch slot, so discovery no longer stalls behind it on a quiet connection. - Hold a slot until the property burst drains: every declared retained value arrived, or the $description resubscribed behind the property filters arrived again. Bound a batch by subscription_batch_values (default 500) as well as by device count. - A stuck slot holder rejoins the end of the queue instead of being resubscribed at once, so healing stays within the batch. - Always unsubscribe a dropped descendant, unsubscribe a $state for an untracked device in tree-rooted mode, and undo a subscribe that lands after the device was dropped on another thread. The real-broker tests now assert every property value and cover 150 and 300 values per child, wildcard discovery, and silent or $state-only devices. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- CHANGELOG.md | 4 +- README.md | 8 +- src/ebus_sdk/homie.py | 357 +++++++++++++++------ tests/test_controller.py | 445 +++++++++++++++++++++------ tests/test_controller_real_broker.py | 179 +++++++---- 5 files changed, 733 insertions(+), 260 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 52b7850..dd68f44 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,12 +34,12 @@ Homie 5 compliance, phase 1: producer wire correctness ([#95](https://github.com - Encoders for `datetime` (`datetime`/`date` as ISO 8601, :132), `duration` (`timedelta` as `PTxHxMxS`, :137-144) and `color` (a component tuple in the first `format` color type, :118-123). These fell through to `str()`, which produced `2026-10-08 12:00:00+00:00`, `0:05:00` and `(255, 0, 0)`. - `Device.publish_alert(alert_id, message)`, `Device.clear_alert(alert_id)` and `Device.alerts()`. Alerts publish retained to `$alert/[alert ID]` (:517), are republished on reconnect, and are cleared by `delete()` (:289). - `Device.invalidate_description_cache()`, the `$description` counterpart of `Property.invalidate_publish_cache()`. `clear_retained_topic()` aimed at the device's own `$description` and `delete_all_from_mqtt()` call it, so a later `publish_description()` is no longer suppressed after the topic was cleared. -- `Controller(subscription_batch_size=8, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device whose filters have been subscribed for `timeout` seconds without its `$state` or `$description` arriving is unsubscribed and resubscribed, so the broker resends its retained messages, up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end. Message handling runs the check at most once a second; a consumer on a quiet connection, or driving its own event loop, can call it from a timer. `stuck_device_timeout=None` turns off the automatic check ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- `Controller(subscription_batch_size=8, subscription_batch_values=500, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device still lacking `$state` or `$description` after `timeout` seconds has those two filters unsubscribed and resubscribed, so the broker resends them; a device still holding a batch slot after `timeout` gives it up and rejoins the end of the queue. Each device is retried up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` or `reason=stuckDeviceRequeue` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end. Message handling runs the check at most once a second; a consumer on a quiet connection, or driving its own event loop, can call it from a timer. `stuck_device_timeout=None` turns off the automatic check ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ### Fixed - `delete()` followed by `stop()` re-created the deleted device as a bare `$state=disconnected` with no `$description` (:272, :288). After `delete()` the root's `stop()` announces nothing, flushes `delete()`'s retained clears and disconnects cleanly in either mode, and a reconnect's `refresh_tree()` republishes nothing. -- A tree-rooted `Controller` could miss the retained `$state` and `$description` of some children of a large tree for good. It subscribed to every child at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes at most `subscription_batch_size` devices (default 8) at a time and starts the next as each one's `$state` and `$description` arrive or it is declared stuck, in tree-rooted descendants and in wildcard discovery alike; all 30 are described. `subscription_batch_size=None` restores the unpaced fan-out. Descendants are subscribed in the order their parent's `$description` lists them ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- A `Controller` could miss retained `$state`, `$description` and property values of some devices for good. It subscribed to every device at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes each tree descendant's `$state` and `$description` (in wildcard discovery, its `$description`) as soon as the device is known, and its property filters once both have arrived, at most `subscription_batch_size` devices and `subscription_batch_values` retained values at a time. The next device starts when an earlier one's retained property values have all arrived, or when its `$description`, resubscribed behind its property filters, arrives again. A declared child that never publishes, or a leftover `$state` with no `$description`, holds no slot. All 30 children are described with every value at 60, 150 and 300 values per child. With the default pacing, a device's property values are no longer tracked until its `$description` arrives. `subscription_batch_size=None` restores the unpaced fan-out. The tree root and the single device of single-device mode are subscribed unpaced ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ## [0.24.0] — 2026-10-03 diff --git a/README.md b/README.md index f93c01e..ca8d589 100644 --- a/README.md +++ b/README.md @@ -303,18 +303,18 @@ subscribed or dropped on the parent's next init→ready transition. #### Paced subscriptions and stuck devices -A broker queues every retained message matching a new subscription for that one client and drops what exceeds its per-client limit (mosquitto: `max_queued_messages` 1000). Retained messages are sent only at subscribe time, so a device whose `$state` or `$description` was dropped is never discovered. The Controller therefore subscribes to at most `subscription_batch_size` devices at a time (default 8; tree-rooted descendants and wildcard-discovered devices) and subscribes the next as each one's `$state` and `$description` arrive. +A broker queues every retained message matching a new subscription for that one client and drops what exceeds its per-client limit (mosquitto: `max_queued_messages` 1000). Retained messages are sent only at subscribe time, so a device whose `$state`, `$description` or property values were dropped never receives them. The Controller therefore subscribes each device in two stages (tree-rooted descendants and wildcard-discovered devices). Its `$state` and `$description` are subscribed as soon as the device is known. Once both have arrived, its property filters are subscribed, at most `subscription_batch_size` devices (default 8) and `subscription_batch_values` retained values (default 500, counted from each `$description`) at a time. A device keeps its slot until every retained value its `$description` declares has arrived, or until its `$description`, resubscribed behind its property filters, arrives again. A device that never publishes holds no slot, so it delays no other device. -A device still lacking either after `stuck_device_timeout` seconds (default 10) gives up its slot and is unsubscribed and resubscribed, so the broker resends its retained messages, up to `max_resubscribe_attempts` times (default 3). Message handling runs this check at most once a second, so a controller that receives traffic heals without help. On a quiet connection, or under a caller-driven event loop, call it yourself: +A device still lacking `$state` or `$description` after `stuck_device_timeout` seconds (default 10) has those two filters unsubscribed and resubscribed, so the broker resends them. A device still holding a slot after that long gives it up and rejoins the end of the queue. Each is retried up to `max_resubscribe_attempts` times (default 3). Message handling runs this check at most once a second. On a connection that goes quiet, or under a caller-driven event loop, call it yourself: ```python controller = Controller(mqtt_cfg=cfg, root_device_id='panel-1', subscription_batch_size=8, stuck_device_timeout=10.0) ... -resubscribed = controller.check_stuck_children() # or check_stuck_children(timeout=30) +healed = controller.check_stuck_children() # or check_stuck_children(timeout=30) ``` -`subscription_batch_size=None` subscribes every device at once; `stuck_device_timeout=None` turns off the automatic check. +`subscription_batch_size=None` subscribes all of every device's filters at once; `subscription_batch_values=None` counts devices only; `stuck_device_timeout=None` turns off the automatic check. ## Module Structure diff --git a/src/ebus_sdk/homie.py b/src/ebus_sdk/homie.py index 20a3a5b..45baf91 100644 --- a/src/ebus_sdk/homie.py +++ b/src/ebus_sdk/homie.py @@ -64,7 +64,7 @@ class StrEnum(str, Enum): pass -from dataclasses import dataclass +from dataclasses import dataclass, field from fractions import Fraction from functools import partial from threading import RLock @@ -3547,9 +3547,24 @@ def get_node_properties(self, node_id: str) -> dict: # Controller subscription pacing and stuck-device healing (GH #97). Subscribing to many # devices at once makes the broker queue every matching retained message for this one # client; past its per-client limits (mosquitto: max_queued_messages 1000) it drops the -# excess, and retained messages are sent only at subscribe time, so a dropped $state or -# $description never arrives. +# excess, and retained messages are sent only at subscribe time, so a dropped message +# never arrives. +# +# Each device is subscribed in two stages. Stage one subscribes the device's $state and +# $description at once (at most two retained messages) and needs no batch slot, so a +# declared device that never publishes blocks nothing. Once both have arrived, stage two +# subscribes the property filters, which carry the bulk of the retained messages, in +# batches of at most subscription_batch_size devices and subscription_batch_values +# retained values (counted from each $description). A device holds its slot until its +# property burst has drained: either every retained property its $description declares +# has arrived, or the retained $description it resubscribes after its property filters +# arrives behind the burst. That marker relies on the broker sending one client's +# messages in order, as mosquitto does; MQTT guarantees order only within a topic, so on +# another broker the marker can free a slot early. CONTROLLER_SUBSCRIPTION_BATCH_SIZE = 8 +# Half of mosquitto's default max_queued_messages, leaving room for the $state and +# $description bursts and for live traffic. +CONTROLLER_SUBSCRIPTION_BATCH_VALUES = 500 CONTROLLER_STUCK_DEVICE_TIMEOUT = 10.0 CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS = 3 # Upper bound on how often message handling runs the opportunistic stuck check. @@ -3557,17 +3572,38 @@ def get_node_properties(self, node_id: str) -> dict: # Per-device topic filter suffixes. Wildcard discovery hears $state through its # broker-wide {domain}/5/+/$state filter, so a device found that way needs only the rest. _DEVICE_FILTERS = ("$state", "$description", "+/+", "+/+/$target") -_WILDCARD_DEVICE_FILTERS = ("$description", "+/+", "+/+/$target") +_ATTRIBUTE_FILTERS = ("$state", "$description") +_WILDCARD_ATTRIBUTE_FILTERS = ("$description",) +_PROPERTY_FILTERS = ("+/+", "+/+/$target") @dataclass class _SubscriptionWatch: - """A device whose filters are subscribed but whose $state or $description has not arrived.""" + """A subscribed device awaiting its retained messages. + + In stage one it awaits $state and $description; in stage two it holds a batch slot + until its property burst drains. + """ filters: tuple subscribed_at: float - holds_slot: bool attempts: int = 0 + expected_values: int = 0 + received_values: set = field(default_factory=set) + + +def _retained_property_count(description: Any) -> int: + """Properties a $description declares as retained (the Homie 5 default).""" + count = 0 + nodes = description.get("nodes") if isinstance(description, dict) else None + if not isinstance(nodes, dict): + return 0 + for node in nodes.values(): + properties = node.get("properties") if isinstance(node, dict) else None + if not isinstance(properties, dict): + continue + count += sum(1 for p in properties.values() if not isinstance(p, dict) or p.get("retained", True) is not False) + return count class Controller: @@ -3602,6 +3638,7 @@ def __init__( qos: int = EBUS_HOMIE_MQTT_QOS, mqttc: Optional[MqttControllerTransport] = None, subscription_batch_size: Optional[int] = CONTROLLER_SUBSCRIPTION_BATCH_SIZE, + subscription_batch_values: Optional[int] = CONTROLLER_SUBSCRIPTION_BATCH_VALUES, stuck_device_timeout: Optional[float] = CONTROLLER_STUCK_DEVICE_TIMEOUT, max_resubscribe_attempts: int = CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS, ): @@ -3633,20 +3670,26 @@ def __init__( Assistant consumer driving MQTT on its own loop). Drive discovery with start_discovery() once the client is connected. Default None: the SDK constructs, starts, and owns a client from mqtt_cfg. - subscription_batch_size: Most devices whose per-device subscriptions - may await their retained $state and $description at once (GH #97). - Further devices (tree descendants, or devices found by wildcard - discovery) wait in order and are subscribed as earlier ones finish - or are declared stuck, so the broker's per-client queue does not - overflow and drop retained messages. None or 0 subscribes every - device immediately. + subscription_batch_size: Most devices whose property filters may + await their retained values at once (GH #97). Every device's + $state and $description are subscribed as soon as it is known; + its property filters follow once both have arrived, in batches + of this many devices, the next starting as an earlier device's + retained property values finish arriving. This keeps the + broker's per-client queue from overflowing and dropping retained + messages. None or 0 subscribes all of a device's filters at once. + subscription_batch_values: Most retained property values the devices + in a batch may still be owed (GH #97), counted from each + device's $description. A device that would exceed it waits, + unless no other device is in flight. None counts devices only. stuck_device_timeout: Seconds a subscribed device may lack $state or - $description before it is declared stuck: it gives up its batch - slot and its filters are unsubscribed and resubscribed so the - broker resends its retained messages. Message handling runs this - check at most once a second; see check_stuck_children(). None - disables the automatic check. - max_resubscribe_attempts: Resubscribes per stuck device before it is + $description, or keep a batch slot, before it is declared stuck: + its $state and $description filters are unsubscribed and + resubscribed so the broker resends them, or it gives up its slot + and waits for another. Message handling runs this check at most + once a second; see check_stuck_children(). None disables the + automatic check. + max_resubscribe_attempts: Retries per stuck device before it is logged as unrecoverable and no longer checked. 0 only logs. """ if device_id is not None and root_device_id is not None: @@ -3687,14 +3730,21 @@ def __init__( raise ValueError("subscription_batch_size must be None or >= 0") if max_resubscribe_attempts < 0: raise ValueError("max_resubscribe_attempts must be >= 0") + if subscription_batch_values is not None and subscription_batch_values < 1: + raise ValueError("subscription_batch_values must be None or >= 1") self._subscription_batch_size = subscription_batch_size or None + self._subscription_batch_values = subscription_batch_values self._stuck_device_timeout = stuck_device_timeout self._max_resubscribe_attempts = max_resubscribe_attempts self._pacing_lock = threading.RLock() - # {device_id: _SubscriptionWatch}: subscribed, awaiting $state and $description. - self._watches: dict = {} - # {device_id: filters}, insertion-ordered: requested but not yet subscribed. + # Stage one, {device_id: _SubscriptionWatch}: awaiting $state and $description. + self._awaiting_attributes: dict = {} + # Stage two, {device_id: attempts}, insertion-ordered: waiting for a batch slot. self._pending_subscriptions: dict = {} + # Stage two, {device_id: _SubscriptionWatch}: holding a batch slot. + self._watches: dict = {} + # Devices whose $description was resubscribed behind their property filters. + self._description_markers: set = set() self._last_stuck_check = time.monotonic() # Callbacks @@ -3792,24 +3842,23 @@ def resync(self) -> None: (via ``MqttClient.from_config``), which an injected client bypasses. """ if self.is_tree_rooted: - # The re-walk re-requests every descendant, paced, so pending work from the - # previous connection is dropped. The root's filters were resubscribed by the + # The re-walk re-requests every descendant, so pacing work from the previous + # connection is dropped. The root's filters were resubscribed by the # transport; watch it so a root whose retained messages are lost also heals. with self._pacing_lock: self._pending_subscriptions.clear() - self._watches = { - self.root_device_id: _SubscriptionWatch(_DEVICE_FILTERS, time.monotonic(), holds_slot=True) - } + self._watches.clear() + self._description_markers.clear() + self._awaiting_attributes = {self.root_device_id: _SubscriptionWatch(_DEVICE_FILTERS, time.monotonic())} # Cold restart of tree-rooted bookkeeping. paho-mqtt's MqttClient # has already re-subscribed our root's four filters; retained # state/description will arrive momentarily and the state-edge - # handler will reconcile descendants from scratch. Wipe the + # handler will reconcile descendants from scratch. Replace the # in-memory device registry so the init→ready edge sees the # transition (the previous state would otherwise short-circuit it). - self.devices = {} + # One assignment, so another thread never sees a registry without the root. self._subscribed_children = {} - device = DiscoveredDevice(self.root_device_id, self.homie_domain) - self.devices[self.root_device_id] = device + self.devices = {self.root_device_id: DiscoveredDevice(self.root_device_id, self.homie_domain)} def start_discovery(self, homie_domain: Optional[str] = None) -> None: """ @@ -3836,7 +3885,7 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: # discovered via the parent's $description.children device = DiscoveredDevice(self.root_device_id, domain) self.devices[self.root_device_id] = device - self._request_subscription(self.root_device_id, _DEVICE_FILTERS) + self._request_subscription(self.root_device_id, paced=False) elif self.device_id: # Single-device mode: subscribe to exact topics, no wildcard # in the device-id position @@ -3844,7 +3893,7 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: # Pre-create the DiscoveredDevice entry device = DiscoveredDevice(self.device_id, domain) self.devices[self.device_id] = device - self._request_subscription(self.device_id, _DEVICE_FILTERS) + self._request_subscription(self.device_id, paced=False) else: # Wildcard discovery mode (original behavior) discovery_topic = f"{domain}/{EBUS_HOMIE_VERSION_MAJOR}/+/$state" @@ -3854,9 +3903,8 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: def _subscribe_filters(self, device_id: str, filters: tuple) -> None: """Subscribe the given per-device filter suffixes for device_id, in order. - Single-device and tree-rooted modes subscribe all four (_DEVICE_FILTERS). - Wildcard discovery already hears $state through {domain}/5/+/$state and - subscribes the other three (_WILDCARD_DEVICE_FILTERS). + Wildcard discovery already hears $state through {domain}/5/+/$state, so it + never subscribes a device's own $state filter. """ if not self.mqttc: return @@ -3879,81 +3927,139 @@ def _unsubscribe_filters(self, device_id: str, filters: tuple) -> None: # ── Subscription pacing and stuck-device healing (GH #97) ────────────── - def _slot_free_locked(self) -> bool: - if self._subscription_batch_size is None: - return True - in_use = sum(1 for w in self._watches.values() if w.holds_slot) - return in_use < self._subscription_batch_size + @property + def _paced(self) -> bool: + return self._subscription_batch_size is not None + + def _subscribe_tracked(self, device_id: str, filters: tuple) -> None: + """Subscribe, then undo it if the device was dropped meanwhile on another thread. + + A drop removes the device from the registry before it unsubscribes, so checking + the registry after subscribing leaves the filters unsubscribed whichever thread + finishes last. + """ + self._subscribe_filters(device_id, filters) + if device_id not in self.devices: + logger.info(f"reason=subscriptionUndoneDeviceDropped,deviceID={device_id}") + self._unsubscribe_filters(device_id, filters) + + def _request_subscription(self, device_id: str, paced: bool = True) -> None: + """Start stage one for a device: subscribe its $state and $description now. + + Unpaced (the tree root, the single device, or subscription_batch_size=None), + the property filters are subscribed at the same time and there is no stage two. + """ + wildcard = not (self.is_tree_rooted or self.device_id) + filters = _WILDCARD_ATTRIBUTE_FILTERS if wildcard else _ATTRIBUTE_FILTERS + if not (paced and self._paced): + filters = filters + _PROPERTY_FILTERS + with self._pacing_lock: + if ( + device_id in self._awaiting_attributes + or device_id in self._pending_subscriptions + or device_id in self._watches + ): + return + self._awaiting_attributes[device_id] = _SubscriptionWatch(filters, time.monotonic()) + self._subscribe_tracked(device_id, filters) def _take_pending_locked(self) -> list: - """Move pending devices into free batch slots; the caller subscribes them unlocked.""" + """Move pending devices into free batch slots; the caller subscribes them unlocked. + + A device starts when a slot is free and the retained values it declares fit in the + value budget beside those still owed to the devices in flight. With nothing in + flight it starts whatever its size. + """ started = [] - while self._pending_subscriptions and self._slot_free_locked(): + owed = sum(max(w.expected_values - len(w.received_values), 0) for w in self._watches.values()) + while self._pending_subscriptions and len(self._watches) < self._subscription_batch_size: device_id = next(iter(self._pending_subscriptions)) - filters = self._pending_subscriptions.pop(device_id) - self._watches[device_id] = _SubscriptionWatch(filters, time.monotonic(), holds_slot=True) - started.append((device_id, filters)) + device = self.devices.get(device_id) + if device is None: + del self._pending_subscriptions[device_id] + continue + expected = _retained_property_count(device.description) + budget = self._subscription_batch_values + if self._watches and budget is not None and owed + expected > budget: + break + attempts = self._pending_subscriptions.pop(device_id) + owed += expected + if expected: + self._watches[device_id] = _SubscriptionWatch( + _PROPERTY_FILTERS, time.monotonic(), attempts=attempts, expected_values=expected + ) + started.append((device_id, attempts)) return started def _start_subscriptions(self, started: list) -> None: - for device_id, filters in started: + """Subscribe each started device's property filters, then resubscribe its $description. + + The broker resends the retained $description behind the property burst, so its + arrival marks the burst as drained. + """ + for device_id, attempts in started: logger.info(f"reason=pacedSubscribe,deviceID={device_id},pending={len(self._pending_subscriptions)}") - self._subscribe_filters(device_id, filters) + if attempts: + self._unsubscribe_filters(device_id, _PROPERTY_FILTERS) + self._description_markers.add(device_id) + self._subscribe_tracked(device_id, _PROPERTY_FILTERS + ("$description",)) - def _request_subscription(self, device_id: str, filters: tuple) -> None: - """Subscribe a device's filters now if a batch slot is free, else queue it in order.""" + def _release_slot(self, device_id: str) -> None: + """A device's property burst has drained: free its slot for the next pending device.""" with self._pacing_lock: - if device_id in self._watches or device_id in self._pending_subscriptions: + if self._watches.pop(device_id, None) is None: return - self._pending_subscriptions[device_id] = filters started = self._take_pending_locked() - if device_id in self._pending_subscriptions: - logger.debug( - f"reason=subscriptionDeferred,deviceID={device_id},pending={len(self._pending_subscriptions)}" - ) self._start_subscriptions(started) def _note_device_progress(self, device_id: str) -> None: - """Stop watching a device once it has both $state and $description; free its slot.""" + """Finish stage one once a device has both $state and $description.""" device = self.devices.get(device_id) + if device is None or device.state is None or device.description is None: + return with self._pacing_lock: - if device_id not in self._watches: - return - if device is not None and (device.state is None or device.description is None): + watch = self._awaiting_attributes.pop(device_id, None) + if watch is None or _PROPERTY_FILTERS[0] in watch.filters: return - del self._watches[device_id] + self._pending_subscriptions[device_id] = 0 started = self._take_pending_locked() self._start_subscriptions(started) - def _forget_subscription(self, device_id: str) -> bool: - """Drop a device from pacing; True when it was still pending (never subscribed).""" + def _forget_subscription(self, device_id: str) -> None: + """Drop a device from pacing, freeing any batch slot it held.""" with self._pacing_lock: - was_pending = self._pending_subscriptions.pop(device_id, None) is not None + self._awaiting_attributes.pop(device_id, None) + self._pending_subscriptions.pop(device_id, None) self._watches.pop(device_id, None) - started = self._take_pending_locked() + self._description_markers.discard(device_id) + started = self._take_pending_locked() if self._paced else [] self._start_subscriptions(started) - return was_pending def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: - """Heal subscribed devices whose retained $state or $description never arrived (GH #97). - - A device counts as stuck when its filters have been subscribed for at - least ``timeout`` seconds (default: the constructor's - ``stuck_device_timeout``) and it still lacks ``$state`` or - ``$description``. A stuck device gives up its batch slot, so the next - pending device is subscribed, and its filters are unsubscribed and - resubscribed so the broker resends its retained messages. After - ``max_resubscribe_attempts`` resubscribes it is logged as unrecoverable - and no longer checked; its subscriptions stay in place, so a device - that appears later is still discovered. + """Heal subscribed devices whose retained messages have not arrived (GH #97). + + A device counts as stuck after ``timeout`` seconds (default: the + constructor's ``stuck_device_timeout``) in either of two cases: + + - It still lacks ``$state`` or ``$description``. Those two filters are + unsubscribed and resubscribed so the broker resends them. They hold no + batch slot, so a device that never publishes delays no other device. + - It still holds a batch slot because its property burst has not been + seen to drain. It gives up the slot and rejoins the end of the queue; + when its turn comes, its property filters are resubscribed, paced like + any other device. + + After ``max_resubscribe_attempts`` retries a device is logged as + unrecoverable and no longer checked; its subscriptions stay in place, + so a device that appears later is still discovered. Message handling calls this at most once a second when - ``stuck_device_timeout`` is set, so a controller receiving traffic heals - without help. On a quiet connection nothing arrives to trigger it: call - it from your own timer or event loop. It uses no threads and is safe to - call from any thread. + ``stuck_device_timeout`` is set. On a connection that goes quiet, + healing waits for the next message unless you call it from your own + timer or event loop. It uses no threads and is safe to call from any + thread. - Returns the ids of the devices resubscribed by this call. + Returns the ids of the devices resubscribed or requeued by this call. """ if timeout is None: timeout = self._stuck_device_timeout @@ -3961,24 +4067,23 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: return [] now = time.monotonic() resubscribe = [] + requeued = [] with self._pacing_lock: self._last_stuck_check = now - for device_id, watch in list(self._watches.items()): + for device_id, watch in list(self._awaiting_attributes.items()): if now - watch.subscribed_at < timeout: continue device = self.devices.get(device_id) if device is None: - del self._watches[device_id] + del self._awaiting_attributes[device_id] continue missing = [ name for name, v in (("$state", device.state), ("$description", device.description)) if v is None ] if not missing: - del self._watches[device_id] - continue - watch.holds_slot = False + continue # _note_device_progress finishes it if watch.attempts >= self._max_resubscribe_attempts: - del self._watches[device_id] + del self._awaiting_attributes[device_id] logger.error( f"reason=stuckDeviceGaveUp,deviceID={device_id},missing={'+'.join(missing)}," f"attempts={watch.attempts}" @@ -3987,7 +4092,20 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: watch.attempts += 1 watch.subscribed_at = now resubscribe.append((device_id, watch.filters, watch.attempts, missing)) - started = self._take_pending_locked() + for device_id, watch in list(self._watches.items()): + if now - watch.subscribed_at < timeout: + continue + del self._watches[device_id] + received = f"{len(watch.received_values)}/{watch.expected_values}" + if watch.attempts >= self._max_resubscribe_attempts: + logger.error( + f"reason=stuckDeviceGaveUp,deviceID={device_id},missing=properties," + f"received={received},attempts={watch.attempts}" + ) + continue + self._pending_subscriptions[device_id] = watch.attempts + 1 + requeued.append((device_id, watch.attempts + 1, received)) + started = self._take_pending_locked() if self._paced else [] for device_id, filters, attempt, missing in resubscribe: logger.warning( @@ -3995,14 +4113,19 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: f"attempt={attempt}/{self._max_resubscribe_attempts}" ) self._unsubscribe_filters(device_id, filters) - self._subscribe_filters(device_id, filters) + self._subscribe_tracked(device_id, filters) + for device_id, attempt, received in requeued: + logger.warning( + f"reason=stuckDeviceRequeue,deviceID={device_id},missing=properties,received={received}," + f"attempt={attempt}/{self._max_resubscribe_attempts}" + ) self._start_subscriptions(started) - return [device_id for device_id, *_ in resubscribe] + return [device_id for device_id, *_ in resubscribe] + [device_id for device_id, *_ in requeued] def _maybe_check_stuck(self) -> None: """Opportunistic, rate-limited stuck check run from message handling.""" timeout = self._stuck_device_timeout - if timeout is None or not self._watches: + if timeout is None or not (self._awaiting_attributes or self._watches): return if time.monotonic() - self._last_stuck_check < min(_STUCK_CHECK_INTERVAL, timeout): return @@ -4038,6 +4161,13 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: self._on_device_removed(removed_device) return + # Tree-rooted mode tracks only what the tree declares. A $state for anything + # else arrives on filters left over from a dropped device: remove them. + if self.is_tree_rooted and device_id not in self.devices: + logger.info(f"reason=untrackedDeviceUnsubscribed,deviceID={device_id}") + self._unsubscribe_filters(device_id, _DEVICE_FILTERS) + return + # New or existing device if device_id not in self.devices: # New device discovered (wildcard mode only; single-device mode @@ -4050,8 +4180,8 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: device.update_state(payload_str) self.devices[device_id] = device - # Subscribe to device's $description and all properties, paced - self._request_subscription(device_id, _WILDCARD_DEVICE_FILTERS) + # Subscribe to the device's $description now and its properties paced + self._request_subscription(device_id) if self._on_device_discovered: self._on_device_discovered(device) @@ -4095,9 +4225,10 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: def _reconcile_descendants(self, device_id: str) -> None: """Diff a device's announced children against what's subscribed (SDK-o1h). - Fired on the init→ready edge in tree-rooted mode. Added children get - full topic subscriptions (their own retained $state/$description then - cascade through this same handler, surfacing grandchildren). Removed + Fired on the init→ready edge in tree-rooted mode. Added children are + subscribed, their property filters paced (their own retained + $state/$description then cascade through this same handler, surfacing + grandchildren). Removed children are unsubscribed and dropped from the registry recursively. The state-edge gate (in _on_state_message) guarantees we only act when @@ -4124,7 +4255,7 @@ def _reconcile_descendants(self, device_id: str) -> None: if child_id not in self.devices: self.devices[child_id] = DiscoveredDevice(child_id, self.homie_domain) self._subscribed_children.setdefault(device_id, set()).add(child_id) - self._request_subscription(child_id, _DEVICE_FILTERS) + self._request_subscription(child_id) for child_id in removed: logger.info(f"reason=treeRootedRemoveDescendant,parentID={device_id},childID={child_id}") @@ -4158,9 +4289,10 @@ def _unsubscribe_and_drop(self, device_id: str) -> None: if device is None: return - # A device still waiting for a batch slot was never subscribed. - if not self._forget_subscription(device_id): - self._unsubscribe_filters(device_id, _DEVICE_FILTERS) + # Unconditionally: after a reconnect the transport holds filters subscribed in an + # earlier connection, whatever the pacing bookkeeping says. + self._forget_subscription(device_id) + self._unsubscribe_filters(device_id, _DEVICE_FILTERS) if self._on_device_removed: try: @@ -4181,6 +4313,20 @@ def _on_description_message(self, device_id: str, topic: str, payload: bytes) -> payload_str = payload.decode("utf-8") if isinstance(payload, bytes) else payload device = self.devices[device_id] + + # The $description resubscribed behind a device's property filters marks the + # end of its property burst. An unchanged one is only that marker. + if device_id in self._description_markers: + self._description_markers.discard(device_id) + self._release_slot(device_id) + try: + unchanged = device.description is not None and json.loads(payload_str) == device.description + except ValueError: + unchanged = False + if unchanged: + device.last_seen = time.time() + return + device.update_description(payload_str) logger.info(f"reason=descriptionReceived,deviceID={device_id}") @@ -4240,6 +4386,13 @@ def _on_property_message(self, device_id: str, topic: str, payload: bytes) -> No old_value = device.get_property(node_id, property_id) device.update_property(node_id, property_id, payload_str) + # Every retained value the $description declares has arrived: the burst is over. + watch = self._watches.get(device_id) + if watch is not None: + watch.received_values.add((node_id, property_id)) + if len(watch.received_values) >= watch.expected_values: + self._release_slot(device_id) + logger.debug( f"reason=propertyChanged,deviceID={device_id},node={node_id},property={property_id},value={payload_str}" ) @@ -4564,8 +4717,10 @@ def stop(self) -> None: self._subscribed_children.clear() self._tree_complete.clear() with self._pacing_lock: + self._awaiting_attributes.clear() self._watches.clear() self._pending_subscriptions.clear() + self._description_markers.clear() # Clear callback references to break reference cycles self._on_device_discovered = None self._on_device_state_changed = None diff --git a/tests/test_controller.py b/tests/test_controller.py index 30115ce..f87e2ea 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -844,10 +844,11 @@ def test_wildcard_per_device_subscribe_uses_custom_qos(self, mock_paho): ctrl.start_discovery() mock_client.subscribe.reset_mock() - # Discover a new device in wildcard mode + # Discover a new device in wildcard mode, then complete its stage one ctrl._on_state_message(f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-2/$state", b"ready") + _push_description(ctrl, "panel-2", {"homie": "5.0"}) - assert mock_client.subscribe.call_count == 3 + assert mock_client.subscribe.call_count == 4 # $description, then +/+, +/+/$target, $description for c in mock_client.subscribe.call_args_list: _, kwargs = c assert kwargs["qos"] == 1 @@ -884,6 +885,12 @@ def _filters_for(device_id): } +def _attribute_filters_for(device_id): + """The $state and $description filters a paced descendant is subscribed to first (GH #97).""" + base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}" + return {f"{base}/$state", f"{base}/$description"} + + class TestTreeRootedInit: def test_mutually_exclusive_with_device_id(self, mock_paho): with pytest.raises(ValueError): @@ -950,10 +957,10 @@ def test_root_with_children_subscribes_each(self, mock_paho): mock_client.subscribe.reset_mock() _push_state(ctrl, "panel-1", "ready") - # init→ready edge → reconcile → subscribe to each child's 4 filters + # init→ready edge → reconcile → subscribe to each child's $state and $description topics = {c[0][0] for c in mock_client.subscribe.call_args_list} - assert _filters_for("bess-1") <= topics - assert _filters_for("evse-1") <= topics + assert _attribute_filters_for("bess-1") <= topics + assert _attribute_filters_for("evse-1") <= topics assert "bess-1" in ctrl.devices assert "evse-1" in ctrl.devices @@ -1081,8 +1088,8 @@ def test_mid_flight_child_addition(self, mock_paho): assert "evse-1" in ctrl.devices topics = {c[0][0] for c in mock_client.subscribe.call_args_list} - # evse-1's 4 filters subscribed; bess-1's were not re-subscribed - assert _filters_for("evse-1") <= topics + # evse-1's $state and $description subscribed; bess-1's were not re-subscribed + assert _attribute_filters_for("evse-1") <= topics assert _filters_for("bess-1").isdisjoint(topics) @@ -1183,8 +1190,8 @@ def test_state_before_description_still_reconciles(self, mock_paho): assert "bess-1" in ctrl.devices assert "evse-1" in ctrl.devices topics = {c[0][0] for c in mock_client.subscribe.call_args_list} - assert _filters_for("bess-1") <= topics - assert _filters_for("evse-1") <= topics + assert _attribute_filters_for("bess-1") <= topics + assert _attribute_filters_for("evse-1") <= topics def test_description_only_acts_when_ready(self, mock_paho): """A $description arriving while $state=init must NOT reconcile.""" @@ -1235,7 +1242,7 @@ def test_grandchild_race_via_intermediate(self, mock_paho): assert "mid-1" in ctrl.devices topics = {c[0][0] for c in mock_client.subscribe.call_args_list} - assert _filters_for("mid-1") <= topics + assert _attribute_filters_for("mid-1") <= topics class TestTreeRootedReconnect: @@ -1553,18 +1560,36 @@ def _make_paced_controller(root_device_id="panel-1", **kwargs): return ctrl, client -def _subscribed_devices(client): - """Device ids in first-subscribe order, from every subscribe call so far.""" +def _topic(device_id, suffix): + return f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}/{suffix}" + + +def _property_subscribed(client): + """Device ids in the order their property filters were first subscribed.""" seen = [] for c in client.subscribe.call_args_list: - device_id = c[0][0].split("/")[2] - if device_id not in seen: - seen.append(device_id) + if c[0][0].endswith("/+/+"): + device_id = c[0][0].split("/")[2] + if device_id not in seen: + seen.append(device_id) return seen -def _child_desc(child_id, parent="panel-1"): - return {"homie": "5.0", "root": "panel-1", "parent": parent} +def _final_subscriptions(client): + """Topic filters left subscribed after replaying every subscribe and unsubscribe in order.""" + live = set() + for name, args, _ in client.method_calls: + if name == "subscribe": + live.add(args[0]) + elif name == "unsubscribe": + live.discard(args[0]) + return live + + +def _child_desc(child_id, props=2, parent="panel-1"): + """A child $description declaring `props` retained properties on node n.""" + properties = {f"p{i}": {"name": f"P{i}", "datatype": "integer"} for i in range(props)} + return {"homie": "5.0", "root": "panel-1", "parent": parent, "nodes": {"n": {"properties": properties}}} def _announce_root(ctrl, children): @@ -1573,128 +1598,302 @@ def _announce_root(ctrl, children): _push_state(ctrl, "panel-1", "ready") -def _deliver(ctrl, child_id): +def _deliver_attributes(ctrl, child_id, props=2): _push_state(ctrl, child_id, "ready") - _push_description(ctrl, child_id, _child_desc(child_id)) + _push_description(ctrl, child_id, _child_desc(child_id, props)) + + +def _deliver_properties(ctrl, child_id, props=2): + for i in range(props): + ctrl._on_property_message(child_id, _topic(child_id, f"n/p{i}"), b"1") + + +def _deliver(ctrl, child_id, props=2): + _deliver_attributes(ctrl, child_id, props) + _deliver_properties(ctrl, child_id, props) class TestSubscriptionPacing: - def test_default_batch_bounds_the_fan_out(self): + def test_every_child_gets_state_and_description_at_once(self): ctrl, client = _make_paced_controller() children = [f"c-{i:02d}" for i in range(20)] _announce_root(ctrl, children) - # The root's slot frees once it has both $state and $description, so - # exactly eight children are subscribed, in declared order. - assert _subscribed_devices(client) == ["panel-1"] + children[:8] + topics = {c[0][0] for c in client.subscribe.call_args_list} + for child in children: + assert _attribute_filters_for(child) <= topics + assert child in ctrl.devices + assert _property_subscribed(client) == ["panel-1"] # the root is subscribed unpaced + + def test_default_batch_bounds_the_property_fan_out(self): + ctrl, client = _make_paced_controller() + children = [f"c-{i:02d}" for i in range(20)] + _announce_root(ctrl, children) for child in children: - assert child in ctrl.devices # every declared child is registered, subscribed or not + _deliver_attributes(ctrl, child) - def test_next_pending_child_starts_when_one_has_state_and_description(self): + assert _property_subscribed(client) == ["panel-1"] + children[:8] + + def test_slot_frees_when_every_retained_value_arrives(self): ctrl, client = _make_paced_controller(subscription_batch_size=2) - _announce_root(ctrl, ["a", "b", "c", "d"]) - assert _subscribed_devices(client) == ["panel-1", "a", "b"] + _announce_root(ctrl, ["a", "b", "c"]) + for child in ("a", "b", "c"): + _deliver_attributes(ctrl, child) + assert _property_subscribed(client) == ["panel-1", "a", "b"] - _push_state(ctrl, "a", "ready") - assert _subscribed_devices(client) == ["panel-1", "a", "b"] # $state alone is not enough + ctrl._on_property_message("a", _topic("a", "n/p0"), b"1") + assert _property_subscribed(client) == ["panel-1", "a", "b"] # one of two values + ctrl._on_property_message("a", _topic("a", "n/p1"), b"1") + assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] + + def test_description_resubscribed_behind_the_property_filters(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a"]) + _deliver_attributes(ctrl, "a") + a_topics = [c[0][0] for c in client.subscribe.call_args_list if "/a/" in c[0][0]] + assert a_topics == [ + _topic("a", "$state"), + _topic("a", "$description"), + _topic("a", "+/+"), + _topic("a", "+/+/$target"), + _topic("a", "$description"), + ] + + def test_resent_description_frees_the_slot_without_a_second_callback(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + received = [] + ctrl.set_on_description_received_callback(lambda d: received.append(d.device_id)) + _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") + assert _property_subscribed(client) == ["panel-1", "a"] + # a has no property values at all; the resent $description marks its burst as over. _push_description(ctrl, "a", _child_desc("a")) - assert _subscribed_devices(client) == ["panel-1", "a", "b", "c"] + assert _property_subscribed(client) == ["panel-1", "a", "b"] + assert received.count("a") == 1 - # Description first, then state, also completes a device. - _push_description(ctrl, "b", _child_desc("b")) - _push_state(ctrl, "b", "ready") - assert _subscribed_devices(client) == ["panel-1", "a", "b", "c", "d"] + def test_changed_description_in_the_marker_slot_is_processed(self): + ctrl, _ = _make_paced_controller(subscription_batch_size=1) + received = [] + ctrl.set_on_description_received_callback(lambda d: received.append(d.device_id)) + _announce_root(ctrl, ["a"]) + _deliver_attributes(ctrl, "a") + _push_description(ctrl, "a", _child_desc("a", props=3)) + assert received.count("a") == 2 + assert len(ctrl.devices["a"].description["nodes"]["n"]["properties"]) == 3 + + def test_value_budget_bounds_the_batch(self): + ctrl, client = _make_paced_controller(subscription_batch_size=8, subscription_batch_values=5) + _announce_root(ctrl, ["a", "b", "c"]) + for child in ("a", "b", "c"): + _deliver_attributes(ctrl, child, props=3) + assert _property_subscribed(client) == ["panel-1", "a"] # 3 + 3 owed would exceed 5 + + _deliver_properties(ctrl, "a", props=3) + assert _property_subscribed(client) == ["panel-1", "a", "b"] # b fits; b and c would not + _deliver_properties(ctrl, "b", props=3) + assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] + + def test_device_over_the_value_budget_starts_alone(self): + ctrl, client = _make_paced_controller(subscription_batch_values=5) + _announce_root(ctrl, ["big", "small"]) + _deliver_attributes(ctrl, "big", props=9) + _deliver_attributes(ctrl, "small", props=1) + assert _property_subscribed(client) == ["panel-1", "big"] + _deliver_properties(ctrl, "big", props=9) + assert _property_subscribed(client) == ["panel-1", "big", "small"] + + def test_no_value_budget_counts_devices_only(self): + ctrl, client = _make_paced_controller(subscription_batch_size=3, subscription_batch_values=None) + _announce_root(ctrl, ["a", "b", "c", "d"]) + for child in ("a", "b", "c", "d"): + _deliver_attributes(ctrl, child, props=1000) + assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] - def test_each_child_gets_all_four_filters(self): + def test_non_retained_properties_are_not_owed(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) _announce_root(ctrl, ["a", "b"]) - _deliver(ctrl, "a") - topics = {c[0][0] for c in client.subscribe.call_args_list} - assert _filters_for("a") <= topics - assert _filters_for("b") <= topics + desc = _child_desc("a", props=2) + desc["nodes"]["n"]["properties"]["p1"]["retained"] = False + _push_state(ctrl, "a", "ready") + _push_description(ctrl, "a", desc) + _deliver_attributes(ctrl, "b") + ctrl._on_property_message("a", _topic("a", "n/p0"), b"1") + assert _property_subscribed(client) == ["panel-1", "a", "b"] - def test_unbounded_subscribes_every_child_at_once(self): + @pytest.mark.parametrize("values", [0, -1]) + def test_value_budget_below_one_rejected(self, values): + with pytest.raises(ValueError): + Controller(mqttc=MagicMock(), subscription_batch_values=values) + + def test_device_with_no_retained_properties_holds_no_slot(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b", "c"]) + _deliver_attributes(ctrl, "a", props=0) + _deliver_attributes(ctrl, "b", props=0) + _deliver_attributes(ctrl, "c") + assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] + + def test_silent_children_block_no_one(self): + """Declared children that never publish take no batch slot, with no traffic and no heal call.""" + ctrl, client = _make_paced_controller(subscription_batch_size=2) + _announce_root(ctrl, ["x", "y", "z", "a", "b"]) # x, y, z never publish + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") + assert _property_subscribed(client) == ["panel-1", "a", "b"] + + def test_wildcard_devices_without_description_block_no_one(self): + client = MagicMock() + ctrl = Controller(mqttc=client, subscription_batch_size=2) + ctrl.start_discovery() + for d in ("dead-0", "dead-1", "dead-2"): + _push_state(ctrl, d, "lost") # retained $state left behind, no $description + _push_state(ctrl, "live", "ready") + _push_description(ctrl, "live", {"homie": "5.0", "nodes": {"n": {"properties": {"p": {}}}}}) + assert _property_subscribed(client) == ["live"] + + def test_wildcard_discovery_is_paced(self): + client = MagicMock() + ctrl = Controller(mqttc=client, subscription_batch_size=2) + ctrl.start_discovery() + client.subscribe.reset_mock() + desc = {"homie": "5.0", "nodes": {"n": {"properties": {"p": {}}}}} + for d in ("d0", "d1", "d2", "d3"): + _push_state(ctrl, d, "ready") + assert [c[0][0] for c in client.subscribe.call_args_list] == [ + _topic(d, "$description") for d in ("d0", "d1", "d2", "d3") + ] + for d in ("d0", "d1", "d2", "d3"): + _push_description(ctrl, d, desc) + assert _property_subscribed(client) == ["d0", "d1"] + + ctrl._on_property_message("d0", _topic("d0", "n/p"), b"1") + assert _property_subscribed(client) == ["d0", "d1", "d2"] + + def test_unbounded_subscribes_every_filter_at_once(self): ctrl, client = _make_paced_controller(subscription_batch_size=None) children = [f"c-{i:02d}" for i in range(20)] _announce_root(ctrl, children) - assert _subscribed_devices(client) == ["panel-1"] + children + topics = {c[0][0] for c in client.subscribe.call_args_list} + for child in children: + assert _filters_for(child) <= topics def test_zero_batch_means_unbounded(self): ctrl, client = _make_paced_controller(subscription_batch_size=0) _announce_root(ctrl, ["a", "b", "c"]) - assert _subscribed_devices(client) == ["panel-1", "a", "b", "c"] + assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] def test_negative_batch_rejected(self): with pytest.raises(ValueError): Controller(mqttc=MagicMock(), subscription_batch_size=-1) - def test_removed_pending_child_is_never_subscribed_or_unsubscribed(self): + def test_removed_pending_child_is_unsubscribed(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) _announce_root(ctrl, ["a", "b"]) - assert _subscribed_devices(client) == ["panel-1", "a"] + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") # waits for a's slot - # The root drops "b" (still pending) through an init -> ready reconfiguration. _push_state(ctrl, "panel-1", "init") _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["a"]}) _push_state(ctrl, "panel-1", "ready") - _deliver(ctrl, "a") assert "b" not in ctrl.devices - assert "b" not in _subscribed_devices(client) - assert not [c for c in client.unsubscribe.call_args_list if "/b/" in c[0][0]] + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("b") + assert _property_subscribed(client) == ["panel-1", "a"] def test_removed_inflight_child_frees_its_slot(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") _push_state(ctrl, "panel-1", "init") _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["b"]}) _push_state(ctrl, "panel-1", "ready") assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("a") - assert _subscribed_devices(client) == ["panel-1", "a", "b"] + assert _property_subscribed(client) == ["panel-1", "a", "b"] + + def test_child_dropped_after_resync_is_unsubscribed_and_stays_gone(self): + """A child subscribed before a reconnect keeps live filters in the transport, even + while the re-walk has it pending; dropping it must unsubscribe them.""" + ctrl, client = _make_paced_controller(subscription_batch_size=1) + discovered = [] + ctrl.set_on_device_discovered_callback(lambda d: discovered.append(d.device_id)) + _announce_root(ctrl, ["a", "b"]) + _deliver(ctrl, "a") + _deliver(ctrl, "b") + + ctrl.resync() + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["a", "b"]}) + _push_state(ctrl, "panel-1", "ready") + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") + assert "b" in ctrl._pending_subscriptions + client.reset_mock() + discovered.clear() + + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["a"]}) + _push_state(ctrl, "panel-1", "ready") + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("b") + + _push_state(ctrl, "b", "ready") # a late retained message on a filter the broker had queued + assert "b" not in ctrl.devices + assert discovered == [] + assert "b" not in ctrl._pending_subscriptions - def test_resync_drops_pending_and_rewalk_is_paced(self): + def test_untracked_state_in_tree_mode_is_unsubscribed_not_discovered(self): + ctrl, client = _make_paced_controller() + discovered = [] + ctrl.set_on_device_discovered_callback(lambda d: discovered.append(d.device_id)) + _announce_root(ctrl, []) + client.reset_mock() + discovered.clear() + _push_state(ctrl, "ghost", "ready") + assert "ghost" not in ctrl.devices + assert discovered == [] + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("ghost") + client.subscribe.assert_not_called() + + def test_resync_drops_pacing_state_and_rewalk_is_paced(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) _announce_root(ctrl, ["a", "b", "c"]) + for child in ("a", "b", "c"): + _deliver_attributes(ctrl, child) ctrl.resync() + assert ctrl._pending_subscriptions == {} + assert ctrl._watches == {} client.subscribe.reset_mock() _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["a", "b", "c"]}) _push_state(ctrl, "panel-1", "ready") - assert _subscribed_devices(client) == ["a"] + for child in ("a", "b", "c"): + _deliver_attributes(ctrl, child) + assert _property_subscribed(client) == ["a"] def test_stop_clears_pacing_state(self): ctrl, _ = _make_paced_controller(subscription_batch_size=1) _announce_root(ctrl, ["a", "b", "c"]) + for child in ("a", "b"): + _deliver_attributes(ctrl, child) ctrl.stop() + assert ctrl._awaiting_attributes == {} assert ctrl._watches == {} assert ctrl._pending_subscriptions == {} - - def test_wildcard_discovery_is_paced(self): - client = MagicMock() - ctrl = Controller(mqttc=client, subscription_batch_size=2) - ctrl.start_discovery() - client.subscribe.reset_mock() - for d in ("d0", "d1", "d2", "d3"): - _push_state(ctrl, d, "ready") - - assert _subscribed_devices(client) == ["d0", "d1"] - assert len(client.subscribe.call_args_list) == 6 # $description, +/+, +/+/$target each - - _push_description(ctrl, "d0", {"homie": "5.0"}) - assert _subscribed_devices(client) == ["d0", "d1", "d2"] + assert ctrl._description_markers == set() def test_wildcard_device_removed_while_pending_is_dropped(self): client = MagicMock() ctrl = Controller(mqttc=client, subscription_batch_size=1) ctrl.start_discovery() - client.subscribe.reset_mock() - _push_state(ctrl, "d0", "ready") - _push_state(ctrl, "d1", "ready") + desc = {"homie": "5.0", "nodes": {"n": {"properties": {"p": {}}}}} + for d in ("d0", "d1"): + _push_state(ctrl, d, "ready") + _push_description(ctrl, d, desc) _push_state(ctrl, "d1", "") # retracted while pending - _push_description(ctrl, "d0", {"homie": "5.0"}) - assert _subscribed_devices(client) == ["d0"] + ctrl._on_property_message("d0", _topic("d0", "n/p"), b"1") + assert _property_subscribed(client) == ["d0"] class TestStuckDeviceHealing: @@ -1710,9 +1909,9 @@ def test_withheld_child_is_resubscribed(self, caplog): assert ctrl.check_stuck_children(timeout=0) == ["b"] names = [c[0] for c in client.method_calls] - assert names == ["unsubscribe"] * 4 + ["subscribe"] * 4 # unsubscribe first, then resubscribe - assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("b") - assert {c[0][0] for c in client.subscribe.call_args_list} == _filters_for("b") + assert names == ["unsubscribe"] * 2 + ["subscribe"] * 2 # unsubscribe first, then resubscribe + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _attribute_filters_for("b") + assert {c[0][0] for c in client.subscribe.call_args_list} == _attribute_filters_for("b") assert "reason=stuckDeviceResubscribe,deviceID=b,missing=$state+$description,attempt=1/3" in caplog.text def test_resubscribe_reuses_the_device_callbacks(self): @@ -1722,12 +1921,11 @@ def test_resubscribe_reuses_the_device_callbacks(self): ctrl.check_stuck_children(timeout=0) callbacks = {c[0][0]: c[1]["param"] for c in client.subscribe.call_args_list} - base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/a" - callbacks[f"{base}/$state"](f"{base}/$state", b"ready") - callbacks[f"{base}/$description"](f"{base}/$description", json.dumps(_child_desc("a")).encode()) + callbacks[_topic("a", "$state")](_topic("a", "$state"), b"ready") + callbacks[_topic("a", "$description")](_topic("a", "$description"), json.dumps(_child_desc("a")).encode()) assert ctrl.devices["a"].state == "ready" assert ctrl.devices["a"].description is not None - assert ctrl.check_stuck_children(timeout=0) == [] + assert "a" not in ctrl._awaiting_attributes def test_only_the_missing_attribute_is_reported(self, caplog): ctrl, _ = _make_paced_controller(subscription_batch_size=1) @@ -1739,19 +1937,12 @@ def test_only_the_missing_attribute_is_reported(self, caplog): def test_not_stuck_before_the_timeout(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) - _announce_root(ctrl, ["a"]) + _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "b") client.reset_mock() assert ctrl.check_stuck_children(timeout=60) == [] client.unsubscribe.assert_not_called() - def test_stuck_child_releases_its_slot(self): - ctrl, client = _make_paced_controller(subscription_batch_size=1) - _announce_root(ctrl, ["a", "b"]) - assert _subscribed_devices(client) == ["panel-1", "a"] - - assert ctrl.check_stuck_children(timeout=0) == ["a"] - assert _subscribed_devices(client) == ["panel-1", "a", "b"] - def test_retry_bound(self, caplog): ctrl, client = _make_paced_controller(subscription_batch_size=1, max_resubscribe_attempts=2) _announce_root(ctrl, ["a"]) @@ -1764,7 +1955,7 @@ def test_retry_bound(self, caplog): assert "reason=stuckDeviceGaveUp,deviceID=a,missing=$state+$description,attempts=2" in caplog.text assert caplog.text.count("reason=stuckDeviceGaveUp") == 1 - assert len(client.unsubscribe.call_args_list) == 8 + assert len(client.unsubscribe.call_args_list) == 4 # Given up, not unsubscribed: a device that appears later is still discovered. _deliver(ctrl, "a") assert ctrl.devices["a"].description is not None @@ -1777,6 +1968,51 @@ def test_zero_attempts_only_logs(self, caplog): client.unsubscribe.assert_not_called() assert "reason=stuckDeviceGaveUp,deviceID=a" in caplog.text + def test_slot_holder_is_requeued_not_resubscribed_at_once(self, caplog): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b", "c"]) + for child in ("a", "b", "c"): + _deliver_attributes(ctrl, child) + assert _property_subscribed(client) == ["panel-1", "a"] + client.reset_mock() + + with caplog.at_level("WARNING", logger="homie"): + assert ctrl.check_stuck_children(timeout=0) == ["a"] + assert "reason=stuckDeviceRequeue,deviceID=a,missing=properties,received=0/2,attempt=1/3" in caplog.text + assert _property_subscribed(client) == ["b"] # a's slot went to b; a waits its turn + client.unsubscribe.assert_not_called() + + _deliver_properties(ctrl, "b") + _deliver_properties(ctrl, "c") + assert _property_subscribed(client) == ["b", "c", "a"] + assert {c[0][0] for c in client.unsubscribe.call_args_list} == { + _topic("a", "+/+"), + _topic("a", "+/+/$target"), + } + + def test_heal_pass_stays_within_the_batch(self): + ctrl, client = _make_paced_controller(subscription_batch_size=2) + children = [f"c{i}" for i in range(6)] + _announce_root(ctrl, children) + for child in children: + _deliver_attributes(ctrl, child) + for _ in range(3): + client.reset_mock() + ctrl.check_stuck_children(timeout=0) + assert len(_property_subscribed(client)) <= 2 + assert len(ctrl._watches) <= 2 + + def test_slot_holder_retry_bound(self, caplog): + ctrl, client = _make_paced_controller(subscription_batch_size=1, max_resubscribe_attempts=1) + _announce_root(ctrl, ["a"]) + _deliver_attributes(ctrl, "a") + with caplog.at_level("WARNING", logger="homie"): + assert ctrl.check_stuck_children(timeout=0) == ["a"] + assert ctrl.check_stuck_children(timeout=0) == [] + assert "reason=stuckDeviceGaveUp,deviceID=a,missing=properties,received=0/2,attempts=1" in caplog.text + assert ctrl._watches == {} + assert ctrl._pending_subscriptions == {} + def test_default_timeout_comes_from_the_constructor(self): ctrl, _ = _make_paced_controller(subscription_batch_size=1, stuck_device_timeout=0) _announce_root(ctrl, ["a"]) @@ -1794,24 +2030,22 @@ def test_message_handling_runs_the_check(self): client.reset_mock() # Any inbound message (here a root property value) drives the heal. - ctrl._on_property_message("panel-1", f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-1/n/p", b"1") - assert {c[0][0] for c in client.unsubscribe.call_args_list} == _filters_for("a") + ctrl._on_property_message("panel-1", _topic("panel-1", "n/p"), b"1") + assert {c[0][0] for c in client.unsubscribe.call_args_list} == _attribute_filters_for("a") def test_message_handling_check_is_rate_limited(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) # default timeout _announce_root(ctrl, ["a"]) with patch.object(ctrl, "check_stuck_children") as check: for _ in range(100): - ctrl._on_property_message( - "panel-1", f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-1/n/p", b"1" - ) + ctrl._on_property_message("panel-1", _topic("panel-1", "n/p"), b"1") check.assert_not_called() # under a second since construction def test_disabled_timeout_skips_the_message_check(self): ctrl, client = _make_paced_controller(subscription_batch_size=1, stuck_device_timeout=None) _announce_root(ctrl, ["a"]) with patch.object(ctrl, "check_stuck_children") as check: - ctrl._on_property_message("panel-1", f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-1/n/p", b"1") + ctrl._on_property_message("panel-1", _topic("panel-1", "n/p"), b"1") check.assert_not_called() def test_wildcard_resubscribe_leaves_the_state_wildcard_alone(self): @@ -1822,12 +2056,7 @@ def test_wildcard_resubscribe_leaves_the_state_wildcard_alone(self): client.reset_mock() assert ctrl.check_stuck_children(timeout=0) == ["d0"] - base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/d0" - assert {c[0][0] for c in client.unsubscribe.call_args_list} == { - f"{base}/$description", - f"{base}/+/+", - f"{base}/+/+/$target", - } + assert {c[0][0] for c in client.unsubscribe.call_args_list} == {_topic("d0", "$description")} def test_stuck_root_is_healed(self): ctrl, client = _make_paced_controller() @@ -1841,3 +2070,21 @@ def test_root_is_watched_after_resync(self): ctrl.start_discovery() ctrl.resync() assert ctrl.check_stuck_children(timeout=0) == ["panel-1"] + + def test_heal_racing_a_drop_leaves_no_subscription(self): + """A heal on a consumer thread interleaved with the paho thread dropping the same child.""" + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["x"]) + + def drop_x_once(topic): + # Runs between the heal's unsubscribe and its resubscribe, as the paho thread could. + if topic == _topic("x", "$description") and "x" in ctrl.devices: + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": []}) + _push_state(ctrl, "panel-1", "ready") + + client.unsubscribe.side_effect = drop_x_once + assert ctrl.check_stuck_children(timeout=0) == ["x"] + + assert "x" not in ctrl.devices + assert not {t for t in _final_subscriptions(client) if "/x/" in t} diff --git a/tests/test_controller_real_broker.py b/tests/test_controller_real_broker.py index f81fdf4..8f8bc91 100644 --- a/tests/test_controller_real_broker.py +++ b/tests/test_controller_real_broker.py @@ -1,10 +1,10 @@ -"""Real-broker regression test for tree-rooted discovery on a busy tree (GH #97). +"""Real-broker regression tests for Controller discovery on a busy bus (GH #97). -Subscribing to every child of a large tree at once makes the broker queue every -matching retained message for one client. Past mosquitto's default per-client -limits (``max_inflight_messages`` 20, ``max_queued_messages`` 1000) it drops the -rest, and retained messages are sent only at subscribe time, so the children -subscribed last never deliver ``$state`` or ``$description``. +Subscribing to many devices at once makes the broker queue every matching retained +message for one client. Past mosquitto's default per-client limits +(``max_inflight_messages`` 20, ``max_queued_messages`` 1000) it drops the rest, and +retained messages are sent only at subscribe time, so the devices subscribed last never +deliver their ``$state``, ``$description`` or property values. Skipped when no ``mosquitto`` binary is available. """ @@ -36,9 +36,9 @@ def _find_mosquitto(): pytestmark = pytest.mark.skipif(MOSQUITTO is None, reason="mosquitto binary not found") CHILDREN = 30 -PROPERTIES_PER_CHILD = 60 -NODES_PER_CHILD = 3 +NODES_PER_DEVICE = 3 ROOT_ID = "busy-root" +BASE = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}" def _free_port(): @@ -83,74 +83,145 @@ def broker(tmp_path): proc.wait(timeout=5) -def _child_id(i): - return f"busy-child-{i:02d}" - - -def _description(device_id, children=None): - props_per_node = PROPERTIES_PER_CHILD // NODES_PER_CHILD +def _description(device_id, properties, children=None, root=None): + per_node = properties // NODES_PER_DEVICE nodes = { f"node-{n}": { "name": f"Node {n}", - "properties": {f"p{p:02d}": {"name": f"P{p}", "datatype": "integer"} for p in range(props_per_node)}, + "properties": {f"p{p:03d}": {"name": f"P{p}", "datatype": "integer"} for p in range(per_node)}, } - for n in range(NODES_PER_CHILD) + for n in range(NODES_PER_DEVICE) } description = {"homie": "5.0", "version": 1, "name": device_id, "nodes": nodes} if children is not None: description["children"] = children - else: - description["root"] = ROOT_ID - description["parent"] = ROOT_ID + if root is not None: + description["root"] = root + description["parent"] = root return description -def _seed_tree(port): - """Publish a retained tree with a raw paho client and wait until the broker has it.""" - client = paho.Client(paho.CallbackAPIVersion.VERSION2, client_id=f"seeder-{uuid.uuid4()}") - client.max_inflight_messages_set(1000) - client.connect("127.0.0.1", port) - client.loop_start() - infos = [] - base = f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}" +class _Seeder: + """Publishes retained Homie topics with a raw paho client and waits until the broker has them.""" + + def __init__(self, port): + self.client = paho.Client(paho.CallbackAPIVersion.VERSION2, client_id=f"seeder-{uuid.uuid4()}") + self.client.max_inflight_messages_set(1000) + self.client.connect("127.0.0.1", port) + self.client.loop_start() + self.infos = [] + + def pub(self, topic, payload): + self.infos.append(self.client.publish(topic, payload, qos=1, retain=True)) + + def device(self, device_id, properties, children=None, root=None): + self.pub(f"{BASE}/{device_id}/$description", json.dumps(_description(device_id, properties, children, root))) + for n in range(NODES_PER_DEVICE): + for p in range(properties // NODES_PER_DEVICE): + self.pub(f"{BASE}/{device_id}/node-{n}/p{p:03d}", str(n * 1000 + p)) + self.pub(f"{BASE}/{device_id}/$state", "ready") + + def close(self): + try: + for info in self.infos: + info.wait_for_publish(timeout=10) + finally: + self.client.loop_stop() + self.client.disconnect() - def pub(topic, payload): - infos.append(client.publish(topic, payload, qos=1, retain=True)) +def _seed_tree(port, properties, silent_children=0): + """A root declaring `silent_children` children that never publish, then CHILDREN real ones.""" + seeder = _Seeder(port) try: - children = [_child_id(i) for i in range(CHILDREN)] + children = [f"busy-child-{i:02d}" for i in range(CHILDREN)] + silent = [f"silent-child-{i:02d}" for i in range(silent_children)] for child in children: - pub(f"{base}/{child}/$description", json.dumps(_description(child))) - for n in range(NODES_PER_CHILD): - for p in range(PROPERTIES_PER_CHILD // NODES_PER_CHILD): - pub(f"{base}/{child}/node-{n}/p{p:02d}", str(n * 100 + p)) - pub(f"{base}/{child}/$state", "ready") - pub(f"{base}/{ROOT_ID}/$description", json.dumps(_description(ROOT_ID, children=children))) - pub(f"{base}/{ROOT_ID}/$state", "ready") - for info in infos: - info.wait_for_publish(timeout=10) + seeder.device(child, properties, root=ROOT_ID) + seeder.device(ROOT_ID, 0, children=silent + children) finally: - client.loop_stop() - client.disconnect() + seeder.close() return children -def test_tree_rooted_controller_discovers_every_child_of_a_busy_tree(broker): - children = _seed_tree(broker) +def _seed_bus(port, properties, state_only=0): + """CHILDREN independent devices, plus `state_only` leftovers with a retained `lost` and nothing else.""" + seeder = _Seeder(port) + try: + for i in range(state_only): + seeder.pub(f"{BASE}/aaa-dead-{i:02d}/$state", "lost") + devices = [f"busy-device-{i:02d}" for i in range(CHILDREN)] + for device in devices: + seeder.device(device, properties) + finally: + seeder.close() + return devices + +def _complete(ctrl, device_id, properties): + device = ctrl.get_device(device_id) + if device is None or device.description is None or device.state != "ready": + return False + return sum(len(values) for values in device.properties.values()) == properties + + +def _await_discovery(ctrl, devices, properties, timeout=30.0): + """Wait until every device has its state, description and every retained property value.""" + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + if all(_complete(ctrl, d, properties) for d in devices): + return + time.sleep(0.1) + described = [d for d in devices if (dev := ctrl.get_device(d)) is not None and dev.description is not None] + full = [d for d in devices if _complete(ctrl, d, properties)] + pytest.fail( + f"{len(described)}/{len(devices)} described, {len(full)}/{len(devices)} with all {properties} values; " + f"incomplete {sorted(set(devices) - set(full))}" + ) + + +@pytest.mark.parametrize("properties", [60, 150, 300]) +def test_tree_rooted_controller_discovers_every_child_of_a_busy_tree(broker, properties): + children = _seed_tree(broker, properties) ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}, root_device_id=ROOT_ID) try: ctrl.start_discovery() - deadline = time.monotonic() + 30.0 - described = set() - while time.monotonic() < deadline: - described = {c for c in children if (d := ctrl.get_device(c)) is not None and d.description is not None} - if len(described) == len(children): - break - time.sleep(0.1) - missing = sorted(set(children) - described) - assert not missing, f"{len(described)}/{len(children)} children described; missing {missing}" - for child in children: - assert ctrl.get_device(child).state == "ready" + _await_discovery(ctrl, children, properties) + finally: + ctrl.stop() + + +def test_wildcard_controller_discovers_every_device_of_a_busy_bus(broker): + devices = _seed_bus(broker, 150) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}) + try: + ctrl.start_discovery() + _await_discovery(ctrl, devices, 150) + finally: + ctrl.stop() + + +def test_silent_declared_children_do_not_stall_a_quiet_tree(broker): + """Children declared ahead of the real ones that never publish must not hold up the rest. + + Nothing publishes after seeding and nobody calls check_stuck_children(), so only the + retained messages the Controller's own subscriptions bring can drive discovery. + """ + children = _seed_tree(broker, 60, silent_children=8) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}, root_device_id=ROOT_ID) + try: + ctrl.start_discovery() + _await_discovery(ctrl, children, 60, timeout=8.0) + finally: + ctrl.stop() + + +def test_state_only_leftovers_do_not_stall_a_quiet_wildcard_bus(broker): + """Devices with a retained $state and no $description must not hold up the rest.""" + devices = _seed_bus(broker, 60, state_only=8) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}) + try: + ctrl.start_discovery() + _await_discovery(ctrl, devices, 60, timeout=8.0) finally: ctrl.stop() From dcc79de8f72aaa86953037c66048631facdbd2f8 Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 13:59:36 -0700 Subject: [PATCH 4/7] Controller pacing: heal late devices, count $target, chunk big devices (#97) - A device that gave up in stage one and publishes later is queued for its property filters (_note_device_progress queues any described device whose nodes lack property filters). - An injected mqttc is unpaced unless subscription_batch_size is passed: the drain marker needs a resubscribe to replay retained messages. - The value budget counts a value and a possible $target per retained property, and a slot is held until the marker or every value and target. - A device over the budget on its own is subscribed node by node in chunks that fit; a slot holder whose retry made no progress gives up; an owned client runs the stuck check from a timer thread. - $description is subscribed with_retain when the transport supports it, so a live republish is not taken for the marker; a changed description updates an active slot's expected count. - CHANGELOG/README/doc: tree-ready precedes descendants' values; untracked $state in tree-rooted mode is ignored and unsubscribed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- CHANGELOG.md | 6 +- README.md | 8 +- doc/consuming-a-homie-tree.md | 2 + src/ebus_sdk/homie.py | 416 +++++++++++++++++++++------ src/ebus_sdk/transport.py | 9 + tests/test_controller.py | 259 +++++++++++++++-- tests/test_controller_real_broker.py | 77 ++++- 7 files changed, 659 insertions(+), 118 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index dd68f44..015f6ce 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,12 +34,14 @@ Homie 5 compliance, phase 1: producer wire correctness ([#95](https://github.com - Encoders for `datetime` (`datetime`/`date` as ISO 8601, :132), `duration` (`timedelta` as `PTxHxMxS`, :137-144) and `color` (a component tuple in the first `format` color type, :118-123). These fell through to `str()`, which produced `2026-10-08 12:00:00+00:00`, `0:05:00` and `(255, 0, 0)`. - `Device.publish_alert(alert_id, message)`, `Device.clear_alert(alert_id)` and `Device.alerts()`. Alerts publish retained to `$alert/[alert ID]` (:517), are republished on reconnect, and are cleared by `delete()` (:289). - `Device.invalidate_description_cache()`, the `$description` counterpart of `Property.invalidate_publish_cache()`. `clear_retained_topic()` aimed at the device's own `$description` and `delete_all_from_mqtt()` call it, so a later `publish_description()` is no longer suppressed after the topic was cleared. -- `Controller(subscription_batch_size=8, subscription_batch_values=500, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device still lacking `$state` or `$description` after `timeout` seconds has those two filters unsubscribed and resubscribed, so the broker resends them; a device still holding a batch slot after `timeout` gives it up and rejoins the end of the queue. Each device is retried up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` or `reason=stuckDeviceRequeue` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end. Message handling runs the check at most once a second; a consumer on a quiet connection, or driving its own event loop, can call it from a timer. `stuck_device_timeout=None` turns off the automatic check ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- `Controller(subscription_batch_size=8, subscription_batch_values=500, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device still lacking `$state` or `$description` after `timeout` seconds has those two filters unsubscribed and resubscribed, so the broker resends them; a device still holding a batch slot after `timeout` gives it up and rejoins the end of the queue. Each device is retried up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` or `reason=stuckDeviceRequeue` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end; a slot holder whose retry received no more than the attempt before it gives up then, with `noProgress=true`. A device that gave up lacking `$state` or `$description` and publishes them later gets its property filters then. Message handling runs the check at most once a second, and so does a daemon timer thread when the Controller built the client; with an injected client on a quiet connection, call it from your own timer. `stuck_device_timeout=None` turns off the automatic check ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ### Fixed - `delete()` followed by `stop()` re-created the deleted device as a bare `$state=disconnected` with no `$description` (:272, :288). After `delete()` the root's `stop()` announces nothing, flushes `delete()`'s retained clears and disconnects cleanly in either mode, and a reconnect's `refresh_tree()` republishes nothing. -- A `Controller` could miss retained `$state`, `$description` and property values of some devices for good. It subscribed to every device at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes each tree descendant's `$state` and `$description` (in wildcard discovery, its `$description`) as soon as the device is known, and its property filters once both have arrived, at most `subscription_batch_size` devices and `subscription_batch_values` retained values at a time. The next device starts when an earlier one's retained property values have all arrived, or when its `$description`, resubscribed behind its property filters, arrives again. A declared child that never publishes, or a leftover `$state` with no `$description`, holds no slot. All 30 children are described with every value at 60, 150 and 300 values per child. With the default pacing, a device's property values are no longer tracked until its `$description` arrives. `subscription_batch_size=None` restores the unpaced fan-out. The tree root and the single device of single-device mode are subscribed unpaced ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- A `Controller` could miss retained `$state`, `$description` and property values of some devices for good. It subscribed to every device at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes each tree descendant's `$state` and `$description` (in wildcard discovery, its `$description`) as soon as the device is known, and its property filters once both have arrived, at most `subscription_batch_size` devices and `subscription_batch_values` retained messages at a time, counting a value and a possible `$target` per retained property. A device larger than `subscription_batch_values` on its own is subscribed node by node (`{node}/+` and `{node}/+/$target`) in chunks that fit. The next device starts when an earlier one's `$description`, resubscribed behind its property filters, arrives again (a live republish of `$description`, told apart by the retain flag from ebus-mqtt-client 0.7.0, does not count), or when every value and `$target` it can owe has arrived. A declared child that never publishes, or a leftover `$state` with no `$description`, holds no slot. All 30 children are described with every value at 60, 150 and 300 values per child, with every `$target` at 150 values and targets per child, and three children of 1500 values each get every value. Pacing is the default only for a client the Controller builds; an injected `mqttc` is unpaced unless `subscription_batch_size` is passed, because pacing needs a resubscribe to replay retained messages, which a transport that only records subscriptions does not do. `subscription_batch_size=None` restores the unpaced fan-out. The tree root and the single device of single-device mode are subscribed unpaced ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- With pacing, a device's property values are not tracked until its `$description` arrives, and `on_tree_ready` / `is_tree_complete()` (every declared device described) come before descendants' retained property values, which arrive afterwards through `on_property_changed`. Unpaced, the subscribe order happened to deliver most of them first ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- In tree-rooted mode a `$state` for a device the tree does not declare (a late retained message on the filters of a dropped descendant) is ignored and that device's filters are unsubscribed; `on_device_discovered` no longer fires for it. It used to be registered as a new device ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ## [0.24.0] — 2026-10-03 diff --git a/README.md b/README.md index ca8d589..f9e254a 100644 --- a/README.md +++ b/README.md @@ -303,9 +303,13 @@ subscribed or dropped on the parent's next init→ready transition. #### Paced subscriptions and stuck devices -A broker queues every retained message matching a new subscription for that one client and drops what exceeds its per-client limit (mosquitto: `max_queued_messages` 1000). Retained messages are sent only at subscribe time, so a device whose `$state`, `$description` or property values were dropped never receives them. The Controller therefore subscribes each device in two stages (tree-rooted descendants and wildcard-discovered devices). Its `$state` and `$description` are subscribed as soon as the device is known. Once both have arrived, its property filters are subscribed, at most `subscription_batch_size` devices (default 8) and `subscription_batch_values` retained values (default 500, counted from each `$description`) at a time. A device keeps its slot until every retained value its `$description` declares has arrived, or until its `$description`, resubscribed behind its property filters, arrives again. A device that never publishes holds no slot, so it delays no other device. +A broker queues every retained message matching a new subscription for that one client and drops what exceeds its per-client limit (mosquitto: `max_queued_messages` 1000). Retained messages are sent only at subscribe time, so a device whose `$state`, `$description` or property values were dropped never receives them. The Controller therefore subscribes each device in two stages (tree-rooted descendants and wildcard-discovered devices). Its `$state` and `$description` are subscribed as soon as the device is known. Once both have arrived, its property filters are subscribed, at most `subscription_batch_size` devices (default 8) and `subscription_batch_values` retained messages (default 500, counting a value and a possible `$target` for each retained property its `$description` declares) at a time. A device larger than `subscription_batch_values` on its own is subscribed node by node, in chunks that fit. A device keeps its slot until its `$description`, resubscribed behind its property filters, arrives again, or until every value and `$target` it can owe has arrived. A device that never publishes holds no slot, so it delays no other device, and if it publishes later it gets its property filters then. -A device still lacking `$state` or `$description` after `stuck_device_timeout` seconds (default 10) has those two filters unsubscribed and resubscribed, so the broker resends them. A device still holding a slot after that long gives it up and rejoins the end of the queue. Each is retried up to `max_resubscribe_attempts` times (default 3). Message handling runs this check at most once a second. On a connection that goes quiet, or under a caller-driven event loop, call it yourself: +Pacing is on by default for a client the Controller builds from `mqtt_cfg` and off for an injected `mqttc`. Pass `subscription_batch_size` to pace an injected transport only if subscribing a filter again makes it deliver the retained messages again, as a broker connection does. + +`on_tree_ready` and `is_tree_complete()` mean every declared device has published its `$description`. With pacing, descendants' retained property values arrive after that, through `on_property_changed`. + +A device still lacking `$state` or `$description` after `stuck_device_timeout` seconds (default 10) has those two filters unsubscribed and resubscribed, so the broker resends them. A device still holding a slot after that long gives it up and rejoins the end of the queue. Each is retried up to `max_resubscribe_attempts` times (default 3); a slot holder whose retry received no more than the attempt before it is not retried again. Message handling runs this check at most once a second, and so does a timer thread when the Controller built the client. With an injected client on a connection that goes quiet, call it yourself: ```python controller = Controller(mqtt_cfg=cfg, root_device_id='panel-1', diff --git a/doc/consuming-a-homie-tree.md b/doc/consuming-a-homie-tree.md index 21a58a6..1b07a84 100644 --- a/doc/consuming-a-homie-tree.md +++ b/doc/consuming-a-homie-tree.md @@ -111,6 +111,8 @@ controller.set_on_tree_ready_callback(lambda root: snapshot(root.device_id)) `is_tree_complete(root_id)` walks the declared tree and returns whether every device named transitively under it has published its own `$description`. It is safe to call at any time, as often as you like, and it will **flip back to False** when a device declares a new child. That is not a defect; it is the open child set showing through. +Described means `$description`, not values. With the `Controller`'s default subscription pacing, each descendant's retained property values arrive after its `$description`, so on the tree-ready edge most of them may not have arrived yet. Read values from `on_property_changed`, or wait for the properties you need. + `set_on_tree_ready_callback()` fires on the incomplete-to-complete edge and **re-arms**: a root that grows a new child fires again once that child describes itself. A tree commissioned in stages produces one call per settled shape rather than one call ever. Read that re-arming as a warning. If you take the first call as a barrier and stop listening, you have rebuilt the one-shot barrier from failure mode 1 out of the very API meant to prevent it. Handle every call. diff --git a/src/ebus_sdk/homie.py b/src/ebus_sdk/homie.py index 45baf91..270169c 100644 --- a/src/ebus_sdk/homie.py +++ b/src/ebus_sdk/homie.py @@ -3555,19 +3555,21 @@ def get_node_properties(self, node_id: str) -> dict: # declared device that never publishes blocks nothing. Once both have arrived, stage two # subscribes the property filters, which carry the bulk of the retained messages, in # batches of at most subscription_batch_size devices and subscription_batch_values -# retained values (counted from each $description). A device holds its slot until its -# property burst has drained: either every retained property its $description declares -# has arrived, or the retained $description it resubscribes after its property filters -# arrives behind the burst. That marker relies on the broker sending one client's -# messages in order, as mosquitto does; MQTT guarantees order only within a topic, so on -# another broker the marker can free a slot early. +# retained messages (counted from each $description: one value and one possible $target +# per retained property). A device whose own count exceeds subscription_batch_values is +# subscribed node by node, in chunks that fit. A device holds its slot until its burst +# has drained: either every value and $target it can owe has arrived, or the retained +# $description it resubscribes after its property filters arrives behind the burst. That +# marker relies on the broker sending one client's messages in order, as mosquitto does, +# and on a resubscribe replaying retained messages, which a transport that only records +# subscriptions does not do; that is why an injected transport is unpaced by default. CONTROLLER_SUBSCRIPTION_BATCH_SIZE = 8 # Half of mosquitto's default max_queued_messages, leaving room for the $state and # $description bursts and for live traffic. CONTROLLER_SUBSCRIPTION_BATCH_VALUES = 500 CONTROLLER_STUCK_DEVICE_TIMEOUT = 10.0 CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS = 3 -# Upper bound on how often message handling runs the opportunistic stuck check. +# Upper bound on how often message handling, or the owned client's timer, runs the stuck check. _STUCK_CHECK_INTERVAL = 1.0 # Per-device topic filter suffixes. Wildcard discovery hears $state through its # broker-wide {domain}/5/+/$state filter, so a device found that way needs only the rest. @@ -3575,6 +3577,23 @@ def get_node_properties(self, node_id: str) -> dict: _ATTRIBUTE_FILTERS = ("$state", "$description") _WILDCARD_ATTRIBUTE_FILTERS = ("$description",) _PROPERTY_FILTERS = ("+/+", "+/+/$target") +# Controller._property_coverage value for a device whose whole-device property filters are subscribed. +_ALL_NODES = "*" + + +class _DefaultBatchSize: + """Sentinel default for subscription_batch_size: paced for an owned client, unpaced for an injected one.""" + + def __repr__(self) -> str: + return "" + + +_DEFAULT_BATCH_SIZE: Any = _DefaultBatchSize() + + +def _node_filters(nodes) -> tuple: + """Property filter suffixes covering only the given nodes.""" + return tuple(f for node in nodes for f in (f"{node}/+", f"{node}/+/$target")) @dataclass @@ -3582,7 +3601,9 @@ class _SubscriptionWatch: """A subscribed device awaiting its retained messages. In stage one it awaits $state and $description; in stage two it holds a batch slot - until its property burst drains. + until its property burst drains. In stage two, ``nodes`` is None for the + whole-device filters or the nodes of one chunk, ``expected_values`` the retained + values those declare, and ``received_values`` the values and targets seen. """ filters: tuple @@ -3590,20 +3611,50 @@ class _SubscriptionWatch: attempts: int = 0 expected_values: int = 0 received_values: set = field(default_factory=set) + nodes: Optional[tuple] = None + last_received: Optional[int] = None + @property + def owed(self) -> int: + """Retained messages still possible: a value and a $target per expected value.""" + return max(2 * self.expected_values - len(self.received_values), 0) -def _retained_property_count(description: Any) -> int: - """Properties a $description declares as retained (the Homie 5 default).""" - count = 0 + @property + def values_received(self) -> int: + return sum(1 for key in self.received_values if len(key) == 2) + + +@dataclass +class _PendingProperties: + """A device waiting for a batch slot to subscribe (more of) its property filters.""" + + attempts: int = 0 + # Filters to unsubscribe before subscribing, so the broker replays them (a retry). + resubscribe: tuple = () + # Messages the failed attempt received, to stop retrying one that cannot progress. + last_received: Optional[int] = None + + +def _retained_counts(description: Any) -> dict: + """{node_id: retained properties (the Homie 5 default)} for every node a $description declares.""" nodes = description.get("nodes") if isinstance(description, dict) else None if not isinstance(nodes, dict): - return 0 - for node in nodes.values(): + return {} + counts = {} + for node_id, node in nodes.items(): properties = node.get("properties") if isinstance(node, dict) else None if not isinstance(properties, dict): + counts[node_id] = 0 continue - count += sum(1 for p in properties.values() if not isinstance(p, dict) or p.get("retained", True) is not False) - return count + counts[node_id] = sum( + 1 for p in properties.values() if not isinstance(p, dict) or p.get("retained", True) is not False + ) + return counts + + +def _retained_property_count(description: Any) -> int: + """Properties a $description declares as retained (the Homie 5 default).""" + return sum(_retained_counts(description).values()) class Controller: @@ -3637,7 +3688,7 @@ def __init__( root_device_id: Optional[str] = None, qos: int = EBUS_HOMIE_MQTT_QOS, mqttc: Optional[MqttControllerTransport] = None, - subscription_batch_size: Optional[int] = CONTROLLER_SUBSCRIPTION_BATCH_SIZE, + subscription_batch_size: Optional[int] = _DEFAULT_BATCH_SIZE, subscription_batch_values: Optional[int] = CONTROLLER_SUBSCRIPTION_BATCH_VALUES, stuck_device_timeout: Optional[float] = CONTROLLER_STUCK_DEVICE_TIMEOUT, max_resubscribe_attempts: int = CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS, @@ -3671,26 +3722,37 @@ def __init__( with start_discovery() once the client is connected. Default None: the SDK constructs, starts, and owns a client from mqtt_cfg. subscription_batch_size: Most devices whose property filters may - await their retained values at once (GH #97). Every device's + await their retained messages at once (GH #97). Every device's $state and $description are subscribed as soon as it is known; its property filters follow once both have arrived, in batches of this many devices, the next starting as an earlier device's - retained property values finish arriving. This keeps the - broker's per-client queue from overflowing and dropping retained + retained burst finishes arriving. This keeps the broker's + per-client queue from overflowing and dropping retained messages. None or 0 subscribes all of a device's filters at once. - subscription_batch_values: Most retained property values the devices - in a batch may still be owed (GH #97), counted from each - device's $description. A device that would exceed it waits, - unless no other device is in flight. None counts devices only. + Default: CONTROLLER_SUBSCRIPTION_BATCH_SIZE (8) for a client the + SDK builds, None for an injected ``mqttc``. Pacing detects the + end of a burst by resubscribing ``$description``, so pass a value + for an injected transport only if a resubscribe makes it deliver + the retained ``$description`` again, as a broker connection does. + subscription_batch_values: Most retained messages the devices in a + batch may still be owed (GH #97), counted from each device's + $description as a value and a possible $target per retained + property. A device that would exceed it waits, unless no other + device is in flight. A device that exceeds it on its own is + subscribed node by node, in chunks that fit. None counts devices + only. stuck_device_timeout: Seconds a subscribed device may lack $state or $description, or keep a batch slot, before it is declared stuck: its $state and $description filters are unsubscribed and resubscribed so the broker resends them, or it gives up its slot and waits for another. Message handling runs this check at most - once a second; see check_stuck_children(). None disables the - automatic check. + once a second, and so does a timer thread for a client the SDK + builds; see check_stuck_children(). None disables the automatic + check. max_resubscribe_attempts: Retries per stuck device before it is - logged as unrecoverable and no longer checked. 0 only logs. + logged as unrecoverable and no longer checked. 0 only logs. A + slot holder whose retry received no more than the attempt + before it is not retried again. """ if device_id is not None and root_device_id is not None: raise ValueError( @@ -3722,10 +3784,12 @@ def __init__( # doesn't look "missing" and get re-subscribed every reconcile. self._subscribed_children: dict = {} - # Subscription pacing and stuck-device healing (GH #97). Event-driven: state - # changes only on message arrival, device removal, resync, or a call to - # check_stuck_children(). The lock guards the bookkeeping only; transport - # calls are made after releasing it. + # Subscription pacing and stuck-device healing (GH #97). State changes on message + # arrival, device removal, resync, or a stuck check (a call to + # check_stuck_children(), or the owned client's timer). The lock guards the + # bookkeeping only; transport calls are made after releasing it. + if subscription_batch_size is _DEFAULT_BATCH_SIZE: + subscription_batch_size = CONTROLLER_SUBSCRIPTION_BATCH_SIZE if mqttc is None else None if subscription_batch_size is not None and subscription_batch_size < 0: raise ValueError("subscription_batch_size must be None or >= 0") if max_resubscribe_attempts < 0: @@ -3739,13 +3803,18 @@ def __init__( self._pacing_lock = threading.RLock() # Stage one, {device_id: _SubscriptionWatch}: awaiting $state and $description. self._awaiting_attributes: dict = {} - # Stage two, {device_id: attempts}, insertion-ordered: waiting for a batch slot. + # Stage two, {device_id: _PendingProperties}, insertion-ordered: waiting for a batch slot. self._pending_subscriptions: dict = {} # Stage two, {device_id: _SubscriptionWatch}: holding a batch slot. self._watches: dict = {} # Devices whose $description was resubscribed behind their property filters. self._description_markers: set = set() + # {device_id: _ALL_NODES or set of node ids}: whose property filters are subscribed. + self._property_coverage: dict = {} self._last_stuck_check = time.monotonic() + # Drives the stuck check for a client the SDK owns, so a quiet connection heals. + self._stuck_timer: Optional[threading.Thread] = None + self._stuck_timer_stop = threading.Event() # Callbacks self._on_device_discovered = None @@ -3850,6 +3919,7 @@ def resync(self) -> None: self._watches.clear() self._description_markers.clear() self._awaiting_attributes = {self.root_device_id: _SubscriptionWatch(_DEVICE_FILTERS, time.monotonic())} + self._property_coverage = {self.root_device_id: _ALL_NODES} # Cold restart of tree-rooted bookkeeping. paho-mqtt's MqttClient # has already re-subscribed our root's four filters; retained # state/description will arrive momentarily and the state-edge @@ -3899,6 +3969,30 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: discovery_topic = f"{domain}/{EBUS_HOMIE_VERSION_MAJOR}/+/$state" logger.info(f"reason=startDiscovery,topic={discovery_topic}") self.mqttc.subscribe(discovery_topic, param=self._on_state_message, qos=self._qos) + self._start_stuck_timer() + + def _start_stuck_timer(self) -> None: + """Run the stuck check from a timer thread when the SDK owns the client. + + An injected client's caller owns its event loop and threads, so it calls + check_stuck_children() itself. + """ + if not self._owns_client or self._stuck_device_timeout is None: + return + if self._stuck_timer is not None and self._stuck_timer.is_alive(): + return + self._stuck_timer_stop.clear() + interval = max(min(_STUCK_CHECK_INTERVAL, self._stuck_device_timeout), 0.05) + + def run() -> None: + while not self._stuck_timer_stop.wait(interval): + try: + self._maybe_check_stuck() + except Exception: + logger.exception("reason=stuckCheckTimerException") + + self._stuck_timer = threading.Thread(target=run, name="ebus-controller-stuck-check", daemon=True) + self._stuck_timer.start() def _subscribe_filters(self, device_id: str, filters: tuple) -> None: """Subscribe the given per-device filter suffixes for device_id, in order. @@ -3909,14 +4003,21 @@ def _subscribe_filters(self, device_id: str, filters: tuple) -> None: if not self.mqttc: return base = f"{self.homie_domain}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}" - callbacks = { - "$state": self._on_state_message, - "$description": partial(self._on_description_message, device_id), - "+/+": partial(self._on_property_message, device_id), - "+/+/$target": partial(self._on_target_message, device_id), - } for suffix in filters: - self.mqttc.subscribe(f"{base}/{suffix}", param=callbacks[suffix], qos=self._qos) + topic = f"{base}/{suffix}" + if suffix == "$state": + self.mqttc.subscribe(topic, param=self._on_state_message, qos=self._qos) + elif suffix == "$description": + # The retain flag tells the resubscribed marker from a live republish. + callback = partial(self._on_description_message, device_id) + if _subscribe_supports_with_retain(self.mqttc): + self.mqttc.subscribe(topic, param=callback, qos=self._qos, with_retain=True) + else: + self.mqttc.subscribe(topic, param=callback, qos=self._qos) + elif suffix.endswith("/$target"): + self.mqttc.subscribe(topic, param=partial(self._on_target_message, device_id), qos=self._qos) + else: + self.mqttc.subscribe(topic, param=partial(self._on_property_message, device_id), qos=self._qos) def _unsubscribe_filters(self, device_id: str, filters: tuple) -> None: if not self.mqttc: @@ -3961,34 +4062,85 @@ def _request_subscription(self, device_id: str, paced: bool = True) -> None: ): return self._awaiting_attributes[device_id] = _SubscriptionWatch(filters, time.monotonic()) + if _PROPERTY_FILTERS[0] in filters: + self._property_coverage[device_id] = _ALL_NODES self._subscribe_tracked(device_id, filters) + def _uncovered_nodes_locked(self, device_id: str, description: Any) -> Optional[list]: + """Nodes of description whose property filters are not subscribed; None when all are.""" + coverage = self._property_coverage.get(device_id) + if coverage == _ALL_NODES: + return None + nodes = list(_retained_counts(description)) + if coverage is None: + return nodes + uncovered = [n for n in nodes if n not in coverage] + return uncovered or None + + def _next_chunk_locked(self, device_id: str, description: Any): + """The next property filters to subscribe for a device: (nodes, filters, expected values). + + The whole-device filters when nothing is subscribed yet and the device's retained + messages fit the value budget; otherwise the next nodes, in declared order, that + fit it (at least one). None when every node is already covered. + """ + uncovered = self._uncovered_nodes_locked(device_id, description) + if uncovered is None: + return None + counts = _retained_counts(description) + budget = self._subscription_batch_values + total = sum(counts[n] for n in uncovered) + if device_id not in self._property_coverage and (budget is None or 2 * total <= budget): + return None, _PROPERTY_FILTERS, total + nodes, expected = [], 0 + for node in uncovered: + if nodes and budget is not None and 2 * (expected + counts[node]) > budget: + break + nodes.append(node) + expected += counts[node] + return tuple(nodes), _node_filters(nodes), expected + + def _queue_front_locked(self, device_id: str, entry: _PendingProperties) -> None: + self._pending_subscriptions = {device_id: entry, **self._pending_subscriptions} + def _take_pending_locked(self) -> list: """Move pending devices into free batch slots; the caller subscribes them unlocked. - A device starts when a slot is free and the retained values it declares fit in the - value budget beside those still owed to the devices in flight. With nothing in - flight it starts whatever its size. + A device starts when a slot is free and the retained messages its next chunk + declares fit in the value budget beside those still owed to the devices in + flight. With nothing in flight it starts whatever its size. """ started = [] - owed = sum(max(w.expected_values - len(w.received_values), 0) for w in self._watches.values()) + owed = sum(w.owed for w in self._watches.values()) while self._pending_subscriptions and len(self._watches) < self._subscription_batch_size: device_id = next(iter(self._pending_subscriptions)) device = self.devices.get(device_id) - if device is None: + entry = self._pending_subscriptions[device_id] + chunk = None if device is None else self._next_chunk_locked(device_id, device.description) + if chunk is None: del self._pending_subscriptions[device_id] continue - expected = _retained_property_count(device.description) + nodes, filters, expected = chunk budget = self._subscription_batch_values - if self._watches and budget is not None and owed + expected > budget: + if self._watches and budget is not None and owed + 2 * expected > budget: break - attempts = self._pending_subscriptions.pop(device_id) - owed += expected + del self._pending_subscriptions[device_id] + owed += 2 * expected + if nodes is None: + self._property_coverage[device_id] = _ALL_NODES + else: + self._property_coverage.setdefault(device_id, set()).update(nodes) if expected: self._watches[device_id] = _SubscriptionWatch( - _PROPERTY_FILTERS, time.monotonic(), attempts=attempts, expected_values=expected + filters, + time.monotonic(), + attempts=entry.attempts, + expected_values=expected, + nodes=nodes, + last_received=entry.last_received, ) - started.append((device_id, attempts)) + self._description_markers.add(device_id) + started.append((device_id, filters, entry.resubscribe, bool(expected))) return started def _start_subscriptions(self, started: list) -> None: @@ -3997,43 +4149,85 @@ def _start_subscriptions(self, started: list) -> None: The broker resends the retained $description behind the property burst, so its arrival marks the burst as drained. """ - for device_id, attempts in started: - logger.info(f"reason=pacedSubscribe,deviceID={device_id},pending={len(self._pending_subscriptions)}") - if attempts: - self._unsubscribe_filters(device_id, _PROPERTY_FILTERS) - self._description_markers.add(device_id) - self._subscribe_tracked(device_id, _PROPERTY_FILTERS + ("$description",)) + for device_id, filters, resubscribe, marked in started: + logger.info( + f"reason=pacedSubscribe,deviceID={device_id},filters={len(filters)}," + f"pending={len(self._pending_subscriptions)}" + ) + if resubscribe: + self._unsubscribe_filters(device_id, resubscribe) + self._subscribe_tracked(device_id, filters + (("$description",) if marked else ())) + + def _requeue_uncovered_locked(self, device_id: str, front: bool = False) -> None: + """Queue a device for stage two if any of its nodes still lacks property filters.""" + device = self.devices.get(device_id) + if ( + device is None + or device.state is None + or device.description is None + or device_id in self._awaiting_attributes + or device_id in self._pending_subscriptions + or device_id in self._watches + or self._uncovered_nodes_locked(device_id, device.description) is None + ): + return + if front: + self._queue_front_locked(device_id, _PendingProperties()) + else: + self._pending_subscriptions[device_id] = _PendingProperties() def _release_slot(self, device_id: str) -> None: - """A device's property burst has drained: free its slot for the next pending device.""" + """A device's property burst has drained: free its slot for the next pending device. + + A device subscribed node by node goes back to the front of the queue for its next chunk. + """ with self._pacing_lock: - if self._watches.pop(device_id, None) is None: + if device_id not in self._watches: return + self._release_slot_locked(device_id) started = self._take_pending_locked() self._start_subscriptions(started) + def _release_slot_locked(self, device_id: str) -> None: + del self._watches[device_id] + self._description_markers.discard(device_id) + self._requeue_uncovered_locked(device_id, front=True) + def _note_device_progress(self, device_id: str) -> None: - """Finish stage one once a device has both $state and $description.""" + """Queue a device for stage two once it has $state and $description and lacks property filters. + + This also covers a device that appears after stage one gave up on it, and new + nodes in a changed $description of a device subscribed node by node. + """ device = self.devices.get(device_id) if device is None or device.state is None or device.description is None: return with self._pacing_lock: - watch = self._awaiting_attributes.pop(device_id, None) - if watch is None or _PROPERTY_FILTERS[0] in watch.filters: + self._awaiting_attributes.pop(device_id, None) + if not self._paced: + return + self._requeue_uncovered_locked(device_id) + if device_id not in self._pending_subscriptions: return - self._pending_subscriptions[device_id] = 0 started = self._take_pending_locked() self._start_subscriptions(started) - def _forget_subscription(self, device_id: str) -> None: - """Drop a device from pacing, freeing any batch slot it held.""" + def _forget_subscription(self, device_id: str) -> tuple: + """Drop a device from pacing, freeing any batch slot it held. + + Returns the property filter suffixes recorded as subscribed for it. + """ with self._pacing_lock: self._awaiting_attributes.pop(device_id, None) self._pending_subscriptions.pop(device_id, None) self._watches.pop(device_id, None) self._description_markers.discard(device_id) + coverage = self._property_coverage.pop(device_id, None) started = self._take_pending_locked() if self._paced else [] self._start_subscriptions(started) + if coverage is None or coverage == _ALL_NODES: + return _PROPERTY_FILTERS + return _PROPERTY_FILTERS + _node_filters(sorted(coverage)) def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: """Heal subscribed devices whose retained messages have not arrived (GH #97). @@ -4050,14 +4244,18 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: any other device. After ``max_resubscribe_attempts`` retries a device is logged as - unrecoverable and no longer checked; its subscriptions stay in place, - so a device that appears later is still discovered. + unrecoverable and no longer checked; so is a slot holder whose retry + received no more messages than the attempt before it. Its subscriptions + stay in place. A device that gave up lacking ``$state`` or + ``$description`` and publishes them later is discovered and gets its + property filters; one that gave up holding a slot keeps the filters it + has and moves on to any nodes not yet subscribed. Message handling calls this at most once a second when - ``stuck_device_timeout`` is set. On a connection that goes quiet, - healing waits for the next message unless you call it from your own - timer or event loop. It uses no threads and is safe to call from any - thread. + ``stuck_device_timeout`` is set, and so does a timer thread when the + SDK built the client. With an injected client on a connection that goes + quiet, healing waits for the next message unless you call it from your + own timer or event loop. It is safe to call from any thread. Returns the ids of the devices resubscribed or requeued by this call. """ @@ -4096,14 +4294,27 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: if now - watch.subscribed_at < timeout: continue del self._watches[device_id] - received = f"{len(watch.received_values)}/{watch.expected_values}" - if watch.attempts >= self._max_resubscribe_attempts: + self._description_markers.discard(device_id) + received = f"{watch.values_received}/{watch.expected_values}" + stalled = watch.last_received is not None and len(watch.received_values) <= watch.last_received + if watch.attempts >= self._max_resubscribe_attempts or stalled: logger.error( f"reason=stuckDeviceGaveUp,deviceID={device_id},missing=properties," - f"received={received},attempts={watch.attempts}" + f"received={received},attempts={watch.attempts}" + (",noProgress=true" if stalled else "") ) + # Its filters stay subscribed; move on to any nodes still uncovered. + self._requeue_uncovered_locked(device_id) continue - self._pending_subscriptions[device_id] = watch.attempts + 1 + coverage = self._property_coverage.get(device_id) + if watch.nodes is None: + self._property_coverage.pop(device_id, None) + elif isinstance(coverage, set): + coverage.difference_update(watch.nodes) + self._pending_subscriptions[device_id] = _PendingProperties( + attempts=watch.attempts + 1, + resubscribe=watch.filters, + last_received=len(watch.received_values), + ) requeued.append((device_id, watch.attempts + 1, received)) started = self._take_pending_locked() if self._paced else [] @@ -4123,7 +4334,7 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: return [device_id for device_id, *_ in resubscribe] + [device_id for device_id, *_ in requeued] def _maybe_check_stuck(self) -> None: - """Opportunistic, rate-limited stuck check run from message handling.""" + """Rate-limited stuck check run from message handling and the owned client's timer.""" timeout = self._stuck_device_timeout if timeout is None or not (self._awaiting_attributes or self._watches): return @@ -4291,8 +4502,8 @@ def _unsubscribe_and_drop(self, device_id: str) -> None: # Unconditionally: after a reconnect the transport holds filters subscribed in an # earlier connection, whatever the pacing bookkeeping says. - self._forget_subscription(device_id) - self._unsubscribe_filters(device_id, _DEVICE_FILTERS) + property_filters = self._forget_subscription(device_id) + self._unsubscribe_filters(device_id, _ATTRIBUTE_FILTERS + property_filters) if self._on_device_removed: try: @@ -4305,8 +4516,14 @@ def _unsubscribe_and_drop(self, device_id: str) -> None: self._tree_complete.pop(device_id, None) self._reevaluate_tree_completeness() - def _on_description_message(self, device_id: str, topic: str, payload: bytes) -> None: - """Handle device $description messages""" + def _on_description_message( + self, device_id: str, topic: str, payload: bytes, retained: Optional[bool] = None + ) -> None: + """Handle device $description messages. + + ``retained`` is the message's retain flag when the transport delivers it + (``subscribe(..., with_retain=True)``), else None. + """ self._maybe_check_stuck() if device_id not in self.devices: return @@ -4315,8 +4532,9 @@ def _on_description_message(self, device_id: str, topic: str, payload: bytes) -> device = self.devices[device_id] # The $description resubscribed behind a device's property filters marks the - # end of its property burst. An unchanged one is only that marker. - if device_id in self._description_markers: + # end of its property burst. An unchanged one is only that marker. A live + # republish (retain flag clear) is not the marker. + if device_id in self._description_markers and retained is not False: self._description_markers.discard(device_id) self._release_slot(device_id) try: @@ -4329,6 +4547,14 @@ def _on_description_message(self, device_id: str, topic: str, payload: bytes) -> device.update_description(payload_str) + # A device holding a slot owes what its new description declares. + with self._pacing_lock: + watch = self._watches.get(device_id) + if watch is not None and device.description is not None: + counts = _retained_counts(device.description) + nodes = counts if watch.nodes is None else watch.nodes + watch.expected_values = sum(counts.get(n, 0) for n in nodes) + logger.info(f"reason=descriptionReceived,deviceID={device_id}") if self._on_description_received: self._on_description_received(device) @@ -4386,12 +4612,7 @@ def _on_property_message(self, device_id: str, topic: str, payload: bytes) -> No old_value = device.get_property(node_id, property_id) device.update_property(node_id, property_id, payload_str) - # Every retained value the $description declares has arrived: the burst is over. - watch = self._watches.get(device_id) - if watch is not None: - watch.received_values.add((node_id, property_id)) - if len(watch.received_values) >= watch.expected_values: - self._release_slot(device_id) + self._note_burst_message(device_id, (node_id, property_id)) logger.debug( f"reason=propertyChanged,deviceID={device_id},node={node_id},property={property_id},value={payload_str}" @@ -4399,6 +4620,25 @@ def _on_property_message(self, device_id: str, topic: str, payload: bytes) -> No if self._on_property_changed: self._on_property_changed(device_id, node_id, property_id, payload_str, old_value) + def _note_burst_message(self, device_id: str, key: tuple) -> None: + """Count a value or $target toward a slot holder's burst. + + Every value and target its description allows has arrived: the burst is over. + Usually the resubscribed $description ends it instead, because $target is optional. + """ + with self._pacing_lock: + watch = self._watches.get(device_id) + if watch is None or (watch.nodes is not None and key[0] not in watch.nodes): + return + if key in watch.received_values: + return + watch.received_values.add(key) + if watch.owed == 0: + self._release_slot_locked(device_id) + # Less is owed now, so the next pending device may fit the value budget. + started = self._take_pending_locked() if self._pending_subscriptions else [] + self._start_subscriptions(started) + def _on_target_message(self, device_id: str, topic: str, payload: bytes) -> None: """ Handle property $target messages @@ -4420,6 +4660,7 @@ def _on_target_message(self, device_id: str, topic: str, payload: bytes) -> None payload_str = decode_empty_string(payload_str) device = self.devices[device_id] device.update_property_target(node_id, property_id, payload_str) + self._note_burst_message(device_id, (node_id, property_id, "$target")) logger.debug( f"reason=targetChanged,deviceID={device_id},node={node_id},property={property_id},target={payload_str}" @@ -4721,6 +4962,9 @@ def stop(self) -> None: self._watches.clear() self._pending_subscriptions.clear() self._description_markers.clear() + self._property_coverage.clear() + self._stuck_timer_stop.set() + self._stuck_timer = None # Clear callback references to break reference cycles self._on_device_discovered = None self._on_device_state_changed = None diff --git a/src/ebus_sdk/transport.py b/src/ebus_sdk/transport.py index 7dbaddf..ee03ede 100644 --- a/src/ebus_sdk/transport.py +++ b/src/ebus_sdk/transport.py @@ -52,6 +52,15 @@ class MqttControllerTransport(MqttTransport, Protocol): ``is_connected``, ``is_running`` and ``publish_and_flush`` are absent because nothing on the ``Controller`` path calls them — they belong to the ``Device`` / ``Property`` path, which types its own injection point with ``MqttDeviceTransport`` below. + + ``Controller`` is unpaced on an injected transport unless given + ``subscription_batch_size``. Pacing requires that subscribing a filter again + delivers its retained messages again, as a broker connection does: the end of a + device's burst is the retained ``$description`` resubscribed behind its property + filters. A ``subscribe`` that takes a keyword-only ``with_retain`` (ebus-mqtt-client + 0.7.0) is called with ``with_retain=True`` for ``$description`` and must then pass + the retain flag as a third callback argument, so a live republish is not taken for + that marker. """ def unsubscribe(self, sub: str) -> object: ... diff --git a/tests/test_controller.py b/tests/test_controller.py index f87e2ea..0c48497 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -1,10 +1,12 @@ """Tests for ebus_sdk.homie.Controller and DiscoveredDevice.""" import json +import time from unittest.mock import MagicMock, patch from ebus_sdk.homie import ( + CONTROLLER_SUBSCRIPTION_BATCH_SIZE, Controller, DiscoveredDevice, DeviceState, @@ -848,7 +850,7 @@ def test_wildcard_per_device_subscribe_uses_custom_qos(self, mock_paho): ctrl._on_state_message(f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/panel-2/$state", b"ready") _push_description(ctrl, "panel-2", {"homie": "5.0"}) - assert mock_client.subscribe.call_count == 4 # $description, then +/+, +/+/$target, $description + assert mock_client.subscribe.call_count == 3 # $description, then +/+, +/+/$target; nothing owed, no marker for c in mock_client.subscribe.call_args_list: _, kwargs = c assert kwargs["qos"] == 1 @@ -865,12 +867,13 @@ def _push_state(ctrl, device_id, state): ) -def _push_description(ctrl, device_id, description): - """Push a $description retained message into the controller.""" +def _push_description(ctrl, device_id, description, retained=None): + """Push a $description message into the controller (retained=None: a transport without the flag).""" ctrl._on_description_message( device_id, f"{EBUS_HOMIE_DOMAIN}/{EBUS_HOMIE_VERSION_MAJOR}/{device_id}/$description", json.dumps(description).encode(), + retained, ) @@ -1554,7 +1557,11 @@ def test_on_tree_ready_survives_a_raising_callback(self, mock_paho): def _make_paced_controller(root_device_id="panel-1", **kwargs): - """A Controller on a mock transport that records calls and delivers nothing by itself.""" + """A Controller on a mock transport that records calls and delivers nothing by itself. + + Paced at the owned-client default unless told otherwise: an injected transport is unpaced by default. + """ + kwargs.setdefault("subscription_batch_size", CONTROLLER_SUBSCRIPTION_BATCH_SIZE) client = MagicMock() ctrl = Controller(mqttc=client, root_device_id=root_device_id, **kwargs) return ctrl, client @@ -1608,9 +1615,19 @@ def _deliver_properties(ctrl, child_id, props=2): ctrl._on_property_message(child_id, _topic(child_id, f"n/p{i}"), b"1") +def _deliver_marker(ctrl, child_id, props=2): + """The $description the broker resends behind the property burst.""" + _push_description(ctrl, child_id, _child_desc(child_id, props)) + + +def _drain(ctrl, child_id, props=2): + _deliver_properties(ctrl, child_id, props) + _deliver_marker(ctrl, child_id, props) + + def _deliver(ctrl, child_id, props=2): _deliver_attributes(ctrl, child_id, props) - _deliver_properties(ctrl, child_id, props) + _drain(ctrl, child_id, props) class TestSubscriptionPacing: @@ -1634,18 +1651,40 @@ def test_default_batch_bounds_the_property_fan_out(self): assert _property_subscribed(client) == ["panel-1"] + children[:8] - def test_slot_frees_when_every_retained_value_arrives(self): + def test_slot_frees_when_every_value_and_target_arrives(self): ctrl, client = _make_paced_controller(subscription_batch_size=2) _announce_root(ctrl, ["a", "b", "c"]) for child in ("a", "b", "c"): _deliver_attributes(ctrl, child) assert _property_subscribed(client) == ["panel-1", "a", "b"] - ctrl._on_property_message("a", _topic("a", "n/p0"), b"1") - assert _property_subscribed(client) == ["panel-1", "a", "b"] # one of two values - ctrl._on_property_message("a", _topic("a", "n/p1"), b"1") + _deliver_properties(ctrl, "a") + assert _property_subscribed(client) == ["panel-1", "a", "b"] # its $target burst may follow + ctrl._on_target_message("a", _topic("a", "n/p0/$target"), b"1") + assert _property_subscribed(client) == ["panel-1", "a", "b"] + ctrl._on_target_message("a", _topic("a", "n/p1/$target"), b"1") assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] + def test_values_alone_hold_the_slot_until_the_marker(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") + _deliver_properties(ctrl, "a") + assert _property_subscribed(client) == ["panel-1", "a"] + _deliver_marker(ctrl, "a") + assert _property_subscribed(client) == ["panel-1", "a", "b"] + + def test_targets_count_toward_the_value_budget(self): + # Two properties may owe two values and two targets: 4 messages. + ctrl, client = _make_paced_controller(subscription_batch_values=7) + _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "a") + _deliver_attributes(ctrl, "b") + assert _property_subscribed(client) == ["panel-1", "a"] + _deliver_properties(ctrl, "a") + assert _property_subscribed(client) == ["panel-1", "a", "b"] # a owes 2 targets; 2 + 4 fits + def test_description_resubscribed_behind_the_property_filters(self): ctrl, client = _make_paced_controller(subscription_batch_size=1) _announce_root(ctrl, ["a"]) @@ -1684,25 +1723,82 @@ def test_changed_description_in_the_marker_slot_is_processed(self): assert len(ctrl.devices["a"].description["nodes"]["n"]["properties"]) == 3 def test_value_budget_bounds_the_batch(self): - ctrl, client = _make_paced_controller(subscription_batch_size=8, subscription_batch_values=5) + ctrl, client = _make_paced_controller(subscription_batch_size=8, subscription_batch_values=11) _announce_root(ctrl, ["a", "b", "c"]) for child in ("a", "b", "c"): _deliver_attributes(ctrl, child, props=3) - assert _property_subscribed(client) == ["panel-1", "a"] # 3 + 3 owed would exceed 5 + assert _property_subscribed(client) == ["panel-1", "a"] # 6 + 6 owed would exceed 11 - _deliver_properties(ctrl, "a", props=3) + _drain(ctrl, "a", props=3) assert _property_subscribed(client) == ["panel-1", "a", "b"] # b fits; b and c would not - _deliver_properties(ctrl, "b", props=3) + _drain(ctrl, "b", props=3) assert _property_subscribed(client) == ["panel-1", "a", "b", "c"] def test_device_over_the_value_budget_starts_alone(self): ctrl, client = _make_paced_controller(subscription_batch_values=5) _announce_root(ctrl, ["big", "small"]) - _deliver_attributes(ctrl, "big", props=9) + _push_state(ctrl, "big", "ready") + _push_description( + ctrl, "big", {"homie": "5.0", "nodes": {"n": {"properties": {f"p{i}": {} for i in range(9)}}}} + ) + _deliver_attributes(ctrl, "small", props=1) + assert _property_subscribed(client) == ["panel-1"] # big's one node goes alone, as n/+ + assert _topic("big", "n/+") in {c[0][0] for c in client.subscribe.call_args_list} + assert ctrl._watches.keys() == {"big"} + _push_description(ctrl, "big", ctrl.devices["big"].description) + assert _property_subscribed(client) == ["panel-1", "small"] + + def test_device_over_the_value_budget_is_subscribed_node_by_node(self): + ctrl, client = _make_paced_controller(subscription_batch_values=8) + _announce_root(ctrl, ["big", "small"]) + nodes = {f"n{k}": {"properties": {f"p{i}": {} for i in range(2)}} for k in range(5)} + desc = {"homie": "5.0", "nodes": nodes} + _push_state(ctrl, "big", "ready") + _push_description(ctrl, "big", desc) _deliver_attributes(ctrl, "small", props=1) - assert _property_subscribed(client) == ["panel-1", "big"] - _deliver_properties(ctrl, "big", props=9) - assert _property_subscribed(client) == ["panel-1", "big", "small"] + + def chunks(): + return [ + c[0][0].split("/", 3)[3] + for c in client.subscribe.call_args_list + if "/big/" in c[0][0] and c[0][0].endswith("/+") + ] + + assert chunks() == ["n0/+", "n1/+"] # 2 nodes x 2 properties x (value + target) = 8 + _push_description(ctrl, "big", desc) # the marker behind the first chunk + assert chunks() == ["n0/+", "n1/+", "n2/+", "n3/+"] + assert "small" not in ctrl._watches # the next chunk went first, and owes 8 + _push_description(ctrl, "big", desc) + assert chunks() == ["n0/+", "n1/+", "n2/+", "n3/+", "n4/+"] + assert "small" in ctrl._watches # 4 + 2 fits + _push_description(ctrl, "big", desc) + assert ctrl._watches.keys() == {"small"} + assert _topic("big", "+/+") not in {c[0][0] for c in client.subscribe.call_args_list} + + # Its per-node filters route values like the whole-device ones, and are unsubscribed on drop. + callbacks = {c[0][0]: c[1]["param"] for c in client.subscribe.call_args_list} + callbacks[_topic("big", "n3/+")](_topic("big", "n3/p1"), b"7") + assert ctrl.devices["big"].get_property("n3", "p1") == "7" + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["small"]}) + _push_state(ctrl, "panel-1", "ready") + assert not {t for t in _final_subscriptions(client) if "/big/" in t} + + def test_new_node_of_a_device_subscribed_node_by_node_is_subscribed(self): + ctrl, client = _make_paced_controller(subscription_batch_values=4) + _announce_root(ctrl, ["big"]) + desc = {"homie": "5.0", "nodes": {f"n{k}": {"properties": {f"p{i}": {} for i in range(2)}} for k in range(2)}} + _push_state(ctrl, "big", "ready") + _push_description(ctrl, "big", desc) + _push_description(ctrl, "big", desc) + _push_description(ctrl, "big", desc) + assert ctrl._watches == {} + + desc["nodes"]["n2"] = {"properties": {"p0": {}}} + _push_state(ctrl, "big", "init") + _push_description(ctrl, "big", desc) + _push_state(ctrl, "big", "ready") + assert _topic("big", "n2/+") in {c[0][0] for c in client.subscribe.call_args_list} def test_no_value_budget_counts_devices_only(self): ctrl, client = _make_paced_controller(subscription_batch_size=3, subscription_batch_values=None) @@ -1720,7 +1816,58 @@ def test_non_retained_properties_are_not_owed(self): _push_description(ctrl, "a", desc) _deliver_attributes(ctrl, "b") ctrl._on_property_message("a", _topic("a", "n/p0"), b"1") + ctrl._on_target_message("a", _topic("a", "n/p0/$target"), b"1") + assert _property_subscribed(client) == ["panel-1", "a", "b"] + + def test_injected_transport_is_unpaced_by_default(self): + client = MagicMock() + ctrl = Controller(mqttc=client, root_device_id="panel-1") + _announce_root(ctrl, ["a", "b"]) + topics = {c[0][0] for c in client.subscribe.call_args_list} + assert _filters_for("a") <= topics and _filters_for("b") <= topics + + def test_owned_client_is_paced_by_default(self, mock_paho): + ctrl, _ = _make_controller(mock_paho, root_device_id="panel-1") + try: + assert ctrl._subscription_batch_size == CONTROLLER_SUBSCRIPTION_BATCH_SIZE + finally: + ctrl.stop() + + def test_live_description_is_not_the_marker(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + received = [] + ctrl.set_on_description_received_callback(lambda d: received.append(d.device_id)) + _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "a", props=4) + _deliver_attributes(ctrl, "b") + received.clear() + + _push_description(ctrl, "a", _child_desc("a", props=6), retained=False) # republished live + assert _property_subscribed(client) == ["panel-1", "a"] + assert ctrl._watches["a"].expected_values == 6 + assert received == ["a"] + + _push_description(ctrl, "a", _child_desc("a", props=6), retained=True) # the marker assert _property_subscribed(client) == ["panel-1", "a", "b"] + assert received == ["a"] + + def test_description_subscribed_with_the_retain_flag_when_supported(self): + calls = [] + + class Transport: + def publish(self, topic, data, qos=1, retain=False): + pass + + def subscribe(self, sub, param, qos=1, *, with_retain=False): + calls.append((sub, with_retain)) + + def unsubscribe(self, sub): + pass + + ctrl = Controller(mqttc=Transport(), root_device_id="panel-1", subscription_batch_size=8) + _announce_root(ctrl, ["a"]) + flags = {sub.split("/", 3)[3]: flag for sub, flag in calls if "/a/" in sub} + assert flags == {"$state": False, "$description": True} @pytest.mark.parametrize("values", [0, -1]) def test_value_budget_below_one_rejected(self, values): @@ -1768,7 +1915,7 @@ def test_wildcard_discovery_is_paced(self): _push_description(ctrl, d, desc) assert _property_subscribed(client) == ["d0", "d1"] - ctrl._on_property_message("d0", _topic("d0", "n/p"), b"1") + _push_description(ctrl, "d0", desc) assert _property_subscribed(client) == ["d0", "d1", "d2"] def test_unbounded_subscribes_every_filter_at_once(self): @@ -1956,9 +2103,56 @@ def test_retry_bound(self, caplog): assert "reason=stuckDeviceGaveUp,deviceID=a,missing=$state+$description,attempts=2" in caplog.text assert caplog.text.count("reason=stuckDeviceGaveUp") == 1 assert len(client.unsubscribe.call_args_list) == 4 - # Given up, not unsubscribed: a device that appears later is still discovered. - _deliver(ctrl, "a") + # Given up, not unsubscribed: a device that appears later is still discovered, + # and gets its property filters. + _deliver_attributes(ctrl, "a") assert ctrl.devices["a"].description is not None + assert _topic("a", "+/+") in {c[0][0] for c in client.subscribe.call_args_list} + _drain(ctrl, "a") + assert ctrl.devices["a"].get_property("n", "p1") == "1" + + def test_device_given_up_in_stage_one_does_not_wait_behind_others(self): + ctrl, client = _make_paced_controller(subscription_batch_size=1, max_resubscribe_attempts=0) + _announce_root(ctrl, ["late", "b"]) + ctrl.check_stuck_children(timeout=0) # late gives up at once + _deliver_attributes(ctrl, "late") + assert _property_subscribed(client) == ["panel-1", "late"] + + def test_wildcard_device_given_up_in_stage_one_gets_its_property_filters(self): + client = MagicMock() + ctrl = Controller(mqttc=client, subscription_batch_size=8, max_resubscribe_attempts=0) + ctrl.start_discovery() + _push_state(ctrl, "d0", "lost") # a leftover $state, no $description + ctrl.check_stuck_children(timeout=0) + assert ctrl._awaiting_attributes == {} + _push_state(ctrl, "d0", "ready") + _push_description(ctrl, "d0", {"homie": "5.0", "nodes": {"n": {"properties": {"p": {}}}}}) + assert _property_subscribed(client) == ["d0"] + + def test_retry_that_made_no_progress_is_not_retried_again(self, caplog): + ctrl, client = _make_paced_controller(subscription_batch_size=1) + _announce_root(ctrl, ["a", "b"]) + _deliver_attributes(ctrl, "a", props=4) + _deliver_attributes(ctrl, "b") + ctrl._on_property_message("a", _topic("a", "n/p0"), b"1") + with caplog.at_level("WARNING", logger="homie"): + assert ctrl.check_stuck_children(timeout=0) == ["a"] # b starts, a waits + _drain(ctrl, "b") + ctrl._on_property_message("a", _topic("a", "n/p0"), b"1") # the retry gets no further + assert ctrl.check_stuck_children(timeout=0) == [] + assert "reason=stuckDeviceGaveUp,deviceID=a,missing=properties,received=1/4,attempts=1,noProgress=true" in ( + caplog.text + ) + assert ctrl._watches == {} and ctrl._pending_subscriptions == {} + + def test_given_up_chunk_moves_on_to_the_next_nodes(self): + ctrl, client = _make_paced_controller(subscription_batch_values=4, max_resubscribe_attempts=0) + _announce_root(ctrl, ["big"]) + desc = {"homie": "5.0", "nodes": {f"n{k}": {"properties": {f"p{i}": {} for i in range(2)}} for k in range(2)}} + _push_state(ctrl, "big", "ready") + _push_description(ctrl, "big", desc) + ctrl.check_stuck_children(timeout=0) # n0's marker never came + assert ctrl._watches["big"].nodes == ("n1",) def test_zero_attempts_only_logs(self, caplog): ctrl, client = _make_paced_controller(subscription_batch_size=1, max_resubscribe_attempts=0) @@ -1982,8 +2176,8 @@ def test_slot_holder_is_requeued_not_resubscribed_at_once(self, caplog): assert _property_subscribed(client) == ["b"] # a's slot went to b; a waits its turn client.unsubscribe.assert_not_called() - _deliver_properties(ctrl, "b") - _deliver_properties(ctrl, "c") + _drain(ctrl, "b") + _drain(ctrl, "c") assert _property_subscribed(client) == ["b", "c", "a"] assert {c[0][0] for c in client.unsubscribe.call_args_list} == { _topic("a", "+/+"), @@ -2050,7 +2244,7 @@ def test_disabled_timeout_skips_the_message_check(self): def test_wildcard_resubscribe_leaves_the_state_wildcard_alone(self): client = MagicMock() - ctrl = Controller(mqttc=client) + ctrl = Controller(mqttc=client, subscription_batch_size=8) ctrl.start_discovery() _push_state(ctrl, "d0", "ready") client.reset_mock() @@ -2058,6 +2252,25 @@ def test_wildcard_resubscribe_leaves_the_state_wildcard_alone(self): assert ctrl.check_stuck_children(timeout=0) == ["d0"] assert {c[0][0] for c in client.unsubscribe.call_args_list} == {_topic("d0", "$description")} + def test_owned_client_runs_the_check_from_a_timer(self, mock_paho): + ctrl, _ = _make_controller(mock_paho, root_device_id="panel-1") + ctrl._stuck_device_timeout = 0.01 + try: + with patch.object(ctrl, "check_stuck_children") as check: + ctrl.start_discovery() # the root awaits its retained messages + deadline = time.monotonic() + 2 + while not check.called and time.monotonic() < deadline: + time.sleep(0.01) + assert check.called + finally: + ctrl.stop() + assert ctrl._stuck_timer is None + + def test_injected_client_gets_no_timer(self): + ctrl, _ = _make_paced_controller() + ctrl.start_discovery() + assert ctrl._stuck_timer is None + def test_stuck_root_is_healed(self): ctrl, client = _make_paced_controller() ctrl.start_discovery() diff --git a/tests/test_controller_real_broker.py b/tests/test_controller_real_broker.py index 8f8bc91..64905de 100644 --- a/tests/test_controller_real_broker.py +++ b/tests/test_controller_real_broker.py @@ -114,11 +114,13 @@ def __init__(self, port): def pub(self, topic, payload): self.infos.append(self.client.publish(topic, payload, qos=1, retain=True)) - def device(self, device_id, properties, children=None, root=None): + def device(self, device_id, properties, children=None, root=None, targets=False): self.pub(f"{BASE}/{device_id}/$description", json.dumps(_description(device_id, properties, children, root))) for n in range(NODES_PER_DEVICE): for p in range(properties // NODES_PER_DEVICE): self.pub(f"{BASE}/{device_id}/node-{n}/p{p:03d}", str(n * 1000 + p)) + if targets: + self.pub(f"{BASE}/{device_id}/node-{n}/p{p:03d}/$target", str(n * 1000 + p)) self.pub(f"{BASE}/{device_id}/$state", "ready") def close(self): @@ -130,14 +132,14 @@ def close(self): self.client.disconnect() -def _seed_tree(port, properties, silent_children=0): - """A root declaring `silent_children` children that never publish, then CHILDREN real ones.""" +def _seed_tree(port, properties, silent_children=0, targets=False, children=CHILDREN): + """A root declaring `silent_children` children that never publish, then `children` real ones.""" seeder = _Seeder(port) try: - children = [f"busy-child-{i:02d}" for i in range(CHILDREN)] + children = [f"busy-child-{i:02d}" for i in range(children)] silent = [f"silent-child-{i:02d}" for i in range(silent_children)] for child in children: - seeder.device(child, properties, root=ROOT_ID) + seeder.device(child, properties, root=ROOT_ID, targets=targets) seeder.device(ROOT_ID, 0, children=silent + children) finally: seeder.close() @@ -225,3 +227,68 @@ def test_state_only_leftovers_do_not_stall_a_quiet_wildcard_bus(broker): _await_discovery(ctrl, devices, 60, timeout=8.0) finally: ctrl.stop() + + +def _targets(ctrl, device_id): + device = ctrl.get_device(device_id) + return 0 if device is None else sum(len(t) for t in device.property_targets.values()) + + +def test_retained_targets_of_a_busy_tree_all_arrive(broker): + """Every property also carries a retained $target, doubling each device's burst.""" + children = _seed_tree(broker, 150, targets=True) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}, root_device_id=ROOT_ID) + try: + ctrl.start_discovery() + _await_discovery(ctrl, children, 150) + deadline = time.monotonic() + 10 + while time.monotonic() < deadline and sum(_targets(ctrl, c) for c in children) < 150 * CHILDREN: + time.sleep(0.1) + assert sum(_targets(ctrl, c) for c in children) == 150 * CHILDREN + finally: + ctrl.stop() + + +def test_devices_larger_than_the_broker_queue_are_discovered_on_a_quiet_tree(broker): + """Each child alone overflows the per-client queue, so it is subscribed node by node. + + Nothing publishes after seeding and nobody calls check_stuck_children(). + """ + children = _seed_tree(broker, 1500, children=3) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker}, root_device_id=ROOT_ID) + try: + ctrl.start_discovery() + _await_discovery(ctrl, children, 1500, timeout=20.0) + finally: + ctrl.stop() + + +def test_child_that_appears_after_giving_up_gets_its_values(broker): + """A declared child silent past the stuck-check retries, then published, gets its property values.""" + seeder = _Seeder(broker) + try: + seeder.device(ROOT_ID, 0, children=["late-child"]) + finally: + seeder.close() + ctrl = Controller( + mqtt_cfg={"host": "127.0.0.1", "port": broker}, + root_device_id=ROOT_ID, + stuck_device_timeout=0.2, + max_resubscribe_attempts=1, + ) + try: + ctrl.start_discovery() + deadline = time.monotonic() + 10 + while time.monotonic() < deadline and ( + "late-child" not in ctrl.devices or "late-child" in ctrl._awaiting_attributes + ): + time.sleep(0.05) + assert "late-child" not in ctrl._awaiting_attributes # given up + seeder = _Seeder(broker) + try: + seeder.device("late-child", 6, root=ROOT_ID) + finally: + seeder.close() + _await_discovery(ctrl, ["late-child"], 6, timeout=5.0) + finally: + ctrl.stop() From 6c2a12d443ee4ae74c64f1fe637dcddddb456ab0 Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 14:24:51 -0700 Subject: [PATCH 5/7] Controller: pace the reconnect replay; rediscover returning tree devices (#97) On disconnect, a client the Controller built unsubscribes every discovered device's own filters, so its reconnect recovery resubscribes only the wildcard discovery filter or the tree root's filters. Wildcard resync() then restarts stage one for each device left without filters, waiting for a fresh $description before pacing its property filters; tree-rooted resync() already re-walks. Values changed during an outage now all arrive, and a large tree no longer stalls for stuck_device_timeout after a reconnect. A tree device that clears its $state keeps its $state/$description filters and drops its property filters. When it returns while still declared, or its parent declares it again, it is tracked again. _unsubscribe_and_drop now prunes and unsubscribes a device already gone from the registry. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- CHANGELOG.md | 4 +- src/ebus_sdk/homie.py | 149 +++++++++++++++++++++++---- tests/test_controller.py | 132 ++++++++++++++++++++++++ tests/test_controller_real_broker.py | 91 ++++++++++++++++ 4 files changed, 352 insertions(+), 24 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 015f6ce..8877b4d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -39,9 +39,9 @@ Homie 5 compliance, phase 1: producer wire correctness ([#95](https://github.com ### Fixed - `delete()` followed by `stop()` re-created the deleted device as a bare `$state=disconnected` with no `$description` (:272, :288). After `delete()` the root's `stop()` announces nothing, flushes `delete()`'s retained clears and disconnects cleanly in either mode, and a reconnect's `refresh_tree()` republishes nothing. -- A `Controller` could miss retained `$state`, `$description` and property values of some devices for good. It subscribed to every device at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes each tree descendant's `$state` and `$description` (in wildcard discovery, its `$description`) as soon as the device is known, and its property filters once both have arrived, at most `subscription_batch_size` devices and `subscription_batch_values` retained messages at a time, counting a value and a possible `$target` per retained property. A device larger than `subscription_batch_values` on its own is subscribed node by node (`{node}/+` and `{node}/+/$target`) in chunks that fit. The next device starts when an earlier one's `$description`, resubscribed behind its property filters, arrives again (a live republish of `$description`, told apart by the retain flag from ebus-mqtt-client 0.7.0, does not count), or when every value and `$target` it can owe has arrived. A declared child that never publishes, or a leftover `$state` with no `$description`, holds no slot. All 30 children are described with every value at 60, 150 and 300 values per child, with every `$target` at 150 values and targets per child, and three children of 1500 values each get every value. Pacing is the default only for a client the Controller builds; an injected `mqttc` is unpaced unless `subscription_batch_size` is passed, because pacing needs a resubscribe to replay retained messages, which a transport that only records subscriptions does not do. `subscription_batch_size=None` restores the unpaced fan-out. The tree root and the single device of single-device mode are subscribed unpaced ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- A `Controller` could miss retained `$state`, `$description` and property values of some devices for good. It subscribed to every device at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes each tree descendant's `$state` and `$description` (in wildcard discovery, its `$description`) as soon as the device is known, and its property filters once both have arrived, at most `subscription_batch_size` devices and `subscription_batch_values` retained messages at a time, counting a value and a possible `$target` per retained property. A device larger than `subscription_batch_values` on its own is subscribed node by node (`{node}/+` and `{node}/+/$target`) in chunks that fit. The next device starts when an earlier one's `$description`, resubscribed behind its property filters, arrives again (a live republish of `$description`, told apart by the retain flag from ebus-mqtt-client 0.7.0, does not count), or when every value and `$target` it can owe has arrived. A declared child that never publishes, or a leftover `$state` with no `$description`, holds no slot. All 30 children are described with every value at 60, 150 and 300 values per child, with every `$target` at 150 values and targets per child, and three children of 1500 values each get every value. Pacing is the default only for a client the Controller builds; an injected `mqttc` is unpaced unless `subscription_batch_size` is passed, because pacing needs a resubscribe to replay retained messages, which a transport that only records subscriptions does not do. `subscription_batch_size=None` restores the unpaced fan-out. The tree root and the single device of single-device mode are subscribed unpaced. A reconnect is paced too: when a client the Controller built disconnects, it unsubscribes every discovered device's own filters, so the client's reconnect recovery resubscribes only the wildcard discovery filter or the tree root's filters, and the devices are subscribed again as on first discovery. In wildcard mode `resync()` now does that for every device left without filters; in tree-rooted mode its re-walk already did. Values changed during an outage on a 30-device bus with 150 values each now all arrive; before, 24 of 30 devices kept their pre-outage values, and a large tree stalled for `stuck_device_timeout` after each reconnect ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). - With pacing, a device's property values are not tracked until its `$description` arrives, and `on_tree_ready` / `is_tree_complete()` (every declared device described) come before descendants' retained property values, which arrive afterwards through `on_property_changed`. Unpaced, the subscribe order happened to deliver most of them first ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). -- In tree-rooted mode a `$state` for a device the tree does not declare (a late retained message on the filters of a dropped descendant) is ignored and that device's filters are unsubscribed; `on_device_discovered` no longer fires for it. It used to be registered as a new device ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- In tree-rooted mode a `$state` for a device the tree does not declare (a late retained message on the filters of a dropped descendant) is ignored and that device's filters are unsubscribed; `on_device_discovered` no longer fires for it. It used to be registered as a new device. A tree device that clears its `$state` keeps its `$state` and `$description` filters and loses its property filters; when it publishes `$state` again while still declared by its parent, or its parent declares it again, it is tracked and discovered again ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ## [0.24.0] — 2026-10-03 diff --git a/src/ebus_sdk/homie.py b/src/ebus_sdk/homie.py index 270169c..6a236a1 100644 --- a/src/ebus_sdk/homie.py +++ b/src/ebus_sdk/homie.py @@ -3596,6 +3596,13 @@ def _node_filters(nodes) -> tuple: return tuple(f for node in nodes for f in (f"{node}/+", f"{node}/+/$target")) +def _coverage_filters(coverage) -> tuple: + """Property filter suffixes that may be subscribed for a Controller._property_coverage value.""" + if coverage is None or coverage == _ALL_NODES: + return _PROPERTY_FILTERS + return _PROPERTY_FILTERS + _node_filters(sorted(coverage)) + + @dataclass class _SubscriptionWatch: """A subscribed device awaiting its retained messages. @@ -3613,6 +3620,9 @@ class _SubscriptionWatch: received_values: set = field(default_factory=set) nodes: Optional[tuple] = None last_received: Optional[int] = None + # Stage one after a reconnect: the device's $description must arrive again, even + # though a stale one is on record, before its property filters are paced. + refresh: bool = False @property def owed(self) -> int: @@ -3875,8 +3885,45 @@ def _handle_disconnect(self, rc=None) -> None: ``on_disconnect(clean: bool)`` hook is notified (SDK-al5). """ logger.info(f"reason=controllerDisconnect,transportRc={rc}") + try: + self._drop_device_subscriptions() + except Exception: + logger.exception("reason=dropDeviceSubscriptionsException") _dispatch_disconnect(self._on_disconnect, rc, "controller") + def _drop_device_subscriptions(self) -> None: + """Remove every discovered device's own filters from the owned client while it is down. + + On reconnect the client resubscribes everything it holds at once, which is the + retained-message flood pacing exists to prevent (GH #97). Dropping the per-device + filters here leaves it only the discovery filter (wildcard) or the root's filters + (tree-rooted), and resync() re-paces the devices. Unpaced and single-device + controllers keep their filters. + """ + client = self._owned_client + if client is None or not getattr(client, "is_running", False) or not self._paced or self.device_id: + return + wildcard = not self.is_tree_rooted + attributes = _WILDCARD_ATTRIBUTE_FILTERS if wildcard else _ATTRIBUTE_FILTERS + with self._pacing_lock: + ids = ( + set(self.devices) + | set(self._property_coverage) + | set(self._awaiting_attributes) + | set(self._pending_subscriptions) + | set(self._watches) + ) + ids.discard(self.root_device_id) + coverage = {d: self._property_coverage.pop(d, None) for d in ids} + for d in ids: + self._awaiting_attributes.pop(d, None) + self._pending_subscriptions.clear() + self._watches.clear() + self._description_markers.clear() + for device_id in sorted(ids): + self._unsubscribe_filters(device_id, attributes + _coverage_filters(coverage[device_id])) + logger.info(f"reason=deviceSubscriptionsDropped,devices={len(ids)}") + @property def qos(self) -> int: """Returns the MQTT QoS level for this controller""" @@ -3901,8 +3948,13 @@ def resync(self) -> None: ``$state``/``$description`` the broker replays after a (re)connect drives a clean re-walk from the root (the state edge that gates descendant discovery is seen rather than short-circuited by stale - state). A no-op in wildcard and single-device modes, where MqttClient's - own sub_callbacks recovery is sufficient. + state). + + In wildcard mode with pacing, a device whose filters were dropped when the + owned client disconnected is subscribed again like a newly discovered one: its + $description first, then its property filters, paced. A device whose filters + are still in place is left alone, so this is a no-op for an injected client + that keeps its own subscriptions. Single-device mode is a no-op. The SDK calls this on every (re)connect for a client it owns. A bring-your-own-transport caller (``Controller(mqttc=...)``) in @@ -3929,6 +3981,29 @@ def resync(self) -> None: # One assignment, so another thread never sees a registry without the root. self._subscribed_children = {} self.devices = {self.root_device_id: DiscoveredDevice(self.root_device_id, self.homie_domain)} + elif not self.device_id and self._paced: + self._repace_wildcard_devices() + + def _repace_wildcard_devices(self) -> None: + """Restart stage one for every known device that has no filters subscribed.""" + restart = [] + with self._pacing_lock: + for device_id in list(self.devices): + if ( + device_id in self._property_coverage + or device_id in self._awaiting_attributes + or device_id in self._pending_subscriptions + or device_id in self._watches + ): + continue + self._awaiting_attributes[device_id] = _SubscriptionWatch( + _WILDCARD_ATTRIBUTE_FILTERS, time.monotonic(), refresh=True + ) + restart.append(device_id) + if restart: + logger.info(f"reason=resyncRepaceDevices,devices={len(restart)}") + for device_id in restart: + self._subscribe_tracked(device_id, _WILDCARD_ATTRIBUTE_FILTERS) def start_discovery(self, homie_domain: Optional[str] = None) -> None: """ @@ -4203,6 +4278,9 @@ def _note_device_progress(self, device_id: str) -> None: if device is None or device.state is None or device.description is None: return with self._pacing_lock: + watch = self._awaiting_attributes.get(device_id) + if watch is not None and watch.refresh: + return self._awaiting_attributes.pop(device_id, None) if not self._paced: return @@ -4225,9 +4303,7 @@ def _forget_subscription(self, device_id: str) -> tuple: coverage = self._property_coverage.pop(device_id, None) started = self._take_pending_locked() if self._paced else [] self._start_subscriptions(started) - if coverage is None or coverage == _ALL_NODES: - return _PROPERTY_FILTERS - return _PROPERTY_FILTERS + _node_filters(sorted(coverage)) + return _coverage_filters(coverage) def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: """Heal subscribed devices whose retained messages have not arrived (GH #97). @@ -4276,7 +4352,9 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: del self._awaiting_attributes[device_id] continue missing = [ - name for name, v in (("$state", device.state), ("$description", device.description)) if v is None + name + for name, v in (("$state", device.state), ("$description", device.description)) + if v is None or (name == "$description" and watch.refresh) ] if not missing: continue # _note_device_progress finishes it @@ -4364,7 +4442,11 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: # Empty payload indicates device removal if not payload_str or len(payload_str) == 0: logger.info(f"reason=deviceRemoved,deviceID={device_id}") - self._forget_subscription(device_id) + property_filters = self._forget_subscription(device_id) + if self.is_tree_rooted and device_id in self.devices: + # Its $state and $description filters stay, so a return is heard; the + # property filters are paced again when it comes back. + self._unsubscribe_filters(device_id, property_filters) if device_id in self.devices: removed_device = self.devices[device_id] del self.devices[device_id] @@ -4372,12 +4454,14 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: self._on_device_removed(removed_device) return - # Tree-rooted mode tracks only what the tree declares. A $state for anything - # else arrives on filters left over from a dropped device: remove them. + # Tree-rooted mode tracks only what the tree declares. A device that cleared its + # $state and is still declared comes back; a $state for anything else arrives on + # filters left over from a dropped device: remove them. if self.is_tree_rooted and device_id not in self.devices: - logger.info(f"reason=untrackedDeviceUnsubscribed,deviceID={device_id}") - self._unsubscribe_filters(device_id, _DEVICE_FILTERS) - return + if not self._readopt_removed_device(device_id): + logger.info(f"reason=untrackedDeviceUnsubscribed,deviceID={device_id}") + self._unsubscribe_filters(device_id, _DEVICE_FILTERS) + return # New or existing device if device_id not in self.devices: @@ -4433,6 +4517,23 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: self._note_device_progress(device_id) + def _readopt_removed_device(self, device_id: str) -> bool: + """Track again a tree device that cleared its $state and has returned. + + True when the device is the root or a child the tree still holds as subscribed. + Its retained $description is requested again, since the one it published before + this $state arrived while it was untracked. + """ + declared = device_id == self.root_device_id or any( + device_id in children for children in self._subscribed_children.values() + ) + if not declared: + return False + logger.info(f"reason=removedDeviceReturned,deviceID={device_id}") + self.devices[device_id] = DiscoveredDevice(device_id, self.homie_domain) + self._request_subscription(device_id, paced=device_id != self.root_device_id) + return True + def _reconcile_descendants(self, device_id: str) -> None: """Diff a device's announced children against what's subscribed (SDK-o1h). @@ -4455,7 +4556,8 @@ def _reconcile_descendants(self, device_id: str) -> None: declared = set(device.children_ids) current = set(self._subscribed_children.get(device_id, set())) - added = declared - current + # A child that cleared its $state is still subscribed but untracked: re-add it. + added = declared - (current & set(self.devices)) removed = current - declared # Declared order, so paced subscriptions follow the description's order. @@ -4478,33 +4580,33 @@ def _unsubscribe_and_drop(self, device_id: str) -> None: Unsubscribes the four topic filters, removes the entry from the registry, and fires on_device_removed (leaves-first so callbacks see a consistent view: when fired for a parent, its children are already - gone). No-op if the device isn't tracked. + gone). A device that already cleared its own $state left the registry + then; it is still unsubscribed and forgotten here, without a second + on_device_removed. """ - if device_id not in self.devices: - return # Snapshot before mutating: collect this device's transitive # descendants from our subscription registry (the authoritative record # of what we subscribed for; doesn't depend on the child's own - # description having arrived). Recurse leaves-first. - children = list(self._subscribed_children.get(device_id, set())) + # description having arrived). Recurse leaves-first. Popped first, so a + # cycle in the declared tree ends here. + children = list(self._subscribed_children.pop(device_id, set())) for child_id in children: self._unsubscribe_and_drop(child_id) - # This device is no longer a parent in our tree - self._subscribed_children.pop(device_id, None) # Remove this device from any parent's subscribed-children set for siblings in self._subscribed_children.values(): siblings.discard(device_id) device = self.devices.pop(device_id, None) - if device is None: - return # Unconditionally: after a reconnect the transport holds filters subscribed in an # earlier connection, whatever the pacing bookkeeping says. property_filters = self._forget_subscription(device_id) self._unsubscribe_filters(device_id, _ATTRIBUTE_FILTERS + property_filters) + if device is None: + return + if self._on_device_removed: try: self._on_device_removed(device) @@ -4549,6 +4651,9 @@ def _on_description_message( # A device holding a slot owes what its new description declares. with self._pacing_lock: + refreshing = self._awaiting_attributes.get(device_id) + if refreshing is not None: + refreshing.refresh = False watch = self._watches.get(device_id) if watch is not None and device.description is not None: counts = _retained_counts(device.description) diff --git a/tests/test_controller.py b/tests/test_controller.py index 0c48497..5db7b0f 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -2301,3 +2301,135 @@ def drop_x_once(topic): assert "x" not in ctrl.devices assert not {t for t in _final_subscriptions(client) if "/x/" in t} + + +class TestRemovedTreeDeviceReturns: + """A tree device that clears its $state and comes back is tracked again.""" + + def test_child_that_returns_directly_is_rediscovered(self): + ctrl, client = _make_paced_controller() + _announce_root(ctrl, ["kid"]) + _deliver(ctrl, "kid") + client.reset_mock() + + _push_state(ctrl, "kid", "") + assert "kid" not in ctrl.devices + assert {c[0][0] for c in client.unsubscribe.call_args_list} == { + _topic("kid", "+/+"), + _topic("kid", "+/+/$target"), + } + + _push_state(ctrl, "kid", "ready") + assert ctrl.devices["kid"].state == "ready" + _push_description(ctrl, "kid", _child_desc("kid")) + assert _filters_for("kid") <= _final_subscriptions(client) | _attribute_filters_for("kid") + assert _property_subscribed(client) == ["kid"] + + def test_child_detached_then_readded_is_rediscovered(self): + ctrl, client = _make_paced_controller() + _announce_root(ctrl, ["kid"]) + _deliver(ctrl, "kid") + _push_state(ctrl, "kid", "") + + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": []}) + _push_state(ctrl, "panel-1", "ready") + assert ctrl._subscribed_children.get("panel-1") == set() + assert not ({_topic("kid", "$state"), _topic("kid", "$description")} & _final_subscriptions(client)) + + client.reset_mock() + _push_state(ctrl, "panel-1", "init") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["kid"]}) + _push_state(ctrl, "panel-1", "ready") + assert "kid" in ctrl.devices + _deliver_attributes(ctrl, "kid") + assert _final_subscriptions(client) == _filters_for("kid") | {_topic("kid", "$description")} + + def test_removed_node_chunked_child_drops_its_node_filters(self): + ctrl, client = _make_paced_controller(subscription_batch_values=4) + _announce_root(ctrl, ["kid"]) + desc = {"homie": "5.0", "nodes": {n: {"properties": {"p0": {}, "p1": {}}} for n in ("a", "b")}} + _push_state(ctrl, "kid", "ready") + _push_description(ctrl, "kid", desc) + assert _topic("kid", "a/+") in _final_subscriptions(client) + + _push_state(ctrl, "kid", "") + live = _final_subscriptions(client) + assert not any(t.startswith(_topic("kid", "")) and t.endswith(("/+", "/$target")) for t in live) + assert {_topic("kid", "$state"), _topic("kid", "$description")} <= live + + +class TestReconnectPacing: + """An owned client drops device filters while down so the reconnect replay is paced (GH #97).""" + + DESC = {"homie": "5.0", "nodes": {"n": {"properties": {"p": {}}}}} + + def _wildcard(self, mock_paho): + ctrl, client = _make_controller(mock_paho) + client.is_running = True + ctrl.start_discovery() + for d in ("d0", "d1"): + _push_state(ctrl, d, "ready") + _push_description(ctrl, d, self.DESC) + ctrl._on_property_message(d, _topic(d, "n/p"), b"1") + _push_description(ctrl, d, self.DESC) # marker + return ctrl, client + + def test_wildcard_disconnect_drops_device_filters(self, mock_paho): + ctrl, client = self._wildcard(mock_paho) + client.reset_mock() + ctrl._handle_disconnect(7) + dropped = {c[0][0] for c in client.unsubscribe.call_args_list} + for d in ("d0", "d1"): + assert {_topic(d, "$description"), _topic(d, "+/+"), _topic(d, "+/+/$target")} <= dropped + assert not any(t.endswith("/+/$state") for t in dropped) + assert ctrl._property_coverage == {} and ctrl._watches == {} + ctrl.stop() + + def test_wildcard_resync_repaces_from_the_description(self, mock_paho): + ctrl, client = self._wildcard(mock_paho) + ctrl._handle_disconnect(7) + client.reset_mock() + ctrl.resync() + assert [c[0][0] for c in client.subscribe.call_args_list] == [ + _topic("d0", "$description"), + _topic("d1", "$description"), + ] + # A replayed $state with a stale description on record does not skip the fresh one. + _push_state(ctrl, "d0", "ready") + assert _property_subscribed(client) == [] + assert ctrl.check_stuck_children(timeout=0) == ["d0", "d1"] + _push_description(ctrl, "d0", self.DESC, retained=True) + assert _property_subscribed(client) == ["d0"] + assert "d0" in ctrl._description_markers + ctrl.stop() + + def test_tree_disconnect_keeps_only_the_root_filters(self, mock_paho): + ctrl, client = _make_controller(mock_paho, root_device_id="panel-1") + client.is_running = True + _announce_root(ctrl, ["a"]) + _deliver(ctrl, "a") + client.reset_mock() + ctrl._handle_disconnect(7) + dropped = {c[0][0] for c in client.unsubscribe.call_args_list} + assert _filters_for("a") <= dropped + assert not any("/panel-1/" in t for t in dropped) + ctrl.stop() + + def test_no_drop_when_stopping_or_unpaced(self, mock_paho): + ctrl, client = self._wildcard(mock_paho) + client.is_running = False + client.reset_mock() + ctrl._handle_disconnect(0) + client.unsubscribe.assert_not_called() + ctrl.stop() + + def test_injected_wildcard_resync_leaves_subscribed_devices_alone(self): + client = MagicMock() + ctrl = Controller(mqttc=client, subscription_batch_size=8) + ctrl.start_discovery() + _push_state(ctrl, "d0", "ready") + _push_description(ctrl, "d0", self.DESC) + client.reset_mock() + ctrl.resync() + client.subscribe.assert_not_called() diff --git a/tests/test_controller_real_broker.py b/tests/test_controller_real_broker.py index 64905de..765dc52 100644 --- a/tests/test_controller_real_broker.py +++ b/tests/test_controller_real_broker.py @@ -292,3 +292,94 @@ def test_child_that_appears_after_giving_up_gets_its_values(broker): _await_discovery(ctrl, ["late-child"], 6, timeout=5.0) finally: ctrl.stop() + + +class _RestartableBroker: + """A persistent mosquitto that can be stopped and restarted on the same port.""" + + def __init__(self, tmp_path): + self.dir = tmp_path + self.port = _free_port() + self.proc = None + + def start(self, port=None): + port = port or self.port + conf = self.dir / "mosquitto.conf" + conf.write_text( + f"listener {port} 127.0.0.1\nallow_anonymous true\n" + f"persistence true\npersistence_location {self.dir}/\npersistence_file mosquitto.db\n" + ) + self.proc = subprocess.Popen([MOSQUITTO, "-c", str(conf)], stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL) + _wait_for_port(port, self.proc) + + def stop(self): + if self.proc is not None: + self.proc.terminate() + try: + self.proc.wait(timeout=5) + except subprocess.TimeoutExpired: + self.proc.kill() + self.proc.wait(timeout=5) + self.proc = None + + +def _new_value(n, p): + return str(n * 1000 + p + 7) + + +@pytest.mark.parametrize("mode", ["wildcard", "tree"]) +def test_values_changed_during_an_outage_arrive_after_reconnect(tmp_path, mode): + """The reconnect replays the retained store paced, so none of it is dropped. + + Every value changes while the Controller is disconnected (on the same broker store, + served on another port), then the broker returns on the original port. + """ + properties = 150 + broker = _RestartableBroker(tmp_path) + broker.start() + ctrl = None + try: + if mode == "tree": + devices = _seed_tree(broker.port, properties) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker.port}, root_device_id=ROOT_ID) + else: + devices = _seed_bus(broker.port, properties) + ctrl = Controller(mqtt_cfg={"host": "127.0.0.1", "port": broker.port}) + ctrl.start_discovery() + _await_discovery(ctrl, devices, properties) + + broker.stop() + offline_port = _free_port() + broker.start(offline_port) + seeder = _Seeder(offline_port) + try: + for device in devices: + for n in range(NODES_PER_DEVICE): + for p in range(properties // NODES_PER_DEVICE): + seeder.pub(f"{BASE}/{device}/node-{n}/p{p:03d}", _new_value(n, p)) + finally: + seeder.close() + broker.stop() + broker.start() + + def fresh(device_id): + device = ctrl.get_device(device_id) + return device is not None and all( + device.get_property(f"node-{n}", f"p{p:03d}") == _new_value(n, p) + for n in range(NODES_PER_DEVICE) + for p in range(properties // NODES_PER_DEVICE) + ) + + # Well inside the 10 s stuck timeout: pacing must settle without a requeue. + deadline = time.monotonic() + 8 + while time.monotonic() < deadline and not ( + all(fresh(d) for d in devices) and not ctrl._watches and not ctrl._pending_subscriptions + ): + time.sleep(0.1) + stale = [d for d in devices if not fresh(d)] + assert stale == [] + assert ctrl._watches == {} and ctrl._pending_subscriptions == {} + finally: + if ctrl is not None: + ctrl.stop() + broker.stop() From c9e97c77036db625d955bd360a767d9a986656ff Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 14:27:59 -0700 Subject: [PATCH 6/7] Controller: stuck_check_thread option for the stuck-check thread (#97) None keeps the default (thread only for a client the SDK builds), False never starts it, True starts it for an injected mqttc. stop() now joins the thread. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- CHANGELOG.md | 2 +- README.md | 2 +- src/ebus_sdk/homie.py | 35 ++++++++++++++++++++---------- tests/test_controller.py | 47 +++++++++++++++++++++++++++++++++++++++- 4 files changed, 72 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8877b4d..892886c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,7 +34,7 @@ Homie 5 compliance, phase 1: producer wire correctness ([#95](https://github.com - Encoders for `datetime` (`datetime`/`date` as ISO 8601, :132), `duration` (`timedelta` as `PTxHxMxS`, :137-144) and `color` (a component tuple in the first `format` color type, :118-123). These fell through to `str()`, which produced `2026-10-08 12:00:00+00:00`, `0:05:00` and `(255, 0, 0)`. - `Device.publish_alert(alert_id, message)`, `Device.clear_alert(alert_id)` and `Device.alerts()`. Alerts publish retained to `$alert/[alert ID]` (:517), are republished on reconnect, and are cleared by `delete()` (:289). - `Device.invalidate_description_cache()`, the `$description` counterpart of `Property.invalidate_publish_cache()`. `clear_retained_topic()` aimed at the device's own `$description` and `delete_all_from_mqtt()` call it, so a later `publish_description()` is no longer suppressed after the topic was cleared. -- `Controller(subscription_batch_size=8, subscription_batch_values=500, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device still lacking `$state` or `$description` after `timeout` seconds has those two filters unsubscribed and resubscribed, so the broker resends them; a device still holding a batch slot after `timeout` gives it up and rejoins the end of the queue. Each device is retried up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` or `reason=stuckDeviceRequeue` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end; a slot holder whose retry received no more than the attempt before it gives up then, with `noProgress=true`. A device that gave up lacking `$state` or `$description` and publishes them later gets its property filters then. Message handling runs the check at most once a second, and so does a daemon timer thread when the Controller built the client; with an injected client on a quiet connection, call it from your own timer. `stuck_device_timeout=None` turns off the automatic check ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- `Controller(subscription_batch_size=8, subscription_batch_values=500, stuck_device_timeout=10.0, max_resubscribe_attempts=3)` and `Controller.check_stuck_children(timeout=None)`. A device still lacking `$state` or `$description` after `timeout` seconds has those two filters unsubscribed and resubscribed, so the broker resends them; a device still holding a batch slot after `timeout` gives it up and rejoins the end of the queue. Each device is retried up to `max_resubscribe_attempts` times, with a `reason=stuckDeviceResubscribe` or `reason=stuckDeviceRequeue` warning per attempt and a `reason=stuckDeviceGaveUp` error at the end; a slot holder whose retry received no more than the attempt before it gives up then, with `noProgress=true`. A device that gave up lacking `$state` or `$description` and publishes them later gets its property filters then. Message handling runs the check at most once a second, and so does a daemon timer thread when the Controller built the client; with an injected client on a quiet connection, call it from your own timer. `Controller(stuck_check_thread=None)` keeps that default; `False` never starts the thread (message handling still runs the check) and `True` starts it for an injected `mqttc` too; `stop()` ends it. `stuck_device_timeout=None` turns off the automatic check and the thread ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ### Fixed diff --git a/README.md b/README.md index f9e254a..47eac0a 100644 --- a/README.md +++ b/README.md @@ -309,7 +309,7 @@ Pacing is on by default for a client the Controller builds from `mqtt_cfg` and o `on_tree_ready` and `is_tree_complete()` mean every declared device has published its `$description`. With pacing, descendants' retained property values arrive after that, through `on_property_changed`. -A device still lacking `$state` or `$description` after `stuck_device_timeout` seconds (default 10) has those two filters unsubscribed and resubscribed, so the broker resends them. A device still holding a slot after that long gives it up and rejoins the end of the queue. Each is retried up to `max_resubscribe_attempts` times (default 3); a slot holder whose retry received no more than the attempt before it is not retried again. Message handling runs this check at most once a second, and so does a timer thread when the Controller built the client. With an injected client on a connection that goes quiet, call it yourself: +A device still lacking `$state` or `$description` after `stuck_device_timeout` seconds (default 10) has those two filters unsubscribed and resubscribed, so the broker resends them. A device still holding a slot after that long gives it up and rejoins the end of the queue. Each is retried up to `max_resubscribe_attempts` times (default 3); a slot holder whose retry received no more than the attempt before it is not retried again. Message handling runs this check at most once a second, and so does a daemon thread named `ebus-controller-stuck-check` when the Controller built the client. `stuck_check_thread=True` starts that thread for an injected `mqttc` too, and `stuck_check_thread=False` never starts it; `stop()` ends it. With an injected client on a connection that goes quiet and no thread, call it yourself: ```python controller = Controller(mqtt_cfg=cfg, root_device_id='panel-1', diff --git a/src/ebus_sdk/homie.py b/src/ebus_sdk/homie.py index 6a236a1..a7b5a9c 100644 --- a/src/ebus_sdk/homie.py +++ b/src/ebus_sdk/homie.py @@ -3702,6 +3702,7 @@ def __init__( subscription_batch_values: Optional[int] = CONTROLLER_SUBSCRIPTION_BATCH_VALUES, stuck_device_timeout: Optional[float] = CONTROLLER_STUCK_DEVICE_TIMEOUT, max_resubscribe_attempts: int = CONTROLLER_MAX_RESUBSCRIBE_ATTEMPTS, + stuck_check_thread: Optional[bool] = None, ): """ Initialize a Homie Controller @@ -3756,13 +3757,20 @@ def __init__( its $state and $description filters are unsubscribed and resubscribed so the broker resends them, or it gives up its slot and waits for another. Message handling runs this check at most - once a second, and so does a timer thread for a client the SDK - builds; see check_stuck_children(). None disables the automatic - check. + once a second, and so does a timer thread when + ``stuck_check_thread`` allows it; see check_stuck_children(). + None disables the automatic check and the thread. max_resubscribe_attempts: Retries per stuck device before it is logged as unrecoverable and no longer checked. 0 only logs. A slot holder whose retry received no more than the attempt before it is not retried again. + stuck_check_thread: Whether start_discovery() starts the daemon + thread "ebus-controller-stuck-check" that runs the stuck check + on a quiet connection. None (default) starts it only for a + client the SDK builds. False never starts it: the caller drives + check_stuck_children(), and message handling still runs the + check. True starts it for an injected ``mqttc`` too. stop() + ends the thread. """ if device_id is not None and root_device_id is not None: raise ValueError( @@ -3810,6 +3818,7 @@ def __init__( self._subscription_batch_values = subscription_batch_values self._stuck_device_timeout = stuck_device_timeout self._max_resubscribe_attempts = max_resubscribe_attempts + self._stuck_check_thread = mqttc is None if stuck_check_thread is None else stuck_check_thread self._pacing_lock = threading.RLock() # Stage one, {device_id: _SubscriptionWatch}: awaiting $state and $description. self._awaiting_attributes: dict = {} @@ -3822,7 +3831,7 @@ def __init__( # {device_id: _ALL_NODES or set of node ids}: whose property filters are subscribed. self._property_coverage: dict = {} self._last_stuck_check = time.monotonic() - # Drives the stuck check for a client the SDK owns, so a quiet connection heals. + # Drives the stuck check when _stuck_check_thread is set, so a quiet connection heals. self._stuck_timer: Optional[threading.Thread] = None self._stuck_timer_stop = threading.Event() @@ -4047,12 +4056,12 @@ def start_discovery(self, homie_domain: Optional[str] = None) -> None: self._start_stuck_timer() def _start_stuck_timer(self) -> None: - """Run the stuck check from a timer thread when the SDK owns the client. + """Run the stuck check from a timer thread when ``stuck_check_thread`` allows it. - An injected client's caller owns its event loop and threads, so it calls - check_stuck_children() itself. + By default an injected client's caller owns its event loop and threads, so it + calls check_stuck_children() itself. """ - if not self._owns_client or self._stuck_device_timeout is None: + if not self._stuck_check_thread or self._stuck_device_timeout is None: return if self._stuck_timer is not None and self._stuck_timer.is_alive(): return @@ -4329,9 +4338,10 @@ def check_stuck_children(self, timeout: Optional[float] = None) -> List[str]: Message handling calls this at most once a second when ``stuck_device_timeout`` is set, and so does a timer thread when the - SDK built the client. With an injected client on a connection that goes - quiet, healing waits for the next message unless you call it from your - own timer or event loop. It is safe to call from any thread. + SDK built the client or ``stuck_check_thread=True`` was passed. With an + injected client on a connection that goes quiet and no such thread, + healing waits for the next message unless you call it from your own + timer or event loop. It is safe to call from any thread. Returns the ids of the devices resubscribed or requeued by this call. """ @@ -5069,6 +5079,9 @@ def stop(self) -> None: self._description_markers.clear() self._property_coverage.clear() self._stuck_timer_stop.set() + timer = self._stuck_timer + if timer is not None and timer is not threading.current_thread(): + timer.join(timeout=2.0) self._stuck_timer = None # Clear callback references to break reference cycles self._on_device_discovered = None diff --git a/tests/test_controller.py b/tests/test_controller.py index 5db7b0f..61edca2 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -1,6 +1,7 @@ """Tests for ebus_sdk.homie.Controller and DiscoveredDevice.""" import json +import threading import time from unittest.mock import MagicMock, patch @@ -356,7 +357,7 @@ def test_one_lost_root_makes_whole_tree_lost(self, mock_paho): # ── Controller ─────────────────────────────────────────────────────────── -def _make_controller(mock_paho, device_id=None, auto_start=False, root_device_id=None): +def _make_controller(mock_paho, device_id=None, auto_start=False, root_device_id=None, **kwargs): """Helper to create a Controller with mocked MQTT.""" with patch("ebus_sdk.homie.MqttClient.from_config") as mock_from_config: mock_client = MagicMock() @@ -368,6 +369,7 @@ def _make_controller(mock_paho, device_id=None, auto_start=False, root_device_id auto_start=auto_start, device_id=device_id, root_device_id=root_device_id, + **kwargs, ) return ctrl, mock_client @@ -2271,6 +2273,49 @@ def test_injected_client_gets_no_timer(self): ctrl.start_discovery() assert ctrl._stuck_timer is None + @staticmethod + def _stuck_threads(): + return {t for t in threading.enumerate() if t.name == "ebus-controller-stuck-check"} + + def _assert_thread(self, ctrl, expected): + """Other tests' controllers may leave their own threads behind, so count only this one's.""" + before = self._stuck_threads() + try: + ctrl.start_discovery() + started = self._stuck_threads() - before + assert len(started) == (1 if expected else 0) + finally: + ctrl.stop() + assert not any(t.is_alive() for t in started) + + def test_stuck_check_thread_default_owned_client(self, mock_paho): + ctrl, _ = _make_controller(mock_paho, root_device_id="panel-1") + self._assert_thread(ctrl, True) + + def test_stuck_check_thread_default_injected_client(self): + ctrl, _ = _make_paced_controller() + self._assert_thread(ctrl, False) + + def test_stuck_check_thread_false_owned_client(self, mock_paho): + ctrl, _ = _make_controller(mock_paho, root_device_id="panel-1", stuck_check_thread=False) + self._assert_thread(ctrl, False) + + def test_stuck_check_thread_true_injected_client(self): + ctrl, _ = _make_paced_controller(stuck_check_thread=True) + self._assert_thread(ctrl, True) + + def test_stuck_check_thread_true_needs_a_timeout(self): + ctrl, _ = _make_paced_controller(stuck_check_thread=True, stuck_device_timeout=None) + self._assert_thread(ctrl, False) + + def test_stuck_check_thread_false_keeps_the_message_check(self): + ctrl, _ = _make_paced_controller(subscription_batch_size=1, stuck_check_thread=False) + _announce_root(ctrl, ["a"]) + ctrl._last_stuck_check = time.monotonic() - 60 + with patch.object(ctrl, "check_stuck_children") as check: + ctrl._on_property_message("panel-1", _topic("panel-1", "n/p"), b"1") + check.assert_called_once() + def test_stuck_root_is_healed(self): ctrl, client = _make_paced_controller() ctrl.start_discovery() From 5f72f41df1411e77618d3c783faafe5c2e444b66 Mon Sep 17 00:00:00 2001 From: Donald Clark Jackson Date: Thu, 8 Oct 2026 14:40:32 -0700 Subject: [PATCH 7/7] Controller: a tree root that clears $state keeps its property filters (#97) 6c2a12d unsubscribed a removed tree device's property filters, the root included. resync() records the root's property filters as subscribed and the returning root takes the already-known branch, so after a reconnect or resync() the root's values never came back. Only descendants lose their property filters now, and the root behaves as on main. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01T32pvgqCzp1qCz7K5gS9Wm --- CHANGELOG.md | 2 +- src/ebus_sdk/homie.py | 5 +++-- tests/test_controller.py | 17 +++++++++++++++++ 3 files changed, 21 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 892886c..21816d3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -41,7 +41,7 @@ Homie 5 compliance, phase 1: producer wire correctness ([#95](https://github.com - `delete()` followed by `stop()` re-created the deleted device as a bare `$state=disconnected` with no `$description` (:272, :288). After `delete()` the root's `stop()` announces nothing, flushes `delete()`'s retained clears and disconnects cleanly in either mode, and a reconnect's `refresh_tree()` republishes nothing. - A `Controller` could miss retained `$state`, `$description` and property values of some devices for good. It subscribed to every device at once, the broker queued every matching retained message for the one client, and past mosquitto's default per-client limit (`max_queued_messages` 1000) it dropped the rest; retained messages are sent only at subscribe time. On a 30-child tree with 60 retained values per child, 17 of 30 children were described. The Controller now subscribes each tree descendant's `$state` and `$description` (in wildcard discovery, its `$description`) as soon as the device is known, and its property filters once both have arrived, at most `subscription_batch_size` devices and `subscription_batch_values` retained messages at a time, counting a value and a possible `$target` per retained property. A device larger than `subscription_batch_values` on its own is subscribed node by node (`{node}/+` and `{node}/+/$target`) in chunks that fit. The next device starts when an earlier one's `$description`, resubscribed behind its property filters, arrives again (a live republish of `$description`, told apart by the retain flag from ebus-mqtt-client 0.7.0, does not count), or when every value and `$target` it can owe has arrived. A declared child that never publishes, or a leftover `$state` with no `$description`, holds no slot. All 30 children are described with every value at 60, 150 and 300 values per child, with every `$target` at 150 values and targets per child, and three children of 1500 values each get every value. Pacing is the default only for a client the Controller builds; an injected `mqttc` is unpaced unless `subscription_batch_size` is passed, because pacing needs a resubscribe to replay retained messages, which a transport that only records subscriptions does not do. `subscription_batch_size=None` restores the unpaced fan-out. The tree root and the single device of single-device mode are subscribed unpaced. A reconnect is paced too: when a client the Controller built disconnects, it unsubscribes every discovered device's own filters, so the client's reconnect recovery resubscribes only the wildcard discovery filter or the tree root's filters, and the devices are subscribed again as on first discovery. In wildcard mode `resync()` now does that for every device left without filters; in tree-rooted mode its re-walk already did. Values changed during an outage on a 30-device bus with 150 values each now all arrive; before, 24 of 30 devices kept their pre-outage values, and a large tree stalled for `stuck_device_timeout` after each reconnect ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). - With pacing, a device's property values are not tracked until its `$description` arrives, and `on_tree_ready` / `is_tree_complete()` (every declared device described) come before descendants' retained property values, which arrive afterwards through `on_property_changed`. Unpaced, the subscribe order happened to deliver most of them first ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). -- In tree-rooted mode a `$state` for a device the tree does not declare (a late retained message on the filters of a dropped descendant) is ignored and that device's filters are unsubscribed; `on_device_discovered` no longer fires for it. It used to be registered as a new device. A tree device that clears its `$state` keeps its `$state` and `$description` filters and loses its property filters; when it publishes `$state` again while still declared by its parent, or its parent declares it again, it is tracked and discovered again ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). +- In tree-rooted mode a `$state` for a device the tree does not declare (a late retained message on the filters of a dropped descendant) is ignored and that device's filters are unsubscribed; `on_device_discovered` no longer fires for it. It used to be registered as a new device. A tree descendant that clears its `$state` keeps its `$state` and `$description` filters and loses its property filters (the root keeps all of its filters); when it publishes `$state` again while still declared by its parent, or its parent declares it again, it is tracked and discovered again ([#97](https://github.com/electrification-bus/python-sdk/issues/97)). ## [0.24.0] — 2026-10-03 diff --git a/src/ebus_sdk/homie.py b/src/ebus_sdk/homie.py index a7b5a9c..cb0bd80 100644 --- a/src/ebus_sdk/homie.py +++ b/src/ebus_sdk/homie.py @@ -4453,9 +4453,10 @@ def _on_state_message(self, topic: str, payload: bytes) -> None: if not payload_str or len(payload_str) == 0: logger.info(f"reason=deviceRemoved,deviceID={device_id}") property_filters = self._forget_subscription(device_id) - if self.is_tree_rooted and device_id in self.devices: + if self.is_tree_rooted and device_id in self.devices and device_id != self.root_device_id: # Its $state and $description filters stay, so a return is heard; the - # property filters are paced again when it comes back. + # property filters are paced again when it comes back. The root keeps + # its property filters: resync() records them as subscribed. self._unsubscribe_filters(device_id, property_filters) if device_id in self.devices: removed_device = self.devices[device_id] diff --git a/tests/test_controller.py b/tests/test_controller.py index 61edca2..6977e85 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -2403,6 +2403,23 @@ def test_removed_node_chunked_child_drops_its_node_filters(self): assert not any(t.startswith(_topic("kid", "")) and t.endswith(("/+", "/$target")) for t in live) assert {_topic("kid", "$state"), _topic("kid", "$description")} <= live + def test_root_that_clears_state_keeps_property_filters_across_resync(self): + ctrl, client = _make_paced_controller() + _announce_root(ctrl, ["kid"]) + _deliver(ctrl, "kid") + root_props = {_topic("panel-1", "+/+"), _topic("panel-1", "+/+/$target")} + assert root_props <= _final_subscriptions(client) + + _push_state(ctrl, "panel-1", "") + assert root_props <= _final_subscriptions(client) + + ctrl.resync() + _push_state(ctrl, "panel-1", "ready") + _push_description(ctrl, "panel-1", {"homie": "5.0", "children": ["kid"]}) + assert root_props <= _final_subscriptions(client) + ctrl.check_stuck_children(timeout=0) + assert root_props <= _final_subscriptions(client) + class TestReconnectPacing: """An owned client drops device filters while down so the reconnect replay is paced (GH #97)."""