search

zigpy / zigpy-deconz

A library which communicates with Deconz radios for zigpy
GNU General Public License v3.0
86 stars 20 forks source link

Error while sending frame: TXStatus.NWK_ROUTE_DISCOVERY_FAILED #169

Closed seblu closed 9 months ago

seblu commented 3 years ago

The background context is a migration from a Raspberry Pi 4 ZHA setup with a Raspbee2 radio to a Conbee2 radio module. There is around 100 Zigbee devices paired.

The Raspbee2 zigbee parameters has been cloned to the Conbee2 via the Phoscon UI. MacAddress, TC Address, Network Key, TC Link Key, NWK Update ID and Channel Mask are equals after cloning. I triple checked this via the zigpy-cli (nb. do not display the Network Key), debug output of homeassitant and Phoscon Restore/Backup JSON.

This is the JSON exported as backup for both keys:

{
   "apsAck" : false,
   "apsUseExtPanId" : "0x0",
   "curChannel" : 15,
   "deconzVersion" : "21206",
   "deviceType" : 0,
   "endpoint1" : {
      "deviceId" : "0x5",
      "deviceVersion" : "0x1",
      "endpoint" : "0x1",
      "inClusters" : [
         "0x0",
         "0xa",
         "0x19",
         "0x501"
      ],
      "index" : 0,
      "outClusters" : [
         "0x1",
         "0x20",
         "0x500",
         "0x502"
      ],
      "profileId" : "0x104"
   },
   "endpoint2" : {
      "deviceId" : "0x64",
      "deviceVersion" : "0x1",
      "endpoint" : "0xf2",
      "inClusters" : [],
      "index" : 1,
      "outClusters" : [
         "0x21"
      ],
      "profileId" : "0xa1e0"
   },
   "extPanId" : "0x*****",
   "frameCounter" : "*****",
   "macAddress" : "0x*****",
   "networkKey" : "*****",
   "nwkAddress" : "0x*****",
   "nwkUpdateId" : "*****",
   "otauactive" : 0,
   "panId" : "0x*****",
   "securityMode" : 3,
   "staticNwkAddress" : false,
   "tcAddress" : "0x*****",
   "tcLinkKey" : "*****"
}

So both radio modules should be equal and there are threads^1^3 about success stories with this method using the deconz plugin.

The Conbee2 path is /dev/ttyACM0 while the Raspbee2 path is /dev/ttyAMA0, so after the path being adjusted in the .storage/core.config_entries and HomeAssistant restarted, I get these errors :

2021-10-21 15:33:04 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 31 under 32 request id, data: b'001f000240030004000700'
2021-10-21 15:33:04 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (26, 32, 0, <DeconzAddressEndpoint address_mode=2 address=0xFDAB endpoint=11>, 260, 768, 1, b'\x00\x1f\x00\x02@\x03\x00\x04\x00\x07\x00', 2, 0)
2021-10-21 15:33:04 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 32]
2021-10-21 15:33:04 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 32: d0
2021-10-21 15:33:04 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x20 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xfdab endpoint=11>, status: 0xd0
2021-10-21 15:33:04 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 32 req id frame: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2021-10-21 15:33:04 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0xFDAB:11:0x0300]: async_initialize: all attempts have failed: [DeliveryError('[0xfdab:11:0x0300]: Message send failure'), DeliveryError('[0xfdab:11:0x0300]: Message send failure'), DeliveryError('[0xfdab:11:0x0300]: Message send failure'), DeliveryError('[0xfdab:11:0x0300]: Message send failure')]

The NWK_ROUTE_DISCOVERY_FAILED is defined in https://github.com/zigpy/zigpy/blob/468b533eda9216dfc679acd6d542849206daa87d/zigpy/types/named.py#L474 and the comment says:

An attempt to discover a route has failed due to a reason other than a lack of routing capacity

I'm a bit stuck by this error message as I don't know where to look next to fix a routing issue.

MattWestb commented 3 years ago

I have not running My RaspBee I under ZHA but is having it in native deCONZ so i cant saying its right or wrong.

But i think the NWK_ROUTE_DISCOVERY_FAILED is because the cornbee II cant find the device in the network. I think your cornbee II is not in the network with your device and cant communicating with the network. Very likely its somthing not OK with the backup and restore of your RaspBee II / Cornbee II so some parameters for the network is not OK (like link keys or security counters for all keys the coordinator is having for communicating with the devices).

Adminiuga commented 3 years ago

I tested moving from ConBee to ConBee II using Phoscon long ago and is confirmed to be working.

You did everything correctly.

NWK_ROUTE_DISCOVERY_FAILED could be normal some times, other times it indicates too much RF noise. 1st and foremost: USE AN USB CABLE EXTENSION for ConBee. Then leave the ConBee running for 1-2 hours, after power cycle the lights and try controlling those lights again.

Adminiuga commented 3 years ago

If you have any Ikea mains powered devices, powercycle those too

Adminiuga commented 3 years ago

If you have any Ikea mains powered devices, powercycle those too

seblu commented 3 years ago

Very likely its somthing not OK with the backup and restore of your RaspBee II / Cornbee II so some parameters for the network is not OK (like link keys or security counters for all keys the coordinator is having for communicating with the devices).

Link and network keys are the same, the JSON from the Phoscon UI backup is not changing on this. I noticed the frameCounter counter is growing over time. So, I backup/restore before every migration attempt. Do you have a precise counter or value I could check more carefully?

NWK_ROUTE_DISCOVERY_FAILED could be normal some times, other times it indicates too much RF noise. 1st and foremost: USE AN USB CABLE EXTENSION for ConBee.

I read this recommendation on various threads about the Conbee so I used a 0.3m USB extension cable very early but to be sure RF noise was not significant I tried 2 things:

  1. I created a new Zigbee network (new keys and MACs) and paired several devices. No RF noise issue ; paired devices are working as expected.
  2. After a migration attempt (so with the rapsbee2 parameters) I paired a new device, and while all others Zigbee devices was not working, the new paired devices are working.

Then leave the ConBee running for 1-2 hours, after power cycle the lights and try controlling those lights again.

I didn't let the test running for so long. When I rollback to the Raspbee2 after a migration failure, all devices reconnect in less than a minute, so I didn't imagine there is some time magic. Could you explain me why we need to wait for 1-2h before everything get back? There is counters to be rotated or timers to elapse ?

I waited everyone was asleep to run a 2-3h test as you suggested. I rebooted several lights (not all). After few minutes, some Aqara sensors starts reporting values and temperature/illuminance/humidity get populated on HomeAssistant. Even some lights (INNR and Hue) showed their status and brightness correctly. But no control was possible even after 2h. Sensors was not updated more than once in the meantime. Error looks like the previous one : Error while sending 178 req id frame: TXStatus.NWK_ROUTE_DISCOVERY_FAILED

Then I tried to pair a new device, and I was successful. This new device works immediately, while all others not. It was a remote I used to trigger automation. Here is the logging when the button was pressed.

2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [27, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <>
2021-10-22 03:10:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x987F:2:0x0006]: received 'press_type' command with [0] args on cluster_id '6' tsn '5'
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 5 under 248 request id, data: b'18050bfd00'
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x987f>, ep: 2, profile: 0x0104, cluster_id: 0x0006, data: b'0105fd0>
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (20, 248, 0, <DeconzAddressEndpoint address_mode=2 address=0x987F endpoint=2>, 260, 6, 1, b'\x18\x05\x0b\xfd\x00', 2, 0)
2021-10-22 03:10:48 INFO (MainThread) [homeassistant.components.automation.room3_shutter_remote] Room3 Shutter/Blind Remote: Running automation actions
2021-10-22 03:10:48 INFO (MainThread) [homeassistant.components.automation.room3_shutter_remote] Room3 Shutter/Blind Remote: Executing step setting variables
2021-10-22 03:10:48 INFO (MainThread) [homeassistant.components.automation.room3_shutter_remote] Room3 Shutter/Blind Remote: Test condition or: True
2021-10-22 03:10:48 INFO (MainThread) [homeassistant.components.automation.room3_shutter_remote] Room3 Shutter/Blind Remote: Executing step call service
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 248]
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 248: 00
2021-10-22 03:10:48 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0xf8 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x987f endpoint=2>, status: 0x00

This led me to ask why this new paired remote doesn't get NWK_ROUTE_DISCOVERY_FAILED errors and works immediately?

I finally roll-backed to the Raspbee2, where all devices get recognized in few minutes.

MattWestb commented 2 years ago

Did you changing the MAC address of the CornBee II to the of the RaspBee II ? If not all devices is trying contacting the "Rasobee" and not the "cornbee" and the "old routing" in the devices is not working.

I dont knowing if you can see / edit it in the backup from deCONZ of you must do it in deCONZ GUI.

The security frame counters can not going down only incensing and if its being negative (from that last OK frame) the device is silent ignoring the frame. I dont knowing how but Rasp/CornBee have one logic for rolling it forward after hard reboot of the coordinator but how its working is one secrete but shall being transparent in the firmware and it have working then you was putting the backup back to the RaspBee II.

I have no perspective of you system is behaving if the you is getting _NWK_ROUTE_DISCOVERYFAILED for all treys communicating with devices on the network or only some devices like sleeping end devices. If its all devices (also "normal routers") its some basic that is not OK with the restore the conbee that making the network liking talking with it and if you have all keys in the backup that is restored OK its only the frame counter and the MAC address that is not OK and the frame counter is OK then you is restoring back on the RaspBee II so only the MAC address is left if the firmware is making it OK (RaspBee II / ConBee II is om the last FW i hope).

seblu commented 2 years ago

Did you changing the MAC address of the CornBee II to the of the RaspBee II ?

Yes, the MAC is part of cloning process and I checked it was correct several time as stated in the in my first post. I keep in mind something may be wrong in the cloning process, but currently all tools reports they are equals.

The Deconz UI: zigbee_diff

Here is the diff of the zigpy-deconz read parameters at the HASS startup with the Raspbee2 and the cloned Conbee2.

 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.protocol_version: 34>, b'')
-DEBUG (MainThread) [zigpy_deconz.api] Read parameter protocol_version response: [268]
+DEBUG (MainThread) [zigpy_deconz.api] Read parameter protocol_version response: [267]
 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.mac_address: 1>, b'')
 DEBUG (MainThread) [zigpy_deconz.api] Read parameter mac_address response: [00:21:2e:01:23:45:67:89]
 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.aps_designed_coordinator: 9>, b'')
@@ -25,6 +25,6 @@
 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.current_channel: 28>, b'')
 DEBUG (MainThread) [zigpy_deconz.api] Read parameter current_channel response: [15]
 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.protocol_version: 34>, b'')
-DEBUG (MainThread) [zigpy_deconz.api] Read parameter protocol_version response: [268]
+DEBUG (MainThread) [zigpy_deconz.api] Read parameter protocol_version response: [267]
 DEBUG (MainThread) [zigpy_deconz.api] Command Command.read_parameter (1, <NetworkParameter.nwk_update_id: 36>, b'')
 DEBUG (MainThread) [zigpy_deconz.api] Read parameter nwk_update_id response: [0]

So from a zigpy point-of-view, except the protocol_version they are equal.

I have no perspective of you system is behaving if the you is getting _NWK_ROUTE_DISCOVERYFAILED for all treys communicating with devices on the network or only some devices like sleeping end devices.

I got NWK_ROUTE_DISCOVERY_FAILED for End and Router devices. Only newly paired devices works.

@Adminiuga I tried a second time to powercycle all mains devices and wait 3-4 hours. No magic happens. I paired again one device with the cloned conbee2, and I do not have NWK_ROUTE_DISCOVERY_FAILED anymore.

DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, ep: 0, profile: 0x0000, cluster_id: 0x0036, data: b'143c00'
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1cad000c000500022356ffc9
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0eae000700a600
DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x04ad0007000000
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04ad0012000b00221501fcff000000000000
DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 21: 00
DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x15 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.GROUP address=0xfffc endpoint=None>, status: 0x00
DEBUG (MainThread) [zigpy_deconz.api] Command Command.write_parameter (2, <NetworkParameter.permit_join: 33>, b'<')
DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x0bae0009000200213c
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0bae000800010021
DEBUG (MainThread) [zigpy_deconz.api] Write parameter permit_join: SUCCESS
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1caf0012000b0003235efffeff818e58ffc9
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1cb0000c000500022356ffc9
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1cb10012000b0003235efffeff818e58ffc9
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1cb2000c000500022356ffc9
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1cb30012000b0003235efffeff818e58ffc9
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0eb4000700aa00
DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x17af000800010001
DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17af002a0023002202fdff000211af00000013000c00ca11af235efffeff818e588e00afff7de60c00c9
DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [35, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xfffd>, 0, <>
INFO (MainThread) [zigpy_deconz.zigbee.application] New device joined: 0xaf11, 58:8e:81:ff:fe:ff:5e:23
INFO (MainThread) [zigpy.application] Device 0xaf11 (58:8e:81:ff:fe:ff:5e:23) joined the network
DEBUG (MainThread) [zigpy.application] Device 58:8e:81:ff:fe:ff:5e:23 changed id (0xaf11 => 0xaf11)
DEBUG (MainThread) [zigpy.device] [0xaf11] Skipping initialization, device is fully initialized
DEBUG (MainThread) [zigpy.application] Device is initialized <Plug model='TS0121' manuf='_TZ3000_g5xawfcq' nwk=0xAF11 ieee=58:8e:81:ff:fe:ff:5e:23 is_initialized=True>
DEBUG (MainThread) [zigpy.zdo] [0xaf11:zdo] ZDO request ZDOCmd.Device_annce: [0xAF11, 58:8e:81:ff:fe:ff:5e:23, 142]
DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 44817:58:8e:81:ff:fe:ff:5e:23 entering async_device_initialized - is_new_join: False
DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 44817:58:8e:81:ff:fe:ff:5e:23 has been reset and re-added or its nwk address changed
DEBUG (MainThread) [homeassistant.components.zha.core.gateway] skipping discovery for previously discovered device - 44817:58:8e:81:ff:fe:ff:5e:23
DEBUG (MainThread) [homeassistant.components.zha.core.device] [44817](TS0121): started configuration
DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [44817:ZDO](TS0121): 'async_configure' stage succeeded
DEBUG (MainThread) [homeassistant.components.zha.core.device] [44817](TS0121): started initialization
DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [44817:ZDO](TS0121): 'async_initialize' stage succeeded
DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xaf11>, ep: 0, profile: 0x0000, cluster_id: 0x0013, data: b'ca11af2>
DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 22 under 23 request id, data: b'16235efffeff818e580106000301be05ffff2e210001'
DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (37, 23, 0, <DeconzAddressEndpoint address_mode=2 address=44817 endpoint=0>, 0, <ZDOCmd.Bind_req: 0x0021>, 0, b'\x16#^\xff\x>
DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x12b0002c00250017000211af000000210000160016235efffeff818e580106000301be05ffff2e2100010200
DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 24 under 25 request id, data: b'18235efffeff818e5801040b0301be05ffff2e210001'
DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [44817:1:0x0000]: finished channel configuration
DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 26 under 27 request id, data: b'1a235efffeff818e580102070301be05ffff2e210001'

while others devices still have issue NWK_ROUTE_DISCOVERY_FAILED.

2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 99 under 100 request id, data: b'0063000b05'
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (20, 100, 0, <DeconzAddressEndpoint address_mode=2 address=44817 endpoint=1>, 260, 2820, 1, b'\x00c\x00\x0b\x05', 2, 0)
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x1235001b00140064000211af010401040b0105000063000b050200
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x123500090002002264
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 100]
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e36000700a600
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x04360007000000
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e37000700ae00
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|APSDE_DATA_CONFIRM|2: 174>, 0]
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04360013000c002a640211af01010000000000
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 100: 00
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x64 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xaf11 endpoint=1>, status: 0x00
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x1737000800010001
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1737002700200022020000010211af010401040b09001863010b050029000000afffdce60c00c3
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <>
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy.zcl] [0xaf11:1:0x0b04] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_respon>
2021-10-22 16:25:19 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xaf11>, ep: 1, profile: 0x0104, cluster_id: 0x0b04, data: b'1863010>
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e38000700a600
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0x04380007000000
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04380013000c00226202cfc30101d000000000
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 98: d0
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x62 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xc3cf endpoint=1>, status: 0xd0
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Error while sending 98 req id frame: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2021-10-22 16:25:21 DEBUG (MainThread) [zigpy.device] [0xc3cf] Delivery error for seq # 0x61, on endpoint id 1 cluster 0x0000: message send failure
2021-10-22 16:25:22 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c39000c000500022356ffc9
2021-10-22 16:25:27 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3a000c000500022356ffc9
2021-10-22 16:25:32 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3b000c000500022356ffc9
2021-10-22 16:25:37 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3c000c000500022356ffc9
2021-10-22 16:25:42 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3d000c000500022356ffc9
2021-10-22 16:25:47 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3e000c000500022356ffc9
2021-10-22 16:25:49 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [44817:1:0x0b04]: async_update

Is zigpy_deconz should log errors if there is a key decryption error?

MattWestb commented 2 years ago

If reading the deCONZ error code https://github.com/dresden-elektronik/deconz-rest-plugin/wiki/Zigbee-Error-Codes-in-the-Log#0xd0-no-route-to-the-receiver-exists all your "old routers" is not playing in the network. Then you is adding or repairing the "new routers" is working with the coordinator but the cant communicating with "old routers" in the network. My conclusion is that somthing is not OK with the network settings in the restored Cornbee II. Or is the firmware not compatible with the backup you have created. Is both the Rasp and CornBee at the same firmware ? https://github.com/dresden-elektronik/deconz-rest-plugin/wiki/Firmware-Changelog

puddly commented 2 years ago

This is likely too late to be helpful, but I had a similar issue with a Conbee II not actually accepting a frame counter write. The migration seemingly "worked" but the frame counter was never actually updated, causing outgoing requests from the device to be rejected by routers on the network.

If you still have both devices and want to try this again, upgrade them both to the latest firmware and try migrating once more with https://github.com/zigpy/zigpy-cli/pull/2. If your Conbee has the same bug as mine, in theory performing a backup with the Conbee still plugged in will yield nearly identical network settings to the Raspbee (+/- a few hundred for the frame counter), but unplugging it and plugging it back in will cause the frame counter in a new backup to "reset" to its old value.

claudegel commented 9 months ago

Hi I have a similar problem with my Conbee II and ZHA. my log are floud with thos error: Is it my Conbee that is going bad ?

2023-12-31 15:39:36.858 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:86 sequence
2023-12-31 15:39:36.878 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:88 sequence
2023-12-31 15:39:36.889 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 180, Status: TXStatus.SUCCESS
2023-12-31 15:39:36.951 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 182, Status: TXStatus.SUCCESS
2023-12-31 15:39:37.311 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a3 sequence
2023-12-31 15:39:37.322 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a4 sequence
2023-12-31 15:39:37.334 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a5 sequence
2023-12-31 15:39:37.352 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a7 sequence
2023-12-31 15:39:37.384 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:ac sequence
2023-12-31 15:39:37.465 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:b3 sequence
2023-12-31 15:39:37.482 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:b6 sequence
2023-12-31 15:39:37.556 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 200, Status: TXStatus.SUCCESS
2023-12-31 15:39:37.678 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 204, Status: TXStatus.SUCCESS
2023-12-31 15:39:37.701 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:ca sequence
2023-12-31 15:39:38.086 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:ce sequence
2023-12-31 15:39:38.095 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:cf sequence
2023-12-31 15:39:38.739 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:d5 sequence
2023-12-31 15:39:38.762 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:d9 sequence
2023-12-31 15:39:38.766 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 213, Status: TXStatus.SUCCESS
2023-12-31 15:39:38.790 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:de sequence
2023-12-31 15:39:38.943 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 218, Status: TXStatus.SUCCESS
2023-12-31 15:39:39.200 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:fd sequence
2023-12-31 15:39:40.243 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:05 sequence
2023-12-31 15:39:41.445 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:14 sequence
2023-12-31 15:39:41.467 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:16 sequence
2023-12-31 15:39:41.495 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 244, Status: TXStatus.SUCCESS
2023-12-31 15:39:41.514 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 244, Status: TXStatus.SUCCESS
2023-12-31 15:39:41.541 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 244, Status: TXStatus.SUCCESS
2023-12-31 15:39:41.623 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:20 sequence
2023-12-31 15:39:41.981 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 253, Status: TXStatus.MAC_NO_ACK
2023-12-31 15:39:41.990 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:33 sequence
2023-12-31 15:39:42.000 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 253, Status: TXStatus.SUCCESS
2023-12-31 15:39:42.042 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:39 sequence
2023-12-31 15:39:42.181 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 1, Status: TXStatus.SUCCESS
2023-12-31 15:39:42.193 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:42 sequence
2023-12-31 15:39:46.897 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:57 sequence
2023-12-31 15:39:48.583 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 28, Status: TXStatus.SUCCESS
2023-12-31 15:39:49.643 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:75 sequence
2023-12-31 15:39:51.300 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:9d sequence
2023-12-31 15:40:01.192 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.prise_tele_chalet_electrical_measurement is taking over 10 seconds
2023-12-31 15:40:02.329 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.prise_tele_salon_electrical_measurement is taking over 10 seconds
2023-12-31 15:40:02.340 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.prise_tele_gym_electrical_measurement is taking over 10 seconds
2023-12-31 15:40:02.346 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.sinope_technologies_sp2610zb_active_power_2 is taking over 10 seconds
2023-12-31 15:40:06.213 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30
2023-12-31 15:40:36.213 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30
2023-12-31 15:40:36.920 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:27 sequence
2023-12-31 15:40:37.020 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:2e sequence
2023-12-31 15:40:37.025 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 55, Status: TXStatus.SUCCESS
2023-12-31 15:40:38.154 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:44 sequence
2023-12-31 15:40:38.169 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:46 sequence
2023-12-31 15:40:38.185 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:48 sequence
2023-12-31 15:40:38.224 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:50 sequence
2023-12-31 15:40:38.230 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:51 sequence
2023-12-31 15:40:38.249 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 68, Status: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2023-12-31 15:40:38.266 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:59 sequence
2023-12-31 15:40:38.271 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 68, Status: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2023-12-31 15:40:38.277 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 68, Status: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2023-12-31 15:40:38.289 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 68, Status: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2023-12-31 15:40:38.300 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 68, Status: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2023-12-31 15:40:38.490 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:6d sequence
2023-12-31 15:40:38.514 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:6f sequence
2023-12-31 15:40:38.715 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:7f sequence
2023-12-31 15:40:40.865 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a3 sequence
2023-12-31 15:40:41.909 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a9 sequence
2023-12-31 15:40:41.925 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:aa sequence
2023-12-31 15:40:42.971 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:b1 sequence
2023-12-31 15:40:43.169 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:c0 sequence
2023-12-31 15:40:47.007 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:d3 sequence
2023-12-31 15:40:47.082 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:d8 sequence
2023-12-31 15:40:47.125 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:dc sequence
2023-12-31 15:40:48.160 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 58, Status: TXStatus.NWK_ROUTE_DISCOVERY_FAILED
2023-12-31 15:40:53.163 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.prise_test_puissance is taking over 10 seconds
2023-12-31 15:41:06.213 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30
2023-12-31 15:41:08.640 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:3f sequence
2023-12-31 15:41:18.804 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:60 sequence
2023-12-31 15:41:18.839 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 168, Status: TXStatus.SUCCESS
2023-12-31 15:41:18.996 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:6f sequence
2023-12-31 15:41:20.034 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:75 sequence
2023-12-31 15:41:21.072 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:7b sequence
2023-12-31 15:41:32.256 WARNING (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x6115:1:0x0702]: async_initialize: all attempts have failed: [DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>')]
2023-12-31 15:41:32.340 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:a8 sequence
2023-12-31 15:41:32.357 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:aa sequence
2023-12-31 15:41:36.215 WARNING (MainThread) [homeassistant.components.sensor] Updating zha sensor took longer than the scheduled update interval 0:00:30
2023-12-31 15:41:38.131 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:ca sequence
2023-12-31 15:41:38.154 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:cd sequence
2023-12-31 15:41:38.163 WARNING (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x6115:1:0x0b04]: async_initialize: all attempts have failed: [TimeoutError(), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>')]
2023-12-31 15:41:38.284 WARNING (MainThread) [zigpy_deconz.zigbee.application] Unexpected transmit confirm for request id 196, Status: TXStatus.SUCCESS
2023-12-31 15:41:39.568 WARNING (MainThread) [zigpy_deconz.api] Duplicate or delayed response for 0x:f3 sequence
2023-12-31 15:41:42.588 WARNING (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x6115:1:0x0006]: async_initialize: all attempts have failed: [DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>'), DeliveryError('Failed to deliver packet: <TXStatus.NWK_ROUTE_DISCOVERY_FAILED: 208>')]
2023-12-31 15:41:43.203 WARNING (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xCCCC:1:0x0702]: async_initialize: all attempts have failed: [TimeoutError(), TimeoutError(), TimeoutError(), TimeoutError()]
2023-12-31 15:41:44.532 ERROR (MainThread) [zigpy.zcl] [0x96CF:1:0xff01] Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/zigpy/device.py", line 316, in request
    return await req.result
           ^^^^^^^^^^^^^^^^
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/device.py", line 315, in request
    async with asyncio_timeout(timeout):
  File "/usr/local/lib/python3.11/asyncio/timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 518, in write_attributes_safe
    res = await self.write_attributes(attributes, manufacturer=manufacturer)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 83, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 66, in wrap_zigpy_exceptions
    raise HomeAssistantError(
homeassistant.exceptions.HomeAssistantError: Failed to send request: device did not respond
puddly commented 9 months ago

@claudegel Try the latest Home Assistant beta. There have been a lot of changes to the Conbee radio library that may help.

claudegel commented 9 months ago

I just notice that my Conbee is at firmware 0x264a0700 which is an old one I think. How could I upgrade it to latest firmware in HA

claudegel commented 9 months ago

I've flashed the dongle and same result in the log. But since last HA update, 2024.1.1 it's gone. back to normal I hope.

claudegel commented 9 months ago

The last HA update fix it. no more error message in log. Thank you