search

zigpy / zigpy-znp

TI CC2531, CC13x2, CC26x2 radio support for Zigpy and ZHA
GNU General Public License v3.0
144 stars 40 forks source link

Unable to pair devices #231

Open pipiche38 opened 8 months ago

pipiche38 commented 8 months ago

Running zigpy 0.59.0 and zigpy-znp 0.11.6.

Unable to pair a device with ZNP while it works perfectly with bellows !

2023-11-04 15:24:13,569 DEBUG   :Sending request: SYS.Ping.Req()
2023-11-04 15:24:13,578 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-11-04 15:24:17,709 DEBUG   :Received command: ZDO.TCDevInd.Callback(SrcNwk=0x23DA, SrcIEEE=00:15:8d:00:01:fe:57:bb, ParentNwk=0x0000)
2023-11-04 15:24:17,711 INFO    :TC device join: ZDO.TCDevInd.Callback(SrcNwk=0x23DA, SrcIEEE=00:15:8d:00:01:fe:57:bb, ParentNwk=0x0000)
2023-11-04 15:24:17,713 DEBUG   :AppZnp get_device raise KeyError ieee: 00158d0001fe57bb nwk: None !!
2023-11-04 15:24:17,718 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0x23DA, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2023-11-04 15:24:17,740 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2023-11-04 15:24:17,789 DEBUG   :Received command: ZDO.EndDeviceAnnceInd.Callback(Src=0x23DA, NWK=0x23DA, IEEE=00:15:8d:00:01:fe:57:bb, Capabilities=<MACCapabilities.AllocateShortAddrDuringAssocNeeded|RXWhenIdle|MainsPowered|Router: 142>)
2023-11-04 15:24:17,792 DEBUG   :Command was not handled
2023-11-04 15:24:17,794 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x23DA, IsBroadcast=<Bool.true: 1>, ClusterId=19, SecurityUse=0, TSN=160, MacDst=0xFFFF, Data=b'\xDA\x23\xBB\x57\xFE\x01\x00\x8D\x15\x00\x8E')
2023-11-04 15:24:17,800 DEBUG   :AppZnp get_device raise KeyError ieee: None nwk: 23da !!
Screenshot 2023-11-04 at 15 26 29

plugin-log.txt

pipiche38 commented 8 months ago

The DeviceAnnoucement is received, but we never get handle_join() to start the provisioning process

puddly commented 8 months ago

I can't replicate this problem, new devices join just fine for me with a CC2652.

Please include packet captures from both radios.

TheJulianJES commented 8 months ago

I remember having a similar issue over a year ago or so. Devices would only join through the coordinator. My network was migrated multiple times (lastly EZSP -> ZNP IIRC) with "scripts" back then. In the end, I was able to reset and re-join all devices to a new network. Everything worked fine after that.

@pipiche38 So, was your network also migrated or did you try this on a "fresh network"? Do the devices join fine if you only allow joins through the coordinator? (If that also doesn't work for you, the issue is probably different)

zigbeefordomoticz commented 8 months ago

If I downgrade zigpy and zigpy-znp then pairing is good Envoyé de mon iPhoneLe 4 nov. 2023 à 18:44, TheJulianJES @.***> a écrit : I remember having a similar issue over a year ago or so. Devices would only join through the coordinator. My network was migrated multiple times (lastly EZSP -> ZNP IIRC) with "scripts" back then. In the end, I was able to reset and re-join all devices to a new network. Everything worked fine after that. @pipiche38 So, was your network also migrated or did you try this on a "fresh network"? Do the devices join fine if you only allow joins through the coordinator? (If that also doesn't work for you, the issue is probably different)

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you are subscribed to this thread.Message ID: @.***>

pipiche38 commented 8 months ago

I remember having a similar issue over a year ago or so. Devices would only join through the coordinator. My network was migrated multiple times (lastly EZSP -> ZNP IIRC) with "scripts" back then. In the end, I was able to reset and re-join all devices to a new network. Everything worked fine after that.

@pipiche38 So, was your network also migrated or did you try this on a "fresh network"? Do the devices join fine if you only allow joins through the coordinator? (If that also doesn't work for you, the issue is probably different)

This is a test SonOff dongle and I don't think that I have migrated from EZSP before. In any case, I returned to 

zigpy==0.56.1
zigpy_deconz==0.21.1
zigpy-cli==1.0.4
zigpy_znp==0.11.2
bellows==0.35.8

and pairing is back to normal.

puddly commented 8 months ago

The problem is that you completely replace packet_received within your ControllerApplication subclass. This is where the ZDO device announce packet is parsed. Either make sure to call super().packet_received(packet) within your application to use zigpy's parsing logic or implement ZDO parsing yourself to trigger join indications. It's available via self._maybe_parse_zdo(packet).

zigbeefordomoticz commented 8 months ago

You are right we are also calling super.packet_receive() but what I don't underunderstand is why it works with bellows and not for ZNP. Is there big differences on the way handle_join() is called ?

pipiche38 commented 8 months ago

I investigated more, and there is something happening in a different way under ZNP than Bellows It looks like device is not updated when a device is leaving the network.

So when the device is paired again, the Device Annoucement message via super(type(self),self).handle_join(nwk, ieee, parent_nwk)

2023-11-10 16:50:45,571 INFO    :b'Removing Device entry 00158d0001fe57bb from plugin IEEE2NWK'
2023-11-10 16:50:45,575 INFO    :b' (afbd/00158d0001fe57bb) sent a Leave indication and will be outside of the network. LQI: 0'
2023-11-10 16:50:45,578 INFO    :b' (afbd/00158d0001fe57bb) cleanup key plugin data informations'
2023-11-10 16:50:45,581 INFO    :b"identified device - <Device model=None manuf=None nwk=0xAFBD ieee=00:15:8d:00:01:fe:57:bb is_initialized=False> (<class 'zigpy.device.Device'>)"
2023-11-10 16:50:45,582 INFO    :b"identified device - <Device model=None manuf=None nwk=0xAFBD ieee=00:15:8d:00:01:fe:57:bb is_initialized=False> (<class 'zigpy.device.Device'>)"
2023-11-10 16:50:45,586 INFO    :b'Decode8047 - Leave response, LQI: 0 Status: 00 - [00] Success'

2023-11-10 16:50:52,091 INFO    :b'handle_join (0xf87d 00:15:8d:00:01:fe:57:bb)'
2023-11-10 16:50:53,100 INFO    :b'Device 0xf87d (00:15:8d:00:01:fe:57:bb) joined the network'
2023-11-10 16:50:53,108 INFO    :b'Device 00:15:8d:00:01:fe:57:bb changed id (0xf87d => 0xf87d)'
pipiche38 commented 8 months ago

Find here attached 2 logs files (archived).

One is the successful pairing with Bellows , and one with ZNP which is un-sucessfull.

Archive.zip

pipiche38 commented 8 months ago

@puddly may be a path. I have added some sleep() between

super(type(self),self).get_device(ieee, nwk) and super(type(self),self).handle_join(nwk, ieee, parent_nwk)

and it looks looks like it does impact, as I'm getting now the Device Annoucement packet

Here after is the logs when successfull !

2023-11-10 17:32:59,868 INFO :b'handle_join (0xf267 00:15:8d:00:01:fe:57:bb)' 2023-11-10 17:33:01,872 INFO :Device 0xf267 (00:15:8d:00:01:fe:57:bb) joined the network 2023-11-10 17:33:01,873 INFO :b'Device 0xf267 (00:15:8d:00:01:fe:57:bb) joined the network' 2023-11-10 17:33:01,874 DEBUG :[0xf267] Scheduling initialization 2023-11-10 17:33:01,875 INFO :b'Device 00:15:8d:00:01:fe:57:bb changed id (0xf267 => 0xf267)' 2023-11-10 17:33:01,878 DEBUG :Tries remaining: 5 2023-11-10 17:33:01,879 INFO :[0xf267] Requesting 'Node Descriptor' 2023-11-10 17:33:01,881 DEBUG :[0xf267] Extending timeout for 0x62 request 2023-11-10 17:33:01,882 DEBUG :Sending packet ZigbeePacket(timestamp=datetime.datetime(2023, 11, 10, 16, 33, 1, 882563, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xF267), dst_ep=0, source_route=None, extended_timeout=True, tsn=98, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'bg\xf2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None) 2023-11-10 17:33:01,886 DEBUG :Sending request: ZDO.ExtRouteChk.Req(Dst=0xF267, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>) 2023-11-10 17:33:01,892 DEBUG :Received command: ZDO.EndDeviceAnnceInd.Callback(Src=0xF267, NWK=0xF267, IEEE=00:15:8d:00:01:fe:57:bb, Capabilities=<MACCapabilities.AllocateShortAddrDuringAssocNeeded|RXWhenIdle|MainsPowered|Router: 142>) 2023-11-10 17:33:01,893 DEBUG :Command was not handled 2023-11-10 17:33:01,896 DEBUG :Received command: ZDO.MsgCbIncoming.Callback(Src=0xF267, IsBroadcast=<Bool.true: 1>, ClusterId=19, SecurityUse=0, TSN=154, MacDst=0xFFFF, Data=b'\x67\xF2\xBB\x57\xFE\x01\x00\x8D\x15\x00\x8E') 2023-11-10 17:33:01,905 DEBUG :Sending 'zdo_leave_req' failed: 2023-11-10 17:33:01,907 INFO :b"identified device - (<class 'zigpy.device.Device'>)" 2023-11-10 17:33:01,922 INFO :b"identified device - (<class 'zigpy.device.Device'>)" 2023-11-10 17:33:01,924 DEBUG :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>) 2023-11-10 17:33:01,929 INFO :b'--> Adding device f267 in self.DevicesInPairingMode' 2023-11-10 17:33:01,935 DEBUG :Sending request: ZDO.ExtRouteDisc.Req(Dst=0xF267, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30) 2023-11-10 17:33:01,937 INFO :b"--> ['9f89', '35cd', '4711', 'a8a1', 'f267']" 2023-11-10 17:33:01,943 INFO :b'[None] NEW OBJECT: f267 None' 2023-11-10 17:33:01,945 INFO :b'--> Not full scope' 2023-11-10 17:33:01,947 INFO :b'--> Build list of Attributes'

pipiche38 commented 8 months ago

the same when not working

2023-11-10 17:40:57,536 INFO :b'handle_join (0x931d 00:15:8d:00:01:fe:57:bb)' 2023-11-10 17:40:57,539 INFO :b'New device 0x931d (00:15:8d:00:01:fe:57:bb) joined the network' 2023-11-10 17:40:59,540 INFO :Device 0x931d (00:15:8d:00:01:fe:57:bb) joined the network 2023-11-10 17:40:59,542 DEBUG :[0x931d] Scheduling initialization 2023-11-10 17:40:59,544 DEBUG :Received frame on uninitialized device from ep 0 to ep 0, cluster 19: Serialized[b'\x8f\x1d\x93\xbbW\xfe\x01\x00\x8d\x15\x00\x8e'] 2023-11-10 17:40:59,546 DEBUG :[0x931d:zdo] ZDO request ZDOCmd.Device_annce: [0x931D, 00:15:8d:00:01:fe:57:bb, 142] 2023-11-10 17:40:59,548 DEBUG :Tries remaining: 5 2023-11-10 17:40:59,549 INFO :[0x931d] Requesting 'Node Descriptor' 2023-11-10 17:40:59,550 DEBUG :[0x931d] Extending timeout for 0x09 request 2023-11-10 17:40:59,552 DEBUG :Sending packet ZigbeePacket(timestamp=datetime.datetime(2023, 11, 10, 16, 40, 59, 552040, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x931D), dst_ep=0, source_route=None, extended_timeout=True, tsn=9, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\t\x1d\x93'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None) 2023-11-10 17:40:59,555 DEBUG :Sending request: ZDO.ExtRouteChk.Req(Dst=0x931D, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>) 2023-11-10 17:40:59,566 DEBUG :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>) 2023-11-10 17:40:59,570 DEBUG :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x931D), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=2, TSN=9, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x09\x1D\x93') 2023-11-10 17:40:59,588 DEBUG :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>) 2023-11-10 17:40:59,623 DEBUG :Received command: ZDO.NodeDescRsp.Callback(Src=0x931D, Status=<Status.SUCCESS: 0>, NWK=0x931D, NodeDescriptor=NullableNodeDescriptor(logical_type=<LogicalType.Router: 1>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle|MainsPowered|FullFunctionDevice: 142>, manufacturer_code=4454, maximum_buffer_size=127, maximum_incoming_transfer_size=80, server_mask=0, maximum_outgoing_transfer_size=80, descriptor_capability_field=<DescriptorCapability.NONE: 0>, allocate_address=True, is_alternate_pan_coordinator=False, is_coordinator=False, is_end_device=False, is_full_function_device=True, is_mains_powered=True, is_receiver_on_when_idle=True, is_router=True, *is_security_capable=False)) 2023-11-10 17:40:59,627 DEBUG :Command was not handled 2023-11-10 17:40:59,629 DEBUG :Received command: ZDO.MsgCbIncoming.Callback(Src=0x931D, IsBroadcast=<Bool.false: 0>, ClusterId=32770, SecurityUse=0, TSN=9, MacDst=0x0000, Data=b'\x00\x1D\x93\x01\x40\x8E\x66\x11\x7F\x50\x00\x00\x00\x50\x00\x00') 2023-11-10 17:40:59,640 INFO :b"identified device - (<class 'zigpy.device.Device'>)" 2023-11-10 17:40:59,644 INFO :b"identified device - (<class 'zigpy.device.Device'>)" 2023-11-10 17:40:59,650 INFO :b'Decode8042 receives a message from a non existing device 931d' 2023-11-10 17:41:03,581 DEBUG :Sending request: SYS.Ping.Req() 2023-11-10 17:41:03,590 DEBUG :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)

pipiche38 commented 8 months ago

@puddly Apologize I didn't push the right log previously. So here are the 2 logs pairing-issue-ZNP copy.log pairing-OK-bellows.log.zip

pipiche38 commented 8 months ago

If you want to look what we have done from a code perspective

Here is the ZNP part https://github.com/zigbeefordomoticz/Domoticz-Zigbee/blob/zigpy-packet-receive/Classes/ZigpyTransport/AppZnp.py

Here is the Bellows part https://github.com/zigbeefordomoticz/Domoticz-Zigbee/blob/zigpy-packet-receive/Classes/ZigpyTransport/AppBellows.py

and here is where the real logic is (and is common to ZNP, Bellows and deconz) https://github.com/zigbeefordomoticz/Domoticz-Zigbee/blob/zigpy-packet-receive/Classes/ZigpyTransport/AppDeconz.py

I'm more than ready to accept that there is an issue in our integration, but when it is perfectly working with Bellows, iot works time to time (when adding sleep) with ZNP, I'm very currious to understand how I should track that and when looking at the log https://github.com/zigpy/zigpy-znp/issues/231#issuecomment-1806094179 I cannot find any thing