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

[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