core: ZHA Devices not available after update to 2022.4, logs flooded with Command.aps_data_request, status: Status.BUSY or APS_NO_ACK

The problem

After updating to 2022.4.X all zigbee devices fail to be available.

What version of Home Assistant Core has the issue?

core-2022.4.2

What was the last working version of Home Assistant Core?

core-2022.3.8

What type of installation are you running?

Home Assistant OS

Integration causing the issue

ZHA

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha/

Diagnostics information

home-assistant.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-04-11 10:21:35 DEBUG (MainThread) [zigpy.device] [0xb9b3] Delivery error for seq # 0x98, on endpoint id 0 cluster 0x8000: message send failure
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x23a1>, 0, 0, 0, b'\xf9\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 42, 97, 183, 58, 3, -86]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy.zdo] [0x23a1:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 249 under 185 request id, data: b'f9008e5f06ffff2e210000000000'
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x23a1>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'f98e5f06ffff2e21000000'
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 185, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x23A1 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xf9\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 185]
2022-04-11 10:21:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.memory_free, old_state=<state sensor.memory_free=2033.0; state_class=measurement, unit_of_measurement=MiB, icon=mdi:memory, friendly_name=Memory free @ 2022-04-11T10:21:20.108684-05:00>, new_state=<state sensor.memory_free=2033.6; state_class=measurement, unit_of_measurement=MiB, icon=mdi:memory, friendly_name=Memory free @ 2022-04-11T10:21:35.109570-05:00>>
2022-04-11 10:21:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.memory_use, old_state=<state sensor.memory_use=1806.5; state_class=measurement, unit_of_measurement=MiB, icon=mdi:memory, friendly_name=Memory use @ 2022-04-11T10:21:20.109340-05:00>, new_state=<state sensor.memory_use=1805.9; state_class=measurement, unit_of_measurement=MiB, icon=mdi:memory, friendly_name=Memory use @ 2022-04-11T10:21:35.110179-05:00>>
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xea74>, 0, 0, 0, b'\xb0\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 255, 111, 183, 58, 3, -56]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy.zdo] [0xea74:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 176 under 186 request id, data: b'b0008e5f06ffff2e210000000000'
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xea74>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'b08e5f06ffff2e21000000'
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 186, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xEA74 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xb0\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 186]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xd423>, 0, 0, 0, b'\xc5\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 239, 98, 183, 58, 3, -64]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy.zdo] [0xd423:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 197 under 187 request id, data: b'c5008e5f06ffff2e210000000000'
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xd423>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'c58e5f06ffff2e21000000'
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 187, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xD423 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xc5\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 187]
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 184, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC61A endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xe3\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:35 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 184]
2022-04-11 10:21:36 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xB288:1:0x0006]: initializing channel: from_cache: False
2022-04-11 10:21:36 DEBUG (MainThread) [zigpy.zcl] [0xB288:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=188, command_id=<GeneralCommand.Read_Attributes: 0>, *is_reply=False)
2022-04-11 10:21:36 DEBUG (MainThread) [zigpy.zcl] [0xB288:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2022-04-11 10:21:36 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 188 under 189 request id, data: b'00bc000000'
2022-04-11 10:21:36 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (20, 189, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xB288 endpoint=1>, 260, 6, 1, b'\x00\xbc\x00\x00\x00', <DeconzTransmitOptions.USE_APS_ACKS|USE_NWK_KEY_SECURITY: 6>, 0)
2022-04-11 10:21:36 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 189]
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x6d56>, 0, 0, 0, b'\xa1\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 255, 113, 183, 58, 3, -50]
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy.zdo] [0x6d56:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 161 under 190 request id, data: b'a1008e5f06ffff2e210000000000'
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x6d56>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'a18e5f06ffff2e21000000'
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 190, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x6D56 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xa1\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 0.5s
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 190, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x6D56 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xa1\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:37 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 1.0s
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 172: a7
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xac 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xea74 endpoint=0>, status: 0xa7
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 172 req id frame: TXStatus.APS_NO_ACK
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy.device] [0xea74] Delivery error for seq # 0xaf, on endpoint id 0 cluster 0x8000: message send failure
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 190, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x6D56 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xa1\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:38 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 190]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xc61a>, 0, 0, 0, b'\xe4\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 255, 132, 183, 58, 3, -50]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy.zdo] [0xc61a:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 228 under 191 request id, data: b'e4008e5f06ffff2e210000000000'
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xc61a>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'e48e5f06ffff2e21000000'
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 191, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC61A endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xe4\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 0.5s
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xc3c7>, 0, 0, 0, b'\xbe\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 18, 134, 183, 58, 3, -87]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy.zdo] [0xc3c7:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 190 under 192 request id, data: b'be008e5f06ffff2e210000000000'
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xc3c7>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'be8e5f06ffff2e21000000'
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 192, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC3C7 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xbe\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 0.5s
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 191, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC61A endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xe4\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:39 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 1.0s
2022-04-11 10:21:40 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 192, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC3C7 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xbe\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:40 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:40 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 1.0s
2022-04-11 10:21:40 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 191, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC61A endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xe4\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:40 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:40 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 1.5s
2022-04-11 10:21:41 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 192, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC3C7 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xbe\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:41 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:41 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 1.5s
2022-04-11 10:21:42 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 191, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC61A endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xe4\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:42 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:42 DEBUG (MainThread) [zigpy.device] [0xc61a] Delivery error for seq # 0xe4, on endpoint id 0 cluster 0x8000: Couldn't enqueue send data request: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:42 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 192, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0xC3C7 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xbe\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:42 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:42 DEBUG (MainThread) [zigpy.device] [0xc3c7] Delivery error for seq # 0xbe, on endpoint id 0 cluster 0x8000: Couldn't enqueue send data request: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x25af>, 0, 0, 0, b'\xdf\x8e_\x06\xff\xff.!\x00\x00\x00', 0, 175, 37, 148, 183, 58, 3, -87]
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy.zdo] [0x25af:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:21:2e:ff:ff:06:5f:8e, 0, 0]
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 223 under 193 request id, data: b'df008e5f06ffff2e210000000000'
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x25af>, ep: 0, profile: 0x0000, cluster_id: 0x0000, data: b'df8e5f06ffff2e21000000'
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 193, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x25AF endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xdf\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 0.5s
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 185: e9
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xb9 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x23a1 endpoint=0>, status: 0xe9
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 185 req id frame: TXStatus.MAC_NO_ACK
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Trying manual source route: [0]
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (32, 185, <DeconzSendDataFlags.RELAYS: 2>, <DeconzAddressEndpoint address_mode=2 address=0x23A1 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xf9\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_APS_ACKS|USE_NWK_KEY_SECURITY: 6>, 0, [0])
2022-04-11 10:21:43 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 185]
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (29, 193, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x25AF endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xdf\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_request' failure: Command.aps_data_request, status: Status.BUSY
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] retrying 'aps_data_request' in 1.0s
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 173: a7
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xad 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x170b endpoint=0>, status: 0xa7
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 173 req id frame: TXStatus.APS_NO_ACK
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy.device] [0x170b] Delivery error for seq # 0xa0, on endpoint id 0 cluster 0x8000: message send failure
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 186: e9
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xba 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xea74 endpoint=0>, status: 0xe9
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 186 req id frame: TXStatus.MAC_NO_ACK
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Trying manual source route: [0]
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 187: 00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xbb 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xd423 endpoint=0>, status: 0x00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (32, 186, <DeconzSendDataFlags.RELAYS: 2>, <DeconzAddressEndpoint address_mode=2 address=0xEA74 endpoint=0>, 0, <ZDOCmd.NWK_addr_rsp: 0x8000>, 0, b'\xb0\x00\x8e_\x06\xff\xff.!\x00\x00\x00\x00\x00', <DeconzTransmitOptions.USE_APS_ACKS|USE_NWK_KEY_SECURITY: 6>, 0, [0])
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 38>, 186]
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 184: 00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xb8 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xc61a endpoint=0>, status: 0x00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 189: 00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xbd 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xb288 endpoint=1>, status: 0x00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 190: 00
2022-04-11 10:21:44 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xbe 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x6d56 endpoint=0>, status: 0x00
2022-04-11 10:21:45 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2022-04-11 10:21:45 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2022-04-11 10:21:45 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 174: a7
2022-04-11 10:21:45 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xae 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x8fcb endpoint=0>, status: 0xa7
2022-04-11 10:21:45 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 174 req id frame: TXStatus.APS_NO_ACK
2022-04-11 10:21:45 DEBUG (MainThread) [zigpy.device] [0x8fcb] Delivery error for seq # 0xea, on endpoint id 0 cluster 0x8000: message send failure

Additional information

This only occurs when updating to 2022.4.X, restoring to a backup of 2022.03.08 resolves the issue with no other changes.

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Reactions: 1
  • Comments: 40 (11 by maintainers)

Most upvoted comments

Thanks for the clarification. This is likely due to ZHA polling the state of your devices on startup.

The changes to zigpy-deconz were introduced to help with runtime routing issues but they may be making the original startup time problem worse when added to ZHA’s internal retrying mechanisms.

Something with the Conbee specifically is causing startup deliverability issues with large-ish networks like this. I’m going to try switching back to the Conbee to try and replicate this.

+6
puddly on Apr 11, 2022

Release notes for 2022.4.3: Add diagnostics support for ZHA (@dmulcahey - https://github.com/home-assistant/core/pull/69756) (zha docs) Bump zigpy to 0.44.2 and and zha-quirks to 0.0.72 (@puddly - https://github.com/home-assistant/core/pull/69879) (zha docs) Downgrade ZHA dependency zigpy-deconz from 0.15.0 to 0.14.0 (@puddly - https://github.com/home-assistant/core/pull/69927) (zha docs)

I just applied this update, and it appears as though my Zigbee network boots up much faster than it has since the upgrade to 2022.4.x. The network itself seems much much more responsive to changes in state, ie. toggling switches.

+4
sgrochowski on Apr 13, 2022
Read more comments on GitHub
← core: ZHA devices becoming unavailable
core: ZHA devices not working after update from 0.114 to 0.115.0b2 →