Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Unable to pair devices #231

Open
pipiche38 opened this issue Nov 4, 2023 · 13 comments
Open

Unable to pair devices #231

pipiche38 opened this issue Nov 4, 2023 · 13 comments

Comments

@pipiche38
Copy link
Contributor

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
Copy link
Contributor Author

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

@pipiche38 pipiche38 mentioned this issue Nov 4, 2023
Closed
@puddly
Copy link
Collaborator

puddly commented Nov 4, 2023

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

Please include packet captures from both radios.

@TheJulianJES
Copy link
Contributor

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
Copy link

zigbeefordomoticz commented Nov 4, 2023 via email

pipiche38 added a commit to zigbeefordomoticz/Domoticz-Zigbee that referenced this issue Nov 4, 2023
@pipiche38
due to zigpy-znp issue on pairing, revert back to solid znp version ( z…
3831fd9 
…igpy/zigpy-znp#231 )
@pipiche38
Copy link
Contributor Author

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
Copy link
Collaborator

puddly commented Nov 4, 2023 •
edited
Loading

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
Copy link

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
Copy link
Contributor Author

pipiche38 commented Nov 10, 2023 •
edited
Loading

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
Copy link
Contributor Author

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
Copy link
Contributor Author

pipiche38 commented Nov 10, 2023 •
edited
Loading

@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
Copy link
Contributor Author

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
Copy link
Contributor Author

pipiche38 commented Nov 10, 2023 •
edited
Loading

@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
Copy link
Contributor Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@TheJulianJES @pipiche38 @puddly @zigbeefordomoticz