NVS Fails (BUG?) sometimes when power down or restart

[urbanze]

I have been developing industrial products with esp32 for some time and today happened again (2 times)...

Rarely when I reboot (via terminal) or remove power, NVS stops working and esp does not start anymore and this is not acceptable for the product. The only working code to check if NVS is OK, obviously does not work, as esp enters boot-loop.

Code: Select all

er = nvs_flash_init_partition("nvs");
if (er != ESP_OK)
{
	nvs_flash_erase_partition("nvs");
	er = nvs_flash_init_partition("nvs");
}
nvs_open_from_partition("nvs", "SG", NVS_READWRITE, &nvsHS);

What is this bug/bug? How can I detect it via software and perform some run-time fix? (I think it would format the partition as in most cases)

ESP Serial monitor log (first time):

Code: Select all

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:780
load:0x40078000,len:0
load:0x40078000,len:11804
entry 0x40078414
I (196) cpu_start: Pro cpu up.
I (196) cpu_start: Starting app cpu, entry point is 0x40081210
0x40081210: call_start_cpu1 at /home/ze/esp/esp-idf/components/esp32/cpu_start.c:224

I (182) cpu_start: App cpu up.
I (199) heap_init: Initializing. RAM available for dynamic allocation:
I (206) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (212) heap_init: At 3FFB9208 len 00026DF8 (155 KiB): DRAM
I (218) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (225) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (231) heap_init: At 4008F2D0 len 00010D30 (67 KiB): IRAM
I (237) cpu_start: Pro cpu start user code
I (255) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
assertion "entry < ENTRY_COUNT" failed: file "/home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.hpp", line 190, function: uint32_t nvs::Page::getEntryAddress(size_t) const
abort() was called at PC 0x400dbb33 on core 0
0x400dbb33: __assert_func at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdlib/../../../.././newlib/libc/stdlib/assert.c:63 (discriminator 8)


Backtrace: 0x4008d363:0x3ffbb270 0x4008d4bb:0x3ffbb290 0x400dbb33:0x3ffbb2b0 0x400e9c2d:0x3ffbb2e0 0x400e9ed1:0x3ffbb300 0x400ea8b2:0x3ffbb320 0x400ead3d:0x3ffbb360 0x400e9a58:0x3ffbb3c0 0x400e935f:0x3ffbb410 0x400e93c9:0x3ffbb430 0x400d5da8:0x3ffbb460 0x400d744f:0x3ffbb4a0 0x400d1804:0x3ffbb4d0
0x4008d363: invoke_abort at /home/ze/esp/esp-idf/components/esp32/panic.c:648

0x4008d4bb: abort at /home/ze/esp/esp-idf/components/esp32/panic.c:648

0x400dbb33: __assert_func at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdlib/../../../.././newlib/libc/stdlib/assert.c:63 (discriminator 8)

0x400e9c2d: nvs::Page::getEntryAddress(unsigned int) const at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:311

0x400e9ed1: nvs::Page::writeEntry(nvs::Item const&) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:311

0x400ea8b2: nvs::Page::moveItem(nvs::Page&) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:404

0x400ead3d: nvs::PageManager::load(unsigned int, unsigned int) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_pagemanager.cpp:222

0x400e9a58: nvs::Storage::init(unsigned int, unsigned int) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_storage.cpp:41

0x400e935f: nvs_flash_init_custom at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:506

0x400e93c9: nvs_flash_init_partition at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:506

0x400d5da8: initLOG() at /home/ze/esp/sg/main/main.cpp:1387

0x400d744f: app_main at /home/ze/esp/sg/main/main.cpp:4343

0x400d1804: main_task at /home/ze/esp/esp-idf/components/esp32/cpu_start.c:466

ESP Serial monitor log (second time (2 mounts after)):

Code: Select all

ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:780
load:0x40078000,len:0
load:0x40078000,len:11804
entry 0x40078414
I (197) cpu_start: Pro cpu up.
I (197) cpu_start: Starting app cpu, entry point is 0x40081210
0x40081210: call_start_cpu1 at /home/ze/esp/esp-idf/components/esp32/cpu_start.c:224

I (183) cpu_start: App cpu up.
I (200) heap_init: Initializing. RAM available for dynamic allocation:
I (207) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (213) heap_init: At 3FFB9208 len 00026DF8 (155 KiB): DRAM
I (219) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (226) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (232) heap_init: At 4008F2D0 len 00010D30 (67 KiB): IRAM
I (238) cpu_start: Pro cpu start user code
I (256) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
assertion "entry < ENTRY_COUNT" failed: file "/home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.hpp", line 190, function: uint32_t nvs::Page::getEntryAddress(size_t) const
abort() was called at PC 0x400dc6ff on core 0
0x400dc6ff: __assert_func at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdlib/../../../.././newlib/libc/stdlib/assert.c:63 (discriminator 8)


Backtrace: 0x4008d363:0x3ffbb270 0x4008d4bb:0x3ffbb290 0x400dc6ff:0x3ffbb2b0 0x400ea7f9:0x3ffbb2e0 0x400eaa9d:0x3ffbb300 0x400eb47e:0x3ffbb320 0x400eb909:0x3ffbb360 0x400ea624:0x3ffbb3c0 0x400e9f2b:0x3ffbb410 0x400e9f95:0x3ffbb430 0x400d5a18:0x3ffbb460 0x400d7dbb:0x3ffbb4a0 0x400d18ac:0x3ffbb4d0
0x4008d363: invoke_abort at /home/ze/esp/esp-idf/components/esp32/panic.c:648

0x4008d4bb: abort at /home/ze/esp/esp-idf/components/esp32/panic.c:648

0x400dc6ff: __assert_func at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdlib/../../../.././newlib/libc/stdlib/assert.c:63 (discriminator 8)

0x400ea7f9: nvs::Page::getEntryAddress(unsigned int) const at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:311

0x400eaa9d: nvs::Page::writeEntry(nvs::Item const&) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:311

0x400eb47e: nvs::Page::moveItem(nvs::Page&) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:404

0x400eb909: nvs::PageManager::load(unsigned int, unsigned int) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_pagemanager.cpp:222

0x400ea624: nvs::Storage::init(unsigned int, unsigned int) at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_storage.cpp:41

0x400e9f2b: nvs_flash_init_custom at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:506

0x400e9f95: nvs_flash_init_partition at /home/ze/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:506

0x400d5a18: initLOG() at /home/ze/esp/sg/main/main.cpp:1419

0x400d7dbb: app_main at /home/ze/esp/sg/main/main.cpp:4571

0x400d18ac: main_task at /home/ze/esp/esp-idf/components/esp32/cpu_start.c:466

[WiFive]

https://github.com/espressif/esp-idf/issues/2026

[urbanze]

https://github.com/espressif/esp-idf/issues/2026

When occur again, I will download nvs partition (quoted in github) and bring more infos..

[urbanze]

I programmed an MCU to manipulate ESP power at various boot times. There are 5 hours in testing and nothing from nvs fails.

Until it happens again, what could be done to solve this entry point fail in RUN_TIME? Why occur? Can I get abort reason and erase partition? What can I do?