espflash::timeout on esp32c6 via JTAG uart

[t-moe]

I'm using espflash master to flash a esp-idf-* (master) project with espflash to a esp32c6.

espflash flash --monitor <ELF>
[2024-01-22T08:43:49Z INFO ] Serial port: '/dev/ttyACM0'
[2024-01-22T08:43:49Z INFO ] Connecting...
[2024-01-22T08:43:49Z INFO ] Using flash stub
Error: espflash::timeout

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

Some more debug output of espflash

[2024-01-22T08:43:36Z DEBUG] Finish stub write
[2024-01-22T08:43:36Z DEBUG] Writing command: MemEnd { no_entry: false, entry: 1082130432 }
[2024-01-22T08:43:36Z DEBUG] Stub written!
[2024-01-22T08:43:36Z DEBUG] Writing command: ReadReg { address: 1073745920 }
Error: espflash::timeout

I've recompiled the stubs with dprint enabled, and I get the following output from the stub:

Stub init! Transport detected: UsbSerialJtag
Stub sending greeting!
Waiting for command

I've also slightly modified src/flasher/mod.rs (espflash)

         debug!("Stub written!");

         match self.connection.read(EXPECTED_STUB_HANDSHAKE.len())? {
             Some(resp) if resp == EXPECTED_STUB_HANDSHAKE.as_bytes() => Ok(()),
             _ => Err(Error::Connection(ConnectionError::InvalidStubHandshake)),
         }?;

+        debug!("Handshake ok");
+        std::thread::sleep(Duration::from_secs(3));
+
         // Re-detect chip to check stub is up
         let magic = self.connection.read_reg(CHIP_DETECT_MAGIC_REG_ADDR)?;
         let chip = Chip::from_magic(magic)?;
         debug!("Re-detected chip: {:?}", chip);

         Ok(())

It seems the handshake is written, but then the chip redetect fails.

When I flash the same binary via Uart0 instead of USB JTAG, it works...

[t-moe]

I'm still trying to reproduce this reliably. This issue here appears at random, and when it appears, it persists until ??. Same goes for esp-rs/espflash#556, which also appears at random and then persists until ??.

Not sure what ?? actually is. Maybe:

• erase the flash
• power cycle the chip
• put the chip into bootloader mode manually
• flash a different firmware
• or a combination of the above

Investigating....

[SergioGasquez]

Can you try using --no-stub and see if the issue persists?

[t-moe]

I can confirm that it flashes + boots as expected with --no-stub. That is, given I get past the "waiting for download" issue (esp-rs/espflash#556 )...

[SergioGasquez]

Just moved the issue to esp-flasher-stub as it seems to be a stub issue, will take a look into esp-rs/espflash#556

[SergioGasquez]

I've tried reproducing this error with no success, maybe is something related with HW? Could you try using a different cable?

espflash is sending the command to detect the chip, but stub is not receiving it for some reason… and this seems to happen with C stubs (are the ones being used in espflash 2.1) and Rust stubs (being used in espflash main), so Im not really sure if this issue belongs here now.

Have you tried with esptool?

[t-moe]

Same here: 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, try with esptool + different cables, as soon as the issue occurs again.

[MabezDev]

It could be a similar error condition we reach in probe-rs: https://github.com/probe-rs/probe-rs/issues/1963#issuecomment-1913575783. Essentially a USB-JTAG-SERIAL reset isn't a real reset and some parts of the chip are left running, one of these could be the memory protection peripheral. Though, at first glance I can't see any similar workarounds in esptool.py 🤔.

[SergioGasquez]

Please, when trying to reproduce this issue in the future, use espflash v3.0.0 or greater, since the C6 stub was updated.

[turulix]

I'm facing the same issue in espflash v3.1.0 where flashing apparently works with --no-stub, but sometimes fails without it. It used to work fine in the beginning and then just randomly stopped working (I was playing around with Wi-Fi, but I don't think it's related to this). Flashing with esptool works fine without any issues.

I also noticed another issue where, when the monitor successfully connects using something like espflash monitor -c esp32c6 -b no-reset-no-sync, trying to reset the chip with CTRL+R doesn't work as expected.

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x1e (SPI_FAST_FLASH_BOOT)
Saved PC:0x408007fe
SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x181c
load:0x4086c110,len:0xe0c
load:0x4086e610,len:0x2e6c
entry 0x4086c11a
I (23) boot: ESP-IDF v5.3 2nd stage bootloader
I (23) boot: compile time Aug 10 2024 00:46:51
I (24) boot: chip revision: v0.1
I (26) boot.esp32c6: SPI Speed      : 40MHz
I (30) boot.esp32c6: SPI Mode       : DIO
I (35) boot.esp32c6: SPI Flash Size : 4MB
I (40) boot: Enabling RNG early entropy source...
I (45) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (56) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (71) boot:  2 factory          factory app      00 00 00010000 003f0000
I (79) boot: End of partition table
I (83) esp_image: segment 0: paddr=00010020 vaddr=42040020 size=109a8h ( 68008) map
I (108) esp_image: segment 1: paddr=000209d0 vaddr=40800000 size=095a8h ( 38312) load
I (119) esp_image: segment 2: paddr=00029f80 vaddr=408095b0 size=017c8h (  6088) load
I (122) esp_image: segment 3: paddr=0002b750 vaddr=00000000 size=048c8h ( 18632)
I (129) esp_image: segment 4: paddr=00030020 vaddr=42000020 size=3d1f0h (250352) map
I (197) boot: Loaded app from partition at offset 0x10000
I (198) boot: Disabling RNG early entropy source...
I (209) cpu_start: Unicore app
I (218) cpu_start: Pro cpu start user code
I (218) cpu_start: cpu freq: 160000000 Hz
I (218) app_init: Application information:
I (221) app_init: Project name:     libespidf
I (226) app_init: App version:      1
I (230) app_init: Compile time:     Aug 10 2024 01:34:21
I (236) app_init: ELF file SHA256:  000000000...
I (241) app_init: ESP-IDF:          v5.3
I (246) efuse_init: Min chip rev:     v0.0
I (251) efuse_init: Max chip rev:     v0.99
I (256) efuse_init: Chip rev:         v0.1
I (261) heap_init: Initializing. RAM available for dynamic allocation:
I (268) heap_init: At 4080BDB0 len 00070860 (450 KiB): RAM
I (274) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (280) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
I (288) spi_flash: detected chip: generic
I (291) spi_flash: flash io: dio
W (295) pcnt(legacy): legacy driver is deprecated, please migrate to `driESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x1e (SPI_FAST_FLASH_BOOT)
Saved PC:0x40022bc8
SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x181c
load:0x4086c110,len:0xe0c
load:0x4086e610,len:0x2e6c
entry 0x4086c11a
I (23) boot: ESP-IDF v5.3 2nd stage bootloader
I (23) boot: compile time Aug 10 2024 00:46:51
I (24) boot: chip revision: v0.1
I (26) boot.esp32c6: SPI Speed      : 40MHz
I (30) boot.esp32c6: SPI Mode       : DIO
I (35) boot.esp32c6: SPI Flash Size : 4MB
I (40) boot: Enabling RNG early entropy source...
I (45) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (56) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (71) boot:  2 factory          factory app      00 00 00010000 003f0000
I (79) boot: End of partition table
I (83) esp_image: segment 0: paddr=00010020 vaddr=42040020 size=109a8h ( 68008) map
I (108) esp_image: segment 1: paddr=000209d0 vaddr=40800000 size=095a8h ( 38312) load
I (119) esp_image: segment 2: paddr=00029f80 vaddr=408095b0 size=017c8h (  6088) load
I (122) esp_image: segment 3: paddr=0002b750 vaddr=00000000 size=048c8h ( 18632)
I (130) esp_image: segment 4: paddr=00030020 vaddr=42000020 size=3d1f0h (250352) map
I (197) boot: Loaded app from partition at offset 0x10000
I (198) boot: Disabling RNG early entropy source...
I (209) cpu_start: Unicore app
Error:   x The device does not recognize the command. (os error 22)

It seems to boot twice, but the second time it just stops. So maybe it has something to do with buggy restarts? Could that be causing the chip to fail to redetect? I don't really know much about this—just throwing out ideas.

One way I figured out how to fix this, at least temporarily, is to:

1. Manually set the chip into bootloader mode.
2. Erase all the flash with espflash erase-flash.
3. Reset the chip to exit bootloader mode (just pressing the Reset button on my XIAO ESP32C6).
4. Flash the chip using espflash flash --monitor.

This will cause everything to work fine (even the issue where it starts twice disappears and it stays connected without errors during resets) until I fully power cycle the chip. After that, it will return to the broken state where the connection times out. In this broken state, esptool still works fine to flash, while espflash does not.

Using espflash monitor -c esp32c6 -b no-reset-no-sync in this broken state and reseting the chip using CTRL+R results in the chip being stuck in a bootloop:

[2024-08-10T01:19:46Z WARN ] Pre-connection option 'NoResetNoSync' was selected. Connection may fail if the chip is not in bootloader or flasher stub mode.
[2024-08-10T01:19:46Z INFO ] Serial port: 'COM5'
[2024-08-10T01:19:46Z INFO ] Connecting...
Commands:
    CTRL+R    Reset chip
    CTRL+C    Exit

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x1e (SPI_FAST_FLASH_BOOT)
Saved PC:0x408015d0
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
load:0x4086e610,len:0x2d68
load:0x40875720,len:0x1800
entry 0x4086c410
ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x1e (SPI_FAST_FLASH_BOOT)
Saved PC:0x4086ed7a
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
load:0x4086e610,len:0x2d68
load:0x40875720,len:0x1800
entry 0x4086c410
ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x7 (TG0_WDT_HPSYS),boot:0x1e (SPI_FAST_FLASH_BOOT)
Saved PC:0x4086ed7a
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xd48
load:0x4086e610,len:0x2d68
load:0x40875720,len:0x1800
entry 0x4086c410