Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ESP32-S2 CDC does not boot after OS updates anymore (IDFGH-14450) #15226

Open
3 tasks done
Tobi177 opened this issue Jan 16, 2025 · 5 comments
Open
3 tasks done

ESP32-S2 CDC does not boot after OS updates anymore (IDFGH-14450) #15226

Tobi177 opened this issue Jan 16, 2025 · 5 comments
Labels
Status: Opened Issue is new Type: Bug bugs in IDF

Comments

@Tobi177
Copy link

Tobi177 commented Jan 16, 2025

Answers checklist.

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

IDF version.

v5.3.2

Espressif SoC revision.

ESp32-S2

Operating System used.

Linux

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-S2

Power Supply used.

USB

What is the expected behavior?

After booting the device CDC connects and the device is running as expected. This all works before the updates of the operating systems fine for several weeks.

What is the actual behavior?

The last days I have worked successfully with the ESP32-S2 on my virtual machine with "Ubuntu24" (Linux 6.8.0-51-generic #52-Ubuntu SMP PREEMPT_DYNAMIC Thu Dec 5 13:09:44 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux) running on a proxmox "Debian12" (Linux 6.8.12-5-pve #1 SMP PREEMPT_DYNAMIC PMX 6.8.12-5 (2024-12-03T10:26Z) x86_64 GNU/Linux) while the host system is Windows 11. Everything works perfectly fine for several weeks.

Then I updated Windows 11, Proxmox/Debian and Ubuntu24 to the latest versions. Afterwards, the ESP32-S2 CDC is not booting properly anymore. I have enabled verbose messages for bootloader and the app. Also, the errors can only be cached with "ESP_CONSOLE_UART" setup to "USB CDC", and more important to activate "ESP_CONSOLE_USB_CDC_SUPPORT_ETS_PRINTF". Esp-idf was not updated, just the release "v5.3.2".

The error is so early within the boot process that I assume this has something to do with the CDC interface. If the option "ESP_CONSOLE_USB_CDC_SUPPORT_ETS_PRINTF" is not enabled, then the device will just not initialized properly by Windows11 and cannot be redirected through the virtual machines.

Important notices:

  1. If I use a bare minimum app, just an arduino loop without code, it works on ubuntu24 within the esp-idf enviromnent. However, it crashes immedately once a do include headers, no matter which ones.
  2. If I compile the arduino component with the TinyUSB library (v.0.18) enabled on esp-idf, all is working fine on the Windows11 host. This does not seems to be a problem of my app.

Steps to reproduce.

  1. Step
  2. Step
  3. Step
    ...

Debug Logs.

Rebooting...
I (47) boot: ESP-IDF v5.3.2 2nd stage bootloader
I (47) boot: compile time Jan 16 2025 20:30:05
I (47) boot: chip revision: v1.0
I (49) boot: efuse block revision: v0.2
I (51) qio_mode: Enabling default flash chip QIO
I (52) boot.esp32s2: SPI Speed      : 80MHz
I (54) boot.esp32s2: SPI Mode       : QIO
I (55) boot.esp32s2: SPI Flash Size : 4MB
I (56) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (59) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 0000f000 00008000
I (65) boot:  1 nvs_keys         NVS keys         01 04 00017000 00001000
I (66) boot:  2 otadata          OTA data         01 00 00018000 00002000
I (68) boot:  3 app0             OTA app          00 10 00020000 001e0000
I (70) boot:  4 app1             OTA app          00 11 00200000 001e0000
I (71) boot:  5 coredump         Unknown data     01 03 003e0000 00010000
I (73) boot: End of partition table
I (73) boot: Enabled a check secure version of app for anti rollback
I (75) boot: Secure version (from eFuse) = 0
I (76) esp_image: segment 0: paddr=00020020 vaddr=3f000020 size=33f8ch (212876) map
I (119) esp_image: segment 1: paddr=00053fb4 vaddr=3ff9e040 size=00004h (     4) load
I (120) esp_image: segment 2: paddr=00053fc0 vaddr=3ffcb5e0 size=0430ch ( 17164) load
I (126) esp_image: segment 3: paddr=000582d4 vaddr=40024000 size=07d44h ( 32068) load
I (135) esp_image: segment 4: paddr=00060020 vaddr=40080020 size=ccf94h (839572) map
I (296) esp_image: segment 5: paddr=0012cfbc vaddr=4002bd44 size=0f898h ( 63640) load
I (312) esp_image: segment 6: paddr=0013c85c vaddr=40070000 size=00040h (    64) load
I (313) esp_image: segment 7: paddr=0013c8a4 vaddr=50000000 size=00004h (     4) load
I (326) boot: Loaded app from partition at offset 0x20000
I (327) boot: Checking flash encryption...
I (327) flash_encrypt: flash encryption is enabled (1 plaintext flashes left)
I (330) boot: Disabling RNG early entropy source...
D (602) cpu_start: calling init function: 0x400880c0 on core: 0
--- 0x400880c0: __esp_system_init_fn_init_newlib_stdio at /home/tobi/esp/esp-idf/components/newlib/newlib_init.c:207

D (603) cpu_start: calling init function: 0x40088574 on core: 0
--- 0x40088574: __esp_system_init_fn_init_pthread at /home/tobi/esp/esp-idf/components/pthread/pthread.c:76

D (605) cpu_start: calling init function: 0x400849c4 on core: 0
--- 0x400849c4: __esp_system_init_fn_init_flash at /home/tobi/esp/esp-idf/components/esp_system/startup_funcs.c:88

Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40149408: f01db468 81004136 08e0b41c
--- 0x40149408: esp_get_idf_version at /home/tobi/esp/esp-idf/components/esp_system/port/esp_system_chip.c:88

Core  0 register dump:
PC      : 0x4014940e  PS      : 0x00060d30  A0      : 0x8002fbbd  A1      : 0x3fffe000
--- 0x4014940e: write_lock_acquire at /home/tobi/esp/esp-idf/components/esp_system/port/usb_console.c:460

A2      : 0x3fffe030  A3      : 0x00000001  A4      : 0x02000006  A5      : 0x00000005
A6      : 0x0000000a  A7      : 0x3fffe030  A8      : 0x8002fb38  A9      : 0x3fffe0b0
A10     : 0x00000001  A11     : 0x00000001  A12     : 0x00060720  A13     : 0x00000000
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x00000008  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x00060720  LEND    : 0x00000000  LCOUNT  : 0x40027280
--- 0x40027280: _xt_handle_exc at /home/tobi/esp/esp-idf/components/xtensa/xtensa_vectors.S:739



Backtrace: 0x4014940b:0x3fffe000 0x4002fbba:0x3fffe020 0x4000f985:0x3fffe060 0x4000fde9:0x3fffe080 0x4000ff21:0x3fffe100 0x4003a07e:0x3fffe150 0x400280aa:0x3fffe190 0x400b329d:0x3fffe1c0 0x4002818b:0x3fffe1e0 0x400b334d:0x3fffe210 0x400849ca:0x3fffe270 0x400848d4:0x3fffe290 0x4008490d:0x3fffe2b0 0x40084953:0x3fffe2d0 0x400255b6:0x3fffe2f0 0x4004fe5d:0x3fffe330 0x4004ffaf:0x3fffe370 0x4004a271:0x3fffe4a0 0x40011371:0x3fffe560 0x4000f788:0x3fffe6f0 0x400072a5:0x3fffe710
--- 0x4014940b: esp_get_idf_version at /home/tobi/esp/esp-idf/components/esp_system/port/esp_system_chip.c:88
0x4002fbba: esp_usb_console_write_char at /home/tobi/esp/esp-idf/components/esp_system/port/usb_console.c:456
0x4000f985: ets_write_char in ROM
0x4000fde9: ets_vprintf in ROM
0x4000ff21: ets_printf in ROM
0x4003a07e: memspi_host_read_id_hs at /home/tobi/esp/esp-idf/components/spi_flash/memspi_host_driver.c:102 (discriminator 1)
0x400280aa: read_id_core at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_api.c:424
0x400b329d: esp_flash_read_chip_id at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_api.c:442
0x4002818b: esp_flash_init_main at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_api.c:351
0x400b334d: esp_flash_init_default_chip at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_spi_init.c:398
0x400849ca: __esp_system_init_fn_init_flash at /home/tobi/esp/esp-idf/components/esp_system/startup_funcs.c:94
0x400848d4: do_system_init_fn at /home/tobi/esp/esp-idf/components/esp_system/startup.c:127
0x4008490d: do_core_init at /home/tobi/esp/esp-idf/components/esp_system/startup.c:165
0x40084953: start_cpu0_default at /home/tobi/esp/esp-idf/components/esp_system/startup.c:198
0x400255b6: call_start_cpu0 at /home/tobi/esp/esp-idf/components/esp_system/port/cpu_start.c:842 (discriminator 1)
0x40011371: ets_run_flash_bootloader in ROM
0x4000f788: main in ROM
0x400072a5: _start in ROM

More Information.

I am fully aware, that this problem cannot be solved/reproduced by the developer team easily. There are three operating systems, virtual machines and more difficulties involved here. However, I do think it is a good idea to report this issue - maybe other people running into similar issues and we collect the experiences here. Maybe, I also have a wrong setup as well and some one have suggestions to solve this issue. Thank you.

@Tobi177 Tobi177 added the Type: Bug bugs in IDF label Jan 16, 2025
@github-actions github-actions bot changed the title ESP32-S2 CDC does not boot after OS updates anymore ESP32-S2 CDC does not boot after OS updates anymore (IDFGH-14450) Jan 16, 2025
@espressif-bot espressif-bot added the Status: Opened Issue is new label Jan 16, 2025
@ESP-Marius
Copy link
Collaborator

I think this looks like problem on our side. I suspect the log where it crashes happens when cache is disabled, but write_lock_acquire wasn't inlined and ended up in flash, which is not accessible.

If in components/esp_system/port/usb_console.c you replace inline with inline __attribute__((always_inline)) for both write_lock_acquire and write_lock_release (remember to choose correct ones, i.e. the ones used when CONFIG_ESP_CONSOLE_USB_CDC_SUPPORT_ETS_PRINTF is enabled), does this solve your issue?

@Tobi177
Copy link
Author

Tobi177 commented Jan 17, 2025

If I changed from "inline" to "attribute((always_inline))" the device is not starting anymore on the Win11 host system and therefore I do not get any output. It seems the functions "write_lock_acquire" and "write_lock_release" are releated to "CONFIG_ESP_CONSOLE_USB_CDC_SUPPORT_ETS_PRINTF" only. Please notice, that I enable the option "CONFIG_ESP_CONSOLE_USB_CDC_SUPPORT_ETS_PRINTF" only to get the error messages. Usually, I do not enable this option, so I do not think the inline declarations can solve this issue.

I just see, that the bootloader was not on verbose level. The following is the boot process which crash in verbose mode:

Rebooting...
I (52) boot: ESP-IDF v5.3.2 2nd stage bootloader
I (52) boot: compile time Jan 16 2025 21:31:17
D (52) bootloader_flash: XMC chip detected by RDID (00204016), skip.
D (55) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (57) boot: chip revision: v1.0
I (57) boot: efuse block revision: v0.2
D (58) qio_mode: Probing for QIO mode enable...
D (59) qio_mode: Raw SPI flash chip id 0x204016
D (60) qio_mode: Manufacturer ID 0x20 chip ID 0x4016
I (62) qio_mode: Enabling default flash chip QIO
D (63) qio_mode: Initial flash chip status 0x2
D (64) qio_mode: QIO mode already enabled in flash
D (65) qio_mode: Enabling QIO mode...
D (68) boot.esp32s2: magic e9
D (69) boot.esp32s2: segments 04
D (70) boot.esp32s2: spi_mode 02
D (71) boot.esp32s2: spi_speed 0f
D (73) boot.esp32s2: spi_size 02
I (74) boot.esp32s2: SPI Speed      : 80MHz
I (75) boot.esp32s2: SPI Mode       : QIO
I (76) boot.esp32s2: SPI Flash Size : 4MB
D (78) boot: Enabling RTCWDT(9000 ms)
I (79) boot: Enabling RNG early entropy source...
D (80) bootloader_flash: rodata starts from paddr=0x0000e000, size=0xc00, will be mapped to vaddr=0x3f000000
V (83) bootloader_flash: after mapping, starting from paddr=0x00000000 and vaddr=0x3f000000, 0x10000 bytes are mapped
D (84) boot: mapped partition table 0xe000 at 0x3f00e000
D (84) flash_parts: partition table verified, 7 entries
I (86) boot: Partition Table:
I (87) boot: ## Label            Usage          Type ST Offset   Length
D (89) boot: load partition table entry 0x3f00e000
D (90) boot: type=1 subtype=2
I (91) boot:  0 nvs              WiFi data        01 02 0000f000 00008000
D (93) boot: load partition table entry 0x3f00e020
D (93) boot: type=1 subtype=4
I (94) boot:  1 nvs_keys         NVS keys         01 04 00017000 00001000
D (96) boot: load partition table entry 0x3f00e040
D (96) boot: type=1 subtype=0
I (97) boot:  2 otadata          OTA data         01 00 00018000 00002000
D (101) boot: load partition table entry 0x3f00e060
D (101) boot: type=0 subtype=10
I (102) boot:  3 app0             OTA app          00 10 00020000 001e0000
D (104) boot: load partition table entry 0x3f00e080
D (104) boot: type=0 subtype=11
I (106) boot:  4 app1             OTA app          00 11 00200000 001e0000
D (108) boot: load partition table entry 0x3f00e0a0
D (109) boot: type=1 subtype=3
I (111) boot:  5 coredump         Unknown data     01 03 003e0000 00010000
I (114) boot: End of partition table
D (114) boot: OTA data offset 0x18000
D (116) bootloader_flash: rodata starts from paddr=0x00018000, size=0x2000, will be mapped to vaddr=0x3f000000
V (118) bootloader_flash: after mapping, starting from paddr=0x00010000 and vaddr=0x3f000000, 0x10000 bytes are mapped
D (120) boot: otadata[0]: sequence values 0x00000001
D (120) boot: otadata[1]: sequence values 0xffffffff
I (122) boot: Enabled a check secure version of app for anti rollback
D (124) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
I (124) boot: Secure version (from eFuse) = 0
D (126) bootloader_flash: rodata starts from paddr=0x00020000, size=0x120, will be mapped to vaddr=0x3f000000
V (129) bootloader_flash: after mapping, starting from paddr=0x00020000 and vaddr=0x3f000000, 0x10000 bytes are mapped
D (130) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (131) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (133) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (135) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (137) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (138) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (139) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (141) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (143) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (144) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (146) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (147) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (149) boot_comm: Only otadata[0] is valid
D (149) boot: Active otadata[0]
D (151) boot: Mapping seq 0 -> OTA slot 0
D (152) bootloader_flash: rodata starts from paddr=0x00020000, size=0x120, will be mapped to vaddr=0x3f000000
V (155) bootloader_flash: after mapping, starting from paddr=0x00020000 and vaddr=0x3f000000, 0x10000 bytes are mapped
D (158) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (159) boot: Trying partition index 0 offs 0x20000 size 0x1e0000
D (160) bootloader_flash: rodata starts from paddr=0x00020000, size=0x120, will be mapped to vaddr=0x3f000000
V (161) bootloader_flash: after mapping, starting from paddr=0x00020000 and vaddr=0x3f000000, 0x10000 bytes are mapped
D (163) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (164) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (166) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (168) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (169) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (171) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (172) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (174) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (176) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (177) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (178) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (180) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (182) esp_image: reading image header @ 0x20000
D (182) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
D (185) esp_image: image header: 0xe9 0x08 0x02 0x02 400253c8
V (186) esp_image: loading segment header 0 at offset 0x20018
V (187) esp_image: segment data length 0x3100c data starts 0x20020
V (190) esp_image: segment 0 map_segment 1 segment_data_offs 0x20020 load_addr 0x3f000020
I (192) esp_image: segment 0: paddr=00020020 vaddr=3f000020 size=3100ch (200716) map
D (193) esp_image: free data page_count 0x00000038
D (193) bootloader_flash: rodata starts from paddr=0x00020020, size=0x3100c, will be mapped to vaddr=0x3f000000
V (195) bootloader_flash: after mapping, starting from paddr=0x00020000 and vaddr=0x3f000000, 0x40000 bytes are mapped
D (197) esp_image: additional anti-rollback check 0x20020
V (238) esp_image: loading segment header 1 at offset 0x5102c
D (239) bootloader_flash: mmu set block paddr=0x00050000 (was 0xffffffff)
V (240) esp_image: segment data length 0x4 data starts 0x51034
V (241) esp_image: segment 1 map_segment 0 segment_data_offs 0x51034 load_addr 0x3ff9e040
I (244) esp_image: segment 1: paddr=00051034 vaddr=3ff9e040 size=00004h (     4) load
D (245) esp_image: free data page_count 0x00000038
D (245) bootloader_flash: rodata starts from paddr=0x00051034, size=0x4, will be mapped to vaddr=0x3f000000
V (247) bootloader_flash: after mapping, starting from paddr=0x00050000 and vaddr=0x3f000000, 0x10000 bytes are mapped
V (248) esp_image: loading segment header 2 at offset 0x51038
D (250) bootloader_flash: mmu set block paddr=0x00050000 (was 0xffffffff)
V (252) esp_image: segment data length 0x41dc data starts 0x51040
V (254) esp_image: segment 2 map_segment 0 segment_data_offs 0x51040 load_addr 0x3ffcaa50
I (255) esp_image: segment 2: paddr=00051040 vaddr=3ffcaa50 size=041dch ( 16860) load
D (256) esp_image: free data page_count 0x00000038
D (256) bootloader_flash: rodata starts from paddr=0x00051040, size=0x41dc, will be mapped to vaddr=0x3f000000
V (260) bootloader_flash: after mapping, starting from paddr=0x00050000 and vaddr=0x3f000000, 0x10000 bytes are mapped
V (266) esp_image: loading segment header 3 at offset 0x5521c
D (267) bootloader_flash: mmu set block paddr=0x00050000 (was 0xffffffff)
V (269) esp_image: segment data length 0xadf4 data starts 0x55224
V (270) esp_image: segment 3 map_segment 0 segment_data_offs 0x55224 load_addr 0x40024000
--- 0x40024000: _WindowOverflow4 at /home/tobi/esp/esp-idf/components/xtensa/xtensa_vectors.S:2027

I (272) esp_image: segment 3: paddr=00055224 vaddr=40024000 size=0adf4h ( 44532) load
D (273) esp_image: free data page_count 0x00000038
D (273) bootloader_flash: rodata starts from paddr=0x00055224, size=0xadf4, will be mapped to vaddr=0x3f000000
V (276) bootloader_flash: after mapping, starting from paddr=0x00050000 and vaddr=0x3f000000, 0x20000 bytes are mapped
V (290) esp_image: loading segment header 4 at offset 0x60018
D (291) bootloader_flash: mmu set block paddr=0x00060000 (was 0xffffffff)
V (292) esp_image: segment data length 0xbb4ac data starts 0x60020
V (295) esp_image: segment 4 map_segment 1 segment_data_offs 0x60020 load_addr 0x40080020
--- 0x40080020: _stext at ??:?

I (297) esp_image: segment 4: paddr=00060020 vaddr=40080020 size=bb4ach (767148) map
D (298) esp_image: free data page_count 0x00000038
D (298) bootloader_flash: rodata starts from paddr=0x00060020, size=0xbb4ac, will be mapped to vaddr=0x3f000000
V (300) bootloader_flash: after mapping, starting from paddr=0x00060000 and vaddr=0x3f000000, 0xc0000 bytes are mapped
V (458) esp_image: loading segment header 5 at offset 0x11b4cc
D (459) bootloader_flash: mmu set block paddr=0x00110000 (was 0xffffffff)
V (460) esp_image: segment data length 0xbc58 data starts 0x11b4d4
V (462) esp_image: segment 5 map_segment 0 segment_data_offs 0x11b4d4 load_addr 0x4002edf4
--- 0x4002edf4: esp_usb_console_before_restart at /home/tobi/esp/esp-idf/components/esp_system/port/usb_console.c:227

I (464) esp_image: segment 5: paddr=0011b4d4 vaddr=4002edf4 size=0bc58h ( 48216) load
D (466) esp_image: free data page_count 0x00000038
D (466) bootloader_flash: rodata starts from paddr=0x0011b4d4, size=0xbc58, will be mapped to vaddr=0x3f000000
V (468) bootloader_flash: after mapping, starting from paddr=0x00110000 and vaddr=0x3f000000, 0x20000 bytes are mapped
V (482) esp_image: loading segment header 6 at offset 0x12712c
D (483) bootloader_flash: mmu set block paddr=0x00120000 (was 0xffffffff)
V (485) esp_image: segment data length 0x40 data starts 0x127134
V (486) esp_image: segment 6 map_segment 0 segment_data_offs 0x127134 load_addr 0x40070000
I (487) esp_image: segment 6: paddr=00127134 vaddr=40070000 size=00040h (    64) load
D (488) esp_image: free data page_count 0x00000038
D (488) bootloader_flash: rodata starts from paddr=0x00127134, size=0x40, will be mapped to vaddr=0x3f000000
V (492) bootloader_flash: after mapping, starting from paddr=0x00120000 and vaddr=0x3f000000, 0x10000 bytes are mapped
V (494) esp_image: loading segment header 7 at offset 0x127174
D (495) bootloader_flash: mmu set block paddr=0x00120000 (was 0xffffffff)
V (497) esp_image: segment data length 0x4 data starts 0x12717c
V (499) esp_image: segment 7 map_segment 0 segment_data_offs 0x12717c load_addr 0x50000000
I (501) esp_image: segment 7: paddr=0012717c vaddr=50000000 size=00004h (     4) load
D (502) esp_image: free data page_count 0x00000038
D (502) bootloader_flash: rodata starts from paddr=0x0012717c, size=0x4, will be mapped to vaddr=0x3f000000
V (504) bootloader_flash: after mapping, starting from paddr=0x00120000 and vaddr=0x3f000000, 0x10000 bytes are mapped
V (505) esp_image: image start 0x00020000 end of last section 0x00127180
D (507) bootloader_flash: mmu set block paddr=0x00120000 (was 0xffffffff)
D (508) boot: Calculated hash: 69608deb7f98bbaac920422d8d1ac136fd5bb5389f04b63afea67bbdee29d9e3
D (520) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (521) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
D (523) efuse: In EFUSE_BLK0__DATA4_REG is used 16 bits starting with 11 bit
I (525) boot: Loaded app from partition at offset 0x20000
I (528) boot: Checking flash encryption...
D (528) efuse: In EFUSE_BLK0__DATA2_REG is used 3 bits starting with 18 bit
D (531) efuse: In EFUSE_BLK0__DATA0_REG is used 1 bits starting with 4 bit
V (532) flash_encrypt: CRYPT_CNT 1, write protection 0
I (532) flash_encrypt: flash encryption is enabled (1 plaintext flashes left)
I (534) boot: Disabling RNG early entropy source...
D (534) boot: Mapping segment 0 as DROM
D (535) boot: Mapping segment 4 as IROM
D (536) boot: calling set_cache_and_start_app
D (537) boot: configure drom and irom and start
V (538) boot: rodata starts from paddr=0x00020020, vaddr=0x3f000020, size=0x3100c
V (540) boot: after mapping rodata, starting from paddr=0x00020000 and vaddr=0x3f000000, 0x40000 bytes are mapped
V (541) boot: mapped one page of the rodata, from paddr=0x00020000 and vaddr=0x3f000000, 0x10000 bytes are mapped
V (542) boot: text starts from paddr=0x00060020, vaddr=0x40080020, size=0xbb4ac
--- 0x40080020: _stext at ??:?

V (544) boot: after mapping text, starting from paddr=0x00060000 and vaddr=0x40080000, 0xc0000 bytes are mapped
D (546) boot: start: 0x400253c8
--- 0x400253c8: call_start_cpu0 at /home/tobi/esp/esp-idf/components/esp_system/port/cpu_start.c:393

D (818) cpu_start: calling init function: 0x40087f50 on core: 0
--- 0x40087f50: __esp_system_init_fn_init_newlib_stdio at /home/tobi/esp/esp-idf/components/newlib/newlib_init.c:207

D (820) cpu_start: calling init function: 0x40088404 on core: 0
--- 0x40088404: __esp_system_init_fn_init_pthread at /home/tobi/esp/esp-idf/components/pthread/pthread.c:76

D (821) cpu_start: calling init function: 0x40084854 on core: 0
--- 0x40084854: __esp_system_init_fn_init_flash at /home/tobi/esp/esp-idf/components/esp_system/startup_funcs.c:88

Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40137930: f01d8713 81004136 08e086d6
--- 0x40137930: esp_get_idf_version at /home/tobi/esp/esp-idf/components/esp_system/port/esp_system_chip.c:88

Core  0 register dump:
PC      : 0x40137936  PS      : 0x00060d30  A0      : 0x8002f0c1  A1      : 0x3fffdff0
--- 0x40137936: write_lock_acquire at /home/tobi/esp/esp-idf/components/esp_system/port/usb_console.c:460

A2      : 0x3fffe020  A3      : 0x00000001  A4      : 0x02000006  A5      : 0x00000005
A6      : 0x0000000a  A7      : 0x3fffe020  A8      : 0x8002f03c  A9      : 0x3fffe0a0
A10     : 0x00000001  A11     : 0x00000001  A12     : 0x00060720  A13     : 0x00000000
A14     : 0x00000000  A15     : 0x00000000  SAR     : 0x00000008  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x00060720  LEND    : 0x00000000  LCOUNT  : 0x40027230
--- 0x40027230: _xt_handle_exc at /home/tobi/esp/esp-idf/components/xtensa/xtensa_vectors.S:739



Backtrace: 0x40137933:0x3fffdff0 0x4002f0be:0x3fffe010 0x4000f985:0x3fffe050 0x4000fde9:0x3fffe070 0x4000ff21:0x3fffe0f0 0x400394ee:0x3fffe140 0x4002805a:0x3fffe180 0x400a4b15:0x3fffe1b0 0x4002813b:0x3fffe1d0 0x400a4bc5:0x3fffe200 0x4008485a:0x3fffe260 0x40084764:0x3fffe280 0x4008479d:0x3fffe2a0 0x400847e3:0x3fffe2c0 0x40025566:0x3fffe2e0 0x40050174:0x3fffe320 0x4005030f:0x3fffe370--- 0x40137933: esp_get_idf_version at /home/tobi/esp/esp-idf/components/esp_system/port/esp_system_chip.c:88
0x4002f0be: esp_usb_console_write_char at /home/tobi/esp/esp-idf/components/esp_system/port/usb_console.c:456
0x4000f985: ets_write_char in ROM
0x4000fde9: ets_vprintf in ROM
0x4000ff21: ets_printf in ROM
0x400394ee: memspi_host_read_id_hs at /home/tobi/esp/esp-idf/components/spi_flash/memspi_host_driver.c:102 (discriminator 1)
0x4002805a: read_id_core at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_api.c:424
0x400a4b15: esp_flash_read_chip_id at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_api.c:442
0x4002813b: esp_flash_init_main at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_api.c:351
0x400a4bc5: esp_flash_init_default_chip at /home/tobi/esp/esp-idf/components/spi_flash/esp_flash_spi_init.c:398
0x4008485a: __esp_system_init_fn_init_flash at /home/tobi/esp/esp-idf/components/esp_system/startup_funcs.c:94
0x40084764: do_system_init_fn at /home/tobi/esp/esp-idf/components/esp_system/startup.c:127
0x4008479d: do_core_init at /home/tobi/esp/esp-idf/components/esp_system/startup.c:165
0x400847e3: start_cpu0_default at /home/tobi/esp/esp-idf/components/esp_system/startup.c:198
0x40025566: call_start_cpu0 at /home/tobi/esp/esp-idf/components/esp_system/port/cpu_start.c:842 (discriminator 1)

 0x4004a2cd:0x3fffe4a0 0x40011371:0x3fffe560 0x4000f788:0x3fffe6f0 0x400072a5:0x3fffe710




ELF file SHA256: 199f6502f
--- 0x40011371: ets_run_flash_bootloader in ROM
0x4000f788: main in ROM
0x400072a5: _start in ROM

This was working for weeks, it have to be related to the updates of the operating systems. But, I do not why. I will try to setup a ESP32-C2 and check if the inbuilt CDC is still working for this device class.

@Tobi177
Copy link
Author

Tobi177 commented Jan 18, 2025

I was able to solve this issue. My sdkconfig configuration had CDC enabled, but the option "CONFIG_ESP32S2_KEEP_USB_ALIVE" was disabled. This option needs to be active and should be setup automatically - accordingly to the docs. I have no clue, how I was able to bring the sdkconfig in this inconsistent state. Maybe my sdkconfig was from v5.1 branch and not up-to-date. I have rebuild thre sdkconfig completely new with set-target and all is working fine again.

I think that the USB interface power was not keep alive and then the access to the flash memory failed during boot process. However, this is just a guess.

@Tobi177
Copy link
Author

Tobi177 commented Jan 18, 2025

Additionally information: It seems the real problem was the option "CONFIG_SPIRAM_USE_MALLOC=y". With this option enabled, my apps are crashing (=CDC not booting). I am running arduino as component and mixing C++ with C/ESP-IDF - maybe this could be the problem with malloc. I switched to "SPIRAM_USE_CAPS_ALLOC" which is enough for me and all is working again! Unfortunately, I had setup "SPIRAM_USE_CAPS_ALLOC" within my sdkconfig.defaults and this gets me into trouble while creating the new sdkconfig.

Well, this was a tricky one - costs me a couple of days! Maybe this information helps!

@Tobi177
Copy link
Author

Tobi177 commented Jan 18, 2025

And finally: You need to have a responsive bootloader, that cdc is recognized on Win11 (and properly other operating systems as well). If you use "BOOTLOADER_LOG_LEVEL_NONE" or "BOOTLOADER_LOG_LEVEL_ERROR" or "BOOTLOADER_LOG_LEVEL_WARN" your device might not be recognized. Just use "BOOTLOADER_LOG_LEVEL_INFO" to ensure you have output on the cdc interface.

Summarize:

  1. Ensure to have a new sdkconfig for the used esp-idf version
  2. If you experience crashes on startup, check "CONFIG_SPIRAM_USE_MALLOC".
  3. Ensure your bootloader is "talking" to the cdc interface. Just use "BOOTLOADER_LOG_LEVEL_INFO"!
  4. Maybe adapt the logging level of your app to info as well.

Well, all this steps are important and now this issue is really solved! Hopefully this information is useful for someone!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Opened Issue is new Type: Bug bugs in IDF
Projects
None yet
Development

No branches or pull requests

3 participants