diff --git a/majordom_zigbee/controller.py b/majordom_zigbee/controller.py index 8298f14..dc1cb58 100644 --- a/majordom_zigbee/controller.py +++ b/majordom_zigbee/controller.py @@ -80,6 +80,14 @@ # In practice, reading too many attributes at once keeps the serial line busy # long enough to trigger NCP ACK timeouts. _MAX_ATTRS_PER_REQUEST = 25 + + +def _log_task_exception(task: asyncio.Task[Any]): + """Retrieves a fire-and-forget task's exception, so asyncio doesn't report it as never retrieved.""" + if not task.cancelled() and (exc := task.exception()): + log.error(f"background task {task.get_coro()!r} failed: {exc!r}", exc_info=exc) + + # Delay between attribute read chunks to let bellows send ASH ACKs. _INTER_CHUNK_DELAY = 0.05 @@ -835,6 +843,7 @@ def connection_lost(self, exc: Exception | None): if self._reconnecting: self._reconnecting.cancel() # lost again while it reopened: start over self._reconnecting = asyncio.create_task(self._reconnect()) + self._reconnecting.add_done_callback(_log_task_exception) async def _reconnect(self): async with self._radio_lock: @@ -972,6 +981,16 @@ async def _read_cluster_attributes( values, failures = await cluster.read_attributes( cast("list[int | str | ZCLAttributeDef]", chunk), only_cache=only_cache, timeout=timeout ) + except TimeoutError as e: + log_level = log.error if cluster.cluster_id in MAIN_PARAMETER_BY_CLUSTER else log.warning + # A listed but unanswered optional cluster (e.g. Metering on a Tuya relay): the + # remaining chunks would time out too, so don't wait for each of them. + log_level( + f"{log_prefix} read_attributes timeout " + f"{_zb_path(device, zbdevice, endpoint, cluster, attr_ids=chunk, error=e)}" + ) + await asyncio.sleep(_INTER_CHUNK_DELAY) # let bellows send pending ASH ACKs + break except Exception as e: log.error( f"{log_prefix} read_attributes error " @@ -1010,6 +1029,7 @@ def _create_task[T](self, coro: Coroutine[Any, Any, T]) -> asyncio.Task[T]: task = asyncio.create_task(coro) self._tasks.add(task) task.add_done_callback(self._tasks.discard) + task.add_done_callback(_log_task_exception) return task async def _subscribe(self, device_id: UUID, device: ZPDevice): diff --git a/tests/test_controller.py b/tests/test_controller.py index 4bf59f2..05238ae 100644 --- a/tests/test_controller.py +++ b/tests/test_controller.py @@ -466,6 +466,41 @@ async def test_ts0001_exposes_only_supported_clusters(zigbee, monkeypatch): ) +async def test_an_unanswered_optional_cluster_read_is_a_warning_not_an_error(zigbee, monkeypatch, caplog): + monkeypatch.setattr(conftest, "MOCK_INPUT_CLUSTERS", _TS0001_INPUT_CLUSTERS) + monkeypatch.setattr(conftest, "MOCK_OUTPUT_CLUSTERS", _TS0001_OUTPUT_CLUSTERS) + _controller, output, _repository, _app = zigbee + metering_reads = 0 + + async def read_attributes(cluster: zigpy.zcl.Cluster, attributes: list[int], **kwargs): + nonlocal metering_reads + if cluster.cluster_id == Metering.cluster_id: + metering_reads += 1 + raise TimeoutError # the relay never answers Metering + return await _ts0001_read_attributes(cluster, attributes, **kwargs) + + with patch.object(zigpy.zcl.Cluster, "read_attributes", new=read_attributes), caplog.at_level("DEBUG"): + caplog.clear() + await _pair(zigbee) + await wait_for(lambda: bool(output.events)) + timeouts = [r for r in caplog.records if "read_attributes" in r.getMessage() and "Metering" in r.getMessage()] + assert timeouts and all(r.levelname == "WARNING" for r in timeouts) + assert metering_reads == 2 # one request each for pairing and the fetch, not one per chunk + + +async def test_a_failed_background_task_is_logged_not_left_unretrieved(zigbee, caplog): + controller, _output, _repository, _app = zigbee + + async def fail(): + raise RuntimeError("boom") + + task = controller._create_task(fail()) + await asyncio.gather(task, return_exceptions=True) + await asyncio.sleep(0) + assert task._log_traceback is False # retrieved: asyncio won't log "Task exception was never retrieved" + assert any("boom" in r.getMessage() and r.levelname == "ERROR" for r in caplog.records) + + @pytest_asyncio.fixture async def running(zigpy_apps, tmp_path, monkeypatch): """Zigbee run by the runtime on a pinned radio, which it reopens without waiting."""