Frozen zigbee network coordinator sample on nRF5340

Working on a zephyr/zigbee/802.15.4 system and my code (loosely based on the Nordic samples) on a custom device was not behaving as expected. 

So I broke out an nRF5340 DK, built and flashed the standard nrf/samples/zigbee/network_coordinator... Hmmm, nothing good there either, LED flashes forever, nothing else.

After managing to get some logging enabled, and peppering the codebase with crumbs I finally came to the attached trace (I added the 10 second delay at the start of main, just to have time to get all the logs, last line is where the hang is).

Short version: after calling zigbee_enable() execution eventually winds its way down to a call to zb_trans_transmit(), which lives in zigbee/osif/zb_nrf_transceiver.c, and then it's stuck there for all time.

In that function, it's getting caught on whatever radio_api->tx() is and just hanging indefinitely, specifically here:

switch (wait_type) {
        case ZB_MAC_TX_WAIT_CSMACA: {
                state_cache.radio_state = RADIO_802154_STATE_TRANSMIT;
                enum ieee802154_tx_mode mode;
                LOG_DBG("%s ZB_MAC_TX_WAIT_CSMACA", __func__);
                if (radio_api->get_capabilities(radio_dev)
                    & IEEE802154_HW_CSMA) {
                        mode = IEEE802154_TX_MODE_CSMA_CA;
                } else {
                        mode = IEEE802154_TX_MODE_CCA;
                }

                LOG_DBG("%s got caps mode %i. Calling radio_api->tx()...", __func__, mode);
                err = radio_api->tx(radio_dev, mode, pkt, &frag);
                LOG_DBG("%s tx called, ret %i", __func__, err);
                break;
        }
    /* ... */
    }


I am at a loss as to how to move forward at this point. 
I am building this with a pretty standard call to

west build -p auto \
    -b nrf5340dk_nrf5340_cpuapp \
    nrf/samples/zigbee/network_coordinator
    

and flashing it as per the usual (directly through the DK, or using a j-link for my boards).

I think the zboss stuff is closed source, or at least distributed as some binary blob (ugh), so I'm not sure how to get further toward resolving this. 

Any ideas how to resolve or at least debug further?

# SEGGER J-Link RTT Viewer V7.58d Terminal Log File
# Compiled: 15:28:47 on Dec  2 2021
# Logging started @ 20 Dec 2021 05:37:54
00> [00:00:00.400,146] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
00> [00:00:00.400,482] <dbg> zboss_osif.zb_trans_set_auto_ack: Function: zb_trans_set_auto_ack, enabled: 1
00> [00:00:00.434,020] <dbg> zboss_osif.
00>                                     de ad 0a 02 00 00 00 00  77 00 b3 00             |........ w...    
00> [00:00:00.434,844] <dbg> zboss_osif.
00>                                     de ad 26 02 00 00 01 00  77 00 b7 00 14 0f 00 00 |..&..... w.......
00>                                     c4 00 00 00 10 00 00 00  00 03 00 00 54 02 00 00 |........ ....T...
00>                                     98 01 00 00 64 02 00 00                          |....d...         
00> [00:00:00.436,828] <dbg> zboss_osif.
00>                                     de ad 0e 02 00 00 02 00  77 00 c0 00 02 00 00 00 |........ w.......
00> [00:00:00.437,713] <dbg> zboss_osif.
00>                                     de ad 0e 02 00 00 03 00  77 00 c2 00 c0 02 00 00 |........ w.......
00> [00:00:00.438,59[00:00:10.616,180] <inf> app: Starting ZBOSS Coordinator example
00> [00:00:10.616,699] <dbg> zboss_osif.
00>                                     de ad 0e 02 04 00 0c 00  90 0c 55 01 01 00 00 00 |........ ..U.....
00> [00:00:10.617,584] <inf> zboss_osif: zigbee_enable created zboss thread
00> [00:00:10.617,950] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 0, len: 12
00> [00:00:10.618,408] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 12, len: 4
00> [00:00:10.618,865] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 16, len: 8
00> [00:00:10.619,293] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 0, len: 12
00> [00:00:10.619,750] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 12, len: 4
00> [00:00:10.620,208] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 16, len: 8
00> [00:00:10.620,635] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 0, len: 12
00> [00:00:10.626,190] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 12, len: 4
00> [00:00:10.626,617] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 16, len: 8
00> [00:00:10.627,075] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 24, len: 12
00> [00:00:10.632,598] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 52, len: 8
00> [00:00:10.633,056] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 60, len: 12
00> [00:00:10.633,514] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 88, len: 8
00> [00:00:10.633,941] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 96, len: 12
00> [00:00:10.634,399] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 124, len: 8
00> [00:00:10.634,857] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 132, len: 12
00> [00:00:10.635,314] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 160, len: 8
00> [00:00:10.635,772] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 168, len: 12
00> [00:00:10.636,230] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 196, len: 8
00> [00:00:10.636,688] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 204, len: 12
00> [00:00:10.642,211] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 232, len: 8
00> [00:00:10.642,669] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 240, len: 12
00> [00:00:10.643,127] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 268, len: 8
00> [00:00:10.643,585] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 276, len: 12
00> [00:00:10.644,042] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 304, len: 8
00> [00:00:10.649,566] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 312, len: 12
00> [00:00:10.650,024] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 340, len: 8
00> [00:00:10.650,482] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 348, len: 12
00> [00:00:10.650,939] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 376, len: 8
00> [00:00:10.651,397] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 384, len: 12
00> [00:00:10.651,855] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 412, len: 8
00> [00:00:10.657,379] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 420, len: 12
00> [00:00:10.657,836] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 448, len: 8
00> [00:00:10.658,294] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 456, len: 12
00> [00:00:10.663,848] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 484, len: 8
00> [00:00:10.664,306] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 492, len: 12
00> [00:00:10.664,764] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 0, len: 12
00> [00:00:10.665,191] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 12, len: 4
00> [00:00:10.665,649] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 16, len: 8
00> [00:00:10.666,076] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 1, pos: 24, len: 12
00> [00:00:10.666,564] <dbg> zboss_osif.zb_osif_nvram_read: Function: zb_osif_nvram_read, page: 0, pos: 468, len: 16
00> [00:00:10.667,083] <dbg> zboss_osif.
00>                                     de ad 0a 02 04 00 0d 00  0b 00 8c 00             |........ ....    
00> [00:00:10.667,907] <dbg> zboss_osif.
00>                                     de ad 0a 02 04 00 0e 00  0b 00 20 02             |........ .. .    
00> [00:00:10.668,731] <dbg> zboss_osif.zb_osif_nvram_write: Function: zb_osif_nvram_write, page: 0, pos: 492, len: 12
00> [00:00:10.674,407] <dbg> zboss_osif.zb_osif_nvram_write: Function: zb_osif_nvram_write, page: 0, pos: 504, len: 16
00> [00:00:10.675,079] <dbg> zboss_osif.zb_osif_nvram_write: Function: zb_osif_nvram_write, page: 0, pos: 520, len: 8
00> [00:00:10.675,659] <inf> zboss_osif: z
00> [00:00:10.676,147] <inf> app: sighndl 23
00> [00:00:10.676,391] <inf> app: def
00> [00:00:10.676,605] <inf> zigbee_app_utils: Production configuration is not present or invalid (status: -1)
00> [00:00:10.677,001] <inf> app: NO JOIN
00> [00:00:10.677,703] <inf> app: sighndl 1
00> [00:00:10.677,947] <inf> app: def
00> [00:00:10.678,161] <inf> zigbee_app_utils: Zigbee stack initialized
00> [00:00:10.678,466] <inf> app: NO JOIN
00> [00:00:10.678,955] <dbg> zboss_osif.
00>                                     de ad 0e 02 04 00 0f 00  2b 08 94 03 01 00 00 00 |........ +.......
00> [00:00:10.686,889] <dbg> zboss_osif.zb_trans_set_pan_id: Function: zb_trans_set_pan_id, PAN ID: 0xffff
00> [00:00:[00:00:10.688,415] <dbg> zboss_osif.zb_trans_set_long_addr: Function: zb_trans_set_long_addr, long addr: 0x77
00> 10.687,[00:00:10.690,124] <dbg> zboss_osif.
00>                                     de ad 1e 02 04 00 10 00  3e 00 53 01 00 00 00 00 |........ >.S.....
00>                                     00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> [00:00:10.691,955] <dbg> zboss_osif.
00>                                     de ad 0a 02 05 00 11 00  3e 00 8e 01             |........ >...    
00> [00:00:10.694,244] <dbg> zboss_osif.
00>                                     de ad 12 02 05 00 12 00  3e 00 f3 01 05 00 00 00 |........ >.......
00>                                     00 00 00 00                                      |....             
00> [00:00:10.695,587] <inf> app: sighndl 5
00> [00:00:10.695,831] <inf> app: def
00> [00:00:10.696,044] <inf> zigbee_app_utils: Device started for the first time
00> [00:00:10.696,380] <inf> zigbee_app_utils: Start network formation (top lev commissionning)
00> [00:00:10.696,716] <inf> app: NO JOIN
00> [00:00:10.697,052] <dbg> zboss_o77] <inf> [00:00:10.701,202] <dbg> zboss_osif.zb_trans_set_short_addr: Function: zb_trans_set_short_addr, 0xfffe
00> app: ZBOSS Coordina[00:00:10.701,995] <dbg> zboss_osif.zb_trans_set_long_addr: Function: zb_trans_set_long_addr, long addr: 0x77
00> tor example started00:00:10.703,704] <dbg> zboss_osif.
00>                                     de ad 1e 02 05 00 14 00  3e 00 53 01 00 00 00 00 |........ >.S.....
00>                                     00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
00> [00:00:10.705,505] <dbg> zboss_osif.
00>                                     de ad 0a 02 05 00 15 00  3e 00 8e 01             |........ >...    
00> [00:00:10.707,427] <dbg> zboss_osif.
00>                                     de ad 0a 02 05 00 16 00  35 00 c1 00             |........ 5...    
00> [00:00:10.708,435] <dbg> zboss_osif.zb_trans_set_pan_id: Function: zb_trans_set_pan_id, PAN ID: 0xffff
00> 0m
00> [00:00:10.709,106] <dbg> zboss_osif.zb_trans_set_tx_power: Function: zb_trans_set_tx_power, power: 20
00> [00:00:10.709,716] <dbg> zboss_osif.zb_trans_get_tx_power: Function: zb_trans_get_tx_power, power: 20
00> [00:00:10.710,113] <dbg> zboss_osif.zb_trans_set_channel: Function: zb_trans_set_channel, channel number: 16
00> [00:00:10.710,754] <dbg> zboss_osif.zb_trans_enter_receive: Function: zb_trans_enter_receive
00> [00:00:10.711,486] <dbg> zboss_osif.zb_trans_transmit: Function: zb_trans_transmit, channel: 16
00> [00:00:10.711,914] <dbg> zboss_osif.zb_trans_transmit: zb_trans_transmit ZB_MAC_TX_WAIT_CSMACA
00> [00:00:10.712,280] <dbg> zboss_osif.zb_trans_transmit: zb_trans_transmit got caps mode 2. Calling radio_api->tx()...

Related