v5.2 bootloader crashes on startup (IDFGH-12141)

readmodifywrite commented 9 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.2 11eaf41b37267ad7709c0899c284e3683d2f0b5e

Espressif SoC revision.

ESP32-C3

Operating System used.

Linux

How did you build your project?

Command line with CMake

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

None

Development Kit.

Custom board

Power Supply used.

USB

What is the expected behavior?

The chip should boot up to the user application.

What is the actual behavior?

The bootloader crashes on startup.

Steps to reproduce.

Run IDF tag v5.2 on the C3.

Debug Logs.

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0xc (RTC_SW_CPU_RST),boot:0xd (SPI_FAST_FLASH_BOOT)
Saved PC:0x403808ec
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd5820,len:0x23e0
load:0x403cc710,len:0xe4c
load:0x403ce710,len:0x354c
entry 0x403cc71a
I (24) boot: ESP-IDF v5.2 2nd stage bootloader
I (24) boot: compile time Feb 16 2024 10:12:36
D (24) bootloader_flash: non-XMC chip detected by SFDP Read (00), skip.
D (29) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (36) boot: chip revision: v0.4
D (40) qio_mode: Probing for QIO mode enable...
D (45) qio_mode: Raw SPI flash chip id 0x5e4016
D (49) qio_mode: Manufacturer ID 0x5e chip ID 0x4016
I (54) qio_mode: Enabling default flash chip QIO
D (60) qio_mode: Initial flash chip status 0x2
D (64) qio_mode: QIO mode already enabled in flash
D (69) qio_mode: Enabling QIO mode...
D (73) boot.esp32c3: magic e9
D (76) boot.esp32c3: segments 03
D (79) boot.esp32c3: spi_mode 02
D (82) boot.esp32c3: spi_speed 0f
D (86) boot.esp32c3: spi_size 02
I (89) boot.esp32c3: SPI Speed      : 80MHz
I (94) boot.esp32c3: SPI Mode       : QIO
I (99) boot.esp32c3: SPI Flash Size : 4MB
D (103) boot: Enabling RTCWDT(9000 ms)
I (107) boot: Enabling RNG early entropy source...
D (113) bootloader_flash: rodata starts from paddr=0x00008000, size=0xc00, will be mapped to vaddr=0x3c000000
V (122) bootloader_flash: after mapping, starting from paddr=0x00000000 and vaddr=0x3c000000, 0x10000 bytes are mapped
D (133) boot: mapped partition table 0x8000 at 0x3c008000
D (139) flash_parts: partition table verified, 7 entries
I (144) boot: Partition Table:
I (148) boot: ## Label            Usage          Type ST Offset   Length
D (155) boot: load partition table entry 0x3c008000
D (160) boot: type=1 subtype=4
I (163) boot:  0 nvs_key          NVS keys         01 04 00009000 00001000
D (171) boot: load partition table entry 0x3c008020
D (176) boot: type=1 subtype=0
I (179) boot:  1 otadata          OTA data         01 00 0000d000 00002000
D (186) boot: load partition table entry 0x3c008040
D (191) boot: type=1 subtype=1
I (195) boot:  2 phy_init         RF data          01 01 0000f000 00001000
D (202) boot: load partition table entry 0x3c008060
D (207) boot: type=0 subtype=10
I (210) boot:  3 ota_0            OTA app          00 10 00010000 00180000
D (218) boot: load partition table entry 0x3c008080
D (223) boot: type=0 subtype=11
I (226) boot:  4 ota_1            OTA app          00 11 00190000 00180000
D (233) boot: load partition table entry 0x3c0080a0
D (238) boot: type=1 subtype=2
I (242) boot:  5 nvs              WiFi data        01 02 00310000 00040000
I (249) boot: End of partition table
D (253) boot: OTA data offset 0xd000
D (257) bootloader_flash: rodata starts from paddr=0x0000d000, size=0x2000, will be mapped to vaddr=0x3c000000
V (267) bootloader_flash: after mapping, starting from paddr=0x00000000 and vaddr=0x3c000000, 0x10000 bytes are mapped
D (278) boot: otadata[0]: sequence values 0x00000001
D (283) boot: otadata[1]: sequence values 0xffffffff
D (288) boot_comm: Only otadata[0] is valid
D (292) boot: Active otadata[0]
D (295) boot: Mapping seq 0 -> OTA slot 0
D (299) boot: Trying partition index 0 offs 0x10000 size 0x180000
D (306) esp_image: reading image header @ 0x10000
D (310) bootloader_flash: mmu set block paddr=0x00010000 (was 0xffffffff)
D (317) esp_image: image header: 0xe9 0x05 0x02 0x02 4038054a
V (323) esp_image: loading segment header 0 at offset 0x10018
V (329) esp_image: segment data length 0x3b300 data starts 0x10020
V (335) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3c0b0020
I (343) esp_image: segment 0: paddr=00010020 vaddr=3c0b0020 size=3b300h (242432) map
D (352) esp_image: free data page_count 0x00000080
D (357) bootloader_flash: rodata starts from paddr=0x00010020, size=0x3b300, will be mapped to vaddr=0x3c000000
V (367) bootloader_flash: after mapping, starting from paddr=0x00010000 and vaddr=0x3c000000, 0x40000 bytes are mapped
V (412) esp_image: loading segment header 1 at offset 0x4b320
D (412) bootloader_flash: mmu set block paddr=0x00040000 (was 0xffffffff)
V (413) esp_image: segment data length 0x2af0 data starts 0x4b328
V (419) esp_image: segment 1 map_segment 0 segment_data_offs 0x4b328 load_addr 0x3fc92200
I (428) esp_image: segment 1: paddr=0004b328 vaddr=3fc92200 size=02af0h ( 10992) load
D (436) esp_image: free data page_count 0x00000080
D (441) bootloader_flash: rodata starts from paddr=0x0004b328, size=0x2af0, will be mapped to vaddr=0x3c000000
V (451) bootloader_flash: after mapping, starting from paddr=0x00040000 and vaddr=0x3c000000, 0x10000 bytes are mapped
V (464) esp_image: loading segment header 2 at offset 0x4de18
D (468) bootloader_flash: mmu set block paddr=0x00040000 (was 0xffffffff)
V (474) esp_image: segment data length 0x21f8 data starts 0x4de20
V (481) esp_image: segment 2 map_segment 0 segment_data_offs 0x4de20 load_addr 0x40380000
I (489) esp_image: segment 2: paddr=0004de20 vaddr=40380000 size=021f8h (  8696) load
D (497) esp_image: free data page_count 0x00000080
D (502) bootloader_flash: rodata starts from paddr=0x0004de20, size=0x21f8, will be mapped to vaddr=0x3c000000
V (512) bootloader_flash: after mapping, starting from paddr=0x00040000 and vaddr=0x3c000000, 0x20000 bytes are mapped
V (525) esp_image: loading segment header 3 at offset 0x50018
D (529) bootloader_flash: mmu set block paddr=0x00050000 (was 0xffffffff)
V (536) esp_image: segment data length 0xaf79c data starts 0x50020
V (542) esp_image: segment 3 map_segment 1 segment_data_offs 0x50020 load_addr 0x42000020
I (550) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=af79ch (718748) map
D (559) esp_image: free data page_count 0x00000080
D (564) bootloader_flash: rodata starts from paddr=0x00050020, size=0xaf79c, will be mapped to vaddr=0x3c000000
V (574) bootloader_flash: after mapping, starting from paddr=0x00050000 and vaddr=0x3c000000, 0xb0000 bytes are mapped
V (685) esp_image: loading segment header 4 at offset 0xff7bc
D (686) bootloader_flash: mmu set block paddr=0x000f0000 (was 0xffffffff)
V (687) esp_image: segment data length 0xff00 data starts 0xff7c4
V (693) esp_image: segment 4 map_segment 0 segment_data_offs 0xff7c4 load_addr 0x403821f8
I (701) esp_image: segment 4: paddr=000ff7c4 vaddr=403821f8 size=0ff00h ( 65280) load
D (710) esp_image: free data page_count 0x00000080
D (715) bootloader_flash: rodata starts from paddr=0x000ff7c4, size=0xff00, will be mapped to vaddr=0x3c000000
V (725) bootloader_flash: after mapping, starting from paddr=0x000f0000 and vaddr=0x3c000000, 0x20000 bytes are mapped
V (747) esp_image: image start 0x00010000 end of last section 0x0010f6c4
D (747) bootloader_flash: mmu set block paddr=0x00100000 (was 0xffffffff)
D (749) boot: Calculated hash: 40bda191c549190fe5903884076fdfe8897b5ef4ec876d026d2ce6b52369a9ba
I (763) boot: Loaded app from partition at offset 0x10000
I (764) boot: Disabling RNG early entropy source...
D (770) boot: Mapping segment 0 as DROM
D (773) boot: Mapping segment 3 as IROM
D (777) boot: calling set_cache_and_start_app
D (782) boot: configure drom and irom and start
V (786) boot: rodata starts from paddr=0x00010020, vaddr=0x3c0b0020, size=0x3b300
V (794) boot: after mapping rodata, starting from paddr=0x00010000 and vaddr=0x3c0b0000, 0x40000 bytes are mapped
V (804) boot: text starts from paddr=0x00050020, vaddr=0x42000020, size=0xaf79c
V (812) boot: after mapping text, starting from paddr=0x00050000 and vaddr=0x42000000, 0xb0000 bytes are mapped
D (822) boot: start: 0x4038054a
I (825) cpu_start: Unicore app
Guru Meditation Error: Core  0 panic'ed (Load access fault). Exception was unhandled.

Core  0 register dump:
MEPC    : 0x4004c48c  RA      : 0x4004c4b0  SP      : 0x3fcde280  GP      : 0x3fc92a00  
TP      : 0x00000000  T0      : 0x00000000  T1      : 0x00000000  T2      : 0x00000009  
S0/FP   : 0x000000ff  S1      : 0x0000000c  A0      : 0x000000ff  A1      : 0x3fcde2b0  
A2      : 0x0012ad40  A3      : 0x03ff0000  A4      : 0x0000e000  A5      : 0x60ffe01c  
A6      : 0xfa000000  A7      : 0x00000003  S2      : 0x3c0eb31f  S3      : 0x00050000  
S4      : 0x4038054a  S5      : 0x00050020  S6      : 0x42000000  S7      : 0x3c0b0000  
S8      : 0x00010000  S9      : 0x3fcd6000  S10     : 0x3fcd6000  S11     : 0x3fcd6000  
T3      : 0x00710000  T4      : 0x000f0000  T5      : 0x00800000  T6      : 0x00800000  
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000005  MTVAL   : 0x60ffe01c  
MHARTID : 0x00000000  

Stack memory:
3fcde280: 0x3c0eb31f 0x0000000c 0x00000050 0x42000e0e 0x0000001b 0x00000001 0x00000000 0x60008000
3fcde2a0: 0x00000001 0x000001e0 0x00000006 0x00000050 0x00000001 0x000001e0 0x00000003 0x000000a0
3fcde2c0: 0x3c0eb31f 0x0000000c 0x00000000 0x4038067e 0x00000000 0x80b67f00 0x000ff6d0 0x3fcde2f4
3fcde2e0: 0x00000000 0x3fcd6000 0x00000000 0x403cfa5e 0x00000000 0x00000336 0x3fcd58bc 0x00050000
3fcde300: 0x3c0eb31f 0x420af7bb 0x3fcd6000 0x403cfa64 0x91a1bd40 0x0f1949c5 0x0003b300 0x000af79c
3fcde320: 0xf45e7b89 0x026d87ec 0xb5e62c6d 0x000b0000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde340: 0x00000000 0x00000000 0x00000000 0x3fcdf000 0x000067a8 0x3fcd6000 0x3fcd6000 0xffffffff
3fcde360: 0x00000000 0x3fcde4b0 0x00000000 0x403d0034 0x3fcd7000 0x0000d000 0x00010000 0x00180000
3fcde380: 0x00010000 0x2f0205e9 0x4038054a 0x000000ee 0x03030005 0x0000c700 0x01000000 0x3c0b0020
3fcde3a0: 0x0003b300 0x3fc92200 0x00002af0 0x40380000 0x000021f8 0x42000020 0x000af79c 0x403821f8
3fcde3c0: 0x0000ff00 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde3e0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde400: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00010020
3fcde420: 0x0004b328 0x0004de20 0x00050020 0x000ff7c4 0x00000000 0x00000000 0x00000000 0x00000000
3fcde440: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x000ff6f0
3fcde460: 0x91a1bd40 0x0f1949c5 0x843890e5 0xe8df6f07 0xf45e7b89 0x026d87ec 0xb5e62c6d 0xbaa96923
3fcde480: 0x000067a8 0x3ff1c14c 0x0000ffff 0x3fce0000 0x00000000 0x00000036 0x000067b0 0x403cc79c
3fcde4a0: 0x10145677 0x78000ca0 0x00000000 0x00000000 0x0000d000 0x00002000 0x00000000 0x00000000
3fcde4c0: 0x00000000 0x00000000 0x00010000 0x00180000 0x00190000 0x00180000 0x00000000 0x00000000
3fcde4e0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde500: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde520: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde540: 0x00000000 0x00000000 0x00000002 0x00000000 0x600c5200 0x600c5200 0xdbb80087 0x4004a296
3fcde560: 0x00000000 0x00000000 0x3fcde668 0x00000000 0xffffffff 0x00000000 0x00010000 0x2f0203e9
3fcde580: 0x403cc71a 0x403ce710 0x0000354c 0x000000ee 0x03030005 0x0000c700 0x01000000 0x3c0067b0
3fcde5a0: 0x7533885e 0xe608c91c 0x1d5ebe25 0xfcb99d89 0x50412066 0x081ea972 0xbd990896 0xf99cb28f
3fcde5c0: 0xf9e235c5 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
3fcde5e0: 0x00000000 0x3fcde700 0x00000101 0x00000002 0xe608c91c 0x1d5ebe25 0xfcb99d89 0x50412066
3fcde600: 0x081ea972 0xbd990896 0xf99cb28f 0xf9e235c5 0x00000000 0x00000000 0x00000000 0x00000000
3fcde620: 0x00000000 0x00000000 0x00000000 0x00000000 0x600087b7 0x669d5bb8 0x9b5d0532 0x5bb8dbb8
3fcde640: 0x76e58d75 0x8f7516fd 0xdba88d59 0x67135bb8 0xdbb80087 0x00008082 0x00000000 0x36000000
3fcde660: 0x00000080 0x00000000 0x00000000 0x803d0300 0x00000000 0x00000000 0x00000000 0x00000000

ELF file SHA256: 

Rebooting...

More Information.

This is fatal for v5.2. This commit should not be tagged with a broken bootloader. Please delete the tag so no one else runs in to this.

What commit (I want the exact hash) on 5.2 actually works?

readmodifywrite commented 9 months ago

This issue persists on release/v5.2 as well: cc649ea869b8c24d19ba2d94c4d3f1146cb2947b

DO NOT USE THIS RELEASE

Absolute fail y'all. I'm going back to 5.1 - please do not suggest updating to 5.2 to deal with the bugs in 5.1 until 5.2 is able to boot up the chip.

readmodifywrite commented 9 months ago

I can confirm that reverting IDF to v5.1 is a viable fix.

igrr commented 9 months ago

Sorry for the bad experience with the version upgrade @readmodifywrite! There haven't been many changes since v5.2-beta1 release, and so far we didn't get feedback that it's absolutely broken, so we went ahead with the final release. In our internal CI, all IDF examples we test on real hardware also worked fine. However sometimes there are cases which are not covered by our CI, usually related to a particular combination of sdkconfig settings. Hopefully we can figure out what is causing the issue in your case quickly.

According to the log, the crash happens during app startup (cpu_start line). Could you please clarify if you are

using IDF v5.2 bootloader with an IDF v5.1 app binary?
or building both the app and the bootloader with v5.2? If yes, please also attach you application's sdkconfig file.

Additionally, could you please use idf.py monitor to get the decoded backtrace? This will help us identify the issue.

readmodifywrite commented 9 months ago

Everything is built on 5.2. It never gets to the app binary. I'm loading over serial with esptool.

I don't have the sdkconfig at the moment, I've already reverted to 5.1 and am now trying to unfuck the mDNS build which refuses to work without the useless component manager.

I'm sorry I can't be more helpful, but it's just whack-a-mole with broken behavior in the IDF. I've got a ton of issues with the MQTT client I'm trying to sort out too (was hoping 5.2 would clean some of this up, apparently it won't).

There is just too much instability, unnecessary complexity, and change for the sake of change for me to keep up. It's a full time job just to workaround bugs in the IDF, and I'm just a solo dev. At some point I need to write my actual app code so I have a product to sell!

igrr commented 9 months ago

Everything is built on 5.2. It never gets to the app binary.

The I (825) cpu_start: Unicore app line indicates that it does get to the app binary, although it crashes soon after, before it gets to your app_main function. (If it crashed in the bootloader, the panic output would also look differently.)

If you manage to share the sdkconfig file and provide the decoded backtrace in the future, it would be very helpful for diagnosing this issue.

readmodifywrite commented 9 months ago

FWIW, y'all really do an amazing job of support here. No other chip vendor even bothers to try.

I'll try and dig a bit more on 5.2 next week - I need to circle back to my MQTT stuff for now. I did get the mDNS sorted so that's something.

andylinpersonal commented 9 months ago

Seems like the user app crashed immaturely when the default console is configured as USB Serial JTAG. Try to use UART0 instead until this issue fixed?

sudeep-mohanty commented 9 months ago

Hello @readmodifywrite, I tried a few default IDF examples with v5.2 but I do not encounter this issue. Even when USB-serial-JTAG is enabled, the bootup looks fine and I am able to enter the user app as intended. Could you please provide some more details about your application and maybe the sdkconfig file? It might help us in narrowing down to the configuration which is causing this problem. Thanks!

andylinpersonal commented 9 months ago

Here is an MWE for this issue.

IDF version: v5.2-166-ge0944287f3 (e0944287f33b348f9ccb7026bd32517d0f6b3e56) Target: esp32-c3 v0.4 Board: LuatOS CORE-ESP32-C3 (C3 + DIO flash) | ESP32C3 Super Mini (C3FH4)

main/main.c

#include <freertos/FreeRTOS.h>
#include <stdio.h>

void app_main(void) {
  while (1) {
    fputs("hello world!\n", stderr);
    vTaskDelay(1000);
  }
}

main/CMakeLists.txt

idf_component_register(SRCS "main.c")

CMakeLists.txt

cmake_minimum_required(VERSION 3.16)
include($ENV{IDF_PATH}/tools/cmake/project.cmake)

project(tester)

sdkconfig.defaults

# C3 stays in the reset loop with this option on
CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG=y

Log messages

 ESP-ROM:esp32c3-api1-20210207
 Build:Feb  7 2021
 rst:0xc (RTC_SW_CPU_RST),boot:0xc (SPI_FAST_FLASH_BOOT)
 Saved PC:0x4038061e
 SPIWP:0xee
 mode:DIO, clock div:1
 load:0x3fcd5820,len:0x1738
 load:0x403cc710,len:0xaf0
 load:0x403ce710,len:0x2e3c
 entry 0x403cc71a
 I (15) boot: ESP-IDF v5.2-166-ge0944287f3 2nd stage bootloader
 I (15) boot: compile time Feb 20 2024 19:21:21
 I (15) boot: chip revision: v0.4
 I (16) boot.esp32c3: SPI Speed      : 80MHz
 I (16) boot.esp32c3: SPI Mode       : DIO
 I (16) boot.esp32c3: SPI Flash Size : 2M I (16) boot: Enabling RNG early entropy source...
 I (16) boot: Partition Table:
 I (16) boot: ## Label            Usage          Type ST Offset   Length
 I (17) boot:  0 nvs              WiFi data        01 02 00009000 00006000
 I (17) boot:  1 phy_init         RF data          01 01 0000f000 00001000
 I (17) boot:  2 factory          factory app      00 00 00010000 00100000
 I (17) boot: End of partition table
 I (18) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=09380h ( 37760) map
 I (24) esp_image: segment 1: paddr=000193a8 vaddr=3fc8a800 size=011cch (  4556) load
 I (25) esp_image: segment 2: paddr=0001a57c vaddr=40380000 size=05a9ch ( 23196) load
 I (30) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=14770h ( 83824) map
 I (44) esp_image: segment 4: paddr=00034798 vaddr=40385a9c size=04cbch ( 19644) load
 I (51) boot: Loaded app from partition at offset 0x10000
 I (51) boot: Disabling RNG early entropy source...
 I (51) cpu_start: Unicore app
 Guru Meditation Error: Core  0 panic'ed (Load access fault). Exception was unhandled.

 Core  0 register dump:
 MEPC    : 0x4004c48c  RA      : 0x4004c4b0  SP      : 0x3fcde280  GP      : 0x3fc8b000
 TP      : 0x00000000  T0      : 0x00000000  T1      : 0x00000000  T2      : 0x00000009
 S0/FP   : 0x000000ff  S1      : 0x00000050  A0      : 0x000000ff  A1      : 0x3fcde298
 A2      : 0x0012ad40  A3      : 0x03ff0000  A4      : 0x0000e000  A5      : 0x60ffe01c
 A6      : 0xfa000000  A7      : 0x00000003  S2      : 0x42000000  S3      : 0x3c020000
 S4      : 0x3fcde42c  S5      : 0x00009380  S6      : 0xffff0000  S7      : 0x40380250
 S8      : 0x00020020  S9      : 0x00010020  S10     : 0x00000005  S11     : 0x3fcde3c0
 T3      : 0x007d0000  T4      : 0x00030000  T5      : 0x00800000  T6      : 0x00800000
 MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000005  MTVAL   : 0x60ffe01c
 MHARTID : 0x00000000

 Stack memory:
 3fcde280: 0x42000000 0x00000050 0x00000001 0x420008a8 0x00000000 0x00000000 0x00000001 0x000001e0
 3fcde2a0: 0x00000003 0x000000a0 0x00000001 0x000001e0 0x00000006 0x00000050 0x00000000 0x60008000
 3fcde2c0: 0x42000000 0x3c02939f 0x0000000c 0x4038031e 0x00000000 0x00a31400 0x00029460 0x00000006
 3fcde2e0: 0x00000000 0x3ff1c14c 0x00000000 0x00000007 0x3fcde37c 0x00009380 0x3fcde42c 0x3c020000
 3fcde300: 0x42000000 0x3c02939f 0x4201478f 0x403cf73c 0x9380cb01 0x58389f35 0x68cbc2fc 0x00014770
 3fcde320: 0x4b08a409 0x8c7151e3 0x22876706 0x00020000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde340: 0x00000000 0x00000000 0x00000000 0x3fcdf000 0x00005094 0x3ff1c14c 0x0000ffff 0xffffffff
 3fcde360: 0xffffffff 0x3fcde4b0 0xffffffff 0x403cfbd4 0x00000000 0x00010000 0x00100000 0x00010000
 3fcde380: 0x1f0205e9 0x40380250 0x000000ee 0x03030005 0x0000c700 0x01000000 0x3c020020 0x00009380
 3fcde3a0: 0x3fc8a800 0x000011cc 0x40380000 0x00005a9c 0x42000020 0x00014770 0x40385a9c 0x00004cbc
 3fcde3c0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde3e0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde400: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00010020 0x000193a8
 3fcde420: 0x0001a57c 0x00020020 0x00034798 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde440: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00029480 0x9380cb01
 3fcde460: 0x58389f35 0x68cbc2fc 0x0ce42cae 0x4b08a409 0x8c7151e3 0x22876706 0xa157afeb 0x00000000
 3fcde480: 0x00005094 0x3ff1c14c 0x0000ffff 0x3fce0000 0x00000000 0x000000e9 0x000050a0 0x403cc79c
 3fcde4a0: 0x82c10107 0x8163460d 0x00000000 0xffffffff 0x00000000 0x00000000 0x00010000 0x00100000
 3fcde4c0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde4e0: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde500: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde520: 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde540: 0x00000000 0x00000000 0x00000000 0x00000000 0x600c5200 0x600c5200 0x00000080 0x4004a296
 3fcde560: 0x00000000 0x00000000 0x3fcde668 0x00000000 0xffffffff 0x00000000 0x00010000 0x1f0203e9
 3fcde580: 0x403cc71a 0x403ce710 0x00002e3c 0x000000ee 0x03030005 0x0000c700 0x01000000 0x3c0050a0
 3fcde5a0: 0x7533885e 0xcf496ecd 0x93252fce 0x6fead1bd 0x6b88d317 0xfc76a269 0x3255d380 0xa67982e5
 3fcde5c0: 0x84eea0c1 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde5e0: 0x00000000 0x3fcde700 0x00000101 0x00000002 0xcf496ecd 0x93252fce 0x6fead1bd 0x6b88d317
 3fcde600: 0xfc76a269 0x3255d380 0xa67982e5 0x84eea0c1 0x00000000 0x00000000 0x00000000 0x00000000
 3fcde620: 0x00000000 0x00000000 0x00000000 0x00000000 0x8f7516fd 0xdba88d59 0x67135bb8 0xdbb80087
 3fcde640: 0x00008082 0x00000000 0x00000000 0xe9000000 0x00000080 0x00000000 0x00000000 0x00000000
 3fcde660: 0x00000000 0x00000000 0x00000000 0x00850200 0x00000000 0x00000000 0x00000000 0x00000000

 ELF file SHA256:

 Rebooting...
 ESP-ROM:esp32c3-api1-20210207
 Build:Feb  7 2021
 rst:0xc (RTC_SW_CPU_RST),boot:0xc (SPI_FAST_FLASH_BOOT)
 Saved PC:0x4038061e
 SPIWP:0xee
 mode:DIO, clock div:1
 load:0x3fcd5820,len:0x1738
 load:0x403cc710,len:0xaf0
 load:0x403ce710,len:0x2e3c
 entry 0x403cc71a

okhsunrog commented 9 months ago

Updated to 5.2 and killed 4 hours trying to figure out why my app won't boot. That was not very fun. I confirm the issue, turns out it happens to me with USB-Serial as default output. esp32-c3 v0.3, linux

ESP-Marius commented 9 months ago

We've also confirmed that there is indeed an issue with using CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG=y on v5.2 and are working on fixing it.

Thanks for the feedback here which helped us find the issue and sorry for all inconvenience this has caused you guys when trying to upgrade to v5.2!

okhsunrog commented 9 months ago

Any updates on this issue?

FL0WL0W commented 9 months ago

Any updates on this issue?

Seems to be fixed on latest dev branch. If you go to my issue that is closed i explain exactly where/what line the issue is.

ESP-Marius commented 9 months ago

Issue was fixed on master with 6768805d20cbd026b7fccf9d7adb49991d6b66a2, but unfortunately that introduced a regression with usb_otg console. My colleague is working on fixing that, and as soon as it is working properly we will merge both fixes to v5.2.

RavenSystem commented 9 months ago

FYI: esp32c3 issue is present too with CONFIG_ESP_CONSOLE_NONE=y.

AxelLin commented 8 months ago

FYI: esp32c3 issue is present too with CONFIG_ESP_CONSOLE_NONE=y.

@ESP-Marius @mythbuster5 Is this fixed for esp32c3?

ESP-Marius commented 8 months ago

Yes, this should be fixed as per the referenced commit. Seems like the issue didnt close automatically.

If anyone is still seeing these issues then please feel free to re-open this ticket.

readmodifywrite commented 7 months ago

Thanks for the quick work on this one!

sailinglove commented 4 months ago

@ESP-Marius @mythbuster5

Sorry for bothering you, but I'm still encountering a similar issue after upgrading my IDF to v5.3-rc1.

I'm using the example_connect() function from the protocol_examples_common library to connect to WiFi by providing the SSID and password through the idf.py monitor's serial console. However, in IDF v5.2-rc1, changing the Channel for console output to USB Serial/JTAG controller resulted in a panic abort. I found this issue and upgraded my IDF to v5.3-rc1, which should have resolved the issue with the commit https://github.com/espressif/esp-idf/commit/6768805d20cbd026b7fccf9d7adb49991d6b66a2.

Despite this, my program still experiences a panic abort, although it now progresses to a later stage. I noticed that the commit message for https://github.com/espressif/esp-idf/commit/6768805d20cbd026b7fccf9d7adb49991d6b66a2 mentions "Fix wrong serial number that has been parsed to rom...", but the debug log before the panic abort shows an error indicating "uart_num error."

I'm quite confused and would appreciate your help in resolving this issue. I've attached the debug logs below for your reference.

Thanks a lot!

Debug Logs:

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0xd (SPI_FAST_FLASH_BOOT)
Saved PC:0x400495da
0x400495da: ets_sha_process in ROM

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd5820,len:0x1738
load:0x403cc710,len:0xb08
load:0x403ce710,len:0x2e90
entry 0x403cc71a
I (24) boot: ESP-IDF v5.3-rc1 2nd stage bootloader
I (24) boot: compile time Jul 15 2024 08:10:11
I (25) boot: chip revision: v0.4
I (25) boot.esp32c3: SPI Speed      : 80MHz
I (25) boot.esp32c3: SPI Mode       : DIO
I (25) boot.esp32c3: SPI Flash Size : 4MB
I (25) boot: Enabling RNG early entropy source...
I (25) boot: Partition Table:
I (25) boot: ## Label            Usage          Type ST Offset   Length
I (26) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (26) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (26) boot:  2 fctry            WiFi data        01 02 00010000 00006000
I (27) boot:  3 factory          factory app      00 00 00020000 00352000
I (27) boot:  4 storage          Unknown data     01 82 00372000 00064000
I (27) boot: End of partition table
I (27) esp_image: segment 0: paddr=00020020 vaddr=3c110020 size=79d84h (499076) map
I (106) esp_image: segment 1: paddr=00099dac vaddr=3fc97200 size=03668h ( 13928) load
I (109) esp_image: segment 2: paddr=0009d41c vaddr=40380000 size=02bfch ( 11260) load
I (111) esp_image: segment 3: paddr=000a0020 vaddr=42000020 size=107e84h (1080964) map
I (280) esp_image: segment 4: paddr=001a7eac vaddr=40382bfc size=144f0h ( 83184) load
I (296) esp_image: segment 5: paddr=001bc3a4 vaddr=50000200 size=00004h (     4) load
I (304) boot: Loaded app from partition at offset 0x20000
I (304) boot: Disabling RNG early entropy source...
I (305) cpu_start: Unicore app
I (313) cpu_start: Pro cpu start user code
I (313) cpu_start: cpu freq: 160000000 Hz
I (313) app_init: Application information:
I (314) app_init: Project name:     alarm-button
I (314) app_init: App version:      782191b-dirty
I (314) app_init: Compile time:     Jul 15 2024 08:09:59
I (314) app_init: ELF file SHA256:  51f47db5a...
I (314) app_init: ESP-IDF:          v5.3-rc1
I (314) efuse_init: Min chip rev:     v0.3
I (314) efuse_init: Max chip rev:     v1.99
I (314) efuse_init: Chip rev:         v0.4
I (315) heap_init: Initializing. RAM available for dynamic allocation:
I (315) heap_init: At 3FCA7770 len 00018890 (98 KiB): RAM
I (315) heap_init: At 3FCC0000 len 0001C710 (113 KiB): Retention RAM
I (315) heap_init: At 3FCDC710 len 00002950 (10 KiB): Retention RAM
I (316) heap_init: At 50000204 len 00001DE4 (7 KiB): RTCRAM
I (317) spi_flash: detected chip: generic
I (317) spi_flash: flash io: dio
I (317) sleep: Configure to isolate all GPIO pins in sleep state
I (318) sleep: Enable automatic switching of GPIO sleep configuration
I (318) main_task: Started on CPU0
I (318) main_task: Calling app_main()
I (318) main: Compile time: Jul 15 2024 08:10:16
I (318) LVGL: Starting LVGL task
I (318) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (318) gc9a01: LCD panel create success, version: 1.2.0
I (438) gpio: GPIO[10]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (438) gpio: GPIO[6]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (438) Knob: Iot Knob Config Succeed, encoder A:10, encoder B:6, direction:0, Version: 0.1.5
I (438) button: IoT Button Version: 3.2.3
I (438) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (438) main: Display LVGL demo
I (438) LVGL_PUB: add group for encoder
I (438) lvgl_basic: Enter home page
I (938) ESP32-C3-LCDKit: BLINK_GPIO setting 8
I (938) gpio: GPIO[8]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (948) ESP32-C3-LCDKit: Partition size: total: 369221, used: 229916
I (948) example_connect: Start example_connect.
I (968) pp: pp rom version: 9387209
I (968) net80211: net80211 rom version: 9387209
I (978) wifi:wifi driver task: 3fcc69fc, prio:23, stack:6656, core=0
I (978) wifi:wifi firmware version: 1026ae2
I (978) wifi:wifi certification version: v7.0
I (978) wifi:config NVS flash: enabled
I (978) wifi:config nano formating: disabled
I (978) wifi:Init data frame dynamic rx buffer num: 32
I (978) wifi:Init static rx mgmt buffer num: 5
I (978) wifi:Init management short buffer num: 32
I (978) wifi:Init dynamic tx buffer num: 32
I (978) wifi:Init static tx FG buffer num: 2
I (978) wifi:Init static rx buffer size: 1600
I (978) wifi:Init static rx buffer num: 10
I (978) wifi:Init dynamic rx buffer num: 32
I (978) wifi_init: rx ba win: 6
I (978) wifi_init: accept mbox: 6
I (978) wifi_init: tcpip mbox: 32
I (978) wifi_init: udp mbox: 6
I (978) wifi_init: tcp mbox: 6
I (978) wifi_init: tcp tx win: 5760
I (978) wifi_init: tcp rx win: 5760
I (978) wifi_init: tcp mss: 1440
I (978) wifi_init: WiFi IRAM OP enabled
I (978) wifi_init: WiFi RX IRAM OP enabled
I (998) phy_init: phy_version 1180,01f2a49,Jun  4 2024,16:34:25
W (998) phy_init: failed to load RF calibration data (0xffffffff), falling back to full calibration
W (1028) phy_init: saving new calibration data because of checksum failure, mode(2)
I (1038) wifi:mode : sta (34:b7:da:a1:b3:cc)
I (1048) wifi:enable tsf
E (1048) uart: uart_driver_install(1618): uart_num error
ESP_ERROR_CHECK failed: esp_err_t 0xffffffff (ESP_FAIL) at 0x4205433c
0x4205433c: example_configure_stdin_stdout at /home/ivanx/esp/esp-idf-v5.3-rc1/examples/common_components/protocol_examples_common/stdin_out.c:25 (discriminator 1)

file: "/IDF/examples/common_components/protocol_examples_common/stdin_out.c" line 25
func: example_configure_stdin_stdout
expression: uart_driver_install( (uart_port_t)CONFIG_ESP_CONSOLE_UART_NUM, 256, 0, 0, NULL, 0)

abort() was called at PC 0x403899db on core 0
0x403899db: _esp_error_check_failed at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/esp_err.c:49

Stack dump detected
Core  0 register dump:
MEPC    : 0x40380778  RA      : 0x403899e6  SP      : 0x3fcaa2c0  GP      : 0x3fc97a00
0x40380778: panic_abort at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/panic.c:463
0x403899e6: __ubsan_include at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/ubsan.c:311

TP      : 0x3fcaa5d0  T0      : 0x37363534  T1      : 0x7271706f  T2      : 0x33323130
S0/FP   : 0x00000004  S1      : 0x3fcaa324  A0      : 0x3fcaa2ec  A1      : 0x3fcaa322
A2      : 0x00000000  A3      : 0x3fcaa319  A4      : 0x00000001  A5      : 0x3fca7000
A6      : 0x7a797877  A7      : 0x76757473  S2      : 0x00000000  S3      : 0x00000000
S4      : 0x00000000  S5      : 0x00000000  S6      : 0x00000000  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x00000000
T3      : 0x6e6d6c6b  T4      : 0x6a696867  T5      : 0x66656463  T6      : 0x62613938
MSTATUS : 0x00001881  MTVEC   : 0x40380001  MCAUSE  : 0x00000007  MTVAL   : 0x00000000
0x40380001: _vector_table at /home/ivanx/esp/esp-idf-v5.3-rc1/components/riscv/vectors_intc.S:54

MHARTID : 0x00000000

Backtrace:

/bin/zsh: /home/ivanx/miniconda3/lib/libtinfo.so.6: no version information available (required by /bin/zsh)
panic_abort (details=details@entry=0x3fcaa2ec "abort() was called at PC 0x403899db on core 0") at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/panic.c:463
463         *((volatile int *) 0) = 0; // NOLINT(clang-analyzer-core.NullDereference) should be an invalid operation on targets
#0  panic_abort (details=details@entry=0x3fcaa2ec "abort() was called at PC 0x403899db on core 0") at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/panic.c:463
#1  0x403899e6 in esp_system_abort (details=details@entry=0x3fcaa2ec "abort() was called at PC 0x403899db on core 0") at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/port/esp_system_chip.c:92
#2  0x403929c6 in abort () at /home/ivanx/esp/esp-idf-v5.3-rc1/components/newlib/abort.c:38
#3  0x403899de in _esp_error_check_failed (rc=<optimized out>, file=file@entry=0x3c11a484 "", line=line@entry=25, function=function@entry=0x3c177c94 <__func__.0> "", expression=expression@entry=0x3c11a430 "") at /home/ivanx/esp/esp-idf-v5.3-rc1/components/esp_system/esp_err.c:49
#4  0x42054340 in example_configure_stdin_stdout () at /home/ivanx/esp/esp-idf-v5.3-rc1/examples/common_components/protocol_examples_common/stdin_out.c:25
#5  0x420541a8 in example_wifi_connect () at /home/ivanx/esp/esp-idf-v5.3-rc1/examples/common_components/protocol_examples_common/wifi_connect.c:254
#6  0x42053762 in example_connect () at /home/ivanx/esp/esp-idf-v5.3-rc1/examples/common_components/protocol_examples_common/connect.c:99
#7  0x420090b4 in ws_prerequisities () at ../main/app_ws.c:122
#8  0x42007a22 in app_main () at ../main/main.c:56
#9  0x42106cc8 in main_task (args=<error reading variable: value has been optimized out>) at /home/ivanx/esp/esp-idf-v5.3-rc1/components/freertos/app_startup.c:208
#10 0x4038ac30 in vPortTaskWrapper (pxCode=<optimized out>, pvParameters=<optimized out>) at /home/ivanx/esp/esp-idf-v5.3-rc1/components/freertos/FreeRTOS-Kernel/portable/riscv/port.c:255
ELF file SHA256: 51f47db5a

Rebooting...

ESP-Marius commented 4 months ago

@sailinglove, I think this is unrelated to the bug reported earlier, as far as I can see CONFIG_EXAMPLE_LOCAL_SERVER_URL_FROM_STDIN has never supported other console inputs than UART.

It will try to initialize an UART driver using CONFIG_ESP_CONSOLE_UART_NUM as the port number, which will fail due to -1 being an invalid port.

sailinglove commented 4 months ago

@ESP-Marius First of all thanks for the quick response! I looked again into the sdkconfig and found that CONFIG_ESP_CONSOLE_UART_NUM was indeed set to -1, though I didn't see CONFIG_EXAMPLE_LOCAL_SERVER_URL_FROM_STDIN anywhere, I think you meant CONFIG_EXAMPLE_WIFI_SSID_PWD_FROM_STDIN?

Anyway, I am just trying to provide wifi ssid and password through idf.py monitor console, but using UART only got me Writing to serial is timing out. Please make sure that your application supports an interactive console and that you have picked the correct console for serial communication. Am I missing some settings?

espressif / esp-idf