"cluster.read_attributes" issue after upgrade to HA2022.2 (zigpy_znp 0.7.0)

[mdeweerd]

2022-02-08 13:57:47 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140119198800864] Error handling message: Unknown error
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/decorators.py", line 27, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 534, in handle_execute_script
    await script_obj.async_run(msg.get("variables"), context=context)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1253, in async_run
    await asyncio.shield(run.async_run())
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 354, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 372, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 575, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1630, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1667, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/config/custom_components/zha_toolkit/__init__.py", line 458, in toolkit_service
    raise handler_exception
  File "/config/custom_components/zha_toolkit/__init__.py", line 422, in toolkit_service
    await handler(
  File "/config/custom_components/zha_toolkit/zcl_attr.py", line 115, in attr_read
    await attr_write(*args, **kwargs)
  File "/config/custom_components/zha_toolkit/zcl_attr.py", line 235, in attr_write
    result_read = await cluster_read_attributes(
  File "/config/custom_components/zha_toolkit/zcl_attr.py", line 100, in cluster_read_attributes
    return await cluster.read_attributes(attrs, manufacturer=manufacturer)
  File "/usr/local/lib/python3.9/site-packages/zigpy/zcl/__init__.py", line 297, in read_attributes
    result = await self.read_attributes_raw(to_read, manufacturer=manufacturer)
  File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 265, in request
    result, msg = await self._application.request(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 439, in request
    return await self._send_request(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 1401, in _send_request
    response = await self._send_request_raw(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 1287, in _send_request_raw
    self._znp.request_callback_rsp(
AttributeError: 'NoneType' object has no attribute 'request_callback_rsp'

https://github.com/zigpy/zigpy-znp/blob/v0.7.0/zigpy_znp/zigbee/application.py#L1283-L1300

Could it be that self is different inside the "shield" ?

[mdeweerd]

I powercycled HA because I saw that you recommended that in another issue.

I got a different result & eventually it worked (it's a sleepy device)/ However, you see that it's a CancelledError (see zigpy/zigpy-znp#141 ).

2022-02-08 14:40:12 ERROR (MainThread) [homeassistant.helpers.script.websocket_api_script] websocket_api script: Error executing script. Unexpected error for call_service at pos 1:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 1286, in _send_request_raw
    response = await asyncio.shield(
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 372, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 575, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1630, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1667, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/config/custom_components/zha_toolkit/__init__.py", line 458, in toolkit_service
    raise handler_exception
  File "/config/custom_components/zha_toolkit/__init__.py", line 422, in toolkit_service
    await handler(
  File "/config/custom_components/zha_toolkit/zcl_attr.py", line 115, in attr_read
    await attr_write(*args, **kwargs)
  File "/config/custom_components/zha_toolkit/zcl_attr.py", line 235, in attr_write
    result_read = await cluster_read_attributes(
  File "/config/custom_components/zha_toolkit/zcl_attr.py", line 100, in cluster_read_attributes
    return await cluster.read_attributes(attrs, manufacturer=manufacturer)
  File "/usr/local/lib/python3.9/site-packages/zigpy/zcl/__init__.py", line 297, in read_attributes
    result = await self.read_attributes_raw(to_read, manufacturer=manufacturer)
  File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 265, in request
    result, msg = await self._application.request(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 439, in request
    return await self._send_request(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 1401, in _send_request
    response = await self._send_request_raw(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 1304, in _send_request_raw
    raise InvalidCommandResponse(
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2022-02-08 14:40:12 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140481434618800] Error handling message: Timeout
2022-02-08 14:40:34 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 888, in request_callback_rsp
    return await callback_rsp
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 888, in request_callback_rsp
    return await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

I tried to read attribute 0 in cluster 0 from a router - that was ok.

[puddly]

AttributeError: 'NoneType' object has no attribute 'request_callback_rsp'

This means that the serial port is disconnected.

Can you post the entire debug log, or at least a minute of context?

[mdeweerd]

I've done several restart since then - I lost the context.

As far as I gather from the logbook, HA restarted at about 1:37 PM The error occurred at 14:40:12.

[mdeweerd]

Closing this, but it looks like zigpy-znp could be improve to recover from communication loss with the ZNP dongle.