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

[Marshall]

whew - I found it. 

I loaded up ncs 2.2.0 and started porting my changes across, When I got to the indication LED. it faulted. 

I have a ws2812 LED, and am using PWM to drive it, I created a new module, that had subscribed to events, and shifted my init code into this module. this also included the init for the LED. 

So the AT2 was attempting to drive the LED, before it had been assigned any memory. 

It was weird that it was only crashing at the settings module, and if it could read the settings, it would work fine. 

I guess it was indeed a timing issue, if the unit booted fast enough, the LED would be init'd in the new module and all was well, if it took that teeny bit longer to search for settings it would crash. 

Thanks for the help! really appreciate it. 

Now to consider if I carry on porting my changes across to v2.2.0! :) 

Regards

Marshall

[Øyvind]

Marshall, that is good news! Happy to hear you found the root cause :) 

Marshall said:

Thanks for the help!

No problem. Any time!

Kind regards,
Øyvind