Optimize ESP32S2-Saola-1 remote bitbang w/ Glasgow JTAG (OCD-289)

[brainstorm]

As commented in the issue originated in https://github.com/espressif/openocd-esp32/pull/134 and my subsequent attempts under:

https://github.com/espressif/vscode-esp-idf-extension/issues/285#issuecomment-757549031

The first error in the debug logs is:

Error: 340 5543 target.c:587 target_halt(): Target not examined yet

I've added the gdb-attach behavior since it was missing in the esp32s2.cfg openocd target like so:

$ git diff esp32s2.cfg.orig esp32s2.cfg
diff --git a/esp32s2.cfg.orig b/esp32s2.cfg
index 7048028..6e73a59 100644
--- a/esp32s2.cfg.orig
+++ b/esp32s2.cfg
@@ -24,7 +24,6 @@ set _CPUNAME cpu
 set _TAPNAME $_CHIPNAME.$_CPUNAME

 jtag newtap $_CHIPNAME $_CPUNAME -irlen 5 -expected-id $_CPUTAPID
-
 if { $_RTOS == "none" } {
     target create $_TARGETNAME esp32s2 -endian little -chain-position $_TAPNAME
 } else {
@@ -38,6 +37,13 @@ xtensa maskisr on
 if { $_SEMIHOST_BASEDIR != "" } {
     esp semihost_basedir $_SEMIHOST_BASEDIR
 }
+
+configure -event gdb-attach {
+# necessary to auto-probe flash bank when GDB is connected
+halt
+}
+
+
 if { $_FLASH_SIZE == 0 } {
     gdb_breakpoint_override hard
 }

But that doesn't seem to help, I've also noticed other issues that were hitting similar symptoms but none of the solutions proposed (if any) seem to help in my case (i.e https://github.com/espressif/openocd-esp32/issues/65, https://github.com/espressif/openocd-esp32/issues/69, https://github.com/espressif/openocd-esp32/issues/73, https://github.com/espressif/openocd-esp32/issues/105, etc...)

I also triple-checked the JTAG wiring (seems to be fine since Glasgow's jtag-probe applet correctly identifies the Tensilica JTAG ID):

$ glasgow run jtag-probe --port A --pin-tck 0 --pin-tms 3 --pin-tdi 2 --pin-tdo 1 -V 3.4 scan
I: g.device.hardware: building bitstream ID b6fbfeae7352e28e3719e661c983c486
I: g.cli: running handler for applet 'jtag-probe'
I: g.applet.interface.jtag_probe: port(s) A voltage set to 3.4 V
I: g.applet.interface.jtag_probe: shifted 32-bit DR=<10100111001011000000000001001000>
I: g.applet.interface.jtag_probe: shifted 5-bit IR=<10000>
I: g.applet.interface.jtag_probe: discovered 1 TAPs
I: g.applet.interface.jtag_probe: TAP #0: IR[5] IDCODE=0x120034e5
I: g.applet.interface.jtag_probe: manufacturer=0x272 (Tensilica) part=0x2003 version=0x1

openocd_log_boot_mode.txt openocd_log_app_mode.txt gdb_log.txt gdbinit.txt

[brainstorm]

Breakpointing and exploring w/ lldb:

lldb -- openocd -d3 -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig

in target_halt() and reading some code I'm wondering why esp32s2_soc_reset() is never called on my OpenOCD sessions? Seems to do exactly what's needed for the ESP32S2?

/cc @gerekon

[brainstorm]

Now things might get a bit more interesting with -c "init; reset; halt" as @projectgus kindly pointed out:

$ openocd -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig -c "init; reset; halt"
Open On-Chip Debugger  v0.10.0-esp32-20201202-2-g7e342cad (2021-01-02-23:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Warn : Transport "jtag" was already selected
Info : FreeRTOS creation
Info : Initializing remote_bitbang driver
Info : Connecting to localhost:5555
Info : remote_bitbang driver initialized
Info : This adapter doesn't support configurable speed
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32s2: Core was reset.
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Warn : Unexpected idcode after end of chain: 384 0x0000003f
Warn : Unexpected idcode after end of chain: 416 0x00000000
Warn : Unexpected idcode after end of chain: 448 0x00000000
Warn : Unexpected idcode after end of chain: 480 0x00000000
Warn : Unexpected idcode after end of chain: 512 0x00000000
Warn : Unexpected idcode after end of chain: 544 0x00000000
Warn : Unexpected idcode after end of chain: 576 0x00000000
Warn : Unexpected idcode after end of chain: 608 0x00000000
Warn : Unexpected idcode after end of chain: 640 0x00000000
Error: double-check your JTAG setup (interface, speed, ...)
Error: Trying to use configured scan chain anyway...
Warn : Bypassing JTAG setup events due to errors
Info : esp32s2: Core was reset.
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Info : esp32s2: Debug controller was reset.
Error: esp32s2_soc_reset: Couldn't halt target before SoC reset

Info : remote_bitbang interface quit

Time to connect my oscilloscope to those JTAG lines and step through the Glasgow applet it seems, I'll be right back ;)

[brainstorm]

I'm not seeing anything weird on those waveforms, but after connecting the probes I'm getting the following:

Every 1.0s: openocd -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig -c 'init; reset; halt'                                                                                                                                             brainstorm.local: Wed Jan 13 23:59:30 2021

Open On-Chip Debugger  v0.10.0-esp32-20201202-2-g7e342cad (2021-01-02-23:47)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Warn : Transport "jtag" was already selected
Info : FreeRTOS creation
Info : Initializing remote_bitbang driver
Info : Connecting to localhost:5555
Info : remote_bitbang driver initialized
Info : This adapter doesn't support configurable speed
Error: JTAG scan chain interrogation failed: all zeroes
Error: Check JTAG interface, timings, target power, etc.
Error: Trying to use configured scan chain anyway...
Error: esp32s2.cpu: IR capture error; saw 0x00 not 0x01
Warn : Bypassing JTAG setup events due to errors
Info : Listening on port 3333 for gdb connections
Error: JTAG scan chain interrogation failed: all zeroes
Error: Check JTAG interface, timings, target power, etc.
Error: Trying to use configured scan chain anyway...
Error: esp32s2.cpu: IR capture error; saw 0x00 not 0x01
Warn : Bypassing JTAG setup events due to errors
Error: esp32s2_soc_reset: Couldn't halt target before SoC reset

Info : remote_bitbang interface quit

[brainstorm]

After flashing the firmware with the following commandline:

$ ~/dev/esp-idf/tools/idf.py build && /Users/romanvg/.espressif/python_env/idf4.3_py3.9_env/bin/python3 ../../esp-idf/components/esptool_py/esptool/esptool.py -p /dev/cu.SLAB_USBtoUART -b 460800 --before default_reset --after hard_reset --chip esp32s2  write_flash --flash_mode dio --flash_size detect --flash_freq 80m 0x1000 build/bootloader/bootloader.bin 0x8000 build/partition_table/partition-table.bin 0x10000 build/twai_network_slave.bin
Executing action: all (aliases: build)
Running ninja in directory /Users/romanvg/dev/esp32s2_can/twai_network_slave/build
Executing "ninja all"...
[1/3] Performing build step for 'bootloader'
ninja: no work to do.

Project build complete. To flash, run this command:
/Users/romanvg/.espressif/python_env/idf4.3_py3.9_env/bin/python3 ../../esp-idf/components/esptool_py/esptool/esptool.py -p (PORT) -b 460800 --before default_reset --after hard_reset --chip esp32s2  write_flash --flash_mode dio --flash_size detect --flash_freq 80m 0x1000 build/bootloader/bootloader.bin 0x8000 build/partition_table/partition-table.bin 0x10000 build/twai_network_slave.bin
or run 'idf.py -p (PORT) flash'
esptool.py v3.1-dev
Serial port /dev/cu.SLAB_USBtoUART
Connecting.....
Chip is ESP32-S2
Features: WiFi, ADC and temperature sensor calibration in BLK2 of efuse
Crystal is 40MHz
MAC: 7c:df:a1:00:ab:80
Uploading stub...
Running stub...
Stub running...
Changing baud rate to 460800
Changed.
Configuring flash size...
Auto-detected Flash size: 4MB
Flash params set to 0x022f
Compressed 20624 bytes to 12691...
Wrote 20624 bytes (12691 compressed) at 0x00001000 in 0.3 seconds (effective 564.1 kbit/s)...
Hash of data verified.
Compressed 3072 bytes to 103...
Wrote 3072 bytes (103 compressed) at 0x00008000 in 0.0 seconds (effective 2204.9 kbit/s)...
Hash of data verified.
Compressed 154128 bytes to 85591...
Wrote 154128 bytes (85591 compressed) at 0x00010000 in 2.0 seconds (effective 607.7 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...

I'm getting this output from OpenOCD right after:

$ openocd -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig -c 'init; reset; halt;'
Open On-Chip Debugger  v0.10.0-esp32-20201202-2-g7e342cad (2021-01-02-23:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Warn : Transport "jtag" was already selected
Info : FreeRTOS creation
Info : Initializing remote_bitbang driver
Info : Connecting to localhost:5555
Info : remote_bitbang driver initialized
Info : This adapter doesn't support configurable speed
Info : JTAG tap: esp32s2.cpu tap/device found: 0xffffffff (mfg: 0x7ff (<invalid>), part: 0xffff, ver: 0xf)
Warn : JTAG tap: esp32s2.cpu       UNEXPECTED: 0xffffffff (mfg: 0x7ff (<invalid>), part: 0xffff, ver: 0xf)
Error: JTAG tap: esp32s2.cpu  expected 1 of 1: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Warn : Unexpected idcode after end of chain: 160 0x1fffffff
Warn : Unexpected idcode after end of chain: 192 0x00000000
Warn : Unexpected idcode after end of chain: 224 0xf0000000
Warn : Unexpected idcode after end of chain: 320 0x0000ffff
Warn : Unexpected idcode after end of chain: 352 0x00000000
Warn : Unexpected idcode after end of chain: 384 0x00000000
Warn : Unexpected idcode after end of chain: 416 0xfe000000
Warn : Unexpected idcode after end of chain: 480 0x00ffffff
Warn : Unexpected idcode after end of chain: 512 0x00000000
Warn : Unexpected idcode after end of chain: 544 0x00000000
Warn : Unexpected idcode after end of chain: 576 0x00000000
Warn : Unexpected idcode after end of chain: 608 0xffc00000
Error: double-check your JTAG setup (interface, speed, ...)
Error: Trying to use configured scan chain anyway...
Error: esp32s2.cpu: IR capture error; saw 0x00 not 0x01
Warn : Bypassing JTAG setup events due to errors
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0xffffffff (mfg: 0x7ff (<invalid>), part: 0xffff, ver: 0xf)
Warn : JTAG tap: esp32s2.cpu       UNEXPECTED: 0xffffffff (mfg: 0x7ff (<invalid>), part: 0xffff, ver: 0xf)
Error: JTAG tap: esp32s2.cpu  expected 1 of 1: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: auto0.tap tap/device found: 0x7fffffff (mfg: 0x7ff (<invalid>), part: 0xffff, ver: 0x7)
Info : TAP auto1.tap has invalid IDCODE (0x0)
Info : TAP auto2.tap has invalid IDCODE (0x0)
Info : TAP auto3.tap has invalid IDCODE (0x0)
Info : TAP auto4.tap has invalid IDCODE (0x0)
Info : TAP auto5.tap has invalid IDCODE (0x0)
Info : TAP auto6.tap has invalid IDCODE (0x0)
Info : TAP auto7.tap has invalid IDCODE (0x0)
Info : TAP auto8.tap has invalid IDCODE (0x0)
Info : TAP auto9.tap has invalid IDCODE (0x0)
Info : TAP auto10.tap has invalid IDCODE (0x0)
Info : TAP auto11.tap has invalid IDCODE (0x0)
Info : TAP auto12.tap has invalid IDCODE (0x0)
Info : TAP auto13.tap has invalid IDCODE (0x0)
Info : TAP auto14.tap has invalid IDCODE (0x0)
Info : TAP auto15.tap has invalid IDCODE (0x0)
Info : TAP auto16.tap has invalid IDCODE (0x0)
Info : TAP auto17.tap has invalid IDCODE (0x0)
Info : TAP auto18.tap has invalid IDCODE (0x0)
Info : TAP auto19.tap has invalid IDCODE (0x0)
Warn : Unexpected idcode after end of chain: 83 0x00000000
Warn : Unexpected idcode after end of chain: 115 0x00000000
Warn : Unexpected idcode after end of chain: 147 0xfc000000
Warn : Unexpected idcode after end of chain: 243 0x000001ff
Warn : Unexpected idcode after end of chain: 275 0x00000000
Warn : Unexpected idcode after end of chain: 307 0xffffff00
Warn : Unexpected idcode after end of chain: 371 0x0000007f
Warn : Unexpected idcode after end of chain: 403 0x00000000
Warn : Unexpected idcode after end of chain: 435 0x00000000
Warn : Unexpected idcode after end of chain: 467 0x00000000
Warn : Unexpected idcode after end of chain: 499 0xffffffe0
Warn : Unexpected idcode after end of chain: 563 0x0000000f
Warn : Unexpected idcode after end of chain: 595 0x00000000
Warn : Unexpected idcode after end of chain: 627 0x00000000
Error: double-check your JTAG setup (interface, speed, ...)
Error: Trying to use configured scan chain anyway...
Error: esp32s2.cpu: IR capture error; saw 0x00 not 0x01
Warn : Bypassing JTAG setup events due to errors
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Error: esp32s2_soc_reset: Couldn't halt target before SoC reset

Info : remote_bitbang interface quit

[brainstorm]

For some reason I was having some mid-level voltages and other artifacts, after reviewing the cables once more the waveforms look a bit better (Light-blue: TCK, Yellow: TDO, Dark Blue: TDI, Green: TMS):

But I'm still getting unexpected messages... the target flashes and seems to run the app well anyway, so I'm not sure if this is a symptom of a damaged JTAG pins/port?:

$ openocd -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig -c 'init; reset; halt;'
Open On-Chip Debugger  v0.10.0-esp32-20201202-2-g7e342cad (2021-01-02-23:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Warn : Transport "jtag" was already selected
Info : FreeRTOS creation
Info : Initializing remote_bitbang driver
Info : Connecting to localhost:5555
Info : remote_bitbang driver initialized
Info : This adapter doesn't support configurable speed
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Error: esp32s2: DSR (FFFFFFFF) indicates target still busy!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an exception!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an overrun!
Error: esp32s2: DSR (FFFFFFFF) indicates target still busy!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an exception!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an overrun!
Error: esp32s2: DSR (FFFFFFFF) indicates target still busy!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an exception!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an overrun!
Info : esp32s2: Target halted, PC=0xFFFFFFFF, debug_reason=00000003
Error: Failed to read break instruction!
Error: esp32s2: DSR (FFFFFFFF) indicates target still busy!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an exception!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an overrun!
Warn : esp32s2: Failed writing 4 bytes at address 0x3f41f064
Error: Failed to write ESP32_S2_TIMG0WDT_PROTECT (-4)!
Polling target esp32s2 failed, trying to reexamine
Examination failed, GDB will be halted. Polling again in 100ms
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Polling target esp32s2 failed, trying to reexamine
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Error: esp32s2: DSR (FFFFFFFF) indicates target still busy!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an exception!
Error: esp32s2: DSR (FFFFFFFF) indicates DIR instruction generated an overrun!
Warn : esp32s2: Failed writing 4 bytes at address 0x3f4080c0
Error: Failed to write ESP32_S2_STORE5 (-4)!

Info : remote_bitbang interface quit

[brainstorm]

Hm, setting up the Glasgow at 2.9V instead of 3.3V:

$ glasgow run jtag-openocd --port A --pin-tck 0 --pin-tms 3 --pin-tdi 2 --pin-tdo 1 -V 2.9 tcp:localhost:5555

It almost works... OpenOCD struggles a bit though:

$ openocd -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig -c 'init; reset; halt;'
Open On-Chip Debugger  v0.10.0-esp32-20201202-2-g7e342cad (2021-01-02-23:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Warn : Transport "jtag" was already selected
Info : FreeRTOS creation
Info : Initializing remote_bitbang driver
Info : Connecting to localhost:5555
Info : remote_bitbang driver initialized
Info : This adapter doesn't support configurable speed
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32s2: Core was reset.
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32s2: Target halted, PC=0x40091BEA, debug_reason=00000000
Warn : Unknown ESP32-S2 chip revision (0x3f400074)!
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Info : esp32s2: Target halted, PC=0x40091BEA, debug_reason=00000000
Warn : Unknown ESP32-S2 chip revision (0x3f400074)!
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Info : esp32s2: Target halted, PC=0x4001276F, debug_reason=00000000
Warn : Unknown ESP32-S2 chip revision (0x3f400074)!
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Info : accepting 'gdb' connection on tcp/3333
Warn : No symbols for FreeRTOS!
Info : esp32s2: Target halted, PC=0x40091BEA, debug_reason=00000000
Warn : Unknown ESP32-S2 chip revision (0x3f400074)!
Error: Invalid stub!
Warn : Failed to get flash mappings (-4)!
Error: Invalid stub!
Error: Invalid stub!
Info : Auto-detected flash bank 'esp32s2.flash' size 4194303 KB
Info : Using flash bank 'esp32s2.flash' size 4194303 KB
Error: Invalid stub!
Warn : Failed to get flash mappings (-4)!
Error: Invalid stub!
Info : Using flash bank 'esp32s2.irom' size 0 KB
Error: Invalid stub!
Warn : Failed to get flash mappings (-4)!
Error: Invalid stub!
Info : Using flash bank 'esp32s2.drom' size 0 KB
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : Target not HALTED!
Warn : xtensa_read_memory: esp32s2: target not halted
Error: Could not read FreeRTOS thread count from target!
Warn : Target not HALTED!
Warn : xtensa_read_memory: esp32s2: target not halted
Error: Could not read FreeRTOS thread count from target!
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted
Warn : xtensa_read_memory: esp32s2: target not halted

But on the GDB side, things start to finally make sense!:

(gdb) target remote :3333
Remote debugging using :3333
warning: No executable has been specified and target does not support
determining executable automatically.  Try using the "file" command.
0x40091bea in ?? ()
(gdb) bt
#0  0x40091bea in ?? ()
#1  0x400870b6 in ?? ()
Backtrace stopped: Cannot access memory at address 0xfffffff4
(gdb) symbol-file /Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf
Reading symbols from /Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf...done.
(gdb) bt
#0  0x40091bea in esp_pm_impl_waiti () at /Users/romanvg/dev/esp-idf/components/esp_pm/pm_impl.c:533
#1  0x400870b6 in esp_vApplicationIdleHook () at /Users/romanvg/dev/esp-idf/components/esp_common/src/freertos_hooks.c:63
Backtrace stopped: Cannot access memory at address 0xfffffff4
(gdb) n
esp32s2: target not halted
target esp32s2 was not halted when step was requested

[gerekon]

It seems that the problems are definitely with JTAG communication.

Warn : Unknown ESP32-S2 chip revision (0x3f400074)!
Error: Could not read FreeRTOS thread count from target!

We have not tested JTAG debugging with remote bitbang driver. Due to its nature there can be problems with voltage levels, timings and so on. I think this can be solved, but even solved it will work much slower then HW JTAG adapters. So currently this is not on our short-term task list.

[gerekon]

@brainstorm Maybe it is worth to try with any other supported HW JTAG adapter?

[brainstorm]

Thanks @gerekon, I understand your concerns, but I'm about to fix this for good, it's just a wiring issue:

I think that even if it's slower, it's a very accessible way to debug since the Glasgow explorer is as handy (perhaps eventually as widespread) as Raspberry Pis?

I personally don't have any other HW JTAG adapter... Perhaps a Blackmagic probe would do?

[brainstorm]

Besides, I do not plan to flash via JTAG (I'll do via UART instead), so speed shouldn't really be an issue for backtrace printing and some stepping and variable inspection I reckon? Or is it in your experience @gerekon ?

[brainstorm]

The funky waveform shape on TDO was due to a missing 10k pullup, configurable on Glasgow this way:

diff --git a/software/glasgow/applet/interface/jtag_openocd/__init__.py b/software/glasgow/applet/interface/jtag_openocd/__init__.py
index ccbf7d4..647640f 100644
--- a/software/glasgow/applet/interface/jtag_openocd/__init__.py
+++ b/software/glasgow/applet/interface/jtag_openocd/__init__.py
@@ -100,6 +100,10 @@ class JTAGOpenOCDApplet(GlasgowApplet, name="jtag-openocd"):
         parser.add_argument(
             "-f", "--frequency", metavar="FREQ", type=int, default=100,
             help="set TCK frequency to FREQ kHz (default: %(default)s)")
+        parser.add_argument(
+            "--pulls", default=False, action="store_true",
+            help="enable integrated pull-ups")
+

     def build(self, target, args):
         self.mux_interface = iface = target.multiplexer.claim_interface(self, args)
@@ -111,7 +115,11 @@ class JTAGOpenOCDApplet(GlasgowApplet, name="jtag-openocd"):
         ))

     async def run(self, device, args):
-        return await device.demultiplexer.claim_interface(self, self.mux_interface, args)
+        pulls = set()
+        if args.pulls:
+            pulls = {args.pin_tdo}
+        return await device.demultiplexer.claim_interface(self, self.mux_interface, args,
+                                                          pull_high=pulls)

     @classmethod
     def add_interact_arguments(cls, parser):

Now it's "fixed" (still looks pretty horrid on the last screenshot, but barely within spec)... on a later on I fix it with pullups between 800ohm and 1k:

Although there might be speed problems, since I'm still seeing some spurious errors like the ones @gerekon pointed earlier, namely:

Warn : Unknown ESP32-S2 chip revision (0x3f400074)!

Warn : Failed to get flash mappings (-4)!

Error: Invalid stub!

Potentially tricky bit is that for bitbang, OpenOCD goes like:

Info : This adapter doesn't support configurable speed

so even if I put Glasgow and OpenOCD at 100kHz (current default on both sides), I'm not entirely sure this is respected at all :confused:

I'd like to pursue this till the end, it's more of a challenge/hobby at this point ;)

[brainstorm]

Aand bingo! Going up to 500kHz (instead of the default 100kHz, I don't get any errors anymore!):

$ openocd -f interface/remote_bitbang.cfg -f target/esp32s2.cfg.orig -c "init; reset; halt;"
Open On-Chip Debugger  v0.10.0-esp32-20201202-2-g7e342cad (2021-01-02-23:47)
Licensed under GNU GPL v2
For bug reports, read
    http://openocd.org/doc/doxygen/bugs.html
Info : only one transport option; autoselect 'jtag'
Warn : Transport "jtag" was already selected
Info : FreeRTOS creation
Info : Initializing remote_bitbang driver
Info : Connecting to localhost:5555
Info : remote_bitbang driver initialized
Info : This adapter doesn't support configurable speed
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32s2: Target halted, PC=0x4001276A, debug_reason=00000000
Info : Detected ESP32-S2 chip
Info : Listening on port 3333 for gdb connections
Info : JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Info : esp32s2: Target halted, PC=0x4001126C, debug_reason=00000000
Info : esp32s2: Core was reset.
Info : esp32s2: Target halted, PC=0x4000D89B, debug_reason=00000000
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : accepting 'gdb' connection on tcp/3333
Warn : No symbols for FreeRTOS!
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s2.flash' size 4096 KB
Info : Using flash bank 'esp32s2.flash' size 4096 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : Using flash bank 'esp32s2.irom' size 76 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : Using flash bank 'esp32s2.drom' size 28 KB
Info : dropped 'gdb' connection
Info : accepting 'gdb' connection on tcp/3333
Warn : No symbols for FreeRTOS!

And the GDB session seems to be working fine now:

(gdb) b app_main
Breakpoint 1 at 0x400852d4: file ../main/twai_network_example_slave_main.c, line 122.
(gdb) c
Continuing.
Note: automatically using hardware breakpoints for read-only addresses.
esp32s2: Target halted, PC=0x400852D4, debug_reason=00000001
[New Thread 1073484888]
[New Thread 1073347668]
[Switching to Thread 1073348076]

Thread 1 hit Breakpoint 1, app_main ()
    at ../main/twai_network_example_slave_main.c:122
122 {
(gdb) l
117     xSemaphoreGive(done_sem);
118     vTaskDelete(NULL);
119 }
120
121 void app_main(void)
122 {
123     //Create semaphores and tasks
124     tx_task_queue = xQueueCreate(1, 10);
125     rx_task_queue = xQueueCreate(1, 10);
126     ctrl_task_sem = xSemaphoreCreateBinary();

Finally! :D

[brainstorm]

By the way, now that I got it working (relatively slow, but working), I can reproduce exactly this seemingly unresolved 2019 OpenOCD issue where @igrr seems to be involved and unrecognized item "timeout" in "qSupported" response warning is mentioned: https://esp32.com/viewtopic.php?t=11181 .

After launching OpenOCD I'm getting the following on GDB on a "fresh" session:

(gdb) target remote :3333
Remote debugging using :3333
Ignoring packet error, continuing...
warning: unrecognized item "timeout" in "qSupported" response
Remote replied unexpectedly to 'vMustReplyEmpty': PacketSize=4000;qXfer:memory-map:read+;qXfer:features:read-;qXfer:threads:read+;QStartNoAckMode+;vContSupported+

The thing works "fine" after ignoring those errors though:

(gdb) target remote :3333
Remote debugging using :3333
0x4001ba60 in ?? ()
(gdb) b app_main
Breakpoint 1 at 0x400852d4: file ../main/twai_network_example_slave_main.c, line 122.
(gdb) c
Continuing.
Note: automatically using hardware breakpoints for read-only addresses.
esp32s2: Target halted, PC=0x400852D4, debug_reason=00000001
[New Thread 1073484888]
[New Thread 1073347668]
[Switching to Thread 1073348076]

Thread 1 hit Breakpoint 1, app_main () at ../main/twai_network_example_slave_main.c:122
122 {
(gdb) bt
#0  app_main () at ../main/twai_network_example_slave_main.c:122
#1  0x4009238d in main_task (args=0x0) at /Users/romanvg/dev/esp-idf/components/freertos/port/port_common.c:133
#2  0x4002802c in vPortTaskWrapper (pxCode=0x40092350 <main_task>, pvParameters=0x0) at /Users/romanvg/dev/esp-idf/components/freertos/port/xtensa/port.c:168

One interesting observation is that on the OpenOCD terminal, the flash commands, presumably the ones defined in esp32s2.cfg as:

configure_esp_workarea $_TARGETNAME 0x40030000 0x3400 0x3FFE0000 0x6000
configure_esp_flash_bank $_TARGETNAME $_TARGETNAME $_FLASH_SIZE

Do take a while to complete (5-15 seconds)... why does OpenOCD take so long to enumerate the memory regions?:

Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s2.flash' size 4096 KB
Info : Using flash bank 'esp32s2.flash' size 4096 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : Using flash bank 'esp32s2.irom' size 76 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : Using flash bank 'esp32s2.drom' size 28 KB

And then the unrecognized item "timeout" in "qSupported" response error seen in GDB above, generates the following output on OpenOCD terminal:

Warn : negative reply, retrying
Warn : negative reply, retrying
Warn : negative reply, retrying
Error: GDB missing ack(2) - assumed good
Error: GDB missing ack(2) - assumed good
Error: GDB missing ack(2) - assumed good

Hope that helps diagnose the problem from 2019 on the forum and get it fixed for good?

[brainstorm]

After putting a "proper" (for quick-build strip-board standards) ground plane... I'll put together a proper board later, just wanted to have signals in better shape:

Also added two 820ohm pullups for both TDO & TCK the JTAG and signals look much better... admittedly not super clean, but presumably within spec?

But the esp32.com forum errors described above keep creeping up anyway, here's the -d3 dump for OpenOCD and GDB as advised in the espressif docs. Please note that the following files have very little resemblance to the original post, now most of the OpenOCD session works fine but there's the qSupported and vMustReplyEmpty errors left to fix:

openocd_log.txt gdb_log.txt gdbinit.txt

Namely:

Debug: 1568 21269 gdb_server.c:1011 gdb_new_connection(): New GDB Connection: 1, Target esp32s2, state: halted
Debug: 1569 21269 gdb_server.c:3358 gdb_input_inner(): received packet: 'qSupported:multiprocess+;swbreak+;hwbreak+;qRelocInsn+;f'...
Debug: 1570 21269 xtensa.c:1105 xtensa_get_gdb_reg_list(): reg_class=0, num_regs=172
Debug: 1571 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$PacketSize=4000;qXfer:memory-map:read+;qXfer:features:read-;qXfer:threads:read+;QStartNoAckMode+;vContSupported+#04'
Warn : 1572 21269 gdb_server.c:441 gdb_put_packet_inner(): negative reply, retrying
Debug: 1573 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$PacketSize=4000;qXfer:memory-map:read+;qXfer:features:read-;qXfer:threads:read+;QStartNoAckMode+;vContSupported+#04'
Warn : 1574 21269 gdb_server.c:441 gdb_put_packet_inner(): negative reply, retrying
Debug: 1575 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$PacketSize=4000;qXfer:memory-map:read+;qXfer:features:read-;qXfer:threads:read+;QStartNoAckMode+;vContSupported+#04'
Warn : 1576 21269 gdb_server.c:441 gdb_put_packet_inner(): negative reply, retrying
Debug: 1577 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$PacketSize=4000;qXfer:memory-map:read+;qXfer:features:read-;qXfer:threads:read+;QStartNoAckMode+;vContSupported+#04'
Debug: 1578 21269 gdb_server.c:3358 gdb_input_inner(): received packet: 'vMustReplyEmpty'
Debug: 1579 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$#00'
Error: 1580 21269 gdb_server.c:463 gdb_put_packet_inner(): GDB missing ack(2) - assumed good
Debug: 1581 21269 gdb_server.c:3358 gdb_input_inner(): received packet: 'vMustReplyEmpty'
Debug: 1582 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$#00'
Error: 1583 21269 gdb_server.c:463 gdb_put_packet_inner(): GDB missing ack(2) - assumed good
Debug: 1584 21269 gdb_server.c:3358 gdb_input_inner(): received packet: 'vMustReplyEmpty'
Debug: 1585 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$#00'
Error: 1586 21269 gdb_server.c:463 gdb_put_packet_inner(): GDB missing ack(2) - assumed good
Debug: 1587 21269 gdb_server.c:3358 gdb_input_inner(): received packet: 'vMustReplyEmpty'
Debug: 1588 21269 gdb_server.c:402 gdb_put_packet_inner(): sending packet '$#00'
Debug: 1589 21279 gdb_server.c:1043 gdb_connection_closed(): GDB Close, Target: esp32s2, state: halted, gdb_actual_connections=0

As mentioned above, the memory regions enumeration takes a few seconds (is this normal?):

(...)
Debug: 804 11796 xtensa_algorithm.c:115 xtensa_stub_load(): addr 0x00000000, sz 5283, flags 1
Debug: 805 11796 target.c:1889 alloc_working_area_try_do(): allocated new working area of 5284 bytes at address 0x40030000
Debug: 806 13947 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (8080CC11)
Debug: 807 13947 target.c:1751 print_wa_layout(): b* 0x40030000-0x400314a3 (5284 bytes)
(...)

After a subsequent target remote :3333 everything works fine. So the only problem left to fix is the initial (long) time it takes to establish the connection after target remote :3333.

Any ideas on what's the underlying issue? Happy to pursue this further myself, hints welcome ;)

The esp32 forum post had exactly the same symptoms back in 2019.

[brainstorm]

Predictably, some time is spent on the host OpenOCD side under remote_bitbang_rread() (blocking?), but those repeated esp_xtensa_get_mappings() function calls are the main hot spot when profiling a target remote :3333 session. See:

And here is the raw tracing file if you want to interactively explore in OSX's instruments profiling system.

[brainstorm]

Here's a bit more detail on how OpenOCD spends time... seems to be waiting on the JTAG execute queue while reading data from the IC:

[igrr]

warning: unrecognized item "timeout" in "qSupported" response
Remote replied unexpectedly to 'vMustReplyEmpty': PacketSize=4000;qXfer:memory-map:read+;qXfer:features:read-;qXfer:threads:read+;QStartNoAckMode+;vContSupported+

Based on your description, it seems that the GDB server (OpenOCD) is actually not responding in time. Can you try adding set remotetimeout 100 to your .gdbinit script, before target remote?

[igrr]

One interesting observation is that on the OpenOCD terminal, the flash commands [snip] Do take a while to complete (5-15 seconds)... why does OpenOCD take so long to enumerate the memory regions?:

OpenOCD needs to execute some code on the target to determine the memory mappings. This involves "running an algorithm" — in OpenOCD terms, loading a bit of code and executing it. Each time all the CPU registers need to be saved and restored. From what I remember while working with OpenOCD remote protocols, this takes significant amount of time over slow connections.

The options I see are:

1. reduce the latency of the connection
2. reduce the number of round-trips over TCP for each JTAG command queue
3. pipeline more requests, block less often for each JTAG command queue
4. disable flash support for esp32s2 target (set ESP_FLASH_SIZE 0)
5. do something about the Xtensa target implementation in OpenOCD to query/save/restore registers less often

Options 2 and 3 likely involve modifying the remote bitbang protocol.

Option 4 means that you would be limited to 2 hardware breakpoints, plus software breakpoints in IRAM.

Option 5 is interesting to explore, but at the moment I don't see any low hanging fruit for such optimizations.

[brainstorm]

Thanks Ivan! :D

The set remotetimeout 100 directive on ~/.gdbinit indeed works and I knew that already, sorry for not mentioning it explicitly (more on why it might not be a good fix below). I also see the options you are proposing and they all make sense... for one, the remote_bitbang protocol saw a reasonable optimization 3 years ago... it actually was way worse before that since it was sending stuff bit by bit :-!

If you look at the screenshot above for remote_bitbang_rread(), OpenOCD seems to be read-ing char-by-char and losing a ton of time on read syscall? That could be a potential low hanging fruit: adjusting that particular read and count to, say, 1500 bytes (size of typical MTUs?).

IMO, points 2&3 would yield the most bang for the buck in terms of optimization and UX improvement for users and community at large... point 5 is also interesting, but I'm not that well versed in Xtensa/Espressif intricacies so I'll just trust your judgement on that ;) ... the rest of the points are either impractical or have downsides.

My objective with this issue has morphed into finding a proper fix for the root cause since I've just timed the "running an algorithm" section:

Info : accepting 'gdb' connection on tcp/3333
Warn : No symbols for FreeRTOS!
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Auto-detected flash bank 'esp32s2.flash' size 4096 KB
Info : Using flash bank 'esp32s2.flash' size 4096 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : Using flash bank 'esp32s2.irom' size 76 KB
Info : esp32s2: Target halted, PC=0x400314BA, debug_reason=00000001
Info : Flash mapping 0: 0x10020 -> 0x3f000020, 25 KB
Info : Flash mapping 1: 0x20020 -> 0x40080020, 73 KB
Info : Using flash bank 'esp32s2.drom' size 28 KB

... and it takes 14 seconds to complete.

This means that your own VSCode ESP-IDF extension reasonable default of 10 seconds gives up just 4 seconds short of establishing a functional debug session out of the box... it's highly possible that other IDEs behave on a similar way, generating support tickets on this repo (I've seen some similarities), so this could be a case of helping myself, you and solve a bunch of stagnant and future support requests all in one go ;)

[igrr]

@brainstorm I understand your desire for performance improvements of remote_bitbang driver. I have checked the list of debugging-related issues reported, and only found mention of remote_bitbang in 3 tickets (2 of which are yours, one more was submitted via Espressif customer support). So I'm not convinced that these performance improvements would easily translate to reduced number of support tickets.

We have looked briefly into the different protocols for encapsulating JTAG transfers, and ended up implementing 2 protocols for our future devices: esp_usb_jtag, which is optimized for being rather simple to implement in hardware, and esp_remote, which can work over USB or TCP, and is more suited for a software implementation. Both protocols address shortcomings of remote_bitbang. Given that we already have these 2 protocols to work with, it is not very likely that we will invest significant time into optimization of remote_bitbang. If you happen to make some improvements, we will be happy to merge your PR, of course.

[erhankur]

@brainstorm Is there anything we can help to close this issue?

[brainstorm]

If the remote_bitbang is in, I'm more than happy to close ;)