LP-CC2652RB: ZigBee gateway not able to start servers

vikas k

Part Number: LP-CC2652RB
Other Parts Discussed in Thread: CC2652RB

Hi,

I am using Zigbee Linux Gateway 3.0 application provided by TI for my gateway project. In the gateway host is IMX8 and ZNP is CC2652RB.

For host the Imx8 mini evaluation board (https://www.nxp.com/docs/en/user-guide/IMX8MMEVKBHUG.pdf)

ZNP is CC2652RB-LP (https://www.ti.com/tool/LP-CC2652RB )

The boards are connected through the expansion headers.DIO2 act as RxD and DIO3 acts as TxD.

The ZNP board is programmed with sample ZNP application provided in simplelink_cc13x2_26x2_sdk_4_40_04_04.

ZIGBEE-LINUX-SENSOR-TO-CLOUD is cross compiled for IMX8.

But after running the zigbeeHAgw script on IMX8 mini the servers are not up.

in the NpiLnxLog i could see [Mon May 24 14:39:28 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000 .Please let me know what is the cause of this error.

Attached the NpiLnxLog and zigbeeHAgw script log for your reference.

I tried resetting the ZNP while running the script .That did not help .

Fullscreen TIGatewayIMX8Log.txt Download

root@arm:/home/Precompiled/servers# ./zigbeeHAgw 
Platform type selected automatically as bbb.
To override this selection, please stop this script, and then run it again,
specifying the desired platform type at the command line:
  ./zigbeeHAgw [help | bbb | x86 ]

running ./zigbeeHAgw on an ARM
done processing arguments, board type bbb, target arm
NPI                 is 'NPI_lnx_arm_server'
Zstack linux server is 'ZLSZNP_arm'
gateway server      is 'GATEWAY_SRVR_arm'
network manager     is 'NWKMGR_SRVR_arm'
OTA server        is 'OTA_SRVR_arm'
Starting the ZigBee gateway subsystem
making sure there are no lingering servers...
there are 0 NPI servers
there are 0 ZLS servers
there are 0 GATEWAY servers
there are 0 NWKMGR servers
there are 0 OTA servers
(total 0)
done
===================================================
starting NPI, cmd ' ./NPI_lnx_arm_server NPI_Gateway.cfg -v 0xFFFFFFFF debugAll ' on Mon 24 May 2021 02:39:26 PM UTC
[14:39:26.349,064] [NPISRVR/MAIN] UNMSKBL: 
[14:39:26.349,235] [NPISRVR/MAIN] UNMSKBL:  ************************************************
[14:39:26.349,248] [NPISRVR/MAIN] UNMSKBL:  *  NPI Server v1.0.2d                          *
[14:39:26.349,258] [NPISRVR/MAIN] UNMSKBL:  ************************************************
[14:39:26.349,268] [NPISRVR/MAIN] UNMSKBL: 
gpioCfg                                 0x42b460
gpioCfg[0]                              0x16fb8630
gpioCfg[0].gpio                         0x16fb8650
gpioCfg[0].levelshifter                 0x16fb87d1
gpioCfg[1]                              0x16fb8638
gpioCfg[1].gpio                         0x16fb8960
gpioCfg[1].levelshifter                 0x16fb8ae1
gpioCfg[2]                              0x16fb8640
gpioCfg[2].gpio                         0x16fb8c70
gpioCfg[2].levelshifter                 0x16fb8df1
------------------------------------------------------
Serial Config Parsing:
-       Section:        TRACE
-       Key:            TRACE_LAYER_NAME_CHAR_COUNT
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found section [SPI]tes
Startup phase 1 completed successfully, server started (NPI_PID=6471) on Mon 24 May 2021 02:39:26 PM UTC
Found section [LOG]
------------------------------------------------------
Serial Config Parsing:
-       Section:        TRACE
-       Key:            TRACE_ARROW_CHAR_COUNT
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found section [SPI]tes
Found section [LOG]tes
------------------------------------------------------
Serial Config Parsing:
-       Section:        DEVICE
-       Key:            deviceKey
Found section [PORT]es
Found section [DEVICE]
Found wanted section!
Line to process deviceKey=0 ; UART (strlen=18)
Found key       'deviceKey' in  'deviceKey=0 ; UART'
Found value '0 '
Found value2 '0 '
[14:39:26.350,555] [NPISRVR/MAIN] INFO   : deviceKey = 0  (0 )
------------------------------------------------------
Serial Config Parsing:
-       Section:        DEVICE
-       Key:            devPath
Found section [PORT]es
Found section [DEVICE]
Found wanted section!
Line to process deviceKey=0 ; UART (strlen=18)
Line to process #deviceKey=1 ; SPI (strlen=18)
Line to process #deviceKey=2 ; I2C (strlen=18)
Line to process  (strlen=0)
Found line < 128===================================================
Line to process #devPath="/dev/ttyUSB2"; (strlen=24)
Line to process #devPath="/dev/ttyO4" ; UART/CDC (strlen=32)
Line to process devPath="/dev/ttymxc2" ; USART3 (strlen=31)
Found key       'devPath' in    'devPath="/dev/ttymxc2" ; USART3'
Found value '/dev/ttymxc2'
Found value2 '/dev/ttymxc2'
[14:39:26.350,819] [NPISRVR/MAIN] INFO   : 'devPath' specified in the config file is overriden by the soc_device_path command line argument
[14:39:26.350,831] [NPISRVR/MAIN] INFO   : devPath = '/dev/ttymxc2'
------------------------------------------------------
Serial Config Parsing:
-       Section:        LOG
-       Key:            log
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found section [SPI]tes
Found section [LOG]tes
Found wanted section!
Line to process log="./NpiLnxLog.txt" ; file to log all event/error (strlen=51)
Found key       'log' in        'log="./NpiLnxLog.txt" ; file to log all event/error'
Found value './NpiLnxLog.txt'
Found value2 './NpiLnxLog.txt'
[14:39:26.351,205] [NPISRVR/MAIN] INFO   : logPath = './NpiLnxLog.txt'
------------------------------------------------------
Serial Config Parsing:
-       Section:        UART
-       Key:            speed
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found wanted section!
Line to process speed=115200 ; speed (strlen=20)
Found key       'speed' in      'speed=115200 ; speed'
Found value '115200 '
Found value2 '115200 '
[UART] Opening device /dev/ttymxc2
[UART] Install IO signal handler 
[UART] Baud rate set to 115200 (0x001002)
[UART] c_cflag set to 0x0018B2
------------------------------------------------------
Serial Config Parsing:
-       Section:        UART
-       Key:            flowcontrol
Found line < 12starting ZLSZNP, cmd ' ./ZLSZNP_arm 127.0.0.1:2533 config.ini -v 0xFFFFFFFF ' on Mon 24 May 2021 02:39:27 PM UTC
[UART] Wait for mutex in rx entry:
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found wanted section!
Line to process speed=115200 ; speed (strlen=20)
Line to process flowcontrol=0 ; 1=enabled 0=disable (strlen=35)
Found key       'flowcontrol' in        'flowcontrol=0 ; 1=enabled 0=disable'
Found value '0 '
Found value2 '0 '
------------------------------------------------------
Serial Config Parsing:
-       Section:        PORT
-       Key:            port
Found section [PORT]es
Found wanted section!
Line to process port=2533 (strlen=9)
Found key       'port' in       'port=2533'
Found value '2533'
Found value2 '2533'
... freeing memory (ret 0)
[14:39:26.352,688] [NPISRVR/MAIN] INFO   : Port: 2533
[14:39:26.353,686] [NPISRVR/MAIN] INFO   : Following IP addresses are available:
[14:39:26.353,897] [NPISRVR/MAIN] INFO   :  IPv4: interface: lo  IP Address 127.0.0.1
[14:39:26.353,910] [NPISRVR/MAIN] INFO   :  IPv6: interface: lo  IP Address ::1
[14:39:26.353,922] [NPISRVR/MAIN] INFO   : The socket will listen on the following IP addresses:
[14:39:26.353,934] [NPISRVR/MAIN] INFO   :   IPv4: 0.0.0.0
[14:39:26.353,943] [NPISRVR/MAIN] INFO   :   IPv6: ::
[14:39:26.353,953] [NPISRVR/MAIN] INFO   : 0.0.0.0 means it will listen to all available IP address
[14:39:26.354,024] [NPISRVR/MAIN] INFO   : waiting for first connection on #3...
[14:39:28.023,071] [Z_STACK/MAIN] MISC1  : Port: 2533

[14:39:28.023,661] [NPISRVR/MAIN] INFO   : Connected to #5.(127.0.0.1 / ::)
Receive message...
[14:39:28.024,227] [NPISRVR/MAIN] PKT_HEX: New incoming connection from client Z_STACK (connection # 5)
[<-- 000:00:00.024248 (+1621867168. 24248)] 08 bytes, subSys 0x5F, cmdId 0x00, pData:    0x02 0x5A 0x5F 0x53 0x54 0x41 0x43 0x4B
!Done
Receive message...
[<-- 000:00:00.024311 (+0.    63)] 02 bytes, subSys 0x25, cmdId 0x3E, pData:    0xFF 0xFF
NPI SREQ:  (len 5) 0x02 0x25 0x3E 0xFF 0xFF
[<-- 000:00:00.024327 (+0.    16)] [UART] write 7 bytes to 4
[14:39:28.024,347] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 02:25:3E:FF:FF
[14:39:28.023,259] [Z_STACK/MAIN] MISC1  : IP addresses for 127.0.0.1:

[14:39:28.023,279] [Z_STACK/MAIN] MISC1  :   IPv4: 127.0.0.1
[14:39:28.023,291] [Z_STACK/MAIN] MISC1  : Trying to connect...
[14:39:28.023,602] [Z_STACK/MAIN] MISC1  : Connected.
[14:39:28.023,827] [Z_STACK/MAIN] UNMSKBL: 
[14:39:28.023,845] [Z_STACK/MAIN] UNMSKBL:  ************************************************
[14:39:28.023,856] [Z_STACK/MAIN] UNMSKBL:  *  ZStack Server for ZNP v1.0.2d               *
[14:39:28.023,867] [Z_STACK/MAIN] UNMSKBL:  ************************************************
[14:39:28.023,877] [Z_STACK/MAIN] UNMSKBL: 
[14:39:28.023,893] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:39:28.023,928] [Z_STACK/MAIN] INFO   : trying to send 8 bytes, subSys 0x1F, cmdId 0x00
[14:39:28.023,971] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [AREQ] 08:5F:00:02:5A:5F:53:54:41:43:4B
[14:39:28.024,007] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [AREQ] 08:5F:00:02:5A:5F:53:54:41:43:4B
[14:39:28.024,183] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:3e, len::2
[14:39:28.024,201] [Z_STACK/MAIN] INFO   : preparing to send 2 bytes, subSys 0x05, cmdId 0x3E, pData:
[14:39:28.024,213] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:28.024,236] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 02:25:3E:FF:FF
[14:39:28.024,258] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 02:25:3E:FF:FF
[14:39:28.024,312] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:28.024,325] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:28.024,336] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:30.024,417] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:30.024,476] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:30.024,489] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:30.024,505] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:30.024,517] [Z_STACK/MAIN] INFO   : zstackpb config: defaultChannelList:2000, configPANID:ffff, deviceType:0
[14:39:30.024,530] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:9, len::1
[14:39:30.024,545] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x09, pData:
[14:39:30.024,557] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:30.024,585] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:09:00
[14:39:30.024,611] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:09:00
[14:39:30.024,755] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:30.024,774] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:30.024,785] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:32.024,860] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:32.024,923] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:32.024,937] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:32.024,952] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:32.024,966] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:6, len::1
[14:39:32.024,980] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x06, pData:
[14:39:32.024,992] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:32.025,021] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:06:00
[14:39:32.025,045] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:06:00
[14:39:32.025,162] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:32.025,181] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:32.025,193] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[<-- 000:00:00.024398 (+0.    71)] [UART] result: 7
[<-- 000:00:00.024404 (+0.     6)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:06.024720 (+6.   316)] 01 bytes, subSys 0x2F, cmdId 0x09, pData:    0x00
NPI SREQ:  (len 4) 0x01 0x2F 0x09 0x00
[<-- 000:00:06.024737 (+0.    17)] [UART] write 6 bytes to 4
[14:39:34.024,760] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:09:00
[14:39:34.025,256] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:34.025,290] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:34.025,303] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:34.025,316] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:34.025,327] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:2, len::1
[14:39:34.025,341] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x02, pData:
[14:39:34.025,353] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:34.025,379] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:02:08
[14:39:34.025,403] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:02:08
[14:39:34.025,540] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:34.025,558] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:34.025,570] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:36.025,646] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:36.025,715] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:36.025,728] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:36.025,744] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:36.025,760] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:8, len::5
[14:39:36.025,775] [Z_STACK/MAIN] INFO   : preparing to send 5 bytes, subSys 0x0F, cmdId 0x08, pData:
[14:39:36.025,787] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:36.025,820] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:00:00:00:00:00
[14:39:36.025,849] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:00:00:00:00:00
[14:39:36.025,986] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:36.026,006] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:36.026,018] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:38.026,089] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:38.026,150] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:38.026,163] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:38.026,178] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:38.026,191] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:8, len::5
[14:39:38.026,207] [Z_STACK/MAIN] INFO   : preparing to send 5 bytes, subSys 0x0F, cmdId 0x08, pData:
[14:39:38.026,218] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:38.026,250] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:01:00:20:00:00
[14:39:38.026,278] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:01:00:20:00:00
[14:39:38.026,412] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:38.026,432] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:38.026,443] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[<-- 000:00:06.024837 (+0.   100)] [UART] result: 6
[<-- 000:00:06.024846 (+0.     9)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:12.025161 (+6.   315)] 01 bytes, subSys 0x2F, cmdId 0x06, pData:    0x00
NPI SREQ:  (len 4) 0x01 0x2F 0x06 0x00
[<-- 000:00:12.025176 (+0.    15)] [UART] write 6 bytes to 4
[14:39:40.025,198] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:06:00
[14:39:40.026,504] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:40.026,538] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:40.026,551] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:40.026,563] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:40.026,577] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:1, cmdID:9, len::6
[14:39:40.026,592] [Z_STACK/MAIN] INFO   : preparing to send 6 bytes, subSys 0x01, cmdId 0x09, pData:
[14:39:40.026,606] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:40.026,638] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 06:21:09:83:00:00:02:FF:FF
[14:39:40.026,674] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 06:21:09:83:00:00:02:FF:FF
[14:39:40.026,802] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:40.026,820] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:40.026,832] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:42.026,908] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:42.026,971] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:42.026,984] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:42.026,999] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:42.027,016] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:1, cmdID:9, len::5
[14:39:42.027,030] [Z_STACK/MAIN] INFO   : preparing to send 5 bytes, subSys 0x01, cmdId 0x09, pData:
[14:39:42.027,042] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:42.027,075] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:21:09:87:00:00:01:00
[14:39:42.027,105] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:21:09:87:00:00:01:00
[14:39:42.027,248] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:42.027,265] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:42.027,276] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:44.027,346] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:44.027,411] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:44.027,425] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:44.027,441] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:44.027,458] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:1, cmdID:15, len::7
[14:39:44.027,472] [Z_STACK/MAIN] INFO   : preparing to send 7 bytes, subSys 0x01, cmdId 0x15, pData:
[14:39:44.027,484] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:44.027,519] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 07:21:15:96:00:C4:64:00:00:00
[14:39:44.027,551] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 07:21:15:96:00:C4:64:00:00:00
[14:39:44.027,689] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:44.027,710] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:44.027,722] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[<-- 000:00:12.025269 (+0.    93)] [UART] result: 6
[<-- 000:00:12.025276 (+0.     7)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:18.025586 (+6.   310)] 01 bytes, subSys 0x2F, cmdId 0x02, pData:    0x08
NPI SREQ:  (len 4) 0x01 0x2F 0x02 0x08
[<-- 000:00:18.025601 (+0.    15)] [UART] write 6 bytes to 4
[14:39:46.025,622] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:02:08
[14:39:46.027,784] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:46.027,818] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:46.027,830] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:46.027,843] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:46.027,857] [Z_STACK/MAIN] INFO   : Port: 2536
[14:39:46.028,229] [Z_STACK/MAIN] INFO   : Following IP addresses are available:

[14:39:46.028,452] [Z_STACK/MAIN] INFO   :  IPv4: interface: lo  IP Address 127.0.0.1
[14:39:46.028,473] [Z_STACK/MAIN] INFO   :  IPv6: interface: lo  IP Address ::1
[14:39:46.028,490] [Z_STACK/MAIN] INFO   : The socket will listen on the following IP addresses:

[14:39:46.028,504] [Z_STACK/MAIN] INFO   :   IPv4: 0.0.0.0
[14:39:46.028,515] [Z_STACK/MAIN] INFO   :   IPv6: ::
[14:39:46.028,525] [Z_STACK/MAIN] INFO   : 0.0.0.0 means it will listen to all available IP address

[14:39:46.028,578] [Z_STACK/MAIN] MISC1  : waiting for first connection on #4...
[14:39:46.028,766] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:5, len::1
[14:39:46.028,787] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x05, pData:
[14:39:46.028,800] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:46.028,827] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:05:04
[14:39:46.028,852] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:05:04
[14:39:46.029,032] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:39:46.029,052] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:46.029,064] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
Startup phase 2 completed successfully, server started (ZLSZNP_PID=6477) on Mon 24 May 2021 02:39:46 PM UTC
===================================================
starting NETWORK_MGR, cmd ' ./NWKMGR_SRVR_arm 127.0.0.1:2536 -v 0xFFFFFFFF ' on Mon 24 May 2021 02:39:46 PM UTC
[14:39:46.042,744] [NWK_MGR/MAIN] INFO   :  there are 2 args
[14:39:46.042,934] [NWK_MGR/MAIN] INFO   :  argv[0] = ./NWKMGR_SRVR_arm
[14:39:46.042,945] [NWK_MGR/MAIN] INFO   :  argv[1] = 127.0.0.1:2536
[14:39:46.042,981] [NWK_MGR/MAIN] MISC1  : Port: 2536

[14:39:46.043,008] [NWK_MGR/MAIN] MISC1  : IP addresses for 127.0.0.1:

[14:39:46.043,022] [NWK_MGR/MAIN] MISC1  :   IPv4: 127.0.0.1
[14:39:46.043,031] [NWK_MGR/MAIN] MISC1  : Trying to connect...
[14:39:46.043,259] [NWK_MGR/MAIN] MISC1  : Connected.
[14:39:46.043,331] [Z_STACK/LSTN] MISC1  : Connected to #5.(127.0.0.1 / ::)
[14:39:46.043,360] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb - connected: 5
[14:39:46.043,370] [Z_STACK/LSTN] CONNECT: Connected to new client, connection # 5
[14:39:46.043,474] [NWK_MGR/MAIN] UNMSKBL: 
[14:39:46.043,490] [NWK_MGR/MAIN] UNMSKBL:  ************************************************
[14:39:46.043,499] [NWK_MGR/MAIN] UNMSKBL:  *  Network Manager Server v1.0.2d              *
[14:39:46.043,509] [NWK_MGR/MAIN] UNMSKBL:  ************************************************
[14:39:46.043,522] [NWK_MGR/MAIN] UNMSKBL: 
[14:39:46.043,537] [NWK_MGR/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:39:46.043,565] [NWK_MGR/MAIN] INFO   : trying to send 8 bytes, subSys 0x1F, cmdId 0x00
[14:39:46.043,715] [Z_STACK/LSTN] INFO   : Receive message...
[14:39:46.043,747] [Z_STACK/LSTN] CONNECT: Client at connection # 5 identified itself as NWK_MGR
[14:39:46.043,762] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:5f, cmdId:0
[14:39:46.043,772] [Z_STACK/LSTN] INFO   : !Done
[14:39:46.045,494] [Z_STACK/LSTN] INFO   : Receive message...
[14:39:46.045,517] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:14
[14:39:46.045,903] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:14:10:00
[14:39:46.045,926] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[14:39:46.045,942] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = DEV_ZDO_CBS_REQ
[14:39:46.045,956] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[14:39:46.046,025] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[14:39:46.046,047] [Z_STACK/LSTN] INFO   : !Done
[14:39:46.046,236] [Z_STACK/LSTN] INFO   : Receive message...
[14:39:46.046,255] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:8
[14:39:46.046,268] [Z_STACK/LSTN] INFO   : preparing to send 0 bytes, subSys 0x05, cmdId 0x50, pData:
[14:39:46.046,277] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:46.043,600] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [AREQ] 08:00:5F:00:03:4E:57:4B:5F:4D:47:52
[14:39:46.043,632] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] [AREQ] 08:00:5F:00:03:4E:57:4B:5F:4D:47:52
[14:39:46.043,884] [NWK_MGR/MAIN] MISC1  : NwkMgr: Sending Device ZDO CB Request
[14:39:46.044,561] [NWK_MGR/MAIN] INFO   : preparing to send 90 bytes, subSys 0x11, cmdId 0x14, pData:
[14:39:46.044,574] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:46.044,682] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 5A:00:31:14:08:14:10:01:18:01:20:01:28:01:30:01:38:01:40:01:48:01:50:01:58:01:60:01:68:01:70:01:71
[14:39:46.044,703] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] devZDOCBReq
[14:39:46.044,970] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = DEV_ZDO_CBS_REQ
[14:39:46.044,986] [NWK_MGR/MAIN] PKTBODY:                                                          srcRtgIndCB = 1
[14:39:46.044,999] [NWK_MGR/MAIN] PKTBODY:                                                          concentratorIndCb = 1
[14:39:46.045,014] [NWK_MGR/MAIN] PKTBODY:                                                          nwkDiscCnfCB = 1
[14:39:46.045,027] [NWK_MGR/MAIN] PKTBODY:                                                          beaconNotIndCB = 1
[14:39:46.045,039] [NWK_MGR/MAIN] PKTBODY:                                                          joinCnfCB = 1
[14:39:46.045,052] [NWK_MGR/MAIN] PKTBODY:                                                          leaveCnfCB = 1
[14:39:46.045,067] [NWK_MGR/MAIN] PKTBODY:                                                          leaveIndCB = 1
[14:39:46.045,080] [NWK_MGR/MAIN] PKTBODY:                                                          nwkAddrRsp = 1
[14:39:46.045,093] [NWK_MGR/MAIN] PKTBODY:                                                          ieeeAddrRsp = 1
[14:39:46.045,106] [NWK_MGR/MAIN] PKTBODY:                                                          nodeDescRsp = 1
[14:39:46.045,121] [NWK_MGR/MAIN] PKTBODY:                                                          powerDescRsp = 1
[14:39:46.045,134] [NWK_MGR/MAIN] PKTBODY:                                                          simpleDescRsp = 1
[14:39:46.045,147] [NWK_MGR/MAIN] PKTBODY:                                                          activeEndpointRsp = 1
[14:39:46.045,160] [NWK_MGR/MAIN] PKTBODY:                                                          matchDescRsp = 1
[14:39:46.045,174] [NWK_MGR/MAIN] PKTBODY:                                                          complexDescRsp = 1
[14:39:46.045,187] [NWK_MGR/MAIN] PKTBODY:                                                          userDescRsp = 1
[14:39:46.045,200] [NWK_MGR/MAIN] PKTBODY:                                                          discoveryCacheRsp = 1
[14:39:46.045,215] [NWK_MGR/MAIN] PKTBODY:                                                          userDescCnf = 1
[14:39:46.045,228] [NWK_MGR/MAIN] PKTBODY:                                                          serverDiscoveryRsp = 1
[14:39:46.045,243] [NWK_MGR/MAIN] PKTBODY:                                                          endDeviceTimeoutRsp = 1
[14:39:46.045,258] [NWK_MGR/MAIN] PKTBODY:                                                          bindRsp = 1
[14:39:46.045,271] [NWK_MGR/MAIN] PKTBODY:                                                          endDeviceBindRsp = 1
[14:39:46.045,284] [NWK_MGR/MAIN] PKTBODY:                                                          unbindRsp = 1
[14:39:46.045,297] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtNwkDiscRsp = 1
[14:39:46.045,311] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtLqiRsp = 1
[14:39:46.045,324] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtRtgRsp = 1
[14:39:46.045,337] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtBindRsp = 1
[14:39:46.045,350] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtLeaveRsp = 1
[14:39:46.045,364] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtDirectJoinRsp = 1
[14:39:46.045,377] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtPermitJoinRsp = 1
[14:39:46.045,390] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtNwkUpdateNotify = 1
[14:39:46.045,405] [NWK_MGR/MAIN] PKTBODY:                                                          deviceAnnounce = 1
[14:39:46.045,416] [NWK_MGR/MAIN] PKTBODY:                                                          devStateChange = 1
[14:39:46.045,428] [NWK_MGR/MAIN] PKTBODY:                                                          tcDeviceInd = 1
[14:39:46.045,500] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[14:39:46.045,511] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:46.045,519] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:46.046,024] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[14:39:46.046,048] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:39:46.046,057] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[14:39:46.046,082] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:46.046,102] [NWK_MGR/MAIN] MISC1  : ZDO Callback Register Response Successful
[14:39:46.046,113] [NWK_MGR/MAIN] MISC1  : NwkMgr sendSysNwkInfoReadReqAndSetTxPower:
[14:39:46.046,127] [NWK_MGR/MAIN] INFO   : preparing to send 2 bytes, subSys 0x11, cmdId 0x08, pData:
[14:39:46.046,139] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:46.046,160] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 02:00:31:08:08:08
[14:39:46.046,179] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] sysNwkInfoReadReq
[14:39:46.046,195] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_REQ
[14:39:46.046,239] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[14:39:46.046,249] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:46.046,257] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:48.029,142] [Z_STACK/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:48.029,198] [Z_STACK/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:48.029,211] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:48.029,238] [Z_STACK/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:48.029,267] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[14:39:48.029,309] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[14:39:48.029,433] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[14:39:48.029,451] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:48.029,463] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:39:48.046,338] [NWK_MGR/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:48.046,370] [NWK_MGR/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:39:48.046,382] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:48.046,395] [NWK_MGR/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:39:48.047,754] [NWK_MGR/MAIN] MISC1  : Opened Database 'DbDeviceInfo.csv', 0 records
[14:39:48.048,058] [NWK_MGR/MAIN] MISC1  : Opened Database 'DbEndpoints.csv', 0 records
[14:39:48.048,699] [NWK_MGR/MAIN] ERROR  : Reading Local Network Information Failed
[14:39:48.048,723] [NWK_MGR/MAIN] UNMSKBL: Initialization failed. Quitting now.

Startup phase 3 failed
./zigbeeHAgw: line 623: killall: command not found
waiting for Zstack linux to exit
[14:39:50.029,543] [Z_STACK/LSTN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:50.029,604] [Z_STACK/LSTN] ERROR  : SRSP Cond Wait timed out!
[14:39:50.029,617] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:50.029,657] [Z_STACK/LSTN] ERROR  : apicSendSynchData() failed getting response
[14:39:50.029,670] [Z_STACK/LSTN] INFO   : zstackpb Sending Network Info Response
[14:39:50.029,727] [Z_STACK/LSTN] INFO   : znp_misc osal_nv_read: id:1, len:8
[14:39:50.029,744] [Z_STACK/LSTN] INFO   : preparing to send 3 bytes, subSys 0x01, cmdId 0x08, pData:
[14:39:50.029,756] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:39:50.029,789] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 03:21:08:01:00:00
[14:39:50.029,816] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 03:21:08:01:00:00
[14:39:50.029,950] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[14:39:50.029,970] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[14:39:50.029,982] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[<-- 000:00:18.025695 (+0.    94)] [UART] result: 6
[<-- 000:00:18.025703 (+0.     8)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:24.026007 (+6.   304)] 05 bytes, subSys 0x2F, cmdId 0x08, pData:    0x00 0x00 0x00 0x00 0x00
NPI SREQ:  (len 8) 0x05 0x2F 0x08 0x00 0x00 0x00 0x00 0x00
[<-- 000:00:24.026032 (+0.    25)] [UART] write 10 bytes to 4
[14:39:52.026,059] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:2F:08:00:00:00:00:00
[14:39:52.030,043] [Z_STACK/LSTN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:39:52.030,077] [Z_STACK/LSTN] ERROR  : SRSP Cond Wait timed out!
[14:39:52.030,090] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:39:52.030,102] [Z_STACK/LSTN] ERROR  : apicSendSynchData() failed getting response
[14:39:52.030,459] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 2F:00:71:0E:08:0E:10:00:19:00:00:00:00:00:00:00:00:20:00:28:00:31:00:00:00:00:00:00:00:00:38:00:40
[14:39:52.030,491] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] sysNwkInfoReadRsp
[14:39:52.030,518] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_RSP
[14:39:52.030,537] [Z_STACK/LSTN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[14:39:52.030,555] [Z_STACK/LSTN] PKTBODY:                                                          ieeeAddr = 00:00:00:00:00:00:00:00
[14:39:52.030,571] [Z_STACK/LSTN] PKTBODY:                                                          devState = HOLD
[14:39:52.030,586] [Z_STACK/LSTN] PKTBODY:                                                          panId = 0x00000000 (0)
[14:39:52.030,604] [Z_STACK/LSTN] PKTBODY:                                                          extendedPanId = 00:00:00:00:00:00:00:00
[14:39:52.030,621] [Z_STACK/LSTN] PKTBODY:                                                          coordAddr = 0x00000000 (0)
[14:39:52.030,637] [Z_STACK/LSTN] PKTBODY:                                                          coordExtAddr = 00:00:00:00:00:00:00:00
[14:39:52.030,653] [Z_STACK/LSTN] PKTBODY:                                                          devTypes :
[14:39:52.030,714] [Z_STACK/LSTN] ERROR  : ERROR: signal 11 was trigerred:
[14:39:52.030,732] [Z_STACK/LSTN] ERROR  :   Fault address: 0x840012a8
[14:39:52.030,744] [Z_STACK/LSTN] ERROR  :   Fault reason: address not mapped to object
[14:39:52.031,713] [Z_STACK/LSTN] ERROR  : Stack trace unavailable
[14:39:52.031,741] [Z_STACK/LSTN] ERROR  : Executing original handler...
./zigbeeHAgw: line 638: killall: command not found
waiting for NPI to exit
[<-- 000:00:24.026132 (+0.   100)] [UART] result: 10
[<-- 000:00:24.026139 (+0.     7)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:30.026456 (+6.   317)] 05 bytes, subSys 0x2F, cmdId 0x08, pData:    0x01 0x00 0x20 0x00 0x00
NPI SREQ:  (len 8) 0x05 0x2F 0x08 0x01 0x00 0x20 0x00 0x00
[<-- 000:00:30.026478 (+0.    22)] [UART] write 10 bytes to 4
[14:39:58.026,506] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:2F:08:01:00:20:00:00
[<-- 000:00:30.026578 (+0.   100)] [UART] result: 10
[<-- 000:00:30.026587 (+0.     9)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:36.028162 (+6.  1575)] 06 bytes, subSys 0x21, cmdId 0x09, pData:    0x83 0x00 0x00 0x02 0xFF 0xFF
NPI SREQ:  (len 9) 0x06 0x21 0x09 0x83 0x00 0x00 0x02 0xFF 0xFF
[<-- 000:00:36.028189 (+0.    27)] [UART] write 11 bytes to 4
[14:40:04.028,219] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 06:21:09:83:00:00:02:FF:FF
[<-- 000:00:36.028294 (+0.   105)] [UART] result: 11
[<-- 000:00:36.028303 (+0.     9)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:42.028604 (+6.   301)] 05 bytes, subSys 0x21, cmdId 0x09, pData:    0x87 0x00 0x00 0x01 0x00
NPI SREQ:  (len 8) 0x05 0x21 0x09 0x87 0x00 0x00 0x01 0x00
[<-- 000:00:42.028626 (+0.    22)] [UART] write 10 bytes to 4
[14:40:10.028,654] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:21:09:87:00:00:01:00
[<-- 000:00:42.028725 (+0.    99)] [UART] result: 10
[<-- 000:00:42.028732 (+0.     7)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:45.957994 (+3.929262)] Signal from UART, grabbing mutex
[<-- 000:00:45.958034 (+0.    40)] Signal read handle, owning mutex
[<-- 000:00:45.958082 (+0.    48)] Signal from UART, grabbing mutex
[<-- 000:00:45.958086 (+0.     4)] Signal read handle, owning mutex
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:48.029033 (+2. 70947)] 07 bytes, subSys 0x21, cmdId 0x15, pData:    0x96 0x00 0xC4 0x64 0x00 0x00 0x00
NPI SREQ:  (len 10) 0x07 0x21 0x15 0x96 0x00 0xC4 0x64 0x00 0x00 0x00
[<-- 000:00:48.029061 (+0.    28)] [UART] write 12 bytes to 4
[14:40:16.029,090] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 07:21:15:96:00:C4:64:00:00:00
[<-- 000:00:48.029164 (+0.   103)] [UART] result: 12
[<-- 000:00:48.029171 (+0.     7)] [UART] (synch data) Conditional wait 6 s
[UART] Send synch data timed out
[ERR] SRSP: npi_ipc_errno 0x02040100
!Done
Synchronous Request Timeout...
Receive message...
[<-- 000:00:54.029484 (+6.   313)] 01 bytes, subSys 0x2F, cmdId 0x05, pData:    0x04
NPI SREQ:  (len 4) 0x01 0x2F 0x05 0x04
[<-- 000:00:54.029500 (+0.    16)] [UART] write 6 bytes to 4
[14:40:22.029,523] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:05:04
^Z
[1]+  Stopped                 ./zigbeeHAgw

Fullscreen NpiLnxLog.txt Download

[Mon May 24 14:40:17 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:40:23 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:29 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:35 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:41 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:47 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:53 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:59 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:05 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:11 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:17 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:23 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:29 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:29 202] Removed connection #5. Error: 01030200
[Mon May 24 14:39:13 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:39:19 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:25 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:31 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:37 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:43 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:49 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:55 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:01 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:07 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:13 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:19 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:02 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:39:05 202] Removed connection #5. Error: 01030200
[Mon May 24 14:43:57 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:44:03 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:09 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:15 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:21 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:27 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:33 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:39 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:45 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:51 202] Removed connection #5. Error: 02040100
[Mon May 24 14:44:57 202] Removed connection #5. Error: 02040100
[Mon May 24 14:45:03 202] Removed connection #5. Error: 02040100
[Mon May 24 14:45:09 202] Removed connection #5. Error: 02040100
[Mon May 24 14:45:09 202] Removed connection #5. Error: 01030200
[Mon May 24 14:40:50 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:40:56 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:02 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:08 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:14 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:20 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:26 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:32 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:38 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:44 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:50 202] Removed connection #5. Error: 02040100
[Mon May 24 14:41:56 202] Removed connection #5. Error: 02040100
[Mon May 24 14:42:02 202] Removed connection #5. Error: 02040100
[Mon May 24 14:42:02 202] Removed connection #5. Error: 01030200
[Mon May 24 14:39:01 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:39:07 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:13 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:19 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:25 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:31 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:37 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:43 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:49 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:55 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:01 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:07 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:13 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:13 202] Removed connection #5. Error: 01030200
[Mon May 24 14:39:28 202] Connected to #5.(127.0.0.1 / ::). Error: 00000000
[Mon May 24 14:39:34 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:40 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:46 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:52 202] Removed connection #5. Error: 02040100
[Mon May 24 14:39:58 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:04 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:10 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:16 202] Removed connection #5. Error: 02040100
[Mon May 24 14:40:22 202] Removed connection #5. Error: 02040100

Thanks,

Vikas

over 4 years ago

0 vikas k over 4 years ago

Intellectual 330 points

Precompiled.zipAttached the Precompiled output of IMX8 cross compiltaion.

0 YiKai Chen over 4 years ago in reply to vikas k

Guru 735695 points

Do you build protobuf by yourself for your i.MX8 platform?

0 vikas k over 4 years ago in reply to YiKai Chen

Intellectual 330 points

Yes.I build protobuf for IMX8 by myself.

0 Ryan Brown1 over 4 years ago

TI__Guru**** 219837 points

Hi Vikas,

Please let me know whether either of these previous E2E threads helps with your SRSP timeout or startup failure:

https://e2e.ti.com/f/1/t/938713
https://e2e.ti.com/f/1/t/940644

Regards,
Ryan

0 vikas k over 4 years ago in reply to Ryan Brown1

Intellectual 330 points

Hi Ryan,

I am getting the server response now.But the script fails after sometimes.Attached the log for your reference.

[14:41:19.209,740] [Z_STACK/MAIN] DEBUG : --> status failed: cmdID:15, status: 255
[14:41:19.209,756] [Z_STACK/MAIN] INFO : Port: 2536

[14:41:22.529,447] [Z_STACK/LSTN] ERROR : ERROR: signal 11 was trigerred:
[14:41:22.529,465] [Z_STACK/LSTN] ERROR : Fault address: 0x84000ce8
[14:41:22.529,479] [Z_STACK/LSTN] ERROR : Fault reason: address not mapped to object
[14:41:22.530,091] [Z_STACK/LSTN] ERROR : Stack trace unavailable

[14:41:22.530,687] [NWK_MGR/READ] INFO : Peer closed connection
[14:41:22.530,756] [NWK_MGR/HNDL] INFO : [MUTEX] Mutex for AREQ unlocked
[14:41:22.530,799] [NWK_MGR/HNDL] DEBUG : Server connection was terminated
[14:41:24.515,138] [NWK_MGR/MAIN] INFO : [MUTEX] SRSP Cond Wait timed out!
[14:41:24.515,190] [NWK_MGR/MAIN] ERROR : SRSP Cond Wait timed out!
[14:41:24.515,203] [NWK_MGR/MAIN] INFO : [MUTEX] Unlock SRSP Mutex
[14:41:24.515,218] [NWK_MGR/MAIN] ERROR : apicSendSynchData() failed getting response
[14:41:24.516,573] [NWK_MGR/MAIN] MISC1 : Opened Database 'DbDeviceInfo.csv', 0 records
[14:41:24.516,849] [NWK_MGR/MAIN] MISC1 : Opened Database 'DbEndpoints.csv', 0 records
[14:41:24.517,480] [NWK_MGR/MAIN] ERROR : Reading Local Network Information Failed
[14:41:24.517,504] [NWK_MGR/MAIN] UNMSKBL: Initialization failed. Quitting now.

Startup phase 3 failed
./zigbeeHAgw: line 623: killall: command not found
waiting for Zstack linux to exit
./zigbeeHAgw: line 638: killall: command not found
waiting for NPI to exit

Please let me know if you can help me with these failures.

Thanks,

Vikas

Fullscreen GatewayHostLog.txt Download

root@arm:/home/ubuntu# cd /home/Precompiled/servers/
root@arm:/home/Precompiled/servers# ls
config.ini          GATEWAY_SRVR_arm    NWKMGR_SRVR_arm     zigbeeHAgw
DbDeviceInfo.csv    NPI_Gateway.cfg     OTA_SRVR_arm        ZLSZNP_arm
DbEndpoints.csv     NPI_lnx_arm_server  sample_app_ota.cfg
gateway_config.ini  NpiLnxLog.txt       start_application
gateway_config.tlg  nwkmgr_config.ini   track_servers
root@arm:/home/Precompiled/servers# ./zigbeeHAgw 
Platform type selected automatically as bbb.
To override this selection, please stop this script, and then run it again,
specifying the desired platform type at the command line:
  ./zigbeeHAgw [help | bbb | x86 ]

running ./zigbeeHAgw on an ARM
done processing arguments, board type bbb, target arm
NPI                 is 'NPI_lnx_arm_server'
Zstack linux server is 'ZLSZNP_arm'
gateway server      is 'GATEWAY_SRVR_arm'
network manager     is 'NWKMGR_SRVR_arm'
OTA server        is 'OTA_SRVR_arm'
Starting the ZigBee gateway subsystem
making sure there are no lingering servers...
there are 0 NPI servers
there are 0 ZLS servers
there are 0 GATEWAY servers
there are 0 NWKMGR servers
there are 0 OTA servers
(total 0)
done
===================================================
starting NPI, cmd ' ./NPI_lnx_arm_server NPI_Gateway.cfg -v 0xFFFFFFFF debugAll ' on Mon 24 May 2021 02:41:17 PM UTC
[14:41:17.499,259] [NPISRVR/MAIN] UNMSKBL: 
[14:41:17.499,473] [NPISRVR/MAIN] UNMSKBL:  ************************************************
[14:41:17.499,486] [NPISRVR/MAIN] UNMSKBL:  *  NPI Server v1.0.2d                          *
[14:41:17.499,496] [NPISRVR/MAIN] UNMSKBL:  ************************************************
[14:41:17.499,508] [NPISRVR/MAIN] UNMSKBL: 
gpioCfg                                 0x42b460
gpioCfg[0]                              0x24741630
gpioCfg[0].gpio                         0x24741650
gpioCfg[0].levelshifter                 0x247417d1
gpioCfg[1]                              0x24741638
gpioCfg[1].gpio                         0x24741960
gpioCfg[1].levelshifter                 0x24741ae1
gpioCfg[2]                              0x24741640
gpioCfg[2].gpio                         0x24741c70
gpioCfg[2].levelshifter                 0x24741df1
------------------------------------------------------
Serial Config Parsing:
-       Section:        TRACE
-       Key:            TRACE_LAYER_NAME_CHAR_COUNT
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Startup phase 1 completed successfully, server started (NPI_PID=6529) on Mon 24 May 2021 02:41:17 PM UTC
Found section [SPI]tes
Found section [LOG]tes
------------------------------------------------------
Serial Config Parsing:
-       Section:        TRACE
-       Key:            TRACE_ARROW_CHAR_COUNT
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found section [SPI]tes
Found section [LOG]tes
------------------------------------------------------
Serial Config Parsing:
-       Section:        DEVICE
-       Key:            deviceKey
Found section [PORT]es
Found section [DEVICE]
Found wanted section!
Line to process deviceKey=0 ; UART (strlen=18)
Found key       'deviceKey' in  'deviceKey=0 ; UART'
Found value '0 '
Found value2 '0 '
[14:41:17.500,798] [NPISRVR/MAIN] INFO   : deviceKey = 0  (0 )
------------------------------------------------------
Serial Config Parsing:
-       Section:        DEVICE
-       Key:            devPath
Found section [PORT]es
Found section [DEVICE]
Found wanted section!
Line to process deviceKey=0 ; UART (strlen=18)
Line to process #deviceKey=1 ; SPI (strlen=18)
Li===================================================
ne to process #deviceKey=2 ; I2C (strlen=18)
Line to process  (strlen=0)
Line to process #devPath="/dev/ttyUSB2"; (strlen=24)
Line to process #devPath="/dev/ttyO4" ; UART/CDC (strlen=32)
Line to process devPath="/dev/ttymxc2" ; USART3 (strlen=31)
Found key       'devPath' in    'devPath="/dev/ttymxc2" ; USART3'
Found value '/dev/ttymxc2'
Found value2 '/dev/ttymxc2'
[14:41:17.500,991] [NPISRVR/MAIN] INFO   : 'devPath' specified in the config file is overriden by the soc_device_path command line argument
[14:41:17.501,000] [NPISRVR/MAIN] INFO   : devPath = '/dev/ttymxc2'
------------------------------------------------------
Serial Config Parsing:
-       Section:        LOG
-       Key:            log
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found section [SPI]tes
Found section [LOG]tes
Found wanted section!
Line to process log="./NpiLnxLog.txt" ; file to log all event/error (strlen=51)
Found key       'log' in        'log="./NpiLnxLog.txt" ; file to log all event/error'
Found value './NpiLnxLog.txt'
Found value2 './NpiLnxLog.txt'
[14:41:17.501,251] [NPISRVR/MAIN] INFO   : logPath = './NpiLnxLog.txt'
------------------------------------------------------
Serial Config Parsing:
-       Section:        UART
-       Key:            speed
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found wanted section!
Line to process speed=115200 ; speed (strlen=20)
Found key       'speed' in      'speed=115200 ; speed'
Found value '115200 '
Found value2 '115200 '
[UART] Opening device /dev/ttymxc2
[UART] Install IO signal handler 
[UART] Baud rate set to 115200 (0x001002)
[UART] c_cflag set to 0x0018B2
------------------------------------------------------
Serial Config Parsing:
-       Section:        UART
-       Key:            flowcontrol
Found line < 128 bstarting ZLSZNP, cmd ' ./ZLSZNP_arm 127.0.0.1:2533 config.ini -v 0xFFFFFFFF ' on Mon 24 May 2021 02:41:18 PM UTC
[UART] Wait for mutex in rx entry:
Found section [PORT]es
Found section [DEVICE]
Found section [GPIO_SRDY.GPIO]
Found section [GPIO_SRDY.LEVEL_SHIFTER]
Found section [GPIO_MRDY.GPIO]
Found section [GPIO_MRDY.LEVEL_SHIFTER]
Found section [GPIO_RESET.GPIO]
Found section [GPIO_RESET.LEVEL_SHIFTER]
Found section [UART]es
Found wanted section!
Line to process speed=115200 ; speed (strlen=20)
Line to process flowcontrol=0 ; 1=enabled 0=disable (strlen=35)
Found key       'flowcontrol' in        'flowcontrol=0 ; 1=enabled 0=disable'
Found value '0 '
Found value2 '0 '
------------------------------------------------------
Serial Config Parsing:
-       Section:        PORT
-       Key:            port
Found section [PORT]es
Found wanted section!
Line to process port=2533 (strlen=9)
Found key       'port' in       'port=2533'
Found value '2533'
Found value2 '2533'
... freeing memory (ret 0)
[14:41:17.502,433] [NPISRVR/MAIN] INFO   : Port: 2533
[14:41:17.502,786] [NPISRVR/MAIN] INFO   : Following IP addresses are available:
[14:41:17.502,983] [NPISRVR/MAIN] INFO   :  IPv4: interface: lo  IP Address 127.0.0.1
[14:41:17.502,996] [NPISRVR/MAIN] INFO   :  IPv6: interface: lo  IP Address ::1
[14:41:17.503,009] [NPISRVR/MAIN] INFO   : The socket will listen on the following IP addresses:
[14:41:17.503,019] [NPISRVR/MAIN] INFO   :   IPv4: 0.0.0.0
[14:41:17.503,030] [NPISRVR/MAIN] INFO   :   IPv6: ::
[14:41:17.503,040] [NPISRVR/MAIN] INFO   : 0.0.0.0 means it will listen to all available IP address
[14:41:17.503,110] [NPISRVR/MAIN] INFO   : waiting for first connection on #3...
[<-- 000:00:02.092293 (+1621867279. 92293)] Signal from UART, grabbing mutex
[<-- 000:00:02.092332 (+0.    39)] Signal read handle, owning mutex
[<-- 000:00:02.093189 (+0.   857)] Signal from UART, grabbing mutex
[<-- 000:00:02.093198 (+0.     9)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x41, Cmd ID: 0x80, length: 6
[14:41:19.093,269] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 06:41:80:00:02:00:02:07:01
[14:41:19.174,206] [Z_STACK/MAIN] MISC1  : Port: 2533

Startup phase 2 completed successfully, server started (ZLSZNP_PID=6536) on Mon 24 May 2021 02:41:19 PM UTC
[UART] npi_procframe signal areq callback thread (invoked by read loop) 
[14:41:19.174,794] [NPISRVR/MAIN] INFO   : Connected to #5.(127.0.0.1 / ::)
Receive message...
[14:41:19.175,377] [NPISRVR/MAIN] PKT_HEX: New incoming connection from client Z_STACK (connection # 5)
[<-- 000:00:00.175398 (+0. 82200)] 08 bytes, subSys 0x5F, cmdId 0x00, pData:    0x02 0x5A 0x5F 0x53 0x54 0x41 0x43 0x4B
!Done
Receive message...
[<-- 000:00:00.175466 (+0.    68)] 02 bytes, subSys 0x25, cmdId 0x3E, pData:    0xFF 0xFF
NPI SREQ:  (len 5) 0x02 0x25 0x3E 0xFF 0xFF
[<-- 000:00:00.175482 (+0.    16)] [UART] write 7 bytes to 4
[14:41:19.175,502] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 02:25:3E:FF:FF
[<-- 000:00:00.175556 (+0.    74)] [UART] result: 7
[<-- 000:00:00.175583 (+0.    27)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.178113 (+0.  2530)] Signal from UART, grabbing mutex
[<-- 000:00:00.178130 (+0.    17)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x65, Cmd ID: 0x3E, length: 1
[14:41:19.178,175] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:65:3E:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x65 0x3E 0x00
[--> 000:00:00.178212 (+1621867279.178212)] 01 bytes, subSys 0x65, cmdId 0x3E, pData:    0x00
[14:41:19.178,232] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:65:3E:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.178601 (+0.   471)] 01 bytes, subSys 0x2F, cmdId 0x09, pData:    0x00
NPI SREQ:  (len 4) 0x01 0x2F 0x09 0x00
[<-- 000:00:00.178613 (+0.    12)] [UART] write 6 bytes to 4
[14:41:19.178,625] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:09:00
[<-- 000:00:00.178657 (+0.    44)] [UART] result: 6
[<-- 000:00:00.178661 (+0.     4)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.181078 (+0.  2417)] Signal from UART, grabbing mutex
[<-- 000:00:00.181087 (+0.     9)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x6f, Cmd ID: 0x09, length: 1
[14:41:19.181,110] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:6F:09:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x6F 0x09 0x00
[--> 000:00:00.181135 (+0.  2923)] 01 bytes, subSys 0x6F, cmdId 0x09, pData:    0x00
[14:41:19.181,149] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:6F:09:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.181363 (+0.   276)] 01 bytes, subSys 0x2F, cmdId 0x06, pData:    0x00
NPI SREQ:  (len 4) 0x01 0x2F 0x06 0x00
[<-- 000:00:00.181372 (+0.     9)] [UART] write 6 bytes to 4
[14:41:19.181,383] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:06:00
[<-- 000:00:00.181411 (+0.    39)] [UART] result: 6
[<-- 000:00:00.181414 (+0.     3)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.183821 (+0.  2407)] Signal from UART, grabbing mutex
[<-- 000:00:00.183829 (+0.     8)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x6f, Cmd ID: 0x06, length: 1
[14:41:19.183,848] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:6F:06:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x6F 0x06 0x00
[--> 000:00:00.183879 (+0.  2744)] 01 bytes, subSys 0x6F, cmdId 0x06, pData:    0x00
[14:41:19.183,892] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:6F:06:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.184089 (+0.   260)] 01 bytes, subSys 0x2F, cmdId 0x02, pData:    0x08
NPI SREQ:  (len 4) 0x01 0x2F 0x02 0x08
[<-- 000:00:00.184097 (+0.     8)] [UART] write 6 bytes to 4
[14:41:19.184,108] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:02:08
[<-- 000:00:00.184133 (+0.    36)] [UART] result: 6
[<-- 000:00:00.184137 (+0.     4)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.187911 (+0.  3774)] Signal from UART, grabbing mutex
[<-- 000:00:00.187918 (+0.     7)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x6f, Cmd ID: 0x02, length: 1
[14:41:19.187,936] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:6F:02:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x6F 0x02 0x00
[--> 000:00:00.187960 (+0.  4081)] 01 bytes, subSys 0x6F, cmdId 0x02, pData:    0x00
[14:41:19.187,974] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:6F:02:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.188377 (+0.   459)] 05 bytes, subSys 0x2F, cmdId 0x08, pData:    0x00 0x00 0x00 0x00 0x00
NPI SREQ:  (len 8) 0x05 0x2F 0x08 0x00 0x00 0x00 0x00 0x00
[<-- 000:00:00.188393 (+0.    16)] [UART] write 10 bytes to 4
[14:41:19.188,414] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:2F:08:00:00:00:00:00
[<-- 000:00:00.188447 (+0.    54)] [UART] result: 10
[<-- 000:00:00.188451 (+0.     4)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.191214 (+0.  2763)] Signal from UART, grabbing mutex
[<-- 000:00:00.191226 (+0.    12)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x6f, Cmd ID: 0x08, length: 1
[14:41:19.191,251] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:6F:08:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x6F 0x08 0x00
[--> 000:00:00.191301 (+0.  3341)] 01 bytes, subSys 0x6F, cmdId 0x08, pData:    0x00
[14:41:19.191,319] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:6F:08:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.191595 (+0.   369)] 05 bytes, subSys 0x2F, cmdId 0x08, pData:    0x01 0x00 0x20 0x00 0x00
NPI SREQ:  (len 8) 0x05 0x2F 0x08 0x01 0x00 0x20 0x00 0x00
[<-- 000:00:00.191612 (+0.    17)] [UART] write 10 bytes to 4
[14:41:19.191,632] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:2F:08:01:00:20:00:00
[<-- 000:00:00.191668 (+0.    56)] [UART] result: 10
[<-- 000:00:00.191673 (+0.     5)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.194435 (+0.  2762)] Signal from UART, grabbing mutex
[<-- 000:00:00.194448 (+0.    13)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x6f, Cmd ID: 0x08, length: 1
[14:41:19.194,473] [NPISRVR/U_RX] PKT_HEX: 14:41:19.174,393] [Z_STACK/MAIN] MISC1  : IP addresses for 127.0.0.1:

[14:41:19.174,413] [Z_STACK/MAIN] MISC1  :   IPv4: 127.0.0.1
[14:41:19.174,425] [Z_STACK/MAIN] MISC1  : Trying to connect...
[14:41:19.174,739] [Z_STACK/MAIN] MISC1  : Connected.
[14:41:19.174,944] [Z_STACK/MAIN] UNMSKBL: 
[14:41:19.174,961] [Z_STACK/MAIN] UNMSKBL:  ************************************************
[14:41:19.174,972] [Z_STACK/MAIN] UNMSKBL:  *  ZStack Server for ZNP v1.0.2d               *
[14:41:19.174,983] [Z_STACK/MAIN] UNMSKBL:  ************************************************
[14:41:19.174,993] [Z_STACK/MAIN] UNMSKBL: 
[14:41:19.175,006] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:41:19.175,042] [Z_STACK/MAIN] INFO   : trying to send 8 bytes, subSys 0x1F, cmdId 0x00
[14:41:19.175,086] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [AREQ] 08:5F:00:02:5A:5F:53:54:41:43:4B
[14:41:19.175,123] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [AREQ] 08:5F:00:02:5A:5F:53:54:41:43:4B
[14:41:19.175,331] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:5, cmdID:3e, len::2
[14:41:19.175,351] [Z_STACK/MAIN] INFO   : preparing to send 2 bytes, subSys 0x05, cmdId 0x3E, pData:
[14:41:19.175,364] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.175,388] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 02:25:3E:FF:FF
[14:41:19.175,411] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 02:25:3E:FF:FF
[14:41:19.175,468] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.175,484] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.175,495] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.178,321] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x65, cmdId 0x3E
[14:41:19.178,357] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.178,370] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.178,399] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.178,420] [Z_STACK/MAIN] INFO   : zstackpb config: defaultChannelList:2000, configPANID:ffff, deviceType:0
[14:41:19.178,435] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:9, len::1
[14:41:19.178,451] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x09, pData:
[14:41:19.178,467] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.178,490] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:09:00
[14:41:19.178,526] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:09:00
[14:41:19.178,597] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.178,607] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.178,615] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.181,205] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x6F, cmdId 0x09
[14:41:19.181,220] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.181,229] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.181,248] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.181,260] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:6, len::1
[14:41:19.181,277] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x06, pData:
[14:41:19.181,286] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.181,303] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:06:00
[14:41:19.181,324] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:06:00
[14:41:19.181,362] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.181,372] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.181,380] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.183,933] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x6F, cmdId 0x06
[14:41:19.183,949] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.183,959] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.183,978] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.183,989] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:2, len::1
[14:41:19.184,000] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x02, pData:
[14:41:19.184,011] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.184,030] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:02:08
[14:41:19.184,050] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:02:08
[14:41:19.184,087] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.184,097] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.184,105] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.188,017] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x6F, cmdId 0x02
[14:41:19.188,032] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.188,042] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.188,221] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.188,239] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:8, len::5
[14:41:19.188,253] [Z_STACK/MAIN] INFO   : preparing to send 5 bytes, subSys 0x0F, cmdId 0x08, pData:
[14:41:19.188,265] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.188,294] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:00:00:00:00:00
[14:41:19.188,323] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:00:00:00:00:00
[14:41:19.188,374] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.188,388] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.188,399] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.191,374] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x6F, cmdId 0x08
[14:41:19.191,394] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.191,407] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.191,430] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.191,445] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:8, len::5
[14:41:19.191,458] [Z_STACK/MAIN] INFO   : preparing to send 5 bytes, subSys 0x0F, cmdId 0x08, pData:
[14:41:19.191,478] [Z_STACK/MAIN] INFO   : [M===================================================
m[SOCZIGB>>NPISRVR                                    ] [SRSP] 01:6F:08:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x6F 0x08 0x00
[--> 000:00:00.194507 (+0.  3206)] 01 bytes, subSys 0x6F, cmdId 0x08, pData:    0x00
[14:41:19.194,525] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:6F:08:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.194784 (+0.   336)] 06 bytes, subSys 0x21, cmdId 0x09, pData:    0x83 0x00 0x00 0x02 0xFF 0xFF
NPI SREQ:  (len 9) 0x06 0x21 0x09 0x83 0x00 0x00 0x02 0xFF 0xFF
[<-- 000:00:00.194802 (+0.    18)] [UART] write 11 bytes to 4
[14:41:19.194,823] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 06:21:09:83:00:00:02:FF:FF
[<-- 000:00:00.194854 (+0.    52)] [UART] result: 11
[<-- 000:00:00.194860 (+0.     6)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.200313 (+0.  5453)] Signal from UART, grabbing mutex
[<-- 000:00:00.200324 (+0.    11)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x61, Cmd ID: 0x09, length: 1
[14:41:19.200,349] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:61:09:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x61 0x09 0x00
[--> 000:00:00.200384 (+0.  5877)] 01 bytes, subSys 0x61, cmdId 0x09, pData:    0x00
[14:41:19.200,402] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:61:09:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.200673 (+0.   349)] 05 bytes, subSys 0x21, cmdId 0x09, pData:    0x87 0x00 0x00 0x01 0x00
NPI SREQ:  (len 8) 0x05 0x21 0x09 0x87 0x00 0x00 0x01 0x00
[<-- 000:00:00.200691 (+0.    18)] [UART] write 10 bytes to 4
[14:41:19.200,710] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 05:21:09:87:00:00:01:00
[<-- 000:00:00.200740 (+0.    49)] [UART] result: 10
[<-- 000:00:00.200744 (+0.     4)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.205956 (+0.  5212)] Signal from UART, grabbing mutex
[<-- 000:00:00.205966 (+0.    10)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x61, Cmd ID: 0x09, length: 1
[14:41:19.205,989] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:61:09:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x61 0x09 0x00
[--> 000:00:00.206023 (+0.  5639)] 01 bytes, subSys 0x61, cmdId 0x09, pData:    0x00
[14:41:19.206,041] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:61:09:00
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.206329 (+0.   363)] 07 bytes, subSys 0x21, cmdId 0x15, pData:    0x96 0x00 0xC4 0x64 0x00 0x00 0x00
NPI SREQ:  (len 10) 0x07 0x21 0x15 0x96 0x00 0xC4 0x64 0x00 0x00 0x00
[<-- 000:00:00.206348 (+0.    19)] [UART] write 12 bytes to 4
[14:41:19.206,369] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 07:21:15:96:00:C4:64:00:00:00
[<-- 000:00:00.206400 (+0.    52)] [UART] result: 12
[<-- 000:00:00.206405 (+0.     5)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.209527 (+0.  3122)] Signal from UART, grabbing mutex
[<-- 000:00:00.209537 (+0.    10)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x60, Cmd ID: 0x00, length: 3
[14:41:19.209,565] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 03:60:00:02:21:15
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 4) 0x01 0x61 0x15 0xFF
[--> 000:00:00.209597 (+0.  3574)] 01 bytes, subSys 0x61, cmdId 0x15, pData:    0xFF
[14:41:19.209,615] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 01:61:15:FF
...sent 4 bytes to Client #5
!Done
Receive message...
[<-- 000:00:00.210930 (+0.  1393)] 01 bytes, subSys 0x2F, cmdId 0x05, pData:    0x04
NPI SREQ:  (len 4) 0x01 0x2F 0x05 0x04
[<-- 000:00:00.210948 (+0.    18)] [UART] write 6 bytes to 4
[14:41:19.210,968] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 01:2F:05:04
[<-- 000:00:00.211019 (+0.    71)] [UART] result: 6
[<-- 000:00:00.211025 (+0.     6)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:00.752484 (+0.541459)] Signal from UART, grabbing mutex
[<-- 000:00:00.752506 (+0.    22)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x6f, Cmd ID: 0x05, length: 1
[14:41:19.752,562] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 01:6F:05:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x45, Cmd ID: 0xC0, length: 1
NPI SRSP: (len 4) 0x01 0x6F 0x05 0x00
[--> 000:00:00.752616 (+0.543019)] 01 bytes, subSys 0x6F, cmdId 0x05, pData:    0x00[14:41:19.752,616] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 01:45:C0:09

[UART] npi_procframe signal areq callback thread (invoked by read loop) 
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x4f, Cmd ID: 0x80, length: 3
[-->] 1 bytes, subSys 0x45, cmdId 0xC0, pData: 0x09[14:41:19.752,652] [NPISRVR/MAIN] PKT_HEX: 
[         NPISRVR>>Z_STACK                           ] [ucst] 01:6F:05:00
[--> 000:00:00.752661 (+0.    45)] 01 bytes, subSys 0x45, cmdId 0xC0, pData:    0x09
[14:41:19.752,690] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 03:4F:80:0D:00:04
[UART] npi_procframe signal areq callback thread (invoked by read loop) 
[14:41:19.752,707] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 01:45:C0:09
...sent 4 bytes to Client #5
!Done
...sent 4 bytes to Client #5
[-->] 3 bytes, subSys 0x4F, cmdId 0x80, pData: 0x0D 0x00 0x04
[--> 000:00:00.752811 (+0.   150)] 03 bytes, subSys 0x4F, cmdId 0x80, pData:    0x0D 0x00 0x04
[14:41:19.752,832] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 03:4F:80:0D:00:04
...sent 6 bytes to Client #5
[<-- 000:00:00.951015 (+0.198509)] Signal from UART, grabbing mutex
[<-- 000:00:00.951039 (+0.    24)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x4f, Cmd ID: 0x80, length: 3
[14:41:19.951,100] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 03:4F:80:08:02:00
[UART] npi_procframe signal areq callback thread (invoked UTEX] Lock SRSP Transaction Mutex
[14:41:19.191,508] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:01:00:20:00:00
[14:41:19.191,537] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:2F:08:01:00:20:00:00
[14:41:19.191,593] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.191,607] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.191,620] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.194,570] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x6F, cmdId 0x08
[14:41:19.194,589] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.194,602] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.194,625] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.194,642] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:1, cmdID:9, len::6
[14:41:19.194,655] [Z_STACK/MAIN] INFO   : preparing to send 6 bytes, subSys 0x01, cmdId 0x09, pData:
[14:41:19.194,668] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.194,698] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 06:21:09:83:00:00:02:FF:FF
[14:41:19.194,728] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 06:21:09:83:00:00:02:FF:FF
[14:41:19.194,784] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.194,799] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.194,811] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.200,450] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x61, cmdId 0x09
[14:41:19.200,473] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.200,486] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.200,510] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.200,528] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:1, cmdID:9, len::5
[14:41:19.200,542] [Z_STACK/MAIN] INFO   : preparing to send 5 bytes, subSys 0x01, cmdId 0x09, pData:
[14:41:19.200,556] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.200,584] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:21:09:87:00:00:01:00
[14:41:19.200,613] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 05:21:09:87:00:00:01:00
[14:41:19.200,672] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.200,686] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.200,699] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.206,093] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x61, cmdId 0x09
[14:41:19.206,112] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.206,123] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.206,149] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.206,168] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:1, cmdID:15, len::7
[14:41:19.206,182] [Z_STACK/MAIN] INFO   : preparing to send 7 bytes, subSys 0x01, cmdId 0x15, pData:
[14:41:19.206,196] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.206,230] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 07:21:15:96:00:C4:64:00:00:00
[14:41:19.206,261] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 07:21:15:96:00:C4:64:00:00:00
[14:41:19.206,303] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.206,317] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.206,327] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.209,664] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x61, cmdId 0x15
[14:41:19.209,685] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.209,698] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.209,726] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.209,740] [Z_STACK/MAIN] DEBUG  : --> status failed: cmdID:15, status: 255
[14:41:19.209,756] [Z_STACK/MAIN] INFO   : Port: 2536
[14:41:19.210,144] [Z_STACK/MAIN] INFO   : Following IP addresses are available:

[14:41:19.210,360] [Z_STACK/MAIN] INFO   :  IPv4: interface: lo  IP Address 127.0.0.1
[14:41:19.210,378] [Z_STACK/MAIN] INFO   :  IPv6: interface: lo  IP Address ::1
[14:41:19.210,397] [Z_STACK/MAIN] INFO   : The socket will listen on the following IP addresses:

[14:41:19.210,411] [Z_STACK/MAIN] INFO   :   IPv4: 0.0.0.0
[14:41:19.210,425] [Z_STACK/MAIN] INFO   :   IPv6: ::
[14:41:19.210,438] [Z_STACK/MAIN] INFO   : 0.0.0.0 means it will listen to all available IP address

[14:41:19.210,498] [Z_STACK/MAIN] MISC1  : waiting for first connection on #4...
[14:41:19.210,701] [Z_STACK/MAIN] INFO   : znp_misc sendNPIExpectDefaultStatusZNP: subSys:f, cmdID:5, len::1
[14:41:19.210,720] [Z_STACK/MAIN] INFO   : preparing to send 1 bytes, subSys 0x0F, cmdId 0x05, pData:
[14:41:19.210,733] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:19.210,760] [Z_STACK/MAIN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:05:04
[14:41:19.210,783] [Z_STACK/MAIN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 01:2F:05:04
[14:41:19.210,891] [Z_STACK/MAIN] INFO   : Waiting for synchronous response...
[14:41:19.210,905] [Z_STACK/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:19.210,917] [Z_STACK/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:19.752,805] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x6F, cmdId 0x05
[14:41:19.752,836] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:19.752,848] [Z_STACK/READ] INFO   : Client Read: (len 4):
[14:41:19.752,878] [Z_STACK/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:19.795,381] [Z_STACK/READ] INFO   : Received 1 bytes, subSys 0x45, cmdId 0xC0
[14:41:19.795,400] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0xC0
[14:41:19.795,412] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0x84000C60 (received  1 messages)...
[14:41:19.795,426] [Z_STACK/READ] INFO   : Filling new message (@ 0x84000C60)...
[14:41:19.795,458] [Z_STACK/READ] INFO   : Received 3 bytes, subSys 0x4F, cmdId 0x80
[14:41:19.795,479] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0x80
[14:41:19.795,496] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0x84000C80 (received  2 messages)...
[14:41:19.795,511] [Z_STACK/READ] INFO   : Filling new message (@ 0x84000C80)...
[14:41:19.795,532] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[14:41:19.795,549] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0x84000C60
[14:41:19.795,567] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[14:41:19.795,581] [Z_STACK/HNDLstarting NETWORK_MGR, cmd ' ./NWKMGR_SRVR_arm 127.0.0.1:2536 -v 0xFFFFFFFF ' on Mon 24 May 2021 02:41:21 PM UTC
by read loop) 
[-->] 3 bytes, subSys 0x4F, cmdId 0x80, pData: 0x08 0x02 0x00
[--> 000:00:00.951154 (+0.198343)] 03 bytes, subSys 0x4F, cmdId 0x80, pData:    0x08 0x02 0x00
[14:41:19.951,178] [NPISRVR/ACBK] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [bcst] 03:4F:80:08:02:00
] INFO   : [DBG] asyncCB: subSys:0x00000005, cmdId:0x000000C0, len:0x00000001, pData:0x84000C70
[14:41:19.795,596] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0x84000C60)...
[14:41:19.795,609] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0x84000C60 (processed 1 messages)...
[14:41:19.795,623] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:41:19.795,636] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[14:41:19.795,648] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0x84000C80
[14:41:19.795,659] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[14:41:19.795,671] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x0000000F, cmdId:0x00000080, len:0x00000003, pData:0x84000C90
[14:41:19.795,909] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0x84000C80)...
[14:41:19.795,925] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0x84000C80 (processed 2 messages)...
[14:41:19.795,937] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:41:19.795,959] [Z_STACK/MAIN] INFO   : zstackpb: AppCnfCommissioningNotification: state:13
[14:41:19.795,976] [Z_STACK/MAIN] INFO   : zstackpb: AppCnfCommissioningNotification: commMode:0
[14:41:19.795,990] [Z_STACK/MAIN] INFO   : zstackpb: AppCnfCommissioningNotification: remainingCommMode:4
[14:41:19.951,320] [Z_STACK/READ] INFO   : Received 3 bytes, subSys 0x4F, cmdId 0x80
[14:41:19.951,348] [Z_STACK/READ] INFO   : RPC_CMD_AREQ cmdId: 0x80
[14:41:19.951,360] [Z_STACK/READ] INFO   : [DBG] Allocated      @ 0x84000C40 (received  3 messages)...
[14:41:19.951,372] [Z_STACK/READ] INFO   : Filling new message (@ 0x84000C40)...
[14:41:19.951,402] [Z_STACK/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[14:41:19.951,417] [Z_STACK/HNDL] INFO   : [DBG] Processing     @ 0x84000C40
[14:41:19.951,432] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ Calling asynchMsgCback (Handle)...
[14:41:19.951,444] [Z_STACK/HNDL] INFO   : [DBG] asyncCB: subSys:0x0000000F, cmdId:0x00000080, len:0x00000003, pData:0x84000C50
[14:41:19.951,485] [Z_STACK/HNDL] INFO   : [MUTEX] AREQ (Handle) (message @ 0x84000C40)...
[14:41:19.951,497] [Z_STACK/HNDL] INFO   : [DBG] Clearing               @ 0x84000C40 (processed 3 messages)...
[14:41:19.951,509] [Z_STACK/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:41:19.951,528] [Z_STACK/MAIN] INFO   : zstackpb: AppCnfCommissioningNotification: state:8
[14:41:19.951,546] [Z_STACK/MAIN] INFO   : zstackpb: AppCnfCommissioningNotification: commMode:2
[14:41:19.951,560] [Z_STACK/MAIN] INFO   : zstackpb: AppCnfCommissioningNotification: remainingCommMode:0
[14:41:22.511,593] [NWK_MGR/MAIN] INFO   :  there are 2 args
...sent 6 bytes to Client #5
Receive message...
[<-- 000:00:03.515174 (+2.564135)] 00 bytes, subSys 0x25, cmdId 0x50, pData:   
NPI SREQ:  (len 3) 0x00 0x25 0x50
[<-- 000:00:03.515188 (+0.    14)] [UART] write 5 bytes to 4
[14:41:22.515,204] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 00:25:50
[14:41:22.512,240] [Z_STACK/LSTN] MISC1  : Connected to #5.(127.0.0.1 / ::)
[14:41:22.512,267] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb - connected: 5
[14:41:22.512,280] [Z_STACK/LSTN] CONNECT: Connected to new client, connection # 5
[14:41:22.512,654] [Z_STACK/LSTN] INFO   : Receive message...
[14:41:22.512,683] [Z_STACK/LSTN] CONNECT: Client at connection # 5 identified itself as NWK_MGR
[14:41:22.512,702] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:5f, cmdId:0
[14:41:22.512,715] [Z_STACK/LSTN] INFO   : !Done
[14:41:22.514,605] [Z_STACK/LSTN] INFO   : Receive message...
[14:41:22.514,628] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:14
[14:41:22.514,717] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 04:00:71:FA:08:14:10:00
[14:41:22.514,739] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] zstackDefaultRsp
[14:41:22.514,754] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = DEV_ZDO_CBS_REQ
[14:41:22.514,767] [Z_STACK/LSTN] PKTBODY:                                                          status = ZSuccess
[14:41:22.514,825] [Z_STACK/LSTN] INFO   : ...sent 8 bytes to Client
[14:41:22.514,840] [Z_STACK/LSTN] INFO   : !Done
[14:41:22.515,036] [Z_STACK/LSTN] INFO   : Receive message...
[14:41:22.515,053] [Z_STACK/LSTN] INFO   : zstackpb zspbHandlePbCb: subsystemID:31, cmdId:8
[14:41:22.515,063] [Z_STACK/LSTN] INFO   : preparing to send 0 bytes, subSys 0x05, cmdId 0x50, pData:
[14:41:22.515,072] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:22.515,089] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[14:41:22.515,107] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 00:25:50
[14:41:22.515,160] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[14:41:22.515,171] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:22.515,179] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:22.519,878] [Z_STACK/READ] INFO   : Received 24 bytes, subSys 0x65, cmdId 0x50
[14:41:22.519,897] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:22.519,908] [Z_STACK/READ] INFO   : Client Read: (len 27):
[14:41:22.519,928] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:22.519,940] [Z_STACK/LSTN] INFO   : zstackpb Sending Network Info Response
[14:41:22.519,951] [Z_STACK/LSTN] INFO   : znp_misc osal_nv_read: id:1, len:8
[14:41:22.519,962] [Z_STACK/LSTN] INFO   : preparing to send 3 bytes, subSys 0x01, cmdId 0x08, pData:
[14:41:22.519,973] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:22.519,994] [Z_STACK/LSTN] PKT_HEX: [         NPISRVR<<Z_STACK                           ] [SREQ] 03:21:08:01:00:00
[14:41:22.520,016] [Z_STACK/LSTN] PKTTYPE: [         NPISRVR<<Z_STACK                           ] [SREQ] 03:21:08:01:00:00
[14:41:22.520,057] [Z_STACK/LSTN] INFO   : Waiting for synchronous response...
[14:41:22.520,067] [Z_STACK/LSTN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:22.520,075] [Z_STACK/LSTN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:22.528,865] [Z_STACK/READ] INFO   : Received 10 bytes, subSys 0x61, cmdId 0x08
[14:41:22.528,886] [Z_STACK/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:22.528,910] [Z_STACK/READ] INFO   : Client Read: (len 13):
[14:41:22.528,934] [Z_STACK/LSTN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:22.529,226] [Z_STACK/LSTN] PKT_HEX: [                  Z_STACK>>NWK_MGR                  ] [ucst] 31:00:71:0E:08:0E:10:00:19:FA:41:F6:14:00:4B:12:00:20:09:28:DE:AC:03:31:FA:41:F6:14:00:4B:12:00:3B
[14:41:22.529,253] [Z_STACK/LSTN] PKTTYPE: [                  Z_STACK>>NWK_MGR                  ] sysNwkInfoReadRsp
[14:41:22.529,279] [Z_STACK/LSTN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_RSP
[14:41:22.529,295] [Z_STACK/LSTN] PKTBODY:                                                          nwkAddr = 0x00000000 (0)
[14:41:22.529,313] [Z_STACK/LSTN] PKTBODY:                                                          ieeeAddr = 00:12:4B:00:14:F6:41:FA
[14:41:22.529,328] [Z_STACK/LSTN] PKTBODY:                                                          devState = DEV_ZB_COORD
[14:41:22.529,343] [Z_STACK/LSTN] PKTBODY:                                                          panId = 0x0000D65E (54878)
[14:41:22.529,359] [Z_STACK/LSTN] PKTBODY:                                                          extendedPanId = 00:12:4B:00:14:F6:41:FA
[14:41:22.529,374] [Z_STACK/LSTN] PKTBODY:                                                          coordAddr = 0x00000000 (0)
[14:41:22.529,391] [Z_STACK/LSTN] PKTBODY:                                                          coordExtAddr = 00:00:00:00:00:00:00:00
[14:41:22.529,406] [Z_STACK/LSTN] PKTBODY:                                                          devTypes :
[14:41:22.529,447] [Z_STACK/LSTN] ERROR  : ERROR: signal 11 was trigerred:
[14:41:22.529,465] [Z_STACK/LSTN] ERROR  :   Fault address: 0x84000ce8
[14:41:22.529,479] [Z_STACK/LSTN] ERROR  :   Fault reason: address not mapped to object
[14:41:22.530,091] [Z_STACK/LSTN] ERROR  : Stack trace unavailable
[14:41:22.530,108] [Z_STACK/LSTN] ERROR  : Executing original handler...
[<-- 000:00:03.515264 (+0.    76)] [UART] result: 5
[<-- 000:00:03.515270 (+0.     6)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:03.519640 (+0.  4370)] Signal from UART, grabbing mutex
[<-- 000:00:03.519653 (+0.    13)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x65, Cmd ID: 0x50, length: 24
[14:41:22.519,714] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 18:65:50:00:00:09:5E:D6:00:00:FA:41:F6:14:00:4B:12:00:00:00:00:00:00:00:00:00:0B
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 27) 0x18 0x65 0x50 0x00 0x00 0x09 0x5E 0xD6 0x00 0x00 0xFA 0x41 0xF6 0x14 0x00 0x4B 0x12 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0B
[--> 000:00:03.519757 (+2.568603)] 24 bytes, subSys 0x65, cmdId 0x50, pData:    0x00 0x00 0x09 0x5E 0xD6 0x00 0x00 0xFA 0x41 0xF6 0x14 0x00 0x4B 0x12 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x0B
[14:41:22.519,805] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 18:65:50:00:00:09:5E:D6:00:00:FA:41:F6:14:00:4B:12:00:00:00:00:00:00:00:00:00:0B
...sent 27 bytes to Client #5
!Done
Receive message...
[<-- 000:00:03.520060 (+0.   407)] 03 bytes, subSys 0x21, cmdId 0x08, pData:    0x01 0x00 0x00
NPI SREQ:  (len 6) 0x03 0x21 0x08 0x01 0x00 0x00
[<-- 000:00:03.520071 (+0.    11)] [UART] write 8 bytes to 4
[14:41:22.520,085] [NPISRVR/MAIN] PKT_HEX: [SOCZIGB<<NPISRVR                                    ] [send] 03:21:08:01:00:00
[<-- 000:00:03.520117 (+0.    46)] [UART] result: 8
[<-- 000:00:03.520121 (+0.     4)] [UART] (synch data) Conditional wait 6 s
[<-- 000:00:03.528667 (+0.  8546)] Signal from UART, grabbing mutex
[<-- 000:00:03.528678 (+0.    11)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x61, Cmd ID: 0x08, length: 10
[14:41:22.528,721] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [SRSP] 0A:61:08:00:08:FA:41:F6:14:00:4B:12:00
[UART] npi_procframe signal synch response received (invoked by read loop) 
NPI SRSP: (len 13) 0x0A 0x61 0x08 0x00 0x08 0xFA 0x41 0xF6 0x14 0x00 0x4B 0x12 0x00
[--> 000:00:03.528763 (+0.  9006)] 10 bytes, subSys 0x61, cmdId 0x08, pData:    0x00 0x08 0xFA 0x41 0xF6 0x14 0x00 0x4B 0x12 0x00
[14:41:22.528,802] [NPISRVR/MAIN] PKT_HEX: [         NPISRVR>>Z_STACK                           ] [ucst] 0A:61:08:00:08:FA:41:F6:14:00:4B:12:00
[14:41:22.511,790] [NWK_MGR/MAIN] INFO   :  argv[0] = ./NWKMGR_SRVR_arm
[14:41:22.511,803] [NWK_MGR/MAIN] INFO   :  argv[1] = 127.0.0.1:2536
[14:41:22.511,853] [NWK_MGR/MAIN] MISC1  : Port: 2536

[14:41:22.511,885] [NWK_MGR/MAIN] MISC1  : IP addresses for 127.0.0.1:

[14:41:22.511,903] [NWK_MGR/MAIN] MISC1  :   IPv4: 127.0.0.1
[14:41:22.511,916] [NWK_MGR/MAIN] MISC1  : Trying to connect...
[14:41:22.512,170] [NWK_MGR/MAIN] MISC1  : Connected.
[14:41:22.512,391] [NWK_MGR/MAIN] UNMSKBL: 
[14:41:22.512,407] [NWK_MGR/MAIN] UNMSKBL:  ************************************************
[14:41:22.512,418] [NWK_MGR/MAIN] UNMSKBL:  *  Network Manager Server v1.0.2d              *
[14:41:22.512,428] [NWK_MGR/MAIN] UNMSKBL:  ************************************************
[14:41:22.512,440] [NWK_MGR/HNDL] INFO   : [MUTEX] Wait for AREQ semaphore
[14:41:22.512,473] [NWK_MGR/MAIN] UNMSKBL: 
[14:41:22.512,494] [NWK_MGR/MAIN] INFO   : trying to send 8 bytes, subSys 0x1F, cmdId 0x00
[14:41:22.512,537] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [AREQ] 08:00:5F:00:03:4E:57:4B:5F:4D:47:52
[14:41:22.512,576] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] [AREQ] 08:00:5F:00:03:4E:57:4B:5F:4D:47:52
[14:41:22.512,841] [NWK_MGR/MAIN] MISC1  : NwkMgr: Sending Device ZDO CB Request
[14:41:22.513,496] [NWK_MGR/MAIN] INFO   : preparing to send 90 bytes, subSys 0x11, cmdId 0x14, pData:
[14:41:22.513,512] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:22.513,662] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 5A:00:31:14:08:14:10:01:18:01:20:01:28:01:30:01:38:01:40:01:48:01:50:01:58:01:60:01:68:01:70:01:71
[14:41:22.513,688] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] devZDOCBReq
[14:41:22.513,969] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = DEV_ZDO_CBS_REQ
[14:41:22.513,988] [NWK_MGR/MAIN] PKTBODY:                                                          srcRtgIndCB = 1
[14:41:22.514,003] [NWK_MGR/MAIN] PKTBODY:                                                          concentratorIndCb = 1
[14:41:22.514,018] [NWK_MGR/MAIN] PKTBODY:                                                          nwkDiscCnfCB = 1
[14:41:22.514,033] [NWK_MGR/MAIN] PKTBODY:                                                          beaconNotIndCB = 1
[14:41:22.514,047] [NWK_MGR/MAIN] PKTBODY:                                                          joinCnfCB = 1
[14:41:22.514,063] [NWK_MGR/MAIN] PKTBODY:                                                          leaveCnfCB = 1
[14:41:22.514,081] [NWK_MGR/MAIN] PKTBODY:                                                          leaveIndCB = 1
[14:41:22.514,097] [NWK_MGR/MAIN] PKTBODY:                                                          nwkAddrRsp = 1
[14:41:22.514,113] [NWK_MGR/MAIN] PKTBODY:                                                          ieeeAddrRsp = 1
[14:41:22.514,129] [NWK_MGR/MAIN] PKTBODY:                                                          nodeDescRsp = 1
[14:41:22.514,147] [NWK_MGR/MAIN] PKTBODY:                                                          powerDescRsp = 1
[14:41:22.514,166] [NWK_MGR/MAIN] PKTBODY:                                                          simpleDescRsp = 1
[14:41:22.514,183] [NWK_MGR/MAIN] PKTBODY:                                                          activeEndpointRsp = 1
[14:41:22.514,198] [NWK_MGR/MAIN] PKTBODY:                                                          matchDescRsp = 1
[14:41:22.514,213] [NWK_MGR/MAIN] PKTBODY:                                                          complexDescRsp = 1
[14:41:22.514,229] [NWK_MGR/MAIN] PKTBODY:                                                          userDescRsp = 1
[14:41:22.514,243] [NWK_MGR/MAIN] PKTBODY:                                                          discoveryCacheRsp = 1
[14:41:22.514,259] [NWK_MGR/MAIN] PKTBODY:                                                          userDescCnf = 1
[14:41:22.514,275] [NWK_MGR/MAIN] PKTBODY:                                                          serverDiscoveryRsp = 1
[14:41:22.514,291] [NWK_MGR/MAIN] PKTBODY:                                                          endDeviceTimeoutRsp = 1
[14:41:22.514,307] [NWK_MGR/MAIN] PKTBODY:                                                          bindRsp = 1
[14:41:22.514,321] [NWK_MGR/MAIN] PKTBODY:                                                          endDeviceBindRsp = 1
[14:41:22.514,337] [NWK_MGR/MAIN] PKTBODY:                                                          unbindRsp = 1
[14:41:22.514,353] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtNwkDiscRsp = 1
[14:41:22.514,371] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtLqiRsp = 1
[14:41:22.514,387] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtRtgRsp = 1
[14:41:22.514,403] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtBindRsp = 1
[14:41:22.514,419] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtLeaveRsp = 1
[14:41:22.514,442] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtDirectJoinRsp = 1
[14:41:22.514,465] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtPermitJoinRsp = 1
[14:41:22.514,488] [NWK_MGR/MAIN] PKTBODY:                                                          mgmtNwkUpdateNotify = 1
[14:41:22.514,511] [NWK_MGR/MAIN] PKTBODY:                                                          deviceAnnounce = 1
[14:41:22.514,521] [NWK_MGR/MAIN] PKTBODY:                                                          devStateChange = 1
[14:41:22.514,535] [NWK_MGR/MAIN] PKTBODY:                                                          tcDeviceInd = 1
[14:41:22.514,615] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[14:41:22.514,626] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:22.514,634] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:22.514,828] [NWK_MGR/READ] INFO   : Received 4 bytes, subSys 0x71, cmdId 0xFA
[14:41:22.514,851] [NWK_MGR/READ] INFO   : [MUTEX] SRSP Cond signal set
[14:41:22.514,860] [NWK_MGR/READ] INFO   : Client Read: (len 8):
[14:41:22.514,886] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:22.514,906] [NWK_MGR/MAIN] MISC1  : ZDO Callback Register Response Successful
[14:41:22.514,917] [NWK_MGR/MAIN] MISC1  : NwkMgr sendSysNwkInfoReadReqAndSetTxPower:
[14:41:22.514,933] [NWK_MGR/MAIN] INFO   : preparing to send 2 bytes, subSys 0x11, cmdId 0x08, pData:
[14:41:22.514,944] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Transaction Mutex
[14:41:22.514,966] [NWK_MGR/MAIN] PKT_HEX: [                  Z_STACK<<NWK_MGR                  ] [SREQ] 02:00:31:08:08:08
[14:41:22.514,984] [NWK_MGR/MAIN] PKTTYPE: [                  Z_STACK<<NWK_MGR                  ] sysNwkInfoReadReq
[14:41:22.514,999] [NWK_MGR/MAIN] PKTBODY:                                                          cmdID = SYS_NWK_INFO_READ_REQ
[14:41:22.515,040] [NWK_MGR/MAIN] INFO   : Waiting for synchronous response...
[14:41:22.515,050] [NWK_MGR/MAIN] INFO   : [MUTEX] Lock SRSP Mutex
[14:41:22.515,060] [NWK_MGR/MAIN] INFO   : [MUTEX] Wait for SRSP Cond signal...
[14:41:22.530,687] [NWK_MGR/READ] INFO   : Peer closed connection
[14:41:22.530,756] [NWK_MGR/HNDL] INFO   : [MUTEX] Mutex for AREQ unlocked
[14:41:22.530,799] [NWK_MGR/HNDL] DEBUG  : Server connection was terminated
[14:41:24.515,138] [NWK_MGR/MAIN] INFO   : [MUTEX] SRSP Cond Wait timed out!
[14:41:24.515,190] [NWK_MGR/MAIN] ERROR  : SRSP Cond Wait timed out!
[14:41:24.515,203] [NWK_MGR/MAIN] INFO   : [MUTEX] Unlock SRSP Mutex
[14:41:24.515,218] [NWK_MGR/MAIN] ERROR  : apicSendSynchData() failed getting response
[14:41:24.516,573] [NWK_MGR/MAIN] MISC1  : Opened Database 'DbDeviceInfo.csv', 0 records
[14:41:24.516,849] [NWK_MGR/MAIN] MISC1  : Opened Database 'DbEndpoints.csv', 0 records
[14:41:24.517,480] [NWK_MGR/MAIN] ERROR  : Reading Local Network Information Failed
[14:41:24.517,504] [NWK_MGR/MAIN] UNMSKBL: Initialization failed. Quitting now.

Startup phase 3 failed
./zigbeeHAgw: line 623: killall: command not found
waiting for Zstack linux to exit
./zigbeeHAgw: line 638: killall: command not found
waiting for NPI to exit
...sent 13 bytes to Client #5
!Done
Receive message...
Will disconnect #5
Done with 5
Removing connection #5
No  Active Connections[<-- 000:00:16.520512 (+12.991834)] Signal from UART, grabbing mutex
[<-- 000:00:16.520543 (+0.    31)] Signal read handle, owning mutex
[<-- 000:00:16.521401 (+0.   858)] Signal from UART, grabbing mutex
[<-- 000:00:16.521410 (+0.     9)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x41, Cmd ID: 0x80, length: 6
[14:41:35.521,460] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 06:41:80:00:02:00:02:07:01
[UART] npi_procframe signal areq callback thread (invoked by read loop) 
[<-- 000:00:18.567604 (+2. 46194)] Signal from UART, grabbing mutex
[<-- 000:00:18.567638 (+0.    34)] Signal read handle, owning mutex
[<-- 000:00:18.568510 (+0.   872)] Signal from UART, grabbing mutex
[<-- 000:00:18.568520 (+0.    10)] Signal read handle, owning mutex
[UART] npi_parseframe: found frame, going to npi_procframe
[UART] npi_procframe, subsys: 0x41, Cmd ID: 0x80, length: 6
[14:41:37.568,571] [NPISRVR/U_RX] PKT_HEX: [SOCZIGB>>NPISRVR                                    ] [ASNC] 06:41:80:00:02:00:02:07:01

0 YiKai Chen over 4 years ago in reply to vikas k

Guru 735695 points

It seems that your Linux OS doesn’t support “killall” command properly.

0 vikas k over 4 years ago in reply to YiKai Chen

Intellectual 330 points

Hi YiKai Chen,

I agree my Linux OS does not support "killall". Do you have any idea why other errors are happening?

Thanks,

Vikas

0 YiKai Chen over 4 years ago in reply to vikas k

Guru 735695 points

Do you mean to ask "ERROR: signal 11 was trigerred:"? If so, signal 11 (known as segmentation violation) means that the program accessed a memory location that was not assigned to it. That's usually a bug in a program. So if you're writing your own program, that's the most likely cause.

0 vikas k over 4 years ago in reply to YiKai Chen

Intellectual 330 points

Hi YiKai Chen,

Thanks for the update. But I did not make any change in the code of ZigBee 3.0 gateway. I have cross compiled the zigbee 3.0 gateway provided by TI for IMX8 .

Thanks,

Vikas

0 YiKai Chen over 4 years ago in reply to vikas k

Guru 735695 points

Is it possible that there’s something wrong when you build protobuf?

Zigbee & Thread

Zigbee & Thread forum

LP-CC2652RB: ZigBee gateway not able to start servers