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

asyncio.TimeoutError when permit to join on specific router #154

Closed pipiche38 closed 2 years ago

pipiche38 commented 2 years ago

when using ZDO.MgmtPermitJoinReq on a targeted router , it open the network on the corresponding router, but around 18 seconds later there is an asyncio.Timeout because we never come back from await self.app.permit(time_s=duration, node=target_router )

If we simply use None for the node, there is no issue at all.

2022-06-28 18:33:26,232 INFO    : [       MainThread] Requesting router: 1775 to enable Permit to join
2022-06-28 18:33:26,233 DEBUG   : [       MainThread] zdp_permit_joining_request 1775 f0 00
2022-06-28 18:33:26,234 DEBUG   : [       MainThread] zdp_raw_permit_joining_request 1775 f0 00
2022-06-28 18:33:26,235 INFO    : [       MainThread] sendData       - [None] PERMIT-TO-JOIN {'Duration': 240, 'targetRouter': 7497054118825609865} None Queue Length: 0
2022-06-28 18:33:26,236 DEBUG   : [       MainThread] ===> sendData - Cmd: PERMIT-TO-JOIN Datas: {'Duration': 240, 'targetRouter': 7497054118825609865}
2022-06-28 18:33:26,261 INFO    :Permitting joins for 240 seconds
2022-06-28 18:33:26,262 DEBUG   : [       ZigpyCom_8] got a command PERMIT-TO-JOIN
2022-06-28 18:33:26,263 DEBUG   :[0x1775] Extending timeout for 0x25 request
2022-06-28 18:33:26,264 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 7497054118825609865}, 'NwkId': None, 'TimeStamp': 1656437606.229769, 'ACKIsDisable': False, 'Sqn': None}
2022-06-28 18:33:26,267 DEBUG   :Sending request: ZDO.ExtRouteChk.Req(Dst=0x1775, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-28 18:33:26,268 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 for Radio: znp for node: 68:0a:e2:ff:fe:7a:ca:89
2022-06-28 18:33:26,272 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:68:0a:e2:ff:fe:7a:ca:89 nwk:None
2022-06-28 18:33:26,273 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x1775 ieee=68:0a:e2:ff:fe:7a:ca:89 is_initialized=False>
2022-06-28 18:33:26,274 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x1775
2022-06-28 18:33:26,276 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x1775 ieee=68:0a:e2:ff:fe:7a:ca:89 is_initialized=False>
2022-06-28 18:33:26,278 DEBUG   :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-28 18:33:26,281 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x1775, Duration=240, TCSignificance=0)
2022-06-28 18:33:26,300 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-28 18:33:26,325 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x1775, Relays=[])
2022-06-28 18:33:26,327 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x1775
2022-06-28 18:33:26,328 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x1775 ieee=68:0a:e2:ff:fe:7a:ca:89 is_initialized=False>
2022-06-28 18:33:26,378 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1775, Status=<Status.SUCCESS: 0>)
2022-06-28 18:33:26,379 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1775, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=8, MacDst=0x0000, Data=b'\x00')
2022-06-28 18:33:26,381 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1775), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=37, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x25\xF0\x00')
2022-06-28 18:33:26,384 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x1775
2022-06-28 18:33:26,386 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x1775 ieee=68:0a:e2:ff:fe:7a:ca:89 is_initialized=False>
2022-06-28 18:33:26,388 DEBUG   : [       ZigpyCom_8] handle_message 0x8036: 0x1775 Profile: 0000 Cluster: 8036 srcEp: 00 dstEp: 00 message: 0800
2022-06-28 18:33:26,390 DEBUG   : [       ZigpyCom_8] ===> receiveData for Forwarded - Message 0180140002ff010003
2022-06-28 18:33:26,391 INFO    : [ ZigpyForwarder_8] Accepting new Hardware: Enable (On)
2022-06-28 18:33:26,402 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-28 18:33:26,439 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x1775, Relays=[])
2022-06-28 18:33:26,441 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x1775, Relays=[])
2022-06-28 18:33:26,444 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x1775
2022-06-28 18:33:26,445 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x1775 ieee=68:0a:e2:ff:fe:7a:ca:89 is_initialized=False>
2022-06-28 18:33:26,504 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1775, Status=<Status.SUCCESS: 0>)
2022-06-28 18:33:26,505 DEBUG   :Command was not handled
2022-06-28 18:33:26,506 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1775, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=37, MacDst=0x0000, Data=b'\x00')
2022-06-28 18:33:26,510 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x1775
2022-06-28 18:33:26,512 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x1775 ieee=68:0a:e2:ff:fe:7a:ca:89 is_initialized=False>
2022-06-28 18:33:26,513 DEBUG   : [       ZigpyCom_8] handle_message 0x8036: 0x1775 Profile: 0000 Cluster: 8036 srcEp: 00 dstEp: 00 message: 2500
2022-06-28 18:33:26,514 DEBUG   : [       ZigpyCom_8] ===> receiveData for Forwarded - Message 0180140002ff010003
2022-06-28 18:33:29,428 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-28 18:33:29,435 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-06-28 18:33:54,439 ERROR   : [       ZigpyCom_8] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 7497054118825609865,}
2022-06-28 18:33:59,438 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-28 18:33:59,446 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
puddly commented 2 years ago

What firmware build date is this?

pipiche38 commented 2 years ago

20211207, I'll try the latest 20220219. The CIE is a zzh

puddly commented 2 years ago

Shouldn't make a difference as long as it's above 20210708.

pipiche38 commented 2 years ago

indeed same problem.

pipiche38 commented 2 years ago

how do you suggest I should approach , debug that issue ?

puddly commented 2 years ago

Everything looks like it should be working and I again tested a ZZH with the latest dev version of Home Assistant with the updated radio libraries and zigpy, including some additional debug logging.

diff --git a/zigpy/application.py b/zigpy/application.py
index 0930fa4..3777b3b 100644
--- a/zigpy/application.py
+++ b/zigpy/application.py
@@ -629,6 +629,7 @@ class ControllerApplication(zigpy.util.ListenableMixin, abc.ABC):
             if node != self.state.node_info.ieee:
                 try:
                     dev = self.get_device(ieee=node)
+                    LOGGER.debug("Sending 'mgmt_permit_joining_req' to %s", node)
                     r = await dev.zdo.permit(time_s)
                     LOGGER.debug("Sent 'mgmt_permit_joining_req' to %s: %s", node, r)
                 except KeyError:

Can you replicate this problem without Domoticz, using just ZHA from Home Assistant dev, and post the debug logs?

pipiche38 commented 2 years ago

@puddly I trust you when you say it works with ZHA I have no doubt on that, so for me this will not bring value to test outside of Domoticz, as my issue is there. But 1/ the problem is happening only on ZNP (not on bellows; for deConz I understood this is not possible) 2/ the problem occurred only on the permit to join when a router is targeted

The problem is not on the permit to join it self, it works, the newtork is correctly open on that router, the issue is it looks like the we never come back from teh request and so zigpy trigger a Timeout

So for me it is more how to debug the await part ?

pipiche38 commented 2 years ago

Here is a minimum logs with bellows

2022-06-29 09:01:52,949 INFO    : [       MainThread] Requesting router: b7eb to enable Permit to join
2022-06-29 09:01:52,950 DEBUG   : [       MainThread] zdp_permit_joining_request b7eb f0 00
2022-06-29 09:01:52,951 DEBUG   : [       MainThread] zdp_raw_permit_joining_request b7eb f0 00
2022-06-29 09:01:52,965 INFO    : [       ZigpyCom_9] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 7497054118825609865}, 'NwkId': None, 'TimeStamp': 1656489712.9469523, 'ACKIsDisable': False, 'Sqn': None}
2022-06-29 09:01:52,967 INFO    : [       ZigpyCom_9] PERMIT-TO-JOIN: duration: 240 for Radio: ezsp for node: 68:0a:e2:ff:fe:7a:ca:89
2022-06-29 09:01:57,817 INFO    : [       ZigpyCom_9] returning from the self.app.permit(time_s=240, node=68:0a:e2:ff:fe:7a:ca:89 )

here are a minimum logs with ZNP

2022-06-29 09:00:25,123 INFO    : [       MainThread] Requesting router: f1fa to enable Permit to join
2022-06-29 09:00:25,153 INFO    :Entering in AppZnp permit 'mgmt_permit_joining_req' to 68:0a:e2:ff:fe:7a:ca:89
2022-06-29 09:00:25,154 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 7497054118825609865}, 'NwkId': None, 'TimeStamp': 1656489625.1214826, 'ACKIsDisable': False, 'Sqn': None}
2022-06-29 09:00:25,156 INFO    :Ready to send 'mgmt_permit_joining_req' to 68:0a:e2:ff:fe:7a:ca:89
2022-06-29 09:00:25,157 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 for Radio: znp for node: 68:0a:e2:ff:fe:7a:ca:89
2022-06-29 09:00:25,281 INFO    : [ ZigpyForwarder_8] Accepting new Hardware: Enable (On)
2022-06-29 09:00:53,331 ERROR   : [       ZigpyCom_8] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 7497054118825609865,}

From my current investigation, it never comes back from

r = await dev.zdo.permit(time_s)

Despite the fact that

:ZDO permit Mgmt_Permit_Joining_req is correctly done.

pipiche38 commented 2 years ago

Is that not an issue ? that I don't seem with Bellows

2022-06-29 09:50:57,314 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-06-29 09:50:57,316 DEBUG   :[0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])