espressif / esp-usb-bridge

USB to UART&JTAG bridge, implemented on ESP32-S2 or ESP32-S3
Apache License 2.0
298 stars 33 forks source link

Cannot make it work on OSX 10.15.7 connected to an ESP32 (EUB-46) #10

Closed AlbertoLopSie closed 1 year ago

AlbertoLopSie commented 1 year ago

Board: ESP32-S2-Saola-1

Target: ESP32-DevKitC

Developing on an iMac (Retina 5K, 27-inch, 2017) running OSX 10.15.7 (Catalina)

OSX detects only one Serial USB device:

Screen Shot 2023-04-22 at 18 09 47

PlatformIO IDE on VSCode detects two serial ports:

Screen Shot 2023-04-22 at 18 15 50

The /dev/cu.SLAB_USBtoUART port can be opened and the monitor output of the esp-usb-bridge can be seen:

Screen Shot 2023-04-22 at 18 19 31

The /dev/cu.usbserial-1420 can not be opened by any serial terminal and no USB Mass Storage device of any kind appears on finder.

Trying to debug the target with the following platformio.ini config:

[env:esp32dev]
board = esp32dev
platform = espressif32
framework = arduino
build_flags = 
    -DCORE_DEBUG_LEVEL=3
    -Wno-unused-variable
    -Wno-unused-but-set-variable
    -Wno-unused-function
    -Wno-format-extra-args
monitor_speed = 115200
monitor_encoding = UTF-8
monitor_filters = 
    direct
    esp32_exception_decoder

debug_init_break = tbreak setup

debug_tool = esp-bridge
debug_port = /dev/cu.SLAB_USBtoUART
upload_port = /dev/cu.usbserial-1420
monitor_port = /dev/cu.usbserial-1420

produces on the DEBUG CONSOLE when trying to Start Debug (skip PreDebug, already built):

Processing esp32dev (board: esp32dev; platform: espressif32; framework: arduino)
--------------------------------------------------------------------------------
Verbose mode can be enabled via `-v, --verbose` option
CONFIGURATION: https://docs.platformio.org/page/boards/espressif32/esp32dev.html
PLATFORM: Espressif 32 (2023.2.0+sha.59388ed) > Espressif ESP32 Dev Module
HARDWARE: ESP32 240MHz, 320KB RAM, 4MB Flash
DEBUG: Current (esp-bridge) External (cmsis-dap, esp-bridge, esp-prog, iot-bus-jtag, jlink, minimodule, olimex-arm-usb-ocd, olimex-arm-usb-ocd-h, olimex-arm-usb-tiny-h, olimex-jtag-tiny, tumpa)
PACKAGES:
 - framework-arduinoespressif32 @ 2.0.7
 - tool-esptoolpy @ 1.40501.0 (4.5.1)
 - tool-mklittlefs @ 1.203.210628 (2.3)
 - tool-mkspiffs @ 2.230.0 (2.30)
 - toolchain-xtensa-esp32 @ 8.4.0+2021r2-patch5
Converting led_blink.ino
LDF: Library Dependency Finder -> https://bit.ly/configure-pio-ldf
LDF Modes: Finder ~ chain, Compatibility ~ soft
Found 32 compatible libraries
Scanning dependencies...
Dependency Graph
|-- CircularBuffer @ 1.3.3
Building in debug mode
Compiling .pio/build/esp32dev/src/led_blink.ino.cpp.o
Building .pio/build/esp32dev/bootloader.bin
Generating partitions .pio/build/esp32dev/partitions.bin
esptool.py v4.6-dev
Creating esp32 image...
Merged 1 ELF section
Successfully created esp32 image.
Compiling .pio/build/esp32dev/FrameworkArduino/Esp.cpp.o
Compiling .pio/build/esp32dev/FrameworkArduino/FirmwareMSC.cpp.o
...........
...........
Compiling .pio/build/esp32dev/FrameworkArduino/wiring_shift.c.o
Archiving .pio/build/esp32dev/libFrameworkArduino.a
Indexing .pio/build/esp32dev/libFrameworkArduino.a
Linking .pio/build/esp32dev/firmware.elf
Retrieving maximum program size .pio/build/esp32dev/firmware.elf
Checking size .pio/build/esp32dev/firmware.elf
Advanced Memory Usage is available via "PlatformIO Home > Project Inspect"
RAM:   [          ]   4.2% (used 13700 bytes from 327680 bytes)
Flash: [=         ]   9.9% (used 129169 bytes from 1310720 bytes)
Building .pio/build/esp32dev/firmware.bin
esptool.py v4.6-dev
Creating esp32 image...
Merged 2 ELF sections
Successfully created esp32 image.
========================= [SUCCESS] Took 39.15 seconds =========================
undefinedOpen On-Chip Debugger  v0.11.0-esp32-20220706 (2022-07-06-15:49)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1002
Info : esp_usb_jtag: capabilities descriptor set to 0x30a
adapter speed: 40000 kHz

WARNING: boards/esp-wroom-32.cfg is deprecated, and may be removed in a future release.
Warn : Transport "jtag" was already selected
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Error: esp_usb_jtag: could not find or open device!

Reading symbols from /Users/alberto/dev/trh-esp32/.pio/build/esp32dev/firmware.elf...
PlatformIO Unified Debugger -> https://bit.ly/pio-debug
PlatformIO: debug_tool = esp-bridge
PlatformIO: Initializing remote target...
Ignoring packet error, continuing...
warning: unrecognized item "timeout" in "qSupported" response
Ignoring packet error, continuing...
.pioinit:11: Error in sourced command file:
Remote replied unexpectedly to 'vMustReplyEmpty': timeout

And no debug session is started.

One line catch my attention, but I don't know what it means nor how to fix it.

Error: esp_usb_jtag: could not find or open device!

Deleting platformio.ini lines (leaving only he debug_tool = esp-bridge one:

debug_port = /dev/cu.SLAB_USBtoUART
upload_port = /dev/cu.usbserial-1420
monitor_port = /dev/cu.usbserial-1420

produces almost the same result:

(compile lines skipped)

Open On-Chip Debugger  v0.11.0-esp32-20220706 (2022-07-06-15:49)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1002
Info : esp_usb_jtag: capabilities descriptor set to 0x30a
adapter speed: 40000 kHz

WARNING: boards/esp-wroom-32.cfg is deprecated, and may be removed in a future release.
Warn : Transport "jtag" was already selected
Info : tcl server disabled
Info : telnet server disabled
Error: esp_usb_jtag: could not find or open device!

.pioinit:11: Error in sourced command file:
Remote connection closed

Can anyone throw me any hint there??

Thanks !!!!

dobairoland commented 1 year ago

Hi @AlbertoLopSie.

First, I'd like to recommend to test (as the first step) just with the Saola board.

Sometimes, when tinyusb crashes, the USB device disappears. This can be seen on linux in the dmesg output (I'm not sure if there is anything similar to your OS). So please try to check the presence of the USB device before attempting to connect to it. If you have any trouble then you can try for comparison any of the tinyusb examples from here. You can check if the device will show up or not. It makes no sense to try anything else until this is not working.

As the next step I would try to connect a serial device with the logging level increased in the bridge. This would help to see what is happening there.

But I'm not sure if you will be able to use a devkit as the target. At least we were not able at the time when we where trying. There are USB-to-UART chips on those devkits and they interfered with some of the serial lines. I don't remember all the details but we were getting some data but could not make everything to work. You might get more luck if you would try to connect a module with some additional circuitry. You can find the simplest working schematics linked from the main README.

I can give you more tips but please try the above first.

AlbertoLopSie commented 1 year ago

Hi Roland!

Thanks for your attention on this issue

First, I'd like to recommend to test (as the first step) just with the Saola board.

That's exactly the path I was thinking on take today... I'll post my findings

Sometimes, when tinyusb crashes, the USB device disappears. This can be seen on linux in the dmesg output (I'm not sure if there is anything similar to your OS). So please try to check the presence of the USB device before attempting to connect to it. If you have any trouble then you can try for comparison any of the tinyusb examples from here. You can check if the device will show up or not. It makes no sense to try anything else until this is not working.

I tried connecting the board a to a Windows VM inside my Mac, but nothing new happened (may be the virtualization, who knows) I'll to connect it to one of the Linux boxes I have around and check the dmsg log. I 'll also check the tusb_msc example to see what happens.

As the next step I would try to connect a serial device with the logging level increased in the bridge. This would help to see what is happening there.

Nice one! At least with this debug level, there's no indication of any tinyusb error.

But I'm not sure if you will be able to use a devkit as the target. At least we were not able at the time when we where trying. There are USB-to-UART chips on those devkits and they interfered with some of the serial lines. I don't remember all the details but we were getting some data but could not make everything to work. You might get more luck if you would try to connect a module with some additional circuitry. You can find the simplest working schematics linked from the main README.

I'm testing esp-usb-bridge on exactly that schematic built on a protoboard. I hope there are no conflicts among JTAG pins and some other chip on the module. That would make these modules undebuggeable!

I can give you more tips but please try the above first.

I Will! Thank you!!!

AlbertoLopSie commented 1 year ago

First (and easiest) try. LOG_LEVEL increased to 5.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x9 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6108,len:0x1764
load:0x4004c000,len:0xabc
load:0x40050000,len:0x31b4
entry 0x4004c1c0
I (21) boot: ESP-IDF v5.0.1-dirty 2nd stage bootloader
I (21) boot: compile time 12:35:25
I (21) boot: chip revision: v0.0
I (24) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (39) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (48) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (82) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=0b9e8h ( 47592) map
I (100) esp_image: segment 1: paddr=0001ba10 vaddr=3ffc5010 size=01d88h (  7560) load
I (102) esp_image: segment 2: paddr=0001d7a0 vaddr=40028000 size=02878h ( 10360) load
I (109) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=20d94h (134548) map
I (142) esp_image: segment 4: paddr=00040dbc vaddr=4002a878 size=0a794h ( 42900) load
I (160) boot: Loaded app from partition at offset 0x10000
I (160) boot: Disabling RNG early entropy source...
I (171) cache: Instruction cache        : size 16KB, 4Ways, cache line size 32Byte
I (171) cpu_start: Pro cpu up.
D (183) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 4 bit
D (183) efuse: In EFUSE_BLK2__DATA4_REG is used 4 bits starting with 0 bit
D (188) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 16 bit
D (202) clk: RTC_SLOW_CLK calibration value: 6589463
I (211) cpu_start: Pro cpu start user code
I (211) cpu_start: cpu freq: 240000000 Hz
I (211) cpu_start: Application information:
I (216) cpu_start: Project name:     bridge
I (221) cpu_start: App version:      779d58e
I (226) cpu_start: Compile time:     Apr 24 2023 12:35:38
I (232) cpu_start: ELF file SHA256:  d77922505c2d7917...
I (238) cpu_start: ESP-IDF:          v5.0.1-dirty
I (243) cpu_start: Min chip rev:     v0.0
I (248) cpu_start: Max chip rev:     v1.99 
I (253) cpu_start: Chip rev:         v0.0
V (258) memory_layout: reserved range is 0x3f00b9d8 - 0x3f00b9f8
D (264) memory_layout: Checking 4 reserved memory ranges:
D (269) memory_layout: Reserved memory range 0x3ff9e000 - 0x3ff9e000
D (276) memory_layout: Reserved memory range 0x3ffb8000 - 0x3ffc500c
D (282) memory_layout: Reserved memory range 0x3ffc5010 - 0x3ffc8380
D (288) memory_layout: Reserved memory range 0x3ffffa10 - 0x40000000
D (295) memory_layout: Building list of available memory regions:
V (301) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffbc000
V (308) memory_layout: Region 0x3ffb8000 - 0x3ffbc000 inside of reserved 0x3ffb8000 - 0x3ffc500c
V (317) memory_layout: Examining memory region 0x3ffbc000 - 0x3ffc0000
V (323) memory_layout: Region 0x3ffbc000 - 0x3ffc0000 inside of reserved 0x3ffb8000 - 0x3ffc500c
V (332) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc4000
V (339) memory_layout: Region 0x3ffc0000 - 0x3ffc4000 inside of reserved 0x3ffb8000 - 0x3ffc500c
V (347) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc8000
V (354) memory_layout: Start of region 0x3ffc4000 - 0x3ffc8000 overlaps reserved 0x3ffb8000 - 0x3ffc500c
V (364) memory_layout: End of region 0x3ffc500c - 0x3ffc8000 overlaps reserved 0x3ffc5010 - 0x3ffc8380
V (373) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffcc000
V (380) memory_layout: Start of region 0x3ffc8000 - 0x3ffcc000 overlaps reserved 0x3ffc5010 - 0x3ffc8380
D (389) memory_layout: Available memory region 0x3ffc8380 - 0x3ffcc000
V (396) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffd0000
D (402) memory_layout: Available memory region 0x3ffcc000 - 0x3ffd0000
V (409) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd4000
D (415) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd4000
V (422) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd8000
D (429) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd8000
V (435) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffdc000
D (442) memory_layout: Available memory region 0x3ffd8000 - 0x3ffdc000
V (448) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffe0000
D (455) memory_layout: Available memory region 0x3ffdc000 - 0x3ffe0000
V (462) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
D (468) memory_layout: Available memory region 0x3ffe0000 - 0x3ffe4000
V (475) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
D (481) memory_layout: Available memory region 0x3ffe4000 - 0x3ffe8000
V (488) memory_layout: Examining memory region 0x3ffe8000 - 0x3ffec000
D (495) memory_layout: Available memory region 0x3ffe8000 - 0x3ffec000
V (501) memory_layout: Examining memory region 0x3ffec000 - 0x3fff0000
D (508) memory_layout: Available memory region 0x3ffec000 - 0x3fff0000
V (514) memory_layout: Examining memory region 0x3fff0000 - 0x3fff4000
D (521) memory_layout: Available memory region 0x3fff0000 - 0x3fff4000
V (528) memory_layout: Examining memory region 0x3fff4000 - 0x3fff8000
D (534) memory_layout: Available memory region 0x3fff4000 - 0x3fff8000
V (541) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (547) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (554) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
V (561) memory_layout: End of region 0x3fffc000 - 0x40000000 overlaps reserved 0x3ffffa10 - 0x40000000
D (570) memory_layout: Available memory region 0x3fffc000 - 0x3ffffa10
V (577) memory_layout: Examining memory region 0x3ff9e000 - 0x3ffa0000
D (583) memory_layout: Available memory region 0x3ff9e000 - 0x3ffa0000
I (590) heap_init: Initializing. RAM available for dynamic allocation:
D (597) heap_init: New heap initialised at 0x3ffc8380
I (602) heap_init: At 3FFC8380 len 00033C80 (207 KiB): DRAM
I (608) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
D (615) heap_init: New heap initialised at 0x3ff9e000
I (620) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
V (626) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (632) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (641) intr_alloc: Connected src 49 to int 2 (cpu 0)
V (646) memspi: raw_chip_id: 16405E

V (649) memspi: chip_id: 5E4016

V (653) memspi: raw_chip_id: 16405E

V (656) memspi: chip_id: 5E4016

D (660) spi_flash: trying chip: issi
D (664) spi_flash: trying chip: gd
D (667) spi_flash: trying chip: mxic
D (671) spi_flash: trying chip: winbond
D (675) spi_flash: trying chip: boya
D (678) spi_flash: trying chip: th
D (682) spi_flash: trying chip: generic
I (686) spi_flash: detected chip: generic
I (690) spi_flash: flash io: dio
D (694) cpu_start: calling init function: 0x40081e74
0x40081e74: esp_reset_reason_init at /Users/alberto/esp/esp-idf/components/esp_system/port/soc/esp32s2/reset_reason.c:67

D (699) cpu_start: calling init function: 0x400814f0
0x400814f0: esp_init_app_elf_sha256 at /Users/alberto/esp/esp-idf/components/esp_app_format/esp_app_desc.c:69

D (704) cpu_start: calling init function: 0x4008566c on core: 0
0x4008566c: __esp_system_init_fn_esp_timer_startup_init at /Users/alberto/esp/esp-idf/components/esp_timer/src/esp_timer.c:509

V (710) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (717) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE02
D (725) intr_alloc: Connected src 73 to int 10 (cpu 0)
D (730) cpu_start: calling init function: 0x4009f9ec on core: 0
0x4009f9ec: __esp_system_init_fn_init_components0 at /Users/alberto/esp/esp-idf/components/esp_system/startup.c:484

V (736) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (742) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (750) intr_alloc: Connected src 28 to int 3 (cpu 0)
I (755) cpu_start: Starting scheduler on PRO CPU.
D (761) heap_init: New heap initialised at 0x3fffc000
V (761) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (771) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (771) intr_alloc: Connected src 17 to int 9 (cpu 0)
I (781) gpio: GPIO[12]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (791) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (801) gpio: GPIO[14]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (811) bridge_main: LED GPIO init done
D (811) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (821) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (831) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (831) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (841) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (851) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
V (851) TUSB:DCD: DCD init - Start
V (861) TUSB:DCD: DCD init - Soft DISCONNECT and Setting up
V (861) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (871) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (881) intr_alloc: Connected src 48 to int 12 (cpu 0)
D (881) boot: 0x3ffc5280   eb 3c 90 6d 6b 66 73 2e  66 61 74 00 02 08 01 00  |.<.mkfs.fat.....|
D (891) boot: 0x3ffc5290   01 20 00 00 c0 f8 18 00  00 00 00 00 00 00 00 00  |. ..............|
D (901) boot: 0x3ffc52a0   00 00 00 00 80 00 29 93  0c 3d 56 45 53 50 50 52  |......)..=VESPPR|
D (911) boot: 0x3ffc52b0   4f 47 5f 4d 53 43 46 41  54 31 36 20 20 20 0e 1f  |OG_MSCFAT16   ..|
D (921) boot: 0x3ffc52c0   be 5b 7c ac 22 c0 74 0b  56 b4 0e bb 07 00 cd 10  |.[|.".t.V.......|
D (931) boot: 0x3ffc52d0   5e eb f0 32 e4 cd 16 cd  19 eb fe 54 68 69 73 20  |^..2.......This |
D (941) boot: 0x3ffc52e0   69 73 20 6e 6f 74 20 61  20 62 6f 6f 74 61 62 6c  |is not a bootabl|
D (941) boot: 0x3ffc52f0   65 20 64 69 73 6b 2e 20  20 50 6c 65 61 73 65 20  |e disk.  Please |
D (951) boot: 0x3ffc5300   69 6e 73 65 72 74 20 61  20 62 6f 6f 74 61 62 6c  |insert a bootabl|
D (961) boot: 0x3ffc5310   65 20 66 6c 6f 70 70 79  20 61 6e 64 0d 0a 70 72  |e floppy and..pr|
D (971) boot: 0x3ffc5320   65 73 73 20 61 6e 79 20  6b 65 79 20 74 6f 20 74  |ess any key to t|
D (981) boot: 0x3ffc5330   72 79 20 61 67 61 69 6e  20 2e 2e 2e 20 0d 0a 00  |ry again ... ...|
D (991) boot: 0x3ffc5340   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1001) boot: 0x3ffc5350   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1011) boot: 0x3ffc5360   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1011) boot: 0x3ffc5370   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1021) boot: 0x3ffc5380   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1031) boot: 0x3ffc5390   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1041) boot: 0x3ffc53a0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1051) boot: 0x3ffc53b0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1061) boot: 0x3ffc53c0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1071) boot: 0x3ffc53d0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1081) boot: 0x3ffc53e0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1091) boot: 0x3ffc53f0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1091) boot: 0x3ffc5400   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1101) boot: 0x3ffc5410   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1111) boot: 0x3ffc5420   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1121) boot: 0x3ffc5430   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1131) boot: 0x3ffc5440   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1141) boot: 0x3ffc5450   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1151) boot: 0x3ffc5460   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1161) boot: 0x3ffc5470   00 00 00 00 00 00 00 00  00 00 00 00 00 00 55 aa  |..............U.|
D (1161) fat: 0x3f006c20   f8 ff ff ff ff ff                                 |......|
D (1171) root: 0x3ffc5240   45 53 50 50 52 4f 47 5f  4d 53 43 08 00 00 00 00  |ESPPROG_MSC.....|
D (1181) root: 0x3ffc5250   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1191) root: 0x3ffc5260   52 45 41 44 4d 45 20 20  54 58 54 01 00 00 00 00  |README  TXT.....|
D (1201) root: 0x3ffc5270   00 00 00 00 00 00 00 00  00 00 02 00 73 00 00 00  |............s...|
I (1211) bridge_msc: MSC disk RAM usage: 698 bytes
I (1211) uart: queue free spaces: 20
V (1221) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1221) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1231) intr_alloc: Connected src 38 to int 13 (cpu 0)
I (1241) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1251) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1261) bridge_serial: UART & GPIO have been initialized
I (1261) gpio: GPIO[8]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1271) gpio: GPIO[9]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1281) gpio: GPIO[10]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1291) gpio: GPIO[3]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
D (1301) dedic_gpio: build platform on core[0] at 0x3ffc816c
D (1311) dedic_gpio: new outward bundle(0x3ffd0e24) on core[0], offset=0, mask(7)
D (1311) dedic_gpio: new inward bundle(0x3ffd0e4c) on core[0], offset=0, mask(1)
I (1321) bridge_jtag: JTAG GPIO init done
D (1321) bridge_jtag: Waiting for the device to be mounted...
D (1361) bridge_serial: usb_sender_task: nothing to send
D (1561) bridge_serial: usb_sender_task: nothing to send
----------------------
D (1761) bridge_serial: usb_sender_task: nothing to send
D (1961) bridge_serial: usb_sender_task: nothing to send
[ repeats once a second ]

I don't see anything related to tinyusb failing... Do you?

AlbertoLopSie commented 1 year ago

More tests...

Plugged on a RPi board...

$ lsusb
Bus 001 Device 007: ID 10c4:ea60 Cygnal Integrated Products, Inc. CP2102/CP2109 UART Bridge Controller [CP210x family]
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp. SMC9512/9514 USB Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

$ dmesg
[607433.526387] usb 1-1.3: new full-speed USB device number 7 using dwc_otg
[607433.662537] usb 1-1.3: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
[607433.662560] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[607433.662578] usb 1-1.3: Product: CP2102N USB to UART Bridge Controller
[607433.662594] usb 1-1.3: Manufacturer: Silicon Labs
[607433.662610] usb 1-1.3: SerialNumber: 3cfd8672cb1ced11be7412cebbdd3192
[607433.831902] usbcore: registered new interface driver usbserial_generic
[607433.831972] usbserial: USB Serial support registered for generic
[607433.838232] usbcore: registered new interface driver cp210x
[607433.838321] usbserial: USB Serial support registered for cp210x
[607433.838521] cp210x 1-1.3:1.0: cp210x converter detected
[607433.844473] usb 1-1.3: cp210x converter now attached to ttyUSB0

$ lsblk
NAME         MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
mmcblk0      179:0    0  3.7G  0 disk
├─mmcblk0p1  179:1    0  256M  0 part /boot
└─mmcblk0p2  179:2    0  3.4G  0 part /
mmcblk0boot0 179:32   0    4M  1 disk
mmcblk0boot1 179:64   0    4M  1 disk

$ ls /dev/*USB*
/dev/ttyUSB0

The monitor shows no apparent difference with the one generated on my Mac:

$ cat /dev/ttyUSB0
ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6108,len:0x1764
load:0x4004c000,len:0xabc
load:0x40050000,len:0x31b4
entry 0x4004c1c0
I (21) boot: ESP-IDF v5.0.1-dirty 2nd stage bootloader
I (21) boot: compile time 12:35:25
I (21) boot: chip revision: v0.0
I (24) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (39) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (48) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (82) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=0b9e8h ( 47592) map
I (100) esp_image: segment 1: paddr=0001ba10 vaddr=3ffc5010 size=01d88h (  7560) load
I (102) esp_image: segment 2: paddr=0001d7a0 vaddr=40028000 size=02878h ( 10360) load
I (109) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=20d94h (134548) map
I (142) esp_image: segment 4: paddr=00040dbc vaddr=4002a878 size=0a794h ( 42900) load
I (160) boot: Loaded app from partition at offset 0x10000
I (160) boot: Disabling RNG early entropy source...
I (171) cache: Instruction cache    : size 16KB, 4Ways, cache line size 32Byte
I (171) cpu_start: Pro cpu up.
D (183) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 4 bit
D (183) efuse: In EFUSE_BLK2__DATA4_REG is used 4 bits starting with 0 bit
D (188) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 16 bit
D (202) clk: RTC_SLOW_CLK calibration value: 6596995
I (211) cpu_start: Pro cpu start user code
I (211) cpu_start: cpu freq: 240000000 Hz
I (211) cpu_start: Application information:
I (216) cpu_start: Project name:     bridge
I (221) cpu_start: App version:      779d58e
I (226) cpu_start: Compile time:     Apr 24 2023 12:35:38
I (232) cpu_start: ELF file SHA256:  d77922505c2d7917...
I (238) cpu_start: ESP-IDF:          v5.0.1-dirty
I (243) cpu_start: Min chip rev:     v0.0
I (248) cpu_start: Max chip rev:     v1.99
I (253) cpu_start: Chip rev:         v0.0
V (258) memory_layout: reserved range is 0x3f00b9d8 - 0x3f00b9f8
D (264) memory_layout: Checking 4 reserved memory ranges:
D (269) memory_layout: Reserved memory range 0x3ff9e000 - 0x3ff9e000
D (276) memory_layout: Reserved memory range 0x3ffb8000 - 0x3ffc500c
D (282) memory_layout: Reserved memory range 0x3ffc5010 - 0x3ffc8380
D (288) memory_layout: Reserved memory range 0x3ffffa10 - 0x40000000
D (295) memory_layout: Building list of available memory regions:
V (301) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffbc000
V (308) memory_layout: Region 0x3ffb8000 - 0x3ffbc000 inside of reserved 0x3ffb8000 - 0x3ffc500c
V (317) memory_layout: Examining memory region 0x3ffbc000 - 0x3ffc0000
V (323) memory_layout: Region 0x3ffbc000 - 0x3ffc0000 inside of reserved 0x3ffb8000 - 0x3ffc500c
V (332) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc4000
V (339) memory_layout: Region 0x3ffc0000 - 0x3ffc4000 inside of reserved 0x3ffb8000 - 0x3ffc500c
V (347) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc8000
V (354) memory_layout: Start of region 0x3ffc4000 - 0x3ffc8000 overlaps reserved 0x3ffb8000 - 0x3ffc500c
V (364) memory_layout: End of region 0x3ffc500c - 0x3ffc8000 overlaps reserved 0x3ffc5010 - 0x3ffc8380
V (373) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffcc000
V (380) memory_layout: Start of region 0x3ffc8000 - 0x3ffcc000 overlaps reserved 0x3ffc5010 - 0x3ffc8380
D (389) memory_layout: Available memory region 0x3ffc8380 - 0x3ffcc000
V (396) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffd0000
D (402) memory_layout: Available memory region 0x3ffcc000 - 0x3ffd0000
V (409) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd4000
D (415) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd4000
V (422) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd8000
D (429) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd8000
V (435) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffdc000
D (442) memory_layout: Available memory region 0x3ffd8000 - 0x3ffdc000
V (448) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffe0000
D (455) memory_layout: Available memory region 0x3ffdc000 - 0x3ffe0000
V (462) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
D (468) memory_layout: Available memory region 0x3ffe0000 - 0x3ffe4000
V (475) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
D (481) memory_layout: Available memory region 0x3ffe4000 - 0x3ffe8000
V (488) memory_layout: Examining memory region 0x3ffe8000 - 0x3ffec000
D (495) memory_layout: Available memory region 0x3ffe8000 - 0x3ffec000
V (501) memory_layout: Examining memory region 0x3ffec000 - 0x3fff0000
D (508) memory_layout: Available memory region 0x3ffec000 - 0x3fff0000
V (514) memory_layout: Examining memory region 0x3fff0000 - 0x3fff4000
D (521) memory_layout: Available memory region 0x3fff0000 - 0x3fff4000
V (528) memory_layout: Examining memory region 0x3fff4000 - 0x3fff8000
D (534) memory_layout: Available memory region 0x3fff4000 - 0x3fff8000
V (541) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (547) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (554) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
V (561) memory_layout: End of region 0x3fffc000 - 0x40000000 overlaps reserved 0x3ffffa10 - 0x40000000
D (570) memory_layout: Available memory region 0x3fffc000 - 0x3ffffa10
V (577) memory_layout: Examining memory region 0x3ff9e000 - 0x3ffa0000
D (583) memory_layout: Available memory region 0x3ff9e000 - 0x3ffa0000
I (590) heap_init: Initializing. RAM available for dynamic allocation:
D (597) heap_init: New heap initialised at 0x3ffc8380
I (602) heap_init: At 3FFC8380 len 00033C80 (207 KiB): DRAM
I (608) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
D (615) heap_init: New heap initialised at 0x3ff9e000
I (620) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
V (626) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (632) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (641) intr_alloc: Connected src 49 to int 2 (cpu 0)
V (646) memspi: raw_chip_id: 16405E
V (649) memspi: chip_id: 5E4016
V (653) memspi: raw_chip_id: 16405E
V (656) memspi: chip_id: 5E4016
D (660) spi_flash: trying chip: issi
D (664) spi_flash: trying chip: gd
D (667) spi_flash: trying chip: mxic
D (671) spi_flash: trying chip: winbond
D (675) spi_flash: trying chip: boya
D (678) spi_flash: trying chip: th
D (682) spi_flash: trying chip: generic
I (686) spi_flash: detected chip: generic
I (690) spi_flash: flash io: dio
D (694) cpu_start: calling init function: 0x40081e74
D (699) cpu_start: calling init function: 0x400814f0
D (704) cpu_start: calling init function: 0x4008566c on core: 0
V (710) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (717) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE02
D (725) intr_alloc: Connected src 73 to int 10 (cpu 0)
D (730) cpu_start: calling init function: 0x4009f9ec on core: 0
V (736) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (742) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (750) intr_alloc: Connected src 28 to int 3 (cpu 0)
I (755) cpu_start: Starting scheduler on PRO CPU.
D (761) heap_init: New heap initialised at 0x3fffc000
V (761) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (771) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (771) intr_alloc: Connected src 17 to int 9 (cpu 0)
I (781) gpio: GPIO[12]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (791) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (801) gpio: GPIO[14]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (811) bridge_main: LED GPIO init done
D (811) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (821) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (831) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (831) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (841) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (851) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
V (851) TUSB:DCD: DCD init - Start
V (861) TUSB:DCD: DCD init - Soft DISCONNECT and Setting up
V (861) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (871) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (881) intr_alloc: Connected src 48 to int 12 (cpu 0)
D (881) boot: 0x3ffc5280   eb 3c 90 6d 6b 66 73 2e  66 61 74 00 02 08 01 00  |.<.mkfs.fat.....|
D (891) boot: 0x3ffc5290   01 20 00 00 c0 f8 18 00  00 00 00 00 00 00 00 00  |. ..............|
D (901) boot: 0x3ffc52a0   00 00 00 00 80 00 29 93  0c 3d 56 45 53 50 50 52  |......)..=VESPPR|
D (911) boot: 0x3ffc52b0   4f 47 5f 4d 53 43 46 41  54 31 36 20 20 20 0e 1f  |OG_MSCFAT16   ..|
D (921) boot: 0x3ffc52c0   be 5b 7c ac 22 c0 74 0b  56 b4 0e bb 07 00 cd 10  |.[|.".t.V.......|
D (931) boot: 0x3ffc52d0   5e eb f0 32 e4 cd 16 cd  19 eb fe 54 68 69 73 20  |^..2.......This |
D (941) boot: 0x3ffc52e0   69 73 20 6e 6f 74 20 61  20 62 6f 6f 74 61 62 6c  |is not a bootabl|
D (941) boot: 0x3ffc52f0   65 20 64 69 73 6b 2e 20  20 50 6c 65 61 73 65 20  |e disk.  Please |
D (951) boot: 0x3ffc5300   69 6e 73 65 72 74 20 61  20 62 6f 6f 74 61 62 6c  |insert a bootabl|
D (961) boot: 0x3ffc5310   65 20 66 6c 6f 70 70 79  20 61 6e 64 0d 0a 70 72  |e floppy and..pr|
D (971) boot: 0x3ffc5320   65 73 73 20 61 6e 79 20  6b 65 79 20 74 6f 20 74  |ess any key to t|
D (981) boot: 0x3ffc5330   72 79 20 61 67 61 69 6e  20 2e 2e 2e 20 0d 0a 00  |ry again ... ...|
D (991) boot: 0x3ffc5340   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1001) boot: 0x3ffc5350   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1011) boot: 0x3ffc5360   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1011) boot: 0x3ffc5370   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1021) boot: 0x3ffc5380   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1031) boot: 0x3ffc5390   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1041) boot: 0x3ffc53a0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1051) boot: 0x3ffc53b0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1061) boot: 0x3ffc53c0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1071) boot: 0x3ffc53d0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1081) boot: 0x3ffc53e0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1091) boot: 0x3ffc53f0   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1091) boot: 0x3ffc5400   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1101) boot: 0x3ffc5410   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1111) boot: 0x3ffc5420   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1121) boot: 0x3ffc5430   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1131) boot: 0x3ffc5440   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1141) boot: 0x3ffc5450   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1151) boot: 0x3ffc5460   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1161) boot: 0x3ffc5470   00 00 00 00 00 00 00 00  00 00 00 00 00 00 55 aa  |..............U.|
D (1161) fat: 0x3f006c20   f8 ff ff ff ff ff                                 |......|
D (1171) root: 0x3ffc5240   45 53 50 50 52 4f 47 5f  4d 53 43 08 00 00 00 00  |ESPPROG_MSC.....|
D (1181) root: 0x3ffc5250   00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
D (1191) root: 0x3ffc5260   52 45 41 44 4d 45 20 20  54 58 54 01 00 00 00 00  |README  TXT.....|
D (1201) root: 0x3ffc5270   00 00 00 00 00 00 00 00  00 00 02 00 73 00 00 00  |............s...|
I (1211) bridge_msc: MSC disk RAM usage: 698 bytes
I (1211) uart: queue free spaces: 20
V (1221) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1221) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1231) intr_alloc: Connected src 38 to int 13 (cpu 0)
I (1241) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1251) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1261) bridge_serial: UART & GPIO have been initialized
I (1261) gpio: GPIO[8]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1271) gpio: GPIO[9]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1281) gpio: GPIO[10]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1291) gpio: GPIO[3]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
D (1301) dedic_gpio: build platform on core[0] at 0x3ffc816c
D (1311) dedic_gpio: new outward bundle(0x3ffd0e24) on core[0], offset=0, mask(7)
D (1311) dedic_gpio: new inward bundle(0x3ffd0e4c) on core[0], offset=0, mask(1)
I (1321) bridge_jtag: JTAG GPIO init done
D (1321) bridge_jtag: Waiting for the device to be mounted...
D (1361) bridge_serial: usb_sender_task: nothing to send
D (1561) bridge_serial: usb_sender_task: nothing to send

Evidently, it's not a host issue. Moving on trying debugging on the Saola board alone.

AlbertoLopSie commented 1 year ago

Well... I've tried to compile the tusb_msc example and verified it's not working either (even after checking this)

I've left an issue there and let's see what happens.

Anyway... Is that necessary related to the bridge not working on the JTAG mode?

AlbertoLopSie commented 1 year ago

Trying the debug a test program on the ESP32-S2-Saola-1 board path...

I'm a bit (in fact, a LOT) confused...

PlatformIO doc says that this board DOES NOT SUPPORT built-in debugging but Espressif esp-usb-bridge say IT DOES or, at least, the ESP32-S2-WROVER my board has it's supposed to support it.

Does it?

Trying to set debug_tool = esp-builtin with this board fails.

What am I doing wrong?

AlbertoLopSie commented 1 year ago

Well... I've tried to compile the tusb_msc example and verified it's not working either (even after checking https://github.com/espressif/esp-idf/issues/10837#issuecomment-1508568357)

I've left https://github.com/espressif/idf-extra-components/issues/172 there and let's see what happens.

Anyway... Is that necessary related to the bridge not working on the JTAG mode?

Well... I've just learnt that the USB MSC port and the USB flash/monitor port are TWO DIFFERENT HARDWARE ANIMALS !! Two separate USB sockets!!

I connected a USB breakout board to GPIO pins 19/20 of my saola board an now I can see:

It's too late now here in Argentina (20:45) but I guess i'm now ready to start trying the debug bridge tomorrow!!

dobairoland commented 1 year ago

The lsusb output shows no bridge device. Until it is not there, makes no sense to try anything else. The CDC class is needed for monitoring/flashing, MSC for virtual storage and Vendor Class for JTAG. Please try to make to work the linked ESP-IDF examples with your Saola board.

PlatformIO doc says that this board DOES NOT SUPPORT built-in debugging but Espressif esp-usb-bridge say IT DOES or, at least, the ESP32-S2-WROVER my board has it's supposed to support it.

The Saola board does not support debugging (directly). If you want to debug it then you need an USB/JTAG dongle which will be connected to the JTAG pins of the board. In this case, the ESP32-S2 will be debugged on the Saola board.

The debugging capabilities of the esp-usb-bridge is something completely different. The USB is used to connect to the target MCU. That means you are not debugging the ESP32-S2 on the Saola board but the MCU connected to it.

I hope everything got answered. You answered some of your previous questions.

AlbertoLopSie commented 1 year ago

Thank you very much Roland for your help!

I have solved the MSC/Bridge Serial Port issue. It was my missunderstanding about to which USB port do I had to connect to.

I now have my debug setup connected this way:

platformio.ini contains:

debug_init_break = tbreak setup
debug_tool = esp-bridge
debug_port = /dev/cu.usbmodem686725C3AC8A1         # USB-2
upload_port = /dev/cu.wchusbserial532200114101          # USB-1
monitor_port = /dev/cu.wchusbserial532200114101        # USB-1

Staring a debug session produces:

undefinedOpen On-Chip Debugger v0.12.0-esp32-20230313 (2023-03-13-09:08)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselecting 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1002
Info : esp_usb_jtag: capabilities descriptor set to 0x30a
adapter speed: 40000 kHz

WARNING: boards/esp-wroom-32.cfg is deprecated, and may be removed in a future release.
Warn : Transport "jtag" was already selected
adapter speed: 5000 kHz

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : esp_usb_jtag: serial (686725C3AC8A)
Info : esp_usb_jtag: Device found. Base speed 4800KHz, div range 1 to 1
Info : clock speed 4800 kHz
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : starting gdb server for esp32.cpu0 on 3333
Info : Listening on port 3333 for gdb connections
Info : [esp32.cpu0] Target halted, PC=0x40087648, debug_reason=00000000
Info : [esp32.cpu0] Reset cause (1) - (Power on reset)
Info : [esp32.cpu1] Target halted, PC=0x400ED042, debug_reason=00000000
Info : [esp32.cpu1] Reset cause (14) - (CPU1 reset by CPU0)
Reading symbols from /Users/alberto/dev/ESP32/trh-esp32/.pio/build/esp32dev/firmware.elf...
PlatformIO Unified Debugger -> https://bit.ly/pio-debug
PlatformIO: debug_tool = esp-bridge
PlatformIO: Initializing remote target...
Ignoring packet error, continuing...
warning: unrecognized item "timeout" in "qSupported" response
Ignoring packet error, continuing...
.pioinit:11: Error in sourced command file:
Remote replied unexpectedly to 'vMustReplyEmpty': timeout

And debug does not start.

I guess I advanced a couple of steps, but still have not arrived!

I note a couple of thing I'm not sure what they mean, could you help me?

AlbertoLopSie commented 1 year ago

Well... new findings... I'll need your help here...

I noticed the target board was not resetting, even when the pio debug console says is...

Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
.....
PlatformIO: Initializing remote target...
Ignoring packet error, continuing...
warning: unrecognized item "timeout" in "qSupported" response
Ignoring packet error, continuing...
.pioinit:13: Error in sourced command file:
Remote replied unexpectedly to 'vMustReplyEmpty': timeout

Keeping an eye on the target device monitoring port I never see it resetting. I noted that on the esp-usb-bridge log:

I (274) gpio: GPIO[12]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (274) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (284) gpio: GPIO[14]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (294) bridge_main: LED GPIO init done
I (304) bridge_msc: MSC disk RAM usage: 698 bytes
I (304) uart: queue free spaces: 20
I (314) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (324) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (334) bridge_serial: UART & GPIO have been initialized
I (334) gpio: GPIO[8]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (344) gpio: GPIO[9]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (354) gpio: GPIO[10]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (364) gpio: GPIO[3]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (374) bridge_jtag: JTAG GPIO init done
I (544) bridge_jtag: Mounted

the OutputEn: 0 string in lines

I (314) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (324) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 

suggest me that GPIO were initialized well. The Espressif doc says that GPIO4 is usually free but GPIO7 is assigned to SPI Flash on boards featuring it, like mine.

So, I changed that GPIO to a free one, GPIO18 in this case. Now the logs shows almost the same regarding OutputEn:

I (314) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (324) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 

BUT... Now the target boards resets when the debug (esp-usb-bridge) does indicating that EN input on target board is no longer floating.

However, the target board never resets again during the attempted debug session, even when the bridge log shows:

I (15804) bridge_serial: BOOT = 1, RST = 1
I (156014) bridge_serial: DTR = 0, RTS = 0 -> BOOT = 1, RST = 1

presumably when openocd is sending some reset command.

It's a problem in the esp-usb-bridge JTAG logic?

AlbertoLopSie commented 1 year ago

More info...

I rebuilt the esp-usb-bridge with maximun debug level. It caused 2 interesting effects:

1) If I DON'T CONNECT to monitor port, the debug console log show some more info before cancelling. During that process the target board reset multiple times !!

undefinedOpen On-Chip Debugger v0.12.0-esp32-20230313 (2023-03-13-09:08)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselecting 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1002
Info : esp_usb_jtag: capabilities descriptor set to 0x30a
Info : esp_usb_jtag: target chip id set to 1
Warn : Transport "jtag" was already selected
adapter speed: 5000 kHz

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : esp_usb_jtag: serial (686725C3AC8A)
Info : esp_usb_jtag: Device found. Base speed 4800KHz, div range 1 to 1
Info : clock speed 4800 kHz
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : starting gdb server for esp32.cpu0 on 3333
Info : Listening on port 3333 for gdb connections
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Reading symbols from /Users/alberto/dev/ESP32/trh-esp32/.pio/build/esp32dev/firmware.elf...
PlatformIO Unified Debugger -> https://bit.ly/pio-debug
PlatformIO: debug_tool = custom
PlatformIO: Initializing remote target...
Info : [esp32.cpu0] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu0] Timed out waiting for CPU to be reset, target state=2
Info : [esp32.cpu0] Reset cause (52) - (Unknown reset cause)
Warn : [esp32.cpu0] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu1] Timed out waiting for CPU to be reset, target state=2
Warn : [esp32.cpu1] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu0] Timed out waiting for CPU to be reset, target state=2
Info : [esp32.cpu0] Reset cause (52) - (Unknown reset cause)
Warn : [esp32.cpu0] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Ignoring packet error, continuing...
warning: unrecognized item "timeout" in "qSupported" response
Info : [esp32.cpu1] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu1] Timed out waiting for CPU to be reset, target state=2
Warn : [esp32.cpu1] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu0] Timed out waiting for CPU to be reset, target state=2
Info : [esp32.cpu0] Reset cause (52) - (Unknown reset cause)
Warn : [esp32.cpu0] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu1] Timed out waiting for CPU to be reset, target state=2
Warn : [esp32.cpu1] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: [esp32.cpu0] Timed out waiting for CPU to be reset, target state=2
Info : [esp32.cpu0] Reset cause (52) - (Unknown reset cause)
Warn : [esp32.cpu0] Timed out waiting for target to finish stepping. dsr=0x8000c000
Info : [esp32.cpu1] Debug controller was reset.
Info : [esp32.cpu1] Core was reset.
Info : [esp32.cpu0] Debug controller was reset.
Info : [esp32.cpu0] Core was reset.
Ignoring packet error, continuing...
.pioinit:13: Error in sourced command file:
Remote replied unexpectedly to 'vMustReplyEmpty': timeout
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 1139 is closed

2) If I CONNECT to monitor port, a never ending flow of messages make impossible to understand anything, so greping the output produces:

$ idf.py -p /dev/cu.SLAB_USBtoUART flash monitor | grep "bridge_jtag" 
--- idf_monitor on /dev/cu.SLAB_USBtoUART 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
0x40081e74: esp_reset_reason_init at /Users/alberto/esp-idf/components/esp_system/port/soc/esp32s2/reset_reason.c:67
0x400814f0: esp_init_app_elf_sha256 at /Users/alberto/esp-idf/components/esp_app_format/esp_app_desc.c:69
0x4008566c: __esp_system_init_fn_esp_timer_startup_init at /Users/alberto/esp-idf/components/esp_timer/src/esp_timer.c:509
0x4009f9ec: __esp_system_init_fn_init_components0 at /Users/alberto/esp-idf/components/esp_system/startup.c:484

I (2651) bridge_jtag: Mounted
D (2661) bridge_jtag: Device mounted!
I (16011) bridge_jtag: bRequest: (3) wValue: (1) wIndex: (0)
[0;32mI (16141) bridge_jtag: bRequest: (0) wValue: (1) wIndex: (0)
D (16591) bridge_jtag: 0x3ffd0f5c   8a                                                |.|
D (16821) bridge_jtag: 0x3ffd0f5d   aa                                                |.|
D (17041) bridge_jtag: 0x3ffd0f5e   2e da                                             |..|
D (17111) bridge_jtag: 0x3ffd0f60   2e 02 0d 5e fd ee 70 2e  da                       |...^..p..|
D (24121) bridge_jtag: Space was 64, USB sent 64 bytes
D (24201) bridge_jtag: Space was 64, USB sent 20 bytes
I (26481) bridge_jtag: Mounted
I (39411) bridge_jtag: Mounted

The problem is that, on the other side something does not works fine:

undefinedOpen On-Chip Debugger v0.12.0-esp32-20230313 (2023-03-13-09:08)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselecting 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1002
Info : esp_usb_jtag: capabilities descriptor set to 0x30a
Info : esp_usb_jtag: target chip id set to 1
Warn : Transport "jtag" was already selected
adapter speed: 5000 kHz

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : esp_usb_jtag: serial (686725C3AC8A)
Info : esp_usb_jtag: Device found. Base speed 4800KHz, div range 1 to 1
Info : clock speed 4800 kHz
Reading symbols from /Users/alberto/dev/ESP32/trh-esp32/.pio/build/esp32dev/firmware.elf...
PlatformIO Unified Debugger -> https://bit.ly/pio-debug
PlatformIO: debug_tool = custom
PlatformIO: Initializing remote target...
Error: libusb_bulk_read error: LIBUSB_ERROR_TIMEOUT
.pioinit:13: Error in sourced command file:
Remote communication error.  Target disconnected.: Device not configured.

I'm suspecting a timing issue.

dobairoland commented 1 year ago

Please see https://github.com/espressif/esp-usb-bridge#known-issues. You might need to add that extra timeout. The debugging is a little slow. We plan to address this in the near future.

AlbertoLopSie commented 1 year ago

Yep... added that line to the .gdbinit file, and no change.

The funny thing is that the bridge seemed to work a bit better when I (inadvertently) introduced delays into the bridge code (the verbose logging and its serial transmitting) I don't see it related to the GDB config. Do you?

I guess I'm dealing with a multiple-head animal here:

Based on your xp an d knowledge of esp-usb-bridge, do you fell are able to pinpoint which one of this layers is causing the failure?

AlbertoLopSie commented 1 year ago

New findings...

I decided to split the problem in parts... I first tried to upload an image only, so configured platformio.ini this way:

debug_init_break = tbreak setup
debug_tool = esp-bridge
upload_protocol = esp-bridge

Despite some Ringbuffer is getting full! warnings the upload worked great. I reduced the number the warnings to almozt zero changing this line in jtag.c:

#define USB_RCVBUF_SIZE             (64*1024) //16384 //8192//4096

As you can see I tried doubling the original 4K size until I got no warnings.

This test reveals me this facts:

The weird thing is that over all the upload process the most active LED is the JTAG one. Only a slight flash of the TX LED at the end on the process is seen. Is this Ok?

Question: Is uploading going thru the TX/RX pins on the target device? Or is going thru the JTAG interface?

Debug, however is still failing, but I'm starting to suspect the problem is in the PlatformIO/openocd/GDB area.

dobairoland commented 1 year ago

Question: Is uploading going thru the TX/RX pins on the target device? Or is going thru the JTAG interface?

This is a bridge. That means if you debug (JTAG) then between the host MCU and target MCU the JTAG lines are used. If you flash/monitor (serial) then serial lines are used on the other end as well.

Only a slight flash of the TX LED at the end on the process is seen.

Probably your target MCU is printing something.

my ESP32 target board

What application is running there? Was it successfully flashed before you attempt to debug it? Some states might interfere with debugging (e.g. clear flash and the chip is in boot loop, watchdog timers continuously rebooting).

Do you have a programmable LED in your ESP32 board? I find very useful to flash the blink example for testing purposes. Periodic printing and visual blinking helps a lot. E.g. I can see without using anything if the board is in reset or working (blinking and printing).

You can increase the debugging level of openocd. That could also reveal potentional issues.

AlbertoLopSie commented 1 year ago

Hi Roland,

If you flash/monitor (serial) then serial lines are used on the other end as well.

The reason to this question is to isolate wiring problems. Flashing is working fine, if flashing is made using the TX/RX lines (on the target CPU) I may suppose those wires are Ok. If flashing goes by the JTAG pins, is that wiring I could consider ok and look another way.

Rephrasing, Is there anything in the logs that could suggest a wiring problem in the JTAG interface? Or some of the messages indicating correct CPU Id for example, indicate that the bridge is communication fine through JTAG?

Probably your target MCU is printing something.

Nope. TX on the bridge. RX on the target CPU. It is the bridge sending something.

What application is running there?

A simple Blink app

#include <Arduino.h>

int pin = 2; //IO2 has a LED connected to it on the wrooom board

void setup() {
  pinMode(pin, OUTPUT);
}

void loop() {
    digitalWrite(pin, HIGH);
    delay(250);
    digitalWrite(pin, LOW);
    delay(250);
}

You can increase the debugging level of openocd. That could also reveal potentional issues.

I tried to increase it to 4 but it's causing VSCode/PlatformIO to freeze. I'll try to send it to a file to see if it helps.

AlbertoLopSie commented 1 year ago

@dobairoland : Please see this issue on the openocd-esp32 repo related to the same problem.

It contains the level 4 logging but I'm not being able to get any useful info from it.

dobairoland commented 1 year ago

Rephrasing, Is there anything in the logs that could suggest a wiring problem in the JTAG interface? Or some of the messages indicating correct CPU Id for example, indicate that the bridge is communication fine through JTAG?

Yes, the following is shown in your log:

Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)

There is a lot of communication through JTAG. You won't get the above by luck. The JTAG wiring should be OK.

dobairoland commented 1 year ago

I see no obvious issue in the log. But the team for openocd is more experienced in that. Let's wait for their response....

AlbertoLopSie commented 1 year ago

Hi @dobairoland!

I searched across espressif/openocd-esp32 for the qSupported error the debug console trows:

warning: unrecognized item "timeout" in "qSupported" response
Ignoring packet error, continuing...
.pioinit:11: Error in sourced command file:
Remote replied unexpectedly to 'vMustReplyEmpty': timeout

And found:

Searching vMustReplyEmpty gives similar results.

Does anything of this make any sound to you?

AlbertoLopSie commented 1 year ago

SOLVED!!!!

YOU WON'T BELIEVE THE REASON!!

ESP-PROG - openocd path contains "undefined" - Advanced Solutions / Debugging - PlatformIO Community

dobairoland commented 1 year ago

Oh, a platformio setup issue?

I'm happy that you solved it.