get_nvs_str() causes not found key if Flash Encryption + NVS Encryption are enabled

[momentum84]

Hi,

I'm preparing for mass-production based on ESP32-S3 and using ESP-IDF v5.3.

To do this, I'm testing enabling Flash Encryption as development mode and NVS Encryption.
After doing that, get_nvs_str() causes key not found issue when I read some keys from nvs partition.
It must be read because I wrote the pre-built nvs partition data before.

What's wrong in my test?

- I created nvs partition bin file using mfg_gen.py. It's located in build/mass_mfg/bin. It's not encrypted.
- My partition table is as follows.
# Name, Type, SubType, Offset, Size, Flags
# Note: if you have increased the bootloader size, make sure to update the offsets to avoid overlap
nvs,data,nvs,0x21000,0x40000
otadata,data,ota,0x61000,0x2000
phy_init,data,phy,0x63000,0x1000
factory,app,factory,0x70000,0x400000
app0,app,ota_0,0x470000,0x400000
app1,app,ota_1,0x870000,0x400000
storage,data,spiffs,0xC70000,0x300000
nvs_key,data,nvs_keys,0xF70000,0x1000,encrypted

- I also enabled ESP-IDF config for Flash Encryption as development mode and NVS Encryption.

CONFIG_SECURE_FLASH_ENC_ENABLED=y
CONFIG_SECURE_FLASH_ENCRYPTION_AES128=y
CONFIG_SECURE_FLASH_ENCRYPTION_MODE_DEVELOPMENT=y
CONFIG_SECURE_FLASH_HAS_WRITE_PROTECTION_CACHE=y
CONFIG_SECURE_FLASH_UART_BOOTLOADER_ALLOW_ENC=y
CONFIG_SECURE_FLASH_SKIP_WRITE_PROTECTION_CACHE=y
CONFIG_SECURE_FLASH_ENCRYPT_ONLY_IMAGE_LEN_IN_APP_PART=y
CONFIG_SECURE_FLASH_CHECK_ENC_EN_IN_APP=y
CONFIG_SECURE_INSECURE_ALLOW_DL_MODE=y

CONFIG_NVS_ENCRYPTION=y
CONFIG_NVS_SEC_KEY_PROTECT_USING_FLASH_ENC=y

- To enable it, I create a flash encryption key and burn it.
espsecure.py generate_flash_encryption_key my_flash_encryption_key.bin
espefuse.py --chip esp32s3 --port /dev/tty.usbserial-1101 burn_key BLOCK_KEY0 my_flash_encryption_key.bin XTS_AES_128_KEY --no-read-protect

- The esptool command I run is as follows.
cd build
python -m esptool --chip esp32s3 -b 460800 --before default_reset --after no_reset --no-stub --port /dev/tty.usbserial-1101 write_flash --flash_mode dio --flash_size 16MB --flash_freq 80m --encrypt 0x0 bootloader/bootloader.bin 0x70000 purrit-iot-app.bin 0x20000 partition_table/partition-table.bin 0x61000 ota_data_initial.bin 0x21000 ./mass_mfg/bin/mass_mfg-4.bin

- Below log is flash writing log.
esptool.py v4.8.dev4
Serial port /dev/tty.usbserial-1101
Connecting....
Chip is ESP32-S3 in Secure Download Mode
Changing baud rate to 460800
Changed.
Enabling default SPI flash mode...
Configuring flash size...
Flash will be erased from 0x00000000 to 0x00007fff...
Flash will be erased from 0x00070000 to 0x0018bfff...
Flash will be erased from 0x00020000 to 0x00020fff...
Flash will be erased from 0x00061000 to 0x00062fff...
Flash will be erased from 0x00021000 to 0x00060fff...
Erasing flash...
WARNING: Security features enabled, so not changing any flash settings.
Took 0.38s to erase flash block
Wrote 32768 bytes at 0x00000000 in 1.0 seconds (266.8 kbit/s)...
Erasing flash...
WARNING: Security features enabled, so not changing any flash settings.
Took 3.28s to erase flash block
Wrote 1162240 bytes at 0x00070000 in 35.0 seconds (265.4 kbit/s)...
Erasing flash...
WARNING: Security features enabled, so not changing any flash settings.
Took 0.05s to erase flash block
Wrote 3072 bytes at 0x00020000 in 0.1 seconds (271.9 kbit/s)...
Erasing flash...
WARNING: Security features enabled, so not changing any flash settings.
Took 0.10s to erase flash block
Wrote 8192 bytes at 0x00061000 in 0.3 seconds (260.2 kbit/s)...
Erasing flash...
WARNING: Security features enabled, so not changing any flash settings.
Took 1.12s to erase flash block
Wrote 262144 bytes at 0x00021000 in 7.8 seconds (267.9 kbit/s)...

Leaving...
Staying in bootloader.

- Below log is booting log.
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2980,len:0x2b58
load:0x403c8700,len:0x4
load:0x403c8704,len:0xcb8
load:0x403cb700,len:0x4498
entry 0x403c8914
I (37) boot: ESP-IDF v5.3-dirty 2nd stage bootloader
I (37) boot: compile time Aug 15 2024 17:59:46
I (37) boot: Multicore bootloader
I (40) boot: chip revision: v0.2
I (44) boot.esp32s3: Boot SPI Speed : 80MHz
I (49) boot.esp32s3: SPI Mode : DIO
I (53) boot.esp32s3: SPI Flash Size : 16MB
I (58) boot: Enabling RNG early entropy source...
I (64) boot: Partition Table:
I (67) boot: ## Label Usage Type ST Offset Length
I (75) boot: 0 nvs WiFi data 01 02 00021000 00040000
I (82) boot: 1 otadata OTA data 01 00 00061000 00002000
I (90) boot: 2 phy_init RF data 01 01 00063000 00001000
I (97) boot: 3 factory factory app 00 00 00070000 00400000
I (104) boot: 4 app0 OTA app 00 10 00470000 00400000
I (112) boot: 5 app1 OTA app 00 11 00870000 00400000
I (120) boot: 6 storage Unknown data 01 82 00c70000 00300000
I (127) boot: 7 nvs_key NVS keys 01 04 00f70000 00001000
I (135) boot: End of partition table
I (139) boot: Defaulting to factory image
I (144) esp_image: segment 0: paddr=00070020 vaddr=3c0d0020 size=34f2ch (216876) map
I (195) esp_image: segment 1: paddr=000a4f54 vaddr=3fc9be00 size=04d80h ( 19840) load
I (200) esp_image: segment 2: paddr=000a9cdc vaddr=40374000 size=0633ch ( 25404) load
I (207) esp_image: segment 3: paddr=000b0020 vaddr=42000020 size=c9f6ch (827244) map
I (374) esp_image: segment 4: paddr=00179f94 vaddr=4037a33c size=11a08h ( 72200) load
I (402) boot: Loaded app from partition at offset 0x70000
I (402) boot: Checking flash encryption...
I (402) flash_encrypt: flash encryption is enabled (1 plaintext flashes left)
I (409) boot: Disabling RNG early entropy source...
I (426) cpu_start: Multicore app
I (436) cpu_start: Pro cpu start user code
I (436) cpu_start: cpu freq: 160000000 Hz
I (436) app_init: Application information:
I (439) app_init: Project name: purrit-iot-app
I (444) app_init: App version: scubic_v1.0.0
I (449) app_init: Compile time: Aug 15 2024 17:59:43
I (455) app_init: ELF file SHA256: ffcc8e8bf...
I (461) app_init: ESP-IDF: v5.3-dirty
I (466) efuse_init: Min chip rev: v0.0
I (471) efuse_init: Max chip rev: v0.99
I (476) efuse_init: Chip rev: v0.2
I (480) heap_init: Initializing. RAM available for dynamic allocation:
I (488) heap_init: At 3FCA8A30 len 00040CE0 (259 KiB): RAM
I (494) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (500) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (506) heap_init: At 600FE100 len 00001EE8 (7 KiB): RTCRAM
I (513) spi_flash: detected chip: generic
I (517) spi_flash: flash io: dio
W (521) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)
W (562) i2c: This driver is an old driver, please migrate your application code to adapt `driver/i2c_master.h`
I (563) nvs_sec_provider: NVS Encryption - Registering Flash encryption-based scheme...
I (571) sleep: Configure to isolate all GPIO pins in sleep state
I (578) sleep: Enable automatic switching of GPIO sleep configuration
I (585) main_task: Started on CPU0
I (595) main_task: Calling app_main()
I (665) nvs: NVS partition "nvs" is encrypted.
I (665) System: Free/Total heap size: 299564/599104 bytes
I (665) System: app_info->project_name=purrit-iot-app
I (675) System: app_info->version=scubic_v1.0.0
I (685) System: app_info->secure_version=0
I (685) System: app_info->date=Aug 15 2024
I (695) System: product_number is not present
I (695) System: serial_number is not present
I (725) pp: pp rom version: e7ae62f
I (725) net80211: net80211 rom version: e7ae62f
I (735) main_task: Returned from app_main()
I (745) wifi:wifi driver task: 3fcb6158, prio:23, stack:6656, core=0
I (745) wifi:wifi firmware version: 0caa81945
I (755) wifi:wifi certification version: v7.0
I (755) wifi:config NVS flash: enabled
I (755) wifi:config nano formating: disabled
I (765) wifi:Init data frame dynamic rx buffer num: 32
I (765) wifi:Init static rx mgmt buffer num: 5
I (775) wifi:Init management short buffer num: 32
I (775) wifi:Init dynamic tx buffer num: 32
I (775) wifi:Init static tx FG buffer num: 2
I (785) wifi:Init static rx buffer size: 1600
I (785) wifi:Init static rx buffer num: 10
I (795) wifi:Init dynamic rx buffer num: 32
I (795) wifi_init: rx ba win: 6
I (795) wifi_init: accept mbox: 6
I (805) wifi_init: tcpip mbox: 32
I (805) wifi_init: udp mbox: 6
I (815) wifi_init: tcp mbox: 6
I (815) wifi_init: tcp tx win: 5760
I (815) wifi_init: tcp rx win: 5760
I (825) wifi_init: tcp mss: 1440
I (825) wifi_init: WiFi IRAM OP enabled
I (835) wifi_init: WiFi RX IRAM OP enabled
I (835) phy_init: phy_version 680,a6008b2,Jun 4 2024,16:41:10
W (845) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
W (895) phy_init: saving new calibration data because of checksum failure, mode(2)
I (915) wifi:mode : sta (80:65:99:c9:c9:e8)
I (915) wifi:enable tsf
I (915) System: Enter event handler
I (915) System: event_base:WIFI_EVENT, event_id:41