Secure boot verification fails after restarting system (`Sig block 0 invalid: Image digest does not match`) (IDFGH-11669)

DCSBL commented 11 months ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.1.2

Espressif SoC revision.

ESP32-D0WD-V3

Operating System used.

macOS

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-WROOM-32E on a breakout board, no extra hardware connected.

Power Supply used.

USB

What is the expected behavior?

At some point we call esp_restart(). The ESP should restart without problems and the reset reason should be SW_CPU_RESET

What is the actual behavior?

We call esp_restart().
The ESP restarts but verification fails.
Then the system is reset by WDT.
Verification was succeeded
Reset reason is set to RTCWDT_RTC_RESET

Steps to reproduce.

Enable secure boot via menuconfig
Sign bootloader + app (standard 2-app OTA partition table)
flash using given commands
Let program call esp_restart().

Debug Logs.

ets J�ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_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:2, clock div:2
secure boot v2 enabled
secure boot verification succeeded
load:0x3fff00b8 len:0xa38
load:0x40078000 len:0x5a24
load:0x40080400 len:0x4
0x40080400: _init at ??:?

load:0x40080404 len:0xc5c
entry 0x400805fc
I (407) cpu_start: Multicore app
I (407) cpu_start: Pro cpu up.
I (407) cpu_start: Starting app cpu, entry point is 0x40081720
0x40081720: call_start_cpu1 at /COMPONENT_ESP_SYSTEM_DIR/port/cpu_start.c:157

I (0) cpu_start: App cpu up.
I (425) cpu_start: Pro cpu start user code
I (425) cpu_start: cpu freq: 240000000 Hz
I (425) cpu_start: Application information:
I (430) cpu_start: Project name:     hello-world
I (435) cpu_start: App version:      1.00
I (441) cpu_start: Secure version:   0
I (445) cpu_start: Compile time:      
I (450) cpu_start: ELF file SHA256:  17ad4f640dff50ff...
I (456) cpu_start: ESP-IDF:          v5.1.2
I (461) cpu_start: Min chip rev:     v3.0
I (465) cpu_start: Max chip rev:     v3.99 
I (470) cpu_start: Chip rev:         v3.0
I (475) heap_init: Initializing. RAM available for dynamic allocation:
I (482) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (488) heap_init: At 3FFBAFD8 len 00025028 (148 KiB): DRAM
I (494) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (501) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (507) heap_init: At 40098C88 len 00007378 (28 KiB): IRAM
I (515) spi_flash: detected chip: generic
I (518) spi_flash: flash io: dio
W (522) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)
I (550) esp_core_dump_flash: Init core dump to flash
E (556) esp_core_dump_flash: No core dump partition found!
E (562) esp_core_dump_flash: No core dump partition found!
I (569) app_start: Starting scheduler on CPU0
I (573) app_start: Starting scheduler on CPU1
I (573) main_task: Started on CPU0
I (583) main_task: Calling app_main()
...
I (16487) button: restarting NOW
ets Jul 29 2019 12:21:46

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:2, clock div:2
secure boot v2 enabled
Sig block 0 invalid: Image digest does not match
secure boot verification failed
ets Jul 29 2019 12:21:46

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:2, clock div:2
secure boot v2 enabled
secure boot verification succeeded
load:0x3fff00b8 len:0xa38
load:0x40078000 len:0x5a24
load:0x40080400 len:0x4
0x40080400: _init at ??:?

load:0x40080404 len:0xc5c
entry 0x400805fc
I (407) cpu_start: Multicore app
I (407) cpu_start: Pro cpu up.
I (407) cpu_start: Starting app cpu, entry point is 0x40081720
0x40081720: call_start_cpu1 at /COMPONENT_ESP_SYSTEM_DIR/port/cpu_start.c:157

I (0) cpu_start: App cpu up.
I (425) cpu_start: Pro cpu start user code
I (425) cpu_start: cpu freq: 240000000 Hz
I (425) cpu_start: Application information:
I (430) cpu_start: Project name:     hello-world
I (435) cpu_start: App version:      1.00
I (441) cpu_start: Secure version:   0
I (446) cpu_start: Compile time:      
I (450) cpu_start: ELF file SHA256:  17ad4f640dff50ff...
I (456) cpu_start: ESP-IDF:          v5.1.2
I (461) cpu_start: Min chip rev:     v3.0
I (466) cpu_start: Max chip rev:     v3.99 
I (471) cpu_start: Chip rev:         v3.0
I (476) heap_init: Initializing. RAM available for dynamic allocation:
I (483) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (489) heap_init: At 3FFBAFD8 len 00025028 (148 KiB): DRAM
I (495) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (501) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (508) heap_init: At 40098C88 len 00007378 (28 KiB): IRAM
I (515) spi_flash: detected chip: generic
I (518) spi_flash: flash io: dio
W (523) flash_encrypt: Flash encryption mode is DEVELOPMENT (not secure)

More Information.

Tried on multiple chips.
Chip has 8MB flash, using only 4MB (with 4MB partition table). This is because production devices are using 4MB.
We have seen this working normally. Because of secure boot we can't update the bootloader to test multiple situations.

The only differences are;

Actual firmware for a different product, but we can isolate the trigger to esp_restart()
We use the ULP for this product, with CONFIG_ULP_COPROC_RESERVE_MEM=6144 set.
Maybe we have used a different ESP-IDF version for the working products. This can be 5.1 or 5.1.1.

DCSBL commented 11 months ago

Just disabled all ULP code, same result

DCSBL commented 11 months ago

Was able to isolate this issue to using the I2S peripheral.

DCSBL commented 11 months ago

Issue is triggered by using ADC-continuous. Rewrote my code to use ADC-singleshot so issue is solved for me. Keeping this open until you (espressif) decides if this issue has to be fixed for real or we can keep it at is.

Kevincoooool commented 7 months ago

Issue is triggered by using ADC-continuous. Rewrote my code to use ADC-singleshot so issue is solved for me. Keeping this open until you (espressif) decides if this issue has to be fixed for real or we can keep it at is.

Hi,I'm facing the same issue that when i call esp_restart(),the chip can not start ,but i can click reset button, it will restart fine,you mean adc-continuous is the key?How about deinit adc before calling esp_restart().

DCSBL commented 7 months ago

Yeah our problem was fixed when we stopped the ADC before reboot.

Kevincoooool commented 7 months ago

Yeah our problem was fixed when we stopped the ADC before reboot.

How do you stop adc continuous,I'm facing issue when calling adc_digi_stop(),

Backtrace:0x40023902:0x3ffdf1900x4002a87d:0x3ffdf1b0 0x40031469:0x3ffdf1d0 0x4002b07f:0x3ffdf2f0 0x40024ccd:0x3ffdf330 0x40024d7d:0x3ffdf360 0x400888ba:0x3ffdf380 0x40086e06:0x3ffdf3a0 0x4002d305:0x3ffdf3c0
0x40023902: panic_abort at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/esp_system/panic.c:402

0x4002a87d: esp_system_abort at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/esp_system/esp_system.c:128

0x40031469: __assert_func at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/newlib/assert.c:85

0x4002b07f: xQueueGenericSend at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/freertos/queue.c:830 (discriminator 8)

0x40024ccd: lock_release_generic at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/newlib/locks.c:201

0x40024d7d: _lock_release at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/newlib/locks.c:207

0x400888ba: adc_digi_stop at F:/ESP-IDF/Espressif/frameworks/esp-idf-v4.4.2/components/driver/adc.c:452

espressif / esp-idf