search

zigpy / zigpy-znp

TI CC2531, CC13x2, CC26x2 radio support for Zigpy and ZHA
GNU General Public License v3.0
146 stars 40 forks source link

Permit to join on specific router ends in timeout #148

Closed SylvainPer closed 2 years ago

SylvainPer commented 2 years ago

Hello, When trying to use the permit to join on a specific router (needed for Xiaomi end devices that not supports all routers), the request always finish in timeout even if the request is successful:

permit-to-join

In the log:

2022-04-22 20:43:29,284 INFO :Permitting joins for 240 seconds 2022-04-22 20:43:29,286 DEBUG :[0xf315] Extending timeout for 0x11 request 2022-04-22 20:43:29,288 DEBUG :Sending request: ZDO.ExtRouteChk.Req(Dst=0xF315, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>) 2022-04-22 20:43:29,298 DEBUG :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>) 2022-04-22 20:43:29,301 DEBUG :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0xF315, Duration=240, TCSignificance=0) 2022-04-22 20:43:29,320 DEBUG :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>) 2022-04-22 20:43:29,366 DEBUG :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0xF315, Status=<Status.SUCCESS: 0>) 2022-04-22 20:43:29,367 DEBUG :Command was not handled 2022-04-22 20:43:29,368 DEBUG :Received command: ZDO.MsgCbIncoming.Callback(Src=0xF315, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=8, MacDst=0x0000, Data=b'\x00')

Seems that the 0x8036 is well decoded after that, not sure that the timeout has a real impact.

pipiche38 commented 2 years ago

@puddly is that an "expected behaviour" and with the new-radio-api it will be sorted out.

1) the Permit to join command is correctly send to the router 2) the router is responding with a Permit Join Response Success

but it looks like we don't come back from the request call.

pipiche38 commented 2 years ago

thanks

pipiche38 commented 2 years ago

This still arrived. I got it several time on my prod. Will try to get you logs

pipiche38 commented 2 years ago

@puddly here are some logs.

Basically everything works except that we got 60 secondes after requesting the Permit join an Exceltopn

asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 6057156780829123354,}

2022-05-12 14:21:53,321 INFO    :Permitting joins for 240 seconds
2022-05-12 14:21:53,323 DEBUG   : [       ZigpyCom_4] got a command PERMIT-TO-JOIN
2022-05-12 14:21:53,326 DEBUG   :[0x836c] Extending timeout for 0x15 request
2022-05-12 14:21:53,328 DEBUG   : [       ZigpyCom_4] PERMIT-TO-JOIN: 6057156780829123354 duration: 240
2022-05-12 14:21:53,332 DEBUG   :Sending request: ZDO.ExtRouteChk.Req(Dst=0x836C, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-05-12 14:21:53,334 DEBUG   : [       ZigpyCom_4] PERMIT-TO-JOIN: duration: 240 target: 54:0f:57:ff:fe:2b:23:1a
2022-05-12 14:21:53,346 DEBUG   :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-05-12 14:21:53,354 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x836C, Duration=240, TCSignificance=0)
2022-05-12 14:21:53,379 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-05-12 14:21:53,405 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x836C, Relays=[])
2022-05-12 14:21:53,451 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x836C, Status=<Status.SUCCESS: 0>)
2022-05-12 14:21:53,456 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x836C, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=7, MacDst=0x0000, Data=b'\x00')
2022-05-12 14:21:53,460 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x836C), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=21, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x15\xF0\x00')
2022-05-12 14:21:53,492 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-05-12 14:21:53,538 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x836C, Status=<Status.SUCCESS: 0>)
2022-05-12 14:21:53,540 DEBUG   :Command was not handled
2022-05-12 14:21:53,543 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x836C, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=21, MacDst=0x0000, Data=b'\x00')
2022-05-12 14:21:54,186 DEBUG   :Received command: ZDO.TCDevInd.Callback(SrcNwk=0xA132, SrcIEEE=00:15:bc:00:1a:01:aa:27, ParentNwk=0x836C)
2022-05-12 14:21:54,188 INFO    :TC device join: ZDO.TCDevInd.Callback(SrcNwk=0xA132, SrcIEEE=00:15:bc:00:1a:01:aa:27, ParentNwk=0x836C)
2022-05-12 14:21:54,192 DEBUG   :get_device raise KeyError ieee: 0015bc001a01aa27 nwk: None !!
2022-05-12 14:21:54,197 DEBUG   :Received command: ZDO.TCDevInd.Callback(SrcNwk=0xA132, SrcIEEE=00:15:bc:00:1a:01:aa:27, ParentNwk=0x836C)
2022-05-12 14:21:54,201 INFO    :TC device join: ZDO.TCDevInd.Callback(SrcNwk=0xA132, SrcIEEE=00:15:bc:00:1a:01:aa:27, ParentNwk=0x836C)
2022-05-12 14:21:54,203 DEBUG   : [       ZigpyCom_4] zigpy_get_device( 0015bc001a01aa27(<class 'str'>), None(<class 'NoneType'>)) NOT FOUND
2022-05-12 14:21:54,207 DEBUG   :get_device raise KeyError ieee: 0015bc001a01aa27 nwk: None !!
2022-05-12 14:21:54,213 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0xA132, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-05-12 14:21:54,221 DEBUG   : [       ZigpyCom_4] zigpy_get_device( 0015bc001a01aa27(<class 'str'>), None(<class 'NoneType'>)) NOT FOUND
2022-05-12 14:21:54,238 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-05-12 14:21:54,988 DEBUG   :Received command: ZDO.EndDeviceAnnceInd.Callback(Src=0xA132, NWK=0xA132, IEEE=00:15:bc:00:1a:01:aa:27, Capabilities=<MACCapabilities.0: 0>)
2022-05-12 14:21:54,991 DEBUG   :Command was not handled
2022-05-12 14:21:55,001 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xA132, IsBroadcast=<Bool.true: 1>, ClusterId=19, SecurityUse=0, TSN=0, MacDst=0xFFFF, Data=b'\x32\xA1\x27\xAA\x01\x1A\x00\xBC\x15\x00\x00')
2022-05-12 14:21:55,004 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0xA132, Relays=[0x836C])
2022-05-12 14:21:55,007 INFO    :ZDO device announce: nwk=0xA132, ieee=00:15:bc:00:1a:01:aa:27, capabilities=0
2022-05-12 14:21:55,010 DEBUG   :get_device raise KeyError ieee: 0015bc001a01aa27 nwk: None !!
2022-05-12 14:21:55,015 DEBUG   : [       ZigpyCom_4] zigpy_get_device( 0015bc001a01aa27(<class 'str'>), None(<class 'NoneType'>)) NOT FOUND
2022-05-12 14:21:56,014 DEBUG   :New device 0xa132 (00:15:bc:00:1a:01:aa:27) joined the network
2022-05-12 14:21:56,868 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1280, SrcAddr=0xA132, SrcEndpoint=35, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=138, SecurityUse=<Bool.false: 0>, TimeStamp=9552364, TSN=0, Data=b'\x19\x18\x01\x0D\x00\x15\x10', MacSrcAddr=0x836C, MsgResultRadius=28)
2022-05-12 14:22:08,280 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=25, SrcAddr=0xA132, SrcEndpoint=35, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=142, SecurityUse=<Bool.false: 0>, TimeStamp=10265590, TSN=0, Data=b'\x11\x1D\x01\x00\x15\x10\x82\x01\x06\x06\x03\x00', MacSrcAddr=0x836C, MsgResultRadius=28)
2022-05-12 14:22:18,820 DEBUG   :Sending request: SYS.Ping.Req()
2022-05-12 14:22:18,838 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-05-12 14:22:18,860 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1280, SrcAddr=0xA132, SrcEndpoint=35, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=134, SecurityUse=<Bool.false: 0>, TimeStamp=10926845, TSN=0, Data=b'\x19\x35\x01\x0D\x00\x15\x10', MacSrcAddr=0x836C, MsgResultRadius=28)
2022-05-12 14:22:21,521 ERROR   : [       ZigpyCom_4] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 6057156780829123354,}
pipiche38 commented 2 years ago

This looks not fixed at that point time, and the issue is still there

2022-06-13 18:45:11,781 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x1918, Duration=240, TCSignificance=0)
2022-06-13 18:45:11,800 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-13 18:45:11,825 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1918, Status=<Status.SUCCESS: 0>)
2022-06-13 18:45:11,828 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1918, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-06-13 18:45:11,832 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1918), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=40, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x28\xF0\x00')
2022-06-13 18:45:11,856 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-13 18:45:11,892 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1918, Status=<Status.SUCCESS: 0>)
2022-06-13 18:45:11,894 DEBUG   :Command was not handled
2022-06-13 18:45:11,896 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1918, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=40, MacDst=0x0000, Data=b'\x00')
2022-06-13 18:45:26,513 DEBUG   :Received command: ZDO.TCDevInd.Callback(SrcNwk=0xCF1D, SrcIEEE=3c:6a:2c:ff:fe:d0:a1:29, ParentNwk=0x0000)
2022-06-13 18:45:26,515 INFO    :TC device join: ZDO.TCDevInd.Callback(SrcNwk=0xCF1D, SrcIEEE=3c:6a:2c:ff:fe:d0:a1:29, ParentNwk=0x0000)
2022-06-13 18:45:26,518 DEBUG   :get_device raise KeyError ieee: 3c6a2cfffed0a129 nwk: None !!
2022-06-13 18:45:26,523 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0xCF1D, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-06-13 18:45:26,536 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-13 18:45:26,725 DEBUG   :Received command: ZDO.EndDeviceAnnceInd.Callback(Src=0xCF1D, NWK=0xCF1D, IEEE=3c:6a:2c:ff:fe:d0:a1:29, Capabilities=<MACCapabilities.AllocateShortAddrDuringAssocNeeded: 128>)
2022-06-13 18:45:26,726 DEBUG   :Command was not handled
2022-06-13 18:45:26,729 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xCF1D, IsBroadcast=<Bool.true: 1>, ClusterId=19, SecurityUse=0, TSN=129, MacDst=0x0000, Data=b'\x1D\xCF\x29\xA1\xD0\xFE\xFF\x2C\x6A\x3C\x80')
2022-06-13 18:45:26,732 INFO    :ZDO device announce: nwk=0xCF1D, ieee=3c:6a:2c:ff:fe:d0:a1:29, capabilities=128
2022-06-13 18:45:26,735 DEBUG   :get_device raise KeyError ieee: 3c6a2cfffed0a129 nwk: None !!
2022-06-13 18:45:27,738 DEBUG   :New device 0xcf1d (3c:6a:2c:ff:fe:d0:a1:29) joined the network
2022-06-13 18:45:31,003 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=25, SrcAddr=0x1918, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=178, SecurityUse=<Bool.false: 0>, TimeStamp=7375377, TSN=0, Data=b'\x01\x43\x01\x00\x66\x11\x00\x03\x02\x00\x04\x11', MacSrcAddr=0x1918, MsgResultRadius=29)
2022-06-13 18:45:39,815 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-13 18:45:39,825 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)

2022-06-13 18:45:39,882 ERROR   : [       ZigpyCom_4] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 6066005683886011,}