espflash does not wait between writing a sync command and reading the response

[stevecheckoway]

I have an ESP32 connected to my computer running macOS 11.6.2. When I connect it, /dev/tty.usbserial-0001 and /dev/cu.usbserial-0001 appear. Using esptool.py, I can connect.

$ esptool.py flash_id
esptool.py v3.3-dev
Found 8 serial ports
Serial port /dev/cu.usbserial-0001
Connecting.................
Detecting chip type... Unsupported detection protocol, switching and trying again...
Connecting.....
Detecting chip type... ESP32
Chip is ESP32-D0WDQ6 (revision 1)
Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None
Crystal is 40MHz
MAC: [...]
Uploading stub...
Running stub...
Stub running...
Manufacturer: 54
Device: 4016
Detected flash size: 4MB
Hard resetting via RTS pin...

Using espflash version 1.2.0, I cannot.

$ espflash board-info
Serial port: /dev/tty.usbserial-0001
Connecting...

Unable to connect, retrying with extra delay...
Unable to connect, retrying with default delay...
Unable to connect, retrying with extra delay...
Unable to connect, retrying with default delay...
Unable to connect, retrying with extra delay...
Unable to connect, retrying with default delay...
Unable to connect, retrying with extra delay...
Error: espflash::connection_failed

  × Error while connecting to device
  ╰─▶ Failed to connect to the device
  help: Ensure that the device is connected and the reset and boot pins are not being held down

The issue is not tty vs. cu as $ esptool.py -p /dev/tty.usbserial-0001 flash_id works correctly and $espflash board-info /dev/cu.usbserial-0001 fails.

The connection failure appears to be happening in Flasher::sync(). I'm happy to provide additional information or assistance in debugging.

[stevecheckoway]

I figured out what the issue is. In Flasher::sync(), the sync command is written here. The response is read immediately afterward. Connection::read_response reads from the serial port and if fewer than 10 bytes are read, returns Ok(None). If any bytes are read, they're discarded.

I added a print statement to Connection::read_response if the serial port returned less than 10 bytes. I hooked up my logic analyzer and could see that espflash was correctly reading the bytes sent by the ESP32 over the serial port, but since it was reading fewer than 10 at a time, it was failing.

A simple fix is to add a sleep between writing the sync command and reading the response. A better thing to do would be to buffer the data read until there were at least 10 bytes. I'm not sure if there are other places where this same thing would be an issue or not.

[jessebraham]

@stevecheckoway I believe this should be resolved. If you get a chance, would you mind verifying that the current master branch fixes your problem please? Feel free to re-open this issue if you feel the need to.

[pavlus]

@jessebraham I have an issue that looks the same. For me it wasn't fixed.

Btw, it would be great, if you changed development version after release, I wanted to check if I've installed it from the git correctly, but value of --version was the same as for the one from the crates.

[stevecheckoway]

I have not had a chance to look into this again, but I think the underlying issue is not resolved by #123 which is that an entire SLIP packet needs to be read and decoded, not just 10 bytes of such a packet. This is easy enough to solve with something like (this is from some code of mine, not a modification of espflash).

    fn read_packet(&mut self, timeout: Duration) -> Result<Vec<u8>> {
        let start_time = Instant::now();
        let mut decoder = slip_codec::SlipDecoder::new();
        let mut response: Vec<u8> = Vec::new();

        loop {
            if self.buffer.is_empty() {
                self.fill_buffer(timeout.saturating_sub(start_time.elapsed()))?;
            }

            let mut cursor = Cursor::new(&self.buffer);
            match decoder.decode(&mut cursor, &mut response) {
                Ok(_) => {
                    // A complete packet has been decoded.
                    let size = cursor.position() as usize;
                    self.buffer.drain(..size);
                    self.trace(Event::SlipRead(Cow::from(&response)));
                    return Ok(response);
                }
                Err(slip_codec::SlipError::EndOfStream) => {
                    // The decoder did not hit the end of the packet but did consume all of self.buffer.
                    self.buffer.clear();
                }
                Err(err) => {
                    panic!("Programming error: decoder.decode() returned {:?}", err);
                }
            }
        }
    }
    fn fill_buffer(&mut self, timeout: Duration) -> Result<()> {
        self.buffer.resize(1024, 0);
        self.serial.set_timeout(max(DEFAULT_SERIAL_TIMEOUT, timeout))?;
        match self.serial.read(&mut self.buffer) {
            Ok(n) => {
                self.buffer.truncate(n);
                self.trace_only(Event::SerialRead(Cow::from(&self.buffer)));
                Ok(())
            }
            Err(err) => {
                // XXX: Trace?
                self.buffer.clear();
                Err(err.into())
            }
        }
    }

This can probably be simplified using a BufReader to handle the buffering, but I didn't think of it when I initially wrote the code and I haven't gone back and attempted to do so.

[pavlus]

@stevecheckoway

"10 bytes" is related to the expected minimum size of decoded packet. SlipDecoder::decode reads full SLIP frame anyway.

But I'm not sure for why you suggest that we need full frame here, if we read CommandResponse struct which is only 10 bytes (according to the ESPRESSIF doc on the protocol it's 12 bytes, last two bytes being reserved. Also, my testing shows that all 12 bytes are being decoded in the current code, we just happen to want only first 10 of them).

Your code most likely works, because it implicitly triggers flushing somewhere, otherwise it looks behaviorally the same, since from the looks of it, problem was with sync request not being sent by the wire at the time of reading response, not with the way response was read.

[pavlus]

OTOH, if it reads full frame and we loop until more data is received, then it will only return after timeout or when more responses are received, then returned buffer will contain data from multiple frames, and the first one won't be the one we need (otherwise it would've already been returned). This is an unlikely course of events(protocol describes only one type of response structure, and it's 12 bytes), but still logically incorrect, even though it will work according to the current protocol description.