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()...
