Unable to pair devices

[pipiche38]

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 !!

plugin-log.txt

[pipiche38]

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

[puddly]

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

Please include packet captures from both radios.

[TheJulianJES]

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]

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]

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]

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]

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]

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]

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]

@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]

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]

@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]

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 #231 (comment) I cannot find any thing