ZigBee Application crash - ERROR 29 [RET_OVERFLOW] at [...]zigbee_app_utils.c:849

[Rogger]

Application crashes with the following log

[06:45:22.727,691] <err> zigbee_app_utils: ERROR 29 [RET_OVERFLOW] at WEST_TOPDIR/nrf/subsys/zigbee/lib/zigbee_app_utils/zigbee_app_utils.c:849
[06:45:22.727,691] <err> zboss_osif: ZBOSS fatal error occurred

The relevant lines from zigbee_app_utils

 

#if defined CONFIG_ZIGBEE_ROLE_END_DEVICE
wait_for_user_input = false;
is_rejoin_start_scheduled = false;

zb_ret_t zb_err_code = ZB_SCHEDULE_APP_ALARM(
stop_network_rejoin,
ZB_TRUE,
ZB_MILLISECONDS_TO_BEACON_INTERVAL(
ZB_DEV_REJOIN_TIMEOUT_MS));
ZB_ERROR_CHECK(zb_err_code);
#endif

It seems that the Alarm cannot be scheduled due to RET_OVERFLOW.

- The implementation of the signal handler is here https://github.com/Rogger/schneggi-sensor/blob/64b2408f1053a15622c618249d887ca7694eb250/src/main.c#L704, in there is as well the call to app utils.

Context:

SDK & toolchain in use 2.5.0

Any help or guidance is highly appreciated, thank you in advance

Best Regards

Michael

[Elfving]

Hello Michael,

We are severely understaffed this week because of the Christmas holidays, and I will have to get back to you on this next week. Sorry for the inconvenience.

In the meantime, could you expand a bit on the network and in what situations the app is crashing like this?

Regards and happy holidays,

Elfving

[Elfving]

Hello again, and thank you for your patience.

Can you again tell me if this is based on any particular sample, what causes it to crash (or what happens leading up to this crash), and how often it happens? And if it happens all the time, or just some times? 

And what does the network consist of? 

Regards,

Elfving

[Rogger]

Hi Elfving,

Thanks for reaching out. I tried to limit the problem, it is pretty tricky since it takes several hours to run into the crash (and not consistently).

Can you again tell me if this is based on any particular sample, what causes it to crash (or what happens leading up to this crash), and how often it happens? And if it happens all the time, or just some times?

And what does the network consist of? 

• The crash happens every time after some hours (at different times, no patterns here).
• The network consists of an end device which is directly connected to the coordinator. The coordinator is a skyconnect stick with home assistant.
• I checked the ZigBee protocol logs from the coordinator (ZHA debug logs) and the network capture with Wireshark. I cannot see anything suspicious at this point.
• The issue might be triggered by low signal strength, but nothing that I can confirm.

I was able to reproduce the issue with the ZigBee light bulb example, by modifying the example in the following way:

• Changed the role from router to end device
• Set zigbee_configure_sleepy_behavior(true);

Any advice on how I could output more relevant logging or debug the problem would be highly appreciated!

Thank you in advance!

MR

[Rogger]

Hi Elfving,

I enabled the following logging options

CONFIG_ZIGBEE_APP_UTILS_LOG_LEVEL_DBG=y
CONFIG_ZBOSS_TRACE_LOG_LEVEL_INF=y
CONFIG_ZBOSS_OSIF_LOG_LEVEL_DBG=y

After 18:39 runtime I got a crash, now with more extensive logging. Does this make any sense to you?

[18:38:26.861,297] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 11
[18:38:26.864,593] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[18:38:26.864,685] <dbg> zboss_osif: zb_trans_enter_sleep: Function: zb_trans_enter_sleep
[18:38:26.864,959] <dbg> zboss_osif: zb_trans_enter_sleep: Function: zb_trans_enter_sleep
[18:38:26.865,020] <dbg> zboss_osif: zb_trans_enter_sleep: Function: zb_trans_enter_sleep
[18:38:26.865,295] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[18:38:28.970,062] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 11
[18:38:28.975,402] <dbg> zboss_osif: zb_trans_buffer_free: Function: zb_trans_buffer_free
[18:38:28.975,494] <dbg> zboss_osif: zb_trans_enter_sleep: Function: zb_trans_enter_sleep
[18:38:28.976,013] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[18:38:29.068,786] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 11
[18:38:29.072,326] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 0e 02 fd d8 bc 06  32 75 02 01 04 00 00 00 |........ 2u......
[18:38:29.095,520] <dbg> zboss_osif: zb_trans_enter_sleep: Function: zb_trans_enter_sleep
[18:38:29.095,855] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 11
--- 22 messages dropped ---
[18:38:29.128,875] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 cf 06  7c 00 39 03 02 00 00 00 |........ |.9.....
                                     b5 50 03 00 7b d9 42 00  00 00 00 00             |.P..{.B. ....    
[18:38:29.128,936] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d0 06  7c 00 39 03 0c 00 00 00 |........ |.9.....
                                     b5 50 03 00 83 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,028] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d1 06  7c 00 39 03 19 00 00 00 |........ |.9.....
                                     b5 50 03 00 8a d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,119] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d2 06  7c 00 39 03 17 00 00 00 |........ |.9.....
                                     b5 50 03 00 92 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,180] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d3 06  7c 00 39 03 11 00 00 00 |........ |.9.....
                                     b5 50 03 00 98 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,272] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d4 06  7c 00 39 03 0d 00 00 00 |........ |.9.....
                                     b5 50 03 00 a0 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,333] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d5 06  7c 00 39 03 18 00 00 00 |........ |.9.....
                                     b5 50 03 00 a7 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,425] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d6 06  7c 00 39 03 1e 00 00 00 |........ |.9.....
                                     b5 50 03 00 af d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.129,486] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d7 06  7c 00 39 03 16 00 00 00 |........ |.9.....
                                     f5 a3 03 00 b6 d9 42 00  00 00 00 00             |......B. ....    
[18:38:29.129,577] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d8 06  7c 00 39 03 0e 00 00 00 |........ |.9.....
                                     2d 4f 03 00 40 da 42 00  00 00 00 00             |[email protected]. ....    
[18:38:29.129,669] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 d9 06  7c 00 39 03 1f 00 00 00 |........ |.9.....
                                     2d 4f 03 00 4b da 42 00  00 00 00 00             |-O..K.B. ....    
[18:38:29.129,730] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 da 06  7c 00 39 03 1d 00 00 00 |........ |.9.....
                                     85 ec 03 00 5a 12 43 00  00 00 00 00             |....Z.C. ....    
[18:38:29.129,852] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 01 d9 db 06  7c 00 39 03 00 00 00 00 |........ |.9.....
                                     ad 27 02 00 91 14 43 00  00 00 00 00             |.'....C. ....    
[18:38:29.130,004] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[18:38:29.160,766] <dbg> zboss_osif: zb_trans_transmit: Function: zb_trans_transmit, channel: 11
[18:38:29.168,914] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 0a 07  7c 00 39 03 1a 00 00 00 |........ |.9.....
                                     b5 50 03 00 74 d9 42 00  00 00 00 00             |.P..t.B. ....    
--- 48 messages dropped ---
[18:38:29.169,006] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 0b 07  7c 00 39 03 02 00 00 00 |........ |.9.....
                                     b5 50 03 00 7b d9 42 00  00 00 00 00             |.P..{.B. ....    
[18:38:29.169,067] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 0c 07  7c 00 39 03 0c 00 00 00 |........ |.9.....
                                     b5 50 03 00 83 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,158] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 0d 07  7c 00 39 03 19 00 00 00 |........ |.9.....
                                     b5 50 03 00 8a d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,219] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 0e 07  7c 00 39 03 17 00 00 00 |........ |.9.....
                                     b5 50 03 00 92 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,311] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 0f 07  7c 00 39 03 11 00 00 00 |........ |.9.....
                                     b5 50 03 00 98 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,372] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 10 07  7c 00 39 03 0d 00 00 00 |........ |.9.....
                                     b5 50 03 00 a0 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,464] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 11 07  7c 00 39 03 18 00 00 00 |........ |.9.....
                                     b5 50 03 00 a7 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,525] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 12 07  7c 00 39 03 1e 00 00 00 |........ |.9.....
                                     b5 50 03 00 af d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.169,616] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 13 07  7c 00 39 03 16 00 00 00 |........ |.9.....
                                     f5 a3 03 00 b6 d9 42 00  00 00 00 00             |......B. ....    
[18:38:29.169,708] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 14 07  7c 00 39 03 0e 00 00 00 |........ |.9.....
                                     2d 4f 03 00 40 da 42 00  00 00 00 00             |[email protected]. ....    
[18:38:29.169,769] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 15 07  7c 00 39 03 1f 00 00 00 |........ |.9.....
                                     2d 4f 03 00 4b da 42 00  00 00 00 00             |-O..K.B. ....    
[18:38:29.169,860] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 16 07  7c 00 39 03 13 00 00 00 |........ |.9.....
                                     2d 4f 03 00 4e da 42 00  00 00 00 00             |-O..N.B. ....    
[18:38:29.169,921] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 17 07  7c 00 39 03 1d 00 00 00 |........ |.9.....
                                     85 ec 03 00 5a 12 43 00  00 00 00 00             |....Z.C. ....    
[18:38:29.170,013] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 05 d9 18 07  7c 00 39 03 00 00 00 00 |........ |.9.....
                                     ad 27 02 00 91 14 43 00  00 00 00 00             |.'....C. ....    
[18:38:29.170,166] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[18:38:29.255,523] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 49 07  7c 00 39 03 02 00 00 00 |......I. |.9.....
                                     b5 50 03 00 7b d9 42 00  00 00 00 00             |.P..{.B. ....    
--- 51 messages dropped ---
[18:38:29.255,615] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 4a 07  7c 00 39 03 0c 00 00 00 |......J. |.9.....
                                     b5 50 03 00 83 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.255,676] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 4b 07  7c 00 39 03 19 00 00 00 |......K. |.9.....
                                     b5 50 03 00 8a d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.255,767] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 4c 07  7c 00 39 03 17 00 00 00 |......L. |.9.....
                                     b5 50 03 00 92 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.255,828] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 4d 07  7c 00 39 03 11 00 00 00 |......M. |.9.....
                                     b5 50 03 00 98 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.255,920] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 4e 07  7c 00 39 03 0d 00 00 00 |......N. |.9.....
                                     b5 50 03 00 a0 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.255,981] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 4f 07  7c 00 39 03 18 00 00 00 |......O. |.9.....
                                     b5 50 03 00 a7 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.256,072] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 50 07  7c 00 39 03 1e 00 00 00 |......P. |.9.....
                                     b5 50 03 00 af d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.256,164] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 51 07  7c 00 39 03 16 00 00 00 |......Q. |.9.....
                                     f5 a3 03 00 b6 d9 42 00  00 00 00 00             |......B. ....    
[18:38:29.256,225] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 52 07  7c 00 39 03 0e 00 00 00 |......R. |.9.....
                                     2d 4f 03 00 40 da 42 00  00 00 00 00             |[email protected]. ....    
[18:38:29.256,317] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 53 07  7c 00 39 03 1f 00 00 00 |......S. |.9.....
                                     2d 4f 03 00 4b da 42 00  00 00 00 00             |-O..K.B. ....    
[18:38:29.256,378] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 54 07  7c 00 39 03 13 00 00 00 |......T. |.9.....
                                     2d 4f 03 00 4e da 42 00  00 00 00 00             |-O..N.B. ....    
[18:38:29.256,469] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 55 07  7c 00 39 03 10 00 00 00 |......U. |.9.....
                                     2d 4f 03 00 55 da 42 00  00 00 00 00             |-O..U.B. ....    
[18:38:29.256,530] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 56 07  7c 00 39 03 1d 00 00 00 |......V. |.9.....
                                     85 ec 03 00 5a 12 43 00  00 00 00 00             |....Z.C. ....    
[18:38:29.256,622] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 0b d9 57 07  7c 00 39 03 00 00 00 00 |......W. |.9.....
                                     ad 27 02 00 91 14 43 00  00 00 00 00             |.'....C. ....    
[18:38:29.256,774] <dbg> zboss_osif: zigbee_event_poll: Received new Zigbee event: 0x01
[18:38:29.355,102] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 6a 07  7c 00 39 03 0c 00 00 00 |......j. |.9.....
                                     b5 50 03 00 83 d9 42 00  00 00 00 00             |.P....B. ....    
--- 21 messages dropped ---
[18:38:29.355,194] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 6b 07  7c 00 39 03 19 00 00 00 |......k. |.9.....
                                     b5 50 03 00 8a d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.355,255] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 6c 07  7c 00 39 03 17 00 00 00 |......l. |.9.....
                                     b5 50 03 00 92 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.355,346] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 6d 07  7c 00 39 03 11 00 00 00 |......m. |.9.....
                                     b5 50 03 00 98 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.355,407] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 6e 07  7c 00 39 03 0d 00 00 00 |......n. |.9.....
                                     b5 50 03 00 a0 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.355,499] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 6f 07  7c 00 39 03 18 00 00 00 |......o. |.9.....
                                     b5 50 03 00 a7 d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.355,590] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 70 07  7c 00 39 03 1e 00 00 00 |......p. |.9.....
                                     b5 50 03 00 af d9 42 00  00 00 00 00             |.P....B. ....    
[18:38:29.355,651] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 71 07  7c 00 39 03 16 00 00 00 |......q. |.9.....
                                     f5 a3 03 00 b6 d9 42 00  00 00 00 00             |......B. ....    
[18:38:29.355,743] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 72 07  7c 00 39 03 0e 00 00 00 |......r. |.9.....
                                     2d 4f 03 00 40 da 42 00  00 00 00 00             |[email protected]. ....    
[18:38:29.355,804] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 73 07  7c 00 39 03 1f 00 00 00 |......s. |.9.....
                                     2d 4f 03 00 4b da 42 00  00 00 00 00             |-O..K.B. ....    
[18:38:29.355,895] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 74 07  7c 00 39 03 13 00 00 00 |......t. |.9.....
                                     2d 4f 03 00 4e da 42 00  00 00 00 00             |-O..N.B. ....    
[18:38:29.355,957] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 75 07  7c 00 39 03 10 00 00 00 |......u. |.9.....
                                     2d 4f 03 00 55 da 42 00  00 00 00 00             |-O..U.B. ....    
[18:38:29.356,048] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 76 07  7c 00 39 03 1d 00 00 00 |......v. |.9.....
                                     85 ec 03 00 5a 12 43 00  00 00 00 00             |....Z.C. ....    
[18:38:29.356,109] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 1a 02 12 d9 77 07  7c 00 39 03 00 00 00 00 |......w. |.9.....
                                     ad 27 02 00 91 14 43 00  00 00 00 00             |.'....C. ....    
[18:38:29.356,201] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 0a 02 12 d9 78 07  7c 00 98 03             |......x. |...    
[18:38:29.356,262] <dbg> zboss_osif: zb_trace_msg_port_do: 
                                     de ad 12 02 12 d9 79 07  60 08 4c 00 7c 00 00 00 |......y. `.L.|...
                                     99 03 00 00                                      |....             
[18:38:29.356,292] <err> zboss_osif: ZBOSS fatal error occurred

Additionally I captured the ZigBee traffic between the end device and the coordinator. Capture is attached.

capture-08-01-24-osif-fatal.pcapng

Searching for "Rejoin Request" leads us to the point where the application restarted after the crash.

It seems to me that the "End Device Timeout Request" is sent by the end device, acknowledged by the coordinator but the ACK not received by the end device (maybe due to low signal strength?).

Any help is appreciated, thank you!

Best Regards
MR

[Elfving]

Hi,

Could you get me the network key for this trace?

Regards,

Elfving