esp32c6: Waiting for download _after_ flashing

[t-moe]

I have a esp32c6 here that I flash using the command espflash flash --monitor --flash-size 8mb --partition-table ./partitions.csv <elf>

Sometimes I have the situation that after flashing the monitor shows:

Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x4 (DOWNLOAD(USB/UART0/SDIO_FEI_FEO))
Saved PC:0x4080041e
0x4080041e - get_buffer_malloc
    at /tmp/backtrace-std/.embuild/espressif/esp-idf/master/components/spi_flash/spi_flash_os_func_app.c:193
waiting for download

Why is it still waiting for download? I have not pulled the strapping pin GPIO9 to low.

I have not yet found out when this happens exactly, but it seems to somehow depend on the firmware I flash...

[t-moe]

Minimal example // repro:

1. start with an erased esp32c6 (I'm using a esp32-c6-devkit-c1 v1.2 here)
2. Run cargo generate esp-rs/esp-idf-template to generate a hello world with std, based on idf v5.1.
3. Connect the target via JTAG USB. The pins are not connected to any external components, just a naked dev kit. (hook up the uart0 pins to the logic analyzer if you like)
4. Flash this to the target with espflash flash --monitor <elf> (flashproblems.elf.zip )
5. So far everything works and the monitor prints the hello world. I can also press CTRL+R, still works
6. Exit the monitor (from step 4), then run espflash monitor --no-stub

espflash shows:

espflash monitor --no-stub
.... (version check with crates.io)
[2024-01-22T12:54:31Z INFO ] Serial port: '/dev/ttyACM0'
[2024-01-22T12:54:31Z INFO ] Connecting...
[2024-01-22T12:54:31Z DEBUG] Attempting flash enable with: SpiAttachParams { clk: 0, q: 0, d: 0, hd: 0, cs: 0 }
[2024-01-22T12:54:31Z DEBUG] Flash detect OK!
Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

Error:   × Broken pipe

Logic analyzer started before step 6:

The first bunch of messages shows:

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0xc (SPI_FAST_FLASH_BOOT)
Saved PC:0x40802990
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
load:0x4086e610,len:0x2d68
load:0x40875720,len:0x1800
SHA-256 comparison failed:
Calculated: 377c26481ad6ab0cce508450f353a55f4bd7eb9159aaf85fde3111071f164514
Expected: 0af544a033ab3492852b8232c904c578d5f07c9d4a423a64473f060db374ab32
Attempting to boot anyway...
entry 0x4086c410
\x1B[0;32mI (41) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader\x1B[0m
\x1B[0;32mI (42) boot: compile time Jun  7 2023 08:02:08\x1B[0m
\x1B[0;32mI (43) boot: chip revision: v0.0\x1B[0m
\x1B[0;32mI (46) boot.esp32c6: SPI Speed      : 40MHz\x1B[0m
\x1B[0;32mI (51) boot.esp32c6: SPI Mode       : DIO\x1B[0m
\x1B[0;32mI (56) boot.esp32c6: SPI Flash Size : 8MB\x1B[0m
\x1B[0;32mI (60) boot: Enabling RNG early entropy source...\x1B[0m
\x1B[0;32mI (66) boot: Partition Table:\x1B[0m
\x1B[0;32mI (69) boot: ## Label            Usage          Type ST Offset   Length\x1B[0m
\x1B[0;32mI (77) boot:  0 nvs              WiFi data        01 02 00009000 00006000\x1B[0m
\x1B[0;32mI (84) boot:  1 phy_init         RF data          01 01 0000f000 00001000\x1B[0m
\x1B[0;32mI (92) boot:  2 factory          factory app      00 00 00010000 007f0000\x1B[0m
\x1B[0;32mI (99) boot: End of partition table\x1B[0m
\x1B[0;32mI (103) esp_image: segment 0: paddr=00010020 vaddr=42000020 size=413f4h (267252) map\x1B[0m
\x1B[0;32mI (166) esp_image: segment 1: paddr=0005141c vaddr=40800000 size=06bfch ( 27644) load\x1B[0m
\x1B[0;32mI (174) esp_image: segment 2: paddr=00058020 vaddr=42048020 size=1da78h (121464) map\x1B[0m
\x1B[0;32mI (\xFFESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x4 (DOWNLOAD(USB/UART0/SDIO_FEI_FEO))
Saved PC:0x4001a36e
waiting for download

then there is a 8 second delay, during which espflash says "broken pipe".
then the board boots up normally with:

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x10 (LP_WDT_SYS),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
load:0x4086e610,len:0x2d68
load:0x40875720,len:0x1800
SHA-256 comparison failed:
Calculated: 377c26481ad6ab0cce508450f353a55f4bd7eb9159aaf85fde3111071f164514
Expected: 0af544a033ab3492852b8232c904c578d5f07c9d4a423a64473f060db374ab32
Attempting to boot anyway...
entry 0x4086c410
\x1B[0;32mI (42) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader\x1B[0m
\x1B[0;32mI (43) boot: compile time Jun  7 2023 08:02:08\x1B[0m
\x1B[0;32mI (44) boot: chip revision: v0.0\x1B[0m
\x1B[0;32mI (47) boot.esp32c6: SPI Speed      : 40MHz\x1B[0m
\x1B[0;32mI (52) boot.esp32c6: SPI Mode       : DIO\x1B[0m
\x1B[0;32mI (57) boot.esp32c6: SPI Flash Size : 8MB\x1B[0m
\x1B[0;32mI (62) boot: Enabling RNG early entropy source...\x1B[0m
\x1B[0;32mI (67) boot: Partition Table:\x1B[0m
\x1B[0;32mI (71) boot: ## Label            Usage          Type ST Offset   Length\x1B[0m
\x1B[0;32mI (78) boot:  0 nvs              WiFi data        01 02 00009000 00006000\x1B[0m
\x1B[0;32mI (85) boot:  1 phy_init         RF data          01 01 0000f000 00001000\x1B[0m
\x1B[0;32mI (93) boot:  2 factory          factory app      00 00 00010000 007f0000\x1B[0m
\x1B[0;32mI (100) boot: End of partition table\x1B[0m
\x1B[0;32mI (105) esp_image: segment 0: paddr=00010020 vaddr=42000020 size=413f4h (267252) map\x1B[0m
\x1B[0;32mI (167) esp_image: segment 1: paddr=0005141c vaddr=40800000 size=06bfch ( 27644) load\x1B[0m
\x1B[0;32mI (175) esp_image: segment 2: paddr=00058020 vaddr=42048020 size=1da78h (121464) map\x1B[0m
\x1B[0;32mI (200) esp_image: segment 3: paddr=00075aa0 vaddr=40806bfc size=0193ch (  6460) load\x1B[0m
\x1B[0;32mI (207) esp_image: segment 4: paddr=000773e4 vaddr=40808540 size=00fcch (  4044) load\x1B[0m
\x1B[0;32mI (211) boot: Loaded app from partition at offset 0x10000\x1B[0m
\x1B[0;32mI (212) boot: Disabling RNG early entropy source...\x1B[0m
\x1B[0;32mI (229) cpu_start: Unicore app\x1B[0m
\x1B[0;32mI (229) cpu_start: Pro cpu up.\x1B[0m
\x1B[0;33mW (238) clk: esp_perip_clk_init() has not been implemented yet\x1B[0m
\x1B[0;32mI (244) cpu_start: Pro cpu start user code\x1B[0m
\x1B[0;32mI (244) cpu_start: cpu freq: 160000000 Hz\x1B[0m
\x1B[0;32mI (245) cpu_start: Application information:\x1B[0m
\x1B[0;32mI (247) cpu_start: Project name:     libespidf\x1B[0m
\x1B[0;32mI (252) cpu_start: App version:      1\x1B[0m
\x1B[0;32mI (257) cpu_start: Compile time:     Jan 22 2024 13:37:02\x1B[0m
\x1B[0;32mI (263) cpu_start: ELF file SHA256:  0000000000000000...\x1B[0m
\x1B[0;32mI (269) cpu_start: ESP-IDF:          v5.1\x1B[0m
\x1B[0;32mI (274) cpu_start: Min chip rev:     v0.0\x1B[0m
\x1B[0;32mI (278) cpu_start: Max chip rev:     v0.99 \x1B[0m
\x1B[0;32mI (283) cpu_start: Chip rev:         v0.0\x1B[0m
\x1B[0;32mI (288) heap_init: Initializing. RAM available for dynamic allocation:\x1B[0m
\x1B[0;32mI (295) heap_init: At 4080A430 len 000721E0 (456 KiB): D/IRAM\x1B[0m
\x1B[0;32mI (301) heap_init: At 4087C610 len 00002F54 (11 KiB): STACK/DIRAM\x1B[0m
\x1B[0;32mI (308) heap_init: At 50000010 len 00003FF0 (15 KiB): RTCRAM\x1B[0m
\x1B[0;32mI (315) spi_flash: detected chip: generic\x1B[0m
\x1B[0;32mI (319) spi_flash: flash io: dio\x1B[0m
\x1B[0;33mW (323) timer_group: legacy driver is deprecated, please migrate to `driver/gptimer.h`\x1B[0m
\x1B[0;32mI (335) sleep: Configure to isolate all GPIO pins in sleep state\x1B[0m
\x1B[0;32mI (339) sleep: Enable automatic switching of GPIO sleep configuration\x1B[0m
\x1B[0;32mI (346) coexist: coex firmware version: ebddf30\x1B[0m
\x1B[0;32mI (351) coexist: coexist rom version 5b8dcfa\x1B[0m
\x1B[0;32mI (356) app_start: Starting scheduler on CPU0\x1B[0m
\x1B[0;32mI (361) main_task: Started on CPU0\x1B[0m
\x1B[0;32mI (361) main_task: Calling app_main()\x1B[0m
\x1B[0;32mI (361) flashproblems: Hello, world!\x1B[0m
\x1B[0;32mI (371) main_task: Returned from app_main()\x1B[0m

If I'm doing espflash monitor (using stub), I don't get the broken pipe, but the target also hangs at "waiting for download" (it does not reset after 8 seconds though)

I'm on ubuntu 22.04 and I'm using espflash 2.1.0 (although it is the same with espflash from git (master))

[t-moe]

I've also tried to use the esp idf provided bootloader, e.g. flash with espflash flash --bootloader target/riscv32imac-esp-espidf/debug/build/esp-idf-sys-7af63acd3e33c9a6/out/build/bootloader/bootloader.bin --monitor target/riscv32imac-esp-espidf/debug/flashproblems

for v5.1.1: same problem.
for v5.2-beta2: same problem.

EDIT:

• power cycling the board does not help.
• but using idf.py monitor (from idf master branch) instead of espflash monitor works.
• I've tried this with two different boards.
• Connecting to the target via Uart (Silabs converter in between), does also not fix this.
• (I'm not connect to a USB hub. the target is directly attached to my laptop)
• Using a esp-hal based (no-std) example, does also not work

[SergioGasquez]

Just tried reproducing the error and I was not able to reproduce it:

[t-moe]

Thanks for trying to reproduce this @SergioGasquez .
I can also not reproduce this reliably. There are times where this issue occurs constantly and then there are times where it does not occur for hours/days.
I'll keep this issue open for a while and try to add more info, as soon as the issue occurs again.

[t-moe]

At least in this case here, it is not the cable: I've just had another occurrence with a new chip + new cable.

The fact that idf.py monitor works in this case, hints that this is some sort of timing issue...

[SergioGasquez]

Just as an experiment, could you try the following?

cargo install espflash --git https://github.com/SergioGasquez/espflash --branch feat/reset-args
espflash monitor --before no-reset-no-sync --chip esp32c6

[csgordon]

I'm just dropping in here to say I have seen what seems to be the same issue with my new esp32c6. With a fresh minimal esp-template project:

$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.39s
     Running `espflash flash --monitor target/riscv32imac-unknown-none-elf/debug/exp3`
[2024-01-31T18:43:17Z INFO ] Detected 6 serial ports
[2024-01-31T18:43:17Z INFO ] Ports which match a known common dev board are highlighted
[2024-01-31T18:43:17Z INFO ] Please select a port
✔ Remember this serial port for future use? · no
[2024-01-31T18:43:19Z INFO ] Serial port: '/dev/cu.usbmodem141401'
[2024-01-31T18:43:19Z INFO ] Connecting...
[2024-01-31T18:43:20Z INFO ] Using flash stub
Chip type:         esp32c6 (revision v0.0)
Crystal frequency: 40MHz
Flash size:        8MB
Features:          WiFi 6, BT 5
MAC address:       40:4c:ca:4e:6a:28
App/part. size:    202,480/8,323,072 bytes, 2.43%
[00:00:00] [========================================]      13/13      0x0
[00:00:00] [========================================]       1/1       0x8000
[00:00:01] [========================================]      79/79      0x10000                                                                                                      [2024-01-31T18:43:21Z INFO ] Flashing has completed!
Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x4 (DOWNLOAD(USB/UART0/SDIO_FEI_FEO))
Saved PC:0x408007fe
0x408007fe - core::option::Option<T>::unwrap
    at /Users/<user>/.rustup/toolchains/nightly-x86_64-apple-darwin/lib/rustlib/src/rust/library/core/src/option.rs:929
waiting for download

I don't have time right this moment, but I wanted to chime in and say there's at least one other occurrence. It looks like I should investigate updating the firmware and I'll try the suggested experiment, but I probably won't get to those until tomorrow.

[MabezDev]

I have seen this too, to reproduce my case:

1. Manually put the chip into download mode, hold boot whilst resetting the chip
2. flash it with espflash
3. Observe the rom download mode message

[csgordon]

Part of me was wondering if this might be a tooling configuration issue (until today I had not gotten any Rust to run on an esp32c6), and wondered if there was some weirdness in my macos setup. But it seems to not be the case.

My experience above was with a Waveshare ESP32-C6-DEV-KIT-N8, which is a custom package around a ESP32-C6-WROOM-1. It still exhibits this issue.

However, 20 minutes ago I received a delivery of a proper Espressif ESP32-C6-DevKitC-1, which also uses the ESP32-C6-WROOM-1. I popped it out of the box, plugged it in, ran cargo run, and it worked perfectly:

$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 7.03s
     Running `espflash flash --monitor target/riscv32imac-unknown-none-elf/debug/exp3`
[2024-02-01T21:08:07Z INFO ] Detected 4 serial ports
[2024-02-01T21:08:07Z INFO ] Ports which match a known common dev board are highlighted
[2024-02-01T21:08:07Z INFO ] Please select a port
[2024-02-01T21:08:15Z INFO ] Serial port: '/dev/cu.usbserial-1410'
[2024-02-01T21:08:15Z INFO ] Connecting...
[2024-02-01T21:08:15Z INFO ] Using flash stub
Chip type:         esp32c6 (revision v0.0)
Crystal frequency: 40MHz
Flash size:        8MB
Features:          WiFi 6, BT 5
MAC address:       40:4c:ca:51:39:7c
App/part. size:    202,480/8,323,072 bytes, 2.43%
[00:00:01] [========================================]      13/13      0x0
[00:00:00] [========================================]       1/1       0x8000
[00:00:07] [========================================]      79/79      0x10000                                                                                                      [2024-02-01T21:08:25Z INFO ] Flashing has completed!
Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
0x4086c410 - _ESP_HAL_DEVICE_PERIPHERALS
    at ??:??
load:0x4086e610,len:0x2d68
0x4086e610 - _ESP_HAL_DEVICE_PERIPHERALS
    at ??:??
load:0x40875720,len:0x1800
0x40875720 - _ESP_HAL_DEVICE_PERIPHERALS
    at ??:??
SHA-256 comparison failed:
Calculated: 377c26481ad6ab0cce508450f353a55f4bd7eb9159aaf85fde3111071f164514
Expected: 0af544a033ab3492852b8232c904c578d5f07c9d4a423a64473f060db374ab32
Attempting to boot anyway...
entry 0x4086c410
0x4086c410 - _ESP_HAL_DEVICE_PERIPHERALS
    at ??:??
I (42) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader
I (42) boot: compile time Jun  7 2023 08:02:08
I (43) boot: chip revision: v0.0
I (47) boot.esp32c6: SPI Speed      : 40MHz
I (52) boot.esp32c6: SPI Mode       : DIO
I (57) boot.esp32c6: SPI Flash Size : 8MB
I (61) boot: Enabling RNG early entropy source...
I (67) boot: Partition Table:
I (70) boot: ## Label            Usage          Type ST Offset   Length
I (78) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (85) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (92) boot:  2 factory          factory app      00 00 00010000 007f0000
I (100) boot: End of partition table
I (104) esp_image: segment 0: paddr=00010020 vaddr=42000020 size=28ab4h (166580) map
I (147) esp_image: segment 1: paddr=00038adc vaddr=40800000 size=0001ch (    28) load
I (147) esp_image: segment 2: paddr=00038b00 vaddr=42028b00 size=078f4h ( 30964) map
I (159) esp_image: segment 3: paddr=000403fc vaddr=4080001c size=012c4h (  4804) load
I (162) boot: Loaded app from partition at offset 0x10000
I (167) boot: Disabling RNG early entropy source...
INFO - Logger is setup
Hello world!
Loop...
Loop...
Loop...
Loop...
<you get the idea>

My new (working) board has the same ESP-ROM and Build date as the one that doesn't work.

For completeness, I'll mention that the espflash board-info reports the exact same for both boards aside from the MAC (below happens to be for the Espressif kit):

$ espflash board-info
[2024-02-01T21:10:43Z INFO ] Detected 4 serial ports
[2024-02-01T21:10:43Z INFO ] Ports which match a known common dev board are highlighted
[2024-02-01T21:10:43Z INFO ] Please select a port
[2024-02-01T21:10:45Z INFO ] Serial port: '/dev/cu.usbserial-1410'
[2024-02-01T21:10:45Z INFO ] Connecting...
[2024-02-01T21:10:45Z INFO ] Using flash stub
Chip type:         esp32c6 (revision v0.0)
Crystal frequency: 40MHz
Flash size:        8MB
Features:          WiFi 6, BT 5
MAC address:       ...

[t-moe]

I dont think this is hardware related.
I had the issue occur with various boards (also different types) and then again it does not appear for days on the exact same hardware. Also, if I remember correctly, idf.py monitor always works, even if espflash monitor fails.

This looks like some timing issue to me...

Without having looked at the source, I imagine there is a memory location or register which tells the first stage bootloader to stay in bootloader mode after reset and do not continue with the normal boot process (so that you can send more commands to it). Can it be that theres old data in this location/register? Just guessing here...

[t-moe]

Just as an experiment, could you try the following?

cargo install espflash --git https://github.com/SergioGasquez/espflash --branch feat/reset-args
espflash monitor --before no-reset-no-sync --chip esp32c6

RUST_LOG=debug espflash flash --monitor target/riscv32imac-unknown-none-elf/debug/esp32_hw_3_0  --before no-reset-no-sync --chip esp32c6
...(Debug messages of crates.io version checking ommited)
[2024-02-05T16:31:24Z WARN ] Pre-connection option 'NoResetNoSync' was selected. Connection may fail if the chip is not in bootloader or flasher stub mode.
[2024-02-05T16:31:24Z INFO ] Serial port: '/dev/ttyACM0'
[2024-02-05T16:31:24Z INFO ] Connecting...
[2024-02-05T16:31:24Z DEBUG] Writing command: ReadReg { address: 1611335768 }
Error: espflash::timeout

  × Error while connecting to device
  ╰─▶ Timeout while running ReadReg command

[Vollbrecht]

does this timeout behavior persist after a cold boot? I also saw it multiple times with current HEAD, even after cold boot, i could only got the timeout cleared by manually forcing it into download mode, but not via cold boot, indicating that it didn't reset the esp correctly after a attach.