nvs_flash_init returns ESP_ERR_NVS_NOT_INITIALIZED (QEMU-171)

[rustyx]

My startup code looks like this

esp_err_t ret = nvs_flash_init();
if (ret == ESP_ERR_NVS_NO_FREE_PAGES) {
    ret = nvs_flash_erase();
    ESP_LOGE(TAG, "nvs_flash_erase: %s", esp_err_to_name(ret));
    ret = nvs_flash_init();
}
if (ret != ESP_OK) {
    ESP_LOGE(TAG, "nvs_flash_init: %s", esp_err_to_name(ret));
}

When I run QEMU in ESP32 mode, NVRAM storage cannot be initialized:

$ (cd build && esptool.py --chip esp32 merge_bin --fill-flash-size 4MB -o flash_image.bin @flash_args)

$ ~/qemu/build/qemu-system-xtensa -nographic -machine esp32 -drive file=build/flash_image.bin,if=mtd,format=raw

Adding SPI flash device
ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x12 (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:2
load:0x3fff0030,len:6012
ho 0 tail 12 room 4
load:0x40078000,len:15320
ho 0 tail 12 room 4
load:0x40080400,len:4424
entry 0x4008069c
I (867) boot: ESP-IDF v4.4.6-56-g987a77505b 2nd stage bootloader
I (872) boot: compile time 22:11:02
I (873) boot: Multicore bootloader
I (891) boot: chip revision: v0.0
I (903) qio_mode: Enabling default flash chip QIO
E (906) qio_mode: Failed to set QIE bit, not enabling QIO mode
I (907) boot.esp32: SPI Speed      : 40MHz
I (908) boot.esp32: SPI Mode       : DIO
I (908) boot.esp32: SPI Flash Size : 4MB
I (930) boot: Enabling RNG early entropy source...
I (965) boot: Partition Table:
I (966) boot: ## Label            Usage          Type ST Offset   Length
I (967) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (969) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (970) boot:  2 factory          factory app      00 00 00010000 00100000
I (980) boot: End of partition table
I (992) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=16784h ( 92036) map
I (1099) esp_image: segment 1: paddr=000267ac vaddr=3ffb0000 size=02f7ch ( 12156) load
I (1133) esp_image: segment 2: paddr=00029730 vaddr=40080000 size=068e8h ( 26856) load
I (1187) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=848a4h (542884) map
I (1682) esp_image: segment 4: paddr=000b48cc vaddr=400868e8 size=0d040h ( 53312) load
I (1756) boot: Loaded app from partition at offset 0x10000
I (1757) boot: Disabling RNG early entropy source...
I (1785) cpu_start: Multicore app
I (1798) cpu_start: Pro cpu up.
I (1803) cpu_start: Starting app cpu, entry point is 0x40080de4
I (1389) cpu_start: App cpu up.
I (3318) cpu_start: Pro cpu start user code
I (3323) cpu_start: cpu freq: 160000000
I (3324) cpu_start: Application information:
I (3325) cpu_start: Project name:     itho-esp
I (3325) cpu_start: App version:      ad05cd0-dirty
I (3326) cpu_start: Compile time:     Oct 14 2023 20:11:09
I (3328) cpu_start: ELF file SHA256:  b45919fa506d8769...
I (3329) cpu_start: ESP-IDF:          v4.4.6-56-g987a77505b
I (3330) cpu_start: Min chip rev:     v0.0
I (3330) cpu_start: Max chip rev:     v3.99 
I (3331) cpu_start: Chip rev:         v0.0
I (3337) heap_init: Initializing. RAM available for dynamic allocation:
I (3341) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (3343) heap_init: At 3FFB7720 len 000288E0 (162 KiB): DRAM
I (3344) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (3344) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (3346) heap_init: At 40093928 len 0000C6D8 (49 KiB): IRAM
I (3448) spi_flash: detected chip: gd
I (3475) spi_flash: flash io: qio
I (3541) cpu_start: Starting scheduler on PRO CPU.
I (10) cpu_start: Starting scheduler on APP CPU.
E (3776) Nvs: nvs_flash_init: ESP_ERR_FLASH_NOT_INITIALISED
W (3786) Nvs: nvs_open: ESP_ERR_NVS_NOT_INITIALIZED

What am I missing?

Note- I build my project with IDF-SDK v4.4:

$ idf.py build
Executing action: all (aliases: build)
Running ninja in directory /home/user/proj1/build
Executing "ninja all"...
[1/4] cd /home/user/proj1/build/esp-idf/esptool_py && python /home/me/esp/esp-idf/components/partit.../home/user/proj1/build/partition_table/partition-table.bin /home/user/proj1/build/proj1.bin
proj1.bin binary size 0xb1930 bytes. Smallest app partition is 0x100000 bytes. 0x4e6d0 bytes (31%) free.
[2/4] Performing build step for 'bootloader'
[1/1] cd /home/user/proj1/build/bootloader/esp-idf/esptool_py && python /home/me/esp/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 bootloader 0x1000 /home/user/proj1/build/bootloader/bootloader.bin
Bootloader binary size 0x64f0 bytes. 0xb10 bytes (10%) free.

Project build complete. To flash, run this command:
/home/me/.espressif/python_env/idf4.4_py3.10_env/bin/python ../../esp/esp-idf/components/esptool_py/esptool/esptool.py -p (PORT) -b 460800 --before default_reset --after hard_reset --chip esp32  write_flash --flash_mode dio --flash_size detect --flash_freq 40m 0x1000 build/bootloader/bootloader.bin 0x8000 build/partition_table/partition-table.bin 0x10000 build/proj1.bin
or run 'idf.py -p (PORT) flash'

Tried calling nvs_flash_erase(), same result.

QEMU esp-develop 2e51514.

[rustyx]

Seems to be related to the QIO mode failure. Switching to DIO mode "fixes" the issue.

I run my actual ESP32 device in QIO mode. Doesn't QEMU support QIO mode?