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.

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

Implement new zigpy radio API #97

Merged
merged 43 commits into from
Jun 19, 2022
Merged

Conversation

puddly
Copy link
Collaborator

@puddly puddly commented Nov 12, 2021

Implements zigpy/zigpy#848.

Unit tests for zigpy-znp pass locally.

@puddly puddly force-pushed the puddly/new-radio-settings-api branch from 19088d2 to 53150fd Compare November 30, 2021 19:42
@puddly puddly force-pushed the puddly/new-radio-settings-api branch from 53150fd to 3ee8c2c Compare December 12, 2021 22:46
@puddly puddly mentioned this pull request Dec 12, 2021
6 tasks
@SylvainPer
Copy link

Hello @puddly, I tried to use the new radio API and last on the same conclusion as @pipiche38, I didn't succeeded in putting the pieces together.
As I understand the changes, the previous startup() function is now replaced by connect() and start_network().

  • connect() goes fine and I have the log: "Connected to /dev/ttyUSB0 at 115200 baud"
  • start_network() is not going to the end, last logs are a problem on commissioning:
2022-02-14 23:50:32,122 DEBUG   :Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2022-02-14 23:50:32,128 DEBUG   :Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2022-02-14 23:50:32,129 DEBUG   :Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)

Any idea what I missed? I'm still a beginner.

I don't see the possibility to form a new network through an option of start_network(), should form_network() called directly ?

@puddly
Copy link
Collaborator Author

puddly commented Feb 14, 2022

As I understand the changes, the previous startup() function is now replaced by connect() and start_network().

The API hasn't really changed. startup() has moved into zigpy since all radios will provide start_network, write_network_settings, etc. so the logic will be the same for all of them: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L57-L73

You still use it the way you did before, you just need to install the "new radio API" branches of zigpy-znp and zigpy. In theory, nothing will change.

start_network() is not going to the end, last logs are a problem on commissioning:

FormationFailure is normal but if the function isn't exiting, that may be a bug. I will take a look at it later.

I don't see the possibility to form a new network through an option of start_network(), should form_network() called directly ?

Pass auto_form=True to startup or call form_network directly, the code merely calls write_network_settings with randomly generated settings: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L105-L168

@pipiche38
Copy link
Contributor

pipiche38 commented Feb 15, 2022

As I understand the changes, the previous startup() function is now replaced by connect() and start_network().

The API hasn't really changed. startup() has moved into zigpy since all radios will provide start_network, write_network_settings, etc. so the logic will be the same for all of them: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L57-L73

You still use it the way you did before, you just need to install the "new radio API" branches of zigpy-znp and zigpy. In theory, nothing will change.

start_network() is not going to the end, last logs are a problem on commissioning:

FormationFailure is normal but if the function isn't exiting, that may be a bug. I will take a look at it later.

I don't see the possibility to form a new network through an option of start_network(), should form_network() called directly ?

Pass auto_form=True to startup or call form_network directly, the code merely calls write_network_settings with randomly generated settings: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L105-L168

It really a shame, we had a working environment and this small changes as you say, make the think not working anymore. I'm not sure this is a comminissioning issue, as the Coordinator works very well with the old radio API

Feb 15 08:56:31 rasp domoticz[25092]: Traceback (most recent call last):
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/threading.py", line 973, in _bootstrap_inner
Feb 15 08:56:31 rasp domoticz[25092]:     self.run()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/threading.py", line 910, in run
Feb 15 08:56:31 rasp domoticz[25092]:     self._target(*self._args, **self._kwargs)
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 73, in zigpy_thread
Feb 15 08:56:31 rasp domoticz[25092]:     asyncio.run(
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
Feb 15 08:56:31 rasp domoticz[25092]:     return loop.run_until_complete(main)
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
Feb 15 08:56:31 rasp domoticz[25092]:     return future.result()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 108, in radio_start
Feb 15 08:56:31 rasp domoticz[25092]:     await self.app.startup(
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppZnp.py", line 59, in startup
Feb 15 08:56:31 rasp domoticz[25092]:     await super().startup(auto_form=auto_form)
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/application.py", line 70, in startup
Feb 15 08:56:31 rasp domoticz[25092]:     await self.start_network()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 183, in start_network
Feb 15 08:56:31 rasp domoticz[25092]:     await self._znp.start_network()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 255, in start_network
Feb 15 08:56:31 rasp domoticz[25092]:     raise RuntimeError(
Feb 15 08:56:31 rasp domoticz[25092]: RuntimeError: Network formation failed: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)

@SylvainPer
Copy link

@puddly you should guess that if everything was working like before, we won't be there :)

The startup from zigpy is not calling connect() so we have to call it first ?

@puddly
Copy link
Collaborator Author

puddly commented Feb 15, 2022

No, that's a regression. I will re-add it to zigpy's startup.

@SylvainPer
Copy link

I had to add a try/except on the call of await self._znp.start_network() in application.py or the function was not ending properly.
I always have this exception at startup.

@pipiche38
Copy link
Contributor

No, that's a regression. I will re-add it to zigpy's startup.

@puddly, can you tell us, how is the standard framework, because I'm struggling that we are facing this issue and you not, no may be we are doing it correctly. Better than we use the same approach to avoid future issues

@Hedda
Copy link
Contributor

Hedda commented Feb 16, 2022

Asked in zigpy/zigpy-zigate#117 if using puddly's new radio API repo branches for zigpy, zigpy-znp, zigpy-cli, and zigpy-zigate(?):

https://github.com/puddly/zigpy/tree/puddly/new-radio-settings-api

https://github.com/puddly/zigpy-znp/tree/puddly/new-radio-settings-api

https://github.com/puddly/zigpy-cli/tree/puddly/zigpy-radio-api

https://github.com/puddly/zigpy-zigate/tree/puddly/new-radio-api

They are all updated so need to install those modified versions of zigpy and zigpy-znp from those branches to test new radio API:

# May need to uninstall zigpy, zigpy-znp, zigpy-cli, and zigpy-zigate first
pip install \
    git+https://github.com/puddly/zigpy.git@puddly/new-radio-settings-api \
    git+https://github.com/puddly/zigpy-znp.git@puddly/new-radio-settings-api \
    git+https://github.com/puddly/zigpy-cli.git@puddly/zigpy-radio-api \
    git+https://github.com/puddly/zigpy-zigate.git@puddly/new-radio-api

As mentioned may need to first uninstall all of them before installing the modified versions of them from puddly's repo branches.

@SylvainPer
Copy link

Hello Hedda,
Installation steps are well understood and it's not the problem we encountered.
With the new radio libraries, the plugin didn't initialized and failed to run.
Two problems identified:

  • connect() was not called anymore
  • an exception is not managed during the start network procedure and raised each time

Our concern is why only us met the problem? How the modification are tested and in which condition, that'll help.

@pipiche38
Copy link
Contributor

@puddly, we are trying to test your PRs by taking your repository for zigpy and zigpy-znp on the new-radio-api branche, but somehow the results are cahotic, which means sometime it works some other time it doesn't

@deufo has identified that the start_network () fails time to time by just adding a try/except on line 183 - encapsulate the start_network()

2022-02-19 13:01:28,574 DEBUG :start_network exception: Network formation failed: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)

So for now, we cannot even think to test zigpy-zigate. can you help us on this ?

@pipiche38
Copy link
Contributor

basically here is the change which makes our plugin working

diff --git a/zigpy_znp/zigbee/application.py b/zigpy_znp/zigbee/application.py
index 2d6f578..fee47c0 100644
--- a/zigpy_znp/zigbee/application.py
+++ b/zigpy_znp/zigbee/application.py
@@ -180,7 +180,11 @@ class ControllerApplication(zigpy.application.ControllerApplication):
         if self.state.node_info == zigpy.state.NodeInfo():
             await self.load_network_info()

-        await self._znp.start_network()
+        asyncio.sleep(1)
+        try:
+            await self._znp.start_network()
+        except:
+            LOGGER.debug("start_network exception: %s" %e)

         self._version_rsp = await self._znp.request(c.SYS.Version.Req())

@puddly
Copy link
Collaborator Author

puddly commented Feb 20, 2022

I will take a look at this later next week.

@pipiche38
Copy link
Contributor

Puddly, While testing zigpy (new radio-API and the znp/new-radio-api from your repository), I still get Timeout when requesting a permit to join to a particular router

2022-06-16 14:50:25,748 INFO    : [       MainThread] Requesting router: 96be to enable Permit to join
2022-06-16 14:50:25,749 DEBUG   : [       MainThread] zdp_permit_joining_request 96be f0 00
2022-06-16 14:50:25,750 DEBUG   : [       MainThread] zdp_raw_permit_joining_request 96be f0 00
2022-06-16 14:50:25,761 INFO    :Permitting joins for 240 seconds
2022-06-16 14:50:25,763 DEBUG   :[0x96be] Extending timeout for 0x10 request
2022-06-16 14:50:25,764 DEBUG   : [       ZigpyCom_8] got a command PERMIT-TO-JOIN
2022-06-16 14:50:25,766 DEBUG   :Sending request: ZDO.ExtRouteChk.Req(Dst=0x96BE, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-16 14:50:25,767 DEBUG   : [       ZigpyCom_8] PERMIT-TO-JOIN: 1253443264226639 duration: 240
2022-06-16 14:50:25,771 DEBUG   : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 target: 00:04:74:00:00:82:a5:4f
2022-06-16 14:50:25,771 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:00:04:74:00:00:82:a5:4f nwk:None
2022-06-16 14:50:25,772 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,773 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x96BE
2022-06-16 14:50:25,774 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,775 DEBUG   :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-16 14:50:25,779 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x96BE, Duration=240, TCSignificance=0)
2022-06-16 14:50:25,792 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,837 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,839 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x96BE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-06-16 14:50:25,841 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x96BE), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=16, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\xF0\x00')
2022-06-16 14:50:25,845 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x96BE
2022-06-16 14:50:25,848 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,850 DEBUG   : [       ZigpyCom_8] handle_message 0x8036: 0x96BE Profile: 0000 Cluster: 8036 srcEp: 00 dstEp: 00 message: 0300
2022-06-16 14:50:25,851 INFO    : [ ZigpyForwarder_8] Accepting new Hardware: Enable (On)
2022-06-16 14:50:25,858 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,903 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,904 DEBUG   :Command was not handled
2022-06-16 14:50:25,905 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x96BE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=16, MacDst=0x0000, Data=b'\x00')
2022-06-16 14:50:25,908 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x96BE
2022-06-16 14:50:25,909 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,910 DEBUG   : [       ZigpyCom_8] handle_message 0x8036: 0x96BE Profile: 0000 Cluster: 8036 srcEp: 00 dstEp: 00 message: 1000
2022-06-16 14:50:33,431 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-16 14:50:33,437 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-06-16 14:50:53,894 ERROR   : [       ZigpyCom_8] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 1253443264226639,}

@puddly
Copy link
Collaborator Author

puddly commented Jun 16, 2022

Looks like it works fine:

2022-06-16 14:50:25,779 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x96BE, Duration=240, TCSignificance=0)
2022-06-16 14:50:25,792 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,837 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)

I also can't replicate the problem with ZHA. How are you permitting joins through a specific router?

@pipiche38
Copy link
Contributor

pipiche38 commented Jun 16, 2022

yes, it does work, however there is a TimeOut which is rise and it looks like until the timout is issue commands are just queuing

So we don't get return from the self.app.permit(time_s=duration, node=target) call

@pipiche38
Copy link
Contributor

pipiche38 commented Jun 16, 2022

I believe the Timeout is triggered by the zigpy lib;
asyncio.TimeoutError /

can it be related to

2022-06-16 14:50:25,903 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,904 DEBUG   :Command was not handled

Don't know much your code, but is this test not the issue, as in that case, I do see that we setup a Callback_rsp as node != self.ieee and time_s != 0

if time_s == 0 or self._zstack_build_id < 20210708 or node == self.ieee:

@puddly
Copy link
Collaborator Author

puddly commented Jun 16, 2022

I've added some extra logging to ZHA and everything is working as intended:

# Before call to `permit(node=...)`
2022-06-16 13:51:29 INFO (MainThread) [homeassistant.components.zha.api] Permitting joins through cc:cc:cc:ff:fe:e6:8e:ca for 60s...

2022-06-16 13:51:29 INFO (MainThread) [zigpy_znp.zigbee.application] Permitting joins for 60 seconds
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.application] Sending 'mgmt_permit_joining_req' to cc:cc:cc:ff:fe:e6:8e:ca
2022-06-16 13:51:29 INFO (MainThread) [zigpy.zdo] Sending ZDOCmd.Mgmt_Permit_Joining_req (60, 0)
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Sending profile, cluster, src_ep, dst_ep, sequence, data = (0, <ZDOCmd.Mgmt_Permit_Joining_req: 0x0036>, 0, 0, 12, b'\x0c<\x00') with seq=<zigpy.util.Request object at 0x10eaf5660>
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x1B94, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x1B94, Duration=60, TCSignificance=0)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1B94, Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x1B94, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1B94), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=12, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x0C\x3C\x00')
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Received hdr args {'_command_id': <ZDOCmd.Mgmt_Permit_Joining_rsp: 0x8036>, '_tsn': 3} [<Status.SUCCESS: 0>] pending {12: <zigpy.util.Request object at 0x10eaf5660>}
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.zdo] [0x1b94:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.zdo] [0x1b94:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1B94, Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x1B94, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=12, MacDst=0x0000, Data=b'\x00')
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Received hdr args {'_command_id': <ZDOCmd.Mgmt_Permit_Joining_rsp: 0x8036>, '_tsn': 12} [<Status.SUCCESS: 0>] pending {12: <zigpy.util.Request object at 0x10eaf5660>}
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Resolving request 12 with [<Status.SUCCESS: 0>]
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.application] Sent 'mgmt_permit_joining_req' to cc:cc:cc:ff:fe:e6:8e:ca: [<Status.SUCCESS: 0>]

# After call to `permit(node=...)`
2022-06-16 13:51:29 INFO (MainThread) [homeassistant.components.zha.api] Successfully permitted joins through cc:cc:cc:ff:fe:e6:8e:ca for 60s

What exact coordinator and firmware are you using?

@pipiche38
Copy link
Contributor

Yes the Permit to join work and I'm able to pair devices, however the permit call is not returning until it's timeout which them create some side effect in our environment.

The problem occured with new-radio-API or not only on ZNP (not on bellows, not on deconz) with
Sonoff and zzh and zzhp

Firmware is 20220219

@puddly
Copy link
Collaborator Author

puddly commented Jun 16, 2022

however the permit call is not returning until it's timeout which them create some side effect in our environment.

This is what I'm unable to replicate. I'm also using a ZZH with the same firmware.

@pipiche38
Copy link
Contributor

however the permit call is not returning until it's timeout which them create some side effect in our environment.

This is what I'm unable to replicate. I'm also using a ZZH with the same firmware.

I'm glad for you, but how should I debug it ? all is in the zigpy layers as it never returns from the call and that is the zigpy async timeout which is triggered!

@pipiche38
Copy link
Contributor

Here is the stack trace when the Timeout is issued

Traceback (most recent call last):
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 344, in _permit_to_joint
    await self.app.permit(time_s=duration, node=target_router )
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 532, in permit
    await super().permit(time_s=time_s, node=node)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/application.py", line 427, in permit
    r = await dev.zdo.permit(time_s)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/device.py", line 327, in request
    return await asyncio.wait_for(req.result, timeout)
  File "/usr/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

Here is global permit to join which do not trigger timeout

2022-06-17 10:01:36,367 INFO    : [       MainThread] Request Accepting new Hardware for 240 seconds
2022-06-17 10:01:36,398 INFO    :Permitting joins for 240 seconds
2022-06-17 10:01:36,401 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=240, TCSignificance=0)
2022-06-17 10:01:36,402 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 'FFFC'}, 'NwkId': None, 'TimeStamp': 1655456496.3652534, 'ACKIsDisable': False, 'Sqn': None}
2022-06-17 10:01:36,405 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 for Radio: znp for node: None
2022-06-17 10:01:36,413 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:01:36,415 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2022-06-17 10:01:36,416 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=10, MacDst=0x0000, Data=b'\x00')
2022-06-17 10:01:36,418 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=167, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\xA7\xF0\x00')
2022-06-17 10:01:36,423 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-06-17 10:01:36,425 DEBUG   :[0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2022-06-17 10:01:36,431 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:01:36,433 INFO    : [       ZigpyCom_8] returning from the self.app.permit(time_s=240, node=None )

Now is the Permit to join to a specific router

2022-06-17 10:00:24,004 INFO    :Permitting joins for 240 seconds
2022-06-17 10:00:24,005 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 1253443264774027}, 'NwkId': None, 'TimeStamp': 1655456423.933107, 'ACKIsDisable': False, 'Sqn': None}
2022-06-17 10:00:24,006 DEBUG   :[0xbfbe] Extending timeout for 0xa6 request
2022-06-17 10:00:24,007 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 for Radio: znp for node: 00:04:74:00:00:8a:ff:8b
2022-06-17 10:00:24,009 DEBUG   :Sending request: ZDO.ExtRouteChk.Req(Dst=0xBFBE, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-17 10:00:24,017 DEBUG   :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-17 10:00:24,019 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0xBFBE, Duration=240, TCSignificance=0)
2022-06-17 10:00:24,038 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,084 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0xBFBE, Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,086 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xBFBE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=9, MacDst=0x0000, Data=b'\x00')
2022-06-17 10:00:24,087 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xBFBE), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=166, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\xA6\xF0\x00')
2022-06-17 10:00:24,094 INFO    : [ ZigpyForwarder_8] Accepting new Hardware: Enable (On)
2022-06-17 10:00:24,109 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,165 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0xBFBE, Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,166 DEBUG   :Command was not handled
2022-06-17 10:00:24,167 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xBFBE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=166, MacDst=0x0000, Data=b'\x00')
2022-06-17 10:00:43,562 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-17 10:00:43,569 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-06-17 10:00:52,133 ERROR   : [       ZigpyCom_8] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 1253443264774027,}

Last I see a strange behaviour while sniffing the trafic as I see 2 Permit to join sent !!

Screenshot 2022-06-17 at 11 12 53

@codecov-commenter
Copy link

codecov-commenter commented Jun 19, 2022

Codecov Report

Merging #97 (9dce57e) into dev (19df5c0) will increase coverage by 0.00%.
The diff coverage is 98.25%.

@@           Coverage Diff           @@
##              dev      #97   +/-   ##
=======================================
  Coverage   98.59%   98.60%           
=======================================
  Files          44       43    -1     
  Lines        3916     3863   -53     
=======================================
- Hits         3861     3809   -52     
+ Misses         55       54    -1     
Impacted Files Coverage Δ
zigpy_znp/api.py 97.15% <96.38%> (+0.34%) ⬆️
zigpy_znp/const.py 100.00% <100.00%> (ø)
zigpy_znp/tools/energy_scan.py 100.00% <100.00%> (ø)
zigpy_znp/tools/network_backup.py 97.82% <100.00%> (-0.10%) ⬇️
zigpy_znp/tools/network_restore.py 100.00% <100.00%> (ø)
zigpy_znp/types/commands.py 100.00% <100.00%> (ø)
zigpy_znp/types/named.py 100.00% <100.00%> (ø)
zigpy_znp/zigbee/application.py 95.27% <100.00%> (-0.60%) ⬇️
zigpy_znp/zigbee/device.py 100.00% <100.00%> (ø)
zigpy_znp/znp/security.py 95.18% <100.00%> (ø)
... and 2 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 19df5c0...9dce57e. Read the comment docs.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants