OTA operations with flash encryption produce exception (IDFGH-4351)

moggiozzi commented 3 years ago

Environment

Development Kit: ESP32-DevKit V1
Kit version v1
Module or chip used: ESP32-WROOM-32
IDF version (run git describe --tags to find it): v4.2-dev-1303-gcd4fa46f5
Build System: idf.py
Compiler version (run xtensa-esp32-elf-gcc --version to find it): (crosstool-NG esp-2020r1) 8.2.0
Operating System: Windows
(Windows only) environment type: ESP Command Prompt
Using an IDE?: No
Power Supply: USB

Problem Description

I use 2 OTA schema (with rollback support) and flash encryption enabled (key generated on PC). After write encrypted fw I try change boot partition with esp_ota_set_boot_partition(). After load firmware mark partition with esp_ota_mark_app_valid_cancel_rollback(). In most cases I get exception: esp_ota_set_boot_partition() rise Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. esp_ota_mark_app_valid_cancel_rollback() rise Guru Meditation Error: Core 0 panic'ed (IllegalInstruction). Exception was unhandled.

I think problem in rewrite_ota_seq() -> esp_partition_write() -> spi_flash_write_encrypted() Not all function used in spi_flash_write_encrypted() marked with IRAM_ATTR (for example, esp_rom_spiflash_unlock())

Expected Behavior

Exceptions not occure.

Actual Behavior

Exceptions occure in most cases (1 lauch OK vs - 4-6 launch with exception)

Steps to reproduce

generate key components\esptool_py\esptool>python espsecure.py generate_flash_encryption_key my_key.bin
enable flash encryption python %IDF_PATH%\components\esptool_py\esptool\espefuse.py --port com3 burn_key flash_encryption my_key.bin python %IDF_PATH%\components\esptool_py\esptool\espefuse.py --port com3 burn_efuse FLASH_CRYPT_CNT python %IDF_PATH%\components\esptool_py\esptool\espefuse.py --port com3 burn_efuse FLASH_CRYPT_CONFIG 0x0F python %IDF_PATH%\components\esptool_py\esptool\espefuse.py --port com3 burn_efuse DISABLE_DL_DECRYPT python %IDF_PATH%\components\esptool_py\esptool\espefuse.py --port com3 burn_efuse DISABLE_DL_CACHE
encrypt files python.exe %IDF_PATH%\components\esptool_py\esptool\espsecure.py encrypt_flash_data --keyfile my_key.bin --address 0x1000 -o .\build\bootloader\bootloader.en .\build\bootloader\bootloader.bin python.exe %IDF_PATH%\components\esptool_py\esptool\espsecure.py encrypt_flash_data --keyfile my_key.bin --address 0x8000 -o .\build\partition_table\partition-table.en .\build\partition_table\partition-table.bin python.exe %IDF_PATH%\components\esptool_py\esptool\espsecure.py encrypt_flash_data --keyfile my_key.bin --address 0x10000 -o fw0.en fw.bin python.exe %IDF_PATH%\components\esptool_py\esptool\espsecure.py encrypt_flash_data --keyfile my_key.bin --address 0x100000 -o fw1.en fw.bin
write files (firmware to both slots) python %IDF_PATH%\components\esptool_py\esptool\esptool.py --chip esp32 --port %1 --baud 921600 --before default_reset --after hard_reset write_flash -z --flash_mode dio --flash_freq 40m --flash_size detect 0x1000 bootloader.en 0x8000 partition-table.en 0x10000 fw0.en 0x100000 fw01en
change OTA slot, mark slots valid esp_ota_set_boot_partition() esp_ota_mark_app_valid_cancel_rollback()

Code

// 1) get next OTA slot
fw_update_info.update_partition = esp_ota_get_next_update_partition(NULL);

// 2) receive encrypted firmware over UART or BT and write it to flash AS IS.
res = spi_flash_write(fw_update_info.update_partition->address, buffer, length);

// 3) change boot OTA slot
err = esp_ota_set_boot_partition(fw_update_info.update_partition);

Debug Logs

upd_err_log.txt

mahavirj commented 3 years ago

@moggiozzi

It would be useful to decode backtrace from exception here.

Either you may run your example through idf.py monitor or decode backtrace using command similar to following:

xtensa-esp32-elf-addr2line -e </path/to/elf> -a 0x4015b9e0:0x3fff7900 0x400d8826:0x3fff7930 0x400d926c:0x3fff7950 0x40092cad:0x3fff7970

moggiozzi commented 3 years ago

Several decoded backtrace:

d:\work\src\Project\build>xtensa-esp32-elf-addr2line -e fw.elf -a 0x4015b9e0:0x3fff
7900 0x400d8826:0x3fff7930 0x400d926c:0x3fff7950 0x40092cad:0x3fff7970
0x4015b9e0
C:/esp4/esp-idf/components/driver/gpio.c:214
0x400d8826
d:\work\src\project\build/../main/hw/wd.c:21
0x400d926c
d:\work\src\project\build/../main/thermo.c:572
0x40092cad
C:/esp4/esp-idf/components/freertos/xtensa/port.c:143

d:\work\src\Project\build>xtensa-esp32-elf-addr2line -e fw.elf -a 0x401306a0:0x3ffd
af20 0x40135e84:0x3ffdaf50 0x400d5db3:0x3ffdaf70 0x400d5f43:0x3ffdaf90 0x400d5f8e:0x3ffdafb0 0x40092
cad:0x3ffdafd0
0x401306a0
C:/esp4/esp-idf/components/driver/ledc.c:404 (discriminator 6)
0x40135e84
??:?
0x400d5db3
d:\work\src\project\build/../main/led.c:165
0x400d5f43
d:\work\src\project\build/../main/led.c:260
0x400d5f8e
d:\work\src\project\build/../main/led.c:285 (discriminator 1)
0x40092cad
C:/esp4/esp-idf/components/freertos/xtensa/port.c:143

xtensa-esp32-elf-addr2line -e fw.elf -a 0x400d6201:0x3fff
9890 0x400d8dd1:0x3fff98c0 0x400d9299:0x3fff9950 0x40092cad:0x3fff9970
0x400d6201
d:\work\src\project\build/../main/settings.c:381
0x400d8dd1
d:\work\src\project\build/../main/thermo.c:411
0x400d9299
d:\work\src\project\build/../main/thermo.c:581
0x40092cad
C:/esp4/esp-idf/components/freertos/xtensa/port.c:143

port.c line 143


static void vPortTaskWrapper(TaskFunction_t pxCode, void *pvParameters)
{
    pxCode(pvParameters);

moggiozzi commented 3 years ago

It is possible to disable otadata encryption?

mahavirj commented 3 years ago

@moggiozzi At-least per backtrace this appears to be issue in somewhere application logic. Can you please confirm you see similar behavior with IDF provided OTA examples?

moggiozzi commented 3 years ago

I write test project for bug reproduce https://github.com/moggiozzi/esp_enc_ota_test (based on esp-idf\examples\bluetooth\bluedroid\classic_bt\bt_spp_acceptor). Code call esp_ota_set_boot_partition() repeatedly in while loop.

shubhamkulkarni97 commented 3 years ago

@moggiozzi,

I tried flashing application from esp_enc_ota_test repo on a flash encryption enabled device and didn't notice any crash. Please check attached logs:

I (418) boot: Loaded app from partition at offset 0x10000
I (471) boot: Set actual ota_seq=1 in otadata[0]
I (471) boot: Checking flash encryption...
I (471) flash_encrypt: flash encryption is enabled (3 plaintext flashes left)
I (477) boot: Disabling RNG early entropy source...
I (483) cpu_start: Pro cpu up.
I (487) cpu_start: Application information:
I (492) cpu_start: Project name:     bt_spp_acceptor_demo
I (498) cpu_start: App version:      8
I (502) cpu_start: Compile time:     Dec  3 2020 15:39:16
I (508) cpu_start: ELF file SHA256:  d0a30d079122fc7c...
I (514) cpu_start: ESP-IDF:          v4.2-dev-1303-gcd4fa46f53
I (521) cpu_start: Starting app cpu, entry point is 0x400815ac
0x400815ac: call_start_cpu1 at /Users/shubhamkulkarni/esp/esp-idf/components/esp32/cpu_start.c:286

W (527) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)
I (0) cpu_start: App cpu up.
I (539) heap_init: Initializing. RAM available for dynamic allocation:
I (545) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (551) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (557) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (564) heap_init: At 3FFCAEE8 len 00015118 (84 KiB): DRAM
I (570) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (576) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (583) heap_init: At 40094630 len 0000B9D0 (46 KiB): IRAM
I (589) cpu_start: Pro cpu start user code
I (607) spi_flash: detected chip: generic
I (608) spi_flash: flash io: dio
W (608) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (618) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (692) BTDM_INIT: BT controller compile version [1ee1530]
I (692) system_api: Base MAC address is not set
I (692) system_api: read default base MAC address from EFUSE
W (702) phy_init: failed to load RF calibration data (0xffffffff), falling back to full calibration
I (852) phy: phy_version: 4181, c9a03e2, Mar 10 2020, 12:45:06, 0, 2
I (1472) SPP_ACCEPTOR_DEMO: ESP_SPP_INIT_EVT
I (1492) SPP_ACCEPTOR_DEMO: event: 10
I (1492) SPP_ACCEPTOR_DEMO: ESP_SPP_START_EVT
W (1492) fw_update_printBootInfo: Boot 0x00010000, Running 0x00010000
I (1502) fw_update_printBootInfo: Running fw version: 8
I (1502) task_ota: Try esp_ota_mark_app_valid_cancel_rollback()...
I (1512) task_ota: esp_ota_mark_app_valid_cancel_rollback ret 0
I (2522) task_ota: next slot addr 0x100000, size 0xf0000, enc 1
I (3522) task_ota: Try esp_ota_set_boot_partition()...
E (3522) esp_image: image at 0x100000 has invalid magic byte
W (3522) esp_image: image at 0x100000 has invalid SPI mode 42
W (3522) esp_image: image at 0x100000 has invalid SPI size 7
E (3532) task_ota: esp_ota_set_boot_partition failed (ESP_ERR_OTA_VALIDATE_FAILED)!
I (4542) task_ota: Try esp_ota_set_boot_partition()...
E (4542) esp_image: image at 0x100000 has invalid magic byte
W (4542) esp_image: image at 0x100000 has invalid SPI mode 42
W (4542) esp_image: image at 0x100000 has invalid SPI size 7
E (4552) task_ota: esp_ota_set_boot_partition failed (ESP_ERR_OTA_VALIDATE_FAILED)!
I (5562) task_ota: Try esp_ota_set_boot_partition()...
E (5562) esp_image: image at 0x100000 has invalid magic byte
W (5562) esp_image: image at 0x100000 has invalid SPI mode 42
W (5562) esp_image: image at 0x100000 has invalid SPI size 7
E (5572) task_ota: esp_ota_set_boot_partition failed (ESP_ERR_OTA_VALIDATE_FAILED)!

moggiozzi commented 3 years ago

@shubhamkulkarni97 1) please write second slot app (bt_spp_acceptor_demo1_v8.en to 0x100000). In your case otadata not updated because app header not valid. 2) please try connect to device with BT or enable payload thread. https://github.com/moggiozzi/esp_enc_ota_test/blob/afd9e3b9085fab12e75f9cfed43d4e453c3814a9/bt_spp_acceptor/main/test.c#L53 Bug not reproduce if all code in cache and cache miss not occure (leads to flash reading). Code some call work, some call crash. See my run output logs https://github.com/moggiozzi/esp_enc_ota_test/blob/main/bt_spp_acceptor/logs/04_run_output.txt

moggiozzi commented 3 years ago

My workaround (decrypted otadata) decrypted_otadata.zip

Harshal5 commented 5 months ago

Could you please check this issue with the latest ESP-IDF versions? Closing this issue now, feel free to re-open the issue if it still exists.

espressif / esp-idf