Timeout while running FlashDeflateData command

[hbhong]

My mcu is ESP32C3 with 16MB flash size, when I am running the following command to flash I got a timeout error

cargo espflash flash --release --partition-table ./default_16MB_one_ota.csv

the output:

[2023-06-21T14:06:50Z INFO ] Serial port: '/dev/ttyACM0'
[2023-06-21T14:06:50Z INFO ] Connecting...
[2023-06-21T14:06:51Z INFO ] Using flash stub
    Finished release [optimized] target(s) in 0.21s
Chip type:         esp32c3 (revision v0.3)
Crystal frequency: 40MHz
Flash size:        16MB
Features:          WiFi, BLE
MAC address:       60:55:f9:77:6d:6c
Bootloader:        /drn/RustProjects/pomodoro/target/riscv32imc-esp-espidf/release/build/esp-idf-sys-9c7a5783fe78fcfb/out/build/bootloader/bootloader.bin
Partition table:   ./default_16MB_one_ota.csv
App/part. size:    8,298,752/12,976,128 bytes, 63.95%
[00:00:01] [========================================]      13/13      0x0                                                                                                                                                                                                 
[00:00:00] [========================================]       1/1       0x8000                                                                                                                                                                                              
Error: espflash::timeout

  × Communication error while flashing device
  ╰─▶ Timeout while running FlashDeflateData command

here is my partition table file:

#Name,   Type, SubType, Offset,  Size, Flags
nvs,      data, nvs,     0x9000,  0x5000,
otadata,  data, ota,     0xe000,  0x2000,
app0,     app,  ota_0,   0x10000, 0xc60000,
spiffs,   data, spiffs,  0xc70000,0x370000,

I just found that when the size of my app is reduced, the program can be flashed successfully. However, when I add more codes, timeout issues occur.
I would greatly appreciate any suggestions or assistance you can provide！

[jessebraham]

Thank you for opening an issue, sorry that you're having issues.

Just out of curiosity, would you be able to share which version of espflash you are using as well as which development kit or board you are using? If you are not using the latest version of espflash (which is 2.0.0) then please try again using this version. I don't believe we offer an ESP32-C3 module with 16MB of flash, so it seems to me that this is some third-party offering.

This problem is reminiscent of a previous issue we faced where the watchdog timer was causing a reset, however this issue should have been resolved in a previous PR. However it's possible there is another issue which we had missed previously.

[hbhong]

@jessebraham Thank for your reply. My espflash is 2.0.0 version. and I'm using third-party development board, its default flash size is 4MB, because my app is a little bigger, so I replaced it with 16MB external flash.

[MabezDev]

@hbhong How long does it flash for before reporting this error? The timeout for erase is 120 seconds, perhaps erasing 16MB could take longer?

[hbhong]

@MabezDev with my current partition table, it takes 02:25. But I think that flash memory produced by different manufacturers may have speed differences.

[hbhong]

I resolved this problem by recompiling the espflash, I change the value of ERASE_WRITE_TIMEOUT_PER_MB from 40 to 400 (I know this value is too large, but I'm sorry I don't have much time to measure how much time is more appropriate. For me, this value ensures that I don't have to worry about such incidents happening again.), is it possible to append a parameter to espflash to allow user to adjust the timeout?

[jessebraham]

Thank you for the additional information! I will discuss this issue with some colleagues next week and try to determine what the best path forward for this is; possibly it's been solved in another tool already.

Perhaps we can simply increase the timeout length, determined by some experimentation. Otherwise, as you suggested maybe we can allow the user to specify this value in some way.

[brainstorm]

I just bumped into this issue with a LOLIN S3 1.0.0 board:

% espflash --version
espflash 2.1.0
% cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.31s
     Running `espflash flash --monitor target/xtensa-esp32s3-none-elf/debug/pancake-legend-lights`
[2023-10-06T03:53:46Z INFO ] Detected 8 serial ports
[2023-10-06T03:53:46Z INFO ] Ports which match a known common dev board are highlighted
[2023-10-06T03:53:46Z INFO ] Please select a port
[2023-10-06T03:53:53Z INFO ] Serial port: '/dev/cu.usbserial-12420'
[2023-10-06T03:53:53Z INFO ] Connecting...
[2023-10-06T03:53:53Z INFO ] Using flash stub
Chip type:         esp32s3 (revision v0.1)
Crystal frequency: 40MHz
Flash size:        16MB
Features:          WiFi, BLE
MAC address:       68:b6:b3:28:6c:bc
App/part. size:    613,024/16,384,000 bytes, 3.74%
[00:00:01] [========================================]      14/14      0x0
[00:00:00] [========================================]       1/1       0x8000
Error: espflash::timeout

  × Communication error while flashing device
  ╰─▶ Timeout while running FlashDeflateData command

EDIT: It did work on a second attempt though without changing anything 🤷🏻

Although something is off, see the checksum warning:

[00:00:01] [========================================]      14/14      0x0
[00:00:00] [========================================]       1/1       0x8000
[00:00:36] [========================================]     335/335     0x10000                                                                                                                             [2023-10-06T03:59:16Z INFO ] Flashing has completed!
Commands:
  CTRL+R    Reset chip
  CTRL+C    Exit

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x3fce3818,len:0x16f8
0x3fce3818 - _stack_region_top
  at ??:??
load:0x403c9700,len:0x4
0x403c9700 - hal_pwr_interrupt_clr_event
  at ??:??
load:0x403c9704,len:0xc00
0x403c9704 - hal_pwr_interrupt_clr_event
  at ??:??
load:0x403cc700,len:0x2eb0
0x403cc700 - hal_pwr_interrupt_clr_event
  at ??:??
SHA-256 comparison failed:
Calculated: 9e7b8c8d53c0514c12b6eb2f4d48f985182d9c70a488ad4caf71e08902c97372
Expected: 3499e4149a363c2b1ee4ee9709ca5031f50ee6b595a532f697c8659516763ae3
Attempting to boot anyway...
entry 0x403c9908
0x403c9908 - hal_pwr_interrupt_clr_event
  at ??:??
I (48) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader
I (48) boot: compile time Jun  7 2023 08:07:32
I (49) boot: Multicore bootloader
I (54) boot: chip revision: v0.1
I (57) boot.esp32s3: Boot SPI Speed : 40MHz
I (62) boot.esp32s3: SPI Mode       : DIO
I (67) boot.esp32s3: SPI Flash Size : 16MB
I (72) boot: Enabling RNG early entropy source...
I (77) boot: Partition Table:
I (81) boot: ## Label            Usage          Type ST Offset   Length
I (88) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (95) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (103) boot:  2 factory          factory app      00 00 00010000 00fa0000
I (110) boot: End of partition table
I (115) esp_image: segment 0: paddr=00010020 vaddr=3c080020 size=15ad0h ( 88784) map
I (145) esp_image: segment 1: paddr=00025af8 vaddr=3fc8db88 size=01204h (  4612) load
I (147) esp_image: segment 2: paddr=00026d04 vaddr=3fca69dc size=00168h (   360) load
I (151) esp_image: segment 3: paddr=00026e74 vaddr=40378000 size=05b84h ( 23428) load
I (166) esp_image: segment 4: paddr=0002ca00 vaddr=00000000 size=03618h ( 13848)
I (171) esp_image: segment 5: paddr=00030020 vaddr=42000020 size=75a50h (481872) map
I (298) boot: Loaded app from partition at offset 0x10000
I (298) boot: Disabling RNG early entropy source...
INFO - Logger is setup
Hello world!
(...)

@MabezDev Runtime for me after adding the -p <port> and removing --monitor to just have non-interactive runtime is:

cargo run  0.20s user 0.16s system 0% cpu 40.312 total

IMPORTANT detail: When I touch the USB cable, I can reliably make it fail, which indicates some type of transient USB cable noise related issue? Perhaps espflash does not gracefully recover (retries when comms are lost or are corrupted) from those transient comms errors?

I can take a couple of Wireshark USB captures if you are interested like I did for debugging serialport/serialport-rs#117... perhaps OSX serial dongle drivers might be at fault here? I can try with either Windows or Linux.

[SergioGasquez]

Hi! Would any of the affected users mind testing #488?

cargo install --git https://github.com/SergioGasquez/espflash --branch fix/deflate-timeout cargo-espflash espflash

[bugadani]

Issue persists with 2c7ee4c

[2023-11-20T08:52:38Z INFO ] Using flash stub
   Compiling esp32c6-hal v0.6.0 (C:\_Hobby\esp-hal\esp32c6-hal)
   Compiling esp-wifi v0.1.0 (https://github.com/esp-rs/esp-wifi.git?rev=0db7a70#0db7a706)
   Compiling card_io_fw v0.1.0 (C:\_Hobby\CardIO\card-io-fw)
    Finished dev [optimized + debuginfo] target(s) in 8.64s
Chip type:         esp32c6 (revision v0.0)
Crystal frequency: 40MHz
Flash size:        8MB
Features:          WiFi 6, BT 5
MAC address:       40:4c:ca:41:db:68
Partition table:   \\?\C:\_Hobby\CardIO\card-io-fw\partitions.csv
[2023-11-20T08:52:47Z INFO ] Erasing otadata (Data(Ota))...
App/part. size:    1,373,072/2,097,152 bytes, 65.47%
[00:00:00] [========================================]      13/13      0x0                                                                                                                                                                                                           
[00:00:00] [========================================]       1/1       0x8000                                                                                                                                                                                                        
Error: espflash::timeout

  × Communication error while flashing device
  ╰─▶ Timeout while running FlashDeflateData command

Update: most likely a hardware issue on my side.