LWM2M Carrier Library and date_time library hard fault

Hello, 

Can you please provide more details on this isseu? What version of nRF Connect SDK and modem FW are you running? Will need more to reproduce on our side. 

Kind regards,
Øyvind

Sorry about that, I’m using NCS v1.7.0 on a custom board with MFW 1.3.0. Not sure about the version of LWM2M Carrier library, I guess whatever is included in NCS v1.7.0 by default

I tested with running NCS v1.7.0 lwm2m carrier sample, adding date time library. 

2022-05-20T10:14:39.955Z DEBUG modem << *** Booting Zephyr OS build v2.6.99-ncs1  ***
2022-05-20T10:14:39.958Z DEBUG modem << Flash regionsDomainPermissions
2022-05-20T10:14:39.962Z DEBUG modem << 00 01 0x00000 0x10000 Securerwxl
2022-05-20T10:14:39.965Z DEBUG modem << 02 31 0x10000 0x100000 Non-Securerwxl
2022-05-20T10:14:39.971Z DEBUG modem << Non-secure callable region 0 placed in flash region 1 with size 32.
2022-05-20T10:14:40.022Z DEBUG modem << SRAM regionDomainPermissions
2022-05-20T10:14:40.025Z DEBUG modem << 00 07 0x00000 0x10000 Securerwxl
2022-05-20T10:14:40.029Z DEBUG modem << 08 31 0x10000 0x40000 Non-Securerwxl
2022-05-20T10:14:40.031Z DEBUG modem << PeripheralDomainStatus
2022-05-20T10:14:40.035Z DEBUG modem << 00 NRF_P0               Non-SecureOK
2022-05-20T10:14:40.038Z DEBUG modem << 01 NRF_CLOCK            Non-SecureOK
2022-05-20T10:14:40.042Z DEBUG modem << 02 NRF_RTC0             Non-SecureOK
2022-05-20T10:14:40.045Z DEBUG modem << 03 NRF_RTC1             Non-SecureOK
2022-05-20T10:14:40.048Z DEBUG modem << 04 NRF_NVMC             Non-SecureOK
2022-05-20T10:14:40.052Z DEBUG modem << 05 NRF_UARTE1           Non-SecureOK
2022-05-20T10:14:40.055Z DEBUG modem << 06 NRF_UARTE2           SecureSKIP
2022-05-20T10:14:40.058Z DEBUG modem << 07 NRF_TWIM2            Non-SecureOK
2022-05-20T10:14:40.062Z DEBUG modem << 08 NRF_SPIM3            Non-SecureOK
2022-05-20T10:14:40.065Z DEBUG modem << 09 NRF_TIMER0           Non-SecureOK
2022-05-20T10:14:40.069Z DEBUG modem << 10 NRF_TIMER1           Non-SecureOK
2022-05-20T10:14:40.072Z DEBUG modem << 11 NRF_TIMER2           Non-SecureOK
2022-05-20T10:14:40.075Z DEBUG modem << 12 NRF_SAADC            Non-SecureOK
2022-05-20T10:14:40.079Z DEBUG modem << 13 NRF_PWM0             Non-SecureOK
2022-05-20T10:14:40.082Z DEBUG modem << 14 NRF_PWM1             Non-SecureOK
2022-05-20T10:14:40.086Z DEBUG modem << 15 NRF_PWM2             Non-SecureOK
2022-05-20T10:14:40.089Z DEBUG modem << 16 NRF_PWM3             Non-SecureOK
2022-05-20T10:14:40.092Z DEBUG modem << 17 NRF_WDT              Non-SecureOK
2022-05-20T10:14:40.096Z DEBUG modem << 18 NRF_IPC              Non-SecureOK
2022-05-20T10:14:40.099Z DEBUG modem << 19 NRF_VMC              Non-SecureOK
2022-05-20T10:14:40.103Z DEBUG modem << 20 NRF_FPU              Non-SecureOK
2022-05-20T10:14:40.106Z DEBUG modem << 21 NRF_EGU1             Non-SecureOK
2022-05-20T10:14:40.109Z DEBUG modem << 22 NRF_EGU2             Non-SecureOK
2022-05-20T10:14:40.113Z DEBUG modem << 23 NRF_DPPIC            Non-SecureOK
2022-05-20T10:14:40.116Z DEBUG modem << 24 NRF_REGULATORS       Non-SecureOK
2022-05-20T10:14:40.120Z DEBUG modem << 25 NRF_PDM              Non-SecureOK
2022-05-20T10:14:40.123Z DEBUG modem << 26 NRF_I2S              Non-SecureOK
2022-05-20T10:14:40.126Z DEBUG modem << 27 NRF_GPIOTE1          Non-SecureOK
2022-05-20T10:14:40.129Z DEBUG modem << SPM: NS image at 0x10000
2022-05-20T10:14:40.131Z DEBUG modem << SPM: NS MSP at 0x20020838
2022-05-20T10:14:40.134Z DEBUG modem << SPM: NS reset vector at 0x1da89
2022-05-20T10:14:40.138Z DEBUG modem << SPM: prepare to jump to Non-Secure image.
2022-05-20T10:14:40.146Z DEBUG modem << *** Booting Zephyr OS build v2.6.99-ncs1  ***
2022-05-20T10:14:40.148Z DEBUG modem << LWM2M Carrier library sample.
2022-05-20T10:14:40.157Z DEBUG modem << DATE_TIME_NOT_OBTAINED 
2022-05-20T10:14:40.359Z DEBUG modem << LWM2M_CARRIER_EVENT_MODEM_INIT
2022-05-20T10:14:40.392Z DEBUG modem << Certificate found, tag 411: [0;32mmatch
2022-05-20T10:14:40.422Z DEBUG modem << [0mCertificate found, tag 412: [0;32mmatch
2022-05-20T10:14:40.438Z DEBUG modem << [0mLWM2M_CARRIER_EVENT_CONNECTING
2022-05-20T10:14:42.542Z DEBUG modem << LWM2M_CARRIER_EVENT_CONNECTED
2022-05-20T10:14:43.584Z DEBUG modem << LWM2M_CARRIER_EVENT_LTE_READY

Gotcha, good to know it’s just an issue on my end. I’ll reproduce in a little bit and get back to you with a better log. Thanks for your help

Sounds good. Make sure to add CONFIG_DATE_TIME=y in prj.conf and add #include <date_time.h>

[00:01:15.316,497] <err> os: Exception occurred in Secure State
[00:01:15.316,497] <err> os: ***** HARD FAULT *****
[00:01:15.316,497] <err> os: Fault escalation (see below)
[00:01:15.316,497] <err> os: ***** BUS FAULT *****
[00:01:15.316,528] <err> os: Precise data bus error
[00:01:15.316,528] <err> os: BFAR Address: 0x50008158
[00:01:15.316,528] <err> os: r0/a1: 0x2002a4a0 r1/a2: 0x00000000 r2/a3: 0x80850000
[00:01:15.316,528] <err> os: r3/a4: 0x0005ca5b r12/ip: 0x00036d04 r14/lr: 0x61060000
[00:01:15.316,558] <err> os: xpsr: 0x40028000
[00:01:15.316,558] <err> os: s[ 0]: 0x00000000 s[ 1]: 0x00000000 s[ 2]: 0x00000000 s[ 3]: 0x00000000
[00:01:15.316,589] <err> os: s[ 4]: 0x00000000 s[ 5]: 0x00000000 s[ 6]: 0x00000000 s[ 7]: 0xffffffff
[00:01:15.316,589] <err> os: s[ 8]: 0x00000000 s[ 9]: 0x00000003 s[10]: 0x00000000 s[11]: 0x00000000
[00:01:15.316,589] <err> os: s[12]: 0x00000000 s[13]: 0x00000000 s[14]: 0x00000000 s[15]: 0x00000000
[00:01:15.316,589] <err> os: fpscr: 0x00000000
[00:01:15.316,589] <err> os: Faulting instruction address (r15/pc): 0x00000000
[00:01:15.316,619] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:01:15.316,619] <err> os: Current thread: 0x200223f8 (time_thread)
[00:01:15.839,660] <err> fatal_error: Resetting system

This is the hard fault. I had put some of my own prints in the date_time library functions to try to trace it down. It seems like this is the critical section:

static void new_date_time_get(void)
{
	int err;

	while (true) {
		k_sem_take(&time_fetch_sem, K_FOREVER);

		LOG_DBG("Updating date time UTC...");
		err = current_time_check();
		if (err == 0) {
			LOG_DBG("Time successfully obtained");
			initial_valid_time = true;
			date_time_notify_event(&evt);
			continue;
		}

		LOG_DBG("Current time not valid");

and is failing after it receives the semaphore from the date_time_update_async function here:

int date_time_update_async(date_time_evt_handler_t evt_handler)
{
	if (evt_handler) {
		app_evt_handler = evt_handler;
	} else if (app_evt_handler == NULL) {
		LOG_DBG("No handler registered");
	}

	k_sem_give(&time_fetch_sem);

	return 0;
}

The relevant variables in prj.conf are:

# Date Time library
CONFIG_DATE_TIME=y
CONFIG_DATE_TIME_NTP=n
CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS=0

I tried non-zero values for CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS and used to have CONFIG_DATE_TIME_NTP enabled but disabled it to try the other option and the fault occurs in all scenarios. Scratching my head a little bit since this call worked fine before integrating LWM2M Carrier, but it may just simply be a stack overflow? 

Are you able to test with the nRF9160:LwM2M carrier sample on your side? I.e. adding date_time to the sample alone. That worked for me. 

esisk said:

[00:01:15.316,497] <err> os: Exception occurred in Secure State

What board are you building for? seems to be an issue with secure, not non-secure. Can you confirm?

Are you able to test with the nRF9160:LwM2M carrier sample on your side? I.e. adding date_time to the sample alone. That worked for me. 

esisk said:

[00:01:15.316,497] <err> os: Exception occurred in Secure State

What board are you building for? seems to be an issue with secure, not non-secure. Can you confirm?

When I get to work today I can test on the bare-bones sample. I always build my project for <custom_board>ns. I can always double check though. Would you mind adding a call to date_time_update_async(handler) in your test? I saw your log say DATE_TIME_NOT_OBTAINED which was before the LWM2M library had connected to the network, but I’d like to see what happens if you call the function I mentioned after the LTE link is ready. 

esisk said:

Would you mind adding a call to date_time_update_async(handler) in your test?

Sure. Initially I called the function from main(). I have now moved it to the LWM2M_CARRIER_EVENT_LTE_READY case. This yields the following output:

2022-05-23T13:09:01.749Z DEBUG modem << *** Booting Zephyr OS build v2.6.99-ncs1 ***
2022-05-23T13:09:01.755Z DEBUG modem << LWM2M Carrier library sample.
2022-05-23T13:09:01.962Z DEBUG modem << LWM2M_CARRIER_EVENT_MODEM_INIT
2022-05-23T13:09:01.990Z DEBUG modem << Certificate found, tag 411: [0;32mmatch
2022-05-23T13:09:02.020Z DEBUG modem << [0mCertificate found, tag 412: [0;32mmatch
2022-05-23T13:09:02.036Z DEBUG modem << [0mLWM2M_CARRIER_EVENT_CONNECTING
2022-05-23T13:09:04.400Z DEBUG modem << LWM2M_CARRIER_EVENT_CONNECTED
2022-05-23T13:09:05.442Z DEBUG modem << LWM2M_CARRIER_EVENT_LTE_READY
2022-05-23T13:09:05.450Z DEBUG modem << DATE_TIME_OBTAINED_MODEM

Make sure that your application waits until the LWM2M_CARRIER_EVENT_LTE_READY event, as the LwM2M carrier lib needs full control before this event to bootstrap with e.g. Verizon server.

See LwM2M carrier library - application integration for more information

What is the stack size of the date_time thread set to? Could you try to increase this to 1280 i.e. CONFIG_DATE_TIME_THREAD_STACK_SIZE=1280, if not already done. 
Ref. this Git pull request: github.com/.../da8d172763815205ac279dff9e91177cd05945ae

Thanks for doing that. Just checked the stack size, and if it's unset in prj.conf, 

esisk said:

tried the same thing with the lwm2m_carrier sample. Worked fine

Ok, so you tested the lwm2m_carrier sample with date_time and it worked. Then it sounds like something else. Are you able to share your whole project with me? If so, I will convert this ticket to private. Will it run on a standard nRF9160DK?