Bootloader appeared to erase 128k flash while booting

[mfitzpatrick]

Hi all,

I have a battery-operated PCB that has an ESP32-WROOM-32E-N16 module on it. During a brownout condition, it recently showed the following logs:

Code: Select all

ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x17 (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:2
load:0x3fff0030,len:4
load:0x3fff0034,len:7492
load:0x40078000,len:14088
load:0x40080400,len:4740
entry 0x4008070c
I (29) boot: ESP-IDF v4.2 2nd stage bootloader
I (29) boot: compile time 21:50:38
I (29) boot: chip revision: 3
I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 16MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 dev_keys         unknown          40 00 0000b000 00005000
I (77) boot:  1 hwtest           test app         00 20 00010000 00200000
I (84) boot:  2 otadata          OTA data         01 00 00210000 00002000
I (91) boot:  3 nvs              WiFi data        01 02 00212000 0000e000
I (99) boot:  4 coredump         Unknown data     01 03 00220000 00010000
I (106) boot:  5 factory          factory app      00 00 00230000 00300000
I (114) boot:  6 ota_0            OTA app          00 10 00530000 00300000
I (122) boot:  7 ota_1            OTA app          00 11 00830000 00300000
I (129) boot:  8 log              unknown          41 00 00b30000 00300000
I (137) boot:  9 storage          Unknown data     01 81 00e30000 00100000
I (144) boot: End of partition table
I (149) boot_comm: chip revision: 3, min. application chip revision: 0
I (156) esp_image: segment 0: paddr=0x00530020 vaddr=0x3f400020 size=0x1502fc (1377020) map
I (689) esp_image: segment 1: paddr=0x00680324 vaddr=0x3ffb0000 size=0x0500c ( 20492) load
I (698) esp_image: segment 2: paddr=0x00685338 vaddr=0x40080000 size=0x00404 (  1028) load
I (699) esp_image: segment 3: paddr=0x00685744 vaddr=0x40080404 size=0x0a8d4 ( 43220) load
I (724) esp_image: segment 4: paddr=0x00690020 vaddr=0x400d0020 size=0xbb8c0 (768192) map
I (1017) esp_image: segment 5: paddr=0x0074b8e8 vaddr=0x4008acd8 size=0x0d3b0 ( 54192) load
I (1041) esp_image: segment 6: paddr=0x00758ca0 vaddr=0x400c0000 size=0x00064 (   100) load
I (1041) esp_image: segment 7: paddr=0x00758d0c vaddr=0x50000000 size=0x00014 (    20) load
I (1048) esp_image: segment 8: paddr=0x00758d28 vaddr=0x00000000 size=0x07258 ( 29272) 
I (1081) boot: Loaded app from partition at offset 0x530000
I (1081) boot: Disabling RNG early entropy source...
I (1082) cpu_start: Pro cpu up.
I (1085) cpu_start: Application information:
I (1090) cpu_start: Project name:     test
I (1095) cpu_start: App version:      v1.0.8
I (1100) cpu_start: Compile time:     Mar 26 2024 07:20:46
I (1107) cpu_start: ELF file SHA256:  63a2c99ecfc845e2...
I (1113) cpu_start: ESP-IDF:          v4.2
I (1118) cpu_start: Starting app cpu, entry point is 0x40081b40
I (0) cpu_start: App cpu up.
I (1128) heap_init: Initializing. RAM available for dynamic allocation:
I (1135) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1141) heap_init: At 3FFBB578 len 00024A88 (146 KiB): DRAM
I (1147) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1154) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1160) heap_init: At 40098088 len 00007F78 (31 KiB): IRAM
I (1167) cpu_start: Pro cpu start user code
I (1185) spi_flash: detected chip: generic
I (1186) spi_flash: flash io: dio
I (1186) esp_core_dump_flash: Init core dump to flash
I (1190) esp_core_dump_flash: Found partition 'coredump' @ 220000 65536 bytes
I (1197) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.

(clip custom app logs. This tried to play audio via I2S immediately before the brownout in the next segment)

Code: Select all

Brownout detector was triggered

ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x17 (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:2
load:0x3fff0030,len:4
load:0x3fff0034,len:7492
load:0x40078000,len:14088
load:0x40080400,len:4740
entry 0x4008070c
I (29) boot: ESP-IDF v4.2 2nd stage bootloader
I (29) boot: compile time 21:50:38
I (29) boot: chip revision: 3
I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0
ets Jul 29 2019 12:21:46

rst:0x10 (RTCWDT_RTC_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
ets Jul 29 2019 12:21:46

rst:0x10 (RTCWDT_RTC_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
invalid header: 0xffffffff
ets Jul 29 2019 12:21:46

The "invalid header" text repeats indefinitely. The log data was captured with "tio", not esp_monitor, so I'm confident that no commands for erasing flash would have been transmitted from the host.

I deflashed the unit, and found that the first 128k of flash is now erased (all bytes 0xff).

I'm sure I didn't touch the unit at the time of the brownout. But what has me very worried is that the bootloader code can erase itself and a large chunk of config and app data.

I have tried to reproduce this behaviour, and I can't. I've caused numerous brownouts and they all (aside from this one) have resulted in a correctly running bootloader. I've also tried searching for any posts on this here and on stack overflow but I haven't found anything mentioning flash erasing during the 2nd stage bootloader so far.

Does anyone have any insights on what could cause this, or what avenues of investigation I should follow next?