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

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

Closed
Tracked by #1235
pipiche38 opened this issue Jun 28, 2022 · 9 comments
Closed
Tracked by #1235

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

pipiche38 opened this issue Jun 28, 2022 · 9 comments

Comments

@pipiche38
Copy link
Contributor

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

puddly commented Jun 28, 2022

What firmware build date is this?

@pipiche38
Copy link
Contributor Author

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

@puddly
Copy link
Collaborator

puddly commented Jun 28, 2022

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

@pipiche38
Copy link
Contributor Author

indeed same problem.

@pipiche38
Copy link
Contributor Author

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

@puddly
Copy link
Collaborator

puddly commented Jun 28, 2022

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

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

pipiche38 commented Jun 29, 2022 •
edited
Loading

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

pipiche38 commented Jun 29, 2022 •
edited
Loading

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

@pipiche38 pipiche38 mentioned this issue Jul 19, 2022
Open
22 tasks
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
2 participants
@pipiche38 @puddly