Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cannot debug ESP32 through esp-usb-bridge (OCD-748) #286

Closed
AlbertoLopSie opened this issue Apr 26, 2023 · 5 comments
Closed

Cannot debug ESP32 through esp-usb-bridge (OCD-748) #286

AlbertoLopSie opened this issue Apr 26, 2023 · 5 comments

Comments

@AlbertoLopSie
Copy link

Development Kit

ESP32-DevkitC

Module or chip used

ESP32WROOM32

Debug Adapter

esp-usb-bridge

OpenOCD version

v0.12.0-esp32-20230313 (2023-03-13-09:08)

Operating System

Mac OSX 10.15.7 (Catalina)

Using an IDE ?

VSCode

OpenOCD command line

openocd -d3 -f board/esp32-bridge.cfg

JTAG Clock Speed

default

ESP-IDF version

5.1

Problem Description

ESP32-Devkit connected to esp-usb-bridge as the schematic suggest.

Trying to debug on VSCode with PlatformIO IDE extension

PlatformIO version
Core: 6.1.6
Home 3.4.3

platformio.ini:

upload_protocol = esp-bridge

; debug_tool = esp-bridge       ; replaced by custom tool to allow debug logging
debug_tool = custom

debug_speed = 1000
debug_server = 
  ${platformio.packages_dir}/tool-openocd-esp32/bin/openocd
  -d3
  -f
  board/esp32-bridge.cfg

Uploading is working fine. Debugging is not.

More info on this esp-usb-bridge issue

See log on my gdrive

I guess the interesting lines are the end, after PlatformIO: Initializing remote target.... It takes about 5-10 minutes to be produced (I guess some process is insisting in getting 4 bytes out of 2 and retrying).

I also have on another window the log generated by esp-usb-bridge if you think is useful (I don't see anything wrong there)

Any clue about this??

Debug Logs

Too long to be accepted here. Get [it from my gdrive](https://drive.google.com/file/d/16JIYCN2utahjGFnBNCdrpHx43CIEvMfG/view?usp=share_link)

Expected behavior

I should be able to start a debugging session

Screenshots

N/A

@github-actions github-actions bot changed the title Cannot debug ESP32 through esp-usb-bridge Cannot debug ESP32 through esp-usb-bridge (OCD-748) Apr 26, 2023
@AlbertoLopSie
Copy link
Author

AlbertoLopSie commented Apr 27, 2023

Following a suggestion from dobairoland on a related issue on espressif/esp-usb-bridge I increased the debug level of the openocd execution. I coudn't be able to doit inside the PlatformIO extension I'm using, but managed to do it on a terminal shell:

$ ./openocd -d4 -l /Users/alberto/dev/ESP32/trh-esp32/openocd.log -f board/esp32-bridge.cfg
Open 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
User : 3 1 options.c:52 configuration_output_handler(): debug_level: 4
User : 4 1 options.c:52 configuration_output_handler(): 
Debug: 5 1 command.c:155 script_debug(): command - log_output /Users/alberto/dev/ESP32/trh-esp32/openocd.log

After a 5-10 minutes running, the log accumulated almost half a GB, so I had to cancel it.

Here is the link to the log on my GDrive.

Up to the end of the logfile (before the terminating signal) there is a pattern that repeats over and over:

Debug: 7115831 768263 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7115832 768263 bitq.c:248 bitq_execute_queue(): scan ir
Debug: 7115833 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115834 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115835 768263 bitq.c:106 bitq_state_move(): tap_set_state(IRSHIFT)
Debug: 7115836 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115837 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7115846 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115847 768263 bitq.c:185 bitq_scan_field(): tap_set_state(IRPAUSE)
Debug: 7115848 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115849 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115850 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115851 768263 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7115852 768263 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7115853 768263 bitq.c:248 bitq_execute_queue(): scan dr
Debug: 7115854 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115855 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115856 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115857 768263 bitq.c:106 bitq_state_move(): tap_set_state(DRSHIFT)
Debug: 7115858 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115859 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7115867 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115868 768263 bitq.c:187 bitq_scan_field(): tap_set_state(DRPAUSE)
Debug: 7115869 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115870 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115871 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115872 768263 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7115873 768263 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7115874 768263 bitq.c:248 bitq_execute_queue(): scan dr
Debug: 7115875 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115876 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115877 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115878 768263 bitq.c:106 bitq_state_move(): tap_set_state(DRSHIFT)
Debug: 7115879 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115880 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7115912 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115913 768263 bitq.c:187 bitq_scan_field(): tap_set_state(DRPAUSE)
Debug: 7115914 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115915 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115916 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115917 768263 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7115918 768263 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7115919 768263 bitq.c:248 bitq_execute_queue(): scan ir
Debug: 7115920 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115921 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115922 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115923 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115924 768263 bitq.c:106 bitq_state_move(): tap_set_state(IRSHIFT)
Debug: 7115925 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115926 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7115935 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115936 768263 bitq.c:185 bitq_scan_field(): tap_set_state(IRPAUSE)
Debug: 7115937 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115938 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115939 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115940 768263 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7115941 768263 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7115942 768263 bitq.c:248 bitq_execute_queue(): scan dr
Debug: 7115943 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115944 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115945 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115946 768263 bitq.c:106 bitq_state_move(): tap_set_state(DRSHIFT)
Debug: 7115947 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115948 768263 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7115956 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115957 768264 bitq.c:187 bitq_scan_field(): tap_set_state(DRPAUSE)
Debug: 7115958 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115959 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115960 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115961 768264 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7115962 768264 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7115963 768264 bitq.c:248 bitq_execute_queue(): scan dr
Debug: 7115964 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115965 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115966 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115967 768264 bitq.c:106 bitq_state_move(): tap_set_state(DRSHIFT)
Debug: 7115968 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7115969 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7116000 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116001 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116002 768264 bitq.c:187 bitq_scan_field(): tap_set_state(DRPAUSE)
Debug: 7116003 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116004 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116005 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116006 768264 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7116007 768264 bitq.c:247 bitq_execute_queue(): scan end in 11
Debug: 7116008 768264 bitq.c:248 bitq_execute_queue(): scan ir
Debug: 7116009 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116010 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116011 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116012 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116013 768264 bitq.c:106 bitq_state_move(): tap_set_state(IRSHIFT)
Debug: 7116014 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116015 768264 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116016 768264 bitq.c:185 bitq_scan_field(): tap_set_state(IRPAUSE)
Debug: 7116017 768264 esp_usb_jtag.c:564 esp_usb_jtag_flush(): esp_usb_jtag: Flush!
Debug: 7116018 768264 esp_usb_jtag.c:441 esp_usb_jtag_send_buf(): esp_usb_jtag: sent 43 bytes.
Debug: 7116019 768267 esp_usb_jtag.c:424 esp_usb_jtag_recv_buf(): esp_usb_jtag: In ep: received 4 bytes; 0 bytes (0 bits) left.
Debug: 7116020 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG IR SCAN to RUN/IDLE
Debug: 7116021 768267 core.c:967 default_interface_jtag_execute_queue():   5b out: 1f
Debug: 7116022 768267 core.c:967 default_interface_jtag_execute_queue():   5b out: 1c
Debug: 7116023 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG DR SCAN to RUN/IDLE
Debug: 7116024 768267 core.c:967 default_interface_jtag_execute_queue():   8b out: 87
Debug: 7116025 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG DR SCAN to RUN/IDLE
Debug: 7116026 768267 core.c:967 default_interface_jtag_execute_queue():   32b out: 00000001
Debug: 7116027 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG IR SCAN to RUN/IDLE
Debug: 7116028 768267 core.c:967 default_interface_jtag_execute_queue():   5b out: 1f
Debug: 7116029 768267 core.c:967 default_interface_jtag_execute_queue():   5b out: 1c
Debug: 7116030 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG DR SCAN to RUN/IDLE
Debug: 7116031 768267 core.c:967 default_interface_jtag_execute_queue():   8b out: 88
Debug: 7116032 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG DR SCAN to RUN/IDLE
Debug: 7116033 768267 core.c:967 default_interface_jtag_execute_queue():   32b out: 00000000
Debug: 7116034 768267 core.c:972 default_interface_jtag_execute_queue():   32b  in: 8000cc01
Debug: 7116035 768267 core.c:962 default_interface_jtag_execute_queue(): JTAG IR SCAN to IRPAUSE
Debug: 7116036 768267 core.c:967 default_interface_jtag_execute_queue():   1b out: 00
Debug: 7116037 768267 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7116038 768267 bitq.c:248 bitq_execute_queue(): scan ir
Debug: 7116039 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116040 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116041 768267 bitq.c:106 bitq_state_move(): tap_set_state(IRSHIFT)
Debug: 7116042 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116043 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7116052 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116053 768267 bitq.c:185 bitq_scan_field(): tap_set_state(IRPAUSE)
Debug: 7116054 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116055 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116056 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116057 768267 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7116058 768267 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7116059 768267 bitq.c:248 bitq_execute_queue(): scan dr
Debug: 7116060 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116061 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116062 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116063 768267 bitq.c:106 bitq_state_move(): tap_set_state(DRSHIFT)
Debug: 7116064 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116065 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7116073 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116074 768267 bitq.c:187 bitq_scan_field(): tap_set_state(DRPAUSE)
Debug: 7116075 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116076 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116077 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116078 768267 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7116079 768267 bitq.c:247 bitq_execute_queue(): scan end in 12
Debug: 7116080 768267 bitq.c:248 bitq_execute_queue(): scan dr
Debug: 7116081 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116082 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116083 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116084 768267 bitq.c:106 bitq_state_move(): tap_set_state(DRSHIFT)
Debug: 7116085 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116086 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
----------------------- [ MANY LINES LIKE THIS] -----------------------
Debug: 7116117 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116118 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116119 768267 bitq.c:187 bitq_scan_field(): tap_set_state(DRPAUSE)
Debug: 7116120 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116121 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116122 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116123 768267 bitq.c:106 bitq_state_move(): tap_set_state(RUN/IDLE)
Debug: 7116124 768267 bitq.c:247 bitq_execute_queue(): scan end in 11
Debug: 7116125 768267 bitq.c:248 bitq_execute_queue(): scan ir
Debug: 7116126 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116127 768267 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116128 768268 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116129 768268 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116130 768268 bitq.c:106 bitq_state_move(): tap_set_state(IRSHIFT)
Debug: 7116131 768268 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116132 768268 bitq.c:51 bitq_in_proc(): bitq in EOF
Debug: 7116133 768268 bitq.c:185 bitq_scan_field(): tap_set_state(IRPAUSE)
Debug: 7116134 768268 esp_usb_jtag.c:564 esp_usb_jtag_flush(): esp_usb_jtag: Flush!
Debug: 7116135 768268 esp_usb_jtag.c:441 esp_usb_jtag_send_buf(): esp_usb_jtag: sent 23 bytes.
Debug: 7116136 768272 esp_usb_jtag.c:424 esp_usb_jtag_recv_buf(): esp_usb_jtag: In ep: received 4 bytes; 0 bytes (0 bits) left.
Debug: 7116137 768272 core.c:962 default_interface_jtag_execute_queue(): JTAG IR SCAN to RUN/IDLE
Debug: 7116138 768272 core.c:967 default_interface_jtag_execute_queue():   5b out: 1f
Debug: 7116139 768272 core.c:967 default_interface_jtag_execute_queue():   5b out: 1c
Debug: 7116140 768272 core.c:962 default_interface_jtag_execute_queue(): JTAG DR SCAN to RUN/IDLE
Debug: 7116141 768272 core.c:967 default_interface_jtag_execute_queue():   8b out: 0a
Debug: 7116142 768272 core.c:962 default_interface_jtag_execute_queue(): JTAG DR SCAN to RUN/IDLE
Debug: 7116143 768272 core.c:967 default_interface_jtag_execute_queue():   32b out: 00000000
Debug: 7116144 768272 core.c:972 default_interface_jtag_execute_queue():   32b  in: 00000000
Debug: 7116145 768272 core.c:962 default_interface_jtag_execute_queue(): JTAG IR SCAN to IRPAUSE
Debug: 7116146 768272 core.c:967 default_interface_jtag_execute_queue():   1b out: 00

One detail that may be not apparent just seen the logs... After the lines like:

Debug: 7116146 768272 core.c:967 default_interface_jtag_execute_queue():   1b out: 00

There are several seconds (I couldn't measure them) until the cycle repeats. Perhaps on that time window openocd is waiting for something more to arrive that never does.

I later retried it under VSCode/PlatformIO and waited to abort. Once VSCode/PlatformIO finished retrying it finally aborted with:

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
User : 3 2 options.c:52 configuration_output_handler(): debug_level: 4
User : 4 2 options.c:52 configuration_output_handler():
Debug: 5 2 command.c:155 script_debug(): command - log_output /Users/alberto/dev/ESP32/trh-esp32/openocd.log
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...
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

The complete compressed log (has more than 800MB) is here.

@AlbertoLopSie
Copy link
Author

I searched across this repo 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?

@AlbertoLopSie
Copy link
Author

@erhankur
Copy link
Collaborator

erhankur commented May 2, 2023

@AlbertoLopSie Sorry, we couldn't get involved in the early stage but glad you found the issue.

@erhankur erhankur closed this as completed May 2, 2023
@ivankravets
Copy link

@AlbertoLopSie how did you solve this issue?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants