Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ZHA: Logs full of "Received an unhandled command: AF.DataConfirm.Callback" messages #62163

Closed
mpredfearn opened this issue Dec 17, 2021 · 9 comments
Closed

ZHA: Logs full of "Received an unhandled command: AF.DataConfirm.Callback" messages #62163

mpredfearn opened this issue Dec 17, 2021 · 9 comments
Assignees
@dmulcahey @Adminiuga
Labels
integration: zha stale

Comments

@mpredfearn
Copy link

The problem

My home assistant logs are full of the following errors, repeating every minute or so. I don't know if this is related to a device in the Zigbee network, and I have not noticed any functional problems, but it seems there is an unhandled exception while processing these unexpected commands?

2021-12-17 06:33:52 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=150)
2021-12-17 06:34:19 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 452, in callback_handler
    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 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-12-17 06:34:19 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=157)
2021-12-17 06:34:30 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 452, in callback_handler
    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 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-12-17 06:35:29 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 452, in callback_handler
    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 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-12-17 06:35:29 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=178)
2021-12-17 06:35:36 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 452, in callback_handler
    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 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

What version of Home Assistant Core has the issue?

core-2021.11.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

ZHA

Link to integration documentation on our website

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response
@Adminiuga
Copy link
Contributor

Don't use Cc2531

@mpredfearn
Copy link
Author

OK, so I guess this is a known issue with CC2531 coordinators? https://www.home-assistant.io/integrations/zha/ says it is a supported device, if only for small networks. I only have 11 devices. If you're saying it is that useless, should it be removed from the hardware compatibility list?

@Hedda
Copy link
Contributor

Hedda commented Dec 20, 2021 •
edited
Loading

Don't use Cc2531

OK, so I guess this is a known issue with CC2531 coordinators? https://www.home-assistant.io/integrations/zha/ says it is a supported device, if only for small networks. I only have 11 devices. If you're saying it is that useless, should it be removed from the hardware compatibility list?

FYI, posted discussion to zigpy-znp as it is upstream and ZHA docs follow upstream recommendations -> zigpy/zigpy-znp#115

@puddly
Copy link
Contributor

puddly commented Dec 20, 2021

Can you enable https://www.home-assistant.io/integrations/zha/#debug-logging and let those same warnings be generated? There's not enough context to really tell what's causing this issue.

It'll be in your home-assistant.log file.

@mpredfearn
Copy link
Author

Hope I captured enough context

2021-12-21 06:49:42 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x8828, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=21, SecurityUse=<Bool.false: 0>, TimeStamp=15575398, TSN=0, Data=b'\x18\x03\x01\x00\x00\x00\x20\xCC', MacSrcAddr=0x8828, MsgResultRadius=29)
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy.zcl] [0x8828:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=3 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:42 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x8828:1:0x0008]: received attribute: 0 update with value: 204
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=4)
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x75B4, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=26, SecurityUse=<Bool.false: 0>, TimeStamp=15575512, TSN=0, Data=b'\x18\x04\x01\x00\x00\x00\x20\xCC', MacSrcAddr=0x75B4, MsgResultRadius=29)
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy.zcl] [0x75b4:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=4 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:42 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x75B4:1:0x0008]: received attribute: 0 update with value: 204
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=5)
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x96C8, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=18, SecurityUse=<Bool.false: 0>, TimeStamp=15575623, TSN=0, Data=b'\x18\x05\x01\x00\x00\x00\x20\xCC', MacSrcAddr=0x96C8, MsgResultRadius=29)
2021-12-21 06:49:42 DEBUG (MainThread) [zigpy.zcl] [0x96c8:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=5 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:42 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x96C8:1:0x0008]: received attribute: 0 update with value: 204
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Group: 1>, address=0x0002), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=6, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x01\x06\x04\xCC\x01\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.entity] light.kitchen_bar_lights_zha_group_0x0002: turned on: {'move_to_level_with_on_off': [4, <Status.SUCCESS: 0>]}
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.entity] light.lk_zbt_dimlight_d0120_3a6c43fe_level_on_off: polling current state
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.entity] light.lk_zbt_dimlight_d0120_5efda7fe_level_on_off: polling current state
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.entity] light.lk_zbt_dimlight_d0120_eeeda7fe_level_on_off: polling current state
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.zigbee.application] Max concurrency reached, delaying requests (1 enqueued)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x8828), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=7, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x07\x00\x00\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 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 452, in callback_handler
    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 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x75B4), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=8, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x08\x00\x00\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=6)
2021-12-21 06:49:46 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=6)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=7)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.zigbee.application] Previously delayed request is now running, delayed by 0.04 seconds
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x96C8), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=9, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x09\x00\x00\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=8)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=9)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0x8828, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=21, SecurityUse=<Bool.false: 0>, TimeStamp=15587125, TSN=0, Data=b'\x18\x07\x01\x00\x00\x00\x10\x01', MacSrcAddr=0x8828, MsgResultRadius=29)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy.zcl] [0x8828:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=7 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x8828), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=10, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x0A\x00\x00\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0x75B4, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=23, SecurityUse=<Bool.false: 0>, TimeStamp=15587292, TSN=0, Data=b'\x18\x08\x01\x00\x00\x00\x10\x01', MacSrcAddr=0x75B4, MsgResultRadius=29)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy.zcl] [0x75b4:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=8 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0x96C8, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=21, SecurityUse=<Bool.false: 0>, TimeStamp=15587381, TSN=0, Data=b'\x18\x09\x01\x00\x00\x00\x10\x01', MacSrcAddr=0x96C8, MsgResultRadius=29)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy.zcl] [0x96c8:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=9 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.zigbee.application] Max concurrency reached, delaying requests (1 enqueued)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x75B4), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=11, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x0B\x00\x00\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=10)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.zigbee.application] Previously delayed request is now running, delayed by 0.04 seconds
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x96C8), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=12, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x0C\x00\x00\x00')
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=11)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x8828, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=23, SecurityUse=<Bool.false: 0>, TimeStamp=15587559, TSN=0, Data=b'\x18\x0A\x01\x00\x00\x00\x20\xCC', MacSrcAddr=0x8828, MsgResultRadius=29)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy.zcl] [0x8828:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=10 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x75B4, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=26, SecurityUse=<Bool.false: 0>, TimeStamp=15587602, TSN=0, Data=b'\x18\x0B\x01\x00\x00\x00\x20\xCC', MacSrcAddr=0x75B4, MsgResultRadius=29)
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x8828:1:0x0008]: received attribute: 0 update with value: 204
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy.zcl] [0x75b4:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=11 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x75B4:1:0x0008]: received attribute: 0 update with value: 204
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=12)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x96C8, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=18, SecurityUse=<Bool.false: 0>, TimeStamp=15587768, TSN=0, Data=b'\x18\x0C\x01\x00\x00\x00\x20\xCC', MacSrcAddr=0x96C8, MsgResultRadius=29)
2021-12-21 06:49:46 DEBUG (MainThread) [zigpy.zcl] [0x96c8:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=12 command_id=Command.Read_Attributes_rsp>
2021-12-21 06:49:46 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x96C8:1:0x0008]: received attribute: 0 update with value: 204
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Group: 1>, address=0x0002), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=13, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x01\x0D\x04\xCC\x01\x00')
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:53 DEBUG (MainThread) [homeassistant.components.zha.entity] light.kitchen_bar_lights_zha_group_0x0002: turned on: {'move_to_level_with_on_off': [4, <Status.SUCCESS: 0>]}
2021-12-21 06:49:53 DEBUG (MainThread) [homeassistant.components.zha.entity] light.lk_zbt_dimlight_d0120_3a6c43fe_level_on_off: polling current state
2021-12-21 06:49:53 DEBUG (MainThread) [homeassistant.components.zha.entity] light.lk_zbt_dimlight_d0120_5efda7fe_level_on_off: polling current state
2021-12-21 06:49:53 DEBUG (MainThread) [homeassistant.components.zha.entity] light.lk_zbt_dimlight_d0120_eeeda7fe_level_on_off: polling current state
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.zigbee.application] Max concurrency reached, delaying requests (1 enqueued)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x8828), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=14, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x0E\x00\x00\x00')
2021-12-21 06:49:53 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 452, in callback_handler
    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 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x75B4), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=15, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x0F\x00\x00\x00')
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=13)
2021-12-21 06:49:53 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=13)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=14)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.zigbee.application] Previously delayed request is now running, delayed by 0.05 seconds
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x96C8), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=16, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x10\x00\x00\x00')
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=15)
2021-12-21 06:49:53 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0x8828, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=23, SecurityUse=<Bool.false: 0>, TimeStamp=15607917, TSN=0, Data=b'\x18\x0E\x01\x00\x00\x00\x10\x01', MacSrcAddr=0x8828, MsgResultRadius=29)

@puddly
Copy link
Contributor

puddly commented Dec 21, 2021

Ah, you're running 2021.11.5. I believe this was already reported and fixed last month: #60101

@probot-home-assistant
Copy link

zha documentation
zha source
(message by IssueLinks)

@probot-home-assistant
Copy link

Hey there @dmulcahey, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!
(message by CodeOwnersMention)

@github-actions
Copy link

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale label Apr 20, 2022
@github-actions github-actions bot locked and limited conversation to collaborators May 22, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@dmulcahey dmulcahey

@Adminiuga Adminiuga

Labels
integration: zha stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@dmulcahey @thecode @Adminiuga @Hedda @mpredfearn @puddly