Asset Tracker V2 - Crashes trying to read non-existent config

[Marshall]

ncs2.1.0

I have one unit, that somehow works, and when I loaded the code into any other blank devices it crashes. 

The kernel panic provides hardly any info, but I'm pretty sure it is related to reading the config from storage and there is nothing there. 

At settings_load_subtree, everything pauses for a couple of seconds, and then crashes. 

data_module.c

static int setup(void)
{
	int err;
	err = settings_subsys_init();
	if (err) {
		LOG_ERR("settings_subsys_init, error: %d", err);
		return err;
	}

    /*----------------!!!!!!-----------*/
    /* on a blank device this disappears and causes a panic*/
	err = settings_load_subtree(DEVICE_SETTINGS_KEY);
	if (err) {
		LOG_ERR("settings_load_subtree, error: %d", err);
		return err;
	}

	/* Wait up to 1 seconds for the settings API to load the device configuration stored
	 * to flash, if any.
	 */
	if (k_sem_take(&config_load_sem, K_SECONDS(1)) != 0) {
		LOG_DBG("Failed retrieveing the device configuration from flash in time");
	}

	err = cloud_codec_init(&current_cfg, cloud_codec_event_handler);
	if (err) {
		LOG_ERR("cloud_codec_init, error: %d", err);
		return err;
	}

	date_time_register_handler(date_time_event_handler);
	return 0;
}

[00:00:03.447,814] <dbg> modem_module: state_set: State transition STATE_DISCONNECTED --> STATE_CONNECTING
ASSERTION FAIL [handler != ((void *)0)] @ WEST_TOPDIR/zephyr/kernel/work.c:666
[00:00:03.765,930] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000029a  r2/a3:  0x00000001
[00:00:03.765,960] <err> os: r3/a4:  0x00037485 r12/ip:  0x00000000 r14/lr:  0x0004ee0f
[00:00:03.765,960] <err> os:  xpsr:  0x41000000
[00:00:03.765,991] <err> os: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
[00:00:03.766,021] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
[00:00:03.766,052] <err> os: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
[00:00:03.766,052] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
[00:00:03.766,082] <err> os: fpscr:  0x00000000
[00:00:03.766,082] <err> os: Faulting instruction address (r15/pc): 0x00055204
[00:00:03.766,113] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:00:03.766,143] <err> os: Current thread: 0x200134a0 (sysworkq)
[00:04:08.808,868] <err> fatal_error: Resetting system

for completeness - here's the faulting instruction address. 

arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 0x00055204
C:/ncs/v2.1.0/zephyr/lib/os/assert.c:44

Any ideas? 

Thanks 

Marshall

[Marshall]

update - It looks like it might be a timing issue? 

NULL handler in work queue entry can be called resulting in silent reboot · Issue #26723 · zephyrproject-rtos/zephyr · GitHub

[Øyvind]

Hello Marshall, 

Have you changed anything in the Asset Tracker v2?  I've never seen this issue with the ATv2 out of the box. I will need some more information in order to try to reproduce it on my side.

What devices are you using? Is this on a development kit, Thingy:91 or custom HW? 

/*----------------!!!!!!-----------*/
/* on a blank device this disappears and causes a panic*/

What are you basing this on? Can you provide more information?

Thanks:

Kind regards,
Øyvind

[Marshall]

Hi Oyvind

Yes it is a modified version of the ATv2, I have external flash for the FOTA, allowing me almost all of the 1MB internal flash for application (except for the bootloader and the settings) 

I have added a couple of strings to the settings.

If I put a breakpoint in flash_map.c as below and run it from boot pressing the Run each time the breakpoint is hit. the application will boot fine. 

If I disable the breakpoint and run it, it crashes. It feels like some sort of timing issue?

If I then connect to the cloud and write some settings into the flash it all runs merrily from then on, once it can find something in the settings.

I've tried moving the settings to external flash, but the partition manager borks when you try it, by disabling FCB and enabling NVS (all in the prj.conf file) 

Thanks Marshall

[Marshall]

it does still crash at flash_map.c:flash_read

I don't know what's going on. 

[Øyvind]

Marshall, thanks for providing this information. This gives us more to work with.

Would it be possible to also run the following

arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 0x00037485

arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 0x0004ee0f

I will discuss the issue with our bootloader team. 

Thanks!

-Øyvind

[Marshall]

I've messed around so much, I don't know if the same addresses are still in the same places, hopefully it's something to work with. 

arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 0x00037485
C:/ncs/v2.1.0/zephyr/drivers/clock_control/clock_control_nrf.c:749

arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 0x0004ee0f
C:/ncs/v2.1.0/zephyr/kernel/sem.c:99

Regards

Marshall

[Øyvind]

Are you still seeing the ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0?

If you are still seeing the error, are you seeing the same numbers at r3/a4 and r14/lr ?

[Marshall]

ASSERTION FAIL [handler != ((void *)0)] @ WEST_TOPDIR/zephyr/kernel/work.c:666
[00:00:00.861,419] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000029a  r2/a3:  0x00000001
[00:00:00.861,450] <err> os: r3/a4:  0x000376b1 r12/ip:  0x00000000 r14/lr:  0x0004f03b
[00:00:00.861,480] <err> os:  xpsr:  0x41000000
[00:00:00.861,480] <err> os: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
[00:00:00.861,511] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
[00:00:00.861,541] <err> os: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
[00:00:00.861,541] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
[00:00:00.861,572] <err> os: fpscr:  0x00000000
[00:00:00.861,572] <err> os: Faulting instruction address (r15/pc): 0x00055430
[00:00:00.861,602] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:00:00.861,633] <err> os: Current thread: 0x20013000 (sysworkq)
[00:00:00.989,868] <err> fatal_error: Resetting system
opito:~$ ý

arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 376b1
C:/ncs/v2.1.0/zephyr/drivers/console/uart_console.c:88
PS C:\opito\zephyr\opito_base_oct22> arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 4f03b
C:/ncs/v2.1.0/zephyr/kernel/work.c:667 (discriminator 3)
PS C:\opito\zephyr\opito_base_oct22> arm-zephyr-eabi-addr2line.exe -e build_opito_nrf9160\zephyr\zephyr.elf 55430
C:/ncs/v2.1.0/zephyr/lib/os/assert.c:44