Calling date_time_update_async from main thread leads to stack overflow

[Sebastian Stein]

Dear Nordic Support Team,

I am using nRF Connect 1.9.1 together with the modem firmware 1.3.2 on a nRF9160 DK.

I noticed that calling the function date_time_update_async in the main thread produces a stack overflow error. This is the case even if a connection to the cellular network was established before calling date_time_update_async .

I have attached three files:

1. [minimalExample.c] Minimal example to produce the error
2. [log_dateTimeStackOverflow.txt] Error log for the case when date_time_update_async  is called without prior connection to the cellular network
3. [log_dateTimeStackOverflow_lte.txt] Error log for the case when date_time_update_async  is called after a connection to the cellular network was established

Fullscreen 4478.minimalExample.c Download

// Zephyr
#include <zephyr.h>

// Nordic
#include <date_time.h>
#include <modem/lte_lc.h>



static bool isDateTimeUpdateDone = false;

static void callback_dateTimeEvent(const struct date_time_evt *evt)
{
    printk("Event %d\n", evt->type);
    isDateTimeUpdateDone = true;
}



void main(void)
{
    printk("I am running!\n");


    int error = 0;

    // error = lte_lc_init();
    // printk("lte_lc_init: %d\n", error);

    // error = lte_lc_connect();
    // printk("lte_lc_connect: %d\n", error);

    error = date_time_update_async(callback_dateTimeEvent);
    printk("date_time_update_async: %d\n", error);

    while (!isDateTimeUpdateDone)
    {
        printk("Waiting...\n");
        k_sleep(K_MSEC(500));
    }


    printk("I am returning!\n");
}

Fullscreen log_dateTimeStackOverflow.txt Download

*** Booting Zephyr OS build v2.7.99-ncs1-1  ***<CR><LF>
I: Starting bootloader<CR><LF>
I: Primary image: magic=good, swap_type=0x4, copy_done=0x1, image_ok=0x1<CR><LF>
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<CR><LF>
I: Boot source: none<CR><LF>
I: Swap type: none<CR><LF>
I: Bootloader chainload address offset: 0x10000<CR><LF>
I: Jumping to the first image slot<CR>
*** Booting Zephyr OS build v2.7.99-ncs1-1  ***<CR><LF>
I am running!<CR><LF>
date_time_update_async: 0<CR><LF>
Waiting...<CR><LF>
[00008712] <ESC><err> os: ***** USAGE FAULT *****<ESC><CR><LF>
[00008712] <ESC><err> os:   Stack overflow (context area not valid)<ESC><CR><LF>
[00008713] <ESC><err> os: r0/a1:  0x00038834  r1/a2:  0x41000000  r2/a3:  0x0001001a<ESC><CR><LF>
[00008713] <ESC><err> os: r3/a4:  0xabddef67 r12/ip:  0x00038fd4 r14/lr:  0x41000000<ESC><CR><LF>
[00008714] <ESC><err> os:  xpsr:  0xadffbc00<ESC><CR><LF>
[00008714] <ESC><err> os: Faulting instruction address (r15/pc): 0x00010079<ESC><CR><LF>
[00008715] <ESC><err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0<ESC><CR><LF>
[00008716] <ESC><err> os: Current thread: 0x2000e2b8 (unknown)<ESC><CR><LF>
[00010417] <ESC><err> fatal_error: Resetting system<ESC><CR>

Fullscreen log_dateTimeStackOverflow_lte.txt Download

*** Booting Zephyr OS build v2.7.99-ncs1-1  ***<CR><LF>
I: Starting bootloader<CR><LF>
I: Primary image: magic=good, swap_type=0x4, copy_done=0x1, image_ok=0x1<CR><LF>
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3<CR><LF>
I: Boot source: none<CR><LF>
I: Swap type: none<CR><LF>
I: Bootloader chainload address offset: 0x10000<CR><LF>
I: Jumping to the first image slot<CR>
*** Booting Zephyr OS build v2.7.99-ncs1-1  ***<CR><LF>
I am running!<CR><LF>
lte_lc_init: 0<CR><LF>
lte_lc_connect: 0<CR><LF>
date_time_update_async: 0<CR><LF>
Waiting...<CR><LF>
[00146596] <ESC><err> os: ***** USAGE FAULT *****<ESC><CR><LF>
[00146597] <ESC><err> os:   Stack overflow (context area not valid)<ESC><CR><LF>
[00146597] <ESC><err> os: r0/a1:  0x00038fc4  r1/a2:  0x41000000  r2/a3:  0xa8044105<ESC><CR><LF>
[00146597] <ESC><err> os: r3/a4:  0xadffbd6b r12/ip:  0x48fc6800 r14/lr:  0x6fedee7e<ESC><CR><LF>
[00146598] <ESC><err> os:  xpsr:  0x00038800<ESC><CR><LF>
[00146598] <ESC><err> os: Faulting instruction address (r15/pc): 0x20010808<ESC><CR><LF>
[00146599] <ESC><err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0<ESC><CR><LF>
[00146600] <ESC><err> os: Current thread: 0x2000e2c0 (unknown)<ESC><CR><LF>
[00148295] <ESC><err> fatal_error: Resetting system<ESC><CR>

In the following are the Kconfig settings I believe to be relevant for this case:

CONFIG_NRF_MODEM_LIB=y
CONFIG_MODEM_KEY_MGMT=y
CONFIG_MODEM_INFO=y

CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_NETWORK_MODE_LTE_M=y
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n

CONFIG_DATE_TIME=y
CONFIG_DATE_TIME_AUTO_UPDATE=n
CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS=7200

CONFIG_MAIN_STACK_SIZE=32768
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=32768
CONFIG_HEAP_MEM_POOL_SIZE=32768

A little more context:

In my application I have multiple time sources. One of them is Nordic's date time library and another is a RTC. I try to initialize both on system startup when a connection to the cellular network isn't established yet. I am expecting the RTC to do its thing and I expect Nordic's date time library to fail gracefully with the event DATE_TIME_NOT_OBTAINED. However my application crashes with the aforementioned error.

I would like to understand what causes the error and how it can be prevented.

Thank you allot for your help! Please don't hesitate to ask if you have any questions.

Cheers,
Sebastian

[Susheel Nuguru]

Hi,

Sorry for late reply and maybe you have solved this already. Stack overflows are sometimes nasty to debug as we need to first find the context which caused the overflow. Looking at the stack frame to get hints sometimes wont work.

Can you try enabling this configs for a better chance to catch stack overflow and better debug info?

CONFIG_THREAD_NAME=y

CONFIG_THREAD_MONITOR=y

CONFIG_STACK_SENTINEL=y

[Sebastian Stein]

Hi Susheel,

I did some debugging myself and I believe that I narrowed the possible error cause down to the following code found in ncs\v1.9.1\nrf\lib\date_time\date_time_core.h, line 87 - 96:

#if defined(CONFIG_DATE_TIME_NTP)
    LOG_DBG("Getting time from NTP server");
    int64_t date_time_ms_ntp = 0;
    
    err = date_time_ntp_get(&date_time_ms_ntp);
    if (err == 0) {
    	date_time_core_store(date_time_ms_ntp, DATE_TIME_OBTAINED_NTP);
    	continue;
    }
#endif

I believe that the error is caused by this code since setting CONFIG_DATE_TIME_NTP=n makes the error disappear.

I hope that helps.

Cheers,
Sebastian

[Susheel Nuguru]

Great effort Sebastian. 

I am not able to replicate this for some reason both in NCSv1.9.1 and also tried with NCSv2.2.0.

Since you narrowed it down to these lines the only place where I can see that the stack overflow happens could be in the k_work queue. 

There has been a lot of changes to this library since NCSv1.9.1. Can you replace your 1.9.1/nrf/libdate_time folder with the contents of this zip file and test again?

date_time.zip

If this doesn't work, I will try to get your whole setup to replicate the issue instead of using just the code snippets

[Sebastian Stein]

Hi Susheel,

thank you for your input.

I have tested your approach. The stack overflow did remain.

Still, I think you have made an important point with mentioning that NCSv1.9.1 is rather old. Since the workaround of setting CONFIG_DATE_TIME_NTP=n does work for me, it might not be reasonable to debug NCSv1.9.1. At least you don't have to do it for me. Thus, we can close this ticked as far as I am concerned.

What are your thoughts?

Cheers,
Sebastian

[Susheel Nuguru]

Sebastian, thanks for an open mind. I agree that we can close this case if you are going to upgrade your product to more recent version. But if you do have to continue using v1.9.1, then I would keep this case open with a hope that you can comeback here to write your observations after the debugging in v1.9.1.

This is a public ticket and your final inputs will help others who stumble upon this thread.