Zigbee net coordinator crashes on first beacon request

Hello,

We're building zigbee devices around the nRF5340 with the nRF SDK/zboss/zephyr.  I'm working on custom boards and have based my 802154 code around the samples in nrf/samples/zigbee.

Though running atop those custom boards, I kept the light_switch and network_coordinator pretty much as-is and was running each on a distinct PCB.  Things weren't working out, so I started looking at each component in turn, to finally find this:

In this example, I'm monitoring the network coordinator with a debugger and sniffing zigbee packets over the air.  I let it run for a minute and all is well.  As soon as I turn on the light_switch, a beacon request is made and crash! A sample of the logs is attached below for reference.

In attempting to trace where the problem lies, I've peppered the nrf/zephyr code with extra bread crumbs.  The "zboss_osif: zbooslooop" (typos make it easy to grep ;-) ) before every call to zboss_main_loop_iteration() in the zboss_thread.  The "zignetco: DEFHNDL" is from every time the network controller's zboss_signal_handler callback is triggered but just passes the signal along to zigbee_default_signal_handler().

Crashes always seem to happen in the same sequence: a beacon request or whatever commissioning stuff arrives through the aether, zboss main loop triggers my signal handler, which passes it back to zigbee_default_signal_handler() which wants to get the goods from the spinel IPC thing and... death.

I have played with

  • CONFIG_HEAP_MEM_POOL_SIZE
  • CONFIG_MAIN_STACK_SIZE
  • CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE

to no avail.  I eventually thought it was my own system stuff, tried to simplify and just use standard vanilla network_controller code on standard vanilla nRF5340DK... that just led me to posting this:
https://devzone.nordicsemi.com/f/nordic-q-a/82962/frozen-zigbee-network-coordinator-sample-on-nrf5340

so no love there, but oddly in that case I can't get anything working at all.

Of course, to not be completely blind in trying to debug all this, I had to disable the default LOG_MINIMAL stuff (not sure what the idea is there, hard to dev without some sort of feedback), and all the interaction between mcuboot and the network processor and I dunno what makes using the serial logging harder to deal with than I care, but I did manage to get the segger RTT debug stuff working--don't know if that has an impact on anything.

For reference, I'm using a relatively fresh codebase, zephyr-sdk-0.13.2 and nrf/VERSION says 1.8.0-rc1 (last commit 053f939f0478b68ba6da4d01f3ebd463c111ee00, Pavel Vasilyev, Dec 2 16:49:27 2021).

Neither my straight port of the network coordinator nor the default code on the default platform are behaving well: people must be using this stuff, I feel like I'm missing something obvious... Any clues as to what's going on, where to look, what to tweak would be appreciated.

# SEGGER J-Link RTT Viewer V7.58d Terminal Log File
# Compiled: 15:28:47 on Dec  2 2021
# Logging started @ 20 Dec 2021 14:01:53
00> [00:00:00.843,688] <dbg> nrf5340_outoflow.remoteproc_mgr_boot: Network MCU released.
00> [00:00:00.850,463] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:00.850,921] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 4 bytes directly
00> [00:00:00.851,440] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 8 bytes.
00> [00:00:00.851,837] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:00.852,294] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
00> [00:00:00.852,600] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:00.853,057] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 5 bytes directly
00> [00:00:00.853,576] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> outoflow init done.
00> 
00> OUTOFLOW Driver startupSetting pin 30 to 0
00> 
00> Setting pin 11 to 0
00> 
00> Adding basic curve to sched... ANIM set black
00> 
00> done
00> 
00> Adding basic curve to sched... ANIM set black
00> 
00> done
00> 
00> Adding basic curve to sched... ANIM set black
00> 
00> done
00> 
00> Setting pin 6 to 0
00> 
00> Setting pin 7 to 0
00> 
00> Setting pin 4 to 0
00> 
00> Setting pin 5 to 0
00> 
00> Prepping IOSpecs for ext switches... 
00> 
00>   adding pin 9 to spec list
00> 
00>   adding pin 10 to spec list
00> 
00>   adding pin 8 to spec list
00> 
00>   adding pin 25 to spec list
00> 
00> DIG input ctor w pin 9
00> 
00> DIG input ctor w pin 10
00> 
00> DIG input ctor w pin 8
00> 
00> DIG input ctor w pin 25
00> 
00> EXT inputs ctrl begin
00> 
00> DIG input ctor w pin 5
00> 
00> Setting pin 26 to 0
00> 
00> ext input 0
00> 
00> ext input 1
00> 
00> ext input 2
00> 
00> ext input 3
00> 
00> ANIM set heartbeat
00> 
00> ANIM set heartbeat
00> 
00> ANIM set heartbeat
00> 
00> Acting as COORDINATOR---startup.
00> 
00> [00:00:04.505,218] <inf> zignetco: COORD STARTUP
00> hohoho indicate coord led cb 1
00> 
00> [00:00:04.505,676] <inf> zboss_osif: zigbee_enable created zboss thread
00> [00:00:04.510,406] <inf> zboss_osif: zbooslooop
00> [00:00:04.510,864] <inf> zignetco: DEFHNDL
00> [00:00:04.511,108] <inf> zigbee_app_utils: Production configuration is not present or invalid (status: -1)
00> [00:00:04.511,932] <inf> zignetco: DEFHNDL
00> [00:00:04.512,176] <inf> zigbee_app_utils: Zigbee stack initialized
00> [00:00:04.514,526] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.514,984] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 6 bytes directly
00> [00:00:04.515,502] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.515,899] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.516,937] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.517,395] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 6 bytes directly
00> [00:00:04.517,913] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.518,280] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.518,920] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.519,378] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 6 bytes directly
00> [00:00:04.519,897] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.520,294] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.520,904] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.526,336] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 12 bytes directly
00> [00:00:04.526,855] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.527,252] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.529,022] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.529,479] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 6 bytes directly
00> [00:00:04.529,998] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.530,395] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.530,944] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.531,402] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 5 bytes directly
00> [00:00:04.531,921] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.532,287] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.532,806] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.538,238] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 5 bytes directly
00> [00:00:04.538,757] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.539,154] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.539,581] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.540,039] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 5 bytes directly
00> [00:00:04.540,557] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.540,954] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.541,412] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.541,870] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 4 bytes directly
00> [00:00:04.542,449] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:04.547,821] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.548,278] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.548,706] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 12 bytes directly
00> [00:00:04.549,285] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.549,682] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.550,109] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.550,567] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 6 bytes directly
00> [00:00:04.551,086] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.556,427] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.556,884] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.557,342] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 6 bytes directly
00> [00:00:04.557,861] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:04.558,258] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.559,112] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.559,570] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 4 bytes directly
00> [00:00:04.565,093] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:04.565,490] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.566,650] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.567,108] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 4 bytes directly
00> [00:00:04.567,657] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:04.568,054] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.573,028] <inf> zignetco: REBOOT
00> [00:00:04.573,272] <inf> zignetco: Start network steering
00> [00:00:04.585,174] <inf> zboss_osif: zbooslooop
00> [00:00:04.585,449] <inf> zignetco: DEFHNDL
00> [00:00:04.595,886] <inf> zboss_osif: zbooslooop
00> [00:00:04.596,191] <inf> zignetco: DEFHNDL
00> [00:00:04.606,567] <inf> zboss_osif: zbooslooop
00> Outoflow startup OK
00> 
00> [00:00:04.616,943] <inf> zboss_osif: zbooslooop
00> [00:00:04.618,957] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:04.619,445] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 72 bytes directly
00> [00:00:04.620,025] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:04.620,422] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:04.624,328] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 27 bytes.
00> [00:00:04.634,887] <inf> zboss_osif: zbooslooop
00> [00:00:04.645,294] <inf> zboss_osif: zbooslooop
00> [00:00:04.655,670] <inf> zboss_osif: zbooslooop
00> [00:00:04.666,137] <inf> zboss_osif: zbooslooop
00> [00:00:04.666,442] <inf> zignetco: DEFHNDL
00> [00:00:04.676,879] <inf> zboss_osif: zbooslooop
00> [00:00:04.677,185] <inf> zignetco: DEFHNDL
00> [00:00:04.687,561] <inf> zboss_osif: zbooslooop
00> [00:00:04.697,937] <inf> zboss_osif: zbooslooop
00> [00:00:04.708,404] <inf> zboss_osif: zbooslooop
00> [00:00:04.708,709] <inf> zignetco: DEFHNDL
00> Running main loop.
00> 
00> Hohoho sensor triggered for 512
00> 
00> Hohoho value is 0
00> 
00> Hohoho sensor triggered for 1024
00> 
00> Hohoho value is 0
00> 
00> Hohoho sensor triggered for 256
00> 
00> Hohoho value is 0
00> 
00> Hohoho sensor triggered for 33554432
00> 
00> Hohoho value is 0
00> 
00> ANIM set net coordinator
00> 
00> LED EN: Activity trig
00> 
00> [00:00:04.746,795] <inf> adi_adp8866: Re-trig low level setup...
00> [00:00:04.747,314] <inf> adi_adp8866: backlight set
00> [00:00:04.747,680] <inf> adi_adp8866: ICS fade rate set
00> [00:00:04.748,046] <inf> adi_adp8866: backlight fade rate set
00> [00:00:04.748,443] <inf> adi_adp8866: ISCC1 set
00> [00:00:04.748,779] <inf> adi_adp8866: ISCC2 set
00> [00:00:04.749,206] <inf> zboss_osif: zbooslooop
00> [00:00:04.749,908] <inf> adi_adp8866: GOT stat 32
00> [00:00:04.750,183] <inf> adi_adp8866: SETUP DONE
00> [00:00:04.759,674] <inf> zboss_osif: zbooslooop
00> [00:00:04.759,948] <inf> zignetco: DEFHNDL
00> [00:00:04.800,476] <inf> zboss_osif: zbooslooop
00> [00:00:04.800,781] <inf> zignetco: DEFHNDL
00> [00:00:04.811,157] <inf> zboss_osif: zbooslooop
00> [00:00:04.821,533] <inf> zboss_osif: zbooslooop
00> [00:00:04.832,000] <inf> zboss_osif: zbooslooop
00> [00:00:04.832,305] <inf> zignetco: DEFHNDL
00> [00:00:04.872,833] <inf> zboss_osif: zbooslooop
00> [00:00:04.873,138] <inf> zignetco: DEFHNDL
00> [00:00:04.883,514] <inf> zboss_osif: zbooslooop
00> [00:00:04.893,890] <inf> zboss_osif: zbooslooop
00> [00:00:04.904,357] <inf> zboss_osif: zbooslooop
00> [00:00:04.904,663] <inf> zignetco: DEFHNDL
00> [00:00:04.945,190] <inf> zboss_osif: zbooslooop
00> [00:00:04.945,495] <inf> zignetco: DEFHNDL
00> [00:00:04.955,871] <inf> zboss_osif: zbooslooop
00> [00:00:04.966,247] <inf> zboss_osif: zbooslooop
00> [00:00:04.976,715] <inf> zboss_osif: zbooslooop
00> [00:00:04.977,020] <inf> zignetco: DEFHNDL
00> [00:00:05.017,547] <inf> zboss_osif: zbooslooop
00> [00:00:05.017,852] <inf> zignetco: DEFHNDL
00> [00:00:05.028,228] <inf> zboss_osif: zbooslooop
00> [00:00:05.038,604] <inf> zboss_osif: zbooslooop
00> [00:00:05.049,072] <inf> zboss_osif: zbooslooop
00> [00:00:05.049,377] <inf> zignetco: DEFHNDL
00> [00:00:05.089,904] <inf> zboss_osif: zbooslooop
00> [00:00:05.090,209] <inf> zignetco: DEFHNDL
00> [00:00:05.100,585] <inf> zboss_osif: zbooslooop
00> [00:00:05.110,961] <inf> zboss_osif: zbooslooop
00> [00:00:05.121,429] <inf> zboss_osif: zbooslooop
00> [00:00:05.121,734] <inf> zignetco: DEFHNDL
00> [00:00:05.153,442] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:05.153,900] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 72 bytes directly
00> [00:00:05.154,510] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:05.154,907] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:05.158,508] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 27 bytes.
00> [00:00:05.161,468] <inf> zignetco: STEERING
00> [00:00:05.161,712] <inf> zignetco: Network steering started
00> [00:00:05.172,271] <inf> zboss_osif: zbooslooop
00> [00:00:05.172,576] <inf> zignetco: DEFHNDL
00> ANIM set net join
00> 
00> [00:00:05.183,044] <inf> zboss_osif: zbooslooop
00> [00:00:05.183,319] <inf> zignetco: DEFHNDL
00> [00:00:05.699,798] <inf> zboss_osif: zbooslooop
00> [00:00:05.710,174] <inf> zboss_osif: zbooslooop
00> [00:00:05.720,672] <inf> zboss_osif: zbooslooop
00> [00:00:05.720,947] <inf> zignetco: DEFHNDL
00> [00:00:06.729,431] <inf> zboss_osif: zbooslooop
00> [00:00:06.739,929] <inf> zboss_osif: zbooslooop
00> [00:00:06.740,203] <inf> zignetco: DEFHNDL
00> ColCB for sched 1 complete... for led 1... 
00> 
00> [00:00:07.748,687] <inf> zboss_osif: zbooslooop
00> [00:00:07.759,155] <inf> zboss_osif: zbooslooop
00> [00:00:07.759,460] <inf> zignetco: DEFHNDL
00> [00:00:08.767,944] <inf> zboss_osif: zbooslooop
00> [00:00:08.778,442] <inf> zboss_osif: zbooslooop
00> [00:00:08.778,717] <inf> zignetco: DEFHNDL
00> [00:00:09.787,292] <inf> zboss_osif: zbooslooop
00> [00:00:09.797,760] <inf> zboss_osif: zbooslooop
00> [00:00:09.798,065] <inf> zignetco: DEFHNDL
00> ColCB for sched 1 complete... for led 1... 
00> 
00> Anim complete!
00> 
00> ANIM set black
00> 
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:10.806,549] <inf> zboss_osif: zbooslooop
00> [00:00:10.817,047] <inf> zboss_osif: zbooslooop
00> [00:00:10.817,321] <inf> zignetco: DEFHNDL
00> [00:00:11.825,805] <inf> zboss_osif: zbooslooop
00> [00:00:11.836,273] <inf> zboss_osif: zbooslooop
00> [00:00:11.836,578] <inf> zignetco: DEFHNDL
00> [00:00:12.845,062] <inf> zboss_osif: zbooslooop
00> [00:00:12.855,529] <inf> zboss_osif: zbooslooop
00> [00:00:12.855,834] <inf> zignetco: DEFHNDL
00> [00:00:13.634,307] <inf> zboss_osif: zbooslooop
00> [00:00:13.634,613] <inf> zignetco: DEFHNDL
00> [00:00:13.844,085] <inf> zboss_osif: zbooslooop
00> [00:00:13.854,461] <inf> zboss_osif: zbooslooop
00> [00:00:13.864,929] <inf> zboss_osif: zbooslooop
00> [00:00:13.865,234] <inf> zignetco: DEFHNDL
00> [00:00:14.873,748] <inf> zboss_osif: zbooslooop
00> [00:00:14.884,216] <inf> zboss_osif: zbooslooop
00> [00:00:14.884,521] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:15.893,005] <inf> zboss_osif: zbooslooop
00> [00:00:15.903,442] <inf> zboss_osif: zbooslooop
00> [00:00:15.903,747] <inf> zignetco: DEFHNDL
00> [00:00:16.912,231] <inf> zboss_osif: zbooslooop
00> [00:00:16.912,536] <inf> zignetco: DEFHNDL
00> [00:00:17.921,020] <inf> zboss_osif: zbooslooop
00> [00:00:17.921,325] <inf> zignetco: DEFHNDL
00> [00:00:18.944,824] <inf> zboss_osif: zbooslooop
00> [00:00:18.945,129] <inf> zignetco: DEFHNDL
00> [00:00:19.785,034] <inf> zboss_osif: zbooslooop
00> [00:00:19.785,339] <inf> zignetco: DEFHNDL
00> [00:00:19.817,047] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:19.817,504] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 63 bytes directly
00> [00:00:19.818,237] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:19.818,603] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:19.820,251] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 27 bytes.
00> [00:00:19.830,932] <inf> zboss_osif: zbooslooop
00> [00:00:19.831,268] <inf> zignetco: DEFHNDL
00> [00:00:19.841,674] <inf> zboss_osif: zbooslooop
00> [00:00:19.841,979] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:19.944,519] <inf> zboss_osif: zbooslooop
00> [00:00:19.944,824] <inf> zignetco: DEFHNDL
00> [00:00:20.799,346] <inf> zboss_osif: zbooslooop
00> [00:00:20.799,652] <inf> zignetco: DEFHNDL
00> [00:00:20.963,165] <inf> zboss_osif: zbooslooop
00> [00:00:20.963,470] <inf> zignetco: DEFHNDL
00> [00:00:21.818,023] <inf> zboss_osif: zbooslooop
00> [00:00:21.818,359] <inf> zignetco: DEFHNDL
00> [00:00:21.981,842] <inf> zboss_osif: zbooslooop
00> [00:00:21.982,147] <inf> zignetco: DEFHNDL
00> [00:00:22.836,669] <inf> zboss_osif: zbooslooop
00> [00:00:22.837,005] <inf> zignetco: DEFHNDL
00> [00:00:23.000,518] <inf> zboss_osif: zbooslooop
00> [00:00:23.000,823] <inf> zignetco: DEFHNDL
00> [00:00:23.855,346] <inf> zboss_osif: zbooslooop
00> [00:00:23.855,651] <inf> zignetco: DEFHNDL
00> [00:00:24.019,165] <inf> zboss_osif: zbooslooop
00> [00:00:24.019,470] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:24.873,992] <inf> zboss_osif: zbooslooop
00> [00:00:24.874,298] <inf> zignetco: DEFHNDL
00> [00:00:25.037,841] <inf> zboss_osif: zbooslooop
00> [00:00:25.038,146] <inf> zignetco: DEFHNDL
00> [00:00:25.892,669] <inf> zboss_osif: zbooslooop
00> [00:00:25.892,974] <inf> zignetco: DEFHNDL
00> [00:00:26.056,488] <inf> zboss_osif: zbooslooop
00> [00:00:26.056,793] <inf> zignetco: DEFHNDL
00> [00:00:26.911,315] <inf> zboss_osif: zbooslooop
00> [00:00:26.911,621] <inf> zignetco: DEFHNDL
00> [00:00:27.075,103] <inf> zboss_osif: zbooslooop
00> [00:00:27.075,408] <inf> zignetco: DEFHNDL
00> ColCB for sched 0 complete... for led 0... 
00> 
00> [00:00:27.929,931] <inf> zboss_osif: zbooslooop
00> [00:00:27.930,236] <inf> zignetco: DEFHNDL
00> [00:00:28.093,750] <inf> zboss_osif: zbooslooop
00> [00:00:28.094,055] <inf> zignetco: DEFHNDL
00> [00:00:28.948,577] <inf> zboss_osif: zbooslooop
00> [00:00:28.948,883] <inf> zignetco: DEFHNDL
00> [00:00:29.112,396] <inf> zboss_osif: zbooslooop
00> [00:00:29.112,701] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:29.967,254] <inf> zboss_osif: zbooslooop
00> [00:00:29.967,559] <inf> zignetco: DEFHNDL
00> [00:00:30.131,103] <inf> zboss_osif: zbooslooop
00> [00:00:30.131,408] <inf> zignetco: DEFHNDL
00> ColCB for sched 1 complete... for led 1... 
00> 
00> [00:00:30.985,900] <inf> zboss_osif: zbooslooop
00> [00:00:30.986,206] <inf> zignetco: DEFHNDL
00> [00:00:31.149,688] <inf> zboss_osif: zbooslooop
00> [00:00:31.149,993] <inf> zignetco: DEFHNDL
00> [00:00:32.173,461] <inf> zboss_osif: zbooslooop
00> [00:00:32.173,767] <inf> zignetco: DEFHNDL
00> [00:00:33.182,250] <inf> zboss_osif: zbooslooop
00> [00:00:33.182,556] <inf> zignetco: DEFHNDL
00> [00:00:34.206,054] <inf> zboss_osif: zbooslooop
00> [00:00:34.206,359] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:34.877,258] <inf> zboss_osif: zbooslooop
00> [00:00:34.877,563] <inf> zignetco: DEFHNDL
00> [00:00:34.909,271] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:34.909,729] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 63 bytes directly
00> [00:00:34.910,339] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:34.910,736] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:34.914,703] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 27 bytes.
00> [00:00:34.925,384] <inf> zboss_osif: zbooslooop
00> [00:00:34.925,689] <inf> zignetco: DEFHNDL
00> [00:00:34.936,126] <inf> zboss_osif: zbooslooop
00> [00:00:34.936,431] <inf> zignetco: DEFHNDL
00> [00:00:35.222,961] <inf> zboss_osif: zbooslooop
00> [00:00:35.223,266] <inf> zignetco: DEFHNDL
00> [00:00:35.908,782] <inf> zboss_osif: zbooslooop
00> [00:00:35.909,088] <inf> zignetco: DEFHNDL
00> [00:00:36.241,607] <inf> zboss_osif: zbooslooop
00> [00:00:36.241,912] <inf> zignetco: DEFHNDL
00> [00:00:36.927,429] <inf> zboss_osif: zbooslooop
00> [00:00:36.927,734] <inf> zignetco: DEFHNDL
00> [00:00:37.260,253] <inf> zboss_osif: zbooslooop
00> [00:00:37.260,559] <inf> zignetco: DEFHNDL
00> [00:00:37.946,075] <inf> zboss_osif: zbooslooop
00> [00:00:37.946,380] <inf> zignetco: DEFHNDL
00> [00:00:38.278,900] <inf> zboss_osif: zbooslooop
00> [00:00:38.279,205] <inf> zignetco: DEFHNDL
00> [00:00:38.964,721] <inf> zboss_osif: zbooslooop
00> [00:00:38.965,026] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:39.297,546] <inf> zboss_osif: zbooslooop
00> [00:00:39.297,851] <inf> zignetco: DEFHNDL
00> [00:00:39.983,367] <inf> zboss_osif: zbooslooop
00> [00:00:39.983,673] <inf> zignetco: DEFHNDL
00> [00:00:40.316,223] <inf> zboss_osif: zbooslooop
00> [00:00:40.316,528] <inf> zignetco: DEFHNDL
00> [00:00:41.002,044] <inf> zboss_osif: zbooslooop
00> [00:00:41.002,380] <inf> zignetco: DEFHNDL
00> [00:00:41.334,869] <inf> zboss_osif: zbooslooop
00> [00:00:41.335,205] <inf> zignetco: DEFHNDL
00> [00:00:42.020,721] <inf> zboss_osif: zbooslooop
00> [00:00:42.021,057] <inf> zignetco: DEFHNDL
00> [00:00:42.353,576] <inf> zboss_osif: zbooslooop
00> [00:00:42.353,881] <inf> zignetco: DEFHNDL
00> [00:00:43.039,398] <inf> zboss_osif: zbooslooop
00> [00:00:43.039,703] <inf> zignetco: DEFHNDL
00> [00:00:43.372,222] <inf> zboss_osif: zbooslooop
00> [00:00:43.372,558] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:44.058,074] <inf> zboss_osif: zbooslooop
00> [00:00:44.058,380] <inf> zignetco: DEFHNDL
00> [00:00:44.390,899] <inf> zboss_osif: zbooslooop
00> [00:00:44.391,204] <inf> zignetco: DEFHNDL
00> [00:00:45.076,721] <inf> zboss_osif: zbooslooop
00> [00:00:45.077,026] <inf> zignetco: DEFHNDL
00> [00:00:45.409,606] <inf> zboss_osif: zbooslooop
00> [00:00:45.409,912] <inf> zignetco: DEFHNDL
00> [00:00:46.095,428] <inf> zboss_osif: zbooslooop
00> [00:00:46.095,733] <inf> zignetco: DEFHNDL
00> [00:00:46.428,222] <inf> zboss_osif: zbooslooop
00> [00:00:46.428,527] <inf> zignetco: DEFHNDL
00> [00:00:47.451,995] <inf> zboss_osif: zbooslooop
00> [00:00:47.452,301] <inf> zignetco: DEFHNDL
00> [00:00:48.460,784] <inf> zboss_osif: zbooslooop
00> [00:00:48.461,090] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:49.484,588] <inf> zboss_osif: zbooslooop
00> [00:00:49.484,893] <inf> zignetco: DEFHNDL
00> ColCB for sched 0 complete... for led 0... 
00> 
00> [00:00:49.955,810] <inf> zboss_osif: zbooslooop
00> [00:00:49.956,115] <inf> zignetco: DEFHNDL
00> [00:00:49.987,823] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:49.988,311] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 63 bytes directly
00> [00:00:49.988,922] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:49.989,318] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:49.991,668] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 27 bytes.
00> [00:00:50.002,349] <inf> zboss_osif: zbooslooop
00> [00:00:50.002,655] <inf> zignetco: DEFHNDL
00> [00:00:50.013,092] <inf> zboss_osif: zbooslooop
00> [00:00:50.013,397] <inf> zignetco: DEFHNDL
00> [00:00:50.499,938] <inf> zboss_osif: zbooslooop
00> [00:00:50.500,244] <inf> zignetco: DEFHNDL
00> ColCB for sched 1 complete... for led 1... 
00> 
00> [00:00:50.986,755] <inf> zboss_osif: zbooslooop
00> [00:00:50.987,060] <inf> zignetco: DEFHNDL
00> [00:00:51.519,531] <inf> zboss_osif: zbooslooop
00> [00:00:51.519,836] <inf> zignetco: DEFHNDL
00> [00:00:52.006,347] <inf> zboss_osif: zbooslooop
00> [00:00:52.006,652] <inf> zignetco: DEFHNDL
00> [00:00:52.539,154] <inf> zboss_osif: zbooslooop
00> [00:00:52.539,459] <inf> zignetco: DEFHNDL
00> [00:00:53.025,970] <inf> zboss_osif: zbooslooop
00> [00:00:53.026,275] <inf> zignetco: DEFHNDL
00> [00:00:53.558,776] <inf> zboss_osif: zbooslooop
00> [00:00:53.559,082] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:54.045,593] <inf> zboss_osif: zbooslooop
00> [00:00:54.045,898] <inf> zignetco: DEFHNDL
00> [00:00:54.578,399] <inf> zboss_osif: zbooslooop
00> [00:00:54.578,704] <inf> zignetco: DEFHNDL
00> [00:00:55.065,216] <inf> zboss_osif: zbooslooop
00> [00:00:55.065,521] <inf> zignetco: DEFHNDL
00> [00:00:55.598,052] <inf> zboss_osif: zbooslooop
00> [00:00:55.598,358] <inf> zignetco: DEFHNDL
00> [00:00:56.084,869] <inf> zboss_osif: zbooslooop
00> [00:00:56.085,174] <inf> zignetco: DEFHNDL
00> [00:00:56.617,675] <inf> zboss_osif: zbooslooop
00> [00:00:56.617,980] <inf> zignetco: DEFHNDL
00> [00:00:57.104,492] <inf> zboss_osif: zbooslooop
00> [00:00:57.104,797] <inf> zignetco: DEFHNDL
00> [00:00:57.637,298] <inf> zboss_osif: zbooslooop
00> [00:00:57.637,603] <inf> zignetco: DEFHNDL
00> [00:00:58.124,114] <inf> zboss_osif: zbooslooop
00> [00:00:58.124,420] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:00:58.656,921] <inf> zboss_osif: zbooslooop
00> [00:00:58.657,226] <inf> zignetco: DEFHNDL
00> [00:00:59.143,737] <inf> zboss_osif: zbooslooop
00> [00:00:59.144,042] <inf> zignetco: DEFHNDL
00> [00:00:59.676,544] <inf> zboss_osif: zbooslooop
00> [00:00:59.676,879] <inf> zignetco: DEFHNDL
00> [00:01:00.163,391] <inf> zboss_osif: zbooslooop
00> [00:01:00.163,696] <inf> zignetco: DEFHNDL
00> [00:01:00.696,228] <inf> zboss_osif: zbooslooop
00> [00:01:00.696,533] <inf> zignetco: DEFHNDL
00> [00:01:01.183,013] <inf> zboss_osif: zbooslooop
00> [00:01:01.183,319] <inf> zignetco: DEFHNDL
00> [00:01:01.715,789] <inf> zboss_osif: zbooslooop
00> [00:01:01.716,094] <inf> zignetco: DEFHNDL
00> [00:01:02.739,562] <inf> zboss_osif: zbooslooop
00> [00:01:02.739,868] <inf> zignetco: DEFHNDL
00> ColCB for sched 2 complete... for led 2... 
00> 
00> [00:01:03.748,352] <inf> zboss_osif: zbooslooop
00> [00:01:03.748,657] <inf> zignetco: DEFHNDL
00> [00:01:04.772,155] <inf> zboss_osif: zbooslooop
00> [00:01:04.772,460] <inf> zignetco: DEFHNDL
00> [00:01:05.044,372] <inf> zboss_osif: zbooslooop
00> [00:01:05.044,677] <inf> zignetco: DEFHNDL
00> [00:01:05.076,385] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:01:05.076,843] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 63 bytes directly
00> [00:01:05.077,453] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:01:05.077,850] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:01:05.079,864] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 27 bytes.
00> [00:01:05.090,545] <inf> zboss_osif: zbooslooop
00> [00:01:05.090,850] <inf> zignetco: DEFHNDL
00> [00:01:05.101,287] <inf> zboss_osif: zbooslooop
00> [00:01:05.101,593] <inf> zignetco: DEFHNDL
00> [00:01:05.787,139] <inf> zboss_osif: zbooslooop
00> [00:01:05.787,445] <inf> zignetco: DEFHNDL
00> [00:01:06.073,944] <inf> zboss_osif: zbooslooop
00> [00:01:06.074,249] <inf> zignetco: DEFHNDL
00> [00:01:06.805,755] <inf> zboss_osif: zbooslooop
00> [00:01:06.806,060] <inf> zignetco: DEFHNDL
00> [00:01:07.092,559] <inf> zboss_osif: zbooslooop
00> [00:01:07.092,864] <inf> zignetco: DEFHNDL
00> [00:01:07.644,195] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 30 bytes.
00> [00:01:07.644,653] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:01:07.645,111] <err> os: ***** USAGE FAULT *****
00> [00:01:07.645,385] <err> os:   Stack overflow (context area not valid)
00> [00:01:07.645,690] <err> os: r0/a1:  0x00000000  r1/a2:  0x00000000  r2/a3:  0x00000000
00> [00:01:07.646,057] <err> os: r3/a4:  0x00000000 r12/ip:  0x0000005b r14/lr:  0x0000005b
00> [00:01:07.646,423] <err> os:  xpsr:  0x00000400
00> [00:01:07.646,667] <err> os: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
00> [00:01:07.647,125] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
00> [00:01:07.647,583] <err> os: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
00> [00:01:07.648,040] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
00> [00:01:07.648,529] <err> os: fpscr:  0x00000000
00> [00:01:07.648,773] <err> os: Faulting instruction address (r15/pc): 0x0004a021
00> [00:01:07.649,078] <err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0
00> [00:01:07.649,414] <err> os: Current thread: 0x20000d80 (unknown)
00> [00:01:07.659,698] [1;31m<err> fatal_error: Resetting system
00> [00:00:00.253,845] <dbg> nrf5340_outoflow.remoteproc_mgr_boot: Network MCU released.
00> [00:00:00.260,467] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:00.260,925] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 4 bytes directly
00> [00:00:00.261,444] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 8 bytes.
00> [00:00:00.261,840] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:00.262,298] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
00> [00:00:00.262,603] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:00.263,061] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 5 bytes directly
00> [00:00:00.263,549] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:00.263,946] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:00.264,404] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:00.264,831] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 5 bytes directly
00> [00:00:00.270,324] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 4 bytes.
00> [00:00:00.270,721] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier
00> [00:00:00.301,849] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_lock_before_request: Locking response notifier
00> [00:00:00.302,307] <dbg> spinel_ipc_backend.nrf_802154_spinel_encoded_packet_send: Sending 4 bytes directly
00> [00:00:00.302,856] <dbg> spinel_ipc_backend.endpoint_cb: PSYHo message of 5 bytes.
00> [00:00:00.303,222] <dbg> spinel_ipc_backend_rsp_ntf.nrf_802154_spinel_response_notifier_property_await: Unlockling response notifier

Parents
  • FYI have been informed the sdk-nrf was a bit out of date and have updated that to latest.  Still has same behaviour.

    I can debug the code and put,e.g. a breakpoint on main, say.  Doing that, it will just keep running happily until a plug in the light_switch.  A few seconds later, I'm back at breakpoint 1, main()--the chip is reset and I've lost all info pertaining to why.

    When I try to nail it down and add bp to z_arm_fault()/z_fatal_error() instead I get thrown into z_arm_usage_fault() when the light_switch comes online, but the backtrace is full of nothing and I'm not certain how to isolate the issue further.


    Is there any way to put in stack canaries or somesuch to aid in isolating what's tripping this?  Which is CPU 0, anyway?  Any help appreciated.

Reply
  • FYI have been informed the sdk-nrf was a bit out of date and have updated that to latest.  Still has same behaviour.

    I can debug the code and put,e.g. a breakpoint on main, say.  Doing that, it will just keep running happily until a plug in the light_switch.  A few seconds later, I'm back at breakpoint 1, main()--the chip is reset and I've lost all info pertaining to why.

    When I try to nail it down and add bp to z_arm_fault()/z_fatal_error() instead I get thrown into z_arm_usage_fault() when the light_switch comes online, but the backtrace is full of nothing and I'm not certain how to isolate the issue further.


    Is there any way to put in stack canaries or somesuch to aid in isolating what's tripping this?  Which is CPU 0, anyway?  Any help appreciated.

Children
No Data
Related