[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 = [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 ] [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 ] [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<>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<>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<>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<>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<>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<>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<>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<>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<>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 ] [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