• State Resolved
  • Locked Locked
  • Replies 13 replies
  • Subscribers 55 subscribers
  • Views 682 views
  • Users 0 members are here
Support feedback
Options
Options
Similar topics

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

Original question:

CC2530: The reported IEEE Address of an end device is and remains 00:00:00:00:00:00:00:00 - ZIGBEE-LINUX-SENSOR-TO-CLOUD_1...

CC2530: Device Announcement, but not added to the Device List - ZIGBEE-LINUX-SENSOR-TO-CLOUD_1.0.1

Mario DW
Genius 3145 points
Part Number: CC2530
Other Parts Discussed in Thread: Z-STACK

Now that the NWKMGR's memory accesses have be fixed, I can concentrate on issues related to core functionnality.

In this test, I associate a device in the network - the gateway announce 0 known devices at the start.
I tried this multiple times (i.e., I did the association process multiple times in row without success)

The device 00:15:8d:00:04:7b:83:69 get the NWK address 0xd596 and transport key, announces itself and reports attributes. It also responds to an extended address request.
Despite that the device does not show up in the device list, the IEEE address reported by the NWK server is 0 and this does not resolve at all.


What has to be changed in the gateway to fix this? [Why does the device announcement does not have its desired effect, etc.]


Logs are below, but separate in the attached zip - there is a timeshift due to local time and utc time for some logs. I do not have the ZLS log.

****** The Device 0xD596 corresponds to a TI SampleLight that must be acting as a router.
****** It was associated in an old session, but is it apparently still allowed to act in the network.
****** This is the entry in an old DbDeviceInfo:
****** DbHistoryFull/20201113_200112.DbDeviceInfo.csv: 00:12:4B:00:01:DD:7A:D7 , 0xD596 , 0x01, 0x0000 , 3, 00:12:4B:00:10:22:82:77, 0x0E
5966 2020-11-14 16:35:24.850816 0xd596 â~F~R 0x0000 ZigBee 47 Route Record, Dst: 0x0000
5967 2020-11-14 16:35:24.851426 â~F~R IEEE 802.15.4 5 Ack
5968 2020-11-14 16:35:24.856837 0xd596 â~F~R 0x0000 ZigBee 51 Update Device
5969 2020-11-14 16:35:24.857179 â~F~R IEEE 802.15.4 5 Ack
5970 2020-11-14 16:35:24.861240 0xd596 â~F~R 0x0000 ZigBee 47 Route Record, Dst: 0x0000
5971 2020-11-14 16:35:24.861692 â~F~R IEEE 802.15.4 5 Ack
5972 2020-11-14 16:35:24.869705 0xd596 â~F~R 0x0000 ZigBee 68 Update Device
****** The device I was adding performs an association request.
5979 2020-11-14 16:35:26.648403 00:15:8d:00:04:7b:83:69 â~F~R 0xd596 IEEE 802.15.4 21 Association Request, RFD
5980 2020-11-14 16:35:26.649119 â~F~R IEEE 802.15.4 5 Ack
5981 2020-11-14 16:35:27.097013 0xd596 â~F~R Broadcast ZigBee 53 Link Status
****** One of these RF packets (or the next) result in the gateway starting a new statemachine
[2020-11-14 17:35:27.134553] [Z_STACK/HNDL] INFO : zstackpb Sending TC Device Ind: nwkAddr:0x3F7C, extAddr:0x00158D00047B8369, parentAddr:0xD596
[2020-11-14 17:35:27.135175] [NWK_MGR/HNDL] MISC1 : Processing ZDO TC Device Ind: 00158D00047B8369
[2020-11-14 17:35:27.135184] [NWK_MGR/HNDL] INFO : NwkMgr AddDevice State Machine Started on 0x00158d00047b8369
[2020-11-14 17:35:27.135191] [NWK_MGR/HNDL] INFO : nwkAddr 3F7C, parent D596
[2020-11-14 17:35:27.135199] [NWK_MGR/HNDL] INFO : AddDevice: No state machines, extending list to 16
5982 2020-11-14 16:35:27.141273 00:15:8d:00:04:7b:83:69 â~F~R 0xd596 IEEE 802.15.4 18 Data Request
5983 2020-11-14 16:35:27.141755 â~F~R IEEE 802.15.4 5 Ack
****** The router responds first (the gateway's MAC has LSBs 0x8277)
5984 2020-11-14 16:35:27.144715 00:12:4b:00:01:dd:7a:d7 â~F~R 00:15:8d:00:04:7b:83:69 IEEE 802.15.4 27 Association Response, PAN: 0xeb67 Addr: 0x3f7c
6000 2020-11-14 16:35:27.849043 0x0000 â~F~R 0xd596 ZigBee 102 Transport Key
6001 2020-11-14 16:35:27.849169 â~F~R IEEE 802.15.4 5 Ack
6002 2020-11-14 16:35:27.963248 0x3f7c â~F~R 0xd596 IEEE 802.15.4 12 Data Request
6003 2020-11-14 16:35:27.963728 â~F~R IEEE 802.15.4 5 Ack
6004 2020-11-14 16:35:27.971736 0xd596 â~F~R 0x3f7c ZigBee 73 Transport Key
6005 2020-11-14 16:35:27.972234 â~F~R IEEE 802.15.4 5 Ack
6006 2020-11-14 16:35:28.038986 0x3f7c â~F~R Broadcast ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69
6007 2020-11-14 16:35:28.039482 â~F~R IEEE 802.15.4 5 Ack
****** The device sends a Report to the coordinator
6011 2020-11-14 16:35:28.084210 0x3f7c â~F~R 0x0000 ZigBee HA 68 ZCL: Report Attributes, Seq: 0
6012 2020-11-14 16:35:28.084335 â~F~R IEEE 802.15.4 5 Ack
****** There's likely an offset of about 0.6 to 1 second with between the sniffer and the PC's time:
****** The gateway requests the IEEE address for 3F7C
[2020-11-14 17:35:27.419,690] [GATEWAY/HNDL] PKT_HEX: [ NWK_MGR<<GATEWAY ] [SREQ] 05:00:39:00:08:00:10:FC:7E
[2020-11-14 17:35:27.419,702] [GATEWAY/HNDL] PKTTYPE: [ NWK_MGR<<GATEWAY ] SrvrGetIeeeAddressReq
[2020-11-14 17:35:27.419,713] [GATEWAY/HNDL] PKTBODY: cmdId = SRVR_GET_IEEE_ADDRESS_REQ
[2020-11-14 17:35:27.419,722] [GATEWAY/HNDL] PKTBODY: shortAddress = 0x00003F7C (16252)
****** And gets back 0, whiile the device has announced itself BEFORE sending the attributes!
[2020-11-14 17:35:27.419834] [NWK_MGR/LSTN] MISC1 :
SRVR_GET_IEEE_ADDRESS_REQ: shortAddr: 3F7C
[2020-11-14 17:35:27.419916] [NWK_MGR/LSTN] PKT_HEX: [ NWK_MGR>>GATEWAY ] [ucst] 0D:00:79:01:08:01:10:01:19:00:00:00:00:00:00:00:00
[2020-11-14 17:35:27.419953] [NWK_MGR/LSTN] PKTTYPE: [ NWK_MGR>>GATEWAY ] SrvrGetIeeeAddressCnf
[2020-11-14 17:35:27.419977] [NWK_MGR/LSTN] PKTBODY: cmdId = SRVR_GET_IEEE_ADDRESS_CNF
[2020-11-14 17:35:27.419990] [NWK_MGR/LSTN] PKTBODY: status = STATUS_FAILURE
[2020-11-14 17:35:27.420000] [NWK_MGR/LSTN] PKTBODY: ieeeAddress = 00:00:00:00:00:00:00:00
[2020-11-14 17:35:27.420,277] [GATEWAY/HNDL] MISC1 : Processing Attribute Report Indication
[2020-11-14 17:35:27.420,336] [GATEWAY/HNDL] PKT_HEX: [ GATEWAY>>SMPLAPP] [bcst] 35:00:53:1A:08:1A:10:00:1A:0F:08:00:11:00:00:00:00:00:00:00:00:28:01:30:01:20:00:2A:13:08:05:10:42:1A:0D:0C:6C:75:6D:69:2E:77:65:61:74:68:65:72:2A:07:08:01:10:20:1A:01:05
[2020-11-14 17:35:27.420,354] [GATEWAY/HNDL] PKTTYPE: [ GATEWAY>>SMPLAPP] GwAttributeReportingInd
[2020-11-14 17:35:27.420,369] [GATEWAY/HNDL] PKTBODY: cmdId = GW_ATTRIBUTE_REPORTING_IND
[2020-11-14 17:35:27.420,378] [GATEWAY/HNDL] PKTBODY: status = STATUS_SUCCESS
[2020-11-14 17:35:27.420,392] [GATEWAY/HNDL] PKTBODY: srcAddress :
[2020-11-14 17:35:27.420,408] [GATEWAY/HNDL] PKTBODY: addressType = UNICAST
****** The IEEE adress reported for this data is 00.
[2020-11-14 17:35:27.420,422] [GATEWAY/HNDL] PKTBODY: ieeeAddr = 00:00:00:00:00:00:00:00
[2020-11-14 17:35:27.420,437] [GATEWAY/HNDL] PKTBODY: endpointId = 0x00000001 (1)
[2020-11-14 17:35:27.420,461] [GATEWAY/HNDL] PKTBODY: gwendpointid = 0x00000001 (1)
[2020-11-14 17:35:27.420,474] [GATEWAY/HNDL] PKTBODY: clusterId = 0x00000000 (0)
[2020-11-14 17:35:27.420,483] [GATEWAY/HNDL] PKTBODY: attributeRecordList :
[2020-11-14 17:35:27.420,491] [GATEWAY/HNDL] PKTBODY: [000] :
[2020-11-14 17:35:27.420,499] [GATEWAY/HNDL] PKTBODY: attributeId = 0x00000005 (5)
[2020-11-14 17:35:27.420,508] [GATEWAY/HNDL] PKTBODY: attributeType = <NOT_FOUND>
[2020-11-14 17:35:27.420,524] [GATEWAY/HNDL] PKTBODY: attributeValue (hex string) = 0C:6C:75:6D:69:2E:77:65:61:74:68:65:72
[2020-11-14 17:35:27.420,532] [GATEWAY/HNDL] PKTBODY: [001] :
[2020-11-14 17:35:27.420,540] [GATEWAY/HNDL] PKTBODY: attributeId = 0x00000001 (1)
[2020-11-14 17:35:27.420,555] [GATEWAY/HNDL] PKTBODY: attributeType = ZCL_DATATYPE_UINT8
[2020-11-14 17:35:27.420,565] [GATEWAY/HNDL] PKTBODY: attributeValue (hex string) = 05

6026 2020-11-14 16:35:31.314915 0x0000 â~F~R 0xd596 ZigBee ZDP 50 Extended Address Request, Nwk Addr: 0xd596
6027 2020-11-14 16:35:31.315365 â~F~R IEEE 802.15.4 5 Ack
6028 2020-11-14 16:35:31.332029 0xd596 â~F~R 0x0000 ZigBee 47 Route Record, Dst: 0x0000
6029 2020-11-14 16:35:31.332505 â~F~R IEEE 802.15.4 5 Ack
6030 2020-11-14 16:35:31.339265 0xd596 â~F~R 0x0000 ZigBee ZDP 57 Extended Address Response, Status: Success, Nwk Addr: 0xd596 = TexasIns_00:01:dd:7a:d7
6031 2020-11-14 16:35:31.339329 â~F~R IEEE 802.15.4 5 Ack

The setup for the debug above is:
- NPI server running on the embedded platform with AM335x and CC2530;
- All other servers running on a Ubuntu 16.04 VM, "manually started";
All servers, except the NWKMGR, built for x86 using the provided scripts;
The NWK is built under Qt, without Qt functionnality, to enable easier debugging.

Messages like:

[2020-11-14 17:35:27.135212] [NWK_MGR/HNDL] DEBUG : Lock PSTATE 0 (zNwkSrv_AD_GetStateMachineAndLock)
[2020-11-14 17:35:27.135221] [NWK_MGR/HNDL] DEBUG : Unlock PSTATE 0 (zNwkSrv_AddDevice)

correspond to the locking and unlocking of a state. Lock/Unlocks in the timer loop on unexpired states are not shown.
Usually the function that locks the machine is called from zNwkSrv_AD_GetStateMachineAndLock, and the unlock shows the function that performed the unlock (and that normally also requested the lock).
So the lock above corresponds to the zNwkSrv_AddDevice requesting a statemachine for new device management.

The zip file holds several logs as usual.

DevAnnouncementNotPropagated.zip

  • 0
    Genius 3145 points

    I added information about the machine state's value and this is logged as:

    [2020-11-15 01:37:02.403575] [NWK_MGR/HNDL] INFO   : PSTATE F7A00518 -> WAITING
[2020-11-15 01:37:09.207225] [NWK_MGR/MAIN] INFO   : AddDevice: Retrying state 1, remaining tries: 4
[2020-11-15 01:37:14.422916] [NWK_MGR/MAIN] INFO   : PSTATE F7A00518 -> GET_PARENT
[2020-11-15 01:37:22.361404] [NWK_MGR/MAIN] MISC1  : NwkMgr sendZdoIeeeAddrReq: ieeeaddr D596
[2020-11-15 01:37:40.573281] [NWK_MGR/MAIN] INFO   : AddDevice: Retrying state 2, remaining tries: 0
[2020-11-15 01:37:40.573288] [NWK_MGR/MAIN] INFO   : AddDevice: Failed to get response from target node, state 2
[2020-11-15 01:37:40.573293] [NWK_MGR/MAIN] INFO   :  device 00158D00047B8369
[2020-11-15 01:37:40.573299] [NWK_MGR/MAIN] INFO   : 
[2020-11-15 01:37:40.573303] [NWK_MGR/MAIN] DEBUG  : - AddDevice Failed 1 on 00158D00047B8369
[2020-11-15 01:37:40.573308] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachine: Entered pState=0xF7A00518
[2020-11-15 01:37:40.573313] [NWK_MGR/MAIN] INFO   : PSTATE F7A00518 -> TO_DELETE
[2020-11-15 01:37:40.573317] [NWK_MGR/MAIN] DEBUG  : Unlock PSTATE 0 (zNwkSrv_UpdateTimers)
[2020-11-15 01:37:40.573322] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachineReal: Entered pState=0xF7A00518
[2020-11-15 01:37:40.573327] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachine: State machine freed
[2020-11-15 01:37:40.573331] [NWK_MGR/MAIN] INFO   : nwkMgrDb_FreeDeviceInfo: Entered pDeviceInfo=0xf7a00800
[2020-11-15 01:37:40.573336] [NWK_MGR/MAIN] INFO   : nwkMgrDb_FreeDeviceInfoSubstructures: Entered pDeviceInfo=0xf7a00800
[2020-11-15 01:37:40.573340] [NWK_MGR/MAIN] INFO   : nwkMgrDb_FreeDeviceInfoSubstructures: Exit
[2020-11-15 01:37:40.573345] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachine: Exit

    zNwkSrv_AD_ProcessDeviceAnnounce is never entered in this case apparently.

  • 0 in reply to Mario DW
    Genius 3145 points

    As I had an issue with unlocking the pState related mutex in the ...Reuse... function, I fixed that and made new trials.

    Unfortunately that did not seem related to the core issue, so I believe that the initial analysis is still ok.

    Anyway, I join new logs to this thread and an analysis that may be complementary to the above.

    The logs also show that other end devices are making device announcements without triggering any manual association - they have been associated with the ZNP in past sessisons.  There are also report_attributes, zone enroll related packets, etc.  Some make their way to the application, but their reported IEEE Address is 0.

    I would think that all devices either have to end up in the Device List and that devices that for some reason do not make it in the device list should receive a "Leave" command.

    So this log holds several unexpected behavoirs.  My main focus for now is getting a device to join the gateway.
    I removed the power from the TI SampleLights at some point, supposing that their routerr function might change the behavior.  While that may be true, I did not get better results.

    [2020-11-15 15:40:14.010832] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR<<<<<<<<<<<SMPLAPP] [read] 06:00:12:0C:08:0C:10:01:18:3C
[2020-11-15 15:40:14.010847] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR<<<<<<<<<<<SMPLAPP] NwkSetPermitJoinReq
[2020-11-15 15:40:14.010859] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_SET_PERMIT_JOIN_REQ
[2020-11-15 15:40:14.010869] [NWK_MGR/LSTN] PKTBODY:                                                          permitJoin = PERMIT_NETWORK
[2020-11-15 15:40:14.010878] [NWK_MGR/LSTN] PKTBODY:                                                          permitJoinTime = 0x0000003C (60)

 5054 2020-11-15 15:40:25.268608 70:b3:d5:b1:30:01:01:1e ▒~F~R 0xd596       IEEE 802.15.4 21 Association Request, RFD
 5055 2020-11-15 15:40:25.269051              ▒~F~R              IEEE 802.15.4 5 Ack
 5056 2020-11-15 15:40:25.761917 70:b3:d5:b1:30:01:01:1e ▒~F~R 0xd596       IEEE 802.15.4 18 Data Request
 5057 2020-11-15 15:40:25.762413              ▒~F~R              IEEE 802.15.4 5 Ack
 5058 2020-11-15 15:40:25.764073 00:12:4b:00:01:dd:7a:d7 ▒~F~R 70:b3:d5:b1:30:01:01:1e IEEE 802.15.4 27 Association Response, PAN: 0xeb67 Addr: 0xfc33
 5059 2020-11-15 15:40:25.765824              ▒~F~R              IEEE 802.15.4 5 Ack

[2020-11-15 15:40:27.726929] [NWK_MGR/HNDL] MISC1  : Processing ZDO TC Device Ind: 70B3D5B13001011E
[2020-11-15 15:40:27.726936] [NWK_MGR/HNDL] INFO   : NwkMgr AddDevice State Machine Started on 0x70b3d5b13001011e
[2020-11-15 15:40:27.726943] [NWK_MGR/HNDL] INFO   :   nwkAddr FC33, parent D596
[2020-11-15 15:40:27.726949] [NWK_MGR/HNDL] INFO   : AddDevice: No state machines, extending list to 16
[2020-11-15 15:40:27.727101] [NWK_MGR/HNDL] DEBUG  : Lock PSTATE 0 (zNwkSrv_AD_GetStateMachineAndLock)
[2020-11-15 15:40:27.727111] [NWK_MGR/HNDL] INFO   : PSTATE F2603C00 -> WAITING
[2020-11-15 15:40:27.727118] [NWK_MGR/HNDL] DEBUG  : Unlock PSTATE 0 (zNwkSrv_AddDevice)

 5106 2020-11-15 15:40:28.058601 00:15:8d:00:04:7b:83:69 ▒~F~R 0xd596       IEEE 802.15.4 18 Data Request
 5107 2020-11-15 15:40:28.059097              ▒~F~R              IEEE 802.15.4 5 Ack
 5108 2020-11-15 15:40:28.062048 00:12:4b:00:01:dd:7a:d7 ▒~F~R 00:15:8d:00:04:7b:83:69 IEEE 802.15.4 27 Association Response, PAN: 0xeb67 Addr: 0x5c66
 5109 2020-11-15 15:40:28.062470              ▒~F~R              IEEE 802.15.4 5 Ack
 5110 2020-11-15 15:40:28.090360       0xfc33 ▒~F~R 0xd596       IEEE 802.15.4 12 Data Request
 5111 2020-11-15 15:40:28.090844              ▒~F~R              IEEE 802.15.4 5 Ack
 5112 2020-11-15 15:40:28.168856       0xfc33 ▒~F~R Broadcast    ZigBee ZDP 65 Device Announcement, Nwk Addr: IeeeRegi_b1:30:01:01:1e
 5113 2020-11-15 15:40:28.195624       0xd596 ▒~F~R 0x0000       ZigBee 47 Route Record, Dst: 0x0000
 5114 2020-11-15 15:40:28.196153              ▒~F~R              IEEE 802.15.4 5 Ack
 5115 2020-11-15 15:40:28.200242       0xd596 ▒~F~R 0x0000       ZigBee 51 Update Device
 5116 2020-11-15 15:40:28.200576              ▒~F~R              IEEE 802.15.4 5 Ack
 5117 2020-11-15 15:40:28.207102       0xd596 ▒~F~R 0x0000       ZigBee 47 Route Record, Dst: 0x0000
 5118 2020-11-15 15:40:28.207594              ▒~F~R              IEEE 802.15.4 5 Ack
 5119 2020-11-15 15:40:28.211984       0xd596 ▒~F~R 0x0000       ZigBee 68 Update Device
...
 5141 2020-11-15 15:40:29.551200       0x5c66 ▒~F~R Broadcast    ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69
 5142 2020-11-15 15:40:29.551329              ▒~F~R              IEEE 802.15.4 5 Ack
 5143 2020-11-15 15:40:29.564305       0x5c66 ▒~F~R Broadcast    ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69
 5144 2020-11-15 15:40:29.597433       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5145 2020-11-15 15:40:29.597904              ▒~F~R              IEEE 802.15.4 5 Ack
 5146 2020-11-15 15:40:29.613188       0x5c66 ▒~F~R 0x0000       ZigBee 49 Route Record, Dst: 0x0000
 5147 2020-11-15 15:40:29.613714              ▒~F~R              IEEE 802.15.4 5 Ack
 5148 2020-11-15 15:40:29.617936       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5149 2020-11-15 15:40:29.623661       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5150 2020-11-15 15:40:29.629185       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5151 2020-11-15 15:40:29.633430       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5152 2020-11-15 15:40:29.645319       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5153 2020-11-15 15:40:29.650917       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5154 2020-11-15 15:40:29.657679       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5155 2020-11-15 15:40:29.663193       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5156 2020-11-15 15:40:30.026294       0x5c66 ▒~F~R Broadcast    ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69
 5157 2020-11-15 15:40:30.039425       0x5c66 ▒~F~R Broadcast    ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69


**** The state machine for Adding the device is created,
****   the parent is already known, but the state later is "GET_PARENT" ...
****   Note: the lcok on PSTATE 0 is only for checking the machine,
****     00158D00047B8369 is handled in PSTATE 1 (states are reported by their index, not their pointer)
[2020-11-15 15:40:30.030978] [NWK_MGR/HNDL] MISC1  : Processing ZDO TC Device Ind: 00158D00047B8369
[2020-11-15 15:40:30.030996] [NWK_MGR/HNDL] INFO   : NwkMgr AddDevice State Machine Started on 0x00158d00047b8369
[2020-11-15 15:40:30.031012] [NWK_MGR/HNDL] INFO   :   nwkAddr 5C66, parent D596
[2020-11-15 15:40:30.031033] [NWK_MGR/HNDL] DEBUG  : Lock PSTATE 0 (zNwkSrv_AD_GetStateMachineAndLock)
[2020-11-15 15:40:30.031049] [NWK_MGR/HNDL] DEBUG  : Unlock PSTATE 0 (zNwkSrv_AD_GetStateMachineAndLock)
[2020-11-15 15:40:30.031065] [NWK_MGR/HNDL] DEBUG  : Lock PSTATE 1 (zNwkSrv_AD_GetStateMachineAndLock)
[2020-11-15 15:40:30.031080] [NWK_MGR/HNDL] INFO   : AddDevice: Initiated new state machine
[2020-11-15 15:40:30.031097] [NWK_MGR/HNDL] INFO   : PSTATE F2603C2E -> WAITING
[2020-11-15 15:40:30.031113] [NWK_MGR/HNDL] DEBUG  : Unlock PSTATE 1 (zNwkSrv_AddDevice)



**** Update timer expired.
****  In the subroutin the PSTATE IDX is not know, so the pointer is shown there,
****  but from the lock message we know that this is for Jennic_00:04:7b:83:69
[2020-11-15 15:40:31.008291] [NWK_MGR/MAIN] DEBUG  : Lock PSTATE 0 (zNwkSrv_UpdateTimers)
[2020-11-15 15:40:31.008331] [NWK_MGR/MAIN] INFO   : AddDevice: Retrying state 1, remaining tries: 4
[2020-11-15 15:40:31.008341] [NWK_MGR/MAIN] INFO   : PSTATE F2603C00 -> GET_PARENT
[2020-11-15 15:40:31.008348] [NWK_MGR/MAIN] MISC1  : NwkMgr sendZdoIeeeAddrReq: ieeeaddr D596
[2020-11-15 15:40:31.008371] [NWK_MGR/MAIN] INFO   : preparing to send 10 bytes, subSys 0x11, cmdId 0x31 (ZDO_IEEE_ADDR_REQ), pData:
[2020-11-15 15:40:31.008380] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[2020-11-15 15:40:31.008403] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 0A:00:31:31:08:31:10:96:AB:03:18:00:20:00
[2020-11-15 15:40:31.008415] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] zdoIeeeAddrReq
[2020-11-15 15:40:31.008430] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[2020-11-15 15:40:31.008439] [NWK_MGR/MAIN] PKTBODY:                                                          nwkAddr = 0x0000D596 (54678)
[2020-11-15 15:40:31.008448] [NWK_MGR/MAIN] PKTBODY:                                                          type = SINGLE_DEVICE
[2020-11-15 15:40:31.008456] [NWK_MGR/MAIN] PKTBODY:                                                          startIndex = 0x00000000 (0)

**** I think this corresponds to.
 5175 2020-11-15 15:40:32.943722       0x0000 ▒~F~R 0xd596       ZigBee ZDP 50 Extended Address Request, Nwk Addr: 0xd596
 5176 2020-11-15 15:40:32.944204              ▒~F~R              IEEE 802.15.4 5 Ack
 5177 2020-11-15 15:40:33.194695       0xd596 ▒~F~R 0x0000       ZigBee ZDP 57 Extended Address Response, Status: Success, Nwk Addr: 0xd596 = TexasIns_00:01:dd:7a:d7
 5178 2020-11-15 15:40:33.194822              ▒~F~R              IEEE 802.15.4 5 Ack
**** By examining the detail of the request it looks as we are gettint information about the router, not about the end device?
Frame 5174: 5 bytes on wire (40 bits), 5 bytes captured (40 bits)
...
ZigBee Device Profile, Extended Address Request, Nwk Addr: 0xd596
    Sequence Number: 19
    Nwk Addr of Interest: 0xd596
    Request Type: Single Device Response (0)
    Index: 0

    MissinginDeviceList2.zip

    Combination of all logs, including sniffer and serial log - some serial data lines were manually moved to put them close to the ZSTACK transaaction they seem to correspond to.

    combined.zip

  • 0 in reply to Mario DW
    TI__Guru**** 202206 points

    Hi le_top,

    Have you previously had any devices (0x3F7C) join through a router and thus have a parent (0xD596) other than the ZNP/ZC Trust Center (0x0000)?  The local device list only consists of devices directly associated and not the ZED children of other parents.  Messages intended for the child must be sent through the parent as maintained by the routing table.  If a ZED  does not check in often enough with the ZR parent then a message transaction may expire before reaching its end destination.

    Regards,
    Ryan

  • 0 in reply to Ryan Brown1
    Genius 3145 points

    Hello Ryan

    The coordinator and the devices have history with regards to association, the 0xd596 is a router.

    The grep on the logs gives an idea of how the number of devices evolved.

    zigbeegw.20201113183908.log:[2020-11-13 19:06:37.642443] [NWK_MGR/LSTN] MISC1  :  found 2 Device Records
zigbeegw.20201114020157.log:[2020-11-14 10:53:08.681545] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114020157.log:[2020-11-14 10:53:08.787659] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114020157.log:[2020-11-14 10:53:15.525540] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114020744.log:[2020-11-14 02:08:21.415259] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114020744.log:[2020-11-14 02:08:21.469000] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114133507.log:[2020-11-14 13:35:43.108627] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114133507.log:[2020-11-14 13:35:45.177200] [NWK_MGR/LSTN] MISC1  :  found 3 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:38:41.254952] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:38:41.374379] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:38:41.403349] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:47:12.319907] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:47:12.345592] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:49:27.609282] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201114133807.log:[2020-11-14 13:49:27.645938] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201115010115.log:[2020-11-15 13:39:50.948563] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201115010115.log:[2020-11-15 13:39:50.994307] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201115010115.log:[2020-11-15 13:40:42.891365] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records
zigbeegw.20201115010115.log:[2020-11-15 13:40:42.920338] [NWK_MGR/LSTN] MISC1  :  found 0 Device Records

    I am not sure at this time if I did a hard reset, but zigbeegw.20201114133807.log starts with 0 Device Records and the serial report has the following reset indication:

    [2020-11-15 14:39:30.779407] > [SYS/AREQ] **RESET_IND**         (SYS:1/TYPE:40/CMD:80) ( 11)::fe 06 41 80 01 02 02 02 07 02 c1

    The Local Device List (CSV) file is not supposed to contain all the devices from what I understand in your reply.

    How can the application know which devices are in the network?

    I've also tries association without the TI SampleLights active, I'll make a session for that.

    However in the above tests (two different ones), I repeatedly had the 00:15:8d:00:04:7b:83:69 device associating with the network.  The Device List in the UI of the sample application remained empty.  I did not manually start the joining of the 70:b3:d5:b1:30:01:01:1e , but the NWKMGR is notified about this device and starts a statemachine for it.  The router responds to that ZED as well 

    How can the application know what router are in the network.

    The SampleLights should still show up as Lights in the Local Device List, shouldn't they?

    The are communciations from end devices directly to the coordinator, so the router should nto interfere with this, should it?  I suppose that NwkGetLocalDeviceInfoReq gets the local device list and NwkGetDeviceListReq should get the full one.

     5154 2020-11-15 15:40:29.657679       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5155 2020-11-15 15:40:29.663193       0x5c66 ▒~F~R 0x0000       ZigBee HA 68 ZCL: Report Attributes, Seq: 0
 5156 2020-11-15 15:40:30.026294       0x5c66 ▒~F~R Broadcast    ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69
 5157 2020-11-15 15:40:30.039425       0x5c66 ▒~F~R Broadcast    ZigBee ZDP 57 Device Announcement, Nwk Addr: Jennic_00:04:7b:83:69

    I've developed a script to parse the serial logs and tag the communications (does not work on long packets yet, such as some OSAL_NV_READs).   I generated combined logs for the first test case above and the second one.  Hopefully they help in the analysis:

    DevAnnmtNotPropagated_combined.zipcombined2.zip

    IMHO the gateway/ZNP should have at least shown association of the device for which I manually started the association, that makes Device Announcements, and reports attributes.

    IMHO it should also either accept devices that are still joined or have them Leave (their Link Key is still valid for the network as the sniffer is reporting only one key, provided in lastkeys.log in the first zip files).

    What happens in practice is that from the application's point of view the network does not have any device, and I can't really see how something usefull can be announced to the end user from what the gateway is communicating to the application.  The end user is just going to conclude that the product is not working.

    I wonder if the state machine that is started to handle the new devices is correct.  From what I see in the sniffer log, the device is associated, but that is not so for the gateway.  Why is the GET_PARENT step failing?  Etc ...

  • 0 in reply to Mario DW
    TI__Guru**** 202206 points

    Hi le_top,

    I apologize for the confusion from my previous response, I forgot that we are talking about the NWK Manager device list and not the local association list.  I am reminded of an E2E thread we had about a month ago.  Did you move zNwkSrv_AddDevice from processZdoTcDeviceInd to processZdoDeviceAnnounce for Z-Stack HA backwards compatibility?  If nwkSrvAddDeviceTcInfoCB is not ported properly then it could explain the fail state of NS_ADS_NO_RSP (1) which only occurs in zNwkSrv_TimerCallback as called by zNwkSrv_AD_ProcessDeviceAnnounce.  You should add a nwkSrvAddDeviceDevAnnceCB or something of that sort to not mix state machines.

    Regards,
    Ryan

  • 0 in reply to Ryan Brown1
    Genius 3145 points

    Hello Ryan

    Thank you for this feedback.

    The Question/Proposal that you refer to is related to a ZED being developed using CC2530 and ZStack3.0.2.
    So the ZED is a Zigbee 3.0, TI Stack based device, which is one of the reasons to condclud ethat the ZED did not need a change as far as I understood as I indicate in my final answer.  But possibly that issue over there (get 0 for the ZED IEEE Address) is related to this one.

    Also, the ZED under development s not part of the current test.  I've been focussing on the gateway, and the prototype is not in function (empty batteries).

    So, the reason(s) are elsewhere.

    Kind regards
    Mario

  • 0 in reply to Mario DW
    Genius 3145 points

    In ran the serail log through my updated decoder and most of the SRSP codes are "Success".  I guess that the following failures are not critical and could be avoided - such as the first "DELETE" and the "SETèTX_POWER" Invalid Parameter.

    2020-11-15 16:16:42.519971] < [AF/SREQ] **DELETE**     (SYS:4/TYPE:20/CMD:04) (  6)::fe 01 24 04 00 21
[2020-11-15 16:16:42.527509] > [AF/SRSP] **DELETE**     ZInvalidParameter       (SYS:4/TYPE:60/CMD:04) (  6)::fe 01 64 04 02 63
[2020-11-15 16:16:47.491168] > [ZDO/AREQ] **SRC_RTG_IND**       (SYS:5/TYPE:40/CMD:C4) ( 10)::fe 05 45 c4 5f 50 01 96 d5 c9
[2020-11-15 16:16:47.503428] > [AF/AREQ] **INCOMING_MSG**       (SYS:4/TYPE:40/CMD:81) ( 33)::fe 1c 44 81 00 00 02 04 5f 50 01 01 00 6b 00 92 f9 16 00 00 08 18 17 0a 00 00 29 4e 0b 96 d5 1c f8
[2020-11-15 16:16:47.507841] > [ZDO/AREQ] **SRC_RTG_IND**       (SYS:5/TYPE:40/CMD:C4) ( 10)::fe 05 45 c4 5f 50 01 96 d5 c9
[2020-11-15 16:16:47.519526] > [ZDO/AREQ] **SRC_RTG_IND**       (SYS:5/TYPE:40/CMD:C4) ( 10)::fe 05 45 c4 5f 50 01 96 d5 c9
[2020-11-15 16:16:47.531078] > [AF/AREQ] **INCOMING_MSG**       (SYS:4/TYPE:40/CMD:81) ( 33)::fe 1c 44 81 00 00 05 04 5f 50 01 01 00 6b 00 c1 f9 16 00 00 08 18 18 0a 00 00 21 bb 12 96 d5 1c 47
[2020-11-15 16:16:47.540378] > [AF/AREQ] **INCOMING_MSG**       (SYS:4/TYPE:40/CMD:81) ( 42)::fe 25 44 81 00 00 03 04 5f 50 01 01 00 6b 00 da f9 16 00 00 11 18 19 0a 00 00 29 e6 03 14 00 28 ff 10 00 29 fc 26 96 d5 1c 1f
[2020-11-15 16:16:49.045164] < [ZDO/SREQ] **EXT_NWK_INFO**      (SYS:5/TYPE:20/CMD:50) (  5)::fe 00 25 50 75
[2020-11-15 16:16:49.054482] > [ZDO/SRSP] **EXT_NWK_INFO**      ZSuccess        (SYS:5/TYPE:60/CMD:50) ( 29)::fe 18 65 50 00 00 09 67 eb 00 00 77 82 22 10 00 4b 12 00 00 00 00 00 00 00 00 00 0b 3d
[2020-11-15 16:16:49.059029] < [SYS/SREQ] **SET_TX_POWER**      (SYS:1/TYPE:20/CMD:14) (  6)::fe 01 21 14 7f 4b
[2020-11-15 16:16:49.067093] > [SYS/SRSP] **SET_TX_POWER**      INVALID PARAM   (SYS:1/TYPE:60/CMD:14) (  6)::fe 01 61 14 03 77
[2020-11-15 16:16:49.515568] < [AF/SREQ] **DELETE**     (SYS:4/TYPE:20/CMD:04) (  6)::fe 01 24 04 01 20
[2020-11-15 16:16:49.523765] > [AF/SRSP] **DELETE**     ZSuccess        (SYS:4/TYPE:60/CMD:04) (  6)::fe 01 64 04 00 61
[2020-11-15 16:16:49.529134] < [AF/SREQ] **DELETE**     (SYS:4/TYPE:20/CMD:04) (  6)::fe 01 24 04 f2 d3
[2020-11-15 16:16:49.538416] > [AF/SRSP] **DELETE**     ZSuccess        (SYS:4/TYPE:60/CMD:04) (  6)::fe 01 64 04 00 61

    Bhat that's note the issue issue I try to fix here.

  • 0 in reply to Mario DW
    TI__Guru**** 202206 points

    SET_TX_POWER fails because it uses an invalid TX Power value (in dBm) of 0x7F, Cmd0 = 0x24 with Cmd1 = 04 is AF_DELETE which deletes the local endpoint specified and frees the memory as such.

    Regards,
    Ryan

  • 0 in reply to Ryan Brown1
    Genius 3145 points

    The 'nwkmgr_config.ini' file says:

    ; tx power per channel, in dBm (from channel 11 to channel 26). Valid range is 127 to -128. The actual power will be the nearest supported power.
CHANNEL_POWER_LIST = {127, 127, 127, 127, 127, 127, 127, 127, 127, 127, 127, 127, 127, 127, 127, 127 }

    So instead, I need to find the valid value for the C2530.

    With regards to the EP, trying to delete something that is not there is not an issue, but could be improved in the gateway.

  • 0 in reply to Mario DW
    Genius 3145 points

    In fact SET_TX_POWER does not fail, it does not return an error value.

  • 0 in reply to Mario DW
    TI__Guru**** 202206 points

    The file's comments are deprecated and inconsistent with the MT API and MT_SysSetTxPower ZNP function.   But as mentioned before, neither this nor the EP action is relevant to the device list behavior.

    Regards,
    Ryan

  • 0 in reply to Ryan Brown1
    Genius 3145 points

    Acutally that comment is still consitent for the CC2530, the actual dBm level set is returned, "3" is not an error.

    The main issue hiere is the Device List indeed and I hope that this can be fixed in the code.

  • 0 in reply to Mario DW
    Genius 3145 points

    this is surely gateway related so I am closing this question.

    I am investigating these issues and fixing the gateway as I go forward.

    If I see anything wrong with ZNP, I'll open a new issue.