IDF4.3: app does not boot if app and bootloader flash SPI speed do not match [solved]

[Zevver]

We have a few hundred devices in the field that, for historical reasons, run different versions of boot loaders - some of these are configured for 40M, others for 80M SPI flash speed. The SPI flash speed of our current application is set to 40m.

We recently upgraded ESP IDF from 4.2 to 4.3 to make use of the new CAN/TWAI errata workarounds, but now we find that the application will not boot after an OTA update in devices which have a 80M bootloader. This worked fine before on IDF 4.2 though. I am able to reproduce this both ways around:

- bootloader compiled with 40M will not boot an app compiled with 80M
- bootloader compiled with 80M will not boot an app compiled with 40M

Interestingly, the problem occurs only if the binary is "large enough": if the .bin file exceeds approx 200Kb it will show this problem, but if we reduce the code size far enough, the app will eventually boot properly.

What can be the cause of this, is it a hard requirement for the SPI flash speed to match between bootloader and application? Is there a workaround for this apart from updating all the boot loaders in the field? What changed in v4.3 to make this problem appear only now?

Thank you,

Boot log with boot loader log level set to 'debug':

Code: Select all

ets Jun  8 2016 00:22:57

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:1
load:0x3fff0030,len:9068
ho 0 tail 12 room 4
load:0x40078000,len:15156
load:0x40080400,len:4076
0x40080400: _init at ??:?

entry 0x400806b4
I (29) boot: ESP-IDF v4.3 2nd stage bootloader
I (29) boot: compile time 11:27:35
D (29) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (35) boot: chip revision: 1
I (38) boot_comm: chip revision: 1, min. bootloader chip revision: 0
D (45) boot.esp32: magic e9
D (48) boot.esp32: segments 03
D (51) boot.esp32: spi_mode 02
D (54) boot.esp32: spi_speed 0f
D (57) boot.esp32: spi_size 03
I (61) boot.esp32: SPI Speed      : 80MHz
I (65) boot.esp32: SPI Mode       : DIO
I (70) boot.esp32: SPI Flash Size : 8MB
D (74) boot: Enabling RTCWDT(9000 ms)
I (78) boot: Enabling RNG early entropy source...
D (83) bootloader_flash: mmu set paddr=00000000 count=1 size=c00 src_addr=8000 src_addr_aligned=0
D (92) boot: mapped partition table 0x8000 at 0x3f408000
D (98) flash_parts: partition table verified, 6 entries
I (103) boot: Partition Table:
I (107) boot: ## Label            Usage          Type ST Offset   Length
D (114) boot: load partition table entry 0x3f408000
D (119) boot: type=1 subtype=2
I (122) boot:  0 nvs              WiFi data        01 02 00009000 00005000
D (130) boot: load partition table entry 0x3f408020
D (135) boot: type=1 subtype=0
I (138) boot:  1 otadata          OTA data         01 00 0000e000 00002000
D (145) boot: load partition table entry 0x3f408040
D (150) boot: type=0 subtype=10
I (154) boot:  2 app0             OTA app          00 10 00010000 00200000
D (161) boot: load partition table entry 0x3f408060
D (166) boot: type=0 subtype=11
I (169) boot:  3 app1             OTA app          00 11 00210000 00200000
D (177) boot: load partition table entry 0x3f408080
D (182) boot: type=1 subtype=81
I (185) boot:  4 ffat             Unknown data     01 81 00410000 003f0000
I (193) boot: End of partition table
D (197) boot: OTA data offset 0xe000
D (200) bootloader_flash: mmu set paddr=00000000 count=1 size=2000 src_addr=e000 src_addr_aligned=0
D (210) boot: otadata[0]: sequence values 0x00000001
D (215) boot: otadata[1]: sequence values 0xffffffff
D (220) boot_comm: Only otadata[0] is valid
D (224) boot: Active otadata[0]
D (227) boot: Mapping seq 0 -> OTA slot 0
D (231) boot: Trying partition index 0 offs 0x10000 size 0x200000
D (237) esp_image: reading image header @ 0x10000
D (242) bootloader_flash: mmu set block paddr=0x00010000 (was 0xffffffff)
D (249) esp_image: image header: 0xe9 0x07 0x02 0x03 400815e0
I (255) boot_comm: chip revision: 1, min. application chip revision: 0
I (262) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=12164h ( 74084) map
D (270) esp_image: free data page_count 0x00000032
D (275) bootloader_flash: mmu set paddr=00010000 count=2 size=12164 src_addr=10020 src_addr_aligned=10000
D (309) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
I (309) esp_image: segment 1: paddr=0002218c vaddr=3ffb0000 size=02fb4h ( 12212) load
D (313) esp_image: free data page_count 0x00000032
D (318) bootloader_flash: mmu set paddr=00020000 count=1 size=2fb4 src_addr=2218c src_addr_aligned=20000
D (331) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
I (334) esp_image: segment 2: paddr=00025148 vaddr=40080000 size=0aed0h ( 44752) load
D (343) esp_image: free data page_count 0x00000032
D (347) bootloader_flash: mmu set paddr=00020000 count=2 size=aed0 src_addr=25148 src_addr_aligned=20000
D (373) bootloader_flash: mmu set block paddr=0x00030000 (was 0xffffffff)
I (374) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=4cbd0h (314320) map
D (378) esp_image: free data page_count 0x00000032
D (382) bootloader_flash: mmu set paddr=00030000 count=5 size=4cbd0 src_addr=30020 src_addr_aligned=30000
D (492) bootloader_flash: mmu set block paddr=0x00070000 (was 0xffffffff)
I (492) esp_image: segment 4: paddr=0007cbf8 vaddr=4008aed0 size=0710ch ( 28940) load
D (496) esp_image: free data page_count 0x00000032
D (501) bootloader_flash: mmu set paddr=00070000 count=2 size=710c src_addr=7cbf8 src_addr_aligned=70000
D (521) bootloader_flash: mmu set block paddr=0x00080000 (was 0xffffffff)
I (521) esp_image: segment 5: paddr=00083d0c vaddr=400c0000 size=00088h (   136) load
D (526) esp_image: free data page_count 0x00000032
D (531) bootloader_flash: mmu set paddr=00080000 count=1 size=88 src_addr=83d0c src_addr_aligned=80000
D (540) bootloader_flash: mmu set block paddr=0x00080000 (was 0xffffffff)
I (547) esp_image: segment 6: paddr=00083d9c vaddr=50000000 size=00010h (    16) load
D (555) esp_image: free data page_count 0x00000032
D (560) bootloader_flash: mmu set paddr=00080000 count=1 size=10 src_addr=83d9c src_addr_aligned=80000
D (570) bootloader_flash: mmu set block paddr=0x00080000 (was 0xffffffff)
D (576) boot: Calculated hash: 971960a5f4c6b4c2a1041d578fb714136e912c656e0575f3d842de33d2b55882
D (585) bootloader_flash: mmu set paddr=00080000 count=1 size=20 src_addr=83db0 src_addr_aligned=80000
D (595) bootloader_flash: mmu set paddr=00080000 count=1 size=20 src_addr=83db0 src_addr_aligned=80000
I (614) boot: Loaded app from partition at offset 0x10000
I (614) boot: Disabling RNG early entropy source...
D (616) boot: Mapping segment 0 as DROM
D (619) boot: Mapping segment 3 as IROM
D (623) boot: calling set_cache_and_start_app
D (628) boot: configure drom and irom and start
D (632) boot: start: 0x400815e0
0x400815e0: call_start_cpu0 at /opt/toolchains/esp-idf/components/esp_system/port/cpu_start.c:252

Here the boot hangs for a few seconds, after which a reboot is triggered, and the same thing repeats

Code: Select all

ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_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:1
load:0x3fff0030,len:9068
ho 0 tail 12 room 4
load:0x40078000,len:15156
load:0x40080400,len:4076
0x40080400: _init at ??:?

entry 0x400806b4
I (29) boot: ESP-IDF v4.3 2nd stage bootloader
I (29) boot: compile time 11:27:35
D (29) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (35) boot: chip revision: 1

[Zevver]

I also created a github issue for this: https://github.com/espressif/esp-idf/issues/9156

I was able to pinpoint the problem to idf commit 2373f115fc6db20a0159ccab11e1db0feb4c0bfa by bisection.

[Zevver]

This was confirmed a bug and will be solved in the next version: https://github.com/espressif/esp-idf/issues/9156