Warn on unanswered optional cluster reads

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):

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."""