nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

jcsbanks
Posts: 305
Joined: Tue Mar 28, 2017 8:03 pm

nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

Postby jcsbanks » Tue Aug 14, 2018 2:57 pm

I have a DEVKIT C that I have been working with on one computer, then installed ESP-IDF on a new computer. I wanted to test something on the old computer/old build, it flashed OK, then crashes with nvs_flash_init.

The DEVKIT can be flashed on the new computer and works again.

Code: Select all

Rebooting...
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:6016
ho 0 tail 12 room 4
load:0x40078000,len:0
load:0x40078000,len:15692
entry 0x40079018
I (30) boot: ESP-IDF v3.1-dev-463-g77eae33a-dirty 2nd stage bootloader
I (30) boot: compile time 15:38:56
I (32) boot: Enabling RNG early entropy source...
I (37) qio_mode: Enabling default flash chip QIO
I (42) boot: SPI Speed      : 80MHz
I (47) boot: SPI Mode       : QIO
I (51) boot: SPI Flash Size : 4MB
I (55) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (73) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00100000
I (88) boot: End of partition table
I (92) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x13458 ( 78936) map
I (110) esp_image: segment 1: paddr=0x00023480 vaddr=0x3ffb0000 size=0x03264 ( 12900) load
I (111) esp_image: segment 2: paddr=0x000266ec vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (119) esp_image: segment 3: paddr=0x00026af4 vaddr=0x40080400 size=0x0951c ( 38172) load
I (133) esp_image: segment 4: paddr=0x00030018 vaddr=0x400d0018 size=0x58d08 (363784) map
0x400d0018: _stext at ??:?

I (177) esp_image: segment 5: paddr=0x00088d28 vaddr=0x4008991c size=0x07268 ( 29288) load
0x4008991c: udp_sendto_if_src at C:/msys32/home/jcsba/esp/esp-idf/components/lwip/core/udp.c:1157

I (181) esp_image: segment 6: paddr=0x0008ff98 vaddr=0x400c0000 size=0x00000 (     0) load
I (187) boot: Loaded app from partition at offset 0x10000
I (190) boot: Disabling RNG early entropy source...
I (195) cpu_start: Pro cpu up.
I (199) cpu_start: Starting app cpu, entry point is 0x40081190
0x40081190: call_start_cpu1 at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/cpu_start.c:225

I (180) cpu_start: App cpu up.
I (209) heap_init: Initializing. RAM available for dynamic allocation:
D (216) heap_init: New heap initialised at 0x3ffae6e0
I (221) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (227) heap_init: New heap initialised at 0x3ffb9000
I (233) heap_init: At 3FFB9000 len 00027000 (156 KiB): DRAM
I (239) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (245) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (252) heap_init: New heap initialised at 0x40090b84
I (257) heap_init: At 40090B84 len 0000F47C (61 KiB): IRAM
I (263) cpu_start: Pro cpu start user code
D (275) clk: RTC_SLOW_CLK calibration value: 3188480
D (60) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (61) intr_alloc: Connected src 57 to int 3 (cpu 0)
D (61) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (66) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (4) cpu_start: Starting scheduler on APP CPU.
D (91) heap_init: New heap initialised at 0x3ffe0440
D (97) heap_init: New heap initialised at 0x3ffe4350
D (102) intr_alloc: Connected src 16 to int 12 (cpu 0)
D (107) nvs: nvs_flash_init_custom partition=nvs start=9 count=6
assertion "false && "item should have been present in cache"" failed: file "C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_item_hash_list.cpp", line 85, function: void nvs::HashList::erase(size_t
)
abort() was called at PC 0x400d571f on core 0
0x400d571f: __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: 0x4008ead0:0x3ffbaab0 0x4008eca7:0x3ffbaad0 0x400d571f:0x3ffbaaf0 0x400e4144:0x3ffbab20 0x400e47b6:0x3ffbab40 0x400e4a91:0x3ffbab80 0x400e3834:0x3ffbabd0 0x400e33db:0x3ffbac20 0x400e3463:0x3ffbac50 0
x400e348e:0x3ffbac70 0x400d3f67:0x3ffbac90 0x400d10ae:0x3ffbad80
0x4008ead0: invoke_abort at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/panic.c:648

0x4008eca7: abort at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/panic.c:648

0x400d571f: __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)

0x400e4144: nvs::HashList::erase(unsigned int) at C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_item_hash_list.cpp:85

0x400e47b6: nvs::Page::eraseEntryAndSpan(unsigned int) at C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:311

0x400e4a91: nvs::Page::findItem(unsigned char, nvs::ItemType, char const*, unsigned int&, nvs::Item&) at C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:311

Next post has startup from same code flashed with ESP IDF 3.2. Is this expected behaviour?

jcsbanks
Posts: 305
Joined: Tue Mar 28, 2017 8:03 pm

Re: nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

Postby jcsbanks » Tue Aug 14, 2018 2:59 pm

Code: Select all

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_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:6352
ho 0 tail 12 room 4
load:0x40078000,len:9884
load:0x40080400,len:6840
entry 0x40080768
I (31) boot: ESP-IDF v3.2-dev-498-g30545f4c 2nd stage bootloader
I (31) boot: compile time 15:46:15
I (31) boot: Enabling RNG early entropy source...
I (37) qio_mode: Enabling default flash chip QIO
I (42) boot: SPI Speed      : 80MHz
I (46) boot: SPI Mode       : QIO
I (50) boot: SPI Flash Size : 4MB
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (73) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00100000
I (88) boot: End of partition table
I (92) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1690c ( 92428) map
I (111) esp_image: segment 1: paddr=0x00026934 vaddr=0x3ffb0000 size=0x035b4 ( 13748) load
I (113) esp_image: segment 2: paddr=0x00029ef0 vaddr=0x3ffb35b4 size=0x00000 (     0) load
I (119) esp_image: segment 3: paddr=0x00029ef8 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at C:/msys32/home/Banks/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (128) esp_image: segment 4: paddr=0x0002a300 vaddr=0x40080400 size=0x05d10 ( 23824) load
I (140) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x66098 (417944) map
0x400d0018: _stext at ??:?

I (192) esp_image: segment 6: paddr=0x000960b8 vaddr=0x40086110 size=0x0cd0c ( 52492) load
0x40086110: ppSearchTxframe at ??:?

I (199) esp_image: segment 7: paddr=0x000a2dcc vaddr=0x400c0000 size=0x00000 (     0) load
I (199) esp_image: segment 8: paddr=0x000a2dd4 vaddr=0x50000000 size=0x00000 (     0) load
I (211) boot: Loaded app from partition at offset 0x10000
I (214) boot: Disabling RNG early entropy source...
I (219) cpu_start: Pro cpu up.
I (223) cpu_start: Starting app cpu, entry point is 0x40081228
0x40081228: call_start_cpu1 at C:/msys32/home/Banks/esp/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
D (233) memory_layout: Checking 7 reserved memory ranges:
D (239) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (245) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb9710
D (251) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (258) memory_layout: Reserved memory range 0x3ffe4000 - 0x3ffe4350
D (264) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (271) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at C:/msys32/home/Banks/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

D (277) memory_layout: Reserved memory range 0x40080000 - 0x40092e1c
0x40080000: _WindowOverflow4 at C:/msys32/home/Banks/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

D (284) memory_layout: Building list of available memory regions:
D (290) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000
D (296) memory_layout: Available memory region 0x3ffb9710 - 0x3ffc0000
D (303) memory_layout: Available memory region 0x3ffc0000 - 0x3ffc2000
D (309) memory_layout: Available memory region 0x3ffc2000 - 0x3ffc4000
D (316) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
D (323) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
D (329) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
D (336) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
D (342) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
D (349) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
D (356) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
D (362) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
D (369) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
D (375) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
D (382) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
D (389) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
D (395) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
D (402) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
D (408) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe4000
D (415) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
D (422) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
D (428) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
D (435) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
D (441) memory_layout: Available memory region 0x3fffc000 - 0x40000000
D (448) memory_layout: Available memory region 0x40092e1c - 0x40094000
D (455) memory_layout: Available memory region 0x40094000 - 0x40096000
D (461) memory_layout: Available memory region 0x40096000 - 0x40098000
D (468) memory_layout: Available memory region 0x40098000 - 0x4009a000
D (474) memory_layout: Available memory region 0x4009a000 - 0x4009c000
D (481) memory_layout: Available memory region 0x4009c000 - 0x4009e000
D (488) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (494) heap_init: Initializing. RAM available for dynamic allocation:
D (501) heap_init: New heap initialised at 0x3ffae6e0
I (507) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (513) heap_init: New heap initialised at 0x3ffb9710
I (518) heap_init: At 3FFB9710 len 000268F0 (154 KiB): DRAM
I (524) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (530) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (537) heap_init: New heap initialised at 0x40092e1c
I (542) heap_init: At 40092E1C len 0000D1E4 (52 KiB): IRAM
I (548) cpu_start: Pro cpu start user code
D (560) clk: RTC_SLOW_CLK calibration value: 3190630
D (47) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (48) intr_alloc: Connected src 57 to int 3 (cpu 0)
D (48) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (53) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (4) cpu_start: Starting scheduler on APP CPU.
D (78) heap_init: New heap initialised at 0x3ffe0440
D (84) heap_init: New heap initialised at 0x3ffe4350
D (89) intr_alloc: Connected src 16 to int 12 (cpu 0)
D (94) nvs: nvs_flash_init_custom partition=nvs start=9 count=6
D (125) nvs: nvs_open_from_partition misc 1
D (125) nvs: nvs_get_str_or_blob log
I (125) wifi: wifi driver task: 3ffc0f24, prio:23, stack:3584, core=0
I (128) wifi: wifi firmware version: 7aac1f9
I (132) wifi: config NVS flash: enabled
I (135) wifi: config nano formating: disabled
I (139) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (149) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (158) nvs: nvs_open_from_partition nvs.net80211 1
D (163) nvs: nvs_get opmode 1
D (166) nvs: nvs_get_str_or_blob sta.ssid
D (171) nvs: nvs_get_str_or_blob sta.mac
D (175) nvs: nvs_get sta.authmode 1
D (178) nvs: nvs_get_str_or_blob sta.pswd
D (183) nvs: nvs_get_str_or_blob sta.pmk
D (186) nvs: nvs_get sta.chan 1
D (189) nvs: nvs_get auto.conn 1
D (193) nvs: nvs_get bssid.set 1
D (196) nvs: nvs_get_str_or_blob sta.bssid
D (200) nvs: nvs_get sta.lis_intval 2
D (204) nvs: nvs_get sta.phym 1
D (207) nvs: nvs_get sta.phybw 1
D (210) nvs: nvs_get_str_or_blob sta.apsw
D (215) nvs: nvs_get_str_or_blob sta.apinfo
D (220) nvs: nvs_get sta.scan_method 1
D (223) nvs: nvs_get sta.sort_method 1
D (226) nvs: nvs_get sta.minrssi 1
D (230) nvs: nvs_get sta.minauth 1
D (233) nvs: nvs_get_str_or_blob ap.ssid
D (238) nvs: nvs_get_str_or_blob ap.mac
D (242) nvs: nvs_get_str_or_blob ap.passwd
D (246) nvs: nvs_get_str_or_blob ap.pmk
D (249) nvs: nvs_get ap.chan 1
D (252) nvs: nvs_get ap.authmode 1
D (256) nvs: nvs_get ap.hidden 1
D (259) nvs: nvs_get ap.max.conn 1
D (263) nvs: nvs_get bcn.interval 2
D (266) nvs: nvs_get ap.phym 1
D (269) nvs: nvs_get ap.phybw 1
D (273) nvs: nvs_get ap.sndchan 1
D (276) nvs: nvs_get lorate 1
D (279) nvs: nvs_set_blob sta.mac 6
D (284) nvs: nvs_set_blob ap.mac 6
I (288) wifi: Init dynamic tx buffer num: 64
I (290) wifi: Init data frame dynamic rx buffer num: 64
I (295) wifi: Init management frame dynamic rx buffer num: 64
I (300) wifi: Init static rx buffer size: 1600
I (304) wifi: Init static rx buffer num: 16
I (308) wifi: Init dynamic rx buffer num: 64
D (313) RTC_MODULE: Wi-Fi takes adc2 lock.
D (317) phy_init: loading PHY init data from application binary
D (322) nvs: nvs_open_from_partition phy 0
D (327) nvs: nvs_get cal_version 4
D (330) nvs: nvs_get_str_or_blob cal_mac
D (335) nvs: nvs_get_str_or_blob cal_data
D (343) nvs: nvs_close 3
I (390) phy: phy_version: 3960, 5211945, Jul 18 2018, 10:40:07, 0, 0
I (391) wifi: mode : sta (30:ae:a4:02:3f:9c)
D (391) event: SYSTEM_EVENT_STA_START
I (394) app_main: SYSTEM_EVENT_STA_START
D (399) rmt: RD (400) intr_alloc: Cmonnected src 45 to int 3 (cpu 1)
t Rx Channel 0|Gpio 34|Sclk_Hz 80000000|Div 80|Thresold 30000|Filter 255
I (640) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1358) wifi: state: init -> auth (b0)
I (1360) wifi: state: auth -> assoc (0)
I (1365) wifi: state: assoc -> run (10)
I (1375) wifi: connected with BTHomeHub2-QFFW, channel 1
I (1375) wifi: pm start, type: 1

D (1375) event: SYSTEM_EVENT_STA_CONNECTED, ssid:REMOVED, ssid_len:15, bssid:REMOVED, channel:1, authmode:3
D (1384) tcpip_adapter: dhcp client init ip/mask/gw to all-0
D (1389) tcpip_adapter: if0 start ip lost tmr: enter
D (1394) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffc8368 interval=120 ip=0
D (1404) tcpip_adapter: dhcp client start successfully
I (1409) app_main: SYSTEM_EVENT_STA_CONNECTED
D (2129) tcpip_adapter: if0 dhcpc cb
D (2129) tcpip_adapter: if0 ip changed=1
D (2129) event: SYSTEM_EVENT_STA_GOT_IP, ip:192.168.1.233, mask:255.255.255.0, gw:192.168.1.1
I (2134) event: sta ip: 192.168.1.233, mask: 255.255.255.0, gw: 192.168.1.1
I (2142) app_main: SYSTEM_EVENT_STA_GOT_IP


jcsbanks
Posts: 305
Joined: Tue Mar 28, 2017 8:03 pm

Re: nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

Postby jcsbanks » Tue Aug 14, 2018 3:02 pm

WiFi code at beginning of main():

Code: Select all

void app_main()
{
    nvs_flash_init();
    tcpip_adapter_init();
    ESP_ERROR_CHECK( esp_event_loop_init(event_handler, NULL) );
    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    ESP_ERROR_CHECK( esp_wifi_init(&cfg) );
    ESP_ERROR_CHECK( esp_wifi_set_storage(WIFI_STORAGE_RAM) );
    ESP_ERROR_CHECK( esp_wifi_set_mode(WIFI_MODE_STA) );
    
	wifi_config_t sta_config =
	{
        .sta = {
			.ssid = "REMOVED",
			.password = "REMOVED",
			.channel = 11,
		}
    };

    ESP_ERROR_CHECK( esp_wifi_set_config(WIFI_IF_STA, &sta_config) );
    ESP_ERROR_CHECK( esp_wifi_start() );

User avatar
fly135
Posts: 606
Joined: Wed Jan 03, 2018 8:33 pm
Location: Orlando, FL

Re: nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

Postby fly135 » Tue Aug 14, 2018 3:23 pm

jcsbanks wrote:I have a DEVKIT C that I have been working with on one computer, then installed ESP-IDF on a new computer. I wanted to test something on the old computer/old build, it flashed OK, then crashes with nvs_flash_init.
I've experienced this before switching between IDFs. I just do a "make erase-flash" and then it's fine. Although you lose what's in the NVS.

John A

ESP_igrr
Posts: 2067
Joined: Tue Dec 01, 2015 8:37 am

Re: nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

Postby ESP_igrr » Tue Aug 14, 2018 4:15 pm

Hi jcsbanks,

As of commit https://github.com/espressif/esp-idf/co ... 65eba04366 (this on release/v3.1 branch), NVS will check the version of the data in flash, and nvs_flash_init will return ESP_ERR_NVS_NEW_VERSION_FOUND error if data has more recent format than supported by the running code.

If the version you are running is earlier than that commit, you will likely get a run time failure when trying to open IDF v3.2 nvs partition with IDF v3.1.

jcsbanks
Posts: 305
Joined: Tue Mar 28, 2017 8:03 pm

Re: nvs: nvs_flash_init_custom "item should have been present in cache" when flashing with ESP-IDF 3.1 after 3.2

Postby jcsbanks » Tue Aug 14, 2018 4:24 pm

Thanks guys!

The reason for wanting to go back was ping times 100ms on 3.2 vs 1ms on 3.1, but it was not due to ESP IDF 3.2, but because I changed from AP to STA as the other computer has wired ethernet instead of WiFi.

When there is concurrent WiFi traffic with either ESP IDF version, the ping times drop back to about 1ms in STA mode. Probably power saving, but it doesn't affect application throughput.

Who is online

Users browsing this forum: Baidu [Spider], Google [Bot] and 99 guests