CC2531EM-IOT-HOME-GATEWAY-RD: Zigbee_3_0_Linux_Gateway_1_0_1 Attaching procedure Errors

Alexander Argollo

Part Number: CC2531EM-IOT-HOME-GATEWAY-RD
Other Parts Discussed in Thread: Z-STACK, CC2531, CC2530

Hi Guys,

A few weeks I´m started to work with Zigbee_3_0_Linux_Gateway_1_0_1 to improve my IoT solutions together TI Gateway!

At the first moment I had some problems and I have supported by Mr. Yk and Ryan Brow1, according this E2E thread, after the first test everything works well with first device attached (on/off device)

I followed with other tests, and tried to include other commercial devices, and I have observed that I can´t attaching those devices int the Zigbee network formed during the first tests, as I attached above in the 1st E2E post. To make additional test I made Hard System Reset on web app and tried to add the 1st device that I got success to attaching before, Would you see bellow the 2st test details.

I started to add the 1st device again, in this 2st test, and I didn´t have success, even I restarting several times nothing has changed in the attaching procedure. Its happens that the attaching phase finish on ZDO/ZDP stage, according you can see on wireshark over the air log by DeviceAnnce message. I saw those erros on Gateway log

AddDevice: Failed to get response from target node, state 2
[22:00:48.855,496] [NWK_MGR/MAIN] INFO : device 00124B002127C9E7

I have observed in the 1st wireshark log, that I got success in the first E2E post and the 2st wireshark log that i have observing abnormal behavior, including the Gateway server logs with full verbose "-v 0xFFFFFFFF" . Additional information, I made the 3rd test and see the same behavior, but i Included the new log, the last file, to show the start up phase after reboot!

My Tests environments:

My On/Off device attributes:
ZB Device Type: Router
On/Off two circuits
ZDO/ZDP capInfo: 8E
TI Z-stack: Z-Stack Home 1.2
IEEE addr:00:12:4b:00:21:27:c9:e7

SimpleDescription Circ.1/Circ.2
ZCL Profile ID: ZCL_HA_PROFILE_ID (0x0104)
ZCL AppID: ZCL_HA_DEVICEID_ON_OFF_LIGHT (0x0100)
EP CIRC. 1 = 1
EP CIRC. 2 = 2

Linux Sensor Gateway:
Version: Zigbee_3_0_Linux_Gateway_1_0_1
Hardware: BeagleBoneBlack rev.c
OS: bone-debian-9.3-iot-armhf-2018-03-05-4gb.img
SoC: CC2531
CC2531 Firmware:CC2531ZNP_GW_ZNP_USB.hex
BDB_DEFAULT_TC_REQUIRE_KEY_EXCHANGE = 0 (defaults)

I have saw those erros on Gateway log, I think that it can explain better why the gateway is not finish the attaching procedure and I cant observed those messages Node Desc Request, Active Desc Request, Simple Desc Request and the respective device (on/off) on the device table list in the App. Somebody can help me to understanding how to fix it?

[22:00:39.844,223] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex
[22:00:39.847,386] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client
[22:00:39.848,625] [Z_STACK/LSTN] INFO : !Done
[22:00:39.864,845] [Z_STACK/READ] INFO : Received 13 bytes, subSys 0x45, cmdId 0x81
[22:00:39.865,001] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0x81
[22:00:39.865,040] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01288 (received 11 messages)...
[22:00:39.865,069] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01288)...
[22:00:39.865,166] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked
[22:00:39.865,213] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01288
[22:00:39.865,243] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[22:00:39.865,272] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6B01290
[22:00:39.865,303] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:81
[22:00:39.865,331] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01288)...
[22:00:39.865,358] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01288 (processed 11 messages)...
[22:00:39.865,388] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore
[22:00:48.855,279] [NWK_MGR/MAIN] INFO :
AddDevice: Retrying state 2, remaining tries: 0
[22:00:48.855,461] [NWK_MGR/MAIN] INFO :
AddDevice: Failed to get response from target node, state 2
[22:00:48.855,496] [NWK_MGR/MAIN] INFO : device 00124B002127C9E7
[22:00:48.855,529] [NWK_MGR/MAIN] INFO :
[22:00:48.855,622] [NWK_MGR/MAIN] DEBUG : - AddDevice Failed 1 on 00124B002127C9E7
[22:00:48.855,656] [NWK_MGR/MAIN] INFO : zNwkSrv_AD_FreeStateMachine: Entered pState=0xb6d00588
[22:00:48.855,685] [NWK_MGR/MAIN] INFO : zNwkSrv_AD_FreeStateMachine: State machine freed
[22:00:48.855,712] [NWK_MGR/MAIN] INFO : nwkMgrDb_FreeDeviceInfo: Entered pDeviceInfo=0xb6d00510
[22:00:48.855,739] [NWK_MGR/MAIN] INFO : nwkMgrDb_FreeDeviceInfoSubstructures: Entered pDeviceInfo=0xb6d00510
[22:00:48.855,766] [NWK_MGR/MAIN] INFO : nwkMgrDb_FreeDeviceInfoSubstructures: Exit
[22:00:48.855,796] [NWK_MGR/MAIN] INFO : zNwkSrv_AD_FreeStateMachine: Exit

App screen with the on/off device that I got success to attaching in the first E2E post (E2E thread)

Wireshark log 1st, that I got success to attaching the On/Off device.

Texas Gateway Attaching SUCESS_20210526.zip

2st test, with the same on/off device, but I saw several errors, as you can see in the wireshark and Gateway logs.

Texas Gateway Attaching error_20210529_sync with LOG.zip

Gateway error on attaching mode sync with wireshark log.txt
[21:58:24.890,883] [NWK_MGR/LSTN] PKT_HEX: [ NWK_MGR>>>>>>>>>>>>>>>>>>>>CON009] [ucst] 12:00:72:0B:08:0B:10:01:18:0D:20:E8:66:29:34:57:49:01:00:4B:12:00 [21:58:24.890,933] [NWK_MGR/LSTN] PKTTYPE: [ NWK_MGR>>>>>>>>>>>>>>>>>>>>CON009] NwkZigbeeNwkInfoCnf [21:58:24.890,981] [NWK_MGR/LSTN] PKTBODY: cmdId = NWK_ZIGBEE_NWK_INFO_CNF [21:58:24.891,021] [NWK_MGR/LSTN] PKTBODY: status = NWK_UP [21:58:24.891,057] [NWK_MGR/LSTN] PKTBODY: nwkChannel = 0x0000000D (13) [21:58:24.891,092] [NWK_MGR/LSTN] PKTBODY: panId = 0x00003368 (13160) [21:58:24.891,129] [NWK_MGR/LSTN] PKTBODY: extPanId = 00:12:4B:00:01:49:57:34 [21:58:24.891,319] [NWK_MGR/LSTN] INFO : ...sent 22 bytes to Client [21:58:24.891,378] [NWK_MGR/LSTN] INFO : !Done [21:58:24.894,906] [Z_STACK/LSTN] INFO : ...sent 52 bytes to Client [21:58:24.898,749] [Z_STACK/LSTN] INFO : !Done [22:00:10.136,806] [Z_STACK/LSTN] INFO : Receive message... [22:00:10.136,952] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:43 [22:00:10.137,014] [Z_STACK/LSTN] INFO : preparing to send 0 bytes, subSys 0x05, cmdId 0x50, pData: [22:00:10.137,049] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:10.137,099] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 00:25:50 [22:00:10.137,149] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 00:25:50 [22:00:10.137,346] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:10.137,397] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:10.137,426] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:10.144,543] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 00:25:50 [22:00:10.135,452] [NWK_MGR/LSTN] INFO : Receive message... [22:00:10.135,876] [NWK_MGR/LSTN] PKT_HEX: [ NWK_MGR<<<<<<<<<<<<<<<<<<<<CON009] [read] 07:00:12:0C:08:0C:10:02:18:B4:01 [22:00:10.135,953] [NWK_MGR/LSTN] PKTTYPE: [ NWK_MGR<<<<<<<<<<<<<<<<<<<<CON009] NwkSetPermitJoinReq [22:00:10.136,007] [NWK_MGR/LSTN] PKTBODY: cmdId = NWK_SET_PERMIT_JOIN_REQ [22:00:10.136,048] [NWK_MGR/LSTN] PKTBODY: permitJoin = PERMIT_ALL [22:00:10.136,084] [NWK_MGR/LSTN] PKTBODY: permitJoinTime = 0x000000B4 (180) [22:00:10.136,126] [NWK_MGR/LSTN] MISC1 : Processing Set Permit Join Request. [22:00:10.136,155] [NWK_MGR/LSTN] MISC1 : NwkMgr sendZdoMgmtPermitJoinReq: nwkaddr FFFC [22:00:10.136,194] [NWK_MGR/LSTN] INFO : preparing to send 11 bytes, subSys 0x11, cmdId 0x43, pData: [22:00:10.136,225] [NWK_MGR/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:10.136,293] [NWK_MGR/LSTN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 0B:00:31:43:08:43:10:FC:FF:03:18:B4:01:20:01 [22:00:10.136,336] [NWK_MGR/LSTN] PKTTYPE: [ Z_STACK<<NWK_MGR ] zdoMgmtPermitJoinReq [22:00:10.136,382] [NWK_MGR/LSTN] PKTBODY: cmdID = ZDO_MGMT_PERMIT_JOIN_REQ [22:00:10.136,423] [NWK_MGR/LSTN] PKTBODY: nwkAddr = 0x0000FFFC (65532) [22:00:10.136,458] [NWK_MGR/LSTN] PKTBODY: duration = 0x000000B4 (180) [22:00:10.136,491] [NWK_MGR/LSTN] PKTBODY: tcSignificance = 1 [22:00:10.149,543] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 18:65:50:00:00:09:68:33:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D [22:00:10.152,936] [Z_STACK/READ] INFO : Received 24 bytes, subSys 0x65, cmdId 0x50 [22:00:10.153,076] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:10.153,112] [Z_STACK/READ] INFO : Client Read: (len 27): [22:00:10.152,242] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 18:65:50:00:00:09:68:33:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D [22:00:10.157,808] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:10.157,960] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:36, len::5 [22:00:10.158,012] [Z_STACK/LSTN] INFO : preparing to send 5 bytes, subSys 0x05, cmdId 0x36, pData: [22:00:10.158,045] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:10.158,110] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 05:25:36:02:00:00:B4:01 [22:00:10.158,170] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 05:25:36:02:00:00:B4:01 [22:00:10.158,379] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:10.158,431] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:10.158,459] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:10.159,977] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 05:25:36:02:00:00:B4:01 [22:00:10.163,015] [NWK_MGR/LSTN] INFO : Waiting for synchronous response... [22:00:10.163,165] [NWK_MGR/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:10.163,201] [NWK_MGR/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:10.166,456] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:36:00 [22:00:10.168,319] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x36 [22:00:10.168,445] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:10.168,480] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:10.167,865] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:36:00 [22:00:10.172,704] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:10.172,868] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:36, len::5 [22:00:10.172,915] [Z_STACK/LSTN] INFO : preparing to send 5 bytes, subSys 0x05, cmdId 0x36, pData: [22:00:10.172,947] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:10.173,012] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 05:25:36:02:FC:FF:B4:01 [22:00:10.173,073] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 05:25:36:02:FC:FF:B4:01 [22:00:10.173,281] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:10.173,333] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:10.173,362] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:10.177,324] [Z_STACK/READ] INFO : Received 3 bytes, subSys 0x45, cmdId 0xB6 [22:00:10.177,448] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0xB6 [22:00:10.177,483] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B004C8 (received 4 messages)... [22:00:10.177,513] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B004C8)... [22:00:10.177,581] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:10.177,624] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B004C8 [22:00:10.177,652] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:10.177,678] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000B6, len:0x00000003, pData:0xB6B004D0 [22:00:10.177,710] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:b6 [22:00:10.177,738] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B004C8)... [22:00:10.177,765] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B004C8 (processed 4 messages)... [22:00:10.177,793] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:10.176,736] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 03:45:B6:00:00:00 [22:00:10.176,951] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 03:45:B6:00:00:00 [22:00:10.184,279] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 05:25:36:02:FC:FF:B4:01 [22:00:10.196,423] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:36:00 [22:00:10.196,843] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:36:00 [22:00:10.205,704] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 03:45:B6:00:00:00 [22:00:10.205,917] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 03:45:B6:00:00:00 [22:00:10.220,644] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x36 [22:00:10.220,803] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:10.220,840] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:10.220,917] [Z_STACK/READ] INFO : Received 3 bytes, subSys 0x45, cmdId 0xB6 [22:00:10.220,957] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0xB6 [22:00:10.220,986] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B004D8 (received 5 messages)... [22:00:10.221,013] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B004D8)... [22:00:10.221,084] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:10.221,129] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B004D8 [22:00:10.221,158] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:10.221,185] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000B6, len:0x00000003, pData:0xB6B004E0 [22:00:10.221,216] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:b6 [22:00:10.221,244] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B004D8)... [22:00:10.221,271] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B004D8 (processed 5 messages)... [22:00:10.221,300] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:10.223,403] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:10.223,524] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:10.224,652] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:10.225,546] [NWK_MGR/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:10.225,678] [NWK_MGR/LSTN] MISC1 : Sending ZigBee Generic Confirmation [22:00:10.225,767] [NWK_MGR/LSTN] PKT_HEX: [ NWK_MGR>>>>>>>>>>>>>>>>>>>>CON009] [ucst] 04:00:72:00:08:00:10:00 [22:00:10.225,817] [NWK_MGR/LSTN] PKTTYPE: [ NWK_MGR>>>>>>>>>>>>>>>>>>>>CON009] NwkZigbeeGenericCnf [22:00:10.225,863] [NWK_MGR/LSTN] PKTBODY: cmdId = ZIGBEE_GENERIC_CNF [22:00:10.225,901] [NWK_MGR/LSTN] PKTBODY: status = STATUS_SUCCESS [22:00:10.226,207] [NWK_MGR/LSTN] INFO : ...sent 8 bytes to Client [22:00:10.226,276] [NWK_MGR/LSTN] INFO : !Done [22:00:10.222,671] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:10.222,865] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:43:10:00 [22:00:10.222,937] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:10.222,994] [Z_STACK/LSTN] PKTBODY: cmdID = ZDO_MGMT_PERMIT_JOIN_REQ [22:00:10.223,034] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:10.230,755] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:10.232,161] [Z_STACK/LSTN] INFO : !Done [22:00:12.247,890] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 0C:45:CA:A9:ED:E7:C9:27:21:00:4B:12:00:00:00 [22:00:12.256,701] [NWK_MGR/READ] INFO : Received 18 bytes, subSys 0x51, cmdId 0x95 [22:00:12.256,823] [NWK_MGR/READ] INFO : RPC_CMD_AREQ cmdId: 0x95 [22:00:12.256,858] [NWK_MGR/READ] INFO : [DBG] Allocated @ 0xB6B004F8 (received 3 messages)... [22:00:12.256,888] [NWK_MGR/READ] INFO : Filling new message (@ 0xB6B004F8)... [22:00:12.250,717] [Z_STACK/READ] INFO : Received 12 bytes, subSys 0x45, cmdId 0xCA [22:00:12.250,853] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0xCA [22:00:12.250,891] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01270 (received 6 messages)... [22:00:12.250,920] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01270)... [22:00:12.255,287] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:12.255,393] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01270 [22:00:12.255,426] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:12.255,454] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000CA, len:0x0000000C, pData:0xB6B01278 [22:00:12.255,489] [Z_STACK/HNDL] INFO : zstackpb Sending TC Device Ind: nwkAddr:0xEDA9, extAddr:0x00124B002127C9E7, parentAddr:0x0000 [22:00:12.255,735] [Z_STACK/HNDL] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 12:00:51:95:08:95:01:10:A9:DB:03:19:E7:C9:27:21:00:4B:12:00:20:00 [22:00:12.255,810] [Z_STACK/HNDL] PKTTYPE: [ Z_STACK>>NWK_MGR ] zdoTcDeviceInd [22:00:12.255,867] [Z_STACK/HNDL] PKTBODY: cmdID = <NOT_FOUND> [22:00:12.255,909] [Z_STACK/HNDL] PKTBODY: nwkAddr = 0x0000EDA9 (60841) [22:00:12.255,947] [Z_STACK/HNDL] PKTBODY: extendedAddr = 00:12:4B:00:21:27:C9:E7 [22:00:12.255,981] [Z_STACK/HNDL] PKTBODY: parentAddr = 0x00000000 (0) [22:00:12.256,302] [Z_STACK/HNDL] INFO : ...sent 22 bytes to Client [22:00:12.256,373] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01270)... [22:00:12.256,405] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01270 (processed 6 messages)... [22:00:12.256,435] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:12.259,510] [NWK_MGR/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:12.263,763] [NWK_MGR/HNDL] INFO : [DBG] Processing @ 0xB6B004F8 [22:00:12.263,834] [NWK_MGR/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:12.263,864] [NWK_MGR/HNDL] INFO : [DBG] asyncCB: subSys:0x00000011, cmdId:0x00000095, len:0x00000012, pData:0xB6B00500 [22:00:12.263,916] [NWK_MGR/HNDL] MISC1 : Processing ZDO TC Device Ind: 00124B002127C9E7 [22:00:12.263,949] [NWK_MGR/HNDL] INFO : NwkMgr AddDevice State Machine Started on 0x00124b002127c9e7 [22:00:12.263,978] [NWK_MGR/HNDL] INFO : nwkAddr EDA9, parent 0000 [22:00:12.264,008] [NWK_MGR/HNDL] INFO : AddDevice: No state machines, extending list to 16 [22:00:12.264,038] [NWK_MGR/HNDL] INFO : AddDevice: Initiated new state machine [22:00:12.264,072] [NWK_MGR/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B004F8)... [22:00:12.264,100] [NWK_MGR/HNDL] INFO : [DBG] Clearing @ 0xB6B004F8 (processed 3 messages)... [22:00:12.264,128] [NWK_MGR/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:12.250,123] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 0C:45:CA:A9:ED:E7:C9:27:21:00:4B:12:00:00:00 [22:00:12.646,644] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 0D:45:C1:A9:ED:A9:ED:E7:C9:27:21:00:4B:12:00:8E [22:00:12.646,887] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 0D:45:C1:A9:ED:A9:ED:E7:C9:27:21:00:4B:12:00:8E [22:00:12.647,406] [Z_STACK/READ] INFO : Received 13 bytes, subSys 0x45, cmdId 0xC1 [22:00:12.647,517] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0xC1 [22:00:12.647,550] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01288 (received 7 messages)... [22:00:12.647,674] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01288)... [22:00:12.650,796] [NWK_MGR/READ] INFO : Received 31 bytes, subSys 0x51, cmdId 0x48 [22:00:12.650,919] [NWK_MGR/READ] INFO : RPC_CMD_AREQ cmdId: 0x48 [22:00:12.650,953] [NWK_MGR/READ] INFO : [DBG] Allocated @ 0xB6B00518 (received 4 messages)... [22:00:12.650,981] [NWK_MGR/READ] INFO : Filling new message (@ 0xB6B00518)... [22:00:12.656,940] [NWK_MGR/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:12.657,092] [NWK_MGR/HNDL] INFO : [DBG] Processing @ 0xB6B00518 [22:00:12.657,130] [NWK_MGR/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:12.657,158] [NWK_MGR/HNDL] INFO : [DBG] asyncCB: subSys:0x00000011, cmdId:0x00000048, len:0x0000001F, pData:0xB6B00520 [22:00:12.657,215] [NWK_MGR/HNDL] MISC1 : NwkMgr processZdoDeviceAnnounce: ieeeaddr 00124B002127C9E7, nwkaddr EDA9, capInfo 0E [22:00:12.657,254] [NWK_MGR/HNDL] INFO : AddDevice: Retrying state 1, remaining tries: 4 [22:00:12.657,287] [NWK_MGR/HNDL] MISC1 : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000 [22:00:12.657,328] [NWK_MGR/HNDL] INFO : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData: [22:00:12.657,359] [NWK_MGR/HNDL] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:12.657,431] [NWK_MGR/HNDL] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00 [22:00:12.657,480] [NWK_MGR/HNDL] PKTTYPE: [ Z_STACK<<NWK_MGR ] zdoIeeeAddrReq [22:00:12.657,528] [NWK_MGR/HNDL] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:12.657,567] [NWK_MGR/HNDL] PKTBODY: nwkAddr = 0x00000000 (0) [22:00:12.657,601] [NWK_MGR/HNDL] PKTBODY: type = SINGLE_DEVICE [22:00:12.657,635] [NWK_MGR/HNDL] PKTBODY: startIndex = 0x00000000 (0) [22:00:12.657,859] [NWK_MGR/HNDL] INFO : Waiting for synchronous response... [22:00:12.657,912] [NWK_MGR/HNDL] INFO : [MUTEX] Lock SRSP Mutex [22:00:12.657,940] [NWK_MGR/HNDL] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:12.649,549] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:12.649,672] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01288 [22:00:12.649,709] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:12.649,738] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000C1, len:0x0000000D, pData:0xB6B01290 [22:00:12.649,773] [Z_STACK/HNDL] INFO : zstackpb Sending Device Announce Ind [22:00:12.649,918] [Z_STACK/HNDL] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 1F:00:51:48:08:48:10:A9:DB:03:18:A9:DB:03:21:E7:C9:27:21:00:4B:12:00:2A:0A:08:00:10:01:18:01:20:01:28:00 [22:00:12.649,976] [Z_STACK/HNDL] PKTTYPE: [ Z_STACK>>NWK_MGR ] zdoDeviceAnnounceInd [22:00:12.650,034] [Z_STACK/HNDL] PKTBODY: cmdID = ZDO_DEVICE_ANNOUNCE [22:00:12.650,075] [Z_STACK/HNDL] PKTBODY: srcAddr = 0x0000EDA9 (60841) [22:00:12.650,111] [Z_STACK/HNDL] PKTBODY: devAddr = 0x0000EDA9 (60841) [22:00:12.650,148] [Z_STACK/HNDL] PKTBODY: devExtAddr = 00:12:4B:00:21:27:C9:E7 [22:00:12.650,182] [Z_STACK/HNDL] PKTBODY: capInfo : [22:00:12.650,213] [Z_STACK/HNDL] PKTBODY: panCoord = 0 [22:00:12.650,300] [Z_STACK/HNDL] PKTBODY: ffd = 1 [22:00:12.650,335] [Z_STACK/HNDL] PKTBODY: mainsPower = 1 [22:00:12.650,370] [Z_STACK/HNDL] PKTBODY: rxOnWhenIdle = 1 [22:00:12.650,403] [Z_STACK/HNDL] PKTBODY: security = 0 [22:00:12.660,942] [Z_STACK/LSTN] INFO : Receive message... [22:00:12.665,817] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:01:00:00:00:00 [22:00:12.664,946] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31 [22:00:12.665,088] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4 [22:00:12.665,134] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData: [22:00:12.665,166] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:12.665,228] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:12.665,285] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:12.665,537] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:12.665,592] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:12.665,621] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:12.668,232] [Z_STACK/HNDL] INFO : ...sent 35 bytes to Client [22:00:12.668,384] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01288)... [22:00:12.668,427] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01288 (processed 7 messages)... [22:00:12.668,457] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:12.674,183] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:12.674,291] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:12.674,324] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:12.672,559] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:01:00 [22:00:12.672,773] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:01:00 [22:00:12.678,733] [NWK_MGR/HNDL] INFO : [MUTEX] Unlock SRSP Mutex [22:00:12.678,914] [NWK_MGR/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B00518)... [22:00:12.678,961] [NWK_MGR/HNDL] INFO : [DBG] Clearing @ 0xB6B00518 (processed 4 messages)... [22:00:12.678,991] [NWK_MGR/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:12.683,493] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00 [22:00:12.683,862] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00 [22:00:12.673,241] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x01 [22:00:12.673,376] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:12.673,412] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:12.673,509] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:12.673,611] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:31:10:00 [22:00:12.673,674] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:12.673,729] [Z_STACK/LSTN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:12.673,771] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:12.673,979] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:12.674,038] [Z_STACK/LSTN] INFO : !Done [22:00:12.716,890] [Z_STACK/READ] INFO : Received 13 bytes, subSys 0x45, cmdId 0x81 [22:00:12.717,051] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0x81 [22:00:12.717,089] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01288 (received 8 messages)... [22:00:12.717,118] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01288)... [22:00:12.717,418] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:12.717,497] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01288 [22:00:12.717,530] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:12.717,559] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6B01290 [22:00:12.717,591] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:81 [22:00:12.717,619] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01288)... [22:00:12.717,646] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01288 (processed 8 messages)... [22:00:12.717,675] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:21.608,769] [Z_STACK/LSTN] INFO : Receive message... [22:00:21.608,952] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:15 [22:00:21.609,011] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:45, len::4 [22:00:21.609,048] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x45, pData: [22:00:21.609,079] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:21.609,140] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:45:00:00:00:05 [22:00:21.609,197] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:45:00:00:00:05 [22:00:21.609,516] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:21.609,575] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:21.609,604] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:21.612,573] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:45:00:00:00:05 [22:00:21.616,215] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:45:00 [22:00:21.602,473] [NWK_MGR/MAIN] INFO : AddDevice: Retrying state 2, remaining tries: 3 [22:00:21.602,659] [NWK_MGR/MAIN] MISC1 : NwkMgr MOT sendNwkRouteReq [22:00:21.602,710] [NWK_MGR/MAIN] INFO : preparing to send 6 bytes, subSys 0x11, cmdId 0x15, pData: [22:00:21.602,743] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:21.602,815] [NWK_MGR/MAIN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 06:00:31:15:08:15:10:00:30:05 [22:00:21.602,864] [NWK_MGR/MAIN] PKTTYPE: [ Z_STACK<<NWK_MGR ] devNwkRouteReq [22:00:21.602,916] [NWK_MGR/MAIN] PKTBODY: cmdID = DEV_NWK_ROUTE_REQ [22:00:21.602,955] [NWK_MGR/MAIN] PKTBODY: dstAddr = 0x00000000 (0) [22:00:21.602,996] [NWK_MGR/MAIN] PKTBODY: radius = 0x00000005 (5) [22:00:21.603,336] [NWK_MGR/MAIN] INFO : Waiting for synchronous response... [22:00:21.603,378] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Mutex [22:00:21.603,406] [NWK_MGR/MAIN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:21.620,454] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x45 [22:00:21.620,589] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:21.620,625] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:21.619,869] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:45:00 [22:00:21.623,984] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:21.624,190] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:15:10:00 [22:00:21.624,262] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:21.624,317] [Z_STACK/LSTN] PKTBODY: cmdID = DEV_NWK_ROUTE_REQ [22:00:21.624,358] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:21.624,799] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:21.624,929] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:21.624,963] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:21.630,334] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:21.630,502] [NWK_MGR/MAIN] MISC1 : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000 [22:00:21.630,559] [NWK_MGR/MAIN] INFO : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData: [22:00:21.630,594] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:21.630,666] [NWK_MGR/MAIN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00 [22:00:21.630,717] [NWK_MGR/MAIN] PKTTYPE: [ Z_STACK<<NWK_MGR ] zdoIeeeAddrReq [22:00:21.630,767] [NWK_MGR/MAIN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:21.630,806] [NWK_MGR/MAIN] PKTBODY: nwkAddr = 0x00000000 (0) [22:00:21.630,843] [NWK_MGR/MAIN] PKTBODY: type = SINGLE_DEVICE [22:00:21.630,878] [NWK_MGR/MAIN] PKTBODY: startIndex = 0x00000000 (0) [22:00:21.631,099] [NWK_MGR/MAIN] INFO : Waiting for synchronous response... [22:00:21.631,150] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Mutex [22:00:21.631,179] [NWK_MGR/MAIN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:21.635,460] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:01:00:00:00:00 [22:00:21.634,519] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:21.634,666] [Z_STACK/LSTN] INFO : !Done [22:00:21.634,740] [Z_STACK/LSTN] INFO : Receive message... [22:00:21.634,817] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31 [22:00:21.634,865] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4 [22:00:21.634,899] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData: [22:00:21.634,930] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:21.634,990] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:21.635,047] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:21.641,205] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:21.642,444] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:01:00 [22:00:21.645,641] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:01:00 [22:00:21.649,628] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x01 [22:00:21.649,961] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:21.650,010] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:21.651,286] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00 [22:00:21.651,518] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00 [22:00:21.652,802] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:21.655,740] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:21.656,802] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:21.657,711] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:31:10:00 [22:00:21.660,748] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:21.662,095] [Z_STACK/LSTN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:21.663,942] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:21.665,261] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:21.665,401] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:21.665,437] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:21.668,300] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:21.671,384] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:21.672,595] [Z_STACK/LSTN] INFO : !Done [22:00:21.688,367] [Z_STACK/READ] INFO : Received 13 bytes, subSys 0x45, cmdId 0x81 [22:00:21.688,539] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0x81 [22:00:21.688,578] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01288 (received 9 messages)... [22:00:21.688,608] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01288)... [22:00:21.688,701] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:21.688,749] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01288 [22:00:21.688,778] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:21.688,806] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6B01290 [22:00:21.688,838] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:81 [22:00:21.688,866] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01288)... [22:00:21.688,893] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01288 (processed 9 messages)... [22:00:21.688,923] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:30.680,773] [Z_STACK/LSTN] INFO : Receive message... [22:00:30.680,905] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:15 [22:00:30.680,961] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:45, len::4 [22:00:30.680,996] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x45, pData: [22:00:30.681,026] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:30.681,085] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:45:00:00:00:05 [22:00:30.681,140] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:45:00:00:00:05 [22:00:30.681,301] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:30.681,344] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:30.681,372] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:30.687,895] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:45:00:00:00:05 [22:00:30.679,844] [NWK_MGR/MAIN] INFO : AddDevice: Retrying state 2, remaining tries: 2 [22:00:30.680,028] [NWK_MGR/MAIN] MISC1 : NwkMgr MOT sendNwkRouteReq [22:00:30.680,079] [NWK_MGR/MAIN] INFO : preparing to send 6 bytes, subSys 0x11, cmdId 0x15, pData: [22:00:30.680,111] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:30.680,183] [NWK_MGR/MAIN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 06:00:31:15:08:15:10:00:30:05 [22:00:30.680,232] [NWK_MGR/MAIN] PKTTYPE: [ Z_STACK<<NWK_MGR ] devNwkRouteReq [22:00:30.680,282] [NWK_MGR/MAIN] PKTBODY: cmdID = DEV_NWK_ROUTE_REQ [22:00:30.680,321] [NWK_MGR/MAIN] PKTBODY: dstAddr = 0x00000000 (0) [22:00:30.680,362] [NWK_MGR/MAIN] PKTBODY: radius = 0x00000005 (5) [22:00:30.692,263] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:45:00 [22:00:30.696,199] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x45 [22:00:30.696,325] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:30.696,360] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:30.695,664] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:45:00 [22:00:30.700,175] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:30.700,382] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:15:10:00 [22:00:30.700,456] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:30.700,512] [Z_STACK/LSTN] PKTBODY: cmdID = DEV_NWK_ROUTE_REQ [22:00:30.700,554] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:30.700,769] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:30.700,831] [Z_STACK/LSTN] INFO : !Done [22:00:30.704,364] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:30.704,524] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:30.704,558] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:30.707,252] [NWK_MGR/MAIN] INFO : Waiting for synchronous response... [22:00:30.708,799] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Mutex [22:00:30.711,393] [NWK_MGR/MAIN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:30.713,636] [Z_STACK/LSTN] INFO : Receive message... [22:00:30.713,790] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31 [22:00:30.713,846] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4 [22:00:30.713,882] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData: [22:00:30.713,913] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:30.714,136] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:30.714,205] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:30.714,389] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:30.714,435] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:30.714,464] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:30.712,818] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:30.712,965] [NWK_MGR/MAIN] MISC1 : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000 [22:00:30.713,019] [NWK_MGR/MAIN] INFO : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData: [22:00:30.713,053] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:30.713,125] [NWK_MGR/MAIN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00 [22:00:30.713,177] [NWK_MGR/MAIN] PKTTYPE: [ Z_STACK<<NWK_MGR ] zdoIeeeAddrReq [22:00:30.713,225] [NWK_MGR/MAIN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:30.713,266] [NWK_MGR/MAIN] PKTBODY: nwkAddr = 0x00000000 (0) [22:00:30.713,302] [NWK_MGR/MAIN] PKTBODY: type = SINGLE_DEVICE [22:00:30.713,336] [NWK_MGR/MAIN] PKTBODY: startIndex = 0x00000000 (0) [22:00:30.720,808] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:01:00:00:00:00 [22:00:30.723,943] [NWK_MGR/MAIN] INFO : Waiting for synchronous response... [22:00:30.725,030] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Mutex [22:00:30.726,049] [NWK_MGR/MAIN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:30.728,169] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:01:00 [22:00:30.729,356] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:01:00 [22:00:30.732,168] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x01 [22:00:30.732,316] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:30.732,354] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:30.735,439] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:30.739,082] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:1E:00 [22:00:30.739,323] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:1E:00 [22:00:30.741,062] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:31:10:00 [22:00:30.743,983] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:30.745,078] [Z_STACK/LSTN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:30.748,080] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:30.749,452] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:30.749,585] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:30.749,789] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:30.752,999] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:30.754,255] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:30.755,987] [Z_STACK/LSTN] INFO : !Done [22:00:30.776,392] [Z_STACK/READ] INFO : Received 13 bytes, subSys 0x45, cmdId 0x81 [22:00:30.776,551] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0x81 [22:00:30.776,588] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01288 (received 10 messages)... [22:00:30.776,617] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01288)... [22:00:30.776,711] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:30.776,756] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01288 [22:00:30.776,784] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:30.776,811] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6B01290 [22:00:30.776,843] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:81 [22:00:30.776,871] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01288)... [22:00:30.776,898] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01288 (processed 10 messages)... [22:00:30.776,926] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:39.765,354] [Z_STACK/LSTN] INFO : Receive message... [22:00:39.765,488] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:15 [22:00:39.765,544] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:45, len::4 [22:00:39.765,578] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x45, pData: [22:00:39.765,608] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:39.765,666] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:45:00:00:00:05 [22:00:39.765,721] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:45:00:00:00:05 [22:00:39.765,892] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:39.765,937] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:39.765,967] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:39.772,682] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:45:00:00:00:05 [22:00:39.764,434] [NWK_MGR/MAIN] INFO : AddDevice: Retrying state 2, remaining tries: 1 [22:00:39.764,620] [NWK_MGR/MAIN] MISC1 : NwkMgr MOT sendNwkRouteReq [22:00:39.764,670] [NWK_MGR/MAIN] INFO : preparing to send 6 bytes, subSys 0x11, cmdId 0x15, pData: [22:00:39.764,703] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:39.764,774] [NWK_MGR/MAIN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 06:00:31:15:08:15:10:00:30:05 [22:00:39.764,823] [NWK_MGR/MAIN] PKTTYPE: [ Z_STACK<<NWK_MGR ] devNwkRouteReq [22:00:39.764,873] [NWK_MGR/MAIN] PKTBODY: cmdID = DEV_NWK_ROUTE_REQ [22:00:39.764,912] [NWK_MGR/MAIN] PKTBODY: dstAddr = 0x00000000 (0) [22:00:39.764,953] [NWK_MGR/MAIN] PKTBODY: radius = 0x00000005 (5) [22:00:39.777,130] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:45:00 [22:00:39.780,709] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x45 [22:00:39.780,954] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:39.781,003] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:39.779,982] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:45:00 [22:00:39.784,832] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:39.785,041] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:15:10:00 [22:00:39.785,113] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:39.785,168] [Z_STACK/LSTN] PKTBODY: cmdID = DEV_NWK_ROUTE_REQ [22:00:39.785,209] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:39.785,416] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:39.785,481] [Z_STACK/LSTN] INFO : !Done [22:00:39.789,635] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:39.789,785] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:39.789,821] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:39.792,010] [NWK_MGR/MAIN] INFO : Waiting for synchronous response... [22:00:39.794,461] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Mutex [22:00:39.795,458] [NWK_MGR/MAIN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:39.799,095] [Z_STACK/LSTN] INFO : Receive message... [22:00:39.799,249] [Z_STACK/LSTN] INFO : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31 [22:00:39.799,307] [Z_STACK/LSTN] INFO : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4 [22:00:39.799,343] [Z_STACK/LSTN] INFO : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData: [22:00:39.799,375] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:39.798,233] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:39.798,361] [NWK_MGR/MAIN] MISC1 : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000 [22:00:39.798,415] [NWK_MGR/MAIN] INFO : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData: [22:00:39.798,448] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Transaction Mutex [22:00:39.798,521] [NWK_MGR/MAIN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00 [22:00:39.798,571] [NWK_MGR/MAIN] PKTTYPE: [ Z_STACK<<NWK_MGR ] zdoIeeeAddrReq [22:00:39.798,620] [NWK_MGR/MAIN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:39.798,660] [NWK_MGR/MAIN] PKTBODY: nwkAddr = 0x00000000 (0) [22:00:39.798,696] [NWK_MGR/MAIN] PKTBODY: type = SINGLE_DEVICE [22:00:39.798,731] [NWK_MGR/MAIN] PKTBODY: startIndex = 0x00000000 (0) [22:00:39.803,700] [Z_STACK/LSTN] PKT_HEX: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:39.806,310] [Z_STACK/LSTN] PKTTYPE: [ NPISRVR<<Z_STACK ] [SREQ] 04:25:01:00:00:00:00 [22:00:39.808,043] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR ] [send] 04:25:01:00:00:00:00 [22:00:39.811,098] [NWK_MGR/MAIN] INFO : Waiting for synchronous response... [22:00:39.813,359] [Z_STACK/LSTN] INFO : Waiting for synchronous response... [22:00:39.816,002] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [SRSP] 01:65:01:00 [22:00:39.819,329] [NPISRVR/MAIN] PKT_HEX: [ NPISRVR>>Z_STACK ] [ucst] 01:65:01:00 [22:00:39.823,139] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:1E:00 [22:00:39.823,377] [NPISRVR/ACBK] PKT_HEX: [ NPISRVR>>Z_STACK ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:1E:00 [22:00:39.826,409] [NWK_MGR/MAIN] INFO : [MUTEX] Lock SRSP Mutex [22:00:39.827,958] [Z_STACK/READ] INFO : Received 1 bytes, subSys 0x65, cmdId 0x01 [22:00:39.828,111] [Z_STACK/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:39.828,146] [Z_STACK/READ] INFO : Client Read: (len 4): [22:00:39.829,192] [Z_STACK/LSTN] INFO : [MUTEX] Lock SRSP Mutex [22:00:39.832,077] [NWK_MGR/MAIN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:39.833,176] [Z_STACK/LSTN] INFO : [MUTEX] Wait for SRSP Cond signal... [22:00:39.834,060] [Z_STACK/LSTN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:39.835,992] [Z_STACK/LSTN] PKT_HEX: [ Z_STACK>>NWK_MGR ] [ucst] 04:00:71:FA:08:31:10:00 [22:00:39.837,244] [Z_STACK/LSTN] PKTTYPE: [ Z_STACK>>NWK_MGR ] zstackDefaultRsp [22:00:39.840,108] [NWK_MGR/READ] INFO : Received 4 bytes, subSys 0x71, cmdId 0xFA [22:00:39.840,245] [NWK_MGR/READ] INFO : [MUTEX] SRSP Cond signal set [22:00:39.840,280] [NWK_MGR/READ] INFO : Client Read: (len 8): [22:00:39.839,295] [Z_STACK/LSTN] PKTBODY: cmdID = ZDO_IEEE_ADDR_REQ [22:00:39.839,402] [Z_STACK/LSTN] PKTBODY: status = ZSuccess [22:00:39.844,223] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex [22:00:39.847,386] [Z_STACK/LSTN] INFO : ...sent 8 bytes to Client [22:00:39.848,625] [Z_STACK/LSTN] INFO : !Done [22:00:39.864,845] [Z_STACK/READ] INFO : Received 13 bytes, subSys 0x45, cmdId 0x81 [22:00:39.865,001] [Z_STACK/READ] INFO : RPC_CMD_AREQ cmdId: 0x81 [22:00:39.865,040] [Z_STACK/READ] INFO : [DBG] Allocated @ 0xB6B01288 (received 11 messages)... [22:00:39.865,069] [Z_STACK/READ] INFO : Filling new message (@ 0xB6B01288)... [22:00:39.865,166] [Z_STACK/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked [22:00:39.865,213] [Z_STACK/HNDL] INFO : [DBG] Processing @ 0xB6B01288 [22:00:39.865,243] [Z_STACK/HNDL] INFO : [MUTEX] AREQ Calling asynchMsgCback (Handle)... [22:00:39.865,272] [Z_STACK/HNDL] INFO : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6B01290 [22:00:39.865,303] [Z_STACK/HNDL] DEBUG : znp_misc handleAsyncMsgs: Unrecognized cmdID:81 [22:00:39.865,331] [Z_STACK/HNDL] INFO : [MUTEX] AREQ (Handle) (message @ 0xB6B01288)... [22:00:39.865,358] [Z_STACK/HNDL] INFO : [DBG] Clearing @ 0xB6B01288 (processed 11 messages)... [22:00:39.865,388] [Z_STACK/HNDL] INFO : [MUTEX] Wait for AREQ semaphore [22:00:48.855,279] [NWK_MGR/MAIN] INFO : AddDevice: Retrying state 2, remaining tries: 0 [22:00:48.855,461] [NWK_MGR/MAIN] INFO : AddDevice: Failed to get response from target node, state 2 [22:00:48.855,496] [NWK_MGR/MAIN] INFO : device 00124B002127C9E7 [22:00:48.855,529] [NWK_MGR/MAIN] INFO : [22:00:48.855,622] [NWK_MGR/MAIN] DEBUG : - AddDevice Failed 1 on 00124B002127C9E7 [22:00:48.855,656] [NWK_MGR/MAIN] INFO : zNwkSrv_AD_FreeStateMachine: Entered pState=0xb6d00588 [22:00:48.855,685] [NWK_MGR/MAIN] INFO : zNwkSrv_AD_FreeStateMachine: State machine freed [22:00:48.855,712] [NWK_MGR/MAIN] INFO : nwkMgrDb_FreeDeviceInfo: Entered pDeviceInfo=0xb6d00510 [22:00:48.855,739] [NWK_MGR/MAIN] INFO : nwkMgrDb_FreeDeviceInfoSubstructures: Entered pDeviceInfo=0xb6d00510 [22:00:48.855,766] [NWK_MGR/MAIN] INFO : nwkMgrDb_FreeDeviceInfoSubstructures: Exit [22:00:48.855,796] [NWK_MGR/MAIN] INFO : zNwkSrv_AD_FreeStateMachine: Exit

Gateway error on attaching mode including startup.txt

over 2 years ago

0 Alexander Argollo over 2 years ago

Genius 3370 points

Hi Guys.

Just for additional information, I have tested Zstack_3.1 (TI Light switch app example) firmware over the SMARTRF05EB Board with CC2530 inside and I have observed the same behavior and did not have success to attaching the well this device. I have included Wireshark log, this can be observed the last DeviceAnnce (line #130). As can be seen there are no other messages.

in the Gateway log attached file as can be observed the last Permit to join in:

[23:29:37.893,107] [NWK_MGR/LSTN] PKTBODY: cmdID = ZDO_MGMT_PERMIT_JOIN_REQ

Texas Gateway Attaching ERROR_TI Zstack3_0-20210531.zip

Gateway error on attaching procedure with Zstack 3_0 device_20210531.txt

0 Alexander Argollo over 2 years ago in reply to Alexander Argollo

Genius 3370 points

Guys, I have found the main problem. I got to success to add the two devices (zstack 1.2 and zstack 3.1 on/off device) that i tested before, as you can see on the app print screen bellow, after I reinstall the CC2531 firmware. to have sure that everything is running well I did hard reset on web App again, and after it I have observed the same behavior, I was no longer never success in add the two devices.

I believe that if I start to reinstall again the CC2531 firmware and do not send hardr reset command everything will working well.

Anybody have observed it?

0 Ryan Brown1 over 2 years ago in reply to Alexander Argollo

TI__Guru**** 202256 points

Hi Alexander,

This issue is due to the fact that the Local Gateway Sample Application does not perform a factory new reset on the ZNP, which is needed to clear the NV memory. You will need to execute a Hard System Reset in the Web Application or perform a SYS_OSAL_NV_WRITE MT command to NV ID 0x03 at value 0x03 followed by a SYS_RESET to clear NV memory, possible through Z-Tool. You can refer to the Final notes from the Zigbee Linux Gateway Project Zero SimpleLink Academy Lab. This is why programming a new ZNP image into the CC2531 resolves the issue, as it clears out the previous NV memory.

Regards,
Ryan

0 Alexander Argollo over 2 years ago in reply to Ryan Brown1

Genius 3370 points

Hi Ryan, sorry I haven´t explained well on my last post. I really performed the hard system reset button on the Web application in the all those tests i made and I have observed that when I execute it I haven´t success to attach a new devices on gateway. as you said everything is working fine again only after I programming a new ZNP images into the CC2531.

Does it make sense what I noticed?

Best Regards,

Alex

0 Ryan Brown1 over 2 years ago in reply to Alexander Argollo

TI__Guru**** 202256 points

Unless you are using the Node.js Web Application as described in the SLA or User's Guide (which is not reflected in your screenshots) we are talking about two different hard reset buttons which perform varying functions. You can verify that erasing NV memory resolves the issue through a Z-Tool test, YK covers this in his blog post.

Regards,
Ryan

0 Alexander Argollo over 2 years ago in reply to Ryan Brown1

Genius 3370 points

Hi Ryan, thanks a lot for your assistance.

I have used Local User Interfaces screenshot before and it my be cause confusion, but I only use it to show because on the local User interface we can see more details about the device attached into gateway. In all those resets (hard reset) I have used Node.js Web App to proceed it.

I didn´t describe it before, but always after I made Hard Reset I can´t see gateway node sending beacons. As you can see below, to see it (beacons) I do reboot, because it in this post I considering 2 st to attaching as a reference.

Node JS Web app with two devices attached, before I proceed the HARD RESET.

1st attempt to add, before reboot and after HArd Reset

I will try to describe step by step the behavior that I´m observing into 2st test.

My 2st Test Enviroment:

On/Off Device Router - 00:12:4b:00:21:27:c9:e7

Short ID - 0x7466 - Set for 2st test.

1 - Node JS Web application, starting to HARD RESET

2 - Hard Reset captured into the gtw log - could you see the all those LOG messages, at this stage, in the file bellow.

[07:50:41.730,277] [NWK_MGR/LSTN] INFO : [MUTEX] Lock SRSP Transaction Mutex
[07:50:41.730,341] [NWK_MGR/LSTN] PKT_HEX: [ Z_STACK<<NWK_MGR ] [SREQ] 06:00:31:00:08:00:10:00:18:01
[07:50:41.730,387] [NWK_MGR/LSTN] PKTTYPE: [ Z_STACK<<NWK_MGR ] sysResetReq
[07:50:41.730,436] [NWK_MGR/LSTN] PKTBODY: cmdID = SYS_RESET_REQ
[07:50:41.730,474] [NWK_MGR/LSTN] PKTBODY: type = DEVICE
[07:50:41.730,508] [NWK_MGR/LSTN] PKTBODY: newNwkState = 1

hard_reset_20210603.txt

3 - 2st. attempt to attaching Wireshark screenshot msg Permit2Join #45 08:03:13,059031

3.1 - Permit2Join in the Gateway LOG, log message [08:03:18.129,228]

Note: You can see into the over the air log and gateway LOG complete messages attached in this post.

4 - Wireshark log and into gateway log you can see that not have any ZCL messages as Node Desc Request, Active Desc Request, Simple Desc Request and etc.

You can see, into the wireshark screenshot bellow ( messages #62 and #68), and in the gateway log bellow the two attempts do complete the attaching procedure, through the two DeviceAnnce messages sent by TI On/Off device and before the Permit2JOIN with duration = 0.

4.1 - Gateway log you can see, as wireshark log also showed, the unsuccessful and incomplete attaching procedure.

Gateway Log 2st apt to add on/off device (unsuccessful).

2st_atp to add_my TI device_20210603.txt

[08:03:18.219,314] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:43:10:00
[08:03:18.219,384] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:03:18.219,440] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = ZDO_MGMT_PERMIT_JOIN_REQ
[08:03:18.219,480] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:03:18.231,771] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:03:18.231,926] [Z_STACK/LSTN] INFO   : !Done
[08:03:56.987,862] [Z_STACK/READ] INFO   : Received 12 bytes, subSys 0x45, cmdId 0xCA
[08:03:56.988,003] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0xCA
[08:03:56.988,041] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A004D8 (received  8 messages)...
[08:03:56.984,959] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 0C:45:CA:66:74:E7:C9:27:21:00:4B:12:00:00:00
[08:03:56.987,262] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 0C:45:CA:66:74:E7:C9:27:21:00:4B:12:00:00:00
[08:03:56.997,637] [NWK_MGR/READ] INFO   : Received 18 bytes, subSys 0x51, cmdId 0x95
[08:03:56.997,756] [NWK_MGR/READ] INFO   : RPC_CMD_AREQ cmdId: 0x95
[08:03:56.997,792] [NWK_MGR/READ] INFO   : [DBG] Allocated      @ 0xB6A004F8 (received  3 messages)...
[08:03:56.997,821] [NWK_MGR/READ] INFO   : Filling new message (@ 0xB6A004F8)...
[08:03:57.001,816] [NWK_MGR/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:03:57.001,913] [NWK_MGR/HNDL] INFO   : [DBG] Processing     @ 0xB6A004F8
[08:03:57.001,947] [NWK_MGR/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:03:57.001,975] [NWK_MGR/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000011, cmdId:0x00000095, len:0x00000012, pData:0xB6A00500
[08:03:57.002,023] [NWK_MGR/HNDL] MISC1  : Processing ZDO TC Device Ind: 00124B002127C9E7
[08:03:57.002,056] [NWK_MGR/HNDL] INFO   :
NwkMgr AddDevice State Machine Started on 0x00124b002127c9e7
[08:03:57.002,085] [NWK_MGR/HNDL] INFO   :   nwkAddr 7466, parent 0000
[08:03:57.002,115] [NWK_MGR/HNDL] INFO   :
AddDevice: No state machines, extending list to 16
[08:03:57.002,146] [NWK_MGR/HNDL] INFO   :
AddDevice: Initiated new state machine
[08:03:57.002,178] [NWK_MGR/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A004F8)...
[08:03:57.002,206] [NWK_MGR/HNDL] INFO   : [DBG] Clearing               @ 0xB6A004F8 (processed 3 messages)...
[08:03:57.002,234] [NWK_MGR/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:03:56.988,070] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A004D8)...
[08:03:56.996,409] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:03:56.996,766] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A004D8
[08:03:56.996,818] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:03:56.996,847] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000CA, len:0x0000000C, pData:0xB6A004E0
[08:03:56.996,881] [Z_STACK/HNDL] INFO   : zstackpb Sending TC Device Ind: nwkAddr:0x7466, extAddr:0x00124B002127C9E7, parentAddr:0x0000
[08:03:56.997,003] [Z_STACK/HNDL] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 12:00:51:95:08:95:01:10:E6:E8:01:19:E7:C9:27:21:00:4B:12:00:20:00
[08:03:56.997,065] [Z_STACK/HNDL] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zdoTcDeviceInd
[08:03:56.997,117] [Z_STACK/HNDL] PKTBODY:                                                          cmdID = <NOT_FOUND>
[08:03:56.997,158] [Z_STACK/HNDL] PKTBODY:                                                          nwkAddr = 0x00007466 (29798)
[08:03:56.997,195] [Z_STACK/HNDL] PKTBODY:                                                          extendedAddr = 00:12:4B:00:21:27:C9:E7
[08:03:56.997,230] [Z_STACK/HNDL] PKTBODY:                                                          parentAddr = 0x00000000 (0)
[08:03:57.006,694] [Z_STACK/HNDL] INFO   : ...sent 22 bytes to Client
[08:03:57.006,856] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A004D8)...
[08:03:57.006,899] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A004D8 (processed 8 messages)...
[08:03:57.006,930] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:03:57.428,329] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 0D:45:C1:66:74:66:74:E7:C9:27:21:00:4B:12:00:8E
[08:03:57.429,694] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 0D:45:C1:66:74:66:74:E7:C9:27:21:00:4B:12:00:8E
[08:03:57.431,016] [Z_STACK/READ] INFO   : Received 13 bytes, subSys 0x45, cmdId 0xC1
[08:03:57.431,163] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0xC1
[08:03:57.431,201] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00CD0 (received  9 messages)...
[08:03:57.431,231] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00CD0)...
[08:03:57.433,473] [NWK_MGR/READ] INFO   : Received 31 bytes, subSys 0x51, cmdId 0x48
[08:03:57.433,601] [NWK_MGR/READ] INFO   : RPC_CMD_AREQ cmdId: 0x48
[08:03:57.433,635] [NWK_MGR/READ] INFO   : [DBG] Allocated      @ 0xB6A00518 (received  4 messages)...
[08:03:57.433,664] [NWK_MGR/READ] INFO   : Filling new message (@ 0xB6A00518)...
[08:03:57.433,751] [NWK_MGR/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:03:57.433,798] [NWK_MGR/HNDL] INFO   : [DBG] Processing     @ 0xB6A00518
[08:03:57.433,829] [NWK_MGR/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:03:57.433,856] [NWK_MGR/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000011, cmdId:0x00000048, len:0x0000001F, pData:0xB6A00520
[08:03:57.433,909] [NWK_MGR/HNDL] MISC1  : NwkMgr processZdoDeviceAnnounce: ieeeaddr 00124B002127C9E7, nwkaddr 7466, capInfo 0E
[08:03:57.433,948] [NWK_MGR/HNDL] INFO   :
AddDevice: Retrying state 1, remaining tries: 4
[08:03:57.433,979] [NWK_MGR/HNDL] MISC1  : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000
[08:03:57.434,019] [NWK_MGR/HNDL] INFO   : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData:
[08:03:57.434,049] [NWK_MGR/HNDL] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:03:57.434,116] [NWK_MGR/HNDL] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00
[08:03:57.434,164] [NWK_MGR/HNDL] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] zdoIeeeAddrReq
[08:03:57.434,211] [NWK_MGR/HNDL] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:03:57.434,250] [NWK_MGR/HNDL] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:03:57.434,285] [NWK_MGR/HNDL] PKTBODY:                                                          type = SINGLE_DEVICE
[08:03:57.434,319] [NWK_MGR/HNDL] PKTBODY:                                                          startIndex = 0x00000000 (0)
[08:03:57.434,485] [NWK_MGR/HNDL] INFO   : Waiting for synchronous response...
[08:03:57.434,533] [NWK_MGR/HNDL] INFO   : [MUTEX] Lock SRSP Mutex
[08:03:57.434,562] [NWK_MGR/HNDL] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:03:57.432,257] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:03:57.432,369] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00CD0
[08:03:57.432,403] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:03:57.432,431] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000C1, len:0x0000000D, pData:0xB6A00CD8
[08:03:57.432,465] [Z_STACK/HNDL] INFO   : zstackpb Sending Device Announce Ind
[08:03:57.432,610] [Z_STACK/HNDL] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 1F:00:51:48:08:48:10:E6:E8:01:18:E6:E8:01:21:E7:C9:27:21:00:4B:12:00:2A:0A:08:00:10:01:18:01:20:01:28:00
[08:03:57.432,667] [Z_STACK/HNDL] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zdoDeviceAnnounceInd
[08:03:57.432,724] [Z_STACK/HNDL] PKTBODY:                                                          cmdID = ZDO_DEVICE_ANNOUNCE
[08:03:57.432,765] [Z_STACK/HNDL] PKTBODY:                                                          srcAddr = 0x00007466 (29798)
[08:03:57.432,800] [Z_STACK/HNDL] PKTBODY:                                                          devAddr = 0x00007466 (29798)
[08:03:57.432,838] [Z_STACK/HNDL] PKTBODY:                                                          devExtAddr = 00:12:4B:00:21:27:C9:E7
[08:03:57.432,871] [Z_STACK/HNDL] PKTBODY:                                                          capInfo :
[08:03:57.432,902] [Z_STACK/HNDL] PKTBODY:                                                            panCoord = 0
[08:03:57.432,990] [Z_STACK/HNDL] PKTBODY:                                                            ffd = 1
[08:03:57.433,025] [Z_STACK/HNDL] PKTBODY:                                                            mainsPower = 1
[08:03:57.433,059] [Z_STACK/HNDL] PKTBODY:                                                            rxOnWhenIdle = 1
[08:03:57.433,092] [Z_STACK/HNDL] PKTBODY:                                                            security = 0
[08:03:57.442,294] [Z_STACK/LSTN] INFO   : Receive message...
[08:03:57.446,198] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:01:00:00:00:00
[08:03:57.445,313] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31
[08:03:57.445,437] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4
[08:03:57.445,480] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData:
[08:03:57.445,512] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:03:57.445,572] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:03:57.445,628] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:03:57.445,924] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:03:57.445,983] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:03:57.446,010] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:03:57.450,345] [Z_STACK/HNDL] INFO   : ...sent 35 bytes to Client
[08:03:57.452,813] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:01:00
[08:03:57.453,034] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:01:00
[08:03:57.455,524] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x01
[08:03:57.455,646] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:03:57.455,680] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:03:57.455,772] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:03:57.459,814] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:03:57.459,929] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:03:57.459,963] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:03:57.463,895] [NWK_MGR/HNDL] INFO   : [MUTEX] Unlock SRSP Mutex
[08:03:57.464,016] [NWK_MGR/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00518)...
[08:03:57.464,058] [NWK_MGR/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00518 (processed 4 messages)...
[08:03:57.464,223] [NWK_MGR/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:03:57.463,506] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00
[08:03:57.463,745] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00
[08:03:57.459,031] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:31:10:00
[08:03:57.459,164] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:03:57.459,228] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:03:57.459,270] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:03:57.459,573] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:03:57.459,649] [Z_STACK/LSTN] INFO   : !Done
[08:03:57.470,638] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00CD0)...
[08:03:57.470,763] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00CD0 (processed 9 messages)...
[08:03:57.470,802] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:03:57.496,933] [Z_STACK/READ] INFO   : Received 13 bytes, subSys 0x45, cmdId 0x81
[08:03:57.497,093] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0x81
[08:03:57.497,131] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00CD0 (received  10 messages)...
[08:03:57.497,160] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00CD0)...
[08:03:57.497,449] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:03:57.497,523] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00CD0
[08:03:57.497,553] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:03:57.497,581] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6A00CD8
[08:03:57.497,613] [Z_STACK/HNDL] DEBUG  : znp_misc handleAsyncMsgs: Unrecognized cmdID:81
[08:03:57.497,641] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00CD0)...
[08:03:57.497,883] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00CD0 (processed 10 messages)...
[08:03:57.497,925] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:04:06.418,800] [Z_STACK/LSTN] INFO   : Receive message...
[08:04:06.418,935] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:15
[08:04:06.418,987] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:45, len::4
[08:04:06.419,021] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x45, pData:
[08:04:06.419,051] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:06.419,108] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:45:00:00:00:05
[08:04:06.419,163] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:45:00:00:00:05
[08:04:06.419,329] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:04:06.419,374] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:06.419,402] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:06.426,677] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:45:00:00:00:05
[08:04:06.417,885] [NWK_MGR/MAIN] INFO   :
AddDevice: Retrying state 2, remaining tries: 3
[08:04:06.418,069] [NWK_MGR/MAIN] MISC1  : NwkMgr MOT sendNwkRouteReq
[08:04:06.418,119] [NWK_MGR/MAIN] INFO   : preparing to send 6 bytes, subSys 0x11, cmdId 0x15, pData:
[08:04:06.418,152] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:06.418,222] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 06:00:31:15:08:15:10:00:30:05
[08:04:06.418,270] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] devNwkRouteReq
[08:04:06.418,325] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = DEV_NWK_ROUTE_REQ
[08:04:06.418,364] [NWK_MGR/MAIN] PKTBODY:                                                          dstAddr = 0x00000000 (0)
[08:04:06.418,405] [NWK_MGR/MAIN] PKTBODY:                                                          radius = 0x00000005 (5)
[08:04:06.429,124] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[08:04:06.429,264] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:06.429,302] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:06.432,014] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:45:00
[08:04:06.434,176] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x45
[08:04:06.434,301] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:06.434,337] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:04:06.433,682] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:45:00
[08:04:06.438,246] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:06.438,459] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:15:10:00
[08:04:06.438,533] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:04:06.438,589] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = DEV_NWK_ROUTE_REQ
[08:04:06.438,630] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:04:06.439,064] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:04:06.439,189] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:06.439,224] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:04:06.445,150] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:04:06.445,319] [Z_STACK/LSTN] INFO   : !Done
[08:04:06.446,411] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:06.446,565] [NWK_MGR/MAIN] MISC1  : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000
[08:04:06.446,618] [NWK_MGR/MAIN] INFO   : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData:
[08:04:06.446,651] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:06.446,726] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00
[08:04:06.446,777] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] zdoIeeeAddrReq
[08:04:06.446,826] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:04:06.446,866] [NWK_MGR/MAIN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:04:06.446,901] [NWK_MGR/MAIN] PKTBODY:                                                          type = SINGLE_DEVICE
[08:04:06.446,936] [NWK_MGR/MAIN] PKTBODY:                                                          startIndex = 0x00000000 (0)
[08:04:06.447,194] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[08:04:06.447,251] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:06.447,281] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:06.451,483] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:01:00:00:00:00
[08:04:06.450,315] [Z_STACK/LSTN] INFO   : Receive message...
[08:04:06.450,495] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31
[08:04:06.450,553] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4
[08:04:06.450,589] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData:
[08:04:06.450,618] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:06.450,678] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:04:06.450,733] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:04:06.456,981] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:04:06.459,700] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:06.460,618] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:06.463,027] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:01:00
[08:04:06.464,546] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:01:00
[08:04:06.465,811] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x01
[08:04:06.465,955] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:06.465,991] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:04:06.470,558] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:06.471,982] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:BD:00
[08:04:06.472,376] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:BD:00
[08:04:06.475,307] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:31:10:00
[08:04:06.477,134] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:04:06.477,258] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:06.477,292] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:04:06.480,012] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:06.476,574] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:04:06.476,708] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:04:06.476,758] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:04:06.484,472] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:04:06.487,195] [Z_STACK/LSTN] INFO   : !Done
[08:04:06.508,853] [Z_STACK/READ] INFO   : Received 13 bytes, subSys 0x45, cmdId 0x81
[08:04:06.509,018] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0x81
[08:04:06.509,058] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00CD0 (received  11 messages)...
[08:04:06.509,087] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00CD0)...
[08:04:06.509,185] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:04:06.509,233] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00CD0
[08:04:06.509,262] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:04:06.509,289] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6A00CD8
[08:04:06.509,320] [Z_STACK/HNDL] DEBUG  : znp_misc handleAsyncMsgs: Unrecognized cmdID:81
[08:04:06.509,348] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00CD0)...
[08:04:06.509,375] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00CD0 (processed 11 messages)...
[08:04:06.509,404] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:04:15.498,432] [NWK_MGR/MAIN] INFO   :
AddDevice: Retrying state 2, remaining tries: 2
[08:04:15.498,589] [NWK_MGR/MAIN] MISC1  : NwkMgr MOT sendNwkRouteReq
[08:04:15.498,644] [NWK_MGR/MAIN] INFO   : preparing to send 6 bytes, subSys 0x11, cmdId 0x15, pData:
[08:04:15.506,164] [Z_STACK/LSTN] INFO   : Receive message...
[08:04:15.506,330] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:15
[08:04:15.506,387] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:45, len::4
[08:04:15.506,422] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x45, pData:
[08:04:15.506,452] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:15.506,510] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:45:00:00:00:05
[08:04:15.506,563] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:45:00:00:00:05
[08:04:15.506,768] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:04:15.506,818] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:15.506,845] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:15.511,662] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:45:00:00:00:05
[08:04:15.498,679] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:15.505,605] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 06:00:31:15:08:15:10:00:30:05
[08:04:15.505,693] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] devNwkRouteReq
[08:04:15.505,751] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = DEV_NWK_ROUTE_REQ
[08:04:15.505,795] [NWK_MGR/MAIN] PKTBODY:                                                          dstAddr = 0x00000000 (0)
[08:04:15.505,838] [NWK_MGR/MAIN] PKTBODY:                                                          radius = 0x00000005 (5)
[08:04:15.515,975] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:45:00
[08:04:15.519,485] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x45
[08:04:15.519,613] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:15.519,648] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:04:15.519,013] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:45:00
[08:04:15.523,591] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:15.523,797] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:15:10:00
[08:04:15.523,868] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:04:15.523,921] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = DEV_NWK_ROUTE_REQ
[08:04:15.523,961] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:04:15.527,443] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:04:15.527,603] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:15.527,639] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:04:15.530,447] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[08:04:15.530,569] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:15.530,605] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:15.530,633] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:15.530,680] [NWK_MGR/MAIN] MISC1  : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000
[08:04:15.530,725] [NWK_MGR/MAIN] INFO   : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData:
[08:04:15.530,756] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:15.530,826] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00
[08:04:15.530,876] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] zdoIeeeAddrReq
[08:04:15.530,924] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:04:15.530,963] [NWK_MGR/MAIN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:04:15.530,998] [NWK_MGR/MAIN] PKTBODY:                                                          type = SINGLE_DEVICE
[08:04:15.531,033] [NWK_MGR/MAIN] PKTBODY:                                                          startIndex = 0x00000000 (0)
[08:04:15.531,286] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[08:04:15.531,345] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:15.531,375] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:15.535,637] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:01:00:00:00:00
[08:04:15.534,720] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:04:15.534,867] [Z_STACK/LSTN] INFO   : !Done
[08:04:15.534,944] [Z_STACK/LSTN] INFO   : Receive message...
[08:04:15.535,021] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31
[08:04:15.535,069] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4
[08:04:15.535,102] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData:
[08:04:15.535,132] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:15.535,191] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:04:15.535,246] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:04:15.541,715] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:01:00
[08:04:15.544,562] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:01:00
[08:04:15.545,929] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x01
[08:04:15.546,066] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:15.546,101] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:04:15.549,243] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:04:15.550,654] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00
[08:04:15.550,894] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00
[08:04:15.552,554] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:15.555,136] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:15.563,734] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:15.565,104] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:31:10:00
[08:04:15.568,606] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:04:15.568,740] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:15.568,777] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:04:15.571,704] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:15.567,848] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:04:15.567,979] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:04:15.568,029] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:04:15.573,895] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:04:15.576,730] [Z_STACK/LSTN] INFO   : !Done
[08:04:15.591,643] [Z_STACK/READ] INFO   : Received 13 bytes, subSys 0x45, cmdId 0x81
[08:04:15.591,800] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0x81
[08:04:15.591,838] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00CD0 (received  12 messages)...
[08:04:15.591,868] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00CD0)...
[08:04:15.595,059] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:04:15.595,165] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00CD0
[08:04:15.595,197] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:04:15.595,226] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6A00CD8
[08:04:15.595,257] [Z_STACK/HNDL] DEBUG  : znp_misc handleAsyncMsgs: Unrecognized cmdID:81
[08:04:15.595,284] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00CD0)...
[08:04:15.595,311] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00CD0 (processed 12 messages)...
[08:04:15.595,340] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:04:24.585,081] [Z_STACK/LSTN] INFO   : Receive message...
[08:04:24.585,214] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:15
[08:04:24.585,269] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:45, len::4
[08:04:24.585,304] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x45, pData:
[08:04:24.585,333] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:24.585,391] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:45:00:00:00:05
[08:04:24.585,444] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:45:00:00:00:05
[08:04:24.585,620] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:04:24.585,665] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:24.585,694] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:24.592,760] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:45:00:00:00:05
[08:04:24.584,181] [NWK_MGR/MAIN] INFO   :
AddDevice: Retrying state 2, remaining tries: 1
[08:04:24.584,356] [NWK_MGR/MAIN] MISC1  : NwkMgr MOT sendNwkRouteReq
[08:04:24.584,408] [NWK_MGR/MAIN] INFO   : preparing to send 6 bytes, subSys 0x11, cmdId 0x15, pData:
[08:04:24.584,440] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:24.584,510] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 06:00:31:15:08:15:10:00:30:05
[08:04:24.584,560] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] devNwkRouteReq
[08:04:24.584,610] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = DEV_NWK_ROUTE_REQ
[08:04:24.584,648] [NWK_MGR/MAIN] PKTBODY:                                                          dstAddr = 0x00000000 (0)
[08:04:24.584,689] [NWK_MGR/MAIN] PKTBODY:                                                          radius = 0x00000005 (5)
[08:04:24.597,754] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:45:00
[08:04:24.601,202] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x45
[08:04:24.601,339] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:24.601,376] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:04:24.600,605] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:45:00
[08:04:24.605,645] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:24.605,855] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:15:10:00
[08:04:24.605,927] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:04:24.605,981] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = DEV_NWK_ROUTE_REQ
[08:04:24.606,022] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:04:24.606,234] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:04:24.606,296] [Z_STACK/LSTN] INFO   : !Done
[08:04:24.609,557] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:04:24.609,705] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:24.609,741] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:04:24.612,571] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[08:04:24.613,866] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:24.614,701] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:24.616,336] [Z_STACK/LSTN] INFO   : Receive message...
[08:04:24.616,511] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:31
[08:04:24.616,570] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:1, len::4
[08:04:24.616,607] [Z_STACK/LSTN] INFO   : preparing to send 4 bytes, subSys 0x05, cmdId 0x01, pData:
[08:04:24.616,636] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:24.616,694] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:04:24.615,420] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:24.615,524] [NWK_MGR/MAIN] MISC1  : NwkMgr sendZdoIeeeAddrReq: ieeeaddr 0000
[08:04:24.615,576] [NWK_MGR/MAIN] INFO   : preparing to send 8 bytes, subSys 0x11, cmdId 0x31, pData:
[08:04:24.615,610] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:04:24.615,683] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 08:00:31:31:08:31:10:00:18:00:20:00
[08:04:24.615,735] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] zdoIeeeAddrReq
[08:04:24.615,782] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:04:24.615,822] [NWK_MGR/MAIN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:04:24.615,857] [NWK_MGR/MAIN] PKTBODY:                                                          type = SINGLE_DEVICE
[08:04:24.615,892] [NWK_MGR/MAIN] PKTBODY:                                                          startIndex = 0x00000000 (0)
[08:04:24.623,032] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 04:25:01:00:00:00:00
[08:04:24.626,306] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 04:25:01:00:00:00:00
[08:04:24.627,653] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:04:24.630,594] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:24.631,613] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:24.633,788] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:01:00
[08:04:24.636,885] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:01:00
[08:04:24.640,022] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x01
[08:04:24.640,492] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:24.640,535] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:04:24.643,635] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00
[08:04:24.643,880] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 0D:45:81:00:34:57:49:01:00:4B:12:00:00:00:00:00
[08:04:24.645,351] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:24.645,535] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:31:10:00
[08:04:24.645,605] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:04:24.645,660] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = ZDO_IEEE_ADDR_REQ
[08:04:24.645,699] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:04:24.645,915] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:04:24.645,978] [Z_STACK/LSTN] INFO   : !Done
[08:04:24.648,584] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:04:24.648,720] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:04:24.648,755] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:04:24.652,554] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[08:04:24.653,625] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[08:04:24.654,422] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:04:24.656,788] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:04:24.680,901] [Z_STACK/READ] INFO   : Received 13 bytes, subSys 0x45, cmdId 0x81
[08:04:24.681,064] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0x81
[08:04:24.681,105] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00CD0 (received  13 messages)...
[08:04:24.681,134] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00CD0)...
[08:04:24.681,227] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:04:24.681,274] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00CD0
[08:04:24.681,303] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:04:24.681,330] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x00000081, len:0x0000000D, pData:0xB6A00CD8
[08:04:24.681,361] [Z_STACK/HNDL] DEBUG  : znp_misc handleAsyncMsgs: Unrecognized cmdID:81
[08:04:24.681,390] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00CD0)...
[08:04:24.681,416] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00CD0 (processed 13 messages)...
[08:04:24.681,446] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:04:33.669,052] [NWK_MGR/MAIN] INFO   :
AddDevice: Retrying state 2, remaining tries: 0
[08:04:33.669,239] [NWK_MGR/MAIN] INFO   :
AddDevice: Failed to get response from target node, state 2
[08:04:33.669,274] [NWK_MGR/MAIN] INFO   :  device 00124B002127C9E7
[08:04:33.669,307] [NWK_MGR/MAIN] INFO   :
[08:04:33.669,335] [NWK_MGR/MAIN] DEBUG  : - AddDevice Failed 1 on 00124B002127C9E7
[08:04:33.669,364] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachine: Entered pState=0xb6c00528
[08:04:33.669,391] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachine: State machine freed
[08:04:33.669,417] [NWK_MGR/MAIN] INFO   : nwkMgrDb_FreeDeviceInfo: Entered pDeviceInfo=0xb6c006f0
[08:04:33.669,444] [NWK_MGR/MAIN] INFO   : nwkMgrDb_FreeDeviceInfoSubstructures: Entered pDeviceInfo=0xb6c006f0
[08:04:33.669,471] [NWK_MGR/MAIN] INFO   : nwkMgrDb_FreeDeviceInfoSubstructures: Exit
[08:04:33.669,501] [NWK_MGR/MAIN] INFO   : zNwkSrv_AD_FreeStateMachine: Exit
[08:06:06.571,768] [Z_STACK/LSTN] INFO   : Receive message...
[08:06:06.571,914] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:43
[08:06:06.571,974] [Z_STACK/LSTN] INFO   : preparing to send 0 bytes, subSys 0x05, cmdId 0x50, pData:
[08:06:06.572,009] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:06:06.572,059] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[08:06:06.572,259] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[08:06:06.572,489] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:06:06.572,544] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:06:06.572,573] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:06:06.578,543] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 00:25:50
[08:06:06.570,656] [NWK_MGR/LSTN] INFO   : Receive message...
[08:06:06.570,887] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR<<<<<<<<<<<<<<<<<<<<CON010] [read] 06:00:12:0C:08:0C:10:02:18:00
[08:06:06.570,953] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR<<<<<<<<<<<<<<<<<<<<CON010] NwkSetPermitJoinReq
[08:06:06.571,007] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_SET_PERMIT_JOIN_REQ
[08:06:06.571,049] [NWK_MGR/LSTN] PKTBODY:                                                          permitJoin = PERMIT_ALL
[08:06:06.571,086] [NWK_MGR/LSTN] PKTBODY:                                                          permitJoinTime = 0x00000000 (0)
[08:06:06.571,127] [NWK_MGR/LSTN] MISC1  : Processing Set Permit Join Request.
[08:06:06.571,156] [NWK_MGR/LSTN] MISC1  : NwkMgr sendZdoMgmtPermitJoinReq: nwkaddr FFFC
[08:06:06.571,196] [NWK_MGR/LSTN] INFO   : preparing to send 10 bytes, subSys 0x11, cmdId 0x43, pData:
[08:06:06.571,226] [NWK_MGR/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:06:06.571,293] [NWK_MGR/LSTN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 0A:00:31:43:08:43:10:FC:FF:03:18:00:20:01
[08:06:06.571,337] [NWK_MGR/LSTN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] zdoMgmtPermitJoinReq
[08:06:06.571,379] [NWK_MGR/LSTN] PKTBODY:                                                          cmdID = ZDO_MGMT_PERMIT_JOIN_REQ
[08:06:06.571,417] [NWK_MGR/LSTN] PKTBODY:                                                          nwkAddr = 0x0000FFFC (65532)
[08:06:06.571,452] [NWK_MGR/LSTN] PKTBODY:                                                          duration = 0x00000000 (0)
[08:06:06.571,487] [NWK_MGR/LSTN] PKTBODY:                                                          tcSignificance = 1
[08:06:06.582,684] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 18:65:50:00:00:09:7A:C7:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D
[08:06:06.586,410] [Z_STACK/READ] INFO   : Received 24 bytes, subSys 0x65, cmdId 0x50
[08:06:06.586,545] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:06:06.586,583] [Z_STACK/READ] INFO   : Client Read: (len 27):
[08:06:06.585,825] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 18:65:50:00:00:09:7A:C7:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D
[08:06:06.590,532] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:06:06.590,687] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:36, len::5
[08:06:06.590,732] [Z_STACK/LSTN] INFO   : preparing to send 5 bytes, subSys 0x05, cmdId 0x36, pData:
[08:06:06.590,765] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:06:06.590,831] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:25:36:02:00:00:00:01
[08:06:06.590,892] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:25:36:02:00:00:00:01
[08:06:06.591,118] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:06:06.591,170] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:06:06.591,199] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:06:06.594,484] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:25:36:02:00:00:00:01
[08:06:06.597,526] [NWK_MGR/LSTN] INFO   : Waiting for synchronous response...
[08:06:06.598,478] [NWK_MGR/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:06:06.598,574] [NWK_MGR/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:06:06.600,676] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:36:00
[08:06:06.602,106] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x36
[08:06:06.602,235] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:06:06.602,271] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:06:06.601,620] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:36:00
[08:06:06.606,308] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:06:06.606,457] [Z_STACK/LSTN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:36, len::5
[08:06:06.606,501] [Z_STACK/LSTN] INFO   : preparing to send 5 bytes, subSys 0x05, cmdId 0x36, pData:
[08:06:06.606,533] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:06:06.606,596] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:25:36:02:FC:FF:00:01
[08:06:06.606,655] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:25:36:02:FC:FF:00:01
[08:06:06.606,925] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:06:06.606,985] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:06:06.607,014] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:06:06.611,000] [Z_STACK/READ] INFO   : Received 3 bytes, subSys 0x45, cmdId 0xB6
[08:06:06.611,121] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0xB6
[08:06:06.611,156] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00490 (received  14 messages)...
[08:06:06.611,186] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00490)...
[08:06:06.611,255] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:06:06.611,298] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00490
[08:06:06.611,325] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:06:06.611,353] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000B6, len:0x00000003, pData:0xB6A00498
[08:06:06.611,384] [Z_STACK/HNDL] DEBUG  : znp_misc handleAsyncMsgs: Unrecognized cmdID:b6
[08:06:06.611,412] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00490)...
[08:06:06.611,438] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00490 (processed 14 messages)...
[08:06:06.611,467] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:06:06.610,353] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 03:45:B6:00:00:00
[08:06:06.610,580] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 03:45:B6:00:00:00
[08:06:06.615,993] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:25:36:02:FC:FF:00:01
[08:06:06.630,792] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:36:00
[08:06:06.631,220] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:36:00
[08:06:06.638,401] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 03:45:B6:00:00:00
[08:06:06.638,616] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 03:45:B6:00:00:00
[08:06:06.652,725] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x36
[08:06:06.652,882] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:06:06.652,919] [Z_STACK/READ] INFO   : Client Read: (len 4):
[08:06:06.652,992] [Z_STACK/READ] INFO   : Received 3 bytes, subSys 0x45, cmdId 0xB6
[08:06:06.653,031] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0xB6
[08:06:06.653,060] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0xB6A00CC0 (received  15 messages)...
[08:06:06.653,088] [Z_STACK/READ] INFO   : Filling new message (@ 0xB6A00CC0)...
[08:06:06.653,161] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[08:06:06.653,203] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0xB6A00CC0
[08:06:06.653,231] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[08:06:06.653,258] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000B6, len:0x00000003, pData:0xB6A00CC8
[08:06:06.653,289] [Z_STACK/HNDL] DEBUG  : znp_misc handleAsyncMsgs: Unrecognized cmdID:b6
[08:06:06.653,316] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0xB6A00CC0)...
[08:06:06.653,343] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0xB6A00CC0 (processed 15 messages)...
[08:06:06.653,372] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[08:06:06.655,483] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[08:06:06.655,606] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:06:06.655,639] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[08:06:06.657,001] [NWK_MGR/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:06:06.657,153] [NWK_MGR/LSTN] MISC1  : Sending ZigBee Generic Confirmation
[08:06:06.657,244] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] [ucst] 04:00:72:00:08:00:10:00
[08:06:06.657,296] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] NwkZigbeeGenericCnf
[08:06:06.657,341] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = ZIGBEE_GENERIC_CNF
[08:06:06.657,381] [NWK_MGR/LSTN] PKTBODY:                                                          status = STATUS_SUCCESS
[08:06:06.657,677] [NWK_MGR/LSTN] INFO   : ...sent 8 bytes to Client
[08:06:06.657,744] [NWK_MGR/LSTN] INFO   : !Done
[08:06:06.654,763] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:06:06.654,952] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:43:10:00
[08:06:06.655,020] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[08:06:06.655,074] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = ZDO_MGMT_PERMIT_JOIN_REQ
[08:06:06.655,114] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[08:06:06.661,941] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[08:06:06.664,771] [Z_STACK/LSTN] INFO   : !Done

Wireshark Log 2st apt to add on/off device (unsuccessful).

2st atp to add on-off device_20210603.zip

note: You can see below the Gateway log startup before the 1st and 2st test.

gtw_startUP_20210603.txt

[08:01:27.666,150] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 31:00:71:0E:08:0E:10:00:19:34:57:49:01:00:4B:12:00:20:09:28:FA:8E:03:31:34:57:49:01:00:4B:12:00:38:00:41:00:00:00:00:00:00:00:00:4A:06:08:01:10:00:18:00:50:0D
[08:01:27.666,209] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] sysNwkInfoReadRsp
[08:01:27.666,273] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_RSP
[08:01:27.666,314] [Z_STACK/LSTN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:01:27.666,353] [Z_STACK/LSTN] PKTBODY:                                                          ieeeAddr = 00:12:4B:00:01:49:57:34
[08:01:27.666,388] [Z_STACK/LSTN] PKTBODY:                                                          devState = DEV_ZB_COORD
[08:01:27.666,421] [Z_STACK/LSTN] PKTBODY:                                                          panId = 0x0000C77A (51066)
[08:01:27.666,458] [Z_STACK/LSTN] PKTBODY:                                                          extendedPanId = 00:12:4B:00:01:49:57:34
[08:01:27.666,491] [Z_STACK/LSTN] PKTBODY:                                                          coordAddr = 0x00000000 (0)
[08:01:27.666,528] [Z_STACK/LSTN] PKTBODY:                                                          coordExtAddr = 00:00:00:00:00:00:00:00
[08:01:27.666,561] [Z_STACK/LSTN] PKTBODY:                                                          devTypes :
[08:01:27.666,592] [Z_STACK/LSTN] PKTBODY:                                                            coodinator = 1
[08:01:27.666,626] [Z_STACK/LSTN] PKTBODY:                                                            router = 0
[08:01:27.666,659] [Z_STACK/LSTN] PKTBODY:                                                            enddevice = 0
[08:01:27.666,694] [Z_STACK/LSTN] PKTBODY:                                                          logicalChannel = 0x0000000D (13)
[08:01:27.673,613] [NWK_MGR/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:01:27.673,805] [NWK_MGR/LSTN] MISC1  : NwkInfoReadRsp:
[08:01:27.673,846] [NWK_MGR/LSTN] MISC1  : - nwkaddr:0000
[08:01:27.673,877] [NWK_MGR/LSTN] MISC1  : - ieeeaddr:00124B0001495734
[08:01:27.673,907] [NWK_MGR/LSTN] MISC1  : - devstate:9
[08:01:27.673,934] [NWK_MGR/LSTN] MISC1  : - panid:C77A
[08:01:27.673,960] [NWK_MGR/LSTN] MISC1  : - extendedpanid:00124B0001495734
[08:01:27.673,987] [NWK_MGR/LSTN] MISC1  : - coordaddr:0000
[08:01:27.674,013] [NWK_MGR/LSTN] MISC1  : - coordextaddr:0000000000000000
[08:01:27.674,039] [NWK_MGR/LSTN] MISC1  : - devtypes: Coordinator: 1
[08:01:27.674,065] [NWK_MGR/LSTN] MISC1  : - devtypes: Router: 0
[08:01:27.674,091] [NWK_MGR/LSTN] MISC1  : - logicalchannel:13

[08:01:27.674,211] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] [ucst] 13:00:72:0B:08:0B:10:01:18:0D:20:FA:8E:03:29:34:57:49:01:00:4B:12:00
[08:01:27.674,262] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] NwkZigbeeNwkInfoCnf
[08:01:27.674,309] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_ZIGBEE_NWK_INFO_CNF
[08:01:27.674,350] [NWK_MGR/LSTN] PKTBODY:                                                          status = NWK_UP
[08:01:27.674,386] [NWK_MGR/LSTN] PKTBODY:                                                          nwkChannel = 0x0000000D (13)
[08:01:27.674,421] [NWK_MGR/LSTN] PKTBODY:                                                          panId = 0x0000C77A (51066)
[08:01:27.674,458] [NWK_MGR/LSTN] PKTBODY:                                                          extPanId = 00:12:4B:00:01:49:57:34
[08:01:27.674,784] [NWK_MGR/LSTN] INFO   : ...sent 23 bytes to Client
[08:01:27.674,855] [NWK_MGR/LSTN] INFO   : !Done
[08:01:27.680,019] [Z_STACK/LSTN] INFO   : ...sent 53 bytes to Client
[08:01:27.681,268] [Z_STACK/LSTN] INFO   : !Done
[08:01:27.816,328] [NWK_MGR/LSTN] INFO   : Receive message...
[08:01:27.816,533] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR<<<<<<<<<<<<<<<<<<<<CON010] [read] 02:00:12:0A:08:0A
[08:01:27.816,597] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR<<<<<<<<<<<<<<<<<<<<CON010] NwkZigbeeNwkInfoReq
[08:01:27.816,647] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_ZIGBEE_NWK_INFO_REQ
[08:01:27.816,691] [NWK_MGR/LSTN] MISC1  : NWK_ZIGBEE_NWK_INFO_REQ
[08:01:27.816,720] [NWK_MGR/LSTN] MISC1  : NwkMgr sendSysNwkInfoReadReqAndSetTxPower:
[08:01:27.816,756] [NWK_MGR/LSTN] INFO   : preparing to send 2 bytes, subSys 0x11, cmdId 0x08, pData:
[08:01:27.816,786] [NWK_MGR/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:01:27.816,838] [NWK_MGR/LSTN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 02:00:31:08:08:08
[08:01:27.816,878] [NWK_MGR/LSTN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] sysNwkInfoReadReq
[08:01:27.816,917] [NWK_MGR/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_REQ
[08:01:27.817,238] [NWK_MGR/LSTN] INFO   : Waiting for synchronous response...
[08:01:27.817,299] [NWK_MGR/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:01:27.817,329] [NWK_MGR/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:01:27.821,876] [Z_STACK/LSTN] INFO   : Receive message...
[08:01:27.822,066] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:8
[08:01:27.822,118] [Z_STACK/LSTN] INFO   : preparing to send 0 bytes, subSys 0x05, cmdId 0x50, pData:
[08:01:27.822,152] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:01:27.822,204] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[08:01:27.822,253] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[08:01:27.822,556] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:01:27.822,618] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:01:27.822,647] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:01:27.825,726] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 00:25:50
[08:01:27.829,409] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 18:65:50:00:00:09:7A:C7:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D
[08:01:27.832,051] [Z_STACK/READ] INFO   : Received 24 bytes, subSys 0x65, cmdId 0x50
[08:01:27.832,339] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:01:27.832,379] [Z_STACK/READ] INFO   : Client Read: (len 27):
[08:01:27.831,481] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 18:65:50:00:00:09:7A:C7:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D
[08:01:27.838,754] [NWK_MGR/READ] INFO   : Received 49 bytes, subSys 0x71, cmdId 0x0E
[08:01:27.838,875] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:01:27.838,910] [NWK_MGR/READ] INFO   : Client Read: (len 53):
[08:01:27.837,253] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:01:27.837,613] [Z_STACK/LSTN] INFO   : zstackpb Sending Network Info Response
[08:01:27.837,829] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 31:00:71:0E:08:0E:10:00:19:34:57:49:01:00:4B:12:00:20:09:28:FA:8E:03:31:34:57:49:01:00:4B:12:00:38:00:41:00:00:00:00:00:00:00:00:4A:06:08:01:10:00:18:00:50:0D
[08:01:27.837,887] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] sysNwkInfoReadRsp
[08:01:27.837,949] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_RSP
[08:01:27.837,991] [Z_STACK/LSTN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:01:27.838,030] [Z_STACK/LSTN] PKTBODY:                                                          ieeeAddr = 00:12:4B:00:01:49:57:34
[08:01:27.838,065] [Z_STACK/LSTN] PKTBODY:                                                          devState = DEV_ZB_COORD
[08:01:27.838,099] [Z_STACK/LSTN] PKTBODY:                                                          panId = 0x0000C77A (51066)
[08:01:27.838,135] [Z_STACK/LSTN] PKTBODY:                                                          extendedPanId = 00:12:4B:00:01:49:57:34
[08:01:27.838,169] [Z_STACK/LSTN] PKTBODY:                                                          coordAddr = 0x00000000 (0)
[08:01:27.838,205] [Z_STACK/LSTN] PKTBODY:                                                          coordExtAddr = 00:00:00:00:00:00:00:00
[08:01:27.838,239] [Z_STACK/LSTN] PKTBODY:                                                          devTypes :
[08:01:27.838,270] [Z_STACK/LSTN] PKTBODY:                                                            coodinator = 1
[08:01:27.838,304] [Z_STACK/LSTN] PKTBODY:                                                            router = 0
[08:01:27.838,337] [Z_STACK/LSTN] PKTBODY:                                                            enddevice = 0
[08:01:27.838,372] [Z_STACK/LSTN] PKTBODY:                                                          logicalChannel = 0x0000000D (13)
[08:01:27.844,374] [NWK_MGR/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:01:27.844,553] [NWK_MGR/LSTN] MISC1  : NwkInfoReadRsp:
[08:01:27.844,594] [NWK_MGR/LSTN] MISC1  : - nwkaddr:0000
[08:01:27.844,623] [NWK_MGR/LSTN] MISC1  : - ieeeaddr:00124B0001495734
[08:01:27.844,654] [NWK_MGR/LSTN] MISC1  : - devstate:9
[08:01:27.844,681] [NWK_MGR/LSTN] MISC1  : - panid:C77A
[08:01:27.844,707] [NWK_MGR/LSTN] MISC1  : - extendedpanid:00124B0001495734
[08:01:27.844,734] [NWK_MGR/LSTN] MISC1  : - coordaddr:0000
[08:01:27.844,760] [NWK_MGR/LSTN] MISC1  : - coordextaddr:0000000000000000
[08:01:27.844,786] [NWK_MGR/LSTN] MISC1  : - devtypes: Coordinator: 1
[08:01:27.844,812] [NWK_MGR/LSTN] MISC1  : - devtypes: Router: 0
[08:01:27.844,838] [NWK_MGR/LSTN] MISC1  : - logicalchannel:13

[08:01:27.844,958] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] [ucst] 13:00:72:0B:08:0B:10:01:18:0D:20:FA:8E:03:29:34:57:49:01:00:4B:12:00
[08:01:27.845,011] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] NwkZigbeeNwkInfoCnf
[08:01:27.845,058] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_ZIGBEE_NWK_INFO_CNF
[08:01:27.845,099] [NWK_MGR/LSTN] PKTBODY:                                                          status = NWK_UP
[08:01:27.845,135] [NWK_MGR/LSTN] PKTBODY:                                                          nwkChannel = 0x0000000D (13)
[08:01:27.845,170] [NWK_MGR/LSTN] PKTBODY:                                                          panId = 0x0000C77A (51066)
[08:01:27.845,207] [NWK_MGR/LSTN] PKTBODY:                                                          extPanId = 00:12:4B:00:01:49:57:34
[08:01:27.845,559] [NWK_MGR/LSTN] INFO   : ...sent 23 bytes to Client
[08:01:27.845,629] [NWK_MGR/LSTN] INFO   : !Done
[08:01:27.850,649] [Z_STACK/LSTN] INFO   : ...sent 53 bytes to Client
[08:01:27.851,633] [Z_STACK/LSTN] INFO   : !Done
[08:01:27.967,184] [NWK_MGR/LSTN] INFO   : Receive message...
[08:01:27.967,391] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR<<<<<<<<<<<<<<<<<<<<CON010] [read] 02:00:12:0A:08:0A
[08:01:27.967,455] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR<<<<<<<<<<<<<<<<<<<<CON010] NwkZigbeeNwkInfoReq
[08:01:27.967,505] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_ZIGBEE_NWK_INFO_REQ
[08:01:27.967,550] [NWK_MGR/LSTN] MISC1  : NWK_ZIGBEE_NWK_INFO_REQ
[08:01:27.967,579] [NWK_MGR/LSTN] MISC1  : NwkMgr sendSysNwkInfoReadReqAndSetTxPower:
[08:01:27.967,615] [NWK_MGR/LSTN] INFO   : preparing to send 2 bytes, subSys 0x11, cmdId 0x08, pData:
[08:01:27.967,644] [NWK_MGR/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:01:27.967,695] [NWK_MGR/LSTN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 02:00:31:08:08:08
[08:01:27.967,735] [NWK_MGR/LSTN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] sysNwkInfoReadReq
[08:01:27.967,773] [NWK_MGR/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_REQ
[08:01:27.972,632] [Z_STACK/LSTN] INFO   : Receive message...
[08:01:27.972,839] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:8
[08:01:27.972,893] [Z_STACK/LSTN] INFO   : preparing to send 0 bytes, subSys 0x05, cmdId 0x50, pData:
[08:01:27.972,928] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[08:01:27.972,981] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[08:01:27.973,031] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[08:01:27.973,276] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[08:01:27.973,334] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:01:27.973,362] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:01:27.976,300] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 00:25:50
[08:01:27.979,873] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 18:65:50:00:00:09:7A:C7:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D
[08:01:27.981,798] [Z_STACK/READ] INFO   : Received 24 bytes, subSys 0x65, cmdId 0x50
[08:01:27.981,922] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:01:27.981,956] [Z_STACK/READ] INFO   : Client Read: (len 27):
[08:01:27.981,306] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 18:65:50:00:00:09:7A:C7:00:00:34:57:49:01:00:4B:12:00:00:00:00:00:00:00:00:00:0D
[08:01:27.987,345] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:01:27.987,475] [Z_STACK/LSTN] INFO   : zstackpb Sending Network Info Response
[08:01:27.987,674] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 31:00:71:0E:08:0E:10:00:19:34:57:49:01:00:4B:12:00:20:09:28:FA:8E:03:31:34:57:49:01:00:4B:12:00:38:00:41:00:00:00:00:00:00:00:00:4A:06:08:01:10:00:18:00:50:0D
[08:01:27.987,731] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] sysNwkInfoReadRsp
[08:01:27.987,792] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_RSP
[08:01:27.987,833] [Z_STACK/LSTN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[08:01:27.987,871] [Z_STACK/LSTN] PKTBODY:                                                          ieeeAddr = 00:12:4B:00:01:49:57:34
[08:01:27.987,905] [Z_STACK/LSTN] PKTBODY:                                                          devState = DEV_ZB_COORD
[08:01:27.987,939] [Z_STACK/LSTN] PKTBODY:                                                          panId = 0x0000C77A (51066)
[08:01:27.987,976] [Z_STACK/LSTN] PKTBODY:                                                          extendedPanId = 00:12:4B:00:01:49:57:34
[08:01:27.988,010] [Z_STACK/LSTN] PKTBODY:                                                          coordAddr = 0x00000000 (0)
[08:01:27.988,046] [Z_STACK/LSTN] PKTBODY:                                                          coordExtAddr = 00:00:00:00:00:00:00:00
[08:01:27.968,072] [NWK_MGR/LSTN] INFO   : Waiting for synchronous response...
[08:01:27.991,673] [NWK_MGR/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[08:01:27.991,722] [NWK_MGR/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[08:01:27.993,587] [NWK_MGR/READ] INFO   : Received 49 bytes, subSys 0x71, cmdId 0x0E
[08:01:27.993,709] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[08:01:27.993,744] [NWK_MGR/READ] INFO   : Client Read: (len 53):
[08:01:27.988,080] [Z_STACK/LSTN] PKTBODY:                                                          devTypes :
[08:01:27.993,019] [Z_STACK/LSTN] PKTBODY:                                                            coodinator = 1
[08:01:27.993,090] [Z_STACK/LSTN] PKTBODY:                                                            router = 0
[08:01:27.993,125] [Z_STACK/LSTN] PKTBODY:                                                            enddevice = 0
[08:01:27.993,165] [Z_STACK/LSTN] PKTBODY:                                                          logicalChannel = 0x0000000D (13)
[08:01:27.997,554] [NWK_MGR/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[08:01:27.997,736] [NWK_MGR/LSTN] MISC1  : NwkInfoReadRsp:
[08:01:27.997,779] [NWK_MGR/LSTN] MISC1  : - nwkaddr:0000
[08:01:27.997,809] [NWK_MGR/LSTN] MISC1  : - ieeeaddr:00124B0001495734
[08:01:27.997,840] [NWK_MGR/LSTN] MISC1  : - devstate:9
[08:01:27.997,866] [NWK_MGR/LSTN] MISC1  : - panid:C77A
[08:01:27.997,892] [NWK_MGR/LSTN] MISC1  : - extendedpanid:00124B0001495734
[08:01:27.997,919] [NWK_MGR/LSTN] MISC1  : - coordaddr:0000
[08:01:27.997,946] [NWK_MGR/LSTN] MISC1  : - coordextaddr:0000000000000000
[08:01:27.997,973] [NWK_MGR/LSTN] MISC1  : - devtypes: Coordinator: 1
[08:01:27.997,999] [NWK_MGR/LSTN] MISC1  : - devtypes: Router: 0
[08:01:27.998,024] [NWK_MGR/LSTN] MISC1  : - logicalchannel:13

[08:01:27.998,143] [NWK_MGR/LSTN] PKT_HEX: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] [ucst] 13:00:72:0B:08:0B:10:01:18:0D:20:FA:8E:03:29:34:57:49:01:00:4B:12:00
[08:01:27.998,196] [NWK_MGR/LSTN] PKTTYPE: [                           NWK_MGR>>>>>>>>>>>>>>>>>>>>CON010] NwkZigbeeNwkInfoCnf
[08:01:27.998,240] [NWK_MGR/LSTN] PKTBODY:                                                          cmdId = NWK_ZIGBEE_NWK_INFO_CNF
[08:01:27.998,279] [NWK_MGR/LSTN] PKTBODY:                                                          status = NWK_UP
[08:01:27.998,316] [NWK_MGR/LSTN] PKTBODY:                                                          nwkChannel = 0x0000000D (13)
[08:01:27.998,351] [NWK_MGR/LSTN] PKTBODY:                                                          panId = 0x0000C77A (51066)
[08:01:27.998,388] [NWK_MGR/LSTN] PKTBODY:                                                          extPanId = 00:12:4B:00:01:49:57:34
[08:01:27.998,596] [NWK_MGR/LSTN] INFO   : ...sent 23 bytes to Client
[08:01:27.998,655] [NWK_MGR/LSTN] INFO   : !Done
[08:01:28.003,958] [Z_STACK/LSTN] INFO   : ...sent 53 bytes to Client
[08:01:28.006,793] [Z_STACK/LSTN] INFO   : !Done

Summarized the test described above, I was not successful to add device that I had attached well before after proceed the hard Reset. If I programming a new ZNP image into the CC2531 resolves the issue, as I described at beginning this post.

Do you advise me to follow and additional procedures to find the cause of this problem?

Best Regards,

Alex

0 Ryan Brown1 over 2 years ago in reply to Alexander Argollo

TI__Guru**** 202256 points

Hi Alex,

It appears that I was mistaken then and the ZNP does not remove NV memory on a hard reset. Therefore the gateway is out of sync with the ZNP which causes issues when attempting to add devices. I recommend you develop a method of factory resetting the ZNP and reference these relevant E2E posts.

https://e2e.ti.com/f/1/t/958460
https://e2e.ti.com/f/1/t/956527
https://e2e.ti.com/f/1/t/949065

Regards,
Ryan

0 Alexander Argollo over 2 years ago in reply to Ryan Brown1

Genius 3370 points

ok Ryan, I´ll starting to develop it and I´ll let you know. Thanks a lot for your assistance!

YiKai Chen I had success to develop a service procedure to start up gateway after the boot, do you want me share it with you to include this on your blog post.?

0 YiKai Chen over 2 years ago in reply to Alexander Argollo

Guru 735455 points

Alexander Argollo Maybe you can post your procedure in this post so others having similar issue can get answer directly here.

0 Alexander Argollo over 2 years ago in reply to Alexander Argollo

Genius 3370 points

Hi Ryan,

after your last post I have to check on Gateway Zigbee Library to understanding more about the Reset flow between the NODE JS Web APP (zb-gateway.js) and the SOC ZNP device. I have see into nwkmgr.js the function Nwkmgr.prototype.hardSystemReset.

Nwkmgr.prototype.hardSystemReset = function() {
console.log("nwkmgr: hardSystemReset");

//create the message
var msg_buf = nwkmgr_pb.NwkZigbeeSystemResetReq.encode({
cmdId: nwkmgr_pb.nwkMgrCmdId_t.NWK_ZIGBEE_SYSTEM_RESET_REQ,
mode: nwkmgr_pb.nwkResetMode_t.HARD_RESET
});

sendMessage(msg_buf);
};

1. My doubt, on the function Nwkmgr.prototype.hardSystemReset above the SYS_OSAL_NV_WRITE (CMD_ID 0x03) and SYS_RESET was not implemented on protobuf?

2. I have compared the behavior in the ZTOOL of the two ZNP SoC CC2531 and CC1352P1. And see something stranger in the CC2531 ZNP

In the CC2531 after received the SYS_RESET Command not sent the SYS_RESET_RESPONSE (0x4108) and disconnect from the ZTOOL. as you can see into file bellow:


    reset_procedure using CC2531.txt
    Start Time: 03/06/2021 22:48:47

*** WARNING ***
    Expected Z-Stack version (2.7.1) does not match with actual Z-Stack version (2.7.2).  Z-Tool may not work properly.

<TX>10:48:52.79 COM3 SYS_PING (0x2101)

<RX>10:48:52.79 COM3 SYS_PING_RESPONSE (0x6101)
    Capabilities: System, AF, ZDO, SimpleAPI, Util, App, GP, AppConfig (0x779)

<TX>10:48:55.87 COM3 SYS_VERSION (0x2102)

<RX>10:48:55.87 COM3 SYS_VERSION_RESPONSE (0x6102)
    TransportRev: 0x02
    Product: 0x00
    MajorRel: 0x02
    MinorRel: 0x07
    HwRev: 0x02

<TX>10:49:09.4 COM3 SYS_OSAL_NV_WRITE (0x2109)
    Id: 0x0003
    Offset: 0x00
    Len: 0x01
    Value: . (0x03)

<RX>10:49:09.43 COM3 SYS_OSAL_NV_WRITE_SRSP (0x6109)
    Status: SUCCESS (0x0)

<TX>10:49:16.95 COM3 SYS_RESET (0x4100)
    Type: 0x00 (HARD RESET) (0x0)

Maybe the main problem is with CC2531 ZNP. What do you thinking about it?

CC1532P1 - Working very well, sent the SYS_RESET_RESPONSE in response to SYS_RESET, as you can see into file attached bellow:

reset_procedure using CC1352P1.txt

Start Time: 03/06/2021 22:27:42

<TX>10:27:49.29 COM5 SYS_PING (0x2101)

<RX>10:27:49.3 COM5 SYS_PING_RESPONSE (0x6101)
    Capabilities: System, AF, ZDO, Util, GP, AppConfig (0x659)

<TX>10:27:56.15 COM5 SYS_VERSION (0x2102)

<RX>10:27:56.17 COM5 SYS_VERSION_RESPONSE (0x6102)
    TransportRev: 0x02
    Product: 0x00
    MajorRel: 0x02
    MinorRel: 0x07
    HwRev: 0x01

<TX>10:29:03.25 COM5 SYS_OSAL_NV_WRITE (0x2109)
    Id: 0x0003
    Offset: 0x00
    Len: 0x01
    Value: . (0x03)

<RX>10:29:03.26 COM5 SYS_OSAL_NV_WRITE_SRSP (0x6109)
    Status: SUCCESS (0x0)

<TX>10:29:15.09 COM5 SYS_RESET (0x4100)
    Type: 0x00 (HARD RESET) (0x0)

<RX>10:29:16.1 COM5 SYS_RESET_RESPONSE (0x4180)
    Reason: 0x00
    TransportRev: 0x02
    Product: 0x00
    MajorRel: 0x02
    MinorRel: 0x07
    HwRev: 0x01

0 Alexander Argollo over 2 years ago in reply to Alexander Argollo

Genius 3370 points

YiKai Chen .OK, I´ll post here in a new thread!

Ryan Brown1, in additional my last post, I got NV memory information on ZTOOL from CC2531 ZNP after made Hard Reset in the NODEJS WEB APP. As you can see bellow. i think that the NV memory was deleted after HD Reset. Maybe the main problem is the abnormal behavior after received the SYS_RESET as I described yesterday.

Does it make sense what I noticed?

got CC2531 ZNP information after hardreset on NodeJS Web App.txt

Start Time: 04/06/2021 07:56:00

*** WARNING ***
    Expected Z-Stack version (2.7.1) does not match with actual Z-Stack version (2.7.2).  Z-Tool may not work properly.

<RX>07:56:08.65 COM7 SYS_VERSION_RESPONSE (0x6102)
    TransportRev: 0x02
    Product: 0x00
    MajorRel: 0x02
    MinorRel: 0x07
    HwRev: 0x02

<TX>08:00:48.46 COM7 SYS_OSAL_NV_READ (0x2108)
    Id: 0x0003
    Offset: 0x00

<RX>08:00:48.46 COM7 SYS_OSAL_NV_READ_SRSP (0x6108)
    Status: SUCCESS (0x0)
    Len: 0x01
    Value: . (0x00)

<TX>08:01:30.65 COM7 SYS_OSAL_NV_READ (0x2108)
    Id: 0x0087
    Offset: 0x00

<RX>08:01:30.66 COM7 SYS_OSAL_NV_READ_SRSP (0x6108)
    Status: SUCCESS (0x0)
    Len: 0x01
    Value: . (0x00)

<TX>08:02:43.07 COM7 UTIL_GET_DEVICE_INFO (0x2700)

<RX>08:02:43.09 COM7 UTIL_GET_DEVICE_INFO_RESPONSE (0x6700)
    Status: SUCCESS (0x0)
    IEEEAddr: 0x00124B0001495734
    ShortAddress: 0xFFFE
    DeviceType: COORDINATOR, ROUTER, END_DEVICE (0x7)
    DeviceState: DEV_HOLD (0x0)
    NumAssocDevices: 0x00
    AssocDevicesList

<TX>08:02:48.1 COM7 UTIL_GET_NV_INFO (0x2701)

<RX>08:02:48.15 COM7 UTIL_GET_NV_INFO_RESPONSE (0x6701)
    Status: 8 (0x8)
    IEEEAddress: 0x00124B0001495734
    ScanChannels: NONE (0x0)
    PanID: 0x0000
    SecurityLevel: 0x20
    PreConfigKey: ....h+n......... (0x00, 0xFF, 0xFF, 0xFF, 0x68, 0x2B, 0x6E, 0x1F, 0x2E, 0x08, 0x9E, 0xC6, 0xEA, 0x92, 0x8D, 0xAD)

Best Regards,

Alex

0 Ryan Brown1 over 2 years ago in reply to Alexander Argollo

TI__Guru**** 202256 points

Hello Alexander,

The CC1352 ZNP uses a UART interface instead of USB, also it contains a serial bootloader in ROM. I do not know whether the CC2531 ZNP enables the Serial Boot Loader in flash, but this would include a delay before starting the application. Or there could be a disconnect causes by the USB CDC peripheral.

Regards,
Ryan

0 Alexander Argollo over 2 years ago in reply to Ryan Brown1

Genius 3370 points

Ok Ryan, thanks.

I made several tests today with CC2531, I have comparing the Hard Reset via Nodejs Web app and ZTOOL and I checked that Hard Reset is not complete as you told me before. Sorry for my confusion!

What do you think about me deleting my last two post?

Best Regard

Alex

0 Ryan Brown1 over 2 years ago in reply to Alexander Argollo

TI__Guru**** 202256 points

Thanks for the update Alex, I don't believe it is necessary to delete any E2E posts.

Regards,
Ryan

+1 Alexander Argollo over 2 years ago in reply to Ryan Brown1

Genius 3370 points

Thanks a lot Ryan. I´m closing this post!

Regards,

Alex

Other wireless

Other wireless technologies forum

CC2531EM-IOT-HOME-GATEWAY-RD: Zigbee_3_0_Linux_Gateway_1_0_1 Attaching procedure Errors