search

zigpy / zigpy-znp

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

Incorrectly neighbor parse on ZDOCmd.Mgmt_Lqi_req (Z-Stack bug ?) #65

Open HiFiPhile opened 3 years ago

HiFiPhile commented 3 years ago

I'm investigating this issue https://github.com/zigpy/zigpy/issues/565 and found after a coordinator rset the neighbor table is wrong.

DEBUG:zigpy.util:Tries remaining: 3
DEBUG:zigpy_znp.zigbee.application:Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=5, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\x05\x00'
DEBUG:zigpy_znp.zigbee.application:Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Sending request: ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=14:ff:fe:5e:50:10:02:0c, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170)]))
DEBUG:zigpy_znp.zigbee.application:Pretending we received a ZDO message: b'\x05\x00\x01\x00\x01\xAE\xD5\x62\x34\xC4\xDF\x2F\x75\x0C\x02\x10\x50\x5E\xFE\xFF\x14\x2E\x84\x12\x02\x01\xAA'
DEBUG:zigpy.neighbor:[0x0000] request status: Status.SUCCESS. response: Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=14:ff:fe:5e:50:10:02:0c, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170)])
DEBUG:zigpy.neighbor:[0x0000] Done scanning. Total 1 neighbours

We can see IEEE is mixed with NWK.

Sometimes there are 2 items, the 2nd is correct

DEBUG:zigpy.util:Tries remaining: 3
DEBUG:zigpy_znp.zigbee.application:Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=3, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\x03\x00'
DEBUG:zigpy_znp.zigbee.application:Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Sending request: ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:aiosqlite:executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x05E6E0A8>, 'DELETE FROM neighbors WHERE device_ieee = ?', (84:2e:14:ff:fe:5e:50:10,))
DEBUG:aiosqlite:operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x05E6E0A8>, 'DELETE FROM neighbors WHERE device_ieee = ?', (84:2e:14:ff:fe:5e:50:10,)) completed
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:aiosqlite:executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x05E6E0A8>, 'INSERT INTO neighbors VALUES (?, ?, ?, ?, ?, ?, ?, ?)', [(84:2e:14:ff:fe:5e:50:10, 75:2f:df:c4:34:62:d5:ae, 00:12:4b:00:21:9f:c1:f9, 0x0000, 4, <PermitJoins.Unknown: 2>, 0, 252)])
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=2, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=14:ff:fe:5e:50:10:02:0c, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170), Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0x020C, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=172)]))
DEBUG:aiosqlite:operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x05E6E0A8>, 'INSERT INTO neighbors VALUES (?, ?, ?, ?, ?, ?, ?, ?)', [(84:2e:14:ff:fe:5e:50:10, 75:2f:df:c4:34:62:d5:ae, 00:12:4b:00:21:9f:c1:f9, 0x0000, 4, <PermitJoins.Unknown: 2>, 0, 252)]) completed
DEBUG:zigpy_znp.zigbee.application:Pretending we received a ZDO message: b'\x03\x00\x02\x00\x02\xAE\xD5\x62\x34\xC4\xDF\x2F\x75\x0C\x02\x10\x50\x5E\xFE\xFF\x14\x2E\x84\x12\x02\x01\xAA\xAE\xD5\x62\x34\xC4\xDF\x2F\x75\x10\x50\x5E\xFE\xFF\x14\x2E\x84\x0C\x02\x12\x02\x01\xAC'
DEBUG:zigpy.neighbor:[0x0000] request status: Status.SUCCESS. response: Neighbors(entries=2, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=14:ff:fe:5e:50:10:02:0c, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170), Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0x020C, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=172)])
DEBUG:aiosqlite:executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x05E6E0A8>)
DEBUG:zigpy.neighbor:[0x0000] Done scanning. Total 2 neighbours
puddly commented 3 years ago

Hmm. Is this only when the ZDO request is being sent to the coordinator itself?

HiFiPhile commented 3 years ago

I tried to query the valve, it seems the response is correct:

DEBUG:zigpy.util:Tries remaining: 3
DEBUG:zigpy.device:[0x020c] Extending timeout for 0x02 request
DEBUG:zigpy_znp.api:Sending request: ZDO.ExtRouteChk.Req(Dst=0x020C, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
DEBUG:zigpy_znp.zigbee.application:Starting watchdog loop
DEBUG:zigpy_znp.api:Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
DEBUG:zigpy_znp.zigbee.application:Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x020C), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=2, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\x02\x00'
DEBUG:zigpy_znp.zigbee.application:Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x020C, StartIndex=0)
DEBUG:zigpy_znp.api:Sending request: ZDO.MgmtLqiReq.Req(Dst=0x020C, StartIndex=0)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiRsp.Callback(Src=0x020C, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=00:12:4b:00:21:9f:c1:f9, nwk=0x0000, packed=4, permit_joining=<PermitJoins.Unknown: 2>, depth=0, lqi=252)]))
DEBUG:zigpy_znp.zigbee.application:Pretending we received a ZDO message: b'\x02\x00\x01\x00\x01\xAE\xD5\x62\x34\xC4\xDF\x2F\x75\xF9\xC1\x9F\x21\x00\x4B\x12\x00\x00\x00\x04\x02\x00\xFC'
DEBUG:zigpy.neighbor:[0x020c] request status: Status.SUCCESS. response: Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=75:2f:df:c4:34:62:d5:ae, ieee=00:12:4b:00:21:9f:c1:f9, nwk=0x0000, packed=4, permit_joining=<PermitJoins.Unknown: 2>, depth=0, lqi=252)])
DEBUG:zigpy.neighbor:[0x020c] Done scanning. Total 1 neighbours
HiFiPhile commented 3 years ago

I can confirme https://github.com/zigpy/zigpy/issues/565 is related to this behavior.

Once the end device is joined both wrong and right neighbor entries are added, after some time the right neighbor is disappeared and end device can no longer be commanded. Both neighbors can be read in ADDRMGR by nvram_read.

It seems it's not just a bug of communication, but the values are wrong on z-stack.

puddly commented 3 years ago

Does this happen for every end device?

I glanced over the relevant pieces of Z-Stack and no immediate location jumped out at me for where the order of these fields in memory is swapped. My theory is that this is a pair of calls to memset that writes these two fields but the order of the calls is flipped.

I'm almost done parsing every table in NVRAM so while in theory this is something that can possibly be fixed in zigpy-znp, it should be reported to TI.

HiFiPhile commented 3 years ago

Does this happen for every end device?

Currently I only have 1 Danfoss Ally for testing.

I did more test from zero with nvram erased.

With @koenkk 's firmware I can reproduce it easily, with TI's original version compiled by CCS I can't reproduce it after 24 hours test.

I do coordinator.neighbors.scan() after the device is joined. At first neighbor was correct, after some time it became wrong:

DEBUG:zigpy.util:Tries remaining: 3
DEBUG:zigpy_znp.zigbee.application:Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=36, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'$\x00'
DEBUG:zigpy_znp.zigbee.application:Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Sending request: ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0xD6CE, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=37)]))
DEBUG:zigpy_znp.zigbee.application:Pretending we received a ZDO message: b'\x24\x00\x01\x00\x01\x65\x7D\xD2\xBE\x4C\x28\xA1\xE4\x10\x50\x5E\xFE\xFF\x14\x2E\x84\xCE\xD6\x12\x02\x01\x25'    
DEBUG:zigpy.neighbor:[0x0000] request status: Status.SUCCESS. response: Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0xD6CE, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=37)])
DEBUG:zigpy.neighbor:[0x0000] Done scanning. Total 1 neighbours
[{'_device': <zigpy.device.Device object at 0x05B8FD48>, '_neighbor': Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0xD6CE, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=37)}]
DEBUG:zigpy.util:Tries remaining: 3
DEBUG:zigpy_znp.zigbee.application:Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=37, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'%\x00'
DEBUG:zigpy_znp.zigbee.application:Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Sending request: ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0xD6CE, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=37)]))
DEBUG:zigpy_znp.zigbee.application:Pretending we received a ZDO message: b'\x25\x00\x01\x00\x01\x65\x7D\xD2\xBE\x4C\x28\xA1\xE4\x10\x50\x5E\xFE\xFF\x14\x2E\x84\xCE\xD6\x12\x02\x01\x25'    
DEBUG:zigpy.neighbor:[0x0000] request status: Status.SUCCESS. response: Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0xD6CE, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=37)])
DEBUG:zigpy.neighbor:[0x0000] Done scanning. Total 1 neighbours
[{'_device': <zigpy.device.Device object at 0x05B8FD48>, '_neighbor': Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=84:2e:14:ff:fe:5e:50:10, nwk=0xD6CE, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=37)}]
DEBUG:zigpy_znp.api:Received command: AF.DataConfirm.Callback(Status=<Status.MAC_TRANSACTION_EXPIRED: 240>, Endpoint=1, TSN=8)
DEBUG:zigpy_znp.zigbee.application:Request failed (Unsuccessful request status code: <Status.MAC_TRANSACTION_EXPIRED: 240>), retry attempt 1 of 5
DEBUG:zigpy_znp.api:Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6CE), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=513, TSN=8, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=30, Data=b'\x18\x08\x0B\x0A\x00')
DEBUG:zigpy_znp.api:Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Sending request: SYS.Ping.Req()
DEBUG:zigpy_znp.api:Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.CAP_APP_CNF|CAP_GP|CAP_UTIL|CAP_ZDO|CAP_AF|CAP_SYS: 1625>)
DEBUG:zigpy_znp.api:Received command: AF.DataConfirm.Callback(Status=<Status.MAC_TRANSACTION_EXPIRED: 240>, Endpoint=1, TSN=8)
DEBUG:zigpy_znp.api:Sending request: Util.AssocGetWithAddress.Req(IEEE=84:2e:14:ff:fe:5e:50:10, NWK=0xD6CE)
DEBUG:zigpy_znp.api:Received command: Util.AssocGetWithAddress.Rsp(Device=Device(shortAddr=0xD6CE, addrIdx=0, nodeRelation=<NodeRelation.CHILD_RFD: 1>, devStatus=8, assocCnt=0, age=0, linkInfo=LinkInfo(txCounter=0, txCost=1, rxLqi=37, inKeySeqNum=0, inFrmCntr=65536, txFailure=65535), PaddingByte1=b'\xFF', PaddingByte2=b'\xFF', endDev=AgingEndDevice(endDevCfg=255, deviceTimeout=4294967295), PaddingByte3=b'\xFF', PaddingByte4=b'\xFF', PaddingByte5=b'\xFF', timeoutCounter=4294967295, keepaliveRcv=255, ctrl=255, PaddingByte6=b'\xFF', PaddingByte7=b'\xFF'))      
DEBUG:zigpy_znp.api:Sending request: Util.AssocRemove.Req(IEEE=84:2e:14:ff:fe:5e:50:10)
DEBUG:zigpy_znp.api:Received command: Util.AssocRemove.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Sending request: ZDO.ExtRouteDisc.Req(Dst=0xD6CE, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
DEBUG:zigpy_znp.api:Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.zigbee.application:Request failed (Unsuccessful request status code: <Status.MAC_TRANSACTION_EXPIRED: 240>), retry attempt 2 of 5
DEBUG:zigpy_znp.api:Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6CE), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=513, TSN=8, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=30, Data=b'\x18\x08\x0B\x0A\x00')
DEBUG:zigpy_znp.api:Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=8)
DEBUG:zigpy_znp.api:Sending request: ZDO.ExtRouteDisc.Req(Dst=0xD6CE, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
DEBUG:zigpy_znp.api:Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.zigbee.application:Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 3 of 5
DEBUG:zigpy_znp.api:Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6CE), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=513, TSN=8, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=30, Data=b'\x18\x08\x0B\x0A\x00')
DEBUG:zigpy_znp.api:Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=8)
DEBUG:zigpy_znp.zigbee.application:Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 4 of 5
DEBUG:zigpy_znp.api:Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6CE), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=513, TSN=8, Options=<TransmitOptions.NONE: 0>, Radius=30, Data=b'\x18\x08\x0B\x0A\x00')
DEBUG:zigpy_znp.api:Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=8)
DEBUG:zigpy_znp.zigbee.application:Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 5 of 5
DEBUG:zigpy_znp.api:Sending request: Util.AssocAdd.Req(NWK=0xD6CE, IEEE=84:2e:14:ff:fe:5e:50:10, NodeRelation=<NodeRelation.CHILD_RFD: 1>)
DEBUG:zigpy_znp.api:Received command: Util.AssocAdd.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy.util:Tries remaining: 3
DEBUG:zigpy_znp.zigbee.application:Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=38, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'&\x00'
DEBUG:zigpy_znp.zigbee.application:Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Sending request: ZDO.MgmtLqiReq.Req(Dst=0x0000, StartIndex=0)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
DEBUG:zigpy_znp.api:Received command: ZDO.MgmtLqiRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=14:ff:fe:5e:50:10:d6:ce, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170)]))
DEBUG:zigpy_znp.zigbee.application:Pretending we received a ZDO message: b'\x26\x00\x01\x00\x01\x65\x7D\xD2\xBE\x4C\x28\xA1\xE4\xCE\xD6\x10\x50\x5E\xFE\xFF\x14\x2E\x84\x12\x02\x01\xAA'    
DEBUG:zigpy.neighbor:[0x0000] request status: Status.SUCCESS. response: Neighbors(entries=1, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=14:ff:fe:5e:50:10:d6:ce, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170)])
DEBUG:zigpy.neighbor:[0x0000] Done scanning. Total 1 neighbours
[{'_device': None, '_neighbor': Neighbor(extended_pan_id=e4:a1:28:4c:be:d2:7d:65, ieee=14:ff:fe:5e:50:10:d6:ce, nwk=0x842E, packed=18, permit_joining=<PermitJoins.Unknown: 2>, depth=1, lqi=170)}]
DEBUG:zi
puddly commented 3 years ago

I believe I just ran into this issue. I formed a test network with three devices on a freshly-erased zzh! stick running the latest build of Z-Stack. The following devices were joined to the coordinator:

When performing a network backup by parsing the NVRAM data structures, I noticed not three but five devices show up:

{
    "nwk_address": "765b",
    "ieee_address": "00124b001c4b2159"  // Sonoff temp/humidity
},
{
    "nwk_address": "ae8e",
    "ieee_address": "00124b001c4b6e8e"  // Sonoff motion
},
{
    "nwk_address": "fffe",
    "ieee_address": "4b001c4b21591f13"  // ???
},
{
    "nwk_address": "0012",
    "ieee_address": "4b001c4b2159d4fc" // ???
},
{
    "nwk_address": "8e2f",
    "ieee_address": "d0cf5efffece3af2",  // Trådfri outlet
    "link_key": {
        "tx_counter": 0,
        "rx_counter": 0,
        "key": "d2b23cb634cda7031b7e0dc49a010ed8"
    }
}

Wireshark confirmed that the coordinator was indeed sending a parent announce message containing these two "devices":

ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
    Frame Control Field: Data (0x08)
    Destination Endpoint: 0
    Parent Announce (Cluster ID: 0x001f)
    Profile: ZigBee Device Profile (0x0000)
    Source Endpoint: 0
    Counter: 8
ZigBee Device Profile, Parent Announce, # children 2 : 4b:00:1c:4b:21:59:1f:13 ...
    Sequence Number: 5
    NumberOfChildren: 2
    Extended Address: 4b:00:1c:4b:21:59:1f:13 (4b:00:1c:4b:21:59:1f:13)
    Extended Address: 4b:00:1c:4b:21:59:d4:fc (4b:00:1c:4b:21:59:d4:fc)

In Z-Stack 3, the address manager table in NVRAM is stored so that each entry has its own "item" that you directly read. I've backed up and restored numerous networks using this parsing code and assume it is correct:

NVRAM[NvSysIds.ZSTACK][ExNvIds.ADDRMGR][0x0000] = AddrMgrEntry(type=<AddrMgrUserType.Assoc: 1>, nwkAddr=0xFFFE, extAddr=4b:00:1c:4b:21:59:1f:13)
NVRAM[NvSysIds.ZSTACK][ExNvIds.ADDRMGR][0x0001] = AddrMgrEntry(type=<AddrMgrUserType.Assoc: 1>, nwkAddr=0x0012, extAddr=4b:00:1c:4b:21:59:d4:fc)

It definitely looks like some Z-Stack bug is causing these bogus devices to be written to NVRAM. I believe some code somewhere in Z-Stack is directly reading the members of a struct like this:

uint8_t extAddr[8];
uint16_t nwkAddr;

But in the wrong order:

uint16_t nwkAddr;
uint8_t extAddr[8];

If you concatenate the NWK and IEEE addresses of the second bogus device, you can see it forms the IEEE address of the Sonoff motion sensor:

// Bogus NWK + IEEE
0x0012 4b:00:1c:4b:21:59:d4:fc

// Sonoff motion IEEE
00124b001c4b2159

This doesn't explain what the two trailing bytes are in either of the two bogus devices' IEEE addresses but it perhaps is the incorrect parsing of some ZDO announcement packet sent by another router? I don't believe a topology scan was performed by zigpy yet so this looks like something triggered by device joining.

MattWestb commented 3 years ago

If putting all "real devices" and comparing them with the "new" i getting little from all in the 2 new.

Real ones: 765b 00124b001c4b2159 ae8e 0012_4b001c4b_6e8e 8e2f d0cf5efffece3af2

False ones: fffe 4b001c4b2159 1f13 0012 4b001c4b2159 d4fc

And found parts in the false ones:

fffe 4b001c4b21591f13 0012 4b001c4b2159d4fc

The problem is the 4b001c4b part can coming from both the Sonoff sensors.

My feeling is that the last part (1f13 and d4fc) is one hashed part of the real devices mwk: 765b ae8e and 8e2f.

@puddly Can you deleting one of the Sonoff and putting in one with more different IEEE (if you is having one with IEEE: 0123456789ABCDEF its one high points device) than you can see witch part that is scrambled.

I only saying INTERESTING !!

And great findings done !!!

MattWestb commented 3 years ago

If i was having one of those coordinators then i have patching 3 IKEA modules with custom IEEE (flashing custom token with IEEE). 0011223344556677, 8899AABBCCDDEEFF and one with 0123456789ABCDEF and reading the NVRAM from the NCP.

puddly commented 3 years ago

If I can find a way recreate it again, I will try with devices with less similar IEEE addresses (and hopefully capture the packet responsible for this). Unfortunately it did not happen again after three attempts 😞