Fix ESP32-S3 USB console detection (ESPTOOL-485)

[egnor]

Description of change

Fix detection of integrated USB for bootloading the ESP32-S3.

This change fixes the following bug(s):

#756

I have tested this change with the following hardware & software combinations:

Ubuntu Linux 22.04, Adafruit Feather ESP32-S3 TFT, arduino-esp under platformio

I have run the esptool.py automated integration tests with this change and the above hardware. The results were:

Various failures, BUT these failures also happen without this change! I think they're mostly related to the serial port disappearing/reappearing during entry to the bootloader. Let me know if you think I should dive into these.

======================================================================
ERROR [12.259s]: test_chip_erase (__main__.TestErase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 627, in test_chip_erase
    self.run_esptool("erase_flash")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'erase_flash']' returned non-zero exit status 1.

======================================================================
ERROR [0.055s]: test_large_region_erase (__main__.TestErase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 644, in test_large_region_erase
    self.run_esptool("erase_region 0x0 0x100000")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'erase_region', '0x0', '0x100000']' returned non-zero exit status 2.

======================================================================
ERROR [0.048s]: test_region_erase (__main__.TestErase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 632, in test_region_erase
    self.run_esptool("write_flash 0x10000 images/one_kb.bin")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'write_flash', '0x10000', 'images/one_kb.bin']' returned non-zero exit status 2.

======================================================================
ERROR [0.043s]: test_flash_id (__main__.TestFlashDetection)
Test manufacturer and device response of flash detection.
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 590, in test_flash_id
    res = self.run_esptool("flash_id")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'flash_id']' returned non-zero exit status 2.

======================================================================
ERROR [0.043s]: test_flash_size_keep (__main__.TestFlashSizes)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 582, in test_flash_size_keep
    self.run_esptool("write_flash -fs keep %d %s" % (offset, image))
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'write_flash', '-fs', 'keep', '0', 'images/bootloader_esp32s3.bin']' returned non-zero exit status 2.

======================================================================
ERROR [0.042s]: test_high_offset (__main__.TestFlashSizes)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 521, in test_high_offset
    self.run_esptool("write_flash -fs 4MB 0x300000 images/one_kb.bin")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'write_flash', '-fs', '4MB', '0x300000', 'images/one_kb.bin']' returned non-zero exit status 2.

======================================================================
ERROR [0.043s]: test_high_offset_no_compression (__main__.TestFlashSizes)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 525, in test_high_offset_no_compression
    self.run_esptool("write_flash -u -fs 4MB 0x300000 images/one_kb.bin")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'write_flash', '-u', '-fs', '4MB', '0x300000', 'images/one_kb.bin']' returned non-zero exit status 2.

======================================================================
ERROR [0.042s]: test_large_image (__main__.TestFlashSizes)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 529, in test_large_image
    self.run_esptool("write_flash -fs 4MB 0x280000 images/one_mb.bin")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'write_flash', '-fs', '4MB', '0x280000', 'images/one_mb.bin']' returned non-zero exit status 2.

======================================================================
ERROR [0.042s]: test_large_no_compression (__main__.TestFlashSizes)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 533, in test_large_no_compression
    self.run_esptool("write_flash -u -fs 4MB 0x280000 images/one_mb.bin")
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--chip', 'esp32s3', '--port', '/dev/ttyACM0', '--baud', '230400', 'write_flash', '-u', '-fs', '4MB', '0x280000', 'images/one_mb.bin']' returned non-zero exit status 2.

======================================================================
ERROR [0.042s]: test_auto_detect (__main__.TestVirtualPort)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 899, in test_auto_detect
    output = self.run_esptool("chip_id", chip_name=None)
  File "/home/egnor/source/esptool/test/test_esptool.py", line 198, in run_esptool
    raise e
  File "/home/egnor/source/esptool/test/test_esptool.py", line 191, in run_esptool
    output = subprocess.check_output(
  File "/usr/lib/python3.10/subprocess.py", line 420, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib/python3.10/subprocess.py", line 524, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/home/egnor/source/esptool/python_venv/bin/python', '/home/egnor/source/esptool/test/../esptool/__init__.py', '--port', '/dev/ttyACM0', '--baud', '230400', 'chip_id']' returned non-zero exit status 2.

======================================================================
ERROR [10.016s]: test_auto_detect_virtual_port (__main__.TestVirtualPort)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 909, in test_auto_detect_virtual_port
    with ESPRFC2217Server() as server:
  File "/home/egnor/source/esptool/test/test_esptool.py", line 111, in __init__
    self.wait_for_server_starts(attempts_count=5)
  File "/home/egnor/source/esptool/test/test_esptool.py", line 145, in wait_for_server_starts
    raise Exception("Server not started successfully!")
Exception: Server not started successfully!

======================================================================
ERROR [10.018s]: test_highspeed_flash_virtual_port (__main__.TestVirtualPort)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 920, in test_highspeed_flash_virtual_port
    with ESPRFC2217Server() as server:
  File "/home/egnor/source/esptool/test/test_esptool.py", line 111, in __init__
    self.wait_for_server_starts(attempts_count=5)
  File "/home/egnor/source/esptool/test/test_esptool.py", line 145, in wait_for_server_starts
    raise Exception("Server not started successfully!")
Exception: Server not started successfully!

======================================================================
FAIL [0.043s]: test_write_no_compression_past_end_fails (__main__.TestFlashSizes)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/egnor/source/esptool/test/test_esptool.py", line 550, in test_write_no_compression_past_end_fails
    self.assertIn("File images/one_kb.bin", output)
AssertionError: 'File images/one_kb.bin' not found in "esptool.py v4.2-dev\nSerial port /dev/ttyACM0\n\nA fatal error occurred: Could not open /dev/ttyACM0, the port doesn't exist\n"

----------------------------------------------------------------------
Ran 74 tests in 288.550s

FAILED (failures=1, errors=12, skipped=8)

Generating XML reports...

[egnor]

This actually seems to cause problems (see some discussion in espressif/arduino-esp32#6762).

The code is definitely broken now, but that means the GPIO0-strapping check never runs, and unfortunately on ESP32-S3 I don't know how to make the GPIO0-strapping check run reliably without false positives when a reset is delivered through the USB Serial/JTAG peripheral (the common case).

[radimkarnis]

Hello @egnor,
thanks a lot for your effort and investigation in the other threads.

The uses_usb() check is only meant for serial via USB-CDC with USB-OTG peripheral (UARTDEV_BUF_NO_USB_OTG = 3). (Also sometimes called native USB or simply USB-OTG. Currently supported by ESP32-S2 and ESP32-S3).

Its primary purpose is to decrease the maximum block size for RAM and Flash writes when in said mode (From 0x1800 to 0x800). The second purpose is to warn users they have to reset the board manually (can't perform a reset with software in this mode).

None of these two reasons apply to the USB Serial/JTAG peripheral (UARTDEV_BUF_NO_USB_OTG = 4). The block size can stay the same and a reset can be performed by wiggling the DTR/RTS lines. As you said yourself in both threads, implementing this has actually no effect. Furthermore, the ESP32-C3 also has the USB Serial/JTAG peripheral and there is no uses_usb() implementation for this target (because it is not needed).

I think they're mostly related to the serial port disappearing/reappearing during entry to the bootloader. Let me know if you think I should dive into these.

That would be great. If you have the time and will to investigate the disappearing port, I think it could be very beneficial!

Anyway, I believe this PR should be closed.

Thank you very much for your work!
Radim.

[xyzzy42]

None of these two reasons apply to the USB Serial/JTAG peripheral (UARTDEV_BUF_NO_USB_OTG = 4). The block size can stay the same and a reset can be performed by wiggling the DTR/RTS lines.

Are you sure about that? I've tested on ESP32-S3 and USB Serial/JTAG peripheral can not reset to SPI boot mode, i.e. normal boot up. While DTR/RTS sequence will trigger a reset, the bootloader is re-entered each time. It appears the state of the GPIO strapping is not updated by this reset and will always be boot:0x21 (DOWNLOAD(USB/UART0)) and never be boot:0x29 (SPI_FAST_FLASH_BOOT), with bit 0x08 set to indicate GPIO0 pin in high, normal boot, mode.

I am sure this the serial/JTAG peripheral being used by the bootloader and not the USB OTG mode.