nrf9160 nvs controller crash

[JBroemmling]

Hello!

Following problem:

I try to save 100Byte uint8_t messages in the nvs on the nrf9160.

Sometimes it works and only some moving logs come up and sometimes the following error comes up and the controller crashes.

Check Message Failed!N FAIL [0] @ WEST_TOPDIR/zephyr/subsys/shell/shell_log_backen
15:33:10.671 -> FCU get all Datad.c:109
15:33:10.717 -> [00:01:16.981,506] <dbg> fs_nvs.nvs_gc: Moving 4, len 101
15:33:10.763 -> [00:01:16.983,276] <dbg> fs_nvs.nvs_gc: Moving 5, len 101
15:33:10.857 -> [00:01:16.985,076] <dbg> fs_nvs.nvs_gc: Moving 6, len 101
15:33:10.950 -> [00:01:16.986,877] <dbg> fs_nvs.nvs_gc: Moving 7, len 101
15:33:10.997 -> [00:01:16.988,708] <dbg> fs_nvs.nvs_gc: Moving 8, len 101
15:33:11.089 -> [00:01:16.990,509] <dbg> fs_nvs.nvs_gc: Moving 9, len 101
15:33:11.184 -> [00:01:16.992,340] <dbg> fs_nvs.nvs_gc: Moving 10, len 101
15:33:11.231 -> [00:01:16.994,201] <dbg> fs_nvs.nvs_gc: Moving 11, len 101
15:33:11.324 -> [00:01:16.996,032] <dbg> fs_nvs.nvs_gc: Moving 1000, len 101
15:33:11.417 -> [00:01:16.997,894] <dbg> fs_nvs.nvs_gc: Moving 1001, len 101
15:33:11.463 -> [00:01:16.999,755] <dbg> fs_nvs.nvs_gc: Moving 1002, len 101
15:33:11.556 -> [00:01:17.001,647] <dbg> fs_nvs.nvs_gc: Moving 1003, len 101
15:33:11.649 -> [00:01:17.003,540] <dbg> fs_nvs.nvs_gc: Moving 1004, len 101
15:33:11.741 -> [00:01:17.005,432] <dbg> fs_nvs.nvs_gc: Moving 1005, len 101
15:33:11.787 -> [00:01:17.007,324] <dbg> fs_nvs.nvs_gc: Moving 1006, len 101
15:33:11.880 -> [00:01:17.008,728] <dbg> fs_nvs.nvs_flash_erase_sector: Erasing flash at d1000, len 4096
15:33:11.975 -> [00:01:18.517,730] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000006d  r2/a3:  0x00000000
15:33:12.113 -> [00:01:18.517,730] <err> os: r3/a4:  0x0002bc5d r12/ip:  0x20016f10 r14/lr:  0x00029c0f
15:33:12.205 -> [00:01:18.517,761] <err> os:  xpsr:  0x41000000
15:33:12.297 -> [00:01:18.517,761] <err> os: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
15:33:12.435 -> [00:01:18.517,761] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
15:33:12.572 -> [00:01:18.517,791] <err> os: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
15:33:12.664 -> [00:01:18.517,791] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
15:33:12.803 -> [00:01:18.517,822] <err> os: fpscr:  0x00000000
15:33:12.895 -> [00:01:18.517,852] <err> os: Faulting instruction address (r15/pc): 0x0004c748
15:33:12.988 -> [00:01:18.517,852] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
15:33:13.080 -> [00:01:18.517,913] <err> os: Current thread: 0x20016988 (logging)
15:33:13.174 -> [00:01:20.992,645] <err> fatal_error: Resetting system
⸮k⸮Ncϣ⸮⸮ ⸮⸮⸮⸮S⸮⸮s⸮⸮/cHf⸮Ȑr⸮Nc⸮PB⸮⸮\⸮
⸮⸮⸮x⸮G⸮⸮tʜ⸮B⸮⸮⸮

I tried to change the flash offset or the message length but both doesn't solve the problem

[Håkon Alseth]

Hi,

 

15:33:11.975 -> [00:01:18.517,730] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000006d  r2/a3:  0x00000000
15:33:12.113 -> [00:01:18.517,730] <err> os: r3/a4:  0x0002bc5d r12/ip:  0x20016f10 r14/lr:  0x00029c0f
15:33:12.205 -> [00:01:18.517,761] <err> os:  xpsr:  0x41000000
15:33:12.297 -> [00:01:18.517,761] <err> os: s[ 0]:  0x00000000  s[ 1]:  0x00000000  s[ 2]:  0x00000000  s[ 3]:  0x00000000
15:33:12.435 -> [00:01:18.517,761] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000000  s[ 6]:  0x00000000  s[ 7]:  0x00000000
15:33:12.572 -> [00:01:18.517,791] <err> os: s[ 8]:  0x00000000  s[ 9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
15:33:12.664 -> [00:01:18.517,791] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
15:33:12.803 -> [00:01:18.517,822] <err> os: fpscr:  0x00000000
15:33:12.895 -> [00:01:18.517,852] <err> os: Faulting instruction address (r15/pc): 0x0004c748
15:33:12.988 -> [00:01:18.517,852] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
15:33:13.080 -> [00:01:18.517,913] <err> os: Current thread: 0x20016988 (logging)
15:33:13.174 -> [00:01:20.992,645] <err> fatal_error: Resetting system

This shows that it is your logging thread that is causing the fault.

In general, you can use arm-none-eabi-addr2line -e build-folder/zephyr/zephyr.elf 0xFAULTINGADDR to resolve the address to a source file and line number. In this case, I suspect the logging thread is running out of memory.

Could you try adjusting the logging thread stack via this config?

CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=2048

 

Kind regards,

Håkon

[JBroemmling]

Thanks for your answer Håkon,

the configuration was 

CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=2048

 before and now I tried it with 

CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=4096

 but it still crashes.

And you are right, it crashes in

zephyr/subsys/logging/log_core.c:1193

Best regards

Joshua

[Håkon Alseth]

Hi Joshua,

 

It seems that the logging assert is a red herring.

Could you try adjusting the MAIN_STACK_SIZE to see if this is the culprit?

 

You can also run addr2line on the faulting content in R3 and LR register as well, which might tell us a bit more on where it came from. If possible, you can also attach your project (if it does not include any secret stuff).

 

Kind regards,

Håkon

[JBroemmling]

Hi Håkon,

I've now disabled the log function because we have generally deleted most logs and will not use them later in the application.

Thanks for your help!

Kind regards,

Joshua