Device stops receiving after sending custom Zigbee commands

[pjbuntinx]

Hi,

I am currently developing a Zigbee (router) device that has a custom cluster with custom commands. I can send 10-20 custom commands to this device successfully (and receive them) but after this, the Zboss loop seems to freeze and won't receive anything anymore. Also, read/write attribute commands to for example the basic cluster don't get received anymore. Do you have any idea what could be the reason for this? The only thing you can do hereafter is reboot the board. Sometime after you get the problem, a lot of data is printed/spammed in the console by the NRF chip. Constantly the same data it seems. Small sample of the logs:

D: de ad 16 02 4b ff 03 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4b ff 04 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4b ff 05 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4b ff 06 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4b ff 07 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00             |....    
D: 
D: 30 00 00 00 de ad 16 02 |0.......
D: 4b ff 08 4c 18 00 6d 05 |K..L..m.
D: 18 00 00 00 08 00 00 00 |........
D: 30 00 00 00             |0...    
D: 
D: de ad 16 02 4b ff 09 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4b ff 0a 4c |....K..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4c ff 0b 4c |....L..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4c ff 0c 4c |....L..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4c ff 0d 4c |....L..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4c ff 0e 4c |....L..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4c ff 0f 4c |....L..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...
D: 
D: de ad 16 02 4c ff 10 4c |....L..L
D: 18 00 6d 05 18 00 00 00 |..m.....
D: 08 00 00 00 30 00 00 00 |....0...

I am using a custom-developed board with a BT840 module which has an NRF52840 onboard. Here is a simplified example of my code: https://github.com/pieterjanbuntinx/test-nrf-custom-commands . In here the buttons and LEDs don't work (other pinouts on my board, I have removed most code for this on here). 

As the coordinator, I am using a custom board with an Espressif chip but I was also able to reproduce the problem with the shell example on an NRF dev board. It can be reproduced by repeatedly executing the following command: 

zcl cmd <short_addr> 2 0xfc00 0x00f1 -i -l 0x050301000004

Thanks in advance.

Best regards,

Pieter-Jan

[pjbuntinx]

I am using NRF connect in vscode and sdk version v2.5.2

[Maria Gilje]

Hi Pieter-Jan,

Please do a sniffer log of the network which includes the network startup, the successful messages, and the freeze. Upload the sniffer log as a .pcap file in a reply. See this guide on how to do sniffer logs for 802.15.4. If your network key differs from the keys in the guide, you need to share your key with us to enable us to decrypt the packets.

If you don't want the network key to be shared publicly, I can make the ticket private. Just let me know!

Best regards,

Maria

[pjbuntinx]

Hi Maria,

Thank you for your response.
I've attached the sniffer capture. The network keys should be the default Nordic keys or just the ones of my dev board, so it does not really matter if I share them. 

From No. 159 on you can see that I am sending a custom command with id 0xf1. Up to and including No. 241, I always get an ACK from the device. After this, none are sent anymore.

Best Regards,
Pieter-Jan

custom_command_problem.pcapng

[Maria Gilje]

Hi Pieter-Jan,

From the sniffer log we can see that the device still ACKs packets on a the MAC layer after it stops APS ACKs. Your hypothesis that the ZBOSS thread freezes could be a possibility. To get more logging and statistics for the active threads of your application you can use the Thread analyzer.

Getting some information on what is happening before the freeze is helpful, so if you can configure your application to a higher logging level and debug it, this can help to close in on what the cause is.

I do not have any hardware to test right now, but I will test this as soon as I can.

Best regards,

Maria

[pjbuntinx]

Hi Maria,

Sorry for the late response. I have enabled the thread analyzer and the stack usage of all the threads seems fine to me. When the problem occurs, the thread analyzer quits printing. I have added a print statement to the main thread that prints a message every second. This also stops working. Are there any other debug logs I can enable to help me debug this?

Thanks!
Best regards,
Pieter-Jan

Below you can find the log:

SEGGER J-Link V7.94e - Real time terminal output
SEGGER J-Link (unknown) V1.0, SN=1050065421
Process: JLink.exe
I: nRF5 802154 radio initialized
D: Function: zb_trans_set_auto_ack, enabled: 1
D: 
D: de ad 0a 02 00 00 00 00 |........
D: 77 00 b3 00             |w...    
D: 
D: de ad 26 02 00 00 01 00 |..&.....
D: 77 00 b7 00 08 10 00 00 |w.......
D: 00 01 00 00 10 00 00 00 |........
D: 0c 03 00 00 84 02 00 00 |........
D: 98 01 00 00 68 02 00 00 |....h...
D: 
D: de ad 0e 02 00 00 02 00 |........
D: 77 00 c0 00 02 00 00 00 |w.......
D: 
D: de ad 0e 02 00 00 03 00 |........
D: 77 00 c2 00 c0 02 00 00 |w.......
D: 
D: de ad 0e 02 00 00 04 00 |........
D: 77 00 c8 00 50 04 00 00 |w...P...
D: 
D: de ad 0e 02 00 00 05 00 |........
D: 77 00 cb 00 90 01 00 00 |w.......
D: 
D: de ad 0e 02 00 00 06 00 |........
D: 77 00 ce 00 70 00 00 00 |w...p...
D: 
D: de ad 0e 02 01 00 07 00 |........
D: 77 00 d1 00 04 00 00 00 |w.......
D: 
D: de ad 0e 02 01 00 08 00 |........
D: 77 00 d8 00 30 00 00 00 |w...0...
D: 
D: de ad 12 02 01 00 09 00 |........
D: 77 00 db 00 dc 03 00 00 |w.......
D: 0c 00 00 00             |....    
D: 
D: de ad 0ePrint Main loop
Print Main loop
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 3 %
      : Total CPU cycles used: 12074
 thread_analyzer     : STACK: unused 560 usage 464 / 1024 (45 %); CPU: 0 %
      : Total CPU cycles used: 206
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 3
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 9
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 8
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 95 %
      : Total CPU cycles used: 320813
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 851
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 1 %
      : Total CPU cycles used: 12787
 thread_analyzer     : STACK: unused 560 usage 464 / 1024 (45 %); CPU: 0 %
      : Total CPU cycles used: 423
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 3
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 9
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 8
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 97 %
      : Total CPU cycles used: 647736
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 881
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 1 %
      : Total CPU cycles used: 13161
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 640
D: Received new Zigbee event: 0x01
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 4
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 12
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 8
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 98 %
      : Total CPU cycles used: 974996
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 911
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 1 %
      : Total CPU cycles used: 13994
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 862
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 5
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 16
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 8
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 98 %
      : Total CPU cycles used: 1301822
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 941
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 14310
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 1079
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 5
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 16
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 8
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 98 %
      : Total CPU cycles used: 1629142
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 971
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 15484
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 1296
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 6
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 19
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 12
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 1955589
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1001
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 15782
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 1514
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 7
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 23
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 12
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 2282920
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1032
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 16062
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 1732
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 7
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 23
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 12
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 2610273
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1062
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 16385
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 1950
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 8
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 26
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 12
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 2937576
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1092
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 16666
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 2169
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 9
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 30
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 12
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 3264917
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1122
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 16933
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 2386
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 9
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 30
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 12
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 3592281
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1152
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 17551
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 2604
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 13
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 41
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 15
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 3919273
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1182
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 19159
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 2821
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 24
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 76
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 15
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 4245226
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1212
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Function: zb_trans_transmit, channel: 21
D: Received new Zigbee event: 0x01
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Print Main loop
Thread analyze:
 zboss               : STACK: unused 868 usage 1116 / 1984 (56 %); CPU: 0 %
      : Total CPU cycles used: 20310
 thread_analyzer     : STACK: unused 528 usage 496 / 1024 (48 %); CPU: 0 %
      : Total CPU cycles used: 3039
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 1
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 31
 nrf5_rx             : STACK: unused 400 usage 336 / 736 (45 %); CPU: 0 %
      : Total CPU cycles used: 97
 sysworkq            : STACK: unused 1720 usage 264 / 1984 (13 %); CPU: 0 %
      : Total CPU cycles used: 15
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 299
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 99 %
      : Total CPU cycles used: 4571664
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 1242
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
D: 
D: de ad 0a 02 6b 24 13 00 |....k$..
D: 49 01 0b 03             |I...    
D: 
D: de ad 16 02 6b 24 14 00 |....k$..
D: 18 00 6d 05 16 00 00 00 |..m.....
D: 02 00 00 00 30 00 00 00 |....0...
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
D: Received new Zigbee event: 0x02
D: Function: zb_trans_get_next_packet
I: Received
D: Function: zb_trans_transmit, channel: 21
D: Function: zb_trans_buffer_free
D: Received new Zigbee event: 0x01
Print Main loop
D: Received new Zigbee event: 0x02

[Maria Gilje]

Hi Pieter-Jan,

There is some more information we can get about which module the log is from. Enable CONFIG_LOG_MODE_DEFERRED=y to get a timestamp and a module name at the beginning of each logging output. In your log right now, the minimal log mode is active (only a letter indicating which logging level is printed).

You can also see how much buffer is used by adding the below code to your main.c and calling print_usage() in your while loop in main().

extern zb_buf_ent_t gc_iobuf_pool[ZB_CONFIG_IOBUF_POOL_SIZE];
extern zb_uint8_t gc_bufs_busy_bitmap[ZB_CONFIG_BUF_POOL_BITMAP_SIZE];

static void print_usage(void)
{
    size_t used = 0;
    for (size_t i = 0; i < ZB_CONFIG_BUF_POOL_BITMAP_SIZE; i++) {
        for (size_t j = 0; j < 8; j++) {
            if (gc_bufs_busy_bitmap[i] & (1 << j)) {
                used++;
            }
        }
    }

    printk("BUFs used: %d / %d\r\n", used, ZB_CONFIG_IOBUF_POOL_SIZE);
}

Best regards,

Maria

[pjbuntinx]

Hi Maria,

Below you can find the console with the extra debug logs. The device seems to always freeze at 19/32 buffers used. The amount of buffers used also does not decrease after waiting some time. 

SEGGER J-Link V7.94e - Real time terminal output
SEGGER J-Link (unknown) V1.0, SN=1050065421
Process: JLink.exe
BUFs used: 6 / 32
BUFs used: 6 / 32
Thread analyze:
 zboss               : STACK: unused 896 usage 1088 / 1984 (54 %); CPU: 0 %
      : Total CPU cycles used: 3352
 thread_analyzer     : STACK: unused 516 usage 444 / 960 (46 %); CPU: 0 %
      : Total CPU cycles used: 206
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 0
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 3
 nrf5_rx             : STACK: unused 360 usage 376 / 736 (51 %); CPU: 0 %
      : Total CPU cycles used: 7
 sysworkq            : STACK: unused 1616 usage 368 / 1984 (18 %); CPU: 0 %
      : Total CPU cycles used: 3824
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 40
 logging             : STACK: unused 1328 usage 720 / 2048 (35 %); CPU: 0 %
      : Total CPU cycles used: 883
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 98 %
      : Total CPU cycles used: 646254
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 415
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
BUFs used: 6 / 32
BUFs used: 6 / 32
BUFs used: 6 / 32
BUFs used: 6 / 32
BUFs used: 6 / 32
[00:00:25.967,742] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:25.967,864] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:25.969,604] <inf> zcl_modbus: Received
[00:00:25.970,123] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:25.973,754] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:25.974,456] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 7 / 32
[00:00:26.817,871] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:26.817,993] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:26.819,732] <inf> zcl_modbus: Received
[00:00:26.820,220] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:26.825,439] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:26.826,141] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 8 / 32
[00:00:27.306,945] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:27.307,037] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:27.578,002] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:27.578,125] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:27.580,047] <inf> zcl_modbus: Received
[00:00:27.580,535] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:27.585,449] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:27.586,151] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 9 / 32
[00:00:28.258,117] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:28.258,239] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:28.259,948] <inf> zcl_modbus: Received
[00:00:28.260,467] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:28.264,404] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:28.265,106] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[00:00:28.878,204] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:28.878,326] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:28.880,096] <inf> zcl_modbus: Received
[00:00:28.880,615] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:28.884,216] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:28.884,918] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 11 / 32
[00:00:29.708,343] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:29.708,465] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:29.710,205] <inf> zcl_modbus: Received
[00:00:29.710,693] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:29.714,080] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:29.714,813] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[00:00:30.037,689] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:30.042,266] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 12 / 32
Thread analyze:
 zboss               : STACK: unused 896 usage 1088 / 1984 (54 %); CPU: 0 %
      : Total CPU cycles used: 6027
 thread_analyzer     : STACK: unused 516 usage 444 / 960 (46 %); CPU: 0 %
      : Total CPU cycles used: 299
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 0
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 12
 nrf5_rx             : STACK: unused 360 usage 376 / 736 (51 %); CPU: 0 %
      : Total CPU cycles used: 30
 sysworkq            : STACK: unused 1616 usage 368 / 1984 (18 %); CPU: 0 %
      : Total CPU cycles used: 5748
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 40
 logging             : STACK: unused 1328 usage 720 / 2048 (35 %); CPU: 0 %
      : Total CPU cycles used: 1681
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 98 %
      : Total CPU cycles used: 967372
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 446
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
[00:00:30.908,538] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:30.908,660] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:30.910,430] <inf> zcl_modbus: Received
[00:00:30.910,919] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:30.915,832] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:30.916,534] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 13 / 32
[00:00:31.718,658] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:31.718,750] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:31.720,489] <inf> zcl_modbus: Received
[00:00:31.721,008] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:31.725,280] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:31.725,982] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 14 / 32
BUFs used: 14 / 32
[00:00:33.078,857] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:33.078,979] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:33.080,749] <inf> zcl_modbus: Received
[00:00:33.081,268] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:33.085,327] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:33.086,029] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 15 / 32
BUFs used: 15 / 32
[00:00:35.209,197] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:35.209,320] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:35.211,059] <inf> zcl_modbus: Received
[00:00:35.211,578] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:35.216,461] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:35.217,315] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 16 / 32
BUFs used: 16 / 32
[00:00:37.159,515] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:37.159,606] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:37.159,851] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 0a 02 7c 09 14 00  49 01 0b 03             |....|... I...    
[00:00:37.159,912] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 16 02 7c 09 15 00  18 00 6d 05 0e 00 00 00 |....|... ..m.....
                                     02 00 00 00 20 00 00 00                          |.... ...         
[00:00:37.161,651] <inf> zcl_modbus: Received
[00:00:37.162,200] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:37.165,802] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:37.166,717] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 17 / 32
BUFs used: 17 / 32
BUFs used: 17 / 32
      : Total CPU cycles used: 6856
--- 2 messages dropped ---
 thread_analyzer     : STACK: unused 516 usage 444 / 960 (46 %); CPU: 0 %
      : Total CPU cycles used: 393
 mcumgr smp          : STACK: unused 1856 usage 192 / 2048 (9 %); CPU: 0 %
      : Total CPU cycles used: 0
 rx_q[0]             : STACK: unused 1424 usage 176 / 1600 (11 %); CPU: 0 %
      : Total CPU cycles used: 20
 nrf5_rx             : STACK: unused 360 usage 376 / 736 (51 %); CPU: 0 %
      : Total CPU cycles used: 49
 sysworkq            : STACK: unused 1616 usage 368 / 1984 (18 %); CPU: 0 %
      : Total CPU cycles used: 7655
 MPSL Work           : STACK: unused 536 usage 424 / 960 (44 %); CPU: 0 %
      : Total CPU cycles used: 40
 logging             : STACK: unused 1328 usage 720 / 2048 (35 %); CPU: 0 %
      : Total CPU cycles used: 2413
 idle                : STACK: unused 272 usage 48 / 320 (15 %); CPU: 98 %
      : Total CPU cycles used: 1290425
 main                : STACK: unused 1312 usage 672 / 1984 (33 %); CPU: 0 %
      : Total CPU cycles used: 476
 ISR0                : STACK: unused 872 usage 1240 / 2112 (58 %)
[00:00:40.219,970] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:40.220,123] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:40.221,984] <inf> zcl_modbus: Received
[00:00:40.222,534] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:40.227,722] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:40.228,485] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 18 / 32
BUFs used: 18 / 32
[00:00:42.389,282] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:42.389,434] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:42.700,378] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x02
[00:00:42.700,531] <dbg> zboss_osif: zb_trans_get_next_packet: Function: zb_trans_get_next_packet
[00:00:42.702,545] <inf> zcl_modbus: Received
[00:00:42.703,094] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 21
[00:00:42.706,726] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[00:00:42.707,489] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
BUFs used: 19 / 32

[Maria Gilje]

Hi Pieter-Jan,

Thank you for the extra log.

I think that the reason for the freeze is that the TX buffers are all allocated and are not being deallocated. Even though the total amount of buffers are 32, only 16 can be used for TX at the same time, so the actual maximum is 16 + 16 for TX + RX. The sniffer log you sent previously showed that the application stopped to send ACKs when the freeze happened, and together with the 19/32 buffers used printout it is likely that the reason for the freeze is that the TX buffers are all allocated. See the Zigbee stack memory management subsystem documentation for more information on this.

Now to what you can do to resolve this:

Examine where you allocate buffers and ensure that you release them after the work is done with zb_buf_free. There is likely some place where you allocate a buffer, but do not release it after.

Best regards,

Maria

[pjbuntinx]

Hi Maria,

That was indeed the problem. I have readded a zb_buf_free statement that I had accidentally removed before. Thank you for your help!

Best Regards,

Pieter-Jan