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

[Feature Request]: better DEBUGGING.txt and fixing ESP32S2 JTAG bitbang debug (VSC-539) #285

Closed
brainstorm opened this issue Jan 8, 2021 · 8 comments
Labels
Feature / Enhancement Request Request for Feature/ Enhancement

Comments

@brainstorm
Copy link

Is your feature request related to a problem? Please describe.

Please see the commit comments on: b4b91b9#r45766576 ... for a good description of the current situation and what I've been trying.

Describe the solution you'd like

I would love to have a "reasonable defaults" config for the esp_debug_adapter... I understand that there might not be an "one size fits all" solution for this, but the docs should be less succint for new users?

@brainstorm brainstorm added the Feature / Enhancement Request Request for Feature/ Enhancement label Jan 8, 2021
@github-actions github-actions bot changed the title [Feature Request]: DEBUGGING.txt needs a bit more clarity? [Feature Request]: DEBUGGING.txt needs a bit more clarity? (VSC-539) Jan 8, 2021
@brainstorm
Copy link
Author

brainstorm commented Jan 9, 2021

I went for the following launch settings:

{
    "version": "0.2.0",
    "configurations": [
    
        {
            "type": "espidf",
            "name": "Launch",
            "request": "launch",
            "logLevel": 5,
            "mode": "auto",
        }
    ]
}

Then I see this on the Glasgow (remote_bitbang JTAG side):

$ glasgow run jtag-openocd --port A --pin-tck 0 --pin-tms 3 --pin-tdi 2 --pin-tdo 1 -V 3.3 tcp:localhost:5555
I: g.device.hardware: device already has bitstream ID 9cfbf1aff24341a17d570a320b7e700f
I: g.cli: running handler for applet 'jtag-openocd'
I: g.applet.interface.jtag_openocd: port(s) A voltage set to 3.3 V
I: g.applet.interface.jtag_openocd: socket: listening at tcp:localhost:5555
I: g.applet.interface.jtag_openocd: socket: new connection from [::1]:57047

And this is the output I'm seeing on the DAP side:

2021-01-09 19:07:40,411 - Debug Adapter (main) - DEBUG - START_TIME_2021_01_09_19-07-40
2021-01-09 19:07:40,411 - Debug Adapter (main) - DEBUG - Init errors:None
2021-01-09 19:07:40,412 - Debug Adapter (main) - INFO - Working directory: /
2021-01-09 19:07:40,412 - Debug Adapter (main) - INFO - Arguments: 
{   'app_flash_off': 65536,
    'board_type': None,
    'cmdfile': None,
    'core_file': (),
    'debug': 5,
    'developer_mode': 'none',
    'device_name': 'esp32s2',
    'elfpath': (   '/Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf',),
    'log_file': '/Users/romanvg/dev/esp32s2_can/twai_network_slave/debug.log',
    'log_mult_files': None,
    'oocd': 'openocd',
    'oocd_args': None,
    'oocd_ip': 'localhost',
    'oocd_mode': 'connect_to_instance',
    'oocd_scripts': None,
    'port': 43474,
    'postmortem': False,
    'toolchain_prefix': None}
DEBUG_ADAPTER_STARTED
2021-01-09 19:07:40,413 - Debug Adapter (main) - CRITICAL - Debug adapter -> Extension: DEBUG_ADAPTER_STARTED
2021-01-09 19:07:40,413 - Debug Adapter (main) - INFO - Starting. Cmd: /Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter_main.py -d 5 -e /Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf -l /Users/romanvg/dev/esp32s2_can/twai_network_slave/debug.log -p 43474 -dn esp32s2 -a 0x10000

2021-01-09 19:07:40,415 - Debug Adapter (main) - INFO - Listening on port 43474
DEBUG_ADAPTER_READY2CONNECT
2021-01-09 19:07:40,415 - Debug Adapter (main) - CRITICAL - Debug adapter -> Extension: DEBUG_ADAPTER_READY2CONNECT
2021-01-09 19:07:40,417 - Debug Adapter (main) - DEBUG - Got connection
2021-01-09 19:07:40,418 - Debug Adapter (ReaderThread) - DEBUG - read line: >>b'Content-Length: 386\\r\\n'<<

2021-01-09 19:07:40,419 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Debug adapter -> Extension: DEBUG_ADAPTER_STARTED\n", "source": {}}, "seq": 0}

2021-01-09 19:07:40,419 - Debug Adapter (ReaderThread) - DEBUG - read line: >>b'\\r\\n'<<

2021-01-09 19:07:40,419 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Starting. Cmd: /Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter_main.py -d 5 -e /Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf -l /Users/romanvg/dev/esp32s2_can/twai_network_slave/debug.log -p 43474 -dn esp32s2 -a 0x10000\n\n", "source": {}}, "seq": 1}

2021-01-09 19:07:40,420 - Debug Adapter(Command Processor) - DEBUG - Got json: {
    "arguments": {
        "adapterID": "espidf",
        "clientID": "vscode",
        "clientName": "Visual Studio Code - Insiders",
        "columnsStartAt1": true,
        "linesStartAt1": true,
        "locale": "sv",
        "pathFormat": "path",
        "supportsInvalidatedEvent": true,
        "supportsProgressReporting": true,
        "supportsRunInTerminalRequest": true,
        "supportsVariablePaging": true,
        "supportsVariableType": true
    },
    "command": "initialize",
    "seq": 1,
    "type": "request"
}
2021-01-09 19:07:40,420 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Listening on port 43474\n", "source": {}}, "seq": 2}

2021-01-09 19:07:40,421 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Debug adapter -> Extension: DEBUG_ADAPTER_READY2CONNECT\n", "source": {}}, "seq": 3}

2021-01-09 19:07:40,421 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Got connection\n", "source": {}}, "seq": 4}

2021-01-09 19:07:40,422 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Got json: {\n    \"arguments\": {\n        \"adapterID\": \"espidf\",\n        \"clientID\": \"vscode\",\n        \"clientName\": \"Visual Studio Code - Insiders\",\n        \"columnsStartAt1\": true,\n        \"linesStartAt1\": true,\n        \"locale\": \"sv\",\n        \"pathFormat\": \"path\",\n        \"supportsInvalidatedEvent\": true,\n        \"supportsProgressReporting\": true,\n        \"supportsRunInTerminalRequest\": true,\n        \"supportsVariablePaging\": true,\n        \"supportsVariableType\": true\n    },\n    \"command\": \"initialize\",\n    \"seq\": 1,\n    \"type\": \"request\"\n}\n", "source": {}}, "seq": 5}

2021-01-09 19:07:40,428 - Gdb - DEBUG - MI->: -gdb-set mi-async on
2021-01-09 19:07:40,442 - Gdb - DEBUG - MI<-:
[{'message': 'thread-group-added',
  'payload': {'id': 'i1'},
  'stream': 'stdout',
  'token': None,
  'type': 'notify'},
 {'message': 'done',
  'payload': None,
  'stream': 'stdout',
  'token': None,
  'type': 'result'}]
2021-01-09 19:07:40,442 - Gdb - INFO - NOTIFY: thread-group-added {'id': 'i1'}
2021-01-09 19:07:40,442 - Gdb - DEBUG - RESULT: done None
2021-01-09 19:07:40,442 - Gdb - DEBUG - MI->: -gdb-set logging file /var/folders/wz/__dd9trs0kl4jb3rs83704y80000gn/T/gdb_proc.log
2021-01-09 19:07:40,443 - Gdb - DEBUG - MI<-:
[{'message': 'done',
  'payload': None,
  'stream': 'stdout',
  'token': None,
  'type': 'result'}]
2021-01-09 19:07:40,443 - Gdb - DEBUG - RESULT: done None
2021-01-09 19:07:40,443 - Gdb - DEBUG - MI->: -gdb-set logging on
2021-01-09 19:07:40,443 - Gdb - DEBUG - MI<-:
[{'message': 'done',
  'payload': None,
  'stream': 'stdout',
  'token': None,
  'type': 'result'}]
2021-01-09 19:07:40,444 - Gdb - DEBUG - RESULT: done None
2021-01-09 19:07:40,445 - Gdb - DEBUG - MI->: -file-exec-and-symbols /Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf
2021-01-09 19:07:40,474 - Gdb - DEBUG - MI<-:
[{'message': 'done',
  'payload': None,
  'stream': 'stdout',
  'token': None,
  'type': 'result'}]
2021-01-09 19:07:40,475 - Gdb - DEBUG - RESULT: done None
2021-01-09 19:07:40,475 - Gdb - DEBUG - Connecting to 127.0.0.1:3333
2021-01-09 19:07:40,475 - Gdb - DEBUG - MI->: -target-select remote 127.0.0.1:3333
2021-01-09 19:07:50,475 - Gdb - DEBUG - MI<-:
[{'message': 'error',
  'payload': {'msg': 'Remote communication error.  Target disconnected.: '
                     'Connection reset by peer.'},
  'stream': 'stdout',
  'token': None,
  'type': 'result'}]
2021-01-09 19:07:50,476 - Gdb - DEBUG - RESULT: error {'msg': 'Remote communication error.  Target disconnected.: Connection reset '
        'by peer.'}
2021-01-09 19:07:50,476 - Debug Adapter (main) - ERROR - Failed to connect to "remote 127.0.0.1:3333"!
Traceback (most recent call last):
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/command_processor.py", line 52, in __call__
    on_request(protocol_message)
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/command_processor.py", line 88, in on_initialize_request
    self.da.adapter_init()
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/debug_adapter.py", line 282, in adapter_init
    raise e
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/debug_adapter.py", line 278, in adapter_init
    self.start_gdb()
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/debug_adapter.py", line 506, in start_gdb
    raise e
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/debug_adapter.py", line 503, in start_gdb
    self._gdb.connect()
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/debug_backend/debug_backend/gdb.py", line 485, in connect
    self.target_select(remote_mode, self._remote_target, tmo=tmo)
  File "/Users/romanvg/.vscode-insiders/extensions/espressif.esp-idf-extension-0.6.0/esp_debug_adapter/debug_adapter/debug_backend/debug_backend/gdb.py", line 219, in target_select
    raise DebuggerError('Failed to connect to "%s %s"!' % (tgt_type, tgt_params))
debug_adapter.debug_backend.debug_backend.defs.DebuggerError: Failed to connect to "remote 127.0.0.1:3333"!
2021-01-09 19:07:50,478 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Failed to connect to \"remote 127.0.0.1:3333\"!\n", "source": {}}, "seq": 6}

2021-01-09 19:07:50,478 - Debug Adapter (WriterThread) - DEBUG - Writing: {"type": "event", "event": "output", "body": {"output": "Failed to connect to \"remote 127.0.0.1:3333\"!\n", "source": {}}, "seq": 7}

So it's essentially dropping the OpenOCD GDB connection on port :3333... investigating why :/

@brainstorm
Copy link
Author

brainstorm commented Jan 9, 2021

The OpenOCD daemon is up and running:

$ lsof -i tcp:3333
COMMAND   PID    USER   FD   TYPE            DEVICE SIZE/OFF NODE NAME
openocd 47428 romanvg    7u  IPv4 0xec3526865396c27      0t0  TCP localhost:dec-notes (LISTEN)

And connects and replies, apparently:

$ nc 127.0.0.1 3333
+
$

It shows that + sign and quickly quits though :-S

Connecting manually it behaves like this, immediately closing the connection on port 3333:

$ /Users/romanvg/.espressif/tools/xtensa-esp32s2-elf/esp-2020r3-8.4.0/xtensa-esp32s2-elf/bin/xtensa-esp32s2-elf-gdb
GNU gdb (crosstool-NG esp-2020r3) 8.1.0.20180627-git
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=x86_64-host_apple-darwin12 --target=xtensa-esp32s2-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
(gdb) target remote :3333
Remote debugging using :3333
Remote connection closed
(gdb) target remote :3333
Remote debugging using :3333
Remote connection closed
(gdb) target-select remote 127.0.0.1:3333
Undefined command: "target-select".  Try "help".
(gdb) target remote 127.0.0.1:3333
Remote debugging using 127.0.0.1:3333
Remote connection closed
(gdb)

For context, the OpenOCD start manager output looks like this:

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 : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
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

The Glasgow side looks fine so far?:

$ glasgow run jtag-openocd --port A --pin-tck 0 --pin-tms 3 --pin-tdi 2 --pin-tdo 1 -V 3.3 tcp:localhost:5555
I: g.device.hardware: device already has bitstream ID 9cfbf1aff24341a17d570a320b7e700f
I: g.cli: running handler for applet 'jtag-openocd'
I: g.applet.interface.jtag_openocd: port(s) A voltage set to 3.3 V
I: g.applet.interface.jtag_openocd: socket: listening at tcp:localhost:5555
I: g.applet.interface.jtag_openocd: socket: new connection from [::1]:57047
I: g.applet.interface.jtag_openocd: socket: connection from [::1]:57047 lost
I: g.applet.interface.jtag_openocd: socket: new connection from [::1]:57160

@brainstorm
Copy link
Author

brainstorm commented Jan 10, 2021

Ok, after examining the output from OpenOCD to a single target remote 127.0.0.1:3333 I'm hitting the following:

Error: Target not examined yet
Error executing event gdb-attach on target esp32s2:

Error: Target not halted
Error: auto_probe failed
Error: Connect failed. Consider setting up a gdb-attach event for the target to prepare target for GDB connect, or use 'gdb_memory_map disable'.
Error: attempted 'gdb' connection rejected

Looking into how to "examine the target" in OpenOCD... might be related to espressif/openocd-esp32#64 and/or espressif/openocd-esp32#105

@brainstorm
Copy link
Author

I got the following but just once (and cannot seem to reproduce), perhaps by mere chance? How can I make sure that the ESP32S2 is in a "good state" upon gdb-attach (when I issue the target remote 127.0.0.1:3333 in the other shell, @igrr?:

$ lldb openocd -- -f interface/remote_bitbang.cfg -f target/esp32s2.cfg
(...)
(lldb) run
Process 16819 launched: '/Users/romanvg/.espressif/tools/openocd-esp32/v0.10.0-esp32-20201202/openocd-esp32/bin/openocd' (x86_64)
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 : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
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 : esp32s2: Core was reset.
Info : esp32s2: Core was reset.
(...)
Info : esp32s2: Core was reset.
Info : accepting 'gdb' connection on tcp/3333
Warn : No symbols for FreeRTOS!
Info : esp32s2: Debug controller was reset.
Info : esp32s2: Core was reset.
Info : esp32s2: Target halted, PC=0x00000000, debug_reason=00000000
Warn : Unknown ESP32-S2 chip revision (0x0)!
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
Error: Failed to find HALTED core!
Error: Target not examined yet
Error: Target not examined yet
Error: esp32s2: Failed to halt target to remove flash BPs (-4)!
Info : dropped 'gdb' connection

@brainstorm
Copy link
Author

brainstorm commented Jan 10, 2021

Passing -d to OpenOCD (as in $ lldb openocd -- -d -f interface/remote_bitbang.cfg -f target/esp32s2.cfg):

Info : 1339 1157869 server.c:100 add_connection(): accepting 'gdb' connection on tcp/3333
Debug: 1340 1157869 breakpoints.c:358 breakpoint_clear_target_internal(): Delete all breakpoints for target: esp32s2
Debug: 1341 1157869 breakpoints.c:552 watchpoint_clear_target(): Delete all watchpoints for target: esp32s2
Debug: 1342 1157869 FreeRTOS.c:1018 FreeRTOS_clean(): FreeRTOS_clean
Debug: 1343 1157869 FreeRTOS.c:491 FreeRTOS_update_threads(): FreeRTOS_update_threads
Warn : 1344 1157870 FreeRTOS.c:497 FreeRTOS_update_threads(): No symbols for FreeRTOS!
Debug: 1345 1157870 target.c:1636 target_call_event_callbacks(): target event 19 (gdb-attach) for core esp32s2
Debug: 1346 1157870 target.c:4637 target_handle_event(): target(0): esp32s2 (esp32s2) event: 19 (gdb-attach) action:
	#$_TARGETNAME xtensa smpbreak BreakIn BreakOut
	# necessary to auto-probe flash bank when GDB is connected
	reset
	halt

Debug: 1347 1157870 command.c:143 script_debug(): command - reset reset
Debug: 1349 1157870 target.c:1654 target_call_reset_callbacks(): target reset 1 (run)
Debug: 1350 1157870 command.c:143 script_debug(): command - target target names
Debug: 1351 1157870 command.c:143 script_debug(): command - esp32s2 esp32s2 invoke-event reset-start
Debug: 1352 1157870 command.c:143 script_debug(): command - transport transport select
Debug: 1353 1157870 command.c:143 script_debug(): command - jtag jtag arp_init-reset
Debug: 1354 1157870 core.c:1576 jtag_init_reset(): Initializing with hard TRST+SRST reset
Debug: 1355 1157870 core.c:742 jtag_add_reset(): JTAG reset with TLR instead of TRST
Debug: 1356 1157870 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 1357 1157870 core.c:1462 jtag_init_inner(): Init JTAG chain
Debug: 1358 1157870 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 1359 1157870 core.c:1128 jtag_examine_chain(): DR scan interrogation for IDCODE/BYPASS
Debug: 1360 1157870 core.c:327 jtag_call_event_callbacks(): jtag event: TAP reset
Info : 1361 1157970 core.c:1027 jtag_examine_chain_display(): JTAG tap: esp32s2.cpu tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Debug: 1362 1157970 core.c:1258 jtag_validate_ircapture(): IR capture validation scan
Debug: 1363 1157974 core.c:1316 jtag_validate_ircapture(): esp32s2.cpu: IR capture 0x01
Debug: 1364 1157974 command.c:143 script_debug(): command - transport transport select
Debug: 1365 1157974 command.c:143 script_debug(): command - esp32s2 esp32s2 cget -chain-position
Debug: 1366 1157974 command.c:143 script_debug(): command - jtag jtag tapisenabled esp32s2.cpu
Debug: 1367 1157974 command.c:143 script_debug(): command - esp32s2 esp32s2 invoke-event examine-start
Debug: 1368 1157974 command.c:143 script_debug(): command - esp32s2 esp32s2 arp_examine allow-defer
Debug: 1369 1157974 xtensa.c:685 xtensa_examine(): xtensa_examine coreid=0
Debug: 1370 1157984 xtensa.c:698 xtensa_examine(): OCD_ID = 03339fd2
Debug: 1371 1157984 command.c:143 script_debug(): command - esp32s2 esp32s2 invoke-event examine-end
Debug: 1372 1157984 command.c:143 script_debug(): command - esp32s2 esp32s2 invoke-event reset-assert-pre
Debug: 1373 1157984 command.c:143 script_debug(): command - transport transport select
Debug: 1374 1157984 command.c:143 script_debug(): command - esp32s2 esp32s2 cget -chain-position
Debug: 1375 1157984 command.c:143 script_debug(): command - jtag jtag tapisenabled esp32s2.cpu
Debug: 1376 1157984 command.c:143 script_debug(): command - esp32s2 esp32s2 arp_reset assert 0
Debug: 1377 1157984 target.c:2010 target_free_all_working_areas_restore(): freeing all working areas
Debug: 1378 1157984 target.c:2010 target_free_all_working_areas_restore(): freeing all working areas
Debug: 1379 1157984 esp32s2.c:293 esp32s2_assert_reset(): esp32s2: begin
Debug: 1380 1157984 esp32s2.c:373 esp32s2_soc_reset(): start
Debug: 1381 1157984 esp32s2.c:377 esp32s2_soc_reset(): esp32s2_soc_reset: Target not halted before SoC reset, trying to halt it first
Debug: 1382 1157984 xtensa.c:1132 xtensa_halt(): xtensa_halt, target: esp32s2
Debug: 1383 1157993 xtensa.c:1144 xtensa_halt(): esp32s2: Core status 0x0
Debug: 1384 1158012 esp_xtensa.c:210 esp_xtensa_poll(): esp32s2: Clear debug stubs info
Debug: 1385 1158019 target.c:3115 target_wait_state(): waiting for target halted...
Debug: 1386 1158037 xtensa.c:889 xtensa_fetch_all_regs(): esp32s2: start
Debug: 1387 1159275 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1388 1160285 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1389 1160323 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1390 1160323 xtensa.c:1847 xtensa_poll(): esp32s2: Target halted, pc=0x00000000, debug_reason=00000000, oldstate=00000003
Debug: 1391 1160323 xtensa.c:1852 xtensa_poll(): esp32s2: Halt reason=0x00000000, exc_cause=0, dsr=0x00000000
Info : 1392 1160323 xtensa.c:1855 xtensa_poll(): esp32s2: Target halted, PC=0x00000000, debug_reason=00000000
Debug: 1393 1160337 target.c:1636 target_call_event_callbacks(): target event 0 (gdb-halt) for core esp32s2
Debug: 1394 1160337 esp32s2.c:621 esp32s2_handle_target_event(): 0
Debug: 1395 1160337 esp_xtensa.c:109 esp_xtensa_handle_target_event(): 0
Debug: 1396 1160337 xtensa.c:2433 xtensa_handle_target_event(): 0
Debug: 1397 1160337 target.c:1636 target_call_event_callbacks(): target event 1 (halted) for core esp32s2
Debug: 1398 1160337 esp32s2.c:621 esp32s2_handle_target_event(): 1
Debug: 1399 1160337 esp_xtensa.c:109 esp_xtensa_handle_target_event(): 1
Debug: 1400 1160337 xtensa.c:2433 xtensa_handle_target_event(): 1
Debug: 1401 1160337 esp_xtensa.c:246 esp_xtensa_dbgstubs_info_update(): esp32s2: Read debug stubs info 0 / 0
Debug: 1402 1160337 target.c:2537 target_write_u32(): address: 0x3f41f064, value: 0x50d83aa1
Debug: 1403 1160358 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1404 1160358 target.c:2537 target_write_u32(): address: 0x3f41f048, value: 0x00000000
Debug: 1405 1160382 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1406 1160382 target.c:2537 target_write_u32(): address: 0x3f420064, value: 0x50d83aa1
Debug: 1407 1160400 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1408 1160400 target.c:2537 target_write_u32(): address: 0x3f420048, value: 0x00000000
Debug: 1409 1160419 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1410 1160419 target.c:2537 target_write_u32(): address: 0x3f4080ac, value: 0x50d83aa1
Debug: 1411 1160437 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1412 1160437 target.c:2537 target_write_u32(): address: 0x3f408094, value: 0x00000000
Debug: 1413 1160455 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1414 1160486 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1415 1160486 esp32s2.c:564 esp32s2_on_halt(): Chip ver 0x80000000
Warn : 1416 1160486 esp32s2.c:572 esp32s2_on_halt(): Unknown ESP32-S2 chip revision (0x80000000)!
Debug: 1417 1160486 target.c:2537 target_write_u32(): address: 0x3f4080bc, value: 0x00000000
Debug: 1418 1160504 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1419 1160504 target.c:2537 target_write_u32(): address: 0x3f4080c0, value: 0x00000000
Debug: 1420 1160519 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1421 1160519 target.c:2537 target_write_u32(): address: 0x3f408074, value: 0x01583218
Debug: 1422 1160538 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1423 1160538 esp32s2.c:324 esp32s2_stall_set(): esp32s2: begin
Debug: 1424 1160566 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1425 1160566 target.c:2449 target_read_u32(): address: 0x3f4080b8, value: 0x80000000
Debug: 1426 1160566 target.c:2537 target_write_u32(): address: 0x3f4080b8, value: 0x84000000
Debug: 1427 1160580 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1428 1160610 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (80000000)
Debug: 1429 1160610 target.c:2449 target_read_u32(): address: 0x3f408000, value: 0x00000000
Debug: 1430 1160611 target.c:2537 target_write_u32(): address: 0x3f408000, value: 0x00000008
Debug: 1431 1160631 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (80000000)
Debug: 1432 1160631 xtensa.c:726 xtensa_smpbreak_write(): esp32s2: write smpbreak set=0x200000 clear=0x430000
Debug: 1433 1160670 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1434 1160670 target.c:2449 target_read_u32(): address: 0x3f408000, value: 0x80000000
Debug: 1435 1160670 target.c:2537 target_write_u32(): address: 0x3f408000, value: 0x80000000
Debug: 1436 1160686 xtensa.c:787 xtensa_core_status_check(): esp32s2: DSR (00000000)
Debug: 1437 1160698 log.c:409 keep_alive(): keep_alive() was not invoked in the 1000ms timelimit (2860). This may cause trouble with GDB connections.
Info : 1439 1160836 xtensa.c:1802 xtensa_poll(): esp32s2: Core was reset.
Debug: 1440 1160852 xtensa.c:1132 xtensa_halt(): xtensa_halt, target: esp32s2
Debug: 1441 1160866 xtensa.c:1144 xtensa_halt(): esp32s2: Core status 0x0
Debug: 1442 1160893 xtensa.c:1818 xtensa_poll(): esp32s2: not powered 0x0 0
Debug: 1443 1160908 target.c:3115 target_wait_state(): waiting for target halted...
Error: 1444 1160908 esp32s2.c:477 esp32s2_soc_reset(): esp32s2_soc_reset: Couldn't halt target before SoC reset
Debug: 1445 1160908 command.c:630 run_command(): Command 'reset' failed with error code -4
User : 1446 1160908 target.c:4656 target_handle_event(): Error executing event gdb-attach on target esp32s2:

Debug: 1447 1160908 esp32s2.c:621 esp32s2_handle_target_event(): 19
Debug: 1448 1160908 esp_xtensa.c:109 esp_xtensa_handle_target_event(): 19
Debug: 1449 1160908 xtensa.c:2433 xtensa_handle_target_event(): 19
Error: 1450 1160908 esp_xtensa.c:717 esp_xtensa_probe(): Target not halted
Error: 1451 1160908 core.c:263 get_flash_bank_by_num(): auto_probe failed
Error: 1452 1160908 gdb_server.c:1003 gdb_new_connection(): Connect failed. Consider setting up a gdb-attach event for the target to prepare target for GDB connect, or use 'gdb_memory_map disable'.
Error: 1453 1160908 server.c:104 add_connection(): attempted 'gdb' connection rejected

The application flashed on the ESP32S2 seems to be running "fine", according to idf.py monitor (see below, despite messages going Debug: 326 465 xtensa.c:1818 xtensa_poll(): esp32s2: not powered 0x0 0):

$ ~/dev/esp-idf/tools/idf.py monitor -p /dev/cu.SLAB_USBtoUART
Executing action: monitor
Running idf_monitor in directory /Users/romanvg/dev/esp32s2_can/twai_network_slave
Executing "/Users/romanvg/.espressif/python_env/idf4.3_py3.9_env/bin/python3 /Users/romanvg/dev/esp-idf/tools/idf_monitor.py -p /dev/cu.SLAB_USBtoUART -b 115200 --toolchain-prefix xtensa-esp32s2-elf- /Users/romanvg/dev/esp32s2_can/twai_network_slave/build/twai_network_slave.elf -m '/Users/romanvg/.espressif/python_env/idf4.3_py3.9_env/bin/python3' '/Users/romanvg/dev/esp-idf/tools/idf.py'"...
--- idf_monitor on /dev/cu.SLAB_USBtoUART 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
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:0x3ffe6100,len:0x8
load:0x3ffe6108,len:0x181c
load:0x4004c000,len:0x9d8
load:0x40050000,len:0x2e34
SHA-256 comparison failed:
Calculated: 192fe66f4f5fd0ab9ef0b5be1cbe6751b42c2489d3fca43cce26f24a87369265
Expected: ec697f67980a4fe3773349f0585aca760f5f3d553e8f6b01321c203f4fb589b2
Attempting to boot anyway...
entry 0x4004c1ec
I (65) boot: ESP-IDF v4.3-dev-2349-g39cbf2f7e-dirty 2nd stage bootloader
I (65) boot: compile time 23:03:21
I (66) boot: chip revision: 0
I (69) boot.esp32s2: SPI Speed      : 80MHz
I (74) boot.esp32s2: SPI Mode       : DIO
I (79) boot.esp32s2: SPI Flash Size : 4MB
I (83) boot: Enabling RNG early entropy source...
I (89) boot: Partition Table:
I (92) boot: ## Label            Usage          Type ST Offset   Length
I (100) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (107) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (115) boot:  2 factory          factory app      00 00 00010000 00100000
I (122) boot: End of partition table
I (127) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=0659ch ( 26012) map
I (141) esp_image: segment 1: paddr=000165c4 vaddr=3ffbc670 size=0264ch (  9804) load
I (146) esp_image: segment 2: paddr=00018c18 vaddr=40022000 size=00404h (  1028) load
I (152) esp_image: segment 3: paddr=00019024 vaddr=40022404 size=06ff4h ( 28660) load
I (168) esp_image: segment 4: paddr=00020020 vaddr=40080020 size=12750h ( 75600) map
I (185) esp_image: segment 5: paddr=00032778 vaddr=400293f8 size=03274h ( 12916) load
I (194) boot: Loaded app from partition at offset 0x10000
I (194) boot: Disabling RNG early entropy source...
I (207) cache: Instruction cache  : size 8KB, 4Ways, cache line size 32Byte
I (207) cpu_start: Pro cpu up.
I (264) cpu_start: Pro cpu start user code
I (264) cpu_start: cpu freq: 160000000
I (264) cpu_start: Application information:
I (267) cpu_start: Project name:     twai_network_slave
I (273) cpu_start: App version:      1
I (277) cpu_start: Compile time:     Jan  6 2021 23:03:06
I (283) cpu_start: ELF file SHA256:  4009f0ba5ceb8314...
I (289) cpu_start: ESP-IDF:          v4.3-dev-2349-g39cbf2f7e-dirty
I (296) heap_init: Initializing. RAM available for dynamic allocation:
I (303) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (310) heap_init: At 3FFBF470 len 0003CB90 (242 KiB): DRAM
I (316) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (322) spi_flash: detected chip: generic
I (327) spi_flash: flash io: dio
I (331) cpu_start: Starting scheduler on PRO CPU.
I (336) BrainCAN: Entering TWAI receive task
I (336) BrainCAN: Entering TWAI transmit task
I (336) BrainCAN: Transmitted TWAI packet
I (346) BrainCAN: Driver started
I (346) BrainCAN: Driver installed
I (2446) BrainCAN: Driver stopped
I (2446) BrainCAN: Transmitted TWAI packet
I (2836) BrainCAN: Received TWAI frame looks wrong?
I (4546) BrainCAN: Driver started
I (4546) BrainCAN: Driver stopped
I (4546) BrainCAN: Transmitted TWAI packet
I (6646) BrainCAN: Driver started
I (6646) BrainCAN: Driver stopped
I (6646) BrainCAN: Transmitted TWAI packet
I (8746) BrainCAN: Driver started
I (8746) BrainCAN: Driver stopped
I (8746) BrainCAN: Transmitted TWAI packet
I (10846) BrainCAN: Driver started
I (10846) BrainCAN: Driver stopped
I (10846) BrainCAN: Transmitted TWAI packet
I (12946) BrainCAN: Driver started
I (12946) BrainCAN: Driver stopped
I (12946) BrainCAN: Transmitted TWAI packet
(...)

I guess that next step would be examining https://github.com/espressif/openocd-esp32/blob/master/src/target/esp32s2.c to see what's being reset/halted wrong unless someone can spot an obvious error or omission in the logs I've posted so far? (/cc @igrr) :-S:

@brainstorm brainstorm changed the title [Feature Request]: DEBUGGING.txt needs a bit more clarity? (VSC-539) [Feature Request]: better DEBUGGING.txt and fixing ESP32S2 JTAG bitbang debug (VSC-539) Jan 11, 2021
@brianignacio5
Copy link
Collaborator

What do you think are reasonable defaults for launch.json ? Can you expand on your feature request ?

Based on the information you shared, seems that default launch.json seems sufficient (with the exception of debug level 5, in the debug adapter repository this value is 2 by default) so I believe your desired behavior is related to openOCD project itself.

Please let us keep related issues to its respective repository, so we can fix these issues.

@brainstorm
Copy link
Author

That's right @brianignacio5, I kept this issue as sort-of a journal as I was fixing this, I'll move to openocd-esp32 repo instead.

W.r.t DEBUGGING.txt, I would have expected an overall description/diagram of which ports communicate with which components since there are a few moving parts (ports: 4444 (telnet/tcl??), 5555 (openocd), 3333 (gdb), 43474 (DAP), etc...

@brainstorm
Copy link
Author

brainstorm commented Jan 11, 2021

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

No branches or pull requests

2 participants