ESP_ERR_NVS_CORRUPT_KEY_PART with NVS encryption, flash encryption and secure boot enabled (IDFGH-7746)

ThanosSiopoudis commented 2 years ago

Environment

Development Kit: Custom PCB / ESP32-S3-WROOM-1-N8R8
Kit version (for WroverKit/PicoKit/DevKitC): [v1|v2|v3|v4]
Module or chip used: ESP32-S3-WROOM-1-N8R8
IDF version (run git describe --tags to find it): v5.0-dev-3654-gc2ccc383da
Build System: idf.py
Compiler version (run xtensa-esp32-elf-gcc --version to find it): xtensa-esp32-elf-gcc (crosstool-NG esp-2022r1-RC1) 11.2.0
Operating System: [macOS]
Using an IDE?: [No|Yes (please give details)] VSCode
Power Supply: external 3.3V

Problem Description

I tried using Secure Boot V2 + Flash encryption on my module with Release mode. While everything works as expected, and the device boots fine after the first reset once encryption is complete, on subsequent boots NVS encryption fails with ESP_ERR_NVS_CORRUPT_KEY_PART. The keys are generated from within the ESP32S3 device

Expected Behavior

NVS encryption should not return ESP_ERR_NVS_CORRUPT_KEY_PART once it has generated the keys

Actual Behavior

ESP_ERR_NVS_CORRUPT_KEY_PART thrown after the second device boot

Steps to reproduce

Create a new project with the attached partition table and sdkconfig file
Make sure that NVS encryption is enabled in menuconfig
Write a simple program with the attached code below
Flash the secure bootloader and other partitions to the device
Boot the device and allow it to enable secure boot and encrypt the paritions
The device will reset itself and the NVS keys will be generated. Once done it will report that the NVS parition was encrypted
Reboot the device
The device will fail with ESP_ERR_NVS_CORRUPT_KEY_PART after nvs_flash_init

Partition table

# ESP-IDF Partition Table
# Name,   Type, SubType, Offset,   Size, Flags
nvs,      data, nvs,     0xD000,   0xF000
nvs_key,  data, nvs_keys,0x1C000,  0x1000, encrypted
phy_init, data, phy,     0x1D000,  0x1000,
otadata,  data, ota,     0x1E000,  0x2000,
app0,     app,  ota_0,   0x20000,  0x3E0000,
app1,     app,  ota_1,   0x400000, 0x3E0000

Code to reproduce this issue

void app_main(void) {
    esp_err_t err_init = nvs_flash_init();
    if (err_init == ESP_ERR_NVS_NO_FREE_PAGES || err_init == ESP_ERR_NVS_NEW_VERSION_FOUND) {
      // NVS partition was truncated and needs to be erased
      // Retry nvs_flash_secure_init
      ESP_ERROR_CHECK(nvs_flash_erase());
      err_init = nvs_flash_init();
    }
    ESP_ERROR_CHECK( err_init );
    ESP_LOGI(kLogPrefix, "NVS Flash Initialised");
}

// If your code is longer than 30 lines, GIST is preferred.

Debug Logs

--- idf_monitor on /dev/cu.usbserial-1433401 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x1a (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3978,len:0x3a34
load:0x403c9700,len:0xe80
load:0x403cc700,len:0x546c
entry 0x403c9930
I (34) boot: ESP-IDF v5.0-dev-3654-gc2ccc383da-dirty 2nd stage bootloader
I (35) boot: compile time 20:00:07
I (35) boot: chip revision: 0
I (38) qio_mode: Enabling default flash chip QIO
I (44) boot.esp32s3: Boot SPI Speed : 80MHz
I (49) boot.esp32s3: SPI Mode       : QIO
I (53) boot.esp32s3: SPI Flash Size : 8MB
I (58) boot: Enabling RNG early entropy source...
I (63) boot: Partition Table:
I (67) boot: ## Label            Usage          Type ST Offset   Length
I (74) boot:  0 nvs              WiFi data        01 02 0000d000 0000f000
I (82) boot:  1 nvs_key          NVS keys         01 04 0001c000 00001000
I (89) boot:  2 phy_init         RF data          01 01 0001d000 00001000
I (97) boot:  3 otadata          OTA data         01 00 0001e000 00002000
I (104) boot:  4 app0             OTA app          00 10 00020000 003e0000
I (112) boot:  5 app1             OTA app          00 11 00400000 003e0000
I (119) boot: End of partition table
I (124) boot: No factory image, trying OTA 0
I (128) esp_image: segment 0: paddr=00020020 vaddr=3c040020 size=147cch ( 83916) map
I (150) esp_image: segment 1: paddr=000347f4 vaddr=3fc931b0 size=03a88h ( 14984) load
I (153) esp_image: segment 2: paddr=00038284 vaddr=40374000 size=07d94h ( 32148) load
I (162) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=3f414h (259092) map
I (203) esp_image: segment 4: paddr=0007f43c vaddr=4037bd94 size=07410h ( 29712) load
I (209) esp_image: segment 5: paddr=00086854 vaddr=50000000 size=00010h (    16) load
I (210) esp_image: segment 6: paddr=0008686c vaddr=00000000 size=09764h ( 38756)
I (223) esp_image: Verifying image signature...
I (224) secure_boot_v2: Secure boot V2 is not enabled yet and eFuse digest keys are not set
I (232) secure_boot_v2: Verifying with RSA-PSS...
I (240) secure_boot_v2: Signature verified successfully!
I (249) boot: Loaded app from partition at offset 0x20000
I (302) boot: Set actual ota_seq=1 in otadata[0]
I (302) secure_boot_v2: enabling secure boot v2...
I (302) efuse: Batch mode of writing fields is enabled
I (307) esp_image: segment 0: paddr=00000020 vaddr=3fce3978 size=03a34h ( 14900)
I (318) esp_image: segment 1: paddr=00003a5c vaddr=403c9700 size=00e80h (  3712)
I (324) esp_image: segment 2: paddr=000048e4 vaddr=403cc700 size=0546ch ( 21612)
I (335) esp_image: Verifying image signature...
I (338) secure_boot_v2: Secure boot V2 is not enabled yet and eFuse digest keys are not set
I (346) secure_boot_v2: Verifying with RSA-PSS...
I (354) secure_boot_v2: Signature verified successfully!
I (358) secure_boot_v2: Secure boot digests absent, generating..
I (370) secure_boot_v2: Digests successfully calculated, 1 valid signatures (image offset 0x0)
I (373) secure_boot_v2: 1 signature block(s) found appended to the bootloader.
I (381) secure_boot_v2: Burning public key hash to eFuse
I (390) efuse: Writing EFUSE_BLK_KEY0 with purpose 9
I (432) secure_boot_v2: Digests successfully calculated, 1 valid signatures (image offset 0x20000)
I (432) secure_boot_v2: 1 signature block(s) found appended to the app.
I (438) secure_boot_v2: Application key(0) matches with bootloader key(0).
I (445) secure_boot_v2: Revoking empty key digest slot (1)...
I (452) secure_boot_v2: Revoking empty key digest slot (2)...
I (458) secure_boot_v2: blowing secure boot efuse...
I (464) secure_boot: Disable ROM Download mode...
I (469) secure_boot: Disable hardware & software JTAG...
I (476) efuse: BURN BLOCK4
I (481) efuse: BURN BLOCK4 - OK (write block == read block)
I (485) efuse: BURN BLOCK0
I (490) efuse: BURN BLOCK0 - OK (all write block bits are set)
I (495) efuse: Batch mode. Prepared fields are committed
I (501) secure_boot_v2: Secure boot permanently enabled
I (506) boot: Checking flash encryption...
I (511) efuse: Batch mode of writing fields is enabled
I (517) flash_encrypt: Generating new flash encryption key...
I (526) efuse: Writing EFUSE_BLK_KEY1 with purpose 2
I (530) efuse: Writing EFUSE_BLK_KEY2 with purpose 3
I (535) flash_encrypt: Disable UART bootloader encryption...
I (541) flash_encrypt: Disable UART bootloader cache...
I (547) flash_encrypt: Disable JTAG...
I (552) efuse: BURN BLOCK6
I (558) efuse: BURN BLOCK6 - OK (write block == read block)
I (562) efuse: BURN BLOCK5
I (568) efuse: BURN BLOCK5 - OK (write block == read block)
I (571) efuse: BURN BLOCK0
I (576) efuse: BURN BLOCK0 - OK (all write block bits are set)
I (581) efuse: Batch mode. Prepared fields are committed
I (587) esp_image: segment 0: paddr=00000020 vaddr=3fce3978 size=03a34h ( 14900)
I (597) esp_image: segment 1: paddr=00003a5c vaddr=403c9700 size=00e80h (  3712)
I (604) esp_image: segment 2: paddr=000048e4 vaddr=403cc700 size=0546ch ( 21612)
I (614) esp_image: Verifying image signature...
I (617) secure_boot_v2: Verifying with RSA-PSS...
I (624) secure_boot_v2: Signature verified successfully!
I (1254) flash_encrypt: bootloader encrypted successfully
I (1316) flash_encrypt: partition table encrypted and loaded successfully
I (1316) flash_encrypt: Encrypting partition 1 at offset 0x1c000 (length 0x1000)...
I (1372) flash_encrypt: Done encrypting
I (1372) flash_encrypt: Encrypting partition 3 at offset 0x1e000 (length 0x2000)...
I (1490) flash_encrypt: Done encrypting
I (1490) esp_image: segment 0: paddr=00020020 vaddr=3c040020 size=147cch ( 83916) map
I (1504) esp_image: segment 1: paddr=000347f4 vaddr=3fc931b0 size=03a88h ( 14984)
I (1507) esp_image: segment 2: paddr=00038284 vaddr=40374000 size=07d94h ( 32148)
I (1514) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=3f414h (259092) map
I (1557) esp_image: segment 4: paddr=0007f43c vaddr=4037bd94 size=07410h ( 29712)
I (1562) esp_image: segment 5: paddr=00086854 vaddr=50000000 size=00010h (    16)
I (1563) esp_image: segment 6: paddr=0008686c vaddr=00000000 size=09764h ( 38756)
I (1577) esp_image: Verifying image signature...
I (1577) secure_boot_v2: Verifying with RSA-PSS...
I (1584) secure_boot_v2: Signature verified successfully!
I (1588) flash_encrypt: Encrypting partition 4 at offset 0x20000 (length 0x3e0000)...
I (4390) flash_encrypt: Done encrypting
I (4390) esp_image: segment 0: paddr=00400020 vaddr=3c040020 size=147cch ( 83916) map
I (4405) esp_image: segment 1: paddr=004147f4 vaddr=3fc931b0 size=03a88h ( 14984)
I (4407) esp_image: segment 2: paddr=00418284 vaddr=40374000 size=07d94h ( 32148)
I (4415) esp_image: segment 3: paddr=00420020 vaddr=42000020 size=3f414h (259092) map
I (4458) esp_image: segment 4: paddr=0045f43c vaddr=4037bd94 size=07410h ( 29712)
I (4463) esp_image: segment 5: paddr=00466854 vaddr=50000000 size=00010h (    16)
I (4463) esp_image: segment 6: paddr=0046686c vaddr=00000000 size=09764h ( 38756)
I (4477) esp_image: Verifying image signature...
I (4478) secure_boot_v2: Verifying with RSA-PSS...
I (4485) secure_boot_v2: Signature verified successfully!
I (4488) flash_encrypt: Encrypting partition 5 at offset 0x400000 (length 0x3e0000)...
I (3743) flash_encrypt: Done encrypting
I (3743) flash_encrypt: Setting CRYPT_CNT for permanent encryption
I (3743) efuse: BURN BLOCK0
I (3748) efuse: BURN BLOCK0 - OK (all write block bits are set)
I (3753) flash_encrypt: Flash encryption completed
I (3759) boot: Resetting with flash encryption enabled...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0x1a (SPI_FAST_FLASH_BOOT)
Saved PC:0x403cde96
SPIWP:0xee
mode:DIO, clock div:1
Valid secure boot key blocks: 0
secure boot verification succeeded
load:0x3fce3978,len:0x3a34
load:0x403c9700,len:0xe80
load:0x403cc700,len:0x546c
entry 0x403c9930
I (76) boot: ESP-IDF v5.0-dev-3654-gc2ccc383da-dirty 2nd stage bootloader
I (76) boot: compile time 20:00:07
I (76) boot: chip revision: 0
I (80) qio_mode: Enabling default flash chip QIO
I (85) boot.esp32s3: Boot SPI Speed : 80MHz
I (90) boot.esp32s3: SPI Mode       : QIO
I (95) boot.esp32s3: SPI Flash Size : 8MB
I (99) boot: Enabling RNG early entropy source...
I (105) boot: Partition Table:
I (108) boot: ## Label            Usage          Type ST Offset   Length
I (116) boot:  0 nvs              WiFi data        01 02 0000d000 0000f000
I (123) boot:  1 nvs_key          NVS keys         01 04 0001c000 00001000
I (131) boot:  2 phy_init         RF data          01 01 0001d000 00001000
I (138) boot:  3 otadata          OTA data         01 00 0001e000 00002000
I (146) boot:  4 app0             OTA app          00 10 00020000 003e0000
I (154) boot:  5 app1             OTA app          00 11 00400000 003e0000
I (161) boot: End of partition table
I (165) esp_image: segment 0: paddr=00020020 vaddr=3c040020 size=147cch ( 83916) map
I (189) esp_image: segment 1: paddr=000347f4 vaddr=3fc931b0 size=03a88h ( 14984) load
I (192) esp_image: segment 2: paddr=00038284 vaddr=40374000 size=07d94h ( 32148) load
I (201) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=3f414h (259092) map
I (248) esp_image: segment 4: paddr=0007f43c vaddr=4037bd94 size=07410h ( 29712) load
I (255) esp_image: segment 5: paddr=00086854 vaddr=50000000 size=00010h (    16) load
I (255) esp_image: segment 6: paddr=0008686c vaddr=00000000 size=09764h ( 38756)
I (269) esp_image: Verifying image signature...
I (269) secure_boot_v2: Verifying with RSA-PSS...
I (275) secure_boot_v2: Signature verified successfully!
I (285) boot: Loaded app from partition at offset 0x20000
I (285) secure_boot_v2: enabling secure boot v2...
I (290) secure_boot_v2: secure boot v2 is already enabled, continuing..
I (297) boot: Checking flash encryption...
I (302) flash_encrypt: flash encryption is enabled (0 plaintext flashes left)
I (310) boot: Disabling RNG early entropy source...
I (327) octal_psram: vendor id    : 0x0d (AP)
I (327) octal_psram: dev id       : 0x02 (generation 3)
I (327) octal_psram: density      : 0x03 (64 Mbit)
I (332) octal_psram: good-die     : 0x01 (Pass)
I (337) octal_psram: Latency      : 0x01 (Fixed)
I (343) octal_psram: VCC          : 0x01 (3V)
I (348) octal_psram: SRF          : 0x01 (Fast Refresh)
I (353) octal_psram: BurstType    : 0x01 (Hybrid Wrap)
I (359) octal_psram: BurstLen     : 0x01 (32 Byte)
I (365) octal_psram: Readlatency  : 0x02 (10 cycles@Fixed)
I (371) octal_psram: DriveStrength: 0x00 (1/1)
W (376) PSRAM: DO NOT USE FOR MASS PRODUCTION! Timing parameters will be updated in future IDF version.
I (387) esp_psram: Found 8MBit SPI RAM device
I (391) esp_psram: Speed: 80MHz
I (395) cpu_start: Pro cpu up.
I (399) cpu_start: Starting app cpu, entry point is 0x40375508
0x40375508: call_start_cpu1 at /Users/thanos/Projects/8BitMods/esp-idf/components/esp_system/port/cpu_start.c:147

I (0) cpu_start: App cpu up.
I (1218) esp_psram: SPI SRAM memory test OK
I (1227) cpu_start: Pro cpu start user code
I (1227) cpu_start: cpu freq: 240000000 Hz
I (1227) cpu_start: Application information:
I (1230) cpu_start: Project name:     My-Project
I (1235) cpu_start: App version:      4d795b4-dirty
I (1241) cpu_start: Compile time:     Jul  4 2022 18:37:38
I (1247) cpu_start: ELF file SHA256:  6612bf29e39c456a...
I (1253) cpu_start: ESP-IDF:          v5.0-dev-3654-gc2ccc383da-dirty
I (1260) heap_init: Initializing. RAM available for dynamic allocation:
I (1268) heap_init: At 3FC98FC8 len 00047038 (284 KiB): D/IRAM
I (1274) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM
I (1281) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (1287) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
I (1294) esp_psram: Adding pool of 8192K of external SPI memory to heap allocator
I (1302) spi_flash: detected chip: generic
I (1306) spi_flash: flash io: qio
I (1311) flash_encrypt: Flash encryption mode is RELEASE
I (1317) sleep: Configure to isolate all GPIO pins in sleep state
I (1323) sleep: Enable automatic switching of GPIO sleep configuration
I (1331) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1376) gpio: GPIO[42]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1376) OLED: Display attached: 1
I (1420) OLED: Display inited: 1
I (1420) [OLEDDisplay]: Setting brightness to 255
I (1420) [MemoryCard]: Initialising I2C Master
I (1424) [MYPROJ SDFS]: Initialising SD Card.
I (1428) gpio: GPIO[8]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1438) gpio: GPIO[9]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1446) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1456) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1466) gpio: GPIO[17]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1474) gpio: GPIO[16]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1658) gpio: GPIO[16]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
Name: SC16G
Type: SDHC/SDXC
Speed: 40 MHz
Size: 15193MB
CSD: ver=2, sector_size=512, capacity=31116288 read_bl_len=9
SSR: bus_width=4
I (1670) nvs: NVS key partition empty, generating keys
I (1736) nvs: NVS partition "nvs" is encrypted.
I (1736) [MYPROJ]: NVS Flash Initialised

Rebooting...
␀�ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x1b (SPI_FAST_FLASH_BOOT)
Saved PC:0x40375c8c
SPIWP:0xee
mode:DIO, clock div:1
Valid secure boot key blocks: 0
secure boot verification succeeded
load:0x3fce3978,len:0x3a34
load:0x403c9700,len:0xe80
load:0x403cc700,len:0x546c
entry 0x403c9930
␛[0;32mI (76) boot: ESP-IDF v5.0-dev-3654-gc2ccc383da-dirty 2nd stage bootloader␛[0m
␛[0;32mI (76) boot: compile time 20:00:07␛[0m
␛[0;32mI (76) boot: chip revision: 0␛[0m
␛[0;32mI (80) qio_mode: Enabling default flash chip QIO␛[0m
␛[0;32mI (85) boot.esp32s3: Boot SPI Speed : 80MHz␛[0m
␛[0;32mI (90) boot.esp32s3: SPI Mode       : QIO␛[0m
␛[0;32mI (95) boot.esp32s3: SPI Flash Size : 8MB␛[0m
␛[0;32mI (99) boot: Enabling RNG early entropy source...␛[0m
␛[0;32mI (105) boot: Partition Table:␛[0m
␛[0;32mI (108) boot: ## Label            Usage          Type ST Offset   Length␛[0m
␛[0;32mI (116) boot:  0 nvs              WiFi data        01 02 0000d000 0000f000␛[0m
␛[0;32mI (123) boot:  1 nvs_key          NVS keys         01 04 0001c000 00001000␛[0m
␛[0;32mI (131) boot:  2 phy_init         RF data          01 01 0001d000 00001000␛[0m
␛[0;32mI (138) boot:  3 otadata          OTA data         01 00 0001e000 00002000␛[0m
␛[0;32mI (146) boot:  4 app0             OTA app          00 10 00020000 003e0000␛[0m
␛[0;32mI (154) boot:  5 app1             OTA app          00 11 00400000 003e0000␛[0m
␛[0;32mI (161) boot: End of partition table␛[0m
␛[0;32mI (165) esp_image: segment 0: paddr=00020020 vaddr=3c040020 size=147cch ( 83916) map␛[0m
␛[0;32mI (189) esp_image: segment 1: paddr=000347f4 vaddr=3fc931b0 size=03a88h ( 14984) load␛[0m
␛[0;32mI (192) esp_image: segment 2: paddr=00038284 vaddr=40374000 size=07d94h ( 32148) load␛[0m
␛[0;32mI (201) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=3f414h (259092) map␛[0m
␛[0;32mI (248) esp_image: segment 4: paddr=0007f43c vaddr=4037bd94 size=07410h ( 29712) load␛[0m
␛[0;32mI (255) esp_image: segment 5: paddr=00086854 vaddr=50000000 size=00010h (    16) load␛[0m
␛[0;32mI (255) esp_image: segment 6: paddr=0008686c vaddr=00000000 size=09764h ( 38756) ␛[0m
␛[0;32mI (269) esp_image: Verifying image signature...␛[0m
␛[0;32mI (269) secure_boot_v2: Verifying with RSA-PSS...␛[0m
␛[0;32mI (275) secure_boot_v2: Signature verified successfully!␛[0m
␛[0;32mI (285) boot: Loaded app from partition at offset 0x20000␛[0m
␛[0;32mI (285) secure_boot_v2: enabling secure boot v2...␛[0m
␛[0;32mI (290) secure_boot_v2: secure boot v2 is already enabled, continuing..␛[0m
␛[0;32mI (297) boot: Checking flash encryption...␛[0m
␛[0;32mI (302) flash_encrypt: flash encryption is enabled (0 plaintext flashes left)␛[0m
␛[0;32mI (310) boot: Disabling RNG early entropy source...␛[0m
␛[0;32mI (327) octal_psram: vendor id    : 0x0d (AP)␛[0m
␛[0;32mI (327) octal_psram: dev id       : 0x02 (generation 3)␛[0m
␛[0;32mI (327) octal_psram: density      : 0x03 (64 Mbit)␛[0m
␛[0;32mI (332) octal_psram: good-die     : 0x01 (Pass)␛[0m
␛[0;32mI (337) octal_psram: Latency      : 0x01 (Fixed)␛[0m
␛[0;32mI (343) octal_psram: VCC          : 0x01 (3V)␛[0m
␛[0;32mI (348) octal_psram: SRF          : 0x01 (Fast Refresh)␛[0m
␛[0;32mI (353) octal_psram: BurstType    : 0x01 (Hybrid Wrap)␛[0m
␛[0;32mI (359) octal_psram: BurstLen     : 0x01 (32 Byte)␛[0m
␛[0;32mI (365) octal_psram: Readlatency  : 0x02 (10 cycles@Fixed)␛[0m
␛[0;32mI (371) octal_psram: DriveStrength: 0x00 (1/1)␛[0m
␛[0;33mW (376) PSRAM: DO NOT USE FOR MASS PRODUCTION! Timing parameters will be updated in future IDF version.␛[0m
␛[0;32mI (387) esp_psram: Found 8MBit SPI RAM device␛[0m
␛[0;32mI (391) esp_psram: Speed: 80MHz␛[0m
␛[0;32mI (395) cpu_start: Pro cpu up.␛[0m
␛[0;32mI (399) cpu_start: Starting app cpu, entry point is 0x40375508␛[0m
␛[0;32mI (348) cpu_start: App cpu up.␛[0m
␛[0;32mI (1218) esp_psram: SPI SRAM memory test OK␛[0m
␛[0;32mI (1227) cpu_start: Pro cpu start user code␛[0m
␛[0;32mI (1227) cpu_start: cpu freq: 240000000 Hz␛[0m
␛[0;32mI (1227) cpu_start: Application information:␛[0m
␛[0;32mI (1230) cpu_start: Project name:     My-Project␛[0m
␛[0;32mI (1235) cpu_start: App version:      4d795b4-dirty␛[0m
␛[0;32mI (1241) cpu_start: Compile time:     Jul  4 2022 18:37:38␛[0m
␛[0;32mI (1247) cpu_start: ELF file SHA256:  6612bf29e39c456a...␛[0m
␛[0;32mI (1253) cpu_start: ESP-IDF:          v5.0-dev-3654-gc2ccc383da-dirty␛[0m
␛[0;32mI (1260) heap_init: Initializing. RAM available for dynamic allocation:␛[0m
␛[0;32mI (1268) heap_init: At 3FC98FC8 len 00047038 (284 KiB): D/IRAM␛[0m
␛[0;32mI (1274) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM␛[0m
␛[0;32mI (1281) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM␛[0m
␛[0;32mI (1287) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM␛[0m
␛[0;32mI (1294) esp_psram: Adding pool of 8192K of external SPI memory to heap allocator␛[0m
␛[0;32mI (1302) spi_flash: detected chip: generic␛[0m
␛[0;32mI (1306) spi_flash: flash io: qio␛[0m
␛[0;32mI (1311) flash_encrypt: Flash encryption mode is RELEASE␛[0m
␛[0;32mI (1317) sleep: Configure to isolate all GPIO pins in sleep state␛[0m
␛[0;32mI (1323) sleep: Enable automatic switching of GPIO sleep configuration␛[0m
␛[0;32mI (1331) cpu_start: Starting scheduler on PRO CPU.␛[0m
␛[0;32mI (0) cpu_start: Starting scheduler on APP CPU.␛[0m
␛[0;32mI (1376) gpio: GPIO[42]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1376) OLED: Display attached: 1␛[0m
␛[0;32mI (1420) OLED: Display inited: 1␛[0m
␛[0;32mI (1420) [OLEDDisplay]: Setting brightness to 255␛[0m
␛[0;32mI (1420) [MemoryCard]: Initialising I2C Master␛[0m
␛[0;32mI (1424) [MYPROJ SDFS]: Initialising SD Card.␛[0m
␛[0;32mI (1428) gpio: GPIO[8]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1438) gpio: GPIO[9]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1446) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1456) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1466) gpio: GPIO[17]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1474) gpio: GPIO[16]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 ␛[0m
␛[0;32mI (1548) gpio: GPIO[16]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 ␛[0m
Name: SC16G
Type: SDHC/SDXC
Speed: 40 MHz
Size: 15193MB
CSD: ver=2, sector_size=512, capacity=31116288 read_bl_len=9
SSR: bus_width=4
␛[0;31mE (1560) nvs: Failed to read NVS security cfg: [0x1117] (ESP_ERR_NVS_CORRUPT_KEY_PART)␛[0m
ESP_ERROR_CHECK failed: esp_err_t 0x1117 (ESP_ERR_NVS_CORRUPT_KEY_PART) at 0x4037b8c4

Other items if possible

sdkconfig.zip

[x] sdkconfig file (attach the sdkconfig file from your project folder)

mahavirj commented 2 years ago

@ThanosSiopoudis

Can you please confirm behavior with SPIRAM disabled, do you still observe same issue? I suspect this could be related to https://github.com/espressif/esp-idf/issues/9244#issuecomment-1174702372

ThanosSiopoudis commented 2 years ago

@mahavirj Sure, I'll give it a go and I'll let you know. Do you think this could also be affecting OTA updates? I have code that works without flash encryption, updating the app partitions, and once I try it on a flash encrypted device it bricks it with error invalid header: 0x6e951e03

ThanosSiopoudis commented 2 years ago

I can confirm that both NVS and OTA updates work with SPIRAM disabled. Are there any workarounds?

mahavirj commented 2 years ago

Are there any workarounds?

Not yet. We are working on this, will keep you posted. CC @ginkgm

ThanosSiopoudis commented 2 years ago

Ok, thanks. I can reliably reproduce the OTA update issue, so I can share code if it's helpful. I'm doing the OTA update through an AES encrypted binary from an sd card, and it fails after 1000-1500 bytes written to flash through esp_ota_write there's a very random panic thrown which is different every time.

This results in a reboot and corrupts the bootloader, bricking the device (recoverable if flashed through development mode). The same code works fine with either flash encryption disabled + PSRAM enabled, or flash encryption enabled + PSRAM disabled.

Please let me know if you prefer I open a new issue with logs and example code for this, unless it's confirmed it's related to the NVS issue.