ESP32-WROOM Occasional reset, and then locked in bootloader WDT

[cdDave]

We have a device based on the ESP32-WROOM which works most of the time. The ESP32 is reading an I2C accelerometer constantly, once every 20 ms. Some of our products can last forever running code - but every so often we see a device get a reset in the ESP I2C driver code. This in of itself is interesting, but what is really bad is we see the device get into a continuous WDT reset in the bootloader when this happens. It takes a manual reset (or pulling of battery) to get it out of this state.

So, two questions. One - has anybody seen an I2C exception like below. And, more interesting - how and why could the device get into the continuous reset state shown below when this happens? NOTE!! We have also tried to "force" the continuous reset situation to debug by setting cmd to 1 in between the two lines below. When we do that, the device does indeed reset (panic) as expected - but boots normally in that case.

The I2C fault that causes the crash in the first place is:
i2c_cmd_handle_t cmd = i2c_cmd_link_create();
I2C_ERR_CHECK(i2c_master_start(cmd));

Somehow cmd (the I2C handle) is 1 (obviously an invalid address) when the problem happens. i2c_cmd_link_create(), which is a core ESP library function, is just calling a calloc - so how could it ever return a 1?

Here's the log dump:

[10/10/19 12:09:28:631] Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception
was unhandled.
[10/10/19 12:09:28:940] Core 0 register dump:
[10/10/19 12:09:28:942] PC : 0x400eccff PS : 0x00060630 A0 : 0x800ed990 A
1 : 0x3ffd39d0
[10/10/19 12:09:28:957] A2 : 0x00000001 A3 : 0x3ffd3a0c A4 : 0x00060220 A
5 : 0x00000000
[10/10/19 12:09:28:957] A6 : 0x00060420 A7 : 0x00000000 A8 : 0x3ffd3bc0 A
9 : 0x000000ff
[10/10/19 12:09:28:957] A10 : 0x61523ff5 A11 : 0x00000001 A12 : 0x7e000000 A
13 : 0x00000001
[10/10/19 12:09:28:957] A14 : 0x00060223 A15 : 0x00000001 SAR : 0x00000007 E
XCCAUSE: 0x0000001c
[10/10/19 12:09:28:957] EXCVADDR: 0x00000001 LBEG : 0x400e9e14 LEND : 0x400e9e33 L
COUNT : 0x00000000
[10/10/19 12:09:28:957]
[10/10/19 12:09:28:957] Backtrace: 0x400eccff:0x3ffd39d0 0x400ed98d:0x3ffd39f0 0x400d4efb:0
x3ffd3a40 0x400d501f:0x3ffd3a70 0x400d71ef:0x3ffd3ae0 0x400d2092:0x3ffd3b30
[10/10/19 12:09:28:957]
[10/10/19 12:09:28:957] Rebooting...
[10/10/19 12:09:28:957] ets Jun 8 2016 00:22:57
[10/10/19 12:09:28:957]
[10/10/19 12:09:28:957] rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:28:957] configsip: 0, SPIWP:0xee
[10/10/19 12:09:28:957] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:28:957] mode:DIO, clock div:2
[10/10/19 12:09:28:957] load:0x3fff0018,len:4
[10/10/19 12:09:28:957] load:0x3fff001c,len:5728
[10/10/19 12:09:28:957] ho 0 tail 12 room 4
[10/10/19 12:09:28:957] load:0x40078000,len:7684
[10/10/19 12:09:28:957] load:0x40080000,len:7392
[10/10/19 12:09:28:957] entry 0x4008039c
[10/10/19 12:09:29:623] ets Jun 8 2016 00:22:57
[10/10/19 12:09:29:625]
[10/10/19 12:09:29:626] rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:29:643] configsip: 0, SPIWP:0xee
[10/10/19 12:09:29:645] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:29:658] mode:DIO, clock div:2
[10/10/19 12:09:29:658] load:0x3fff0018,len:4
[10/10/19 12:09:29:659] load:0x3fff001c,len:5728
[10/10/19 12:09:29:660] ho 0 tail 12 room 4
[10/10/19 12:09:29:660] load:0x40078000,len:7684
[10/10/19 12:09:29:661] load:0x40080000,len:7392
[10/10/19 12:09:29:662] entry 0x4008039c
[10/10/19 12:09:29:981] ets Jun 8 2016 00:22:57
[10/10/19 12:09:29:983]
[10/10/19 12:09:29:984] rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:29:993] configsip: 0, SPIWP:0xee
[10/10/19 12:09:29:994] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:30:003] mode:DIO, clock div:2
[10/10/19 12:09:30:004] load:0x3fff0018,len:4
[10/10/19 12:09:30:004] load:0x3fff001c,len:5728
[10/10/19 12:09:30:011] ho 0 tail 12 room 4
[10/10/19 12:09:30:012] load:0x40078000,len:7684
[10/10/19 12:09:30:012] load:0x40080000,len:7392
[10/10/19 12:09:30:013] entry 0x4008039c
[10/10/19 12:09:30:343] ets Jun 8 2016 00:22:57
[10/10/19 12:09:30:345]
[10/10/19 12:09:30:346] rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:30:361] configsip: 0, SPIWP:0xee
[10/10/19 12:09:30:363] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:30:376] mode:DIO, clock div:2
[10/10/19 12:09:30:377] load:0x3fff0018,len:4
[10/10/19 12:09:30:377] load:0x3fff001c,len:5728
[10/10/19 12:09:30:378] ho 0 tail 12 room 4
[10/10/19 12:09:30:378] load:0x40078000,len:7684
[10/10/19 12:09:30:379] load:0x40080000,len:7392
[10/10/19 12:09:30:379] entry 0x4008039c
[10/10/19 12:09:30:699] ets Jun 8 2016 00:22:57
[10/10/19 12:09:30:700]
[10/10/19 12:09:30:700] rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:30:707] configsip: 0, SPIWP:0xee
[10/10/19 12:09:30:707] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:30:716] mode:DIO, clock div:2
[10/10/19 12:09:30:722] load:0x3fff0018,len:4
[10/10/19 12:09:30:723] load:0x3fff001c,len:5728
[10/10/19 12:09:30:731] ho 0 tail 12 room 4
[10/10/19 12:09:30:732] load:0x40078000,len:7684
[10/10/19 12:09:30:732] load:0x40080000,len:7392
[10/10/19 12:09:30:733] entry 0x4008039c
[10/10/19 12:09:31:059] ets Jun 8 2016 00:22:57
[10/10/19 12:09:31:062]
[10/10/19 12:09:31:064] rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:31:072] configsip: 0, SPIWP:0xee
[10/10/19 12:09:31:073] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:31:086] mode:DIO, clock div:2
[10/10/19 12:09:31:087] load:0x3fff0018,len:4
[10/10/19 12:09:31:087] load:0x3fff001c,len:5728
[10/10/19 12:09:31:094] ho 0 tail 12 room 4
[10/10/19 12:09:31:095] load:0x40078000,len:7684
[10/10/19 12:09:31:096] load:0x40080000,len:7392
[10/10/19 12:09:31:096] entry 0x4008039c
[10/10/19 12:09:31:418] ets Jun 8 2016 00:22:57
[10/10/19 12:09:31:420]
[10/10/19 12:09:31:421] rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/10/19 12:09:31:436] configsip: 0, SPIWP:0xee
[10/10/19 12:09:31:438] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:
0x00
[10/10/19 12:09:31:453] mode:DIO, clock div:2
[10/10/19 12:09:31:454] load:0x3fff0018,len:4
[10/10/19 12:09:31:455] load:0x3fff001c,len:5728
[10/10/19 12:09:31:456] ho 0 tail 12 room 4
[10/10/19 12:09:31:457] load:0x40078000,len:7684
[10/10/19 12:09:31:458] load:0x40080000,len:7392
[10/10/19 12:09:31:468] entry 0x4008039c
[10/10/19 12:09:31:777] ets Jun 8 2016 00:22:57

[ESP_houwenxiang]

Hi, cdDave
Which GPIO are you using? What is the GPIO level when it is restarted?

[ESP_houwenxiang]

In addition, we can see that the chip are jumping to the 2th bootloader. Can you add some debugging information? It is difficult for us to reproduce your issue.
find the function "call_start_cpu0", add some log like this:

Code: Select all

void __attribute__((noreturn)) call_start_cpu0(void)
{
    ESP_LOGE(TAG, "----%p----------", call_start_cpu0);
    // 1. Hardware initialization
    if (bootloader_init() != ESP_OK) {
        ESP_LOGE(TAG, "---- init fail ----", call_start_cpu0);
        bootloader_reset();
    }
    ESP_LOGE(TAG, "---- init OK ----", call_start_cpu0);
    ....
}

[cdDave]

Thanks for the response!

I assume by "which GPIO are you using", you are referring to IO0 and Reset?

If so, both of those are pulled high at all times, through a 10k resistor. We have the capability to enter programming mode by jumpering those pins, but normal operation always has those pins pulled high.

I have added the debug in the call_start_cpu0 function as you recommend and will try to re-capture a fail event.

Also, I assume you know it's entering the 2nd bootloader because of this line in the logs: entry 0x4008039c. Is that correct?

[ESP_houwenxiang]

I assume by "which GPIO are you using", you are referring to IO0 and Reset?

I am referring to which IOs are used in the I2C bus(SCL. SDA).

Also, I assume you know it's entering the 2nd bootloader because of this line in the logs: entry 0x4008039c. Is that correct?

Yes, I think the 2nd bootloader has a problem, maybe is the flash reading error.

[WiFive]

Do you have 2nd stage bootloader logs disabled?

[cdDave]

Thanks.

For the I2C pins - IO21 is SDA, and IO22 is SCL on our device.

Regarding the 2nd bootloader logging - I haven't changed that from the IDF defaults. How do I go about enabling the logging?

[cdDave]

I have some more results based on the above.

1) I upgraded the IDF version to 3.3 just to make sure I'm on a more recent branch (We were previously on an older IDF version)
2) I added the logging at the beginning of the 2nd bootloader as suggested

The crash happened on one out of 7 devices again last night. Below is included the log.

A couple of things are interesting.

1) I see a csum err occurring on each bad boot cycle - looks like when trying to load the 2nd bootloader
2) The 2nd bootloader does NOT start running
3) When I manually reset the device (by grounding/ releasing the ESP reset pin) at 10/25/19 08:30:19:521, you see that the boot process then completes as expected, and the device comes back alive and begins executing the program normally.

The big question is - why would the boot process run into csum err until the device is manually reset?

[10/25/19 08:30:18:545] rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/25/19 08:30:18:545] configsip: 0, SPIWP:0xee
[10/25/19 08:30:18:546] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[10/25/19 08:30:18:546] mode:DIO, clock div:2
[10/25/19 08:30:18:547] load:0x3fff0018,len:4
[10/25/19 08:30:18:547] load:0x3fff001c,len:6432
[10/25/19 08:30:18:548] ho 0 tail 12 room 4
[10/25/19 08:30:18:548] load:0x40078000,len:11344
[10/25/19 08:30:18:549] load:0x40080400,len:6624
[10/25/19 08:30:18:549] csum err:0x50!=0xd0
[10/25/19 08:30:18:550] ets_main.c 371
[10/25/19 08:30:18:867] ets Jun 8 2016 00:22:57
[10/25/19 08:30:18:869]
[10/25/19 08:30:18:871] rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/25/19 08:30:18:873] configsip: 0, SPIWP:0xee
[10/25/19 08:30:18:875] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[10/25/19 08:30:18:877] mode:DIO, clock div:2
[10/25/19 08:30:18:879] load:0x3fff0018,len:4
[10/25/19 08:30:18:881] load:0x3fff001c,len:6432
[10/25/19 08:30:18:883] ho 0 tail 12 room 4
[10/25/19 08:30:18:885] load:0x40078000,len:11344
[10/25/19 08:30:18:887] load:0x40080400,len:6624
[10/25/19 08:30:18:889] csum err:0x50!=0xd0
[10/25/19 08:30:18:890] ets_main.c 371
[10/25/19 08:30:19:191] ets Jun 8 2016 00:22:57
[10/25/19 08:30:19:193]
[10/25/19 08:30:19:195] rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/25/19 08:30:19:196] configsip: 0, SPIWP:0xee
[10/25/19 08:30:19:198] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[10/25/19 08:30:19:199] mode:DIO, clock div:2
[10/25/19 08:30:19:200] load:0x3fff0018,len:4
[10/25/19 08:30:19:202] load:0x3fff001c,len:6432
[10/25/19 08:30:19:204] ho 0 tail 12 room 4
[10/25/19 08:30:19:207] load:0x40078000,len:11344
[10/25/19 08:30:19:209] load:0x40080400,len:6624
[10/25/19 08:30:19:210] csum err:0x50!=0xd0
[10/25/19 08:30:19:212] ets_main.c 371
[10/25/19 08:30:19:517] ets Jun 8 2016 00:22:57
[10/25/19 08:30:19:519]
[10/25/19 08:30:19:521] rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/25/19 08:30:19:523] configsip: 0, SPIWP:0xee
[10/25/19 08:30:19:525] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[10/25/19 08:30:19:526] mode:DIO, clock div:2
[10/25/19 08:30:19:528] load:0x3fff0018,len:4
[10/25/19 08:30:19:530] load:0x3fff001c,len:6432
[10/25/19 08:30:19:531] ho 0 tail 12 room 4
[10/25/19 08:30:19:533] load:0x40078000,len:11344
[10/25/19 08:30:19:535] load:0 ets Jun 8 2016 00:22:57
[10/25/19 08:30:20:414]
[10/25/19 08:30:20:416] rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[10/25/19 08:30:20:418] configsip: 0, SPIWP:0xee
[10/25/19 08:30:20:420] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[10/25/19 08:30:20:422] mode:DIO, clock div:2
[10/25/19 08:30:20:424] load:0x3fff0018,len:4
[10/25/19 08:30:20:426] load:0x3fff001c,len:6432
[10/25/19 08:30:20:429] ho 0 tail 12 room 4
[10/25/19 08:30:20:431] load:0x40078000,len:11344
[10/25/19 08:30:20:432] load:0x40080400,len:6624
[10/25/19 08:30:20:434] entry 0x40080770
[10/25/19 08:30:20:436] [0;31mE (72) boot: ---0x40080770--------------[0m
[10/25/19 08:30:20:460] [0;32mI (35) boot: ESP-IDF v3.3 2nd stage bootloader[0m
[10/25/19 08:30:20:462] [0;32mI (35) boot: compile time 08:49:49[0m
[10/25/19 08:30:20:463] [0;32mI (35) boot: Enabling RNG early entropy source...[0m
[10/25/19 08:30:20:464] [0;32mI (39) boot: SPI Speed : 40MHz[0m
[10/25/19 08:30:20:465] [0;32mI (43) boot: SPI Mode : DIO[0m
[10/25/19 08:30:20:467] [0;32mI (47) boot: SPI Flash Size : 4MB[0m
[10/25/19 08:30:20:482] [0;31mE (51) boot: ---- init OK ---[0m
[10/25/19 08:30:20:483] [0;32mI (55) boot: Partition Table:[0m
[10/25/19 08:30:20:484] [0;32mI (58) boot: ## Label Usage Type ST Offset Length[0m
[10/25/19 08:30:20:484] [0;32mI (66) boot: 0 nvs WiFi data 01 02 00009000 00006000[0m
[10/25/19 08:30:20:485] [0;32mI (73) boot: 1 phy_init RF data 01 01 0000f000 00001000[0m
[10/25/19 08:30:20:485] [0;32mI (81) boot: 2 factory factory app 00 00 00010000 00100000[0m
[10/25/19 08:30:20:506] [0;32mI (88) boot: End of partition table[0m
[10/25/19 08:30:20:506] [0;32mI (92) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x14904 ( 84228) map[0m
[10/25/19 08:30:20:536] [0;32mI (131) esp_image: segment 1: paddr=0x0002492c vaddr=0x3ffbdb60 size=0x03230 ( 12848) load[0m
[10/25/19 08:30:20:537] [0;32mI (136) esp_image: segment 2: paddr=0x00027b64 vaddr=0x40080000 size=0x00400 ( 1024) load[0m
[10/25/19 08:30:20:539] [0;32mI (138) esp_image: segment 3: paddr=0x00027f6c vaddr=0x40080400 size=0x080a4 ( 32932) load[0m
[10/25/19 08:30:20:568] [0;32mI (160) esp_image: segment 4: paddr=0x00030018 vaddr=0x400d0018 size=0x391f8 (233976) map[0m
[10/25/19 08:30:20:629] [0;32mI (243) esp_image: segment 5: paddr=0x00069218 vaddr=0x400884a4 size=0x03b4c ( 15180) load[0m
[10/25/19 08:30:20:661] [0;32mI (257) boot: Loaded app from partition at offset 0x10000[0m
[10/25/19 08:30:20:663] [0;32mI (257) boot: Disabling RNG early entropy source...[0m
[10/25/19 08:30:20:664] [0;32mI (257) cpu_start: Pro cpu up.[0m
[10/25/19 08:30:20:666] [0;32mI (261) cpu_start: Application information:[0m
[10/25/19 08:30:20:667] [0;32mI (266) cpu_start: Project name: HESP32[0m
[10/25/19 08:30:20:691] [0;32mI (271) cpu_start: App version: V_1.45-6-g43518ef-dirty[0m
[10/25/19 08:30:20:692] [0;32mI (277) cpu_start: Compile time: Oct 23 2019 09:07:02[0m
[10/25/19 08:30:20:693] [0;32mI (283) cpu_start: ELF file SHA256: 76e73c942389751d...[0m
[10/25/19 08:30:20:694] [0;32mI (289) cpu_start: ESP-IDF: v3.3-dirty[0m
[10/25/19 08:30:20:695] [0;32mI (295) cpu_start: Starting app cpu, entry point is 0x4008125c[0m
[10/25/19 08:30:20:723] [0;32mI (0) cpu_start: App cpu up.[0m
[10/25/19 08:30:20:724] [0;32mI (305) heap_init: Initializing. RAM available for dynamic allocation:[0m
[10/25/19 08:30:20:725] [0;32mI (312) heap_init: At 3FFAE6E0 len 0000F480 (61 KiB): DRAM[0m
[10/25/19 08:30:20:726] [0;32mI (318) heap_init: At 3FFCDD18 len 000122E8 (72 KiB): DRAM[0m
[10/25/19 08:30:20:727] [0;32mI (324) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM[0m
[10/25/19 08:30:20:754] [0;32mI (331) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[10/25/19 08:30:20:756] [0;32mI (337) heap_init: At 4008BFF0 len 00014010 (80 KiB): IRAM[0m
[10/25/19 08:30:20:757] [0;32mI (343) cpu_start: Pro cpu start user code[0m
[10/25/19 08:30:20:759] [0;32mI (26) cpu_start: Chip Revision: 1[0m
[10/25/19 08:30:20:760] [0;33mW (27) cpu_start: Chip revision is higher than the one configured in menuconfig. Suggest to upgrade it.[0m
[10/25/19 08:30:20:785] [0;32mI (30) cpu_start: Starting scheduler on PRO CPU.[0m
[10/25/19 08:30:20:786] [0;32mI (0) cpu_start: Starting scheduler on APP CPU.[0m

[ESP_houwenxiang]

Hi, cdDave
I think this problem is caused by the power supply of flash. Can you measure the voltage of the following three points with an oscilloscope(When the chip always restart)? because we don't have your hardware to do test.

1: VCC of ESP32
2: VCC of flash
3: EN pin of ESP32



thanks !!

[cdDave]

Hi,

We are using the ESP32-WROOM, so I don't have access to the flash voltage lines.

EN is pulled to high voltage at all times.

What could explain the difference in boot behavior between the automatic constant reset (and getting checksum fail) vs doing a manual reset and then the boot successfully completes?

Thanks